Page MenuHomePhabricator

"User::loadFromSession called before the end of Setup.php" warning due to AbuseFilter
Open, NormalPublic

Description

Details

@Krinkle wrote:

This happens on page views when the user visits a wiki besides the one they created their account on, for the first time, >which results in local "autocreation" via CentralAuth, which then runs through AbuseFilter rules.
The warning in question is non-fatal and does visibly affect the page view for the end-user.
However it does mean the AbuseFilter rules are likely not actually working correctly, which could cause certain "abuse" to not be "filtered" due to this bug.

Error

Caused by AbuseFilter::executeFilterActions parsing the custom AF warning message on [auto]createaccount filter checks.

WARNING User::loadFromSession called before the end of Setup.php

#0 /srv/mediawiki/php-1.31.0-wmf.1/includes/user/User.php(5269): User->load()
#1 /srv/mediawiki/php-1.31.0-wmf.1/includes/user/User.php(2887): User->loadOptions()
#2 /srv/mediawiki/php-1.31.0-wmf.1/includes/context/RequestContext.php(364): User->getOption(string)
#3 /srv/mediawiki/php-1.31.0-wmf.1/includes/StubObject.php(205): RequestContext->getLanguage()
#4 /srv/mediawiki/php-1.31.0-wmf.1/includes/StubObject.php(167): StubUserLang->_newObject()
#5 /srv/mediawiki/php-1.31.0-wmf.1/includes/StubObject.php(110): StubObject->_unstub(string, integer)
#6 /srv/mediawiki/php-1.31.0-wmf.1/includes/StubObject.php(137): StubObject->_call(string, array)
#7 /srv/mediawiki/php-1.31.0-wmf.1/includes/parser/Parser.php(2108): StubObject->__call(string, array)
#8 /srv/mediawiki/php-1.31.0-wmf.1/includes/parser/Parser.php(2073): Parser->replaceInternalLinks2(string)
#9 /srv/mediawiki/php-1.31.0-wmf.1/includes/parser/Parser.php(1302): Parser->replaceInternalLinks(string)
#10 /srv/mediawiki/php-1.31.0-wmf.1/includes/parser/Parser.php(451): Parser->internalParse(string)
#11 /srv/mediawiki/php-1.31.0-wmf.1/includes/OutputPage.php(1952): Parser->parse(string, Title, ParserOptions, boolean, boolean, NULL)
#12 /srv/mediawiki/php-1.31.0-wmf.1/includes/OutputPage.php(1975): OutputPage->parse(string, boolean, boolean)
#13 /srv/mediawiki/php-1.31.0-wmf.1/extensions/AbuseFilter/includes/AbuseFilter.class.php(760): OutputPage->parseInline(string)
#14 /srv/mediawiki/php-1.31.0-wmf.1/extensions/AbuseFilter/includes/AbuseFilter.class.php(972): AbuseFilter::executeFilterActions(array, Title, AbuseFilterVariableHolder)
#15 /srv/mediawiki/php-1.31.0-wmf.1/extensions/AbuseFilter/includes/AbuseFilterPreAuthenticationProvider.php(41): AbuseFilter::filterAction(AbuseFilterVariableHolder, Title, string, User)
#16 /srv/mediawiki/php-1.31.0-wmf.1/extensions/AbuseFilter/includes/AbuseFilterPreAuthenticationProvider.php(13): AbuseFilterPreAuthenticationProvider->testUser(User, User, boolean)
#17 /srv/mediawiki/php-1.31.0-wmf.1/includes/auth/AuthManager.php(1649): AbuseFilterPreAuthenticationProvider->testUserForCreation(User, string, array)
#18 /srv/mediawiki/php-1.31.0-wmf.1/includes/Setup.php(869): MediaWiki\Auth\AuthManager->autoCreateUser(User, string, boolean)
#19 /srv/mediawiki/php-1.31.0-wmf.1/includes/WebStart.php(114): include(string)
#20 /srv/mediawiki/php-1.31.0-wmf.1/api.php(38): include(string)
#21 /srv/mediawiki/w/api.php(3): include(string)
#22 {main}

There's another caused by use of LinkRenderer in AbuseLogHitFormatter::getMessageParameters() during auto-creation.

WARNING User::loadFromSession called before the end of Setup.php

#0 /srv/mediawiki/php-1.31.0-wmf.1/includes/user/User.php(5269): User->load()
#1 /srv/mediawiki/php-1.31.0-wmf.1/includes/user/User.php(2887): User->loadOptions()
#2 /srv/mediawiki/php-1.31.0-wmf.1/includes/user/User.php(2957): User->getOption(string)
#3 /srv/mediawiki/php-1.31.0-wmf.1/includes/user/User.php(3248): User->getIntOption(string)
#4 /srv/mediawiki/php-1.31.0-wmf.1/includes/linker/LinkRendererFactory.php(66): User->getStubThreshold()
#5 /srv/mediawiki/php-1.31.0-wmf.1/includes/ServiceWiring.php(321): MediaWiki\Linker\LinkRendererFactory->createForUser(User)
#6 [internal function]: Closure$#32(MediaWiki\MediaWikiServices)
#7 /srv/mediawiki/php-1.31.0-wmf.1/includes/services/ServiceContainer.php(361): call_user_func_array(Closure$#32;150, array)
#8 /srv/mediawiki/php-1.31.0-wmf.1/includes/services/ServiceContainer.php(344): MediaWiki\Services\ServiceContainer->createService(string)
#9 /srv/mediawiki/php-1.31.0-wmf.1/includes/MediaWikiServices.php(617): MediaWiki\Services\ServiceContainer->getService(string)
#10 /srv/mediawiki/php-1.31.0-wmf.1/extensions/AbuseFilter/includes/AbuseLogHitFormatter.php(16): MediaWiki\MediaWikiServices->getLinkRenderer()
#11 /srv/mediawiki/php-1.31.0-wmf.1/includes/logging/LogFormatter.php(465): AbuseLogHitFormatter->getMessageParameters()
#12 /srv/mediawiki/php-1.31.0-wmf.1/includes/logging/LogFormatter.php(440): LogFormatter->getActionMessage()
#13 /srv/mediawiki/php-1.31.0-wmf.1/includes/logging/LogFormatter.php(189): LogFormatter->getActionText()
#14 /srv/mediawiki/php-1.31.0-wmf.1/includes/logging/LogEntry.php(697): LogFormatter->getPlainActionText()
#15 /srv/mediawiki/php-1.31.0-wmf.1/extensions/AbuseFilter/includes/AbuseFilter.class.php(1165): ManualLogEntry->getRecentChange()
#16 /srv/mediawiki/php-1.31.0-wmf.1/extensions/AbuseFilter/includes/AbuseFilter.class.php(995): AbuseFilter::addLogEntries(array, array, string, AbuseFilterVariableHolder, string)
#17 /srv/mediawiki/php-1.31.0-wmf.1/extensions/AbuseFilter/includes/AbuseFilterPreAuthenticationProvider.php(41): AbuseFilter::filterAction(AbuseFilterVariableHolder, Title, string, User)
#18 /srv/mediawiki/php-1.31.0-wmf.1/extensions/AbuseFilter/includes/AbuseFilterPreAuthenticationProvider.php(13): AbuseFilterPreAuthenticationProvider->testUser(User, User, boolean)
#19 /srv/mediawiki/php-1.31.0-wmf.1/includes/auth/AuthManager.php(1649): AbuseFilterPreAuthenticationProvider->testUserForCreation(User, string, array)
#20 /srv/mediawiki/php-1.31.0-wmf.1/includes/Setup.php(869): MediaWiki\Auth\AuthManager->autoCreateUser(User, string, boolean)
#21 /srv/mediawiki/php-1.31.0-wmf.1/includes/WebStart.php(114): include(string)
#22 /srv/mediawiki/php-1.31.0-wmf.1/index.php(40): include(string)
#23 /srv/mediawiki/w/index.php(3): include(string)
#24 {main}

Event Timeline

Tgr created this task.Nov 22 2016, 5:01 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptNov 22 2016, 5:01 AM
demon triaged this task as Normal priority.Sep 14 2017, 8:08 PM
demon added a subscriber: demon.

Still happens in production.

Anomie updated the task description. (Show Details)Oct 5 2017, 6:15 PM
Krinkle added a subscriber: Krinkle.

Still seen. Tagging Platform per mw:Maintainers for AbuseFilter. However, if this is a side-effect of other code, do un-tag :-) . Couldn't quite tell what causes it.

Exception "User::loadFromSession called before the end of Setup.php"

#0 /srv/mediawiki/php-1.32.0-wmf.20/includes/user/User.php(5461): User->load()
#1 /srv/mediawiki/php-1.32.0-wmf.20/includes/user/User.php(3153): User->loadOptions()
#2 /srv/mediawiki/php-1.32.0-wmf.20/includes/user/User.php(3223): User->getOption(string)
#3 /srv/mediawiki/php-1.32.0-wmf.20/includes/user/User.php(3515): User->getIntOption(string)
#4 /srv/mediawiki/php-1.32.0-wmf.20/includes/linker/LinkRendererFactory.php(65): User->getStubThreshold()
#5 /srv/mediawiki/php-1.32.0-wmf.20/includes/ServiceWiring.php(206): MediaWiki\Linker\LinkRendererFactory->createForUser(User)
#6 /srv/mediawiki/php-1.32.0-wmf.20/includes/services/ServiceContainer.php(431): Closure$#19(MediaWiki\MediaWikiServices)
#7 /srv/mediawiki/php-1.32.0-wmf.20/includes/services/ServiceContainer.php(414): MediaWiki\Services\ServiceContainer->createService(string)
#8 /srv/mediawiki/php-1.32.0-wmf.20/includes/MediaWikiServices.php(596): MediaWiki\Services\ServiceContainer->getService(string)
#9 /srv/mediawiki/php-1.32.0-wmf.20/extensions/AbuseFilter/includes/AbuseLogHitFormatter.php(17): MediaWiki\MediaWikiServices->getLinkRenderer()
#10 /srv/mediawiki/php-1.32.0-wmf.20/includes/logging/LogFormatter.php(470): AbuseLogHitFormatter->getMessageParameters()
#11 /srv/mediawiki/php-1.32.0-wmf.20/includes/logging/LogFormatter.php(445): LogFormatter->getActionMessage()
#12 /srv/mediawiki/php-1.32.0-wmf.20/includes/logging/LogFormatter.php(196): LogFormatter->getActionText()
#13 /srv/mediawiki/php-1.32.0-wmf.20/includes/logging/LogEntry.php(761): LogFormatter->getPlainActionText()
#14 /srv/mediawiki/php-1.32.0-wmf.20/extensions/AbuseFilter/includes/AbuseFilter.php(1381): ManualLogEntry->getRecentChange()
#15 /srv/mediawiki/php-1.32.0-wmf.20/extensions/AbuseFilter/includes/AbuseFilter.php(1212): AbuseFilter::addLogEntries(array, array, AbuseFilterVariableHolder, string)
#16 /srv/mediawiki/php-1.32.0-wmf.20/extensions/AbuseFilter/includes/AbuseFilterPreAuthenticationProvider.php(53): AbuseFilter::filterAction(AbuseFilterVariableHolder, Title, string, User)
#17 /srv/mediawiki/php-1.32.0-wmf.20/extensions/AbuseFilter/includes/AbuseFilterPreAuthenticationProvider.php(25): AbuseFilterPreAuthenticationProvider->testUser(User, User, boolean)
#18 /srv/mediawiki/php-1.32.0-wmf.20/includes/auth/AuthManager.php(1663): AbuseFilterPreAuthenticationProvider->testUserForCreation(User, string, array)
#19 /srv/mediawiki/php-1.32.0-wmf.20/includes/Setup.php(927): MediaWiki\Auth\AuthManager->autoCreateUser(User, string, boolean)
#20 /srv/mediawiki/php-1.32.0-wmf.20/includes/WebStart.php(77): include(string)
#21 /srv/mediawiki/php-1.32.0-wmf.20/index.php(39): include(string)
Krinkle updated the task description. (Show Details)Sep 12 2018, 2:13 AM

Reading the stacktrace, the last call in AbuseFilter is to ManualLogEntry::getRecentChange. The log entry in question is constructed here and includes a performer. Such performer is in turn the User object generated here, which can be either:

  1. An user object used to call AbuseFilter::filterAction
  2. $wgUser if no user is specified
  3. A dummy anonymous user if the user isn't safe to load

In this specific case, we do call filterAction with an User object coming directly from AuthManager. However, I guess when this all happens $wgFullyInitialised is false, and thus we end up using the dummy account, which is apparently fine on our end. However, AFAICS, something above in the stacktrace isn't fine with it, and ends up loading the user object, which the User class refuses to do as $wgFullyInitialised is still false.

If my assumption is correct, the next step would be to determine whether AbuseFilter is really fine with a dummy user. If it is, then we should probably either pass data to CheckUser in another way or handle cases where the User object isn't safe somewhere above in the stacktrace. If it isn't, then we should directly rework the logic in AbuseFilter.
If, instead, my assumption isn't correct, I don't have any other ideas.

For createaccount/autocreateaccount filtering, shouldn't the log performer always be anonymous? It doesn't make sense to use a non-existent user, half created, as the performer. That logic shouldn't depend on User::isSafeToLoad(), which is implemented in a hackish way, it should just depend on $action.

@tstarling Yes, I guess this makes sense. Making the log entry anonymous seems pretty straightforward, but what about the row to insert in abuse_filter_log? We need an ID and a name for it, so we still need to know if the user is safe to load. Or, do we?

Daimona moved this task from Backlog to Next on the User-Daimona board.
Daimona moved this task from Next to Waiting on the User-Daimona board.Nov 7 2018, 11:17 AM

Is this still happening? I guess it does, but in the meanwhile the code has been changed to never use $wgUser, so there may be a little hope.

demon removed a subscriber: demon.Dec 8 2018, 6:05 PM

Yes. Below is an entry of today from Logstash/mediawiki-errors with query +message:"called before the end of" (last 7 days):

from AuthManager::autoCreateUser / AbuseFilter / AbuseLogHitFormatter / Message::getLanguage
[session] WARNING

User::loadFromSession called before the end of Setup.php

#0 /srv/mediawiki/php-1.33.0-wmf.6/includes/user/User.php(2456): User->load()
#1 /srv/mediawiki/php-1.33.0-wmf.6/includes/user/User.php(5566): User->getId()
#2 /srv/mediawiki/php-1.33.0-wmf.6/includes/user/User.php(3186): User->loadOptions()
#3 /srv/mediawiki/php-1.33.0-wmf.6/includes/context/RequestContext.php(334): User->getOption(string)
#4 /srv/mediawiki/php-1.33.0-wmf.6/includes/Message.php(381): RequestContext->getLanguage()
#5 /srv/mediawiki/php-1.33.0-wmf.6/includes/Message.php(1299): Message->getLanguage()
#6 /srv/mediawiki/php-1.33.0-wmf.6/includes/Message.php(851): Message->fetchMessage()
#7 /srv/mediawiki/php-1.33.0-wmf.6/includes/Message.php(980): Message->toString(string)
#8 /srv/mediawiki/php-1.33.0-wmf.6/extensions/AbuseFilter/includes/AbuseFilter.php(2694): Message->escaped()
#9 /srv/mediawiki/php-1.33.0-wmf.6/extensions/AbuseFilter/includes/AbuseLogHitFormatter.php(51): AbuseFilter::getActionDisplay(string)
#10 /srv/mediawiki/php-1.33.0-wmf.6/includes/logging/LogFormatter.php(464): AbuseLogHitFormatter->getMessageParameters()
#11 /srv/mediawiki/php-1.33.0-wmf.6/includes/logging/LogFormatter.php(439): LogFormatter->getActionMessage()
#12 /srv/mediawiki/php-1.33.0-wmf.6/includes/logging/LogFormatter.php(190): LogFormatter->getActionText()
#13 /srv/mediawiki/php-1.33.0-wmf.6/includes/logging/LogEntry.php(761): LogFormatter->getPlainActionText()
#14 /srv/mediawiki/php-1.33.0-wmf.6/extensions/AbuseFilter/includes/AbuseFilter.php(1387): ManualLogEntry->getRecentChange()
#15 /srv/mediawiki/php-1.33.0-wmf.6/extensions/AbuseFilter/includes/AbuseFilter.php(1213): AbuseFilter::addLogEntries(array, array, AbuseFilterVariableHolder, string)
#16 /srv/mediawiki/php-1.33.0-wmf.6/extensions/AbuseFilter/includes/AbuseFilterPreAuthenticationProvider.php(53): AbuseFilter::filterAction(AbuseFilterVariableHolder, Title, string, User)
#17 /srv/mediawiki/php-1.33.0-wmf.6/extensions/AbuseFilter/includes/AbuseFilterPreAuthenticationProvider.php(25): AbuseFilterPreAuthenticationProvider->testUser(User, User, boolean)
#18 /srv/mediawiki/php-1.33.0-wmf.6/includes/auth/AuthManager.php(1664): AbuseFilterPreAuthenticationProvider->testUserForCreation(User, string, array)
#19 /srv/mediawiki/php-1.33.0-wmf.6/includes/Setup.php(942): MediaWiki\Auth\AuthManager->autoCreateUser(User, string, boolean)
#20 /srv/mediawiki/php-1.33.0-wmf.6/includes/WebStart.php(77): include(string)
#21 /srv/mediawiki/php-1.33.0-wmf.6/index.php(39): include(string)

Another another one:

from AuthManager::autoCreateUser / AbuseFilter / AbuseLogHitFormatter / LinkRenderer
#0 /srv/mediawiki/php-1.33.0-wmf.6/includes/user/User.php(2456): User->load()
#1 /srv/mediawiki/php-1.33.0-wmf.6/includes/user/User.php(5566): User->getId()
#2 /srv/mediawiki/php-1.33.0-wmf.6/includes/user/User.php(3186): User->loadOptions()
#3 /srv/mediawiki/php-1.33.0-wmf.6/includes/user/User.php(3256): User->getOption(string)
#4 /srv/mediawiki/php-1.33.0-wmf.6/includes/user/User.php(3548): User->getIntOption(string)
#5 /srv/mediawiki/php-1.33.0-wmf.6/includes/linker/LinkRendererFactory.php(65): User->getStubThreshold()
#6 /srv/mediawiki/php-1.33.0-wmf.6/includes/ServiceWiring.php(206): MediaWiki\Linker\LinkRendererFactory->createForUser(User)
#7 /srv/mediawiki/php-1.33.0-wmf.6/includes/services/ServiceContainer.php(431): Closure$#19(MediaWiki\MediaWikiServices)
#8 /srv/mediawiki/php-1.33.0-wmf.6/includes/services/ServiceContainer.php(414): MediaWiki\Services\ServiceContainer->createService(string)
#9 /srv/mediawiki/php-1.33.0-wmf.6/includes/MediaWikiServices.php(597): MediaWiki\Services\ServiceContainer->getService(string)
#10 /srv/mediawiki/php-1.33.0-wmf.6/extensions/AbuseFilter/includes/AbuseLogHitFormatter.php(17): MediaWiki\MediaWikiServices->getLinkRenderer()
#11 /srv/mediawiki/php-1.33.0-wmf.6/includes/logging/LogFormatter.php(464): AbuseLogHitFormatter->getMessageParameters()
#12 /srv/mediawiki/php-1.33.0-wmf.6/includes/logging/LogFormatter.php(439): LogFormatter->getActionMessage()
#13 /srv/mediawiki/php-1.33.0-wmf.6/includes/logging/LogFormatter.php(190): LogFormatter->getActionText()
#14 /srv/mediawiki/php-1.33.0-wmf.6/includes/logging/LogEntry.php(761): LogFormatter->getPlainActionText()
#15 /srv/mediawiki/php-1.33.0-wmf.6/extensions/AbuseFilter/includes/AbuseFilter.php(1387): ManualLogEntry->getRecentChange()
#16 /srv/mediawiki/php-1.33.0-wmf.6/extensions/AbuseFilter/includes/AbuseFilter.php(1213): AbuseFilter::addLogEntries(array, array, AbuseFilterVariableHolder, string)
#17 /srv/mediawiki/php-1.33.0-wmf.6/extensions/AbuseFilter/includes/AbuseFilterPreAuthenticationProvider.php(53): AbuseFilter::filterAction(AbuseFilterVariableHolder, Title, string, User)
#18 /srv/mediawiki/php-1.33.0-wmf.6/extensions/AbuseFilter/includes/AbuseFilterPreAuthenticationProvider.php(25): AbuseFilterPreAuthenticationProvider->testUser(User, User, boolean)
#19 /srv/mediawiki/php-1.33.0-wmf.6/includes/auth/AuthManager.php(1664): AbuseFilterPreAuthenticationProvider->testUserForCreation(User, string, array)
#20 /srv/mediawiki/php-1.33.0-wmf.6/includes/Setup.php(942): MediaWiki\Auth\AuthManager->autoCreateUser(User, string, boolean)
#21 /srv/mediawiki/php-1.33.0-wmf.6/includes/WebStart.php(77): include(string)
#22 /srv/mediawiki/php-1.33.0-wmf.6/index.php(39): include(string)

In addition to the above two groups of errors, there are also a number of very similar errors. There are variations of the above two that start from api.php instead of index.php, and there are variations of those four that are logged-out instead of logged-in (and thus skip User->getId), but otherwise identical.

@Krinkle Many thanks for the report! I'm trying to do some local testing, and I could also find the same error coming from AbuseFilter::throttleIdentifier (which directly calls $wgUser->getId()). May you please check if that method is in any stacktrace related to this error? It could also be happening due to the hacky way I'm using to reproduce the issue, but according to the logic I think it actually doesn't. As for the first reported case, since the error happens because we're trying to display a message in the user's language, another solution could be to use contentLanguage if the user isn't safe to load (here). The Link Renderer one maybe could be resolved by using $factory = MediaWikiServices::getInstance()->getLinkRendererFactory() and then $factory->create() (here)? And the throttle one, if it is a thing, could be resolved again by checking wgUser->isSafeToLoad and falling back to a null identifier (here, and also for the 'editcount' case)...

I could also find the same error coming from AbuseFilter::throttleIdentifier (which directly calls $wgUser->getId()). May you please check if that method is in any stacktrace related to this error?

Yes, it is.

So, recapping, this error can be triggered from the following:

  1. AbuseFilter::throttleIdentifier doing $wgUser->getId()
  2. AbuseFilter::getActionDisplay Trying to display a message in the user lang (called from AbuseLogHitFormatter)
  3. AbuseLogHitFormatter doing MediaWikiServices::getInstance()->getLinkRenderer()

And as pointed out in the task description, this only happens for account autocreation.

Tgr added a comment.EditedJan 9 2019, 6:12 PM

3 is not really AbuseFilter-related. The service wiring for LinkRenderer uses $wgUser so it should check if the user is safe to load. Same for the first error in the task description (triggered by a content parse for some of the filter rules - although why are even content-based filter variables available for an autocreation event?).

@Tgr Well, nice point for 3. As for 1 in task description, I had to go to REL1_30 to find it; here is the bad line, but it doesn't happen anymore (for AF, of course) since rEABF799a2fb1ed73c210adcdb8e3713805430f590960 removed parsing at that point.

Krinkle added a comment.EditedMar 12 2019, 5:08 AM

Still seeing the warnings logged in production on user requests for page views and user-script pages, mainly from AbuseLogHitFormatter.php via autocreate, but others as well.

Could one of you, as starting point, summarize the impact of this currently, for end users? In what way is the requesting user, and/or the wiki more generally, affected, when this warning is logged from AF?

Tgr added a comment.Mar 12 2019, 6:36 AM

AbuseFilter checks on autocreation will ignore user settings when parsing messages or text. Error messages will be in the default wiki language, not the user's language (which is not set at this point anyway, although in theory some global preferences extension could provide it). Autocreation errors are not shown to the user anyway so I don't think there's any impact other than log noise.