| Anomie added a comment. |
There doesn't seem to be any real "user related stuff" here, or anything actually related to Wikibase or the API. It looks like the bug will be hit on whatever the first thing is that opens a DB connection. In the linked traces that happens to be CentralAuth checking whether the user exists locally.
It seems likely that Addshore is right that the renewed use of the cpPosTime cookie is probably a factor here.
Based on Addshore's comment above that it could be reproduced relatively easily on testwiki, I added a hack on mwdebug1001 to ChronologyProtector::initPositions() to do some additional logging. and fired some write requests immediately followed by read requests at it.
The relevant bit of the hack, inserted here, looked like
wfDebugLog( 'AdHocDebug', "$this->waitForPosTime; " . self::minPosTime( $data ) . "; " . var_export( $data, 1 ) );
- A log message not exhibiting the bug: https://logstash.wikimedia.org/app/kibana#/doc/logstash-*/logstash-2017.12.08/mediawiki?id=AWA2vEiEhTduSC7pvHX8&_g=()
1512746796.6372; 1512746796.6398; array (
'positions' =>
array (
'db1075' =>
Wikimedia\Rdbms\MySQLMasterPos::__set_state(array(
'file' => 'db1075-bin.002287',
'pos' => '971204539',
'gtids' =>
array (
0 => '0-171966669-4051016729',
1 => '180359174-180359174-94123433',
2 => '171966669-171966669-1497088137',
),
'asOfTime' => 1512746796.6398,
)),
'10.64.16.187' =>
Wikimedia\Rdbms\MySQLMasterPos::__set_state(array(
'file' => 'es1014-bin.001930',
'pos' => '91982167',
'gtids' =>
array (
0 => '',
),
'asOfTime' => 1512746796.641,
)),
),
)- A log message exhibiting the bug: https://logstash.wikimedia.org/app/kibana#/doc/logstash-*/logstash-2017.12.08/mediawiki?id=AWA2u2tTOBGWx1mQW9Xy&_g=()
1512746734.7688; 1512746683.2953; array (
'positions' =>
array (
'db1075' =>
Wikimedia\Rdbms\MySQLMasterPos::__set_state(array(
'file' => 'db1075-bin.002287',
'pos' => '967383713',
'gtids' =>
array (
0 => '0-171966669-4051016667',
1 => '180359174-180359174-94123433',
2 => '171966669-171966669-1497079015',
),
'asOfTime' => 1512746734.7753,
)),
'10.64.16.187' =>
Wikimedia\Rdbms\MySQLMasterPos::__set_state(array(
'file' => 'es1014-bin.001930',
'pos' => '86433351',
'gtids' =>
array (
0 => '',
),
'asOfTime' => 1512746683.2953,
)),
'10.64.0.6' =>
Wikimedia\Rdbms\MySQLMasterPos::__set_state(array(
'file' => 'es1011-bin.001932',
'pos' => '392199459',
'gtids' =>
array (
0 => '',
),
'asOfTime' => 1512746734.785,
)),
),
)It looks like what's happening here is that the write balancing between ExternalStore cluster24 and cluster25 is confusing ChronologyProtector: if one write hits cluster24 and another hits cluster25 within the 60-second lifetime of ChronologyProtector's memcache entry, ChronologyProtector is going to be waiting for an "update" to whichever of the two was written earlier that is never going to come.
Cc: Sjoerddebruin, Anomie, Anvilaquarius, Steinsplitter, Lucas_Werkmeister_WMDE, thiemowmde, Jonas, Krinkle, aaron, aude, TerraCodes, Jay8g, Fnielsen, MisterSynergy, Manu1400, Simon_Villeneuve, hoo, daniel, Framawiki, Envlh, Kghbln, jhsoby, Trizek-WMF, Liuxinyu970226, Joe, Ladsgroup, Addshore, Lea_Lacroix_WMDE, Aklapper, Imarlier, Lahi, Gq86, GoranSMilovanovic, QZanden, Vali.matei, Sethakill, dg711, Volker_E, Wikidata-bugs, GWicke, jayvdb, Mbch331, Legoktm
_______________________________________________ Wikidata-bugs mailing list [email protected] https://lists.wikimedia.org/mailman/listinfo/wikidata-bugs
