Error
MediaWiki version: 1.35.0-wmf.26
message
PHP Warning: Recursion detected in RequestContext::getLanguage
Impact
Significant error rate increase following testwiki deployment. No production impact beyond testwiki and log spam.
Description
Description
Details
Details
- Request ID
- XoOknQpAAL8AA4@boCkAAAAP
- Request URL
- https://test.wikipedia.org/w/index.php?title=User:SR5/test3.js&action=raw&ctype=text/javascript
Stack Trace
exception.trace
#0 [internal function]: MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 /srv/mediawiki/php-1.35.0-wmf.26/includes/context/RequestContext.php(334): trigger_error(string, integer)
#2 /srv/mediawiki/php-1.35.0-wmf.26/includes/language/Message.php(721): RequestContext->getLanguage()
#3 /srv/mediawiki/php-1.35.0-wmf.26/includes/context/RequestContext.php(443): Message->setContext(RequestContext)
#4 /srv/mediawiki/php-1.35.0-wmf.26/includes/user/UserNameUtils.php(178): RequestContext->msg(string)
#5 /srv/mediawiki/php-1.35.0-wmf.26/includes/user/UserNameUtils.php(280): MediaWiki\User\UserNameUtils->isUsable(string)
#6 /srv/mediawiki/php-1.35.0-wmf.26/includes/user/User.php(1147): MediaWiki\User\UserNameUtils->getCanonical(string, string)
#7 /srv/mediawiki/php-1.35.0-wmf.26/includes/user/User.php(539): User::getCanonicalName(string, string)
#8 /srv/mediawiki/php-1.35.0-wmf.26/includes/session/UserInfo.php(104): User::newFromName(string, string)
#9 /srv/mediawiki/php-1.35.0-wmf.26/extensions/CentralAuth/includes/session/CentralAuthSessionProvider.php(203): MediaWiki\Session\UserInfo::newFromName(string, boolean)
#10 /srv/mediawiki/php-1.35.0-wmf.26/includes/session/SessionManager.php(466): CentralAuthSessionProvider->provideSessionInfo(WebRequest)
#11 /srv/mediawiki/php-1.35.0-wmf.26/includes/session/SessionManager.php(191): MediaWiki\Session\SessionManager->getSessionInfoForRequest(WebRequest)
#12 /srv/mediawiki/php-1.35.0-wmf.26/includes/WebRequest.php(810): MediaWiki\Session\SessionManager->getSessionForRequest(WebRequest)
#13 /srv/mediawiki/php-1.35.0-wmf.26/includes/user/User.php(1169): WebRequest->getSession()
#14 /srv/mediawiki/php-1.35.0-wmf.26/includes/user/User.php(341): User->loadDefaults()
#15 /srv/mediawiki/php-1.35.0-wmf.26/includes/user/User.php(5066): User->load()
#16 /srv/mediawiki/php-1.35.0-wmf.26/includes/user/User.php(2889): User->loadOptions()
#17 /srv/mediawiki/php-1.35.0-wmf.26/includes/context/RequestContext.php(351): User->getOption(string)
#18 /srv/mediawiki/php-1.35.0-wmf.26/includes/language/Message.php(721): RequestContext->getLanguage()
#19 /srv/mediawiki/php-1.35.0-wmf.26/includes/context/RequestContext.php(443): Message->setContext(RequestContext)
#20 /srv/mediawiki/php-1.35.0-wmf.26/includes/user/UserNameUtils.php(178): RequestContext->msg(string)
#21 /srv/mediawiki/php-1.35.0-wmf.26/includes/user/User.php(993): MediaWiki\User\UserNameUtils->isUsable(string)
#22 /srv/mediawiki/php-1.35.0-wmf.26/extensions/CentralAuth/includes/session/CentralAuthSessionProvider.php(166): User::isUsableName(string)
#23 /srv/mediawiki/php-1.35.0-wmf.26/includes/session/SessionManager.php(466): CentralAuthSessionProvider->provideSessionInfo(WebRequest)
#24 /srv/mediawiki/php-1.35.0-wmf.26/includes/session/SessionManager.php(191): MediaWiki\Session\SessionManager->getSessionInfoForRequest(WebRequest)
#25 /srv/mediawiki/php-1.35.0-wmf.26/includes/WebRequest.php(810): MediaWiki\Session\SessionManager->getSessionForRequest(WebRequest)
#26 /srv/mediawiki/php-1.35.0-wmf.26/includes/session/SessionManager.php(129): WebRequest->getSession()
#27 /srv/mediawiki/php-1.35.0-wmf.26/includes/Setup.php(720): MediaWiki\Session\SessionManager::getGlobalSession()
#28 /srv/mediawiki/php-1.35.0-wmf.26/includes/WebStart.php(89): require_once(string)
#29 /srv/mediawiki/php-1.35.0-wmf.26/index.php(44): require(string)
#30 /srv/mediawiki/w/index.php(3): require(string)
#31 {main}Customize query in gerrit
| Status | Subtype | Assigned | Task | ||
|---|---|---|---|---|---|
| Resolved | Release | • dduvall | T247773 1.35.0-wmf.26 deployment blockers | ||
| Resolved | PRODUCTION ERROR | DannyS712 | T249045 PHP Warning: Recursion detected in RequestContext::getLanguage | ||
| Resolved | Jrbranaa | T249645 Train Blocker UBN - T249045 - Retrospective |
Event Timeline
Comment Actions
Change 577687 had a related patch set uploaded (by DannyS712; owner: DannyS712):
[mediawiki/core@master] Add a MessageFactory service to inject a message localizer
Comment Actions
The normal approach would be to revert the patch, but reverting rMW23242d04d1dc: Add a new UserNameUtils service looks moderately painful; however, merging MessageFactory and rushing it out feels not ideal.
Comment Actions
Change 585033 had a related patch set uploaded (by DannyS712; owner: DannyS712):
[mediawiki/core@master] Use wfMessage in UserNameUtils::isUsable for now
Comment Actions
Considering that the new service class is < 10 actual lines of code, it may still be the best option. If it's known to actually fix the issue.
Comment Actions
I'm wondering how we could test for this kind of problem. Why does this not show up in API integration tests or Selenium tests or some such?
Comment Actions
Change 585036 had a related patch set uploaded (by Jforrester; owner: Jforrester):
[mediawiki/core@master] Revert "Add a new UserNameUtils service"
Comment Actions
Note this isn't actually a thrown exception, it's just a log that uses an unthrown exception to produce a trace. Looks like it gets written as warning-level to the 'error' channel and info-level to the 'recursion-guard' channel. Do those tests check those log channels?
Locally I also see a lot of info-level messages to GlobalTitleFail that begin like
2020-03-31 17:03:26 [eb484a2c5485f265aca87719] GlobalTitleFail INFO: RequestContext::getTitle called with no title set. [Exception Exception] (/usr/local/src/MediaWiki/core/includes/context/RequestContext.php:175) #0 /usr/local/src/MediaWiki/core/includes/language/Message.php(722): RequestContext->getTitle() #1 /usr/local/src/MediaWiki/core/includes/context/RequestContext.php(443): Message->setContext(RequestContext) #2 /usr/local/src/MediaWiki/core/includes/user/UserNameUtils.php(178): RequestContext->msg(string) #3 /usr/local/src/MediaWiki/core/includes/user/User.php(993): MediaWiki\User\UserNameUtils->isUsable(string) ...
and an info-level to 'session' like
2020-03-31 17:03:26 [eb484a2c5485f265aca87719] session WARNING: User::loadFromSession called before the end of Setup.php [Exception Exception] (/usr/local/src/MediaWiki/core/includes/user/User.php:339) User::loadFromSession called before the end of Setup.php #0 /usr/local/src/MediaWiki/core/includes/user/User.php(5066): User->load() #1 /usr/local/src/MediaWiki/core/includes/user/User.php(2889): User->loadOptions() #2 /usr/local/src/MediaWiki/core/includes/context/RequestContext.php(351): User->getOption(string) #3 /usr/local/src/MediaWiki/core/includes/language/Message.php(721): RequestContext->getLanguage() #4 /usr/local/src/MediaWiki/core/includes/context/RequestContext.php(443): Message->setContext(RequestContext) #5 /usr/local/src/MediaWiki/core/includes/user/UserNameUtils.php(178): RequestContext->msg(string) #6 /usr/local/src/MediaWiki/core/includes/user/User.php(993): MediaWiki\User\UserNameUtils->isUsable(string) ...
Comment Actions
Both of the patches I submitted (just using wfMessage, and adding a proxy service) should fix those by removing the use of RequestContext completely
Comment Actions
Change 585033 merged by jenkins-bot:
[mediawiki/core@master] Use wfMessage in UserNameUtils::isUsable for now
Comment Actions
Change 585040 had a related patch set uploaded (by Jforrester; owner: DannyS712):
[mediawiki/core@wmf/1.35.0-wmf.26] Use wfMessage in UserNameUtils::isUsable for now
Comment Actions
Change 585040 merged by jenkins-bot:
[mediawiki/core@wmf/1.35.0-wmf.26] Use wfMessage in UserNameUtils::isUsable for now
Comment Actions
Mentioned in SAL (#wikimedia-operations) [2020-03-31T21:46:26Z] <jforrester@deploy1001> Synchronized php-1.35.0-wmf.26/includes/user/UserNameUtils.php: T249045 Use wfMessage in UserNameUtils::isUsable for now (duration: 00m 58s)
Comment Actions
Change 585053 had a related patch set uploaded (by Ppchelko; owner: Ppchelko):
[mediawiki/core@master] UserNameUtils: use ITextFormatter instead of MessageLocalizer
Comment Actions
From looking at the stack trace, this is another instance of lazy-instantiation leading to unpredictable behavior during the initialization phase: For creating a session, we need to validate a user name. Name validation depends on system messages (in the content language) which we get from MessageLocalizer - this is the bit that the patches above are fixing, but it's not problematic by itself. MessageLocalizer however defaults to the user's interface language and tries to determine it first. However, determining the user language causes the so-far-uninitialiezd User object to be initialized, which again leads to session initialization (we have already gone full circle at this point, but this has not yet detected), which again wants to check for user name validity, which uses MessageLocalizer.
To reproduce this, a test would have to attempt session initialization with GlobalAuth enabled and the User object still uninitialized. It's unlikely that we would catch such a case with a unit test - in fact, unit tests are generally designed to bypass any such setup.
The only way I see to catch this kind of this is to run end-to-end tests against a production-like environment. I don't see a way to do this before we merge, but it could be done before we deploy, see T248683: Create and run a suite of end-to-end tests for the Wikimedia environment.
Comment Actions
Change 585036 abandoned by Ppchelko:
Revert "Add a new UserNameUtils service"
Reason:
A different mitigation was deployed
Comment Actions
Change 585053 merged by jenkins-bot:
[mediawiki/core@master] UserNameUtils: use ITextFormatter instead of MessageLocalizer
Comment Actions
Change 577687 abandoned by DannyS712:
[mediawiki/core@master] Add a MessageFactory service to inject a message localizer
Reason: