That does sound like a bug. I would suggest filing a task about it at
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 <david(a)tentwentyfour.lu> 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