Page MenuHomePhabricator

Wikibase and Lexeme browser tests are failing with `failed-save: The save has failed.`
Closed, ResolvedPublic

Description

Several Wikibase and WikibaseLexeme browser tests are failing with the error message failed-save: The save has failed.. This affects both ruby and nodejs tests.

Example: jenkins-bot comment, job console

Details

Event Timeline

Michael created this task.Jun 14 2019, 11:00 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJun 14 2019, 11:00 AM
Michael triaged this task as High priority.Jun 14 2019, 11:01 AM

This seems to be related to the ratelimit. As for https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-hhvm-docker/53930/consoleFull the first error exactly matches the timestamp of the first rate-limit error message:

2019-06-14 10:33:33 1b09f406778b wikidb: User '127.0.0.1' (IP 127.0.0.1) tripped mediawiki:limiter:edit:ip:127.0.0.1 at 8 (limit 8 in 60s)
See: https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-hhvm-docker/53930/artifact/log/mw-ratelimit.log

But also there are quite some errors in the mw-dberror.log:

Fri Jun 14 10:24:36 UTC 2019	1b09f406778b	wikidb-unittest_	BrokenRedirectsPage::reallyDoQuery	/workspace/db/quibble-mysql-h6p0v4cu/socket	1137	Can't reopen table: 'p1' (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  p1.page_namespace AS `namespace`,p1.page_title AS `title`,p1.page_title AS `value`,rd_namespace,rd_title,rd_fragment  FROM `unittest_redirect` JOIN `unittest_page` `p1` ON ((rd_from=p1.page_id)) LEFT JOIN `unittest_page` `p2` ON ((rd_namespace=p2.page_namespace) AND (rd_title=p2.page_title))   WHERE (rd_namespace >= 0) AND (rd_interwiki IS NULL OR rd_interwiki = '') AND (p2.page_namespace IS NULL)  ORDER BY rd_namespace,rd_title,rd_from LIMIT 51  
Fri Jun 14 10:24:36 UTC 2019	1b09f406778b	wikidb-unittest_	DoubleRedirectsPage::reallyDoQuery	/workspace/db/quibble-mysql-h6p0v4cu/socket	1137	Can't reopen table: 'ra' (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  pa.page_namespace AS `namespace`,pa.page_title AS `title`,pa.page_title AS `value`,pb.page_namespace AS `b_namespace`,pb.page_title AS `b_title`,rb.rd_namespace AS `c_namespace`,rb.rd_title AS `c_title`,rb.rd_fragment AS `c_fragment`,rb.rd_interwiki AS `c_interwiki`  FROM `unittest_redirect` `ra`,`unittest_redirect` `rb`,`unittest_page` `pa`,`unittest_page` `pb`    WHERE (ra.rd_from = pa.page_id) AND (ra.rd_interwiki IS NULL OR ra.rd_interwiki = '') AND (pb.page_namespace = ra.rd_namespace) AND (pb.page_title = ra.rd_title) AND (rb.rd_from = pb.page_id)  ORDER BY ra.rd_namespace,ra.rd_title LIMIT 51  
Fri Jun 14 10:24:36 UTC 2019	1b09f406778b	wikidb-unittest_	WantedFilesPage::reallyDoQuery	/workspace/db/quibble-mysql-h6p0v4cu/socket	1137	Can't reopen table: 'img1' (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  6 AS `namespace`,il_to AS `title`,COUNT(*) AS `value`  FROM `unittest_imagelinks` LEFT JOIN `unittest_page` ON ((il_to = page_title) AND page_namespace = '6') LEFT JOIN `unittest_redirect` ON ((page_id = rd_from) AND rd_namespace = '6' AND rd_interwiki = '') LEFT JOIN `unittest_image` `img1` ON ((il_to = img1.img_name)) LEFT JOIN `unittest_image` `img2` ON ((rd_title = img2.img_name))   WHERE img1.img_name IS NULL AND img2.img_name IS NULL  GROUP BY il_to ORDER BY value DESC,namespace,title LIMIT 51  
Fri Jun 14 10:24:36 UTC 2019	1b09f406778b	wikidb-unittest_	WantedPagesPage::reallyDoQuery	/workspace/db/quibble-mysql-h6p0v4cu/socket	1137	Can't reopen table: 'pg1' (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  pl_namespace AS `namespace`,pl_title AS `title`,COUNT(*) AS `value`  FROM `unittest_pagelinks` LEFT JOIN `unittest_page` `pg1` ON ((pg1.page_namespace = pl_namespace) AND (pg1.page_title = pl_title)) LEFT JOIN `unittest_page` `pg2` ON ((pg2.page_id = pl_from))   WHERE (pg1.page_namespace IS NULL) AND (pl_namespace NOT IN ('2','3')) AND (pg2.page_namespace != '8')  GROUP BY pl_namespace,pl_title HAVING (COUNT(*) > '0') AND (COUNT(*) > SUM(pg2.page_is_redirect)) ORDER BY value DESC,namespace,title LIMIT 51  
Fri Jun 14 10:24:36 UTC 2019	1b09f406778b	wikidb-unittest_	ListredirectsPage::reallyDoQuery	/workspace/db/quibble-mysql-h6p0v4cu/socket	1137	Can't reopen table: 'p1' (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  p1.page_namespace AS `namespace`,p1.page_title AS `title`,p1.page_title AS `value`,rd_namespace,rd_title,rd_fragment,rd_interwiki,p2.page_id AS `redirid`  FROM `unittest_page` `p1` LEFT JOIN `unittest_redirect` ON ((rd_from=p1.page_id)) LEFT JOIN `unittest_page` `p2` ON ((p2.page_namespace=rd_namespace) AND (p2.page_title=rd_title))   WHERE p1.page_is_redirect = '1'  ORDER BY p1.page_namespace,p1.page_title LIMIT 51  
Fri Jun 14 10:25:33 UTC 2019	1b09f406778b	wikidb-unittest_	SqlBagOStuff::fetchBlobMulti	/workspace/db/quibble-mysql-h6p0v4cu/socket	1146	Table 'wikidb.unittest_objectcache' doesn't exist (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  keyname,value,exptime  FROM `unittest_objectcache`    WHERE keyname = 'wikidb-unittest_:mf:mobileview:9::19700101000000:0::wikidb-unittest_%3Apcache%3Aidhash%3A0-0!dateformat=default!wb=3'  
Fri Jun 14 10:25:33 UTC 2019	1b09f406778b	wikidb-unittest_	SqlBagOStuff::fetchBlobMulti	/workspace/db/quibble-mysql-h6p0v4cu/socket	1146	Table 'wikidb.unittest_objectcache' doesn't exist (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  keyname,value,exptime  FROM `unittest_objectcache`    WHERE keyname = 'wikidb-unittest_:mf:mobileview:9::19700101000000:0::wikidb-unittest_%3Apcache%3Aidhash%3A0-0!dateformat=default!wb=3'  
Fri Jun 14 10:25:33 UTC 2019	1b09f406778b	wikidb-unittest_	SqlBagOStuff::fetchBlobMulti	/workspace/db/quibble-mysql-h6p0v4cu/socket	1146	Table 'wikidb.unittest_objectcache' doesn't exist (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  keyname,value,exptime  FROM `unittest_objectcache`    WHERE keyname = 'wikidb-unittest_:mf:mobileview:9::19700101000000:0::wikidb-unittest_%3Apcache%3Aidhash%3A0-0!dateformat=default!wb=3'  
Fri Jun 14 10:25:33 UTC 2019	1b09f406778b	wikidb-unittest_	SqlBagOStuff::fetchBlobMulti	/workspace/db/quibble-mysql-h6p0v4cu/socket	1146	Table 'wikidb.unittest_objectcache' doesn't exist (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  keyname,value,exptime  FROM `unittest_objectcache`    WHERE keyname = 'wikidb-unittest_:mf:mobileview:9::19700101000000:0::wikidb-unittest_%3Apcache%3Aidhash%3A0-0!dateformat=default!wb=3'  
Fri Jun 14 10:25:33 UTC 2019	1b09f406778b	wikidb-unittest_	SqlBagOStuff::fetchBlobMulti	/workspace/db/quibble-mysql-h6p0v4cu/socket	1146	Table 'wikidb.unittest_objectcache' doesn't exist (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  keyname,value,exptime  FROM `unittest_objectcache`    WHERE keyname = 'wikidb-unittest_:mf:mobileview:9::19700101000000:0::wikidb-unittest_%3Apcache%3Aidhash%3A0-0!dateformat=default!wb=3'  
Fri Jun 14 10:25:33 UTC 2019	1b09f406778b	wikidb-unittest_	SqlBagOStuff::fetchBlobMulti	/workspace/db/quibble-mysql-h6p0v4cu/socket	1146	Table 'wikidb.unittest_objectcache' doesn't exist (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  keyname,value,exptime  FROM `unittest_objectcache`    WHERE keyname = 'wikidb-unittest_:mf:mobileview:9::19700101000000:0::wikidb-unittest_%3Apcache%3Aidhash%3A0-0!dateformat=default!wb=3'  
Fri Jun 14 10:25:33 UTC 2019	1b09f406778b	wikidb-unittest_	SqlBagOStuff::fetchBlobMulti	/workspace/db/quibble-mysql-h6p0v4cu/socket	1146	Table 'wikidb.unittest_objectcache' doesn't exist (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  keyname,value,exptime  FROM `unittest_objectcache`    WHERE keyname = 'wikidb-unittest_:mf:mobileview:9::19700101000000:0::wikidb-unittest_%3Apcache%3Aidhash%3A0-0!dateformat=default!wb=3'  
Fri Jun 14 10:25:33 UTC 2019	1b09f406778b	wikidb-unittest_	SqlBagOStuff::fetchBlobMulti	/workspace/db/quibble-mysql-h6p0v4cu/socket	1146	Table 'wikidb.unittest_objectcache' doesn't exist (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  keyname,value,exptime  FROM `unittest_objectcache`    WHERE keyname = 'wikidb-unittest_:mf:mobileview:9::19700101000000:0::wikidb-unittest_%3Apcache%3Aidhash%3A0-0!dateformat=default!wb=3'  
Fri Jun 14 10:25:33 UTC 2019	1b09f406778b	wikidb-unittest_	SqlBagOStuff::fetchBlobMulti	/workspace/db/quibble-mysql-h6p0v4cu/socket	1146	Table 'wikidb.unittest_objectcache' doesn't exist (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  keyname,value,exptime  FROM `unittest_objectcache`    WHERE keyname = 'wikidb-unittest_:mf:mobileview:9::19700101000000:0::wikidb-unittest_%3Apcache%3Aidhash%3A0-0!dateformat=default!wb=3'  
Fri Jun 14 10:25:33 UTC 2019	1b09f406778b	wikidb-unittest_	SqlBagOStuff::fetchBlobMulti	/workspace/db/quibble-mysql-h6p0v4cu/socket	1146	Table 'wikidb.unittest_objectcache' doesn't exist (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  keyname,value,exptime  FROM `unittest_objectcache`    WHERE keyname = 'wikidb-unittest_:mf:mobileview:9::19700101000000:0::wikidb-unittest_%3Apcache%3Aidhash%3A0-0!dateformat=default!wb=3'  
Fri Jun 14 10:25:33 UTC 2019	1b09f406778b	wikidb-unittest_	SqlBagOStuff::fetchBlobMulti	/workspace/db/quibble-mysql-h6p0v4cu/socket	1146	Table 'wikidb.unittest_objectcache' doesn't exist (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  keyname,value,exptime  FROM `unittest_objectcache`    WHERE keyname = 'wikidb-unittest_:mf:mobileview:9::19700101000000:0::wikidb-unittest_%3Apcache%3Aidhash%3A0-0!dateformat=default!wb=3'  
Fri Jun 14 10:25:33 UTC 2019	1b09f406778b	wikidb-unittest_	SqlBagOStuff::fetchBlobMulti	/workspace/db/quibble-mysql-h6p0v4cu/socket	1146	Table 'wikidb.unittest_objectcache' doesn't exist (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  keyname,value,exptime  FROM `unittest_objectcache`    WHERE keyname = 'wikidb-unittest_:mf:mobileview:9::19700101000000:0::wikidb-unittest_%3Apcache%3Aidhash%3A0-0!dateformat=default!wb=3'  
Fri Jun 14 10:25:33 UTC 2019	1b09f406778b	wikidb-unittest_	SqlBagOStuff::fetchBlobMulti	/workspace/db/quibble-mysql-h6p0v4cu/socket	1146	Table 'wikidb.unittest_objectcache' doesn't exist (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  keyname,value,exptime  FROM `unittest_objectcache`    WHERE keyname = 'wikidb-unittest_:mf:mobileview:9::19700101000000:0::wikidb-unittest_%3Apcache%3Aidhash%3A0-0!dateformat=default!wb=3'  
Fri Jun 14 10:25:33 UTC 2019	1b09f406778b	wikidb-unittest_	SqlBagOStuff::fetchBlobMulti	/workspace/db/quibble-mysql-h6p0v4cu/socket	1146	Table 'wikidb.unittest_objectcache' doesn't exist (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  keyname,value,exptime  FROM `unittest_objectcache`    WHERE keyname = 'wikidb-unittest_:mf:mobileview:9::19700101000000:0::wikidb-unittest_%3Apcache%3Aidhash%3A0-0!dateformat=default!wb=3'  
Fri Jun 14 10:25:33 UTC 2019	1b09f406778b	wikidb-unittest_	SqlBagOStuff::fetchBlobMulti	/workspace/db/quibble-mysql-h6p0v4cu/socket	1146	Table 'wikidb.unittest_objectcache' doesn't exist (/workspace/db/quibble-mysql-h6p0v4cu/socket)	SELECT  keyname,value,exptime  FROM `unittest_objectcache`    WHERE keyname = 'wikidb-unittest_:mf:mobileview:9::19700101000000:0::wikidb-unittest_%3Apcache%3Aidhash%3A0-0!dateformat=default!wb=3'

See https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-hhvm-docker/53930/artifact/log/mw-dberror.log

This seems to be related to the ratelimit. As for https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-hhvm-docker/53930/consoleFull the first error exactly matches the timestamp of the first rate-limit error message:
2019-06-14 10:33:33 1b09f406778b wikidb: User '127.0.0.1' (IP 127.0.0.1) tripped mediawiki:limiter:edit:ip:127.0.0.1 at 8 (limit 8 in 60s)
See: https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-hhvm-docker/53930/artifact/log/mw-ratelimit.log

On further inspection, this error is very strange, because the user is logged-in during that test and thus shouldn't trigger the ratelimit for IPs:
https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-hhvm-docker/53930/artifact/log/Lexeme%253AHeader-shows-id.png

Change 517074 had a related patch set uploaded (by Michael Große; owner: Michael Große):
[mediawiki/extensions/Wikibase@master] DNM: try to see if working around ratelimit works

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

I've had this happen to me locally (T126611#2022173) but I didn't know a mediawiki instance at a jenkins VM would be ratelimited at all. @hashar do you have any ideas?

@hashar mentioned on IRC that the value of $wgMainCacheType has been recently changed to no longer be CACHE_NONE

10:40:31) hashar: leszek_wmde: there are some changes that have been done in mediawiki/core related to caching
(10:41:17) hashar: notably to have the CLI installer.php to properly detect and enable APC as the default cache type
(10:41:25) hashar: when previously it apparently defaulted to CACHE_NONE

Then @Michael noticed that according to https://www.mediawiki.org/wiki/Manual:$wgRateLimits, this triggered actually using $wgRateLimits

$wgMainCacheType must be set to a value other than CACHE_NONE for this setting to work.

It seems that for the CI it would make sense to disable rate limiting. It seems it has implicitly been the case.

Change 517385 had a related patch set uploaded (by WMDE-leszek; owner: WMDE-leszek):
[mediawiki/core@master] Disable rate limiting in Development Settings

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

Change 517392 had a related patch set uploaded (by Hashar; owner: WMDE-leszek):
[mediawiki/core@REL1_31] Disable rate limiting in Development Settings

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

Change 517393 had a related patch set uploaded (by Hashar; owner: WMDE-leszek):
[mediawiki/core@fundraising/REL1_31] Disable rate limiting in Development Settings

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

Change 517394 had a related patch set uploaded (by Hashar; owner: WMDE-leszek):
[mediawiki/core@REL1_32] Disable rate limiting in Development Settings

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

Change 517395 had a related patch set uploaded (by Hashar; owner: WMDE-leszek):
[mediawiki/core@REL1_33] Disable rate limiting in Development Settings

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

Change 517385 merged by jenkins-bot:
[mediawiki/core@master] Disable rate limiting in Development Settings

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

WMDE-leszek lowered the priority of this task from High to Normal.Jun 17 2019, 5:47 PM

https://gerrit.wikimedia.org/r/517385 helped and unblocked merging Wikibase patches. Thanks to @hashar and @zeljkofilipin for help. And special thanks to @Michael for discovering the root issue.
Leaving the ticket open until the backport patches get merged.

Change 517392 merged by jenkins-bot:
[mediawiki/core@REL1_31] Disable rate limiting in Development Settings

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

Change 517394 merged by jenkins-bot:
[mediawiki/core@REL1_32] Disable rate limiting in Development Settings

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

Change 517395 merged by jenkins-bot:
[mediawiki/core@REL1_33] Disable rate limiting in Development Settings

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

Change 517565 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@master] DevelopmentSettings: Document why wgRateLimits is disabled

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

Change 517565 merged by jenkins-bot:
[mediawiki/core@master] DevelopmentSettings: Document why wgRateLimits is disabled

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

WMDE-leszek closed this task as Resolved.Jun 18 2019, 7:05 AM
WMDE-leszek claimed this task.

Thanks all!

Thank you, very well done :]

Change 517074 abandoned by Michael Große:
DNM: try to see if working around ratelimit works

Reason:
The issue has been resolved. See the linked phab task.

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

Change 517393 merged by jenkins-bot:
[mediawiki/core@fundraising/REL1_31] Disable rate limiting in Development Settings

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

hashar added a comment.Jul 4 2019, 7:45 AM

And the nice fixes have been back ported to all currently supported branches. I would like to express my gratitude to @Michael and @WMDE-leszek for finding and fixing this. That kind of issue is typically not so trivial to find out :-]

mmodell changed the subtype of this task from "Task" to "Production Error".Aug 28 2019, 11:06 PM