Page MenuHomePhabricator
Create Task
Maniphest T210696

OATHAuth logging fails using Monolog
Closed, ResolvedPublicSecurity
Actions

Description

[865bcb67a341d09028218a81] /wiki/Special:Two-factor_authentication   ErrorException from line 333 of /srv/mediawiki/php-1.33.0-wmf.6/vendor/monolog/monolog/src/Monolog/Logger.php: PHP Warning: Invalid argument: function: not string, closure, or array
#0 [internal function]: MWExceptionHandler::handleError(integer, string, string, integer, array, array)
#1 /srv/mediawiki/php-1.33.0-wmf.6/vendor/monolog/monolog/src/Monolog/Logger.php(333): call_user_func(NULL, array)
#2 /srv/mediawiki/php-1.33.0-wmf.6/vendor/monolog/monolog/src/Monolog/Logger.php(546): Monolog\Logger->addRecord(integer, string, array)
#3 /srv/mediawiki/php-1.33.0-wmf.6/extensions/OATHAuth/includes/OATHAuthKey.php(141): Monolog\Logger->info(string, array)
#4 /srv/mediawiki/php-1.33.0-wmf.6/extensions/OATHAuth/includes/special/SpecialOATHEnable.php(187): OATHAuthKey->verifyToken(string, OATHUser)
#5 /srv/mediawiki/php-1.33.0-wmf.6/includes/htmlform/HTMLForm.php(663): SpecialOATHEnable->onSubmit(array, OOUIHTMLForm)
#6 /srv/mediawiki/php-1.33.0-wmf.6/includes/htmlform/HTMLForm.php(555): HTMLForm->trySubmit()
#7 /srv/mediawiki/php-1.33.0-wmf.6/includes/htmlform/HTMLForm.php(570): HTMLForm->tryAuthorizedSubmit()
#8 /srv/mediawiki/php-1.33.0-wmf.6/includes/specialpage/FormSpecialPage.php(184): HTMLForm->show()
#9 /srv/mediawiki/php-1.33.0-wmf.6/extensions/OATHAuth/includes/special/ProxySpecialPage.php(192): FormSpecialPage->execute(NULL)
#10 /srv/mediawiki/php-1.33.0-wmf.6/includes/specialpage/SpecialPage.php(569): ProxySpecialPage->execute(NULL)
#11 /srv/mediawiki/php-1.33.0-wmf.6/includes/specialpage/SpecialPageFactory.php(558): SpecialPage->run(NULL)
#12 /srv/mediawiki/php-1.33.0-wmf.6/includes/MediaWiki.php(288): MediaWiki\Special\SpecialPageFactory->executePath(Title, RequestContext)
#13 /srv/mediawiki/php-1.33.0-wmf.6/includes/MediaWiki.php(862): MediaWiki->performRequest()
#14 /srv/mediawiki/php-1.33.0-wmf.6/includes/MediaWiki.php(517): MediaWiki->main()
#15 /srv/mediawiki/php-1.33.0-wmf.6/index.php(42): MediaWiki->run()
#16 /srv/mediawiki/w/index.php(3): include(string)
#17 {main}
[865bcb67a341d09028218a81] /wiki/Special:Two-factor_authentication   PHP Fatal Error from line 333 of /srv/mediawiki/php-1.33.0-wmf.6/vendor/monolog/monolog/src/Monolog/Logger.php: Argument 1 passed to Monolog\Processor\WebProcessor::__invoke() must be an instance of array, null given
#0 /srv/mediawiki/php-1.33.0-wmf.6/vendor/monolog/monolog/src/Monolog/Logger.php(333): call_user_func(Monolog\Processor\WebProcessor, NULL)
#1 /srv/mediawiki/php-1.33.0-wmf.6/vendor/monolog/monolog/src/Monolog/Logger.php(546): Monolog\Logger->addRecord(integer, string, array)
#2 /srv/mediawiki/php-1.33.0-wmf.6/extensions/OATHAuth/includes/OATHAuthKey.php(141): Monolog\Logger->info(string, array)
#3 /srv/mediawiki/php-1.33.0-wmf.6/extensions/OATHAuth/includes/special/SpecialOATHEnable.php(187): OATHAuthKey->verifyToken(string, OATHUser)
#4 /srv/mediawiki/php-1.33.0-wmf.6/includes/htmlform/HTMLForm.php(663): SpecialOATHEnable->onSubmit(array, OOUIHTMLForm)
#5 /srv/mediawiki/php-1.33.0-wmf.6/includes/htmlform/HTMLForm.php(555): HTMLForm->trySubmit()
#6 /srv/mediawiki/php-1.33.0-wmf.6/includes/htmlform/HTMLForm.php(570): HTMLForm->tryAuthorizedSubmit()
#7 /srv/mediawiki/php-1.33.0-wmf.6/includes/specialpage/FormSpecialPage.php(184): HTMLForm->show()
#8 /srv/mediawiki/php-1.33.0-wmf.6/extensions/OATHAuth/includes/special/ProxySpecialPage.php(192): FormSpecialPage->execute(NULL)
#9 /srv/mediawiki/php-1.33.0-wmf.6/includes/specialpage/SpecialPage.php(569): ProxySpecialPage->execute(NULL)
#10 /srv/mediawiki/php-1.33.0-wmf.6/includes/specialpage/SpecialPageFactory.php(558): SpecialPage->run(NULL)
#11 /srv/mediawiki/php-1.33.0-wmf.6/includes/MediaWiki.php(288): MediaWiki\Special\SpecialPageFactory->executePath(Title, RequestContext)
#12 /srv/mediawiki/php-1.33.0-wmf.6/includes/MediaWiki.php(862): MediaWiki->performRequest()
#13 /srv/mediawiki/php-1.33.0-wmf.6/includes/MediaWiki.php(517): MediaWiki->main()
#14 /srv/mediawiki/php-1.33.0-wmf.6/index.php(42): MediaWiki->run()
#15 /srv/mediawiki/w/index.php(3): include(string)
#16 {main}
@bd808 wrote:

I think this error means that whatever processor Monolog applied right before WebProcessor returned a null value for the record. The more interesting failure is probably the other one from T210643#4782512 where call_user_func($processor, $record); blew up with $processor not being a callable. That should have been our "normalized_message" processor if I'm reading wmf-config/logging.php correctly.

Related Objects
Search...

StatusAssignedTask
Restricted Task
 ResolvedReedyT151010 Add logging to OATHAuth
 ResolvedTgrT210696 OATHAuth logging fails using Monolog

Event Timeline

Reedy created this task.Nov 29 2018, 6:21 AM
Reedy created this object with visibility "Public (No Login Required)".
Reedy created this object with edit policy "All Users".
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptNov 29 2018, 6:21 AM
Reedy added a comment.Nov 30 2018, 1:36 AM

@bd808 per your comment on the other bug...

Any suggestions from your previous experience with monolog how to debug/narrow it down further?

bd808 added a comment.Nov 30 2018, 4:04 AM
In T210696#4788041, @Reedy wrote:

Any suggestions from your previous experience with monolog how to debug/narrow it down further?

One super weird thing here was that the error was seen at all. The WhatFailureGroupHandler that is added to all of the handler chains in wmf-config/logging.php should have caught and silently discarded the output error.

I assume that you have tested the change with some configuration other than our prod logging setup. That means that the bug seen on wikitech is related to the monolog setup somehow. I guess I would start by using eval.php to examine the runtime generated config for the logging channel you were using when running as wikitech. Maybe that will show something interesting. If not I would continue by trying to recreate the exception in isolation again using eval.php. If there are still no reproduction or clues it might be possible to reproduce by staging a revert on one of the mwdebug servers, adding a dump of the logger config right before the call, and seeing if you can recreate and capture useful info there.

Tgr added a subscriber: Tgr.Dec 18 2018, 3:52 AM

There's also this:

PHP Warning: Attempted to serialize unserializable builtin class Closure$#3;9592
srv/mediawiki/php-1.33.0-wmf.8/includes/libs/objectcache/RedisBagOStuff.php:335
#0 /srv/mediawiki/php-1.33.0-wmf.8/includes/libs/objectcache/RedisBagOStuff.php(335): MWExceptionHandler::handleError(integer, string, string, integer, array, array)
#1 /srv/mediawiki/php-1.33.0-wmf.8/includes/libs/objectcache/RedisBagOStuff.php(121): RedisBagOStuff->serialize(array)
#2 /srv/mediawiki/php-1.33.0-wmf.8/includes/libs/objectcache/CachedBagOStuff.php(65): RedisBagOStuff->set(string, array, integer, integer)
#3 /srv/mediawiki/php-1.33.0-wmf.8/includes/session/SessionBackend.php(739): CachedBagOStuff->set(string, array, integer, integer)
#4 /srv/mediawiki/php-1.33.0-wmf.8/includes/session/SessionBackend.php(596): MediaWiki\Session\SessionBackend->save()
#5 [internal function]: Closure$MediaWiki\Session\SessionBackend::delaySave()
#6 /srv/mediawiki/php-1.33.0-wmf.8/vendor/wikimedia/scoped-callback/src/ScopedCallback.php(96): call_user_func_array(Closure$MediaWiki\Session\SessionBackend::delaySave;8007, array)
#7 /srv/mediawiki/php-1.33.0-wmf.8/vendor/wikimedia/scoped-callback/src/ScopedCallback.php(56): Wikimedia\ScopedCallback->__destruct()
#8 /srv/mediawiki/php-1.33.0-wmf.8/includes/session/SessionManager.php(886): Wikimedia\ScopedCallback::consume(NULL)
#9 /srv/mediawiki/php-1.33.0-wmf.8/includes/session/SessionManager.php(214): MediaWiki\Session\SessionManager->getSessionFromInfo(MediaWiki\Session\SessionInfo, WebRequest)
#10 /srv/mediawiki/php-1.33.0-wmf.8/includes/WebRequest.php(744): MediaWiki\Session\SessionManager->getSessionById(string, boolean, WebRequest)
#11 /srv/mediawiki/php-1.33.0-wmf.8/includes/user/User.php(4735): WebRequest->getSession()
#12 /srv/mediawiki/php-1.33.0-wmf.8/includes/user/User.php(4752): User->getEditTokenObject(string, WebRequest)
#13 /srv/mediawiki/php-1.33.0-wmf.8/includes/htmlform/HTMLForm.php(1121): User->getEditToken(string)
#14 /srv/mediawiki/php-1.33.0-wmf.8/includes/htmlform/HTMLForm.php(1043): HTMLForm->getHiddenFields()
#15 /srv/mediawiki/php-1.33.0-wmf.8/includes/htmlform/HTMLForm.php(1021): HTMLForm->getHTML(boolean)
#16 /srv/mediawiki/php-1.33.0-wmf.8/includes/htmlform/HTMLForm.php(575): HTMLForm->displayForm(boolean)
#17 /srv/mediawiki/php-1.33.0-wmf.8/includes/specialpage/FormSpecialPage.php(184): HTMLForm->show()
#18 /srv/mediawiki/php-1.33.0-wmf.8/extensions/OATHAuth/includes/special/ProxySpecialPage.php(192): FormSpecialPage->execute(NULL)
#19 /srv/mediawiki/php-1.33.0-wmf.8/includes/specialpage/SpecialPage.php(569): ProxySpecialPage->execute(NULL)
#20 /srv/mediawiki/php-1.33.0-wmf.8/includes/specialpage/SpecialPageFactory.php(558): SpecialPage->run(NULL)
#21 /srv/mediawiki/php-1.33.0-wmf.8/includes/MediaWiki.php(288): MediaWiki\Special\SpecialPageFactory->executePath(Title, RequestContext)
#22 /srv/mediawiki/php-1.33.0-wmf.8/includes/MediaWiki.php(862): MediaWiki->performRequest()
#23 /srv/mediawiki/php-1.33.0-wmf.8/includes/MediaWiki.php(517): MediaWiki->main()
#24 /srv/mediawiki/php-1.33.0-wmf.8/index.php(42): MediaWiki->run()
#25 /srv/mediawiki/w/index.php(3): include(string)
#26 {main}

which does explain the mystery: OAuthKey gets serialized, which makes weird things happen to its logger instance.

Tgr closed this task as Resolved.Dec 18 2018, 3:59 AM
Tgr claimed this task.
Content licensed under Creative Commons Attribution-ShareAlike 3.0 (CC-BY-SA) unless otherwise noted; code licensed under GNU General Public License (GPL) or other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL