Page MenuHomePhabricator

quibble-vendor-mysql-hhvm-docker fails on EchoDiscussionParserTest
Closed, ResolvedPublicPRODUCTION ERROR

Description

Seen on https://gerrit.wikimedia.org/r/c/mediawiki/extensions/WikibaseCirrusSearch/+/496079
and https://gerrit.wikimedia.org/r/c/mediawiki/extensions/WikibaseCirrusSearch/+/496333

07:39:06 1) EchoDiscussionParserTest::testAnnotation with data set #4 ('Bug T78424', array(array(3, 7, array('== Washington Post Reception Source ==', '', '''The Boston Post'' source th... (UTC)'), array('== Washington Post Reception Source ==', '', '''The Boston Post'' source th... (UTC)', '', '== Grand jury no bill reception ==', '', '{{u|Bob K31416}} has started ... (UTC)')), array(4, 4, 'add', '\n== Grand jury no bill recept... (UTC)')), 'Cwobeel', array(array('new-section-with-comment', '== Grand jury no bill recepti... (UTC)')))
07:39:06 === Logs generated by test case
07:39:06 [wfDebug] [debug] User: loading options for user 2 from database. {"private":false}
07:39:06 [wfDebug] [debug] User: cache miss for user 2 {"private":false}
07:39:06 [wfDebug] [debug] User: loading options for user 2 from database. {"private":false}
07:39:06 [GlobalTitleFail] [info] RequestContext::getTitle called by Hooks::callHook/WikimediaEventsHooks::onUserSaveOptions/WikimediaEventsHooks::isKnownSettingsPage/ContextSource->getTitle/RequestContext->getTitle with no title set. {"private":false}
07:39:06 [CentralAuthVerbose] [info] Loading state for global user Cwobeel from DB {"private":false}
07:39:06 [squid] [info] CdnCacheUpdate::purge: http://2a50c4345ab1/index.php/User:Cwobeel http://2a50c4345ab1/index.php?title=User:Cwobeel&action=history {"private":false}
07:39:06 [wfDebug] [debug] IP: 127.0.0.1 {"private":false}
07:39:06 [wfDebug] [debug] User: loading options for user 2 from override cache. {"private":false}
07:39:06 [wfDebug] [debug] User: loading options for user 2 from override cache. {"private":false}
07:39:06 [PHPUnitCommand] [info] FAILURE in EchoDiscussionParserTest::testAnnotation with data set #4: [PHPUnit_Framework_ExpectationFailedException] Bug T78424
07:39:06 Failed asserting that two arrays are equal. {"private":false}
07:39:06 ===
07:39:06 Bug T78424
07:39:06 Failed asserting that two arrays are equal.
07:39:06 --- Expected
07:39:06 +++ Actual
07:39:06 @@ @@
07:39:06  Array (
07:39:06      0 => Array (
07:39:06 -        'type' => 'new-section-with-comment'
07:39:06 +        'type' => 'unknown-unsigned-addition'
07:39:06          'content' => '== Grand jury no bill recepti... (UTC)'
07:39:06      )
07:39:06  )
07:39:06 
07:39:06 /workspace/src/extensions/Echo/tests/phpunit/DiscussionParserTest.php:1249
07:39:06 /workspace/src/tests/phpunit/MediaWikiTestCase.php:425
07:39:06 /workspace/src/maintenance/doMaintenance.php:94
07:39:06 
07:39:06 FAILURES!
07:39:06 Tests: 4435, Assertions: 14950, Failures: 1, Skipped: 39.

Event Timeline

Restricted Application added subscribers: Liuxinyu970226, Aklapper. · View Herald Transcript
hashar added a subscriber: hashar.

tests/phpunit/DiscussionParserTest.php makes expectations which are fine when just running Echo tests, though that should be verified for example by sending a dummy change to Echo and see whether the job passes. I cant tell what is wrong really, might be in Echo or in mediawiki/core, or worse some code added in another extension that end up triggering a condition that this test does not expect :-/

Smalyshev triaged this task as Unbreak Now! priority.Mar 15 2019, 6:16 PM

This is blocking all builds/merges for all extensions.

I'll disable this test, just a moment.

Change 496860 had a related patch set uploaded (by Kosta Harlan; owner: Kosta Harlan):
[mediawiki/extensions/Echo@master] Disable DiscussionParserTest until we can figure out why it broke

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

Change 496860 merged by jenkins-bot:
[mediawiki/extensions/Echo@master] Disable DiscussionParserTest until we can figure out why it broke

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

Jdforrester-WMF lowered the priority of this task from Unbreak Now! to High.Mar 15 2019, 8:50 PM
Jdforrester-WMF removed a project: Patch-For-Review.

Test disabled, so blocker removed; leaving task open for the Growth team to decide what to do next.

This comment was removed by Catrope.

I suspect this is caused by some sort of interference from the CentralAuth extension that breaks DiscussionParserTest::setupTestUser() somehow. This Echo patch that brings back the disabled test cases doesn't fail Jenkins, but this no-op patch in WikibaseCirrusSearch that depends on the Echo patch does fail. I'm now testing whether a no-op patch in CentralAuth also fails this way.

Debugging this is slow going because it's only reproducible in Jenkins (not locally), only through Depends-On patches in certain other extensions (not Echo itself), and the job that runs the tests in question takes 15-20 minutes to run.

I tried debugging this a bit, but I only got as far as finding that the signatures that DiscussionParser looks for do not take into account the test users' custom signatures (the nickname preference), even though the test harness sets it. It looks like the preference changes that the test harness makes get lost somehow. At the time I thought the most likely culprit was CentralAuth.

@kostajh did some great detective work today and found that the culprit (or well, the trigger) appears to be BetaFeatures instead. If BF is installed and at least one extension that registers a beta feature is also installed, BetaFeaturesHooks::updateUserCounts() (which is a UserSaveOptions hook) will do $oldUser = User::newFromName( $user->getName() ); /*... */ $oldUser->getOption( $name );. In Kosta's testing this getOption() call appeared to break things.

Kosta then bisected against MediaWiki core, which pointed him to rMW03908112635f: rdbms: make Database::query() more readable and consistent. I just got quibble set up locally, and I can confirm that the test passes before this change and fails after this change.

I set up my local environment with BetaFeatures, VisualEditor (which has a BetaFeatures preferences hook) Echo and core on HEAD, and set $wgMWLoggerDefaultSpi to log to the console.

Then I did two PHPUnit test runs (extensions/Echo/tests/phpunit --filter testSigningDetection). Test run A results in failing tests. For test run B, I added a continue; just above $oldVal = $oldUser->getOption( $name ) in BetaFeaturesHooks::updateUserCounts(). For both test runs, I piped their output to text files, then I diffed the text files.

In the diff below, the red text represents test run A (failing tests) and green text represents test run B (passing tests, where $oldUser->getOption() does not execute).

@@ -1416,19 +1412,11 @@
 [debug] [DBQuery] default-unittest_ BEGIN /* User::saveSettings root@b7a0196bf8... */ 
 [debug] [DBQuery] BEGIN
 [debug] [DBQuery] startAtomic: entering level 0 (User::saveSettings)
-[debug] [DBQuery] default-unittest_ UPDATE /* User::saveSettings root@b7a0196bf8... */  `unittest_user` SET user_name = 'Werdna3',user_real_name = '',user_email = '',user_email_authenticated = NULL,user_touched = '20190319021333',user_token = '141f6ad9936890a57ae4ec7e711be554',user_email_token = NULL,user_email_token_expires = NULL WHERE user_id = '2' AND user_touched = '20190319021332'
-[debug] [DBQuery] UPDATE  `unittest_user` SET user_name = 'Werdna3',user_real_name = '',user_email = '',user_email_authenticated = NULL,user_touched = '20190319021333',user_token = '141f6ad9936890a57ae4ec7e711be554',user_email_token = NULL,user_email_token_expires = NULL WHERE user_id = '2' AND user_touched = '20190319021332'
+[debug] [DBQuery] default-unittest_ UPDATE /* User::saveSettings root@b7a0196bf8... */  `unittest_user` SET user_name = 'Werdna3',user_real_name = '',user_email = '',user_email_authenticated = NULL,user_touched = '20190319134156',user_token = '771b87476dd806bede75747bbb488df6',user_email_token = NULL,user_email_token_expires = NULL WHERE user_id = '2' AND user_touched = '20190319134155'
+[debug] [DBQuery] UPDATE  `unittest_user` SET user_name = 'Werdna3',user_real_name = '',user_email = '',user_email_authenticated = NULL,user_touched = '20190319134156',user_token = '771b87476dd806bede75747bbb488df6',user_email_token = NULL,user_email_token_expires = NULL WHERE user_id = '2' AND user_touched = '20190319134155'
 [debug] [DBQuery] endAtomic: leaving level 0 (User::saveSettings)
 [debug] [DBQuery] default-unittest_ COMMIT /* User::saveSettings root@b7a0196bf8... */ 
 [debug] [DBQuery] COMMIT
-[debug] User: cache miss for user 2
-[debug] [DBQuery] default-unittest_ SELECT /* User::loadFromDatabase root@b7a0196bf8... */  user_id,user_name,user_real_name,user_email,user_touched,user_token,user_email_authenticated,user_email_token,user_email_token_expires,user_registration,user_editcount  FROM `unittest_user`    WHERE user_id = '2'  LIMIT 1  
-[debug] [DBQuery] SELECT  user_id,user_name,user_real_name,user_email,user_touched,user_token,user_email_authenticated,user_email_token,user_email_token_expires,user_registration,user_editcount  FROM `unittest_user`    WHERE user_id = '2'  LIMIT 1  
-[debug] [DBQuery] default-unittest_ SELECT /* UserGroupMembership::getMembershipsForUser root@b7a0196bf8... */  ug_user,ug_group,ug_expiry  FROM `unittest_user_groups`    WHERE ug_user = '2'  
-[debug] [DBQuery] SELECT  ug_user,ug_group,ug_expiry  FROM `unittest_user_groups`    WHERE ug_user = '2'  
-[debug] User: loading options for user 2 from database.
-[debug] [DBQuery] default-unittest_ SELECT /* User::loadOptions root@b7a0196bf8... */  up_property,up_value  FROM `unittest_user_properties`    WHERE up_user = '2'  
-[debug] [DBQuery] SELECT  up_property,up_value  FROM `unittest_user_properties`    WHERE up_user = '2'  
 [debug] [DBQuery] default-unittest_ SELECT /* User::saveOptions root@b7a0196bf8... */  up_property,up_value  FROM `unittest_user_properties`    WHERE up_user = '2'  
 [debug] [DBQuery] SELECT  up_property,up_value  FROM `unittest_user_properties`    WHERE up_user = '2'  
 [debug] [DBQuery] default-unittest_ INSERT /* User::saveOptions root@b7a0196bf8... */ IGNORE INTO `unittest_user_properties` (up_user,up_property,up_value) VALUES ('2','fancysig','1'),('2','nickname','[[User talk:Werdna3|Andrew]]')
@@ -1436,17 +1424,22 @@
 [debug] [DBQuery] default-unittest_ SELECT /* LinkCache::fetchPageRow root@b7a0196bf8... */  page_id,page_len,page_is_redirect,page_latest,page_restrictions,page_content_model  FROM `unittest_page`    WHERE page_namespace = '2' AND page_title = 'Werdna3'  LIMIT 1  
 [debug] [DBQuery] SELECT  page_id,page_len,page_is_redirect,page_latest,page_restrictions,page_content_model  FROM `unittest_page`    WHERE page_namespace = '2' AND page_title = 'Werdna3'  LIMIT 1  
 [info] [squid] CdnCacheUpdate::purge: http://default.web.mw.localhost:80/mediawiki/index.php/User:Werdna3 http://default.web.mw.localhost:80/mediawiki/index.php?title=User:Werdna3&action=history
-[debug] [session] SessionBackend "mlb53olcham7kt9pu9g7sgfs20vf9lns" is unsaved, marking dirty in constructor
-[debug] [session] SessionBackend "mlb53olcham7kt9pu9g7sgfs20vf9lns" save: dataDirty=1 metaDirty=1 forcePersist=0
+[debug] [session] SessionBackend "6r4h81ltcm3bjp3lmum1404mdjrl7492" is unsaved, marking dirty in constructor
+[debug] [session] SessionBackend "6r4h81ltcm3bjp3lmum1404mdjrl7492" save: dataDirty=1 metaDirty=1 forcePersist=0
 [debug] IP: 127.0.0.1
+[debug] User: cache miss for user 2
+[debug] [DBQuery] default-unittest_ SELECT /* User::loadFromDatabase root@b7a0196bf8... */  user_id,user_name,user_real_name,user_email,user_touched,user_token,user_email_authenticated,user_email_token,user_email_token_expires,user_registration,user_editcount  FROM `unittest_user`    WHERE user_id = '2'  LIMIT 1  
+[debug] [DBQuery] SELECT  user_id,user_name,user_real_name,user_email,user_touched,user_token,user_email_authenticated,user_email_token,user_email_token_expires,user_registration,user_editcount  FROM `unittest_user`    WHERE user_id = '2'  LIMIT 1  
+[debug] [DBQuery] default-unittest_ SELECT /* UserGroupMembership::getMembershipsForUser root@b7a0196bf8... */  ug_user,ug_group,ug_expiry  FROM `unittest_user_groups`    WHERE ug_user = '2'  
+[debug] [DBQuery] SELECT  ug_user,ug_group,ug_expiry  FROM `unittest_user_groups`    WHERE ug_user = '2'  
+[debug] User: loading options for user 2 from database.
+[debug] [DBQuery] default-unittest_ SELECT /* User::loadOptions root@b7a0196bf8... */  up_property,up_value  FROM `unittest_user_properties`    WHERE up_user = '2'  
+[debug] [DBQuery] SELECT  up_property,up_value  FROM `unittest_user_properties`    WHERE up_user = '2'  
 [debug] User: loading options for user 2 from override cache.
-[debug] [DBQuery] default-unittest_ SELECT /* User::idFromName root@b7a0196bf8... */  user_id  FROM `unittest_user`    WHERE user_name = 'Swalling'  LIMIT 1  
-[debug] [DBQuery] SELECT  user_id  FROM `unittest_user`    WHERE user_name = 'Swalling'  LIMIT 1  
 [debug] [DBQuery] default-unittest_ SET /* MediaWikiTestCase::tearDown root@b7a0196bf8... */ sql_mode = ''
 [debug] [DBQuery] SET sql_mode = ''
-[info] [PHPUnitCommand] FAILURE in EchoDiscussionParserTest::testSigningDetection with data set #2: [PHPUnit\Framework\ExpectationFailedException] false does not match expected type "array".
-F[info] [PHPUnitCommand] End test EchoDiscussionParserTest::testSigningDetection with data set #2
-[debug] [DBQuery] default-unittest_ TRUNCATE /* MediaWikiTestCase::truncateTable root@b7a0196bf8... */ TABLE `unittest_user`
+[info] [PHPUnitCommand] End test EchoDiscussionParserTest::testSigningDetection with data set #2
+.[debug] [DBQuery] default-unittest_ TRUNCATE /* MediaWikiTestCase::truncateTable root@b7a0196bf8... */ TABLE `unittest_user`

The two things I see here are:

  1. The timing for when User::loadFromDatabase executes is different between the two test runs. As a result, in the failing test run, User::loadOptions runs _before_ User::saveOptions and so doesn't find the signature.
  2. The failing test executes User::idFromName

@aaron do you have ideas as to what in rMW03908112635f9da82e4e1141cb4ed4838c56a84d might have caused the change in order of execution above, specifically

The timing for when User::loadFromDatabase executes is different between the two test runs. As a result, in the failing test run, User::loadOptions runs _before_ User::saveOptions and so doesn't find the signature.

OK, so moving the set of [$this->lastWriteTime](https://gerrit.wikimedia.org/r/c/mediawiki/core/+/496362/5/includes/libs/rdbms/database/Database.php#1260) and changing the logic of when that is set seems to be responsible. Adding back that line causes tests to pass.

With rMW03908112635f, $this->lastWriteTime is now set based on $isEffectiveWrite which in turn is set by !$this->registerTempTableOperation( $sql );, that evaluates to false so in attemptQuery(), $this->lastWriteTime is not set. Setting $isEffectiveWrite = true just below this line also causes the test to pass.

I'd imagine --use-normal tables would pass and not having that would fail. In production, there is no reason to treat temporary table operations as writes (e.g. for triggering commitMasterChanges as so on). They would just be used for complex reads and accumulated results. For tests, without --use-normal-tables, everything is temporary (though it it's meant to represent permanent stuff). Even still, this rarely matters, though things like User do check hasOrMadeRecentMasterChanges(), which would hit the edge case of everything being temporary (no longer returning true).

If the test framework injected some flag to treat temp tables as permanent ones (except the tests of the temp table logic itself), I guess that would work...though it seem hacky. Always treating them as writes also seems hacky and prone to other bugs (e.g. things using READ_LATEST with DB_MASTER for no reason).

Actually, given the nature of tests all using DB_MASTER, I don't yet see what would be significantly affected here. It can't be hasMasterChanges() since that wouldn't have changed, doneWrites() is not used, lastDoneWrites() is only used by lastMasterChangeTimestamp(). That in turn is used by hasOrMadeRecentMasterChanges() and waitForReplication().

Maybe the User::saveSettings() call has its clearSharedCache() call deferred in the old code, due to hasOrMadeRecentMasterChanges(), but is immediate in the new code. If the tests relied on the old cached value being there, then they could fail.

Change 497685 had a related patch set uploaded (by Aaron Schulz; owner: Aaron Schulz):
[mediawiki/core@master] rdbms: treat cloned temporary tables as "effective write" targets

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

T218388#5036149 debug session by @kostajh is exactly how I used to track those kind of regressions. Namely:

  • clone as few repositories as possible
  • run tests with --filter until a repro is find then either revert/rollback/git bisect or insert print/return/continue statements.
  • log thing and use colordiff (wrapper around diff with ansi coloring) / wdiff (word by word differences, colordiff supports colorizing it). Or: wdiff bad.log good.log | colordiff

Well done!

Change 497685 merged by jenkins-bot:
[mediawiki/core@master] rdbms: treat cloned temporary tables as "effective write" targets

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

Change 499660 had a related patch set uploaded (by Kosta Harlan; owner: Kosta Harlan):
[mediawiki/extensions/Echo@master] Re-enable DiscussionParser tests

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

Change 499660 merged by jenkins-bot:
[mediawiki/extensions/Echo@master] Re-enable DiscussionParser tests

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

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