That does sound like a bug. I would suggest filing a task about it at https://phabricator.wikimedia.org where it can be discussed further (feel free to add me as a subscriber). Optionally, if you are feeling ambitious, you can also submit a patch in gerrit.
-- Bawolff On Friday, May 6, 2022, David Raison <[email protected]> wrote: > Hi everyone, > > > I just realized I probably sent my original message (see below) to the > wrong list. So here goes again, this time with a deeper understanding what > is going on, but also still much doubt and confusion. > > tl;dr on the original post: Users are being randomly disconnected from our > mediawiki instances. > > > I would like to check with you if what I found is a bug or not and if it's > not, then I'm looking to understand why it behaves this way. I am also > looking for information on what triggers garbage collection of PHP sessions. > > > Since I originally posted, I have found out what is deleting sessions from > the objectcache table in the database. I have been able to reproduce this > both on a remote server and locally. Both times, my set-up is running in a > docker environment. > > > The call-stack that does this is the following: > > #0 SqlBagOStuff->deleteServerObjectsExpiringBefore() called at > [/var/www/html/includes/objectcache/SqlBagOStuff.php:668] > #1 SqlBagOStuff->deleteObjectsExpiringBefore() called at > [/var/www/html/includes/libs/objectcache/CachedBagOStuff.php:148] > #2 CachedBagOStuff->deleteObjectsExpiringBefore() called at > [/var/www/html/includes/session/PHPSessionHandler.php:376] > #3 MediaWiki\Session\PHPSessionHandler->gc() > #4 session_start() called at [/var/www/html/includes/Setup.php:757] > #5 require_once(/var/www/html/includes/Setup.php) called at > [/var/www/html/includes/WebStart.php:89] > #6 require(/var/www/html/includes/WebStart.php) called at > [/var/www/html/index.php:44] > > Usually, SqlBagOStuff::deleteServerObjectsExpiringBefore is called from > MWCallableUpdate->doUpdate() and passed a Unix timestamp. This timestamp > is a UTC value and handled as such. > > However, sometimes, as can be seen from the backtrace above, it is called > from the Garbage Collector in PHPSessionHandler: > > public function gc( $maxlifetime ) { > if ( self::$instance !== $this ) { > throw new \UnexpectedValueException( __METHOD__ . ': Wrong > instance called!' ); > } > $before = date( 'YmdHis', time() ); > $this->store->deleteObjectsExpiringBefore( $before ); > return true; > } > > The problem here is that – probably for historical reasons - the function > is passed a date string here instead of a Unix timestamp. And *the actual > problem with that* is that the date() function applies timezone > information (if $wgLocaltimezone is set). The resulting timestamp will > thus be in the future (or be local time, interpreted as UTC). With a value > of something equivalent to GMT+2, gc() will cause all current sessions to > be deleted since they have a standard expiry time of 1h, stored as UTC > value in the database. > > If this happens, and the session is not declared persistent ( > $session->isPersistent(), "Keep me logged in"), then all users are > immediately logged out of mediawiki. > > > Thus, my first question: Is this a bug? Since the $timestamp parameter is > passed to ConvertibleTimestamp::convert( TS_UNIX, $timestamp ) in > SqlBagOStuff::deleteServerObjectsExpiringBefore anyway, I do not see any > reason to pass a date string. My suggestion for a fix would be to change > the gc method as follows: > > public function gc( $maxlifetime ) { > if ( self::$instance !== $this ) { > throw new \UnexpectedValueException( __METHOD__ . ': Wrong > instance called!' ); > } > $this->store->deleteObjectsExpiringBefore( microtime(true) ); // > time() would be sufficient > return true; > } > > > My second question would be: What controls when PHPSessionHandler::gc is > called? Is it indeed the session configuration for the PHP process (i.e. > session.gc_probability, > session.gc_divisor and session.gc_maxlifetime) ? > > > Thanks, > David > > > > > Hi all, > > > I'm writing to the list in the hope of receiving some feedback, questions, > maybe answers to help us solve a conundrum with sessions we have on our > Wikibase/Mediawiki installation. > > > We're running two different docker-based wikibase installations (one > staging, one production) on two separate virtual machines. Both use the > SimpleSaml extension to connect to a SAML implementation, but we have found > that the random session deletion happens both with and without the SAML > extension used. > > > The symptoms that we've seen are that out of the blue, users are > disconnected from mediawiki. Since we use SAML, it's enough to click the > Login link to again be connected. > > > The duration or number of requests until a session is deleted seems > random. It does appear though, that the more (or more frequent) requests > are made (and thus background jobs run) the quicker a session is deleted. > > > We have even tried setting $wgObjectCacheSessionExpiry = 7200; in order > to exclude any TimeZone related issues which was our first suspicion. > However, changing this from the default 1h session expiry does not change > the behavior we're seeing. > > > Sessions are deleted regardless of their nature. E.g. sessions established > for oauth connections are deleted in the same way and at the same time as > other sessions. E.g. using wikidataintegrator we're able to run a number of > requests until the CSRF token expires (with the number of requests that > succeed before this happens being random): > > […] > Created Item Q379 from Class > http://www.cidoc-crm.org/cidoc-crm/E34_Inscription. > Created Item Q380 from Class http://www.cidoc-crm.org/cidoc-crm/E53_Place. > Error while writing to Wikidata > ERROR creating class reference for > http://www.cidoc-crm.org/cidoc-crm/E35_Title: {'error': {'code': 'badtoken', > 'info': 'Invalid CSRF token.', '*': 'See https://saf-dev.bnl.lu/w/api.php for > API usage. Subscribe to the mediawiki-api-announce mailing list at > <https://lists.wikimedia.org/mailman/listinfo/mediawiki-api-announce> > for notice of API deprecations and breaking changes.'}} > Error while writing to Wikidata > ERROR creating object property reference for > http://www.cidoc-crm.org/cidoc-crm/P16_used_specific_object: {'error': > {'code': 'badtoken', 'info': 'Invalid CSRF token.', '*': 'See > https://saf-dev.bnl.lu/w/api.php for API usage. Subscribe to the > mediawiki-api-announce mailing list at > <https://lists.wikimedia.org/mailman/listinfo/mediawiki-api-announce> > for notice of API deprecations and breaking changes.'}} > > > > If sessions are not randomly deleted, then session renewal seems to work > as planned with them being renewed after half their expiry time: > > [DBQuery] SqlBagOStuff::fetchBlobMulti [0s] db.svc:3306: SELECT > keyname,value,exptime FROM `objectcache` WHE > RE keyname = 'mediawiki:MWSession:n9krnsfa303qk9c2osp6c81tp1k2bp5b' > [session] SessionBackend > "require/require_once/MediaWiki\Session\Session->renew/MediaWiki\Session\SessionBackend- > >renew" metadata dirty for renew(): > >require/require_once/MediaWiki\Session\Session->renew/MediaWiki\Session\Sessi > onBackend->renew > [session] SessionBackend "n9krnsfa303qk9c2osp6c81tp1k2bp5b" force-persist for > renew(): require/require_once/Media > Wiki\Session\Session->renew/MediaWiki\Session\SessionBackend->renew > [session] SessionBackend "n9krnsfa303qk9c2osp6c81tp1k2bp5b" save: dataDirty=0 > metaDirty=1 forcePersist=1 > [cookie] setcookie: "mediawiki_session", "n9krnsfa303qk9c2osp6c81tp1k2bp5b", > "0", "/", "", "1", "1", "" > [cookie] setcookie: "mediawikiUserID", "13", "1648233666", "/", "", "1", "1", > "" > [cookie] setcookie: "mediawikiUserName", "Ibl676", "1648233666", "/", "", > "1", "1", "" > [cookie] already deleted setcookie: "mediawikiToken", "", "1614105666", "/", > "", "1", "1", "" > [cookie] already deleted setcookie: "forceHTTPS", "", "1614105666", "/", "", > "", "1", "" > [session] SessionBackend "n9krnsfa303qk9c2osp6c81tp1k2bp5b" Taking over PHP > session > [session] SessionBackend "n9krnsfa303qk9c2osp6c81tp1k2bp5b" save: dataDirty=0 > metaDirty=1 forcePersist=1 > [cookie] already set setcookie: "mediawiki_session", > "n9krnsfa303qk9c2osp6c81tp1k2bp5b", "0", "/", "", "1", "1", > "" > [cookie] already set setcookie: "mediawikiUserID", "13", "1648233666", "/", > "", "1", "1", "" > [cookie] already set setcookie: "mediawikiUserName", "Ibl676", "1648233666", > "/", "", "1", "1", "" > [cookie] already deleted setcookie: "mediawikiToken", "", "1614105666", "/", > "", "1", "1", "" > [cookie] already deleted setcookie: "forceHTTPS", "", "1614105666", "/", "", > "", "1", "" > [DBQuery] SqlBagOStuff::updateTable [0.002s] db.svc:3306: REPLACE INTO > `objectcache` (keyname,value,exptime) VALU > ES > ('mediawiki:MWSession:n9krnsfa303qk9c2osp6c81tp1k2bp5b','...\0','20220223194106') > > Here is one example where the session got deleted by whatever feels > responsible to do so: > > MariaDB [mediawiki]> select keyname, exptime from objectcache where keyname > like > 'mediawiki:MWSession%';+------------------------------------------------------+---------------------+ > | keyname | exptime > |+------------------------------------------------------+---------------------+ > | mediawiki:MWSession:t7d5lms2nrma6k627c6usrgc6289en3a | 2022-03-24 17:34:34 > |+------------------------------------------------------+---------------------+1 > row in set (0.001 sec) > > MariaDB [mediawiki]> select keyname, exptime from objectcache where keyname > like 'mediawiki:MWSession%'; > Empty set (0.001 sec) > > MariaDB [mediawiki]> select now();+---------------------+ > | now() |+---------------------+ > | 2022-03-24 17:37:15 |+---------------------+1 row in set (0.024 sec) > > > The only instance of me finding something remotely related to randomly > deleting a session would be these log entries: > > > 2022-03-24 17:03:29 51290acae35a mediawiki: SessionManager using store > SqlBagOStuff > 2022-03-24 17:03:29 51290acae35a mediawiki: Saving all sessions on shutdown > 2022-03-24 17:03:29 51290acae35a mediawiki: SessionManager using store > SqlBagOStuff > 2022-03-24 17:03:29 51290acae35a mediawiki: Session > "[30]MediaWiki\Session\CookieSessionProvider<-:13:Ibl676>8favvi92d08njut82j66un60r601titn": > Unverified user provided and no metadata to auth it > 2022-03-24 17:03:29 51290acae35a mediawiki: setcookie: "mediawiki_session", > "", "1616605409", "/", "", "1", "1", "" > 2022-03-24 17:03:29 51290acae35a mediawiki: setcookie: "mediawikiUserID", "", > "1616605409", "/", "", "1", "1", "" > 2022-03-24 17:03:29 51290acae35a mediawiki: already deleted setcookie: > "mediawikiToken", "", "1616605409", "/", "", "1", "1", "" > 2022-03-24 17:03:29 51290acae35a mediawiki: already deleted setcookie: > "forceHTTPS", "", "1616605409", "/", "", "", "1", "" > 2022-03-24 17:03:29 51290acae35a mediawiki: SessionBackend > "ujf6rcheseb51lpaojrqggb4c23s1flr" is unsaved, marking dirty in constructor > 2022-03-24 17:03:29 51290acae35a mediawiki: SessionBackend > "ujf6rcheseb51lpaojrqggb4c23s1flr" save: dataDirty=1 metaDirty=1 > forcePersist=0 > 2022-03-24 17:03:29 51290acae35a mediawiki: already deleted setcookie: > "mediawiki_session", "", "1616605409", "/", "", "1", "1", "" > 2022-03-24 17:03:29 51290acae35a mediawiki: already deleted setcookie: > "mediawikiUserID", "", "1616605409", "/", "", "1", "1", "" > 2022-03-24 17:03:29 51290acae35a mediawiki: already deleted setcookie: > "mediawikiToken", "", "1616605409", "/", "", "1", "1", "" > 2022-03-24 17:03:29 51290acae35a mediawiki: already deleted setcookie: > "forceHTTPS", "", "1616605409", "/", "", "", "1", "" > 2022-03-24 17:03:29 51290acae35a mediawiki: Saving all sessions on shutdown > > IBL676 is my SAML ID. I'm not sure why the user is unverified and what > metadata would be used/required to verify it? > > > > Looking forward to any advice on how to further investigate what is going > on here. > > > -- > > *TenTwentyFour S.à r.l.* > www.tentwentyfour.lu > *T*: +352 20 211 1024 > *F*: +352 20 211 1023 > 1 place de l'Hôtel de Ville > <https://www.google.com/maps/search/1+place+de+l'H%C3%B4tel+de+Ville+%0D%0A++++++++++4138+Esch-sur-Alzette?entry=gmail&source=g> > 4138 Esch-sur-Alzette >
_______________________________________________ Wikitech-l mailing list -- [email protected] To unsubscribe send an email to [email protected] https://lists.wikimedia.org/postorius/lists/wikitech-l.lists.wikimedia.org/
