Page MenuHomePhabricator
Create Task
Maniphest T264793

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

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

Details

SubjectRepoBranchLines +/-
Enable logging of session cookie changes everywhereoperations/mediawiki-configmaster+1 -3
Deduplicate SessionBackend::logPersistenceChange callsmediawiki/corewmf/1.36.0-wmf.10+27 -4
Deduplicate SessionBackend::logPersistenceChange callsmediawiki/corewmf/1.36.0-wmf.11+27 -4
Deduplicate SessionBackend::logPersistenceChange callsmediawiki/coremaster+27 -4
Enable logging of session cookie changes in group1operations/mediawiki-configmaster+1 -0
Log when SessionManager is emitting cookiesmediawiki/corewmf/1.36.0-wmf.10+74 -2
Log when SessionManager is emitting cookiesmediawiki/corewmf/1.36.0-wmf.12+74 -2
Log when SessionManager is emitting cookiesmediawiki/corewmf/1.36.0-wmf.11+74 -2
Enable logging of session cookie changes in group0operations/mediawiki-configmaster+1 -0
Log when SessionManager is emitting cookiesmediawiki/coremaster+74 -2
Customize query in gerrit

Related Objects

Event Timeline

Tgr created this task.Oct 6 2020, 7:39 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptOct 6 2020, 7:39 PM
DannyS712 subscribed.Oct 6 2020, 8:24 PM
Tgr added a comment.Oct 7 2020, 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.

gerritbot added a comment.Oct 7 2020, 4:50 AM

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

gerritbot added a project: Patch-For-Review.Oct 7 2020, 4:50 AM
WDoranWMF added a project: Platform Engineering.Oct 7 2020, 7:32 PM
gerritbot added a comment.Oct 7 2020, 8:17 PM

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

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

gerritbot added a comment.Oct 7 2020, 8:34 PM

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

gerritbot added a comment.Oct 7 2020, 8:34 PM

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

gerritbot added a comment.Oct 7 2020, 8:35 PM

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

ReleaseTaggerBot added a project: MW-1.36-notes (1.36.0-wmf.13; 2020-10-12).Oct 7 2020, 9:00 PM
Daimona subscribed.Oct 7 2020, 9:24 PM
gerritbot added a comment.Oct 7 2020, 9:39 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

gerritbot added a comment.Oct 7 2020, 9:39 PM

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

gerritbot added a comment.Oct 7 2020, 9:39 PM

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

gerritbot added a comment.Oct 7 2020, 11:41 PM

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

gerritbot added a comment.Oct 7 2020, 11:48 PM

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

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

Stashbot added a comment.Oct 7 2020, 11:58 PM

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)

ReleaseTaggerBot edited projects, added MW-1.36-notes (1.36.0-wmf.10; 2020-09-22); removed MW-1.36-notes (1.36.0-wmf.13; 2020-10-12).Oct 8 2020, 12:00 AM
Stashbot added a comment.Oct 8 2020, 12:03 AM

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)

gerritbot added a comment.Oct 8 2020, 12:05 AM

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

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

gerritbot added a comment.Oct 8 2020, 12:10 AM

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

gerritbot added a comment.Oct 8 2020, 12:12 AM

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

Stashbot added a comment.Oct 8 2020, 12:15 AM

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)

Stashbot added a comment.Oct 8 2020, 12:20 AM

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.Oct 8 2020, 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.

ReleaseTaggerBot edited projects, added MW-1.36-notes (1.36.0-wmf.11; 2020-09-29); removed MW-1.36-notes (1.36.0-wmf.10; 2020-09-22).Oct 8 2020, 1:00 AM
Tgr added a comment.Oct 8 2020, 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.

gerritbot added a comment.Oct 8 2020, 4:40 PM

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

gerritbot added a comment.Oct 8 2020, 8:35 PM

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

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

gerritbot added a comment.Oct 8 2020, 8:35 PM

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

ReleaseTaggerBot edited projects, added MW-1.36-notes (1.36.0-wmf.13; 2020-10-12); removed MW-1.36-notes (1.36.0-wmf.11; 2020-09-29).Oct 8 2020, 9:00 PM
gerritbot added a comment.Oct 8 2020, 9:08 PM

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

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

gerritbot added a comment.Oct 8 2020, 9:14 PM

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

gerritbot added a comment.Oct 8 2020, 9:37 PM

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

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

Stashbot added a comment.Oct 8 2020, 9:52 PM

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)

ReleaseTaggerBot edited projects, added MW-1.36-notes (1.36.0-wmf.11; 2020-09-29); removed MW-1.36-notes (1.36.0-wmf.13; 2020-10-12).Oct 8 2020, 10:00 PM
gerritbot added a comment.Oct 8 2020, 11:09 PM

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

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

Stashbot added a comment.Oct 8 2020, 11:16 PM

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.Oct 8 2020, 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.

Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL