AbuseFilterConsequencesTest broken when $wgParsoidSettings['linting'] is set to true
Closed, ResolvedPublic
Actions

Assigned To

Authored By

	kostajh
	Jun 30 2025, 9:22 AM

Description

AbuseFilterConsequencesTest is sensitive to stale state in cached Title objects because it relies on Title::newFromTextThrow() which usues a static cache of Title instances. This can cause test failures if a hook handler from another extension also called Title::newFromText() for the same title, causing the title object to be put into the static cache.

Original report

Seen on unrelated patches in CheckUser just now:

https://integration.wikimedia.org/ci/job/quibble-vendor-mysql-php81/14271/consoleFull

There were 11 failures:
09:17:37 
09:17:37 1) AbuseFilterConsequencesTest::testFilterConsequences with data set "Check that all tags are applied" (array(5), array('edit', 'User:UTSysop', 'Hey.', 'I am a very nice user, really!', ''), array(array(5)))
09:17:37 Expected the action to have the following tags: firstTag, secondTag. Got the following instead: .
09:17:37 
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:710
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:797
Logs generated by test
09:17:37 
09:17:37 2) AbuseFilterConsequencesTest::testFilterConsequences with data set "Check that throttled filters only execute "safe" actions" (array(10), array('edit', 'Buffalo', 'Buffalo', 'Buffalo buffalo Buffalo buffa...ffalo.', 'Buffalo!'), array(array(10)))
09:17:37 Expected the action to have the following tags: testTag. Got the following instead: .
09:17:37 
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:710
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:797
Logs generated by test
09:17:37 
09:17:37 3) AbuseFilterConsequencesTest::testFilterConsequences with data set "Check that every throttled filter only executes "safe" actions" (array(10, 13), array('edit', 'Tyger! Tyger! Burning bright', 'In the forests of the night', 'What immortal hand or eye', 'Could frame thy fearful symmetry?'), array(array(10)))
09:17:37 Expected the action to have the following tags: testTag. Got the following instead: .
09:17:37 
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:710
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:797
Logs generated by test
09:17:37 
09:17:37 4) AbuseFilterConsequencesTest::testStashedEdit with data set #2 ('miss', array(5), array('User:UTSysop', 'Hey.', 'I am a very nice user, really!', ''), array(array(5)))
09:17:37 Expected the action to have the following tags: firstTag, secondTag. Got the following instead: .
09:17:37 
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:710
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:1363
Logs generated by test
09:17:37 
09:17:37 5) AbuseFilterConsequencesTest::testStashedEdit with data set #3 ('hit', array(5), array('User:UTSysop', 'Hey.', 'I am a very nice user, really!', ''), array(array(5)))
09:17:37 Expected the action to have the following tags: firstTag, secondTag. Got the following instead: .
09:17:37 
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:710
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:1363
Logs generated by test
09:17:37 
09:17:37 6) AbuseFilterConsequencesTest::testStashedEdit with data set #10 ('miss', array(10), array('Buffalo', 'Buffalo', 'Buffalo buffalo Buffalo buffa...ffalo.', 'Buffalo!'), array(array(10)))
09:17:37 Expected the action to have the following tags: testTag. Got the following instead: .
09:17:37 
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:710
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:1363
Logs generated by test
09:17:37 
09:17:37 7) AbuseFilterConsequencesTest::testStashedEdit with data set #11 ('hit', array(10), array('Buffalo', 'Buffalo', 'Buffalo buffalo Buffalo buffa...ffalo.', 'Buffalo!'), array(array(10)))
09:17:37 Expected the action to have the following tags: testTag. Got the following instead: .
09:17:37 
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:710
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:1363
Logs generated by test
09:17:37 
09:17:37 8) AbuseFilterConsequencesTest::testStashedEdit with data set #14 ('miss', array(10, 13), array('Tyger! Tyger! Burning bright', 'In the forests of the night', 'What immortal hand or eye', 'Could frame thy fearful symmetry?'), array(array(10)))
09:17:37 Expected the action to have the following tags: testTag. Got the following instead: .
09:17:37 
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:710
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:1363
Logs generated by test
09:17:37 
09:17:37 9) AbuseFilterConsequencesTest::testStashedEdit with data set #15 ('hit', array(10, 13), array('Tyger! Tyger! Burning bright', 'In the forests of the night', 'What immortal hand or eye', 'Could frame thy fearful symmetry?'), array(array(10)))
09:17:37 Expected the action to have the following tags: testTag. Got the following instead: .
09:17:37 
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:710
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:1363
Logs generated by test
09:17:37 
09:17:37 10) AbuseFilterConsequencesTest::testGlobalFilters with data set #1 (array(19), array('edit', 'A global page', 'Foo', 'Bar', 'Baz'), array(array(19)))
09:17:37 Expected the action to have the following tags: globalTag. Got the following instead: .
09:17:37 
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:710
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:1499
Logs generated by test
09:17:37 
09:17:37 11) AbuseFilterConsequencesTest::testGlobalFilters with data set #4 (array(19), array('stashedit', 'Cellar door', '', 'Too many doors', '', 'hit'), array(array(19)))
09:17:37 Expected the action to have the following tags: globalTag. Got the following instead: .
09:17:37 
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:710
09:17:37 /workspace/src/extensions/AbuseFilter/tests/phpunit/AbuseFilterConsequencesTest.php:1499
Logs generated by test
09:17:37 
09:17:37 FAILURES!
09:17:37 Tests: 931, Assertions: 3702, Failures: 11.

Details

Related Changes in Gerrit:

	Subject	Repo	Branch	Lines +/-
	Tests: work around stale Title objects	mediawiki/extensions/AbuseFilter	master	+6 -1
	Revert "REST: Enable wikitext to lint transformations"	mediawiki/core	master	+104 -94

Customize query in gerrit

Related Objects

Mentioned In: T388401: Enable transform/wikitext/to/lint endpoint in production
Mentioned Here: T388401: Enable transform/wikitext/to/lint endpoint in production
rMW46d9bf2930c5: REST: Enable wikitext to lint transformations

Event Timeline

kostajh created this task.Jun 30 2025, 9:22 AM

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJun 30 2025, 9:22 AM

CheckUser CI is broken, so marking this as UBN.

kostajh updated the task description. (Show Details)Jun 30 2025, 9:26 AM

git bisect points to rMW46d9bf2930c5: REST: Enable wikitext to lint transformations / T388401

A_smart_kitten merged a task: T398174: AbuseFilterConsequencesTest blocks CI merges.Jun 30 2025, 9:32 AM

A_smart_kitten added a subscriber: Urbanecm_WMF.

Specifically, this line $wgParsoidSettings['linting'] = true;

Change #1164962 had a related patch set uploaded (by Kosta Harlan; author: Kosta Harlan):

[mediawiki/core@master] Revert "REST: Enable wikitext to lint transformations"

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

gerritbot added a project: Patch-For-Review.Jun 30 2025, 9:33 AM

Michael subscribed.Jun 30 2025, 9:43 AM

In T398175#10957690, @kostajh wrote:

Specifically, this line $wgParsoidSettings['linting'] = true;

Hm.... that's unfortunate. If we can't enable linting per default in DevelopmentSettings, we can't have mocha tests for the endpoint.

I was under the impression that this flag only tells parsoid to collect linter info, I would expect the output to be the same. Do you know why this setting makes AbuseFilterConsequencesTest fail?

Pinging @cscott for ideas.

In T398175#10957747, @daniel wrote:

In T398175#10957690, @kostajh wrote:

Specifically, this line $wgParsoidSettings['linting'] = true;

Hm.... that's unfortunate. If we can't enable linting per default in DevelopmentSettings, we can't have mocha tests for the endpoint.

I was under the impression that this flag only tells parsoid to collect linter info, I would expect the output to be the same. Do you know why this setting makes AbuseFilterConsequencesTest fail?

Pinging @cscott for ideas.

I have no idea. One option would be to update the relevant broken tests to override wgParsoidSettings but that seems like it is masking a deeper problem.

Change #1164962 merged by jenkins-bot:

[mediawiki/core@master] Revert "REST: Enable wikitext to lint transformations"

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

Maintenance_bot removed a project: Patch-For-Review.Jun 30 2025, 10:30 AM

A_smart_kitten merged a task: T398183: AbuseFilter tests are failing in CI.Jun 30 2025, 10:57 AM

A_smart_kitten added a subscriber: ItamarWMDE.

ReleaseTaggerBot added a project: MW-1.45-notes (1.45.0-wmf.8; 2025-07-01).Jun 30 2025, 11:00 AM

This seems to have fixed the tests issues, resolving. Let's re-make the patch in a way that passes through CI in T388401.

daniel mentioned this in T388401: Enable transform/wikitext/to/lint endpoint in production.Jun 30 2025, 12:00 PM

@kostajh What setup did you use for bisect? I can't reproduce the test failure locally, with linting enabled and AbuseFilter and CheckUser loaded.

In T398175#10958310, @daniel wrote:

@kostajh What setup did you use for bisect? I can't reproduce the test failure locally, with linting enabled and AbuseFilter and CheckUser loaded.

FWIW, I quickly tried this and I too can't reproduce locally with r1164962 applied.

wikitext/to/lint doesn't emit any HTML, only generates lints and returns the lint output -- so no tests should be run against this endpoint that require the HTML.

See this Parsoid code and this core code.

Not that that explains why the tests are failing in AbuseFilter which presumably is only invoking the HTML-producing REST API endpoints, but just in case that observation above helps someone debug this.

The AF test in question is only making edits and then checking what change tags were applied to that edit. From a quick look at the code (getActionTags), it grabs the logging entry for the given page with the maximum log_id and matching type. This can obviously fail if tags were not applied, but also if it happens to be picking the wrong log entry. Maybe something to keep in mind, in case something else is say making an edit to the same page.

In T398175#10958528, @ssastry wrote:

wikitext/to/lint doesn't emit any HTML, only generates lints and returns the lint output -- so no tests should be run against this endpoint that require the HTML.

But $wgParsoidSettings['linting'] = true wouldn't interfere with the normal generation of HTML in general, would it? The AbuseFilter test isn't invoking any REST APIs at all, it's checking parser output... $wgParsoidSettings['linting'] = true shouldn't have any effect unless you are actually asking for linter output, right?

In T398175#10958575, @daniel wrote:

In T398175#10958528, @ssastry wrote:

wikitext/to/lint doesn't emit any HTML, only generates lints and returns the lint output -- so no tests should be run against this endpoint that require the HTML.

But $wgParsoidSettings['linting'] = true wouldn't interfere with the normal generation of HTML in general, would it? The AbuseFilter test isn't invoking any REST APIs at all, it's checking parser output... $wgParsoidSettings['linting'] = true shouldn't have any effect unless you are actually asking for linter output, right?

Ya, I agree. I was just pointing that out in case that helped figure out what was going on. For example, if there is something messed up in caching of parser output in test config that would cause abusefilter to fail ... if we can repro this locally, dumping the parser output object that AF sees would provide a clue.

My wild guess would be that Parsoid is logging something (probably something inconsequential) when linting is turned on, and that's interfering with the naive way that the AF test is looking for its log entries:

In T398175#10958561, @Daimona wrote:

The AF test in question is only making edits and then checking what change tags were applied to that edit. From a quick look at the code (getActionTags), it grabs the logging entry for the given page with the maximum log_id and matching type. This can obviously fail if tags were not applied, but also if it happens to be picking the wrong log entry.

I can reproduce by having LocalSettings include:

$wgParsoidSettings['linting'] = true;
wfLoadExtensions( [ 'Linter', 'AbuseFilter', 'CheckUser' ] );

...and running phpunit with --AbuseFilterConsequencesTest and SQLite

I also compared the debug logs:

sudo -u www-data mkdir /tmp-phpunit/debug_logs_lint_off
sudo -u www-data mkdir /tmp-phpunit/debug_logs_lint_on
# Comment out << $wgParsoidSettings['linting'] = true; >> line
sudo -u www-data MW_LOG_DIR=/tmp-phpunit/debug_logs_lint_off vendor/bin/phpunit --filter=AbuseFilterConsequencesTest
# Enable << $wgParsoidSettings['linting'] = true; >> line
sudo -u www-data MW_LOG_DIR=/tmp-phpunit/debug_logs_lint_on vendor/bin/phpunit --filter=AbuseFilterConsequencesTest
# Mask fiddly ms walltime from some logs
cd /tmp-phpunit
cat debug_logs_lint_off/mw-debug-cli.log | sed -E 's/\[[0-9]+\.[0-9]+ms\]//g' | sed -E 's/'\''[0-9]{14}'\''//g' > lint_off.log
cat debug_logs_lint_on/mw-debug-cli.log | sed -E 's/\[[0-9]+\.[0-9]+ms\]//g' | sed -E 's/'\''[0-9]{14}'\''//g' > lint_on.log
meld lint_off lint_on

I see a lot of added lines like:

[objectcache] getWithSetCallback(global:rdbms-server-readonly:localhost): process cache hit
[rdbms] Wikimedia\Rdbms\LoadBalancer::reuseOrOpenConnectionForNewRef: reusing connection for 0/my_wiki-unittest_
[rdbms] MediaWiki\Cache\LinkBatch::doQuery (for MediaWiki\Parser\Parsoid\Config\DataAccess::getPageInfo)  localhost: SELECT  page_id,page_namespace,page_title,page_is_redirect,page_is_new,page_latest,page_touched,page_len,page_content_model  FROM "unittest_page" "page"    WHERE ((page_namespace = 0 AND page_title = 'Test_page'))  
[Linter] MediaWiki\Linter\Hooks::onParserLogLinterData: Recording 0 errors for Test page

ParsoidParser has:

$defaultOptions = [
			'pageBundle' => true,
			'wrapSections' => true,
			'logLinterData' => true,

Also, Parsoid.php has this line (which I can see being hit in xdebug+phpstorm):

		// FIXME: Does this belong in parseWikitext so that the other endpoint
		// is covered as well?  It probably depends on expectations of the
		// Rest API.  If callers of /page/lint/ assume that will update the
		// results on the Special page.
		if ( $env->linting() ) {
			( new LintLogger( $env ) )->logLintOutput();
		}

This triggers onParserLogLinterData, which also triggers RecordLintJob for any current revision parse. I don't see DB updates from setForPage() in the Linter extension, so it must have determined no errors. Still, I don't see why it calls getDBConnectionRef( DB_PRIMARY ) even when it bails early.

@aaron thanks, that helped! Enabling the Linter extension did the trick.

So the test is failign because it's looking up tags for the wrong revision: the page in question has two revisions, 1 and 2. Revision 2 has the tags, revision 1 doesnt. The reason that AbuseFilterConsequencesTest looks up tags for revision 1 is that that's what it's now getting from Title::getCurrentRevID, because it's getting a cached Title instance from the static cache in Title.

Enabling linting causes something (presumably the Linter extension) to construct a Title instance before revision 2 is created. And that instance gets stuck in the cache.

The static cache of Title objects is really a horrible trap...

I'll work on a fix.

daniel updated the task description. (Show Details)Jul 1 2025, 10:53 AM

Change #1165484 had a related patch set uploaded (by Daniel Kinzler; author: Daniel Kinzler):

[mediawiki/extensions/AbuseFilter@master] Tests: work around stale Title objects

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

gerritbot added a project: Patch-For-Review.Jul 1 2025, 10:56 AM

Change #1165484 merged by jenkins-bot: