In addition to the one linked in the task description, failed builds include:

https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-php81/27599/console:

............................................................. 2318 / 3655 ( 63%)
...........................................PHP Fatal error:  Maximum execution time of 120 seconds exceeded in /workspace/src/vendor/wikimedia/remex-html/src/TreeBuilder/ActiveFormattingElements.php on line 52

https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-php81/27615/console:

............................................................. 2318 / 3809 ( 60%)
..............PHP Fatal error:  Maximum execution time of 120 seconds exceeded in /workspace/src/includes/libs/uuid/GlobalIdGenerator.php on line 750

So the error doesn’t always happen in the same test, but it always seems to happen after ca. 2318 tests.

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

[mediawiki/extensions/Wikibase@master] Add debug code for T402390

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

I don’t know where the timeout comes from… in this change I tried to see if there’s a general timeout configured across all the tests, but it doesn’t look like it:

public function testDebugT402390(): void {
	$this->fail( 'max_execution_time is ' . ini_get( 'max_execution_time' ) );
}

There was 1 failure:

1) Wikibase\Repo\Tests\WikibasePingbackTest::testDebugT402390
max_execution_time is 0

My best guess is that it’s “leaking” from some other test which sets the max_execution_time and then fails to reset it… so far the best candidate I’ve found is DatabaseTestHelper, though that hasn’t been touched recently AFAICT.

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

[mediawiki/core@master] DNM: Reset max_execution_time when destructing DatabaseTestHelper

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

In T402390#11102807, @gerritbot wrote:

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

[mediawiki/core@master] DNM: Reset max_execution_time when destructing DatabaseTestHelper

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

Okay, that didn’t help (CI build still had a timeout).

Okay, PS2 of that MediaWiki core change seems to have worked better (the build still failed but only because the $this->fail() was still in there).

diff --git c/tests/phpunit/MediaWikiTestCaseTrait.php w/tests/phpunit/MediaWikiTestCaseTrait.php
index 32149bcae0..16c9bb546d 100644
--- c/tests/phpunit/MediaWikiTestCaseTrait.php
+++ w/tests/phpunit/MediaWikiTestCaseTrait.php
@@ -403,0 +404,9 @@ protected function fakeTimestampTearDown() {
+	/**
+	 * Reset the max_execution_time to unlimited/infinity if any test set it.
+	 *
+	 * @after
+	 */
+	protected function maxExecutionTimeTearDown(): void {
+		ini_set( 'max_execution_time', '0' );
+	}
+

I’m not super thrilled about the idea of adding this overhead to every test, though… it would be nice if we could track down where the time limit comes from and put a stop to it. But so far I haven’t found anything else that matches the 120 seconds.

I’m about to leave for today; if someone urgently needs CI unbroken (as far as I’m aware it’s “only” affecting Wikibase, not MediaWiki core, but I don’t know for sure), it’s probably okay to take the “DNM” out of the commit message of that core change and merge it.

as far as I’m aware it’s “only” affecting Wikibase

https://gerrit.wikimedia.org/r/c/mediawiki/extensions/Math/+/1180252
https://gerrit.wikimedia.org/r/c/mediawiki/extensions/Wikisource/+/1180258
https://gerrit.wikimedia.org/r/c/mediawiki/extensions/InputBox/+/1166294

In T402390#11102791, @Lucas_Werkmeister_WMDE wrote:

My best guess is that it’s “leaking” from some other test which sets the max_execution_time and then fails to reset it…

Alternatively: A test might call set_time_limit() or RequestTimeout::singleton()->setWallTimeLimit(). There...is a surprisingly high number of different ways to ultimately limit the processing time, it seems.

Change #1180675 had a related patch set uploaded (by Urbanecm; author: Urbanecm):

[mediawiki/core@master] [DNM] Verify whether wfTransactionalTimeLimit gets called

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

Change #1180676 had a related patch set uploaded (by Urbanecm; author: Urbanecm):

[mediawiki/extensions/Math@master] [DNM] Testing CI

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

In T402390#11104726, @Urbanecm_WMF wrote:

In T402390#11102791, @Lucas_Werkmeister_WMDE wrote:

My best guess is that it’s “leaking” from some other test which sets the max_execution_time and then fails to reset it…

Alternatively: A test might call set_time_limit() or RequestTimeout::singleton()->setWallTimeLimit(). There...is a surprisingly high number of different ways to ultimately limit the processing time, it seems.

...or wfTransactionalTimeLimit(). Interestingly, that does set the timeout to 120 seconds (at least by default). I've uploaded patches that test that.

Change #1180678 had a related patch set uploaded (by Urbanecm; author: Urbanecm):

[mediawiki/extensions/Wikibase@master] [DNM] Add debug code for T402390

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

In T402390#11104791, @Urbanecm_WMF wrote:

In T402390#11104726, @Urbanecm_WMF wrote:

In T402390#11102791, @Lucas_Werkmeister_WMDE wrote:

My best guess is that it’s “leaking” from some other test which sets the max_execution_time and then fails to reset it…

Alternatively: A test might call set_time_limit() or RequestTimeout::singleton()->setWallTimeLimit(). There...is a surprisingly high number of different ways to ultimately limit the processing time, it seems.

...or wfTransactionalTimeLimit(). Interestingly, that does set the timeout to 120 seconds (at least by default). I've uploaded patches that test that.

...of course it gets called many times, we call it on every writing action. This makes me ask...how/why did this work before?

In T402390#11104726, @Urbanecm_WMF wrote:

In T402390#11102791, @Lucas_Werkmeister_WMDE wrote:

My best guess is that it’s “leaking” from some other test which sets the max_execution_time and then fails to reset it…

Alternatively: A test might call set_time_limit() or RequestTimeout::singleton()->setWallTimeLimit(). There...is a surprisingly high number of different ways to ultimately limit the processing time, it seems.

set_time_limit() just maps to max_execution_time.

php > set_time_limit( 12345 ); echo ini_get( 'max_execution_time' );
12345

RequestTimeout::singleton()->setWallTimeLimit() maps either to Excimer or, if that’s not installed, to max_execution_time again (see RequestTimeout::factory() / BasicRequestTimeout). And wfTransactionalTimeLimit() maps to RequestTimeout. As far as I’m aware it’s really just two underlying mechanisms, accessed in a handful of different ways.

In T402390#11104893, @Urbanecm_WMF wrote:

...of course it gets called many times, we call it on every writing action. This makes me ask...how/why did this work before?

Tests and CI scripts start with no timeout (max_execution_time 0; this is set up in several places), and wfTransactionalTimeLimit() only increases the timeout – if it’s already at infinity, it’s not changed.

Adding to the Omega team’s board for now, though if anyone from other Wikibase teams, or anyone else, wants to help out, that would be useful. (Thanks @Urbanecm_WMF!) So far I’m still not sure how to debug this further.

In T402390#11105639, @Lucas_Werkmeister_WMDE wrote:

So far I’m still not sure how to debug this further.

I’m not sure why this took me so long to figure out, but of course we can do (PS3 of the core change):

	/**
	 * Reset the max_execution_time to unlimited/infinity if any test set it.
	 *
	 * @after
	 */
	protected function maxExecutionTimeTearDown(): void {
		if ( ini_get( 'max_execution_time' ) != '0' ) {
			ini_set( 'max_execution_time', '0' );
			$this->fail( 'This test set max_execution_time without resetting it!' );
		}
	}

And here is one possible culprit:

1. MediaWiki\CheckUser\Tests\Integration\CheckUser\SpecialCheckUserTest::testSubmitFormForGetActionsCheckWithResults

This test set max_execution_time without resetting it!

// Sorting might take some time
// phpcs:ignore Generic.PHP.NoSilencedErrors.Discouraged
@set_time_limit( 60 );

I’d previously found this in codesearch, but discarded it as it’s the wrong limit value (60 ≠ 120 {{cn}}). But I guess something must be multiplying it by 2 or whatever? Or there’s more than one place that sets the time limit (as I’m writing this, the CI build hasn’t finished yet – edit: it’s now finished and found nothing else).

This set_time_limit() call has been in CheckUser, in various forms and places, since 2008. However, it was only this Tuesday that CheckUser’s tests were migrated from Selenium to PHPUnit (cc @Dreamy_Jazz and @mszwarc), so I’m guessing it was previously never reached in a PHPUnit context. This fits the timing of the Wikibase breakage pretty well AFAICT.

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

[mediawiki/extensions/CheckUser@master] Reset time limit (max_execution_time) in SpecialCheckUser tests

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

Thanks for finding this. Who knew that converting flaky selenium tests to PHPUnit would also cause test failures :D.

I've added it to our sprint board so we can provide code review.

Given the CheckUser patch a +2, so moving to Done on our board.

Change #1180587 abandoned by Lucas Werkmeister (WMDE):

[mediawiki/core@master] DNM: Reset max_execution_time after tests

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

Change #1180539 abandoned by Lucas Werkmeister (WMDE):

[mediawiki/extensions/Wikibase@master] Test T402390

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

Change #1180829 merged by jenkins-bot:

[mediawiki/extensions/CheckUser@master] Reset time limit (max_execution_time) in SpecialCheckUser tests

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

Change #1180676 abandoned by Urbanecm:

[mediawiki/extensions/Math@master] [DNM] Testing CI

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

Change #1180675 abandoned by Urbanecm:

[mediawiki/core@master] [DNM] Verify whether wfTransactionalTimeLimit gets called

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

Change #1180678 abandoned by Urbanecm:

[mediawiki/extensions/Wikibase@master] [DNM] Add debug code for T402390

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