Page MenuHomePhabricator

PHP Warning: Recursion detected in RequestContext::getLanguage
Closed, ResolvedPublicPRODUCTION ERROR

Description

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.

Notes

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}

Event Timeline

dduvall created this task.Mar 31 2020, 8:16 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptMar 31 2020, 8:16 PM
DannyS712 triaged this task as High priority.
DannyS712 added a subscriber: DannyS712.
Restricted Application added a project: User-DannyS712. · View Herald TranscriptMar 31 2020, 8:19 PM
Jdforrester-WMF raised the priority of this task from High to Unbreak Now!.Mar 31 2020, 8:28 PM
Restricted Application added a subscriber: Liuxinyu970226. · View Herald TranscriptMar 31 2020, 8:28 PM

Change 577687 had a related patch set uploaded (by DannyS712; owner: DannyS712):
[mediawiki/core@master] Add a MessageFactory service to inject a message localizer

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

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.

Change 585033 had a related patch set uploaded (by DannyS712; owner: DannyS712):
[mediawiki/core@master] Use wfMessage in UserNameUtils::isUsable for now

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

daniel added a subscriber: daniel.Mar 31 2020, 8:53 PM

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.

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.

daniel added a comment.EditedMar 31 2020, 8:54 PM

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?

Change 585036 had a related patch set uploaded (by Jforrester; owner: Jforrester):
[mediawiki/core@master] Revert "Add a new UserNameUtils service"

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

Anomie added a subscriber: Anomie.Mar 31 2020, 9:08 PM

Why does this not show up in API integration tests or Selenium tests or some such?

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)
  ...

Why does this not show up in API integration tests or Selenium tests or some such?

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)
  ...

Both of the patches I submitted (just using wfMessage, and adding a proxy service) should fix those by removing the use of RequestContext completely

Change 585033 merged by jenkins-bot:
[mediawiki/core@master] Use wfMessage in UserNameUtils::isUsable for now

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

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

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

Change 585040 merged by jenkins-bot:
[mediawiki/core@wmf/1.35.0-wmf.26] Use wfMessage in UserNameUtils::isUsable for now

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

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)

Catrope closed this task as Resolved.Mar 31 2020, 10:45 PM

Change 585053 had a related patch set uploaded (by Ppchelko; owner: Ppchelko):
[mediawiki/core@master] UserNameUtils: use ITextFormatter instead of MessageLocalizer

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

daniel added a comment.Apr 1 2020, 2:34 PM

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.

Change 585036 abandoned by Ppchelko:
Revert "Add a new UserNameUtils service"

Reason:
A different mitigation was deployed

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

Change 585053 merged by jenkins-bot:
[mediawiki/core@master] UserNameUtils: use ITextFormatter instead of MessageLocalizer

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

DannyS712 moved this task from In progress to Merged on the User-DannyS712 board.May 27 2020, 8:36 AM

Change 577687 abandoned by DannyS712:
[mediawiki/core@master] Add a MessageFactory service to inject a message localizer

Reason:

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

Aklapper removed a subscriber: Anomie.Oct 16 2020, 5:38 PM