Error
- mwversion: 1.45.0-wmf.20
- reqId: 76218f35-ed65-4eab-b16a-4b93439288e6
- Find reqId in Logstash
Session data is authenticated, should not be an anonymous user
Impact
[warnings] 3 occurrences in the last 24 hours on testwiki
| DAlangi_WMF | |
| Sep 25 2025, 5:38 PM |
| Restricted File | |
| Oct 8 2025, 9:49 AM |
| F66736110: Screenshot 2025-10-07 at 3.00.22 PM.png | |
| Oct 7 2025, 12:02 PM |
Session data is authenticated, should not be an anonymous user
[warnings] 3 occurrences in the last 24 hours on testwiki
| Status | Subtype | Assigned | Task | ||
|---|---|---|---|---|---|
| Resolved | JTweed-WMF | T398814 WE5.1.1 Session storage protection | |||
| Resolved | JTweed-WMF | T400372 Separate storage backend for anonymous sessions | |||
| Resolved | DAlangi_WMF | T402808 Deploy separate anonymous session backend to Wikimedia production, in log-only mode | |||
| Resolved | PRODUCTION ERROR | DAlangi_WMF | T405633 Session data is authenticated, should not be an anonymous user |
Around 40K/day now that we are on group1: https://logstash.wikimedia.org/goto/651666aef95e04aae3c4b0c1c8f98c7c
50K in the last 24 hours. 30.5K is from the NetworkSessionProvider. 17K from CentralAuthSessionProvider. 2K from CentralAuthApiSessionProvider. No other providers as far as I can see.
(Note this is unrelated to the Session "{session}": the session store entry is for an anonymous user, but the session metadata indicates a non-anonynmous user session log entries which sound similar but happen at a different layer, and have been a longstanding issue - T181869.)
That's not completely random (e.g. OAuth is not present, even though a lot of requests use OAuth) but not very specific either. NetworkSessionProvider (the CirrusSearch updater) seems a big overrepresented (not that much, though - it does make a lot of requests). Some of these are immutable providers so this can't be related to to cross-domain cookie mixups or race conditions around login / logout. The stack trace is early Setup.php, well before autocreation, so can't be related to autocreation failures either.
Actually, why are we saving at all during the session initialization in Setup.php?
Maybe these are all fake saves (using WRITE_CACHE_ONLY, which SessionBackend::save() does for unpersisted sessions)? Maybe as a first step we should log the value of the BagOStuff flag. The store mismatch still doesn't make sense for cache-only writes, but it's a less scary problem.
Ended up closing T405634: Authenticated data should not be in the anonymous store as a duplicate of this because one is triggered from MultiBackendSessionStore::get() and the other is triggered from MultiBackendSessionStore::getActiveStore(). get() calls getActiveStore(). The difference is that one is triggered when there is no UserInfo object, and the other is more generic than that; however, the causes could potentially be the same, and I think fixing one would also fix the other.
Additionally, @Tgr, we have also observed the opposite case in Logstash, filed a ticket: T406560: Anonymous data should not be in the authenticated store.
Maybe these are all fake saves (using WRITE_CACHE_ONLY, which SessionBackend::save() does for unpersisted sessions)? Maybe as a first step we should log the value of the BagOStuff flag.
Yes, I want to go down this route and see what's happening, but at first glance, it could most likely be the case. After looking through the logs last night, I couldn't see why a call to get() would trigger a SessionBackend::save(). The loadSessionInfoFromStore() method needs to be looked at more closely, but that will come after we've logged the flags to understand more about what's happening.
Spent some more time digging into this, and it turns out the majority of this happens during "account autocreation". I have looked at so many requests, and you can see what's happening to these examples below:
It also appears that these are related to a ticket you filed at T406433: Warning "User::loadFromSession called before the end of Setup.php" (2025 October), as I can see it in those requests as well.
Something very similar I see related to those requests is something like (see image below)
Change #1194188 had a related patch set uploaded (by D3r1ck01; author: Derick Alangi):
[mediawiki/core@master] session: Write cache write flags in `SessionStore::set()`
Change #1194281 had a related patch set uploaded (by Gergő Tisza; author: Derick Alangi):
[mediawiki/core@wmf/1.45.0-wmf.21] session: Log cache write flags in `SessionStore::set()`
Change #1194282 had a related patch set uploaded (by Gergő Tisza; author: Derick Alangi):
[mediawiki/core@wmf/1.45.0-wmf.22] session: Log cache write flags in `SessionStore::set()`
Change #1194188 merged by jenkins-bot:
[mediawiki/core@master] session: Log cache write flags in `SessionStore::set()`
Change #1194281 merged by jenkins-bot:
[mediawiki/core@wmf/1.45.0-wmf.21] session: Log cache write flags in `SessionStore::set()`
Change #1194282 merged by jenkins-bot:
[mediawiki/core@wmf/1.45.0-wmf.22] session: Log cache write flags in `SessionStore::set()`
Mentioned in SAL (#wikimedia-operations) [2025-10-07T21:30:44Z] <tgr@deploy2002> Started scap sync-world: Backport for [[gerrit:1194261|session: Log actual class name in preventSessionsForUser exception (T406566)]], [[gerrit:1194262|session: Log actual class name in preventSessionsForUser exception (T406566)]], [[gerrit:1194281|session: Log cache write flags in SessionStore::set() (T405633 T405634)]], [[gerrit:1194282|session: Log cache write flags in SessionStore::set() (T4056
Mentioned in SAL (#wikimedia-operations) [2025-10-07T21:34:47Z] <tgr@deploy2002> tgr: Backport for [[gerrit:1194261|session: Log actual class name in preventSessionsForUser exception (T406566)]], [[gerrit:1194262|session: Log actual class name in preventSessionsForUser exception (T406566)]], [[gerrit:1194281|session: Log cache write flags in SessionStore::set() (T405633 T405634)]], [[gerrit:1194282|session: Log cache write flags in SessionStore::set() (T405633 T405634)]] synced
Mentioned in SAL (#wikimedia-operations) [2025-10-07T21:40:21Z] <tgr@deploy2002> Finished scap sync-world: Backport for [[gerrit:1194261|session: Log actual class name in preventSessionsForUser exception (T406566)]], [[gerrit:1194262|session: Log actual class name in preventSessionsForUser exception (T406566)]], [[gerrit:1194281|session: Log cache write flags in SessionStore::set() (T405633 T405634)]], [[gerrit:1194282|session: Log cache write flags in SessionStore::set() (T405
Seems like what's happening is the opposite, please correct me if I'm misunderstanding this. SessionBackend::save() calls SessionStore::set() with 0 (as suspected, since that's the default in most cases) as the flag when the session is to be persisted or WRITE_CACHE_ONLY otherwise.
When SessionStore::set() is called with 0 as the flag, we write to both the in-process cache and the backend. Perhaps in some of these cases (such as account auto-creation, where we already have a central session and potentially a local session via edge-login for a given wiki), attempting to update data to the backend cache (which already exists) causes these issues? I imagine a case where edge-login has already planted a session (in the background prepping to login on next page view), then the user comes around to visit that wiki to materialize the session and we try to do a session write to update the backend, what's supposed to happen?
Could this be some race condition? Because, like we saw yesterday, for most requests that have this issue, it's about account auto-creation and a race condition locally. See another example today:
{F66738351}
I just spotted a request with 8 (WRITE_CACHE_ONLY) as the flag: https://logstash.wikimedia.org/goto/0573dd85f53c069ad3da339ea3b1e62f. Now I'm confused ☺️
Change #1194582 had a related patch set uploaded (by D3r1ck01; author: Derick Alangi):
[mediawiki/core@master] session: Check that `$anonUserId` is not null (like other cases)
Change #1194663 had a related patch set uploaded (by D3r1ck01; author: Derick Alangi):
[mediawiki/core@master] session: Improve logging for MultiBackendSessionStore
Change #1194582 abandoned by D3r1ck01:
[mediawiki/core@master] session: Check that `$anonUserId` is not null (like other cases)
Reason:
Per If9c4a13f7e49349cf344e32a4f6e2714e9e44e3a, we're not using userID anymore.
Change #1194663 merged by jenkins-bot:
[mediawiki/core@master] session: Improve logging for MultiBackendSessionStore
Change #1194963 had a related patch set uploaded (by D3r1ck01; author: Derick Alangi):
[mediawiki/core@wmf/1.45.0-wmf.21] session: Improve logging for MultiBackendSessionStore
Change #1194964 had a related patch set uploaded (by D3r1ck01; author: Derick Alangi):
[mediawiki/core@wmf/1.45.0-wmf.22] session: Improve logging for MultiBackendSessionStore
Change #1194963 merged by jenkins-bot:
[mediawiki/core@wmf/1.45.0-wmf.21] session: Improve logging for MultiBackendSessionStore
Change #1194964 merged by jenkins-bot:
[mediawiki/core@wmf/1.45.0-wmf.22] session: Improve logging for MultiBackendSessionStore
Mentioned in SAL (#wikimedia-operations) [2025-10-09T16:10:27Z] <tgr@deploy2002> Started scap sync-world: Backport for [[gerrit:1194963|session: Improve logging for MultiBackendSessionStore (T402808 T405633 T405634)]], [[gerrit:1194964|session: Improve logging for MultiBackendSessionStore (T402808 T405633 T405634)]]
Mentioned in SAL (#wikimedia-operations) [2025-10-09T16:14:09Z] <tgr@deploy2002> tgr, d3r1ck01: Backport for [[gerrit:1194963|session: Improve logging for MultiBackendSessionStore (T402808 T405633 T405634)]], [[gerrit:1194964|session: Improve logging for MultiBackendSessionStore (T402808 T405633 T405634)]] synced to the testservers (see https://wikitech.wikimedia.org/wiki/Mwdebug). Changes can now be verified there.
Mentioned in SAL (#wikimedia-operations) [2025-10-09T16:30:34Z] <tgr@deploy2002> Finished scap sync-world: Backport for [[gerrit:1194963|session: Improve logging for MultiBackendSessionStore (T402808 T405633 T405634)]], [[gerrit:1194964|session: Improve logging for MultiBackendSessionStore (T402808 T405633 T405634)]] (duration: 20m 07s)
Change #1195029 had a related patch set uploaded (by D3r1ck01; author: Derick Alangi):
[mediawiki/core@master] session: Avoid logging in session store if UserInfo is available
Store is authenticated, but the user associated to the data is anonymous
from /srv/mediawiki/php-1.45.0-wmf.22/includes/session/MultiBackendSessionStore.php(208)
#0 /srv/mediawiki/php-1.45.0-wmf.22/includes/session/SessionManager.php(632): MediaWiki\Session\MultiBackendSessionStore->get(MediaWiki\Session\SessionInfo)
#1 /srv/mediawiki/php-1.45.0-wmf.22/includes/session/SessionManager.php(588): MediaWiki\Session\SessionManager->loadSessionInfoFromStore(MediaWiki\Session\SessionInfo, MediaWiki\Request\WebRequest)
#2 /srv/mediawiki/php-1.45.0-wmf.22/includes/session/SessionManager.php(136): MediaWiki\Session\SessionManager->getSessionInfoForRequest(MediaWiki\Request\WebRequest)
#3 /srv/mediawiki/php-1.45.0-wmf.22/includes/Request/WebRequest.php(860): MediaWiki\Session\SessionManager->getSessionForRequest(MediaWiki\Request\WebRequest)
#4 /srv/mediawiki/php-1.45.0-wmf.22/includes/Setup.php(502): MediaWiki\Request\WebRequest->getSession()
#5 /srv/mediawiki/php-1.45.0-wmf.22/includes/WebStart.php(72): require_once(string)
#6 /srv/mediawiki/php-1.45.0-wmf.22/index.php(36): require(string)
#7 /srv/mediawiki/w/index.php(3): require(string)
#8 {main}We're satisfied with the logs so far, and we'll be closing this as resolved. The log messages have been changed anyway by If9c4a13f7e49349cf344e32a4f6e2714e9e44e3a (2ea77a739a39d9da255c88cd876e7baf49237ae8).
If any issues arise, we'll file new tasks and track from there. Even with the deployment to group2 today, we're having an average of about two occurrences (warnings) of this per minute, which sounds fine.
Change #1195029 abandoned by D3r1ck01:
[mediawiki/core@master] session: Avoid logging in session store if UserInfo is available