We have tried skipping the offending test in: https://gerrit.wikimedia.org/r/#/c/mediawiki/extensions/ContentTranslation/+/449447/

Unfortunately this just seems to move the failure to the next test along.

We've been progressively debugging but since we can't reproduce locally it's taking quite a while.

So far it seems the problem is related to:

[Wikibase\Lib\Store\Sql\WikiPageEntityRevisionLookup] loadEntityBlob: Calling getRevisionText() on revision 2
[Wikibase\Repo\Store\WikiPageEntityStore] Q1
[MessageCache] MessageCache::load: Loading en... local cache is empty, global cache is expired/volatile, loading from database
[Wikibase\Repo\Api\EntitySavingHelper] Could not create a new page.
It already exists.

From (for example): https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-hhvm-docker/9261/artifact/log/mw-debug-www.log

Continuing to look to figure out why this happens.

Change 449483 had a related patch set uploaded (by Tarrow; owner: Tarrow):
[mediawiki/extensions/Wikibase@master] WIP DNM Logging for T200693

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

In T200693#4464211, @hashar wrote:

I ran the Selenium tests through Quibble using all the extensions and unfortunately it passes just fine locally.

Did you try a run as in CI, with phpunit qunit & selenium in the same run?

Just tried @Addshore 's thought. It does fail! Looks like something is left over from phpunit or qunit. Now to track it down

Followed a hunch on the TitleExists hook which in this integration EducationProgram provides but can likely be ruled out as the culprit.

Also happens if "Lexeme:Forms can be added" is the only spec run (with NODE_DEBUG=request)

REQUEST { method: 'POST',
  headers: { 'User-Agent': 'mwbot/1.0.10' },
  qs: { format: 'json' },
  form: 
   { action: 'wbeditentity',
     new: 'item',
     data: '{"labels":{}}',
     token: '+\\' },
  timeout: 120000,
  jar: true,
  time: true,
  json: true,
  uri: 'http://127.0.0.1:9412//api.php',
  callback: [Function] }
REQUEST make request http://127.0.0.1:9412//api.php?format=json
INFO:backend.DevWebServer:[Wed Aug  1 09:51:03 2018] 127.0.0.1:60112 [200]: //api.php?format=json
REQUEST onRequestResponse http://127.0.0.1:9412//api.php?format=json 200 { host: '127.0.0.1:9412',
  connection: 'close',
  'x-powered-by': 'PHP/7.0.30-0+deb9u1',
  'x-content-type-options': 'nosniff',
  'mediawiki-api-error': 'failed-save, edit-already-exists',
  'content-type': 'application/json; charset=utf-8',
  'x-frame-options': 'DENY',
  'content-disposition': 'inline; filename=api-result.json',
  'set-cookie': 
   [ 'UseDC=master; expires=Wed, 01-Aug-2018 09:51:13 GMT; Max-Age=10; path=/; HttpOnly',
     'UseCDNCache=false; expires=Wed, 01-Aug-2018 09:51:13 GMT; Max-Age=10; path=/; HttpOnly' ],
  'cache-control': 'private, must-revalidate, max-age=0' }

Narrowed down to occur only if WikibaseLexeme phpunit tests (tests/phpunit/phpunit.php --debug-tests --testsuite extensions --exclude-group Broken,ParserFuzz,Stub,Database) are run before the browser tests

Manually bisecting which of the WikibaseLexeme phpunit tests is at fault (if any in isolation). So far identified as not at fault:

• src/extensions/WikibaseLexeme/tests/phpunit/composer
• src/extensions/WikibaseLexeme/tests/phpunit/mediawiki/Api
• src/extensions/WikibaseLexeme/tests/phpunit/mediawiki/Diff
• src/extensions/WikibaseLexeme/tests/phpunit/mediawiki/Content
• src/extensions/WikibaseLexeme/tests/phpunit/mediawiki/ParserOutput
• src/extensions/WikibaseLexeme/tests/phpunit/mediawiki/LexemePageTest.php

Apparently running only src/extensions/WikibaseLexeme/tests/phpunit/mediawiki/Specials/SpecialNewLexemeTest.php from the WikibaseLexeme tests is enough to let the following selenium test turn red -> seems unintuitive as it is in @group Database and as such should not be executed in the run before selenium, but reliably reproducible. It's also worth noting that this way SpecialNewLexemeTest gets loaded into memory, but none of its tests are actually executed (due to the @group). So maybe something in setupBeforeClass()?

Change 449453 had a related patch set uploaded (by Jakob; owner: Jakob):
[mediawiki/extensions/WikibaseLexeme@master] Create a dummy item before running the first browser test.

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

In T200693#4465900, @Tarrow wrote:

Just tried @Addshore 's thought. It does fail! Looks like something is left over from phpunit or qunit. Now to track it down

Did you manage to look LinkCache possible oddities any more?

Still looking. Not yet done much link cache investigation but have got the mysql general log out of my local quibble. It's not attached ( >70MB ) so anyone else who wants to dig through let me know.

Change 449453 merged by jenkins-bot:
[mediawiki/extensions/WikibaseLexeme@master] Create a dummy item before running the first browser test.

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

The errors seems to have changed and now appear in PHPUnit section: https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-hhvm-docker/9369/console

You are probably aware, but mentioning just in case.

I was able to reproduce those lexeme related test failures with quibble locally. The test failures go away if I add PropertySuggester to the --exclude-groups. The PropertySuggester extension hasn't changed in ages, so this is all very strange.

Change 449764 had a related patch set uploaded (by WMDE-leszek; owner: WMDE-leszek):
[mediawiki/extensions/Wikibase@master] DNM Hunting after T200693

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

Change 449766 had a related patch set uploaded (by WMDE-leszek; owner: WMDE-leszek):
[mediawiki/extensions/ContentTranslation@master] DNM Hunting T200693

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

The failures seem to also happen while running the Property Suggestor CI? https://integration.wikimedia.org/ci/job/quibble-composer-mysql-hhvm-docker/492/console which was the CI for https://gerrit.wikimedia.org/r/#/c/mediawiki/extensions/PropertySuggester/+/449878/ has the same failures as shown most recently above.

@Addshore my late evening discovery yesterday was along the lines of what you say. I mean those Scribunto language fallback test failures. My current guess is those test got broken with the work on T199983. These haven't been spotted until now though as if I see right Wikibase quibble job does not include Scribunto.
I am looking at the failures, and am about to file a request to add scribunto to Wikibase quibble job (or see if I can add it myself).

But it shall not be missed, that these 4 failures are not the only problem, see browser test failures that have been kind of worked around for now.

Wikibase quibble job does not include Scribunto

Sounds like something we should fix, if you get a patch up send it my way and I'll see if I can get it in.

But it shall not be missed, that these 4 failures are not the only problem, see browser test failures that have been kind of worked around for now.

Indeed.

My gut feeling is that something running before the browser tests (meaning all phpunit tests not marked as in the Database group) is creating an item and when it should not be, in the real db, thus it hang around.

This is very odd though, as it appears that some of the db does actually get reset? The SQL table containing the counter for the Items IDs appears to be reset, causing the issue. So when wikibase tries to make a new item it again gets told to use Q1, but then mediawiki & the mediawiki mysql tables (or maybe just some cache) already say that that item exists.
I'm not actually sure anything in the tests ever resets the wb_id_counters, which makes this seem even stranger.

At one point my hunch was leaning toward something odd happening with the LinkCache during execution, as this is what is relied upon for the Title::exists check, and it looks like it is only cleared in specific cases in MediaWikiTestCase if cloned tables are used or if the page table is used, neither of which would happen if the test is not marked as in the Database group.

I haven't had a full deep dive into the issue yet, but if everyone is drawing blanks / hitting walls then I can.

Picking up from where I left yesterday, checking what the DB contains after test "run" of SpecialNewLexemeTest.php, in particular with regards to wb_id_counters.

Some stuff from IRC:

<•addshore>                     6 Query     INSERT /* MediaWiki\Storage\SqlBlobStore::storeBlob nobody@2e7d0434... */  INTO `text` (old_id,old_text,old_flags) VALUES (NULL,'{\"type\":\"item\",\"id\":\"Q1\",\"labels\":[],\"descriptions\":[],\"aliases\":[],\"claims\":[],\"sitelinks\":[]}','utf-8')
note the INTO text
if this was marked with @Databasse this would be INTO unittest_text
for example that are occourances of 
6 Query     INSERT /* MediaWiki\Storage\SqlBlobStore::storeBlob nobody@2e7d0434... */  INTO `unittest_text` (old_id,old_text,old_flags) VALUES (NULL,'Some lame file','utf-8')
there is more than 1 it appears
https://www.irccloud.com/pastebin/jYvzdyOp/

<•Pablo_WMDE> purple is it way down in the log? could simply be from the selenium runs, right?

<•addshore> line 2147 is the Q1 insertion
but yes, you make a good point, this will also have the selenium runs in it

<•Pablo_WMDE> purple but the very first line is 9mins before the others, right?

<•addshore> 3 mins between the creation of Q1 and Q123
then 6 mins between Q123 and Q10
and then it goes 10 11 12 13 etc
maybe whenever mediawiki creates Q1, make it log a stacktrace?
then do a run with that patch, and the mysql logging, then get the timestamp from the mysql log, and line it up with the stacktrace that matches in the debug log?

<•tarrow> Tom Yep, I'll try that ASAP. Currently stuck with other breaking tets in my local quibble
`Wikibase\Lexeme\Tests\MediaWiki\Specials\LexemeSpecialEntityDataTest::testSensesKeyExistsInJsonWhenEnabled Error: 1146 Table 'wikidb.unittest_content_models' doesn't exist

In T200693#4471255, @Addshore wrote:

At one point my hunch was leaning toward something odd happening with the LinkCache during execution, as this is what is relied upon for the Title::exists check, and it looks like it is only cleared in specific cases in MediaWikiTestCase if cloned tables are used or if the page table is used, neither of which would happen if the test is not marked as in the Database group.

This reminds me of T150512#2814743 – it feels like this issue has the same cause (and I don't understand why that bug was closed: T150512#2885781)

Apparently the provider SpecialNewLexemeTest::provideValidEntityCreationRequests() is at fault
See https://github.com/sebastianbergmann/phpunit/issues/2007

Change 450038 had a related patch set uploaded (by Addshore; owner: Addshore):
[mediawiki/extensions/WikibaseLexeme@master] WIP DNM Hardcode an id that is not Q1

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

Change 450044 had a related patch set uploaded (by Pablo Grass (WMDE); owner: Pablo Grass (WMDE)):
[mediawiki/extensions/WikibaseLexeme@master] phpunit tests: do not persist in providers

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

Change 450038 abandoned by Addshore:
WIP DNM Hardcode an id that is not Q1

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

Checked all the other WikibaseLexeme data providers - apparently they are all clean; only return values w/o causing side effects.

Change 450054 had a related patch set uploaded (by Jakob; owner: Jakob):
[mediawiki/extensions/WikibaseLexeme@master] Get rid of Reflection hack used to override factory member

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

Created a revert for the selenium hack we implemented to get this (partially) green https://gerrit.wikimedia.org/r/#/c/mediawiki/extensions/WikibaseLexeme/+/450052/
/cc @Jakob_WMDE

Here are my findings regarding the following PHPUnit failing tests (of Wikibase). Please note however, that I have the working theory of mine at least three times while investigating these, so take the most current one with a grain of salt.

14:18:15 There were 4 failures:
14:18:15 
14:18:15 1) LuaSandbox: Wikibase\Client\Tests\DataAccess\Scribunto\Scribunto_LuaWikibaseLibraryTest::testRenderSnak_languageFallback with data set #0 (true, array('Q885588#L'))
14:18:15 Failed asserting that Array &0 (
14:18:15     0 => 'Q885588'
14:18:15 ) is identical to Array &0 (
14:18:15     0 => 'Pisîk'
14:18:15 ).
14:18:15 
14:18:15 /workspace/src/extensions/Wikibase/client/tests/phpunit/includes/DataAccess/Scribunto/Scribunto_LuaWikibaseLibraryTest.php:344
14:18:15 /workspace/src/tests/phpunit/MediaWikiTestCase.php:469
14:18:15 /workspace/src/maintenance/doMaintenance.php:94
14:18:15 
14:18:15 2) LuaSandbox: Wikibase\Client\Tests\DataAccess\Scribunto\Scribunto_LuaWikibaseLibraryTest::testRenderSnak_languageFallback with data set #1 (false, array('Q32488#X', 'Q885588#L'))
14:18:15 Failed asserting that Array &0 (
14:18:15     0 => 'Q885588'
14:18:15 ) is identical to Array &0 (
14:18:15     0 => 'Pisîk'
14:18:15 ).
14:18:15 
14:18:15 /workspace/src/extensions/Wikibase/client/tests/phpunit/includes/DataAccess/Scribunto/Scribunto_LuaWikibaseLibraryTest.php:344
14:18:15 /workspace/src/tests/phpunit/MediaWikiTestCase.php:469
14:18:15 /workspace/src/maintenance/doMaintenance.php:94
14:18:15 
14:18:15 3) LuaStandalone: Wikibase\Client\Tests\DataAccess\Scribunto\Scribunto_LuaWikibaseLibraryTest::testRenderSnak_languageFallback with data set #0 (true, array('Q885588#L'))
14:18:15 Failed asserting that Array &0 (
14:18:15     0 => 'Q885588'
14:18:15 ) is identical to Array &0 (
14:18:15     0 => 'Pisîk'
14:18:15 ).
14:18:15 
14:18:15 /workspace/src/extensions/Wikibase/client/tests/phpunit/includes/DataAccess/Scribunto/Scribunto_LuaWikibaseLibraryTest.php:344
14:18:15 /workspace/src/tests/phpunit/MediaWikiTestCase.php:469
14:18:15 /workspace/src/maintenance/doMaintenance.php:94
14:18:15 
14:18:15 4) LuaStandalone: Wikibase\Client\Tests\DataAccess\Scribunto\Scribunto_LuaWikibaseLibraryTest::testRenderSnak_languageFallback with data set #1 (false, array('Q32488#X', 'Q885588#L'))
14:18:15 Failed asserting that Array &0 (
14:18:15     0 => 'Q885588'
14:18:15 ) is identical to Array &0 (
14:18:15     0 => 'Pisîk'
14:18:15 ).
14:18:15 
14:18:15 /workspace/src/extensions/Wikibase/client/tests/phpunit/includes/DataAccess/Scribunto/Scribunto_LuaWikibaseLibraryTest.php:344
14:18:15 /workspace/src/tests/phpunit/MediaWikiTestCase.php:469
14:18:15 /workspace/src/maintenance/doMaintenance.php:94

Failures seem to have nothing to do with WikibaseLexeme neither PropertySuggester. I managed to reproduced them in the non-quibble setup with Wikibase and Scribunto extensions enabled. For easier debugging I disabled WikibaseRepo component, which halved the number of tests run. Failures happen when tests are run like:
php phpunit.php --testsuite extensions --group Database
Running Scribunto_LuaWikibaseLibraryTest::testRenderSnak_languageFallback in isolation does NOT result in failing tests.

Finally, to the point:

• Scribunto_LuaWikibaseLibraryTest "reset" WikibaseClient instance, and override the TermLookup instance of WikibaseClient. The point of this is to "mock" the store and "inject" test data like Q885588 with the said label "Pisîk" in the language "ku-latn".
• "Resetting" WikibaseClient essentially means re-creating the WikibaseClient singleton
• This is a way to "clean up" the WikibaseClient state for the tests, and also is a first step done before overriding services like TermLookup.
• This all seems to be a Wikibase's way of using "fake" data in edge-to-edge kind of tests like the ones testing Scribunto functionality
• Scribunto_LuaWikibaseLibraryTest does its test fixture scaffolding fine, problem arises as Scribunto_LuaWikibaseLibraryTest::testRenderSnak_languageFallback (formatting values in the statement) hits WikibaseClient::getDefaultValueFormatterBuilders which deals with another singleton.
• PropertyParserFunctionIntegrationTest also hits the code path calling WikibaseClient::getDefaultValueFormatterBuilders, which results to formatter builder singleton being instantiated, including WikibaseClient's "default" TermLookup, i.e. the one using database
• When later in the test suite run Scribunto_LuaWikibaseLibraryTest is executed, its resetting WikibaseClient instance has no influence on DefaultValueFormatterBuilders' singleton, i.e. even though Scribunto_LuaWikibaseLibraryTest "overrides" TermLookup instance, the lookup that value formatter will use

I am not 100% decided on what would be the best way out of this singleton issue. I am considering making WikibaseClient::getDefaultValueFormatterBuilders not using the independent singleton, as it seems to be instantiating WikibaseClient any way. I don't see a reason to not use WikibaseClient as a proxy to formatter, instead of having another kind of "singleton cache" (might mean some more function calls to get to the formatter instance, but I am not able to say what kind of performance implications that might have).
Generally, it seems that "resetting" of WikibaseClient singleton for test purposes is a root cause, and it should be replaced with some more reliable and deterministic mechanism.

More details about the newly failing senses tests: https://phabricator.wikimedia.org/T201137

Change 450194 had a related patch set uploaded (by WMDE-leszek; owner: WMDE-leszek):
[mediawiki/extensions/Wikibase@master] Make getDefaultValueFormatterBuilders in sync with WikibaseClient singleton resetting

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

Change 449444 abandoned by Pablo Grass (WMDE):
Skip form add test

Reason:
Root cause resolved in https://phabricator.wikimedia.org/T200693

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

Change 449439 abandoned by Jakob:
DNM WIP Debugging T200693

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

Change 449440 abandoned by Jakob:
DNM Debugging T200693

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

Is there a plan B here? Having a WMF project blocked on CI for over a week is not good. Can we disable these tests in CX until the issue is resolved?

Change 450514 had a related patch set uploaded (by WMDE-leszek; owner: WMDE-leszek):
[integration/config@master] Temporarily exclude WikibaseLexeme from jobs including Wikibase

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

Change 450514 merged by jenkins-bot:
[integration/config@master] Temporarily exclude WikibaseLexeme from jobs including Wikibase

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

@Esanders good points. WMDE is not happy to be in any way blocking other projects. We've been putting quite some effort to fix the issues over last week. We're sad it has not been enough.

Is there some general practice/guidelines here that could be applied? I am especially thinking of a case when (especially unexpected) test failures of extension X cause CI jobs for Y, Z or H to be blocked? We'd happily follow a rule "after N days/hours, the misbehaving test is disabled", or any other reasonable guideline. Does anything like this exist for WMF CI, in any formal or informal form? Pinging @hashar and @greg on this particular topic.

FWIW we're taking WikibaseLexeme out of the CI jobs, so that hopefully lets you go back to normal work.
We'd still appreciate some solid help with T201137.

So https://gerrit.wikimedia.org/r/450514 is deployed and https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-hhvm-docker/9891/console which ran for https://gerrit.wikimedia.org/r/#/c/mediawiki/extensions/ContentTranslation/+/449441/ now fails with Wikibase test failures which can be seen at https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-hhvm-docker/9891/console

This is probably due to the recent ParserOutput / Option changes to do with content language in core, and the ContentLanguage service.

Change 450517 had a related patch set uploaded (by Tarrow; owner: Tarrow):
[mediawiki/extensions/Wikibase@master] Skip failing Lua test to hack around T200693

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

Change 450194 merged by jenkins-bot:
[mediawiki/extensions/Wikibase@master] Make getDefaultValueFormatterBuilders in sync with WikibaseClient singleton resetting

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

Change 450517 abandoned by Tarrow:
Skip failing Lua test to hack around T200693

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

Change 450517 restored by Tarrow:
Skip failing Lua test to hack around T200693

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

It looks like ContentTranslation is unblocked now, I just +2ed https://gerrit.wikimedia.org/r/#/c/mediawiki/extensions/ContentTranslation/+/449441/ to double check.

Change 449443 abandoned by Tarrow:
Skip statement.add browser test

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

Change 449483 abandoned by Tarrow:
WIP DNM Logging for T200693

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

Change 449447 abandoned by Tarrow:
DNM TESTING for T200693

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

Change 450517 abandoned by Tarrow:
Skip failing Lua test to hack around T200693

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

Change 449443 restored by Addshore:
Skip statement.add browser test

Reason:
Restore to test something

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

Change 450044 merged by jenkins-bot:
[mediawiki/extensions/WikibaseLexeme@master] phpunit tests: do not persist in providers

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

Thanks everyone for getting this fixed!

In T200693#4480095, @WMDE-leszek wrote:

Is there some general practice/guidelines here that could be applied? I am especially thinking of a case when (especially unexpected) test failures of extension X cause CI jobs for Y, Z or H to be blocked? We'd happily follow a rule "after N days/hours, the misbehaving test is disabled", or any other reasonable guideline. Does anything like this exist for WMF CI, in any formal or informal form? Pinging @hashar and @greg on this particular topic.

Your proposal sounds reasonable; I can't speak for the language team in this case, but a general guideline would benefit all teams I think, if it doesn't already exist. For the editing team we wouldn't want to go much more than a day without working CI.

Change 450590 had a related patch set uploaded (by Addshore; owner: Addshore):
[integration/config@master] Revert "Temporarily exclude WikibaseLexeme from jobs including Wikibase"

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

Change 450590 merged by jenkins-bot:
[integration/config@master] Revert "Temporarily exclude WikibaseLexeme from jobs including Wikibase"

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

Change 449764 abandoned by Addshore:
DNM Hunting after T200693

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

Change 450054 merged by jenkins-bot:
[mediawiki/extensions/WikibaseLexeme@master] Get rid of Reflection hack used to override factory member

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

Change 449766 abandoned by WMDE-leszek:
DNM Hunting T200693

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