Page MenuHomePhabricator
Create Task
Maniphest T371460

Build failures from Wikibase\Repo\Tests\ChangeModification\DispatchChangeVisibilityNotificationJobTest::testHandle and Wikibase\Lib\Tests\Store\Sql\SqlChangeStoreTest::testSaveChange_insert
Closed, ResolvedPublicBUG REPORT
Actions

Description

These failing tests from Wikibase are preventing merges in mediawiki/core and other repos:

23:50:47 There were 7 failures:
23:50:47 
23:50:47 1) Wikibase\Repo\Tests\ChangeModification\DispatchChangeVisibilityNotificationJobTest::testHandle with data set "One job with one revision identifier dispatched" (array(array('[{"arrayFormatVersion":1,"ent...":12}]', 1)), array(12), array(array(1, 0)))
23:50:47 jobs for dummywiki
23:50:47 Failed asserting that array contains the expected submap.
23:50:47 --- Expected
23:50:47 +++ Actual
23:50:47 @@ @@
23:50:47  array (
23:50:47 -  0 => 
23:50:47 -  array (
23:50:47 -    'revisionIdentifiersJson' => '[{"arrayFormatVersion":1,"entityIdSerialization":"Q1042","revisionTimestamp":"20230504030201","revisionId":12}]',
23:50:47 -    'visibilityBitFlag' => 1,
23:50:47 -  ),
23:50:47  )
23:50:47 
23:50:47 /workspace/src/tests/phpunit/MediaWikiTestCaseTrait.php:252
23:50:47 /workspace/src/extensions/Wikibase/repo/tests/phpunit/includes/ChangeModification/DispatchChangeVisibilityNotificationJobTest.php:206
23:50:47 phpvfscomposer:///workspace/src/vendor/phpunit/phpunit/phpunit:106
Logs generated by test

Show Details
23:50:47 
23:50:47 2) Wikibase\Repo\Tests\ChangeModification\DispatchChangeVisibilityNotificationJobTest::testHandle with data set "One job with two revision identifiers dispatched" (array(array('[{"arrayFormatVersion":1,"ent...":13}]', 1)), array(12, 13), array(array(1, 0), array(1, 474)))
23:50:47 jobs for dummywiki
23:50:47 Failed asserting that array contains the expected submap.
23:50:47 --- Expected
23:50:47 +++ Actual
23:50:47 @@ @@
23:50:47  array (
23:50:47 -  0 => 
23:50:47 -  array (
23:50:47 -    'revisionIdentifiersJson' => '[{"arrayFormatVersion":1,"entityIdSerialization":"Q1042","revisionTimestamp":"20230504030201","revisionId":12},{"arrayFormatVersion":1,"entityIdSerialization":"Q1042","revisionTimestamp":"20230504030201","revisionId":13}]',
23:50:47 -    'visibilityBitFlag' => 1,
23:50:47 -  ),
23:50:47  )
23:50:47 
23:50:47 /workspace/src/tests/phpunit/MediaWikiTestCaseTrait.php:252
23:50:47 /workspace/src/extensions/Wikibase/repo/tests/phpunit/includes/ChangeModification/DispatchChangeVisibilityNotificationJobTest.php:206
23:50:47 phpvfscomposer:///workspace/src/vendor/phpunit/phpunit/phpunit:106
Logs generated by test

Show Details
23:50:47 
23:50:47 3) Wikibase\Repo\Tests\ChangeModification\DispatchChangeVisibilityNotificationJobTest::testHandle with data set "Two jobs dispatched (different bit flags)" (array(array('[{"arrayFormatVersion":1,"ent...":12}]', 1), array('[{"arrayFormatVersion":1,"ent...":13}]', 6)), array(12, 13), array(array(1, 0), array(6, 2)))
23:50:47 jobs for dummywiki
23:50:47 Failed asserting that array contains the expected submap.
23:50:47 --- Expected
23:50:47 +++ Actual
23:50:47 @@ @@
23:50:47  array (
23:50:47 -  0 => 
23:50:47 -  array (
23:50:47 -    'revisionIdentifiersJson' => '[{"arrayFormatVersion":1,"entityIdSerialization":"Q1042","revisionTimestamp":"20230504030201","revisionId":12}]',
23:50:47 -    'visibilityBitFlag' => 1,
23:50:47 -  ),
23:50:47 -  1 => 
23:50:47 -  array (
23:50:47 -    'revisionIdentifiersJson' => '[{"arrayFormatVersion":1,"entityIdSerialization":"Q1042","revisionTimestamp":"20230504030201","revisionId":13}]',
23:50:47 -    'visibilityBitFlag' => 6,
23:50:47 -  ),
23:50:47  )
23:50:47 
23:50:47 /workspace/src/tests/phpunit/MediaWikiTestCaseTrait.php:252
23:50:47 /workspace/src/extensions/Wikibase/repo/tests/phpunit/includes/ChangeModification/DispatchChangeVisibilityNotificationJobTest.php:206
23:50:47 phpvfscomposer:///workspace/src/vendor/phpunit/phpunit/phpunit:106
Logs generated by test

Show Details
23:50:47 
23:50:47 4) Wikibase\Repo\Tests\ChangeModification\DispatchChangeVisibilityNotificationJobTest::testHandle with data set "Two jobs dispatched (small batch size)" (array(array('[{"arrayFormatVersion":1,"ent...":13}]', 1), array('[{"arrayFormatVersion":1,"ent...":14}]', 1)), array(12, 13, 14), array(array(1, 0), array(1, 2), array(1, 99)), 2)
23:50:47 jobs for dummywiki
23:50:47 Failed asserting that array contains the expected submap.
23:50:47 --- Expected
23:50:47 +++ Actual
23:50:47 @@ @@
23:50:47  array (
23:50:47 -  0 => 
23:50:47 -  array (
23:50:47 -    'revisionIdentifiersJson' => '[{"arrayFormatVersion":1,"entityIdSerialization":"Q1042","revisionTimestamp":"20230504030201","revisionId":12},{"arrayFormatVersion":1,"entityIdSerialization":"Q1042","revisionTimestamp":"20230504030201","revisionId":13}]',
23:50:47 -    'visibilityBitFlag' => 1,
23:50:47 -  ),
23:50:47 -  1 => 
23:50:47 -  array (
23:50:47 -    'revisionIdentifiersJson' => '[{"arrayFormatVersion":1,"entityIdSerialization":"Q1042","revisionTimestamp":"20230504030201","revisionId":14}]',
23:50:47 -    'visibilityBitFlag' => 1,
23:50:47 -  ),
23:50:47  )
23:50:47 
23:50:47 /workspace/src/tests/phpunit/MediaWikiTestCaseTrait.php:252
23:50:47 /workspace/src/extensions/Wikibase/repo/tests/phpunit/includes/ChangeModification/DispatchChangeVisibilityNotificationJobTest.php:206
23:50:47 phpvfscomposer:///workspace/src/vendor/phpunit/phpunit/phpunit:106
Logs generated by test

Show Details
23:50:47 
23:50:47 5) Wikibase\Repo\Tests\ChangeModification\DispatchChangeVisibilityNotificationJobTest::testHandle with data set "Multiple jobs with multiple revisions dispatched" (array(array('[{"arrayFormatVersion":1,"ent...":14}]', 1), array('[{"arrayFormatVersion":1,"ent...":13}]', 6)), array(12, 13, 14), array(array(1, 0), array(6, 2), array(1, 99)))
23:50:47 jobs for dummywiki
23:50:47 Failed asserting that array contains the expected submap.
23:50:47 --- Expected
23:50:47 +++ Actual
23:50:47 @@ @@
23:50:47  array (
23:50:47 -  0 => 
23:50:47 -  array (
23:50:47 -    'revisionIdentifiersJson' => '[{"arrayFormatVersion":1,"entityIdSerialization":"Q1042","revisionTimestamp":"20230504030201","revisionId":12},{"arrayFormatVersion":1,"entityIdSerialization":"Q1042","revisionTimestamp":"20230504030201","revisionId":14}]',
23:50:47 -    'visibilityBitFlag' => 1,
23:50:47 -  ),
23:50:47 -  1 => 
23:50:47 -  array (
23:50:47 -    'revisionIdentifiersJson' => '[{"arrayFormatVersion":1,"entityIdSerialization":"Q1042","revisionTimestamp":"20230504030201","revisionId":13}]',
23:50:47 -    'visibilityBitFlag' => 6,
23:50:47 -  ),
23:50:47  )
23:50:47 
23:50:47 /workspace/src/tests/phpunit/MediaWikiTestCaseTrait.php:252
23:50:47 /workspace/src/extensions/Wikibase/repo/tests/phpunit/includes/ChangeModification/DispatchChangeVisibilityNotificationJobTest.php:206
23:50:47 phpvfscomposer:///workspace/src/vendor/phpunit/phpunit/phpunit:106
Logs generated by test

Show Details
23:50:47 
23:50:47 6) Wikibase\Repo\Tests\ChangeModification\DispatchChangeVisibilityNotificationJobTest::testHandle with data set "One job dispatched, some revisions discarded" (array(array('[{"arrayFormatVersion":1,"ent...":12}]', 1)), array(404, 12, 408), array(array(1, 0), array(1, 0), array(1, 2)))
23:50:47 jobs for dummywiki
23:50:47 Failed asserting that array contains the expected submap.
23:50:47 --- Expected
23:50:47 +++ Actual
23:50:47 @@ @@
23:50:47  array (
23:50:47 -  0 => 
23:50:47 -  array (
23:50:47 -    'revisionIdentifiersJson' => '[{"arrayFormatVersion":1,"entityIdSerialization":"Q1042","revisionTimestamp":"20230504030201","revisionId":12}]',
23:50:47 -    'visibilityBitFlag' => 1,
23:50:47 -  ),
23:50:47  )
23:50:47 
23:50:47 /workspace/src/tests/phpunit/MediaWikiTestCaseTrait.php:252
23:50:47 /workspace/src/extensions/Wikibase/repo/tests/phpunit/includes/ChangeModification/DispatchChangeVisibilityNotificationJobTest.php:206
23:50:47 phpvfscomposer:///workspace/src/vendor/phpunit/phpunit/phpunit:106
Logs generated by test

Show Details
23:50:47 
23:50:47 7) Wikibase\Lib\Tests\Store\Sql\SqlChangeStoreTest::testSaveChange_insert with data set "Simple change" (array('wikibase-item~add', '20230504030201', 'Q21389475', '0', '0', '[]'), Wikibase\Lib\Changes\ItemChange Object (...))
23:50:47 Change time
23:50:47 Failed asserting that 1722376144 matches expected 1683169321.
23:50:47 
23:50:47 /workspace/src/extensions/Wikibase/lib/tests/phpunit/Store/Sql/SqlChangeStoreTest.php:136
23:50:47 phpvfscomposer:///workspace/src/vendor/phpunit/phpunit/phpunit:106
Logs generated by test

Show Details
23:50:47 
23:50:47 FAILURES!
23:50:47 Tests: 15016, Assertions: 63141, Failures: 7, Skipped: 140.

Example failing changes:

Details

Related Changes in Gerrit:
SubjectRepoBranchLines +/-
Don’t call setFakeTime() in data providermediawiki/extensions/MediaModerationmaster+0 -2
DNM: Empty change to test CImediawiki/extensions/Wikibasemaster+0 -0
Customize query in gerrit

Related Objects

Event Timeline

matmarex created this task.Jul 31 2024, 9:01 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJul 31 2024, 9:01 AM
matmarex triaged this task as Unbreak Now! priority.Jul 31 2024, 9:01 AM
Tacsipacsi subscribed.Jul 31 2024, 9:04 AM

Thanks for filing this!

dcausse merged a task: T371459: DispatchChangeVisibilityNotificationJobTest failures with wmf-quibble-vendor-mysql-php74.Jul 31 2024, 9:04 AM
dcausse added a project: MediaWiki-extensions-Wikibase-Repo.
dcausse subscribed.
Dreamy_Jazz subscribed.Jul 31 2024, 9:11 AM

This is also the case in CI for wmf branches.

Lucas_Werkmeister_WMDE claimed this task.Jul 31 2024, 9:14 AM
Lucas_Werkmeister_WMDE added a project: [Archived]Wikidata Dev Team (Wikidata.org Slice).
Lucas_Werkmeister_WMDE moved this task from In Task Breakdown to In Development on the [Archived]Wikidata Dev Team (Wikidata.org Slice) board.
Lucas_Werkmeister_WMDE added a comment.Jul 31 2024, 9:18 AM

So far I can’t reproduce this locally (neither repo/tests/phpunit/includes/ChangeModification/DispatchChangeVisibilityNotificationJobTest.php nor lib/tests/phpunit/Store/Sql/SqlChangeStoreTest.php), even after updating core and Wikibase locally. I guess I need to look closer at the test and see if I can figure out which other extension might be related…

gerritbot added a comment.Jul 31 2024, 9:19 AM

Change #1058569 had a related patch set uploaded (by Lucas Werkmeister (WMDE); author: Lucas Werkmeister (WMDE)):

[mediawiki/extensions/Wikibase@master] DNM: Empty change to test CI

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

gerritbot added a project: Patch-For-Review.Jul 31 2024, 9:19 AM
Jakob_WMDE subscribed.Jul 31 2024, 9:27 AM
WMDE-leszek subscribed.Jul 31 2024, 9:28 AM
matmarex updated the task description. (Show Details)Jul 31 2024, 9:29 AM
Dreamy_Jazz updated the task description. (Show Details)Jul 31 2024, 9:30 AM
Lucas_Werkmeister_WMDE added a comment.Jul 31 2024, 9:32 AM
Show Details
23:50:47 
23:50:47 7) Wikibase\Lib\Tests\Store\Sql\SqlChangeStoreTest::testSaveChange_insert with data set "Simple change" (array('wikibase-item~add', '20230504030201', 'Q21389475', '0', '0', '[]'), Wikibase\Lib\Changes\ItemChange Object (...))
23:50:47 Change time
23:50:47 Failed asserting that 1722376144 matches expected 1683169321.
23:50:47 
23:50:47 /workspace/src/extensions/Wikibase/lib/tests/phpunit/Store/Sql/SqlChangeStoreTest.php:136
23:50:47 phpvfscomposer:///workspace/src/vendor/phpunit/phpunit/phpunit:106

I don’t know where this was copy+pasted from, but this build has the same test fail with different timestamps (even ignoring time zones):

11:07:59 7) Wikibase\Lib\Tests\Store\Sql\SqlChangeStoreTest::testSaveChange_insert with data set "Simple change" (array('wikibase-item~add', '20230504030201', 'Q21389475', '0', '0', '[]'), Wikibase\Lib\Changes\ItemChange Object (...))
11:07:59 Change time
11:07:59 Failed asserting that 1722416751 matches expected 1683169321.

Note that the expected timestamp is identical, though the actual one isn’t. The actual timestamp seems to be the real time when the test runs (see date -d @1722416751); the “expected” timestamp is a seemingly random time in 2023-05-04.

I put “expected” in scare quotes because this test doesn’t really expect a particular timestamp, it initializes it with the current time:

SqlChangeStoreTest
	public function saveChangeInsertProvider() {
		$factory = $this->getEntityChangeFactory();

		$time = wfTimestamp( TS_MW );

		# ...

		return [
			'Simple change' => [
				[
					'change_type' => 'wikibase-item~add',
					'change_time' => $time,
		# ...

I think something must be calling ConvertibleTimestamp::setFakeTime() (which affects wfTimestamp()) and not properly resetting it? And I think that could potentially explain the other test failure too – something in change dispatching might be discarding a change that looks like it’s too old.

Lucas_Werkmeister_WMDE added a comment.Jul 31 2024, 9:35 AM

Okay, gotta be MediaModeration. (I needed to codesearch for the timestamp without dashes.)

$ TZ=UTC date -d @1683169321
Do 4. Mai 03:02:01 UTC 2023
ScanFilesInScanTableTest (a few other files also use this timestamp)
	public function testParseLastCheckedTimestamp( $lastCheckedOptionValue, $expectedLastChecked ) {
		// Fix the current time as the method under test calls ConvertibleTimestamp::time.
		ConvertibleTimestamp::setFakeTime( '20230504030201' );
Lucas_Werkmeister_WMDE added a comment.Jul 31 2024, 9:39 AM

Okay, I can reproduce it locally with:

diff --git a/phpunit.xml.dist b/phpunit.xml.dist
index 863277be2a..aa1b2c6c3c 100644
--- a/phpunit.xml.dist
+++ b/phpunit.xml.dist
@@ -23,6 +23,10 @@
 		<ini name="max_execution_time" value="0" />
 	</php>
 	<testsuites>
+		<testsuite name="T371460">
+			<file>extensions/MediaModeration/tests/phpunit/unit/maintenance/ScanFilesInScanTableTest.php</file>
+			<file>extensions/Wikibase/lib/tests/phpunit/Store/Sql/SqlChangeStoreTest.php</file>
+		</testsuite>
 		<testsuite name="core:unit">
 			<directory>tests/phpunit/unit</directory>
 		</testsuite>
composer run phpunit:entrypoint -- --testsuite T371460
gerritbot added a comment.Jul 31 2024, 9:44 AM

Change #1058572 had a related patch set uploaded (by Lucas Werkmeister (WMDE); author: Lucas Werkmeister (WMDE)):

[mediawiki/extensions/MediaModeration@master] Don’t call setFakeTime() in data provider

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

Lucas_Werkmeister_WMDE added a comment.Jul 31 2024, 9:45 AM

It turns out ScanFilesInScanTableTest.php calls setFakeTime() in a data provider, thus also setting the fake time for all other data providers. (setFakeTime() calls in the actual test function are “protected” by MediaWikiTestCaseTrait::fakeTimestampTearDown() automatically running after every test, but data providers don’t have that; see also T332865: PHPUnit data providers should be simple static functions that return plain data.)

Lucas_Werkmeister_WMDE added a comment.EditedJul 31 2024, 9:57 AM

Apparently the problematic setFakeTime() call has been there since December 2023, so I guess the immediate cause for this bug task is Add MediaModeration to the gated extensions list (T371324).

gerritbot added a comment.Jul 31 2024, 10:04 AM

Change #1058569 abandoned by Lucas Werkmeister (WMDE):

[mediawiki/extensions/Wikibase@master] DNM: Empty change to test CI

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

gerritbot added a comment.Jul 31 2024, 10:10 AM

Change #1058572 merged by jenkins-bot:

[mediawiki/extensions/MediaModeration@master] Don’t call setFakeTime() in data provider

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

Lucas_Werkmeister_WMDE mentioned this in T371467: [GENERAL] Make PHPUnit dataProvider static in Wikibase-related extensions.Jul 31 2024, 10:24 AM
Maintenance_bot removed a project: Patch-For-Review.Jul 31 2024, 10:30 AM
Lucas_Werkmeister_WMDE closed this task as Resolved.Jul 31 2024, 10:46 AM
Lucas_Werkmeister_WMDE moved this task from In Development to Done on the [Archived]Wikidata Dev Team (Wikidata.org Slice) board.

CI is fixed AFAICT; I think if we want to follow-up by forbidding setFakeTime() in data providers in general, we should have a separate task for that.

ReleaseTaggerBot added a project: MW-1.43-notes (1.43.0-wmf.17; 2024-08-06).Jul 31 2024, 11:00 AM
matmarex mentioned this in T371477: Disallow using setFakeTime() in PHPUnit data providers.Jul 31 2024, 11:02 AM

Thank you for debugging @Lucas_Werkmeister_WMDE and @Dreamy_Jazz. I filed the followup task: T371477: Disallow using setFakeTime() in PHPUnit data providers.

matmarex added a project: MediaModeration.Jul 31 2024, 11:06 AM
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL · Credits