Page MenuHomePhabricator

Warning: Recursion detected in RequestContext::getLanguage in /includes/context/RequestContext.php on line 284
Closed, ResolvedPublic

Description

I thought there was a bug for this, but I can't find it...

Warning: Recursion detected in RequestContext::getLanguage in /usr/local/apache/common-local/php-1.22wmf16/includes/context/RequestContext.php on line 281

The amount of the warnings seems to have increased a lot more in wmf16/wmf17

Such occurrences and stracktraces can be found in logstash with _type: mediawiki and channel: recursion-guard.

Details

Reference
bz54193

Event Timeline

bzimport raised the priority of this task from to High.Nov 22 2014, 1:52 AM
bzimport added a project: MediaWiki-General.
bzimport set Reference to bz54193.
bzimport added a subscriber: Unknown Object (MLST).
Reedy created this task.Sep 16 2013, 11:07 PM

I can't do anything about this without a backtrace. Not sure how to mark that.

Sam, are these still being observed, or have they gone away?

Reedy added a comment.Nov 12 2013, 5:27 PM

Yup, there are these warnings almost always shown in the last 1000 lines of the apache syslogs

Every 2.0s: tail -n 1000 /home/wikipedia/syslog/apache.log | grep -v 'Search backend error' | grep -v -i 'swift' | grep 'PHP\|Segmentation ... Tue Nov 12 22:33:46 2013

240 Warning:  Recursion detected in RequestContext::getLanguage in /usr/local/apache/common-local/php-1.23wmf3/includes/context/RequestContext.php on line 284
 72 Warning:  Recursion detected in RequestContext::getLanguage in /usr/local/apache/common-local/php-1.23wmf2/includes/context/RequestContext.php on line 284
ori added a comment.Nov 21 2013, 12:33 AM

200 of these every hour in /a/mw-log/apache2.log

Would it be possible to provide more information about which wiki(s) display this behavior, or possibly even page(s)?

Being able t reproduce this would probably go a long way towards resolving it.

Side note: the logs this information is extracted from, could we make those more widely available so they could get more eyeballs? From my experience doing this at translatewiki.net it often helps in identifying issues a lot earlier.

Change 96709 had a related patch set uploaded by Ori.livneh:
Enable recursion-guard log bucket to investigate bug 54193

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

Change 96709 merged by Ori.livneh:
Enable recursion-guard log bucket to investigate bug 54193

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

ori added a comment.Nov 21 2013, 11:15 AM

Created attachment 13858
stack trace from fluorine:/a/mw-log/recursion-guard-stack-trace.log

Attached:

ori added a comment.Nov 21 2013, 11:19 AM

(In reply to comment #6)

Would it be possible to provide more information about which wiki(s) display
this behavior, or possibly even page(s)? Being able t reproduce this would
probably go a long way towards resolving it.

I added a trace; additional ones are available in fluorine:/a/mw-log/recursion-guard-stack-trace.log. If you want me to grab additional ones, let me know.

(In reply to comment #7)

Side note: the logs this information is extracted from, could we make those
more widely available so they could get more eyeballs? From my experience
doing this at translatewiki.net it often helps in identifying issues a lot
earlier.

Yeah, fair point. We (platform & ops) are working on setting up a better platform for log analysis, probably using logstash. The current situation sucks.

What a scary backtrace. It seems to relate on automatic creation of local accounts interacting with abuse filter. No wonder it seems to only happen in production.

I have no idea how to fix this. Perhaps automatic local account creation should happen somewhere else?

Given the backtrace, this does not seem to be an i18n issue, except for that the class (Stub)Language is involved at one level. Reclassifying and updating CCs accordingly. Niklas and I will stay on CC.

(In reply to comment #12)

What a scary backtrace. It seems to relate on automatic creation of local
accounts interacting with abuse filter. No wonder it seems to only happen in
production.
I have no idea how to fix this. Perhaps automatic local account creation
should
happen somewhere else?

cc Anomie

So the problem generally appears to be that Language::getLanguage() unstubs the User object by trying to fetch the 'language' pref, and the various hooks called during that process may themselves wind up doing something that tries to call Language::getLanguage(). There are also some instances where something hooking 'UserGetLanguageObject' tries to call getLanguage().

Code paths I see in a quick look through the log include:

  • getLanguage() → Log in from cookies → Trying to get the localized alias for NS_USER on wikis with variants → getLanguage()
    • This seems to be a large number of the instances: srwiki, uzwiktionary, kuwiktionary, etc.
  • getLanguage() → Autocreate account → AbuseFilter's checkNewAccount hook → dividebyzero → Trying to get localized error message → getLanguage()
    • enwiki and eswiki have this
  • getLanguage() → ULS's getLanguage hook → User::saveOptions → BetaFeatures's hook on UserSaveOptions → VisualEditor's onGetBetaPreferences hook or VectorBeta's prefs hook → getLanguage()
  • getLanguage() → Autocreate account → User::saveOptions → BetaFeatures's hook on UserSaveOptions → VisualEditor's onGetBetaPreferences hook or VectorBeta's prefs hook → getLanguage()
  • getLanguage() → Autocreate account → TitleBlacklist hit → Trying to get localized error message → getLanguage()
  • getLanguage() → Autocreate account → NewUserMessage::createNewUserMessage → various different code paths involving the parser and/or MessageCache → getLanguage()

I think that the fallback behavior added in Gerrit change 48080 is probably the best thing to do in general.

BTW, the previous bug on this topic was probably bug 44754.

Yurik added a comment.Dec 18 2013, 9:11 PM

Hiding the warning in fatal monitor with Gerrit change #102557 - the stacktrace logging is still on

Looks like bug 41201 again ("UserLoadFromSession considered evil"). I probably should have pushed that one a bit harder during the CA2 sprint. It should be a pretty simple change for Brad or Chris.

(In reply to Tim Starling from comment #17)

Looks like bug 41201 again ("UserLoadFromSession considered evil"). I
probably should have pushed that one a bit harder during the CA2 sprint. It
should be a pretty simple change for Brad or Chris.

Is it?

Change 174051 had a related patch set uploaded by Ori.livneh:
Avoid calling Title::makeTitleSafe in User::idFromName

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

Change 174051 merged by jenkins-bot:
Avoid calling Title::makeTitleSafe in User::idFromName

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

Change 174057 had a related patch set uploaded by Ori.livneh:
Avoid calling Title::makeTitleSafe in User::idFromName

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

Change 174057 abandoned by Umherirrender:
Avoid calling Title::makeTitleSafe in User::idFromName

Reason:
Old branch, proper fix already in master (Ib902573996c69d1e77527cc7b2faf4e7fa5d3daf)

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

hashar updated the task description. (Show Details)Jun 1 2015, 2:15 PM
hashar set Security to None.
hashar added a subscriber: hashar.

That is still hitting us, stracktraces can be found in logstash with _type: mediawiki and channel: recursion-guard.

Is anyone working on it?

Seems to not be Wikimedia-only, I experience this error too:

Productversion
MediaWiki1.25.2 (9c89a16) 18:08, 3 September 2015
HHVM3.8.1 (srv)
MariaDB10.0.20-MariaDB-0+deb8u1-log

Configuration: https://github.com/miraheze/mw-config/blob/master/LocalSettings.php

#0 /srv/mediawiki/w/includes/StubObject.php(204): RequestContext->getLanguage()
#1 /srv/mediawiki/w/includes/StubObject.php(160): StubUserLang->_newObject()
#2 /srv/mediawiki/w/includes/parser/ParserOptions.php(588): StubObject->_unstub()
#3 /srv/mediawiki/w/includes/cache/MessageCache.php(148): ParserOptions->__construct()
#4 /srv/mediawiki/w/includes/cache/MessageCache.php(988): MessageCache->getParserOptions()
#5 /srv/mediawiki/w/includes/Message.php(1059): MessageCache->transform()
#6 /srv/mediawiki/w/includes/Message.php(726): Message->transformText()
#7 /srv/mediawiki/w/includes/Message.php(789): Message->toString()
#8 /srv/mediawiki/w/includes/User.php(748): Message->text()
#9 /srv/mediawiki/w/includes/User.php(790): User::isUsableName()
#10 /srv/mediawiki/w/extensions/CentralAuth/includes/CentralAuthHooks.php(1082): User::isCreatableName()
#11 /srv/mediawiki/w/extensions/CentralAuth/includes/CentralAuthHooks.php(835): CentralAuthHooks::attemptAddUser()
#12 /srv/mediawiki/w/includes/Hooks.php(209): CentralAuthHooks::onUserLoadFromSession()
#13 /srv/mediawiki/w/includes/User.php(1132): Hooks::run()
#14 /srv/mediawiki/w/includes/User.php(361): User->loadFromSession()
#15 /srv/mediawiki/w/includes/User.php(4942): User->load()
#16 /srv/mediawiki/w/includes/User.php(2587): User->loadOptions()
#17 /srv/mediawiki/w/includes/context/RequestContext.php(342): User->getOption()
#18 /srv/mediawiki/w/includes/Message.php(577): RequestContext->getLanguage()
#19 /srv/mediawiki/w/includes/context/RequestContext.php(436): Message->setContext()
#20 /srv/mediawiki/w/includes/context/ContextSource.php(176): RequestContext->msg()
#21 /srv/mediawiki/w/includes/OutputPage.php(974): ContextSource->msg()
#22 /srv/mediawiki/w/includes/page/Article.php(512): OutputPage->setPageTitle()
#23 /srv/mediawiki/w/includes/actions/ViewAction.php(44): Article->view()
#24 /srv/mediawiki/w/includes/MediaWiki.php(395): ViewAction->show()
#25 /srv/mediawiki/w/includes/MediaWiki.php(273): MediaWiki->performAction()
#26 /srv/mediawiki/w/includes/MediaWiki.php(566): MediaWiki->performRequest()
#27 /srv/mediawiki/w/includes/MediaWiki.php(414): MediaWiki->main()
#28 /srv/mediawiki/w/index.php(41): MediaWiki->run()
#29 {main}
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptSep 3 2015, 7:26 PM
bd808 added a comment.Sep 3 2015, 10:00 PM

Seems to not be Wikimedia-only, I experience this error too:

This looks to be a variant on one of the patterns noted in T56193#554201:

  • getLanguage() → Log in from cookies → User::isUsableName() → Message → getLanguage()

In this particular case, the wfMessage() call is going to be rendered using the inContentLanguage() method but before it can get that far the Parser wants to know the User's language.

The statement of "It should be a pretty simple change for Brad or Chris." in T56193#554221 has thus far proved to be a variant on Fermat's Last Theorem. Many people have looked for the proof but none have yet been able to provide one.

hashar removed a subscriber: hashar.Sep 7 2015, 2:39 PM

@bd808: do you think there is any value in keeping this error message? It seems to me like it's expected behavior at this point and not really valuable.

@bd808: do you think there is any value in keeping this error message? It seems to me like it's expected behavior at this point and not really valuable.

Disabling the log message has been proposed as a patch before (https://gerrit.wikimedia.org/r/#/c/102557/) and @tstarling at that time wanted the message to stay until the underlying bug was fixed.

Got this locally on MediaWiki-Vagrant.

In T56193#2068539, @Mattflaschen wrote:

16 0.8985 8361744 Message->isDisabled( ) ../TitleBlacklist.list.php:98

WTF are you doing there, TitleBlacklist?

Change 273586 had a related patch set uploaded (by Anomie):
Fix 'localpage' message handling

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

Change 273586 merged by jenkins-bot:
Fix 'localpage' message handling

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

tstarling closed this task as Resolved.Feb 21 2017, 1:32 AM
tstarling claimed this task.

No events logged in the recursion-guard channel since December 2016.

mmodell changed the subtype of this task from "Task" to "Production Error".Wed, Aug 28, 11:12 PM