Page MenuHomePhabricator

UserGetLanguageObjectHook is unsafe: "User::loadFromSession called before the end of Setup.php" [8H investigate]
Closed, ResolvedPublic

Description

Error message
User::loadFromSession called before the end of Setup.php
Stack trace
#0 /srv/mediawiki/php-1.36.0-wmf.14/includes/user/User.php(2009): User->load()
#1 /srv/mediawiki/php-1.36.0-wmf.14/includes/user/User.php(2948): User->getId()
#2 /srv/mediawiki/php-1.36.0-wmf.14/includes/user/User.php(2964): User->isRegistered()
#3 /srv/mediawiki/php-1.36.0-wmf.14/extensions/UniversalLanguageSelector/includes/UniversalLanguageSelectorHooks.php(309): User->isAnon()
#4 /srv/mediawiki/php-1.36.0-wmf.14/includes/HookContainer/HookContainer.php(333): UniversalLanguageSelectorHooks::getLanguage(User, string, RequestContext)
#5 /srv/mediawiki/php-1.36.0-wmf.14/includes/HookContainer/HookContainer.php(140): MediaWiki\HookContainer\HookContainer->callLegacyHook(string, array, array, array)
#6 /srv/mediawiki/php-1.36.0-wmf.14/includes/HookContainer/HookRunner.php(4245): MediaWiki\HookContainer\HookContainer->run(string, array)
#7 /srv/mediawiki/php-1.36.0-wmf.14/includes/context/RequestContext.php(370): MediaWiki\HookContainer\HookRunner->onUserGetLanguageObject(User, string, RequestContext)
#8 /srv/mediawiki/php-1.36.0-wmf.14/includes/StubUserLang.php(52): RequestContext->getLanguage()
#9 /srv/mediawiki/php-1.36.0-wmf.14/includes/StubObject.php(172): StubUserLang->_newObject()
#10 /srv/mediawiki/php-1.36.0-wmf.14/includes/StubObject.php(115): StubObject->_unstub(string, integer)
#11 /srv/mediawiki/php-1.36.0-wmf.14/includes/StubObject.php(142): StubObject->_call(string, array)
#12 /srv/mediawiki/php-1.36.0-wmf.14/includes/user/User.php(2749): StubObject->__call(string, array)
#13 /srv/mediawiki/php-1.36.0-wmf.14/languages/Language.php(2234): User->getDatePreference()
#14 /srv/mediawiki/php-1.36.0-wmf.14/languages/Language.php(2340): Language->dateFormat(boolean)
#15 /srv/mediawiki/php-1.36.0-wmf.14/languages/Language.php(4608): Language->timeanddate(string, boolean)
#16 /srv/mediawiki/php-1.36.0-wmf.14/includes/block/BlockErrorFormatter.php(111): Language->formatExpiry(string)
#17 /srv/mediawiki/php-1.36.0-wmf.14/includes/block/BlockErrorFormatter.php(204): MediaWiki\Block\BlockErrorFormatter->getFormattedBlockErrorInfo(MediaWiki\Block\DatabaseBlock, User, LanguageEn)
#18 /srv/mediawiki/php-1.36.0-wmf.14/includes/block/BlockErrorFormatter.php(65): MediaWiki\Block\BlockErrorFormatter->getBlockErrorMessageParams(MediaWiki\Block\DatabaseBlock, User, LanguageEn, string)
#19 /srv/mediawiki/php-1.36.0-wmf.14/includes/auth/CheckBlocksSecondaryAuthenticationProvider.php(92): MediaWiki\Block\BlockErrorFormatter->getMessage(MediaWiki\Block\DatabaseBlock, User, LanguageEn, string)
#20 /srv/mediawiki/php-1.36.0-wmf.14/includes/auth/AuthManager.php(1706): MediaWiki\Auth\CheckBlocksSecondaryAuthenticationProvider->testUserForCreation(User, string, array)
#21 /srv/mediawiki/php-1.36.0-wmf.14/includes/Setup.php(812): MediaWiki\Auth\AuthManager->autoCreateUser(User, string, boolean)
#22 /srv/mediawiki/php-1.36.0-wmf.14/includes/WebStart.php(89): require_once(string)
#23 /srv/mediawiki/php-1.36.0-wmf.14/api.php(43): require(string)
#24 /srv/mediawiki/w/api.php(3): require(string)
#25 {main}

Logstash permalink to example

Impact

The user options are ignored and instead the object is treated is anon/default

Exact impact to-be-determined by maintainers of UniversalLanguageSelector and/or BlockErrorFormatter (I've CC-ed Lang team, and AHT).

Notes

There is effectively a bad loop where during the initialisation of a User object, the BlockErrorFormatter is asking for information from the (same) User object thus causing a paradox. I suspect UniversalLanguageSelector is merely a bystander here, being the first one to call something on the object before it is returned to BlockErrorFormatter, but I'm not 100% sure, it's possible ULS might be inducing it somehow.

See also:

Status

Trying to figure out between Language-Team, Anti-Harassment and Platform Engineering who and how to address this.

Related Objects

Event Timeline

ULS gets a lot of collateral for using the UserGetLanguageObject, where I think it should be safe to except that the User object's methods can be called.

The irony is that the hook doesn't do anything on WMF due to the configuration – other than exposing these bugs.

Rileych added a subscriber: Rileych.

Please ping us (the Language team) if you need our assistance. Thank you!

ULS gets a lot of collateral for using the UserGetLanguageObject, where I think it should be safe to accept that the User object's methods can be called.

It is not safe today because MW supports auto creation, language unstubbing, and Block/Language doing date-formatting based on wgUser global state. So long as two of these three exist, these errors will continue. And I'd say based on that, using this hook in this way is thus not supported by MW today.

But, the use case seems fair to me. I'd recommend working with AHT and/or PET to explain the need so that support for this can be added.

And I'd say based on that, using this hook in this way is thus not supported by MW today.

So in a hook which allows to override the language of an user, one cannot access even the method to determine whether the user is logged in or not to determine whether to override the language. That sounds like a bug to me.

But, the use case seems fair to me. I'd recommend working with AHT and/or PET to explain the need so that support for this can be added.

ULS needs to know whether the user is logged in or not to determine whether to override the user's interface language. Depending on the configuration, it will override the interface language based on a cookie or the Accept-Language request header, but only for logged out users.

I'll ask @Rileych to help coordinate.

Nikerabbit renamed this task from "User::loadFromSession called before the end of Setup.php" warning due to UniversalLanguageSelector to UserGetLanguageObjectHook is unsafe: "User::loadFromSession called before the end of Setup.php".Nov 24 2020, 9:22 AM

@ARamirez_WMF @Naike (cc @Rileych)

Ticket name/link: UserGetLanguageObjectHook is unsafe: "User::loadFromSession called before the end of Setup.php"
What problem is this causing: Main issue is log spam at a rate of almost 100 messages per hour. To our knowledge this does not cause user facing issues, but complicates train deployments by adding noise to the logs.
Which team we need help from: Anti-Harassment and Platform
What we need the other team to do: We need to figure out a solution together to stop the log spam. The solution is not obvious, because it arises from the interaction of multiple different parts of code in MediaWiki core and the Universal Language Selector (ULS). Our opinion is that ULS’s use of the “UserGetLanguageObject” hook should be supported.
How urgent is this/timeline: end of April.
Language team POC: Niklas (@Nikerabbit)

AHaT will be creating a spike to look into this. We'll drag the spike into our next sprint (which starts in 2 weeks).

ARamirez_WMF renamed this task from UserGetLanguageObjectHook is unsafe: "User::loadFromSession called before the end of Setup.php" to UserGetLanguageObjectHook is unsafe: "User::loadFromSession called before the end of Setup.php" [8H].Feb 17 2021, 5:20 PM
ARamirez_WMF renamed this task from UserGetLanguageObjectHook is unsafe: "User::loadFromSession called before the end of Setup.php" [8H] to UserGetLanguageObjectHook is unsafe: "User::loadFromSession called before the end of Setup.php" [8H investigate].Feb 17 2021, 5:23 PM

An updated stack trace, since the line numbers have shifted since the one in the ticket:

from /srv/mediawiki/php-1.36.0-wmf.30/includes/user/User.php(365)
#0 /srv/mediawiki/php-1.36.0-wmf.30/includes/user/User.php(2063): User->load()
#1 /srv/mediawiki/php-1.36.0-wmf.30/includes/user/User.php(3042): User->getId()
#2 /srv/mediawiki/php-1.36.0-wmf.30/includes/user/User.php(3060): User->isRegistered()
#3 /srv/mediawiki/php-1.36.0-wmf.30/extensions/UniversalLanguageSelector/includes/UniversalLanguageSelectorHooks.php(320): User->isAnon()
#4 /srv/mediawiki/php-1.36.0-wmf.30/includes/HookContainer/HookContainer.php(333): UniversalLanguageSelectorHooks::getLanguage(User, string, RequestContext)
#5 /srv/mediawiki/php-1.36.0-wmf.30/includes/HookContainer/HookContainer.php(140): MediaWiki\HookContainer\HookContainer->callLegacyHook(string, array, array, array)
#6 /srv/mediawiki/php-1.36.0-wmf.30/includes/HookContainer/HookRunner.php(4276): MediaWiki\HookContainer\HookContainer->run(string, array)
#7 /srv/mediawiki/php-1.36.0-wmf.30/includes/context/RequestContext.php(392): MediaWiki\HookContainer\HookRunner->onUserGetLanguageObject(User, string, RequestContext)
#8 /srv/mediawiki/php-1.36.0-wmf.30/includes/StubUserLang.php(59): RequestContext->getLanguage()
#9 /srv/mediawiki/php-1.36.0-wmf.30/includes/StubObject.php(179): StubUserLang->_newObject()
#10 /srv/mediawiki/php-1.36.0-wmf.30/includes/StubObject.php(119): StubObject->_unstub(string, integer)
#11 /srv/mediawiki/php-1.36.0-wmf.30/includes/StubObject.php(149): StubObject->_call(string, array)
#12 /srv/mediawiki/php-1.36.0-wmf.30/includes/user/User.php(2844): StubObject->__call(string, array)
#13 /srv/mediawiki/php-1.36.0-wmf.30/languages/Language.php(2235): User->getDatePreference()
#14 /srv/mediawiki/php-1.36.0-wmf.30/languages/Language.php(2341): Language->dateFormat(boolean)
#15 /srv/mediawiki/php-1.36.0-wmf.30/languages/Language.php(4699): Language->timeanddate(string, boolean)
#16 /srv/mediawiki/php-1.36.0-wmf.30/includes/block/BlockErrorFormatter.php(111): Language->formatExpiry(string)
#17 /srv/mediawiki/php-1.36.0-wmf.30/includes/block/BlockErrorFormatter.php(204): MediaWiki\Block\BlockErrorFormatter->getFormattedBlockErrorInfo(MediaWiki\Block\DatabaseBlock, User, LanguageEn)
#18 /srv/mediawiki/php-1.36.0-wmf.30/includes/block/BlockErrorFormatter.php(65): MediaWiki\Block\BlockErrorFormatter->getBlockErrorMessageParams(MediaWiki\Block\DatabaseBlock, User, LanguageEn, string)
#19 /srv/mediawiki/php-1.36.0-wmf.30/includes/auth/CheckBlocksSecondaryAuthenticationProvider.php(92): MediaWiki\Block\BlockErrorFormatter->getMessage(MediaWiki\Block\DatabaseBlock, User, LanguageEn, string)
#20 /srv/mediawiki/php-1.36.0-wmf.30/includes/auth/AuthManager.php(1712): MediaWiki\Auth\CheckBlocksSecondaryAuthenticationProvider->testUserForCreation(User, string, array)
#21 /srv/mediawiki/php-1.36.0-wmf.30/includes/Setup.php(823): MediaWiki\Auth\AuthManager->autoCreateUser(User, string, boolean)
#22 /srv/mediawiki/php-1.36.0-wmf.30/includes/WebStart.php(89): require_once(string)
#23 /srv/mediawiki/php-1.36.0-wmf.30/api.php(43): require(string)
#24 /srv/mediawiki/w/api.php(3): require(string)
#25 {main}

Also, logstash link for the query to find this specific error path: https://logstash.wikimedia.org/goto/8fc2fed8fa16825c2e33762e978671db (just a search for normalized_message:"User::loadFromSession called before the end of Setup.php" AND exception.trace:UniversalLanguageSelectorHooks)

Change 665188 had a related patch set uploaded (by Umherirrender; owner: Umherirrender):
[mediawiki/core@master] Avoid unstubbing user in BlockErrorFormatter::getFormattedBlockErrorInfo

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

Change 665188 merged by jenkins-bot:
[mediawiki/core@master] Avoid unstubbing user in BlockErrorFormatter::getFormattedBlockErrorInfo

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

I haven't been able to recreate the circumstances to reproduce this (can anyone advise me how?), but the patch from @Umherirrender looks as though it should solve the problem.

As previous comments say, the problem appears to be that Language::formatExpiry tries to access the language preferences for the global user (via Language::dateFormat), rather than for the user passed to BlockErrorFormatter::getFormattedBlockErrorInfo, before the global user is initialised.

If I've understood that correctly, then the patch should solve the problem, since it allows the correct user to be passed into Language::formatExpiry.

Either way, we should go ahead with the patch, since it should be possible to pass the correct user to Language::formatExpiry, and one purpose of introducing the BlockErrorFormatter was to avoid accessing the global request context.

If this doesn't solve the issue we may need some advice from someone with a better knowledge of setup.

Yes, it is hard to trigger the error on local wiki. My fix is inspired by the stack trace where the use of global user is shown and that has make problems before when used too early.

The patch solves the problem or it gets a complet different stack trace. It is also possible that other places showing up due to use of the global user in early state.

Let's wait for the next train to get feedback from the logs

Let's wait for the next train to get feedback from the logs

I'll keep this in the QA column for now, until we have some evidence the error is no longer happening.

I couldn't reproduce this bug either.

I did some regression testing of the modified BlockErrorFormatter::getFormattedBlockErrorInfo and Language::formatExpiry functions. The expiry messages look fine on pages like Special:ProtectedTitles, Special:BlockList and in the block message.

Test environments:

I would assume a local ip block which blocks the account creation and a global user without a local account trying to autocreate an account on the first view of that wiki. It is also possible that its a direct link to the edit form with an autoblock/cookieblock for the global user without a local account on that wiki, which also trigger an autocreate.

But that is only a guess, not proved.

I would assume a local ip block which blocks the account creation and a global user without a local account trying to autocreate an account on the first view of that wiki. It is also possible that its a direct link to the edit form with an autoblock/cookieblock for the global user without a local account on that wiki, which also trigger an autocreate.

I tried that when I was testing, but couldn't reproduce.