Page MenuHomePhabricator

Make sure SessionManager emitting Set-Cookie headers gets logged
Closed, ResolvedPublic

Description

SessionManager emits Set-Cookie headers randomly (in the sense that it is unrelated to what URL was requested) in at least three cases:

  • when the session is near expiry
  • when the session is incorrect (e.g. the user name and ID don't match) or invalid (e.g. the user token does not match the one in the database), to delete the cookies
  • when the user has no local session cookies but has CentralAuth second-level domain session cookies

Make sure all such events can easily be listed in Logstash, with at least the following information:

  • type of the event (the three options above)
  • username for which the cookies are issued
  • IP of the request
  • user agent of the request

Event Timeline

Tgr created this task.Tue, Oct 6, 7:39 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptTue, Oct 6, 7:39 PM
Tgr added a comment.Wed, Oct 7, 2:18 AM

The session renew call chain is Session::renew() --> SessionBackend::renew() --> SessionBackend::autosave() --> SessionBackend::save() --> SessionProvider::persistSession() / unpersistSession().
Session::renew() is called unconditionally in Setup.php, autosave/save is called frequently for other reasons, so it is either SessionBackend::renew() (where the "near expiry" check actually happens - it already has some logging, but debug-level only) or right at the persist/unpersist call. The first makes it easy to tell this is a renew, the second makes it easy to tell whether we are persisting or unpersisting (also there are exotic cases where the renew is aborted without the renew() method knowing).

Fixing the session happens by SessionManager::getSessionInfoForRequest() calling unpersistSession() - either none of the SessionProvider::provideSessionInfo() calls return a usable session, or SessionManager::loadSessionInfoFromStore() invalidates them all for some reason (request data is internally inconsistent, session id is not in the session store, request data and session store metadata don't match, user token does not match etc). Right before/after unpersistSession() seems like the only sane place for logging.
(This will be removed by T264794: SessionManager should not emit Set-Cookies on session renewal, but just in case that needs to be rolled back, it's probably a good idea to add logging first.)

Creation of the local CentralAuth session uses the autosave mechanis: during session setup, after SessionManager::getSessionInfoForRequest() gets the session info object from the provider, it calls SessionManager::getSessionFromInfo() to turn it into an actual SessionBackend. SessionBackend starts in a dirty metadata state since it cannot load any session store object, so the next SessionBackend::save() (called at the end of session setup) will persist the session - this is largely the same path as the one for renew.

The sanest approach is probably to have a flag that tells the logging code what triggered the logging.

Change 632601 had a related patch set uploaded (by Gergő Tisza; owner: Gergő Tisza):
[mediawiki/core@master] Log when SessionManager is emitting cookies

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

Change 632601 merged by jenkins-bot:
[mediawiki/core@master] Log when SessionManager is emitting cookies

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

Change 632685 had a related patch set uploaded (by Gergő Tisza; owner: Gergő Tisza):
[mediawiki/core@wmf/1.36.0-wmf.10] Log when SessionManager is emitting cookies

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

Change 632806 had a related patch set uploaded (by Gergő Tisza; owner: Gergő Tisza):
[mediawiki/core@wmf/1.36.0-wmf.11] Log when SessionManager is emitting cookies

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

Change 632807 had a related patch set uploaded (by Gergő Tisza; owner: Gergő Tisza):
[mediawiki/core@wmf/1.36.0-wmf.12] Log when SessionManager is emitting cookies

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

Daimona added a subscriber: Daimona.Wed, Oct 7, 9:24 PM

Change 632795 had a related patch set uploaded (by Gergő Tisza; owner: Gergő Tisza):
[operations/mediawiki-config@master] Enable logging of session cookie changes in group0

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

Change 632796 had a related patch set uploaded (by Gergő Tisza; owner: Gergő Tisza):
[operations/mediawiki-config@master] Enable logging of session cookie changes in group1

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

Change 632797 had a related patch set uploaded (by Gergő Tisza; owner: Gergő Tisza):
[operations/mediawiki-config@master] Enable logging of session cookie changes everywhere

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

Change 632685 merged by Gergő Tisza:
[mediawiki/core@wmf/1.36.0-wmf.10] Log when SessionManager is emitting cookies

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

Change 632795 merged by jenkins-bot:
[operations/mediawiki-config@master] Enable logging of session cookie changes in group0

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

Mentioned in SAL (#wikimedia-operations) [2020-10-07T23:58:51Z] <tgr@deploy1001> Synchronized php-1.36.0-wmf.10/includes/session: Backport: [[gerrit:632685|Log when SessionManager is emitting cookies (T264793)]] (duration: 01m 00s)

Mentioned in SAL (#wikimedia-operations) [2020-10-08T00:03:07Z] <tgr@deploy1001> Synchronized wmf-config/InitialiseSettings.php: Config: [[gerrit:632795|Enable logging of session cookie changes in group0 (T264793)]] (duration: 00m 58s)

Change 632796 merged by jenkins-bot:
[operations/mediawiki-config@master] Enable logging of session cookie changes in group1

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

Change 632806 merged by jenkins-bot:
[mediawiki/core@wmf/1.36.0-wmf.11] Log when SessionManager is emitting cookies

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

Change 632807 merged by jenkins-bot:
[mediawiki/core@wmf/1.36.0-wmf.12] Log when SessionManager is emitting cookies

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

Mentioned in SAL (#wikimedia-operations) [2020-10-08T00:15:08Z] <tgr@deploy1001> Synchronized wmf-config/InitialiseSettings.php: Config: [[gerrit:632796|Enable logging of session cookie changes in group1 (T264793)]] (duration: 00m 57s)

Mentioned in SAL (#wikimedia-operations) [2020-10-08T00:20:51Z] <tgr@deploy1001> Synchronized wmf-config/InitialiseSettings.php: Config: [[gerrit:632796|Enable logging of session cookie changes in group1 (T264793)]] (again, forgot to rebase the previous time) (duration: 00m 59s)

Tgr added a comment.Thu, Oct 8, 12:34 AM

That didn't work out: just deploying it to group1 doubled MediaWiki log volume (and increased total Logstash volume by 10%): https://logstash.wikimedia.org/goto/d37d7de3baf53661e1843f1dd61f907a
I'll leave it on group1 for a day and see if I can figure out why is it logging so much.

Tgr added a comment.Thu, Oct 8, 3:43 PM

Total MediaWiki log volume (without the session channel) is about 50M events / day. The large group1 wikis (login, meta, wikidata, commons, mw, enwikt, ensource, liwikt) are about 15M from that. group0/1 session logs, extrapolated for 24 hours, are about 10M. So it's not that bad, actually (previously I used some default dashboard that filtered out api feature usage logs, which is the most common). Still, it almost doubles log volume and should be cut down.

Change 632959 had a related patch set uploaded (by Gergő Tisza; owner: Gergő Tisza):
[mediawiki/core@master] Deduplicate SessionBackend::logPersistenceChange calls

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

Change 632959 merged by jenkins-bot:
[mediawiki/core@master] Deduplicate SessionBackend::logPersistenceChange calls

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

Change 632991 had a related patch set uploaded (by Hashar; owner: Gergő Tisza):
[mediawiki/core@wmf/1.36.0-wmf.11] Deduplicate SessionBackend::logPersistenceChange calls

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

Change 632991 merged by jenkins-bot:
[mediawiki/core@wmf/1.36.0-wmf.11] Deduplicate SessionBackend::logPersistenceChange calls

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

Change 632992 had a related patch set uploaded (by Hashar; owner: Gergő Tisza):
[mediawiki/core@wmf/1.36.0-wmf.10] Deduplicate SessionBackend::logPersistenceChange calls

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

Change 632992 merged by jenkins-bot:
[mediawiki/core@wmf/1.36.0-wmf.10] Deduplicate SessionBackend::logPersistenceChange calls

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

Mentioned in SAL (#wikimedia-operations) [2020-10-08T21:52:21Z] <hashar@deploy1001> Synchronized php-1.36.0-wmf.10/includes/session/SessionBackend.php: Deduplicate SessionBackend::logPersistenceChange calls - T264793 (duration: 01m 01s)

Change 632797 merged by jenkins-bot:
[operations/mediawiki-config@master] Enable logging of session cookie changes everywhere

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

Mentioned in SAL (#wikimedia-operations) [2020-10-08T23:16:21Z] <tgr@deploy1001> Synchronized wmf-config/InitialiseSettings.php: Config: [[gerrit:632797|Enable logging of session cookie changes everywhere (T264793)]] (duration: 01m 01s)

Tgr closed this task as Resolved.Thu, Oct 8, 11:42 PM
Tgr claimed this task.

So, this is out and logging now. The log volume increase between group1 and group2 ended up surprisingly modest, we would probably have been okay even without the last patch.