@brennen If the volume remains low, feel free to move the train ahead without this. Consider it akin to a deprecation warning. Nothing has changed behaviour this week. We've only added telemetry for an anti-pattern after we fixed all known violations of it. We found two which is great, but we can take a few days to remedy those outside the train blocking path as there is no observable impact or regression here.

Will do, thanks.

@Krinkle going forward, please use "Content-Transform-Team" to ping us for non-Parsoid tasks. We now have a weekly triage meeting for tasks with that intake tag.

IMO if we treat these as telemetry, they should use normal logging, not trigger_error which is not an established pattern for logging known-bad usages (and e.g. on my dev setup is configured to throw exceptions because I want to make sure I don't miss them). the usage in SpecialPageFactory::capturePath doesn't seem easily fixable, either - someone would have to go through all transcludable special pages and make sure they don't access the global context, or call anything that accesses the global context, and then this pattern could be replaced with injecting a custom context into the special page.

(FWIW the search isIncludable|mIncludable|IncludableSpecialPage finds 58 includable special pages. You can also make a special page includable via constructor argument, that's hard to search for.)

(See T290706: Parser code for special page transclusion replaces main context for the details of this issue.)

@Krinkle wrote:

@brennen If the volume remains low, feel free to move the train ahead without this. Consider it akin to a deprecation warning. Nothing has changed behaviour this week. We've only added telemetry for an anti-pattern after we fixed all known violations of it. We found two which is great, but we can take a few days to remedy those outside the train blocking path as there is no observable impact or regression here.

Per discussion, I moved the train forward to group1.

Notices immediately spiked to around 15k before I started a rollback:

2 canaries failed on the deploy - not enough for scap to halt, but enough to give a deployer heartburn:

19:08:27 Check 'Logstash Error rate for mw1415.eqiad.wmnet' failed: ERROR: 60% OVER_THRESHOLD (Avg. Error rate: Before: 0.03, After: 2.50, Threshold: 1.00)                                                                     
19:08:27 Check 'Logstash Error rate for mw1417.eqiad.wmnet' failed: ERROR: 60% OVER_THRESHOLD (Avg. Error rate: Before: 0.01, After: 2.50, Threshold: 1.00)
…
19:08:27 Canary error check failed for 2 canaries, less than threshold to halt deployment (3.25/9), see https://logstash.wikimedia.org for details. Continuing...

...and logspam-watch is noisy enough to be less useful:

⌚ 19:31:06 UTC  distinct errors: 12 😑  total errors: 14791 ☠️
1count  2histo  3first  4last   5exception              6message
14760   ▁▁▁▁▆▇▄ 1831    1929 ◍  Error...............    .10 i/c/RequestContext:311  PHP Notice: Unexpected clearActionName after getActionName already called

This is a high enough volume to interfere with deploy tooling and potentially obscure real errors.

Change 857764 had a related patch set uploaded (by Krinkle; author: Krinkle):

[mediawiki/core@master] specialpage: Silence known violation unsafe RequestContext changes

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

In T323184#8398520, @Tgr wrote:

IMO if we treat these as telemetry, they should use normal logging, not trigger_error which is not an established pattern for logging known-bad usages […]

I think my use of the word telemetry is causing confusion. We're measuring something that will become unsupported. A more common term for this is deprecation or error detection. It is entirely an established pattern in MediaWiki and more generally in software development to issue warnings and other non-fatal log-only errors of this kind when recoverable mistakes or soon-will-be-mistakes are detected in code.

What's also normal and established over the past decade is that we don't issue such "hard" deprecation until after we've eliminated all known usages. And that's exactly what we did. The SpecialPage transclusion mechanism violating this was uncovered only now, after no reports from CI or local dev during the past week(s). It is currently the only known violation of this.

I believe the typical way we address these, whch I'm writing a patch for now, is to either fix, or undeprecate briefly, or silence one-off violations.

In T323184#8398520, @Tgr wrote:

[…] the usage in SpecialPageFactory::capturePath doesn't seem easily fixable, either - someone would have to go through all transcludable special pages and make sure they don't access the global context, or call anything that accesses the global context, and then this pattern could be replaced with injecting a custom context into the special page.

I don't think this is correct. SpecialPage and Action subclasses are context-aware and context-injected by SpecialPageFactory::capturePath and have been for many years. Access to legacy $wg globals is unrelated to this RequestContext restriction. While some indirect utility methods and hooks may be bypassing this, the global context and temporal context are likely equivalent for the purposes of code unrelated to the SpecialPage. Direct access has but a handful of violations in codesearch (6 matching files, of which 5 false positives), that are trivially replaced with $this.

Change 857764 merged by jenkins-bot:

[mediawiki/core@master] specialpage: Silence known violation unsafe RequestContext changes

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

Change 857439 had a related patch set uploaded (by Brennen Bearnes; author: Krinkle):

[mediawiki/core@wmf/1.40.0-wmf.10] specialpage: Silence known violation unsafe RequestContext changes

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

Change 857439 merged by jenkins-bot:

[mediawiki/core@wmf/1.40.0-wmf.10] specialpage: Silence known violation unsafe RequestContext changes

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

Mentioned in SAL (#wikimedia-operations) [2022-11-16T22:27:45Z] <brennen@deploy1002> Started scap: Backport for [[gerrit:857439|specialpage: Silence known violation unsafe RequestContext changes (T323184)]]

Mentioned in SAL (#wikimedia-operations) [2022-11-16T22:28:11Z] <brennen@deploy1002> brennen and brennen: Backport for [[gerrit:857439|specialpage: Silence known violation unsafe RequestContext changes (T323184)]] synced to the testservers: mwdebug1001.eqiad.wmnet, mwdebug1002.eqiad.wmnet, mwdebug2002.codfw.wmnet, mwdebug2001.codfw.wmnet

Mentioned in SAL (#wikimedia-operations) [2022-11-16T22:33:35Z] <brennen@deploy1002> Finished scap: Backport for [[gerrit:857439|specialpage: Silence known violation unsafe RequestContext changes (T323184)]] (duration: 05m 50s)

Seeing a bunch of these (12k and counting) after rolling back to group1; think I missed this as a separate error earlier:

Error

• mwversion: 1.40.0-wmf.10
• reqId: f3d1d64d-5d64-4af0-af70-6c7fc3aad209
• Find reqId in Logstash

[{reqId}] {exception_url}   PHP Notice: Unexpected clearActionName after getActionName already called

from /srv/mediawiki/php-1.40.0-wmf.10/includes/context/RequestContext.php(311)
#0 [internal function]: MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 /srv/mediawiki/php-1.40.0-wmf.10/includes/context/RequestContext.php(311): trigger_error(string)
#2 /srv/mediawiki/php-1.40.0-wmf.10/includes/context/RequestContext.php(176): RequestContext->clearActionName()
#3 /srv/mediawiki/php-1.40.0-wmf.10/includes/MediaWiki.php(483): RequestContext->setTitle(Title)
#4 /srv/mediawiki/php-1.40.0-wmf.10/includes/MediaWiki.php(315): MediaWiki->initializeArticle()
#5 /srv/mediawiki/php-1.40.0-wmf.10/includes/MediaWiki.php(901): MediaWiki->performRequest()
#6 /srv/mediawiki/php-1.40.0-wmf.10/includes/MediaWiki.php(559): MediaWiki->main()
#7 /srv/mediawiki/php-1.40.0-wmf.10/index.php(50): MediaWiki->run()
#8 /srv/mediawiki/php-1.40.0-wmf.10/index.php(46): wfIndexMain()
#9 /srv/mediawiki/w/index.php(3): require(string)
#10 {main}

Searching logstash on the trace suggests that these are most of the notices.

I will likely roll back to group0 out of an abundance of caution before I go AFK for the day, just due to the volume, but I'm assuming these can also be trivially silenced.

In T323184#8400610, @Krinkle wrote:

I believe the typical way we address these, whch I'm writing a patch for now, is to either fix, or undeprecate briefly, or silence one-off violations.

Right, the point I was trying to make is that we should undeprecate (I guess I'm less optimistic about the "briefly" part); of course the other options work too. Thanks for patching!

In T323184#8398520, @Tgr wrote:

I don't think this is correct. SpecialPage and Action subclasses are context-aware and context-injected by SpecialPageFactory::capturePath and have been for many years. Access to legacy $wg globals is unrelated to this RequestContext restriction. While some indirect utility methods and hooks may be bypassing this, the global context and temporal context are likely equivalent for the purposes of code unrelated to the SpecialPage. Direct access has but a handful of violations in codesearch (6 matching files, of which 5 false positives), that are trivially replaced with $this.

Accessing the request context can happen anywhere in a service or helper invoked by the special page, not just the special page itself. It can also happen during service initialization (SpecialPageFactory::capturePath changes the context object in-place, so if something already held an instance of it, but not the request/user/etc, that's also affected). That's something like 150 instances to review, at a glance.

In T323184#8401081, @brennen wrote:

Seeing a bunch of these (12k and counting) after rolling back to group1; think I missed this as a separate error earlier:

Can confirm locally. I think it happens when the action is initialized (via RequestContext::getAction or RequestContext::getActionName) in the InitializeArticleMaybeRedirect hook, but then the article is not a redirect (so the // Article may have been changed by hook branch is followed in MediaWiki::initializeArticle).
Specifically, FlaggedRevs does that via FlaggedRevsUIHooks::overrideRedirect -> FlaggablePageView::showingStable -> FlaggablePageView::isDefaultPageView as the stable version is only supposed to be shown on view and similar actions.

None of the four implementers of that hook change the article, and it doesn't seem like a reasonable thing to do, so I think that branch can just be dropped. Although that wouldn't prevent this error when FlaggedRevs is present and the page is a redirect.

Change 858109 had a related patch set uploaded (by Gergő Tisza; author: Gergő Tisza):

[mediawiki/core@master] InitializeArticleMaybeRedirect hook: Improve docs & restrict

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

In T323184#8401376, @Tgr wrote:

[…] Although that wouldn't prevent this error when FlaggedRevs is present and the page is a redirect.

Ack, this is a genuine bug imho and exactly the sort of thing we want to find. I.e. code passed around or otherwise inspected the determined action, but then later changes the title and thus the content model and associated action overriddes. Either it needs to opt-out from the title change, or needs to do so without needing to vary by action as that's recursive/paradoxal.

These should be rare enough that we can have those few deprecations in the logs while we patch those out. I'll prepare an un-deprecate just in case.

Change 858109 merged by jenkins-bot:

[mediawiki/core@master] InitializeArticleMaybeRedirect hook: Improve docs & restrict

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

Not sure if a new ticket should be opened or this is an expected behavior, but we are observing the same issue on REL1_39, when visiting a page with the following content
https://github.com/wikimedia/mediawiki/blame/db9361491a7737684e607d6b383ea50488ff2106/includes/context/RequestContext.php#L172

{|
| style="border-top: 2px solid #4a4056; padding: 5px 15px 10px 15px; vertical-align:top;" |<h3>Wiki Activity</h3>
{{Special:RecentChanges/days=7,limit=10,hidebots,hideminor}}
|}

Log

#0 /var/www/wiki/includes/context/RequestContext.php(185): RequestContext->clearActionName()
#1 /var/www/wiki/includes/specialpage/SpecialPageFactory.php(1483): RequestContext->setTitle()
#2 /var/www/wiki/includes/parser/Parser.php(3222): MediaWiki\SpecialPage\SpecialPageFactory->capturePath()
#3 /var/www/wiki/includes/parser/PPFrame_Hash.php(276): Parser->braceSubstitution()
#4 /var/www/wiki/includes/parser/Parser.php(2954): PPFrame_Hash->expand()
#5 /var/www/wiki/includes/parser/Parser.php(1609): Parser->replaceVariables()
#6 /var/www/wiki/includes/parser/Parser.php(723): Parser->internalParse()
#7 /var/www/wiki/includes/content/WikitextContentHandler.php(301): Parser->parse()
#8 /var/www/wiki/includes/content/ContentHandler.php(1721): WikitextContentHandler->fillParserOutput()
#9 /var/www/wiki/includes/content/Renderer/ContentRenderer.php(47): ContentHandler->getParserOutput()
#10 /var/www/wiki/includes/Revision/RenderedRevision.php(266): MediaWiki\Content\Renderer\ContentRenderer->getParserOutput()
#11 /var/www/wiki/includes/Revision/RenderedRevision.php(237): MediaWiki\Revision\RenderedRevision->getSlotParserOutputUncached()
#12 /var/www/wiki/includes/Revision/RevisionRenderer.php(221): MediaWiki\Revision\RenderedRevision->getSlotParserOutput()
#13 /var/www/wiki/includes/Revision/RevisionRenderer.php(158): MediaWiki\Revision\RevisionRenderer->combineSlotOutput()
#14 [internal function]: MediaWiki\Revision\RevisionRenderer->MediaWiki\Revision\{closure}()
#15 /var/www/wiki/includes/Revision/RenderedRevision.php(199): call_user_func()
#16 /var/www/wiki/includes/poolcounter/PoolWorkArticleView.php(91): MediaWiki\Revision\RenderedRevision->getRevisionParserOutput()
#17 /var/www/wiki/includes/poolcounter/PoolWorkArticleViewCurrent.php(97): PoolWorkArticleView->renderRevision()
#18 /var/www/wiki/includes/poolcounter/PoolCounterWork.php(162): PoolWorkArticleViewCurrent->doWork()
#19 /var/www/wiki/includes/page/ParserOutputAccess.php(299): PoolCounterWork->execute()
#20 /var/www/wiki/includes/page/Article.php(714): MediaWiki\Page\ParserOutputAccess->getParserOutput()
#21 /var/www/wiki/includes/page/Article.php(528): Article->generateContentOutput()
#22 /var/www/wiki/includes/actions/ViewAction.php(78): Article->view()
#23 /var/www/wiki/includes/MediaWiki.php(542): ViewAction->show()
#24 /var/www/wiki/includes/MediaWiki.php(322): MediaWiki->performAction()
#25 /var/www/wiki/includes/MediaWiki.php(904): MediaWiki->performRequest()
#26 /var/www/wiki/includes/MediaWiki.php(562): MediaWiki->main()
#27 /var/www/wiki/index.php(50): MediaWiki->run()
#28 /var/www/wiki/index.php(46): wfIndexMain()
#29 {main}

Though the page is generated fine even with the error