Page MenuHomePhabricator

Analyze "temporary logging for T372702" data and then stop logging it
Closed, ResolvedPublic

Description

We added "temporary logging for T372702" in https://gerrit.wikimedia.org/r/c/mediawiki/extensions/CentralAuth/+/1081967, and then we forgot about it. I found the code today while working on something else.

Unfortunately I have no idea what the presence of the log event indicates. @Tgr @DAlangi_WMF Do you remember?

Once we've learned whatever there is to learn, we should remove this code.

Logged data can be found here: https://logstash.wikimedia.org/goto/8ef44848b324cc6b053692ff05a5a4c5

Quick review of what I can see:

  • All logged events have persisted=true, remembered=true, isCentral=true
  • There are events with caller=refreshCookies (until 2025-03-18) and with caller=validateSession (still ongoing)
  • Most of the users, but not all, are temp users

Event Timeline

I think this started off as part of T380500: CentralAuthUser returning outdated data after user creation when we were investigating the frequent logout issue. @Tgr already worked on fixing one leg of it and there are other things to fix but I doubt that it's related to the logging here.

As you mentioned above, this is still happening today (for both named and temp users). So we might need maybe look at it sometime soon.

A task was made for this and then declined (by myself) with a comment from Tgr - T383049#10434087. Maybe these lookup failures are related to some grand SessionBackend issue? I'm currently eyeing T392251: SessionBackend seems to store session changes too often.

I think we added this when were trying to identify the bug that eventually got fixed in T379254: centralauth_Token cookie not set on top-level autologin. The assumption was that the logouts are caused by the central session "remember me" flag going from true to false (which was correct) and that it would happen by the session expiring and getCentralSession() returning on-the-spot-generated session data with the flag set to false (which was incorrect, it was happening via CentralAuthSessionProvider automatically recreating the central session after expiry).

There are events with caller=refreshCookies (until 2025-03-18) and with caller=validateSession (still ongoing)

Maybe worth looking into that a little. /refreshCookies was used during central login, we don't do that much anymore (for temp users only, and temp users are only enabled on a few wikis) so it makes sense that there aren't many of those (I'm a bit surprised there are zero). It also makes sense it happened in the first place since /refreshCookies uses a subresource request while central login uses top-level redirects, so it shouldn't be that uncommon that the prior requests work but then /refreshCookies doesn't see the cookies.
/validateSession is surprising though - we can only get there if, immediately before, /checkLoggedIn (on the same domain, with the same type of request) had a valid session.

Change #1148486 had a related patch set uploaded (by Bartosz Dziewoński; author: Bartosz Dziewoński):

[mediawiki/extensions/CentralAuth@master] Revert "Log unexpected central session lookup misses"

https://gerrit.wikimedia.org/r/1148486

Change #1148486 merged by jenkins-bot:

[mediawiki/extensions/CentralAuth@master] Revert "Log unexpected central session lookup misses"

https://gerrit.wikimedia.org/r/1148486