Page MenuHomePhabricator

PHP Notice: Trying to access array offset on value of type null (in Echo NotifUser)
Closed, ResolvedPublicPRODUCTION ERROR

Description

Error
normalized_message
[{reqId}] {exception_url}   PHP Notice: Trying to access array offset on value of type null
exception.trace
from /srv/mediawiki/php-1.39.0-wmf.27/extensions/Echo/includes/NotifUser.php(261)
#0 /srv/mediawiki/php-1.39.0-wmf.27/extensions/Echo/includes/NotifUser.php(261): MWExceptionHandler::handleError(integer, string, string, integer, array)
#1 /srv/mediawiki/php-1.39.0-wmf.27/extensions/Echo/includes/NotifUser.php(223): MWEchoNotifUser->getLastUnreadNotificationTime(string)
#2 /srv/mediawiki/php-1.39.0-wmf.27/extensions/Echo/includes/Hooks.php(1013): MWEchoNotifUser->getLastUnreadAlertTime()
#3 /srv/mediawiki/php-1.39.0-wmf.27/includes/HookContainer/HookContainer.php(338): MediaWiki\Extension\Notifications\Hooks::onSkinTemplateNavigationUniversal(MediaWiki\Skins\Vector\SkinVector22, array)
#4 /srv/mediawiki/php-1.39.0-wmf.27/includes/HookContainer/HookContainer.php(137): MediaWiki\HookContainer\HookContainer->callLegacyHook(string, array, array, array)
#5 /srv/mediawiki/php-1.39.0-wmf.27/includes/HookContainer/HookRunner.php(3527): MediaWiki\HookContainer\HookContainer->run(string, array, array)
#6 /srv/mediawiki/php-1.39.0-wmf.27/includes/skins/SkinTemplate.php(1202): MediaWiki\HookContainer\HookRunner->onSkinTemplateNavigation__Universal(MediaWiki\Skins\Vector\SkinVector22, array)
#7 /srv/mediawiki/php-1.39.0-wmf.27/skins/Vector/includes/SkinVector.php(343): SkinTemplate->runOnSkinTemplateNavigationHooks(MediaWiki\Skins\Vector\SkinVector22, array)
#8 /srv/mediawiki/php-1.39.0-wmf.27/includes/skins/SkinTemplate.php(1571): MediaWiki\Skins\Vector\SkinVector->runOnSkinTemplateNavigationHooks(MediaWiki\Skins\Vector\SkinVector22, array)
#9 /srv/mediawiki/php-1.39.0-wmf.27/includes/skins/SkinTemplate.php(789): SkinTemplate->buildContentNavigationUrlsInternal()
#10 /srv/mediawiki/php-1.39.0-wmf.27/includes/skins/SkinTemplate.php(229): SkinTemplate->getPortletsTemplateData()
#11 /srv/mediawiki/php-1.39.0-wmf.27/includes/skins/SkinMustache.php(88): SkinTemplate->getTemplateData()
#12 /srv/mediawiki/php-1.39.0-wmf.27/skins/Vector/includes/SkinVector.php(449): SkinMustache->getTemplateData()
#13 /srv/mediawiki/php-1.39.0-wmf.27/skins/Vector/includes/SkinVector22.php(168): MediaWiki\Skins\Vector\SkinVector->getTemplateData()
#14 /srv/mediawiki/php-1.39.0-wmf.27/includes/skins/SkinMustache.php(58): MediaWiki\Skins\Vector\SkinVector22->getTemplateData()
#15 /srv/mediawiki/php-1.39.0-wmf.27/includes/skins/SkinTemplate.php(177): SkinMustache->generateHTML()
#16 /srv/mediawiki/php-1.39.0-wmf.27/includes/OutputPage.php(2859): SkinTemplate->outputPage()
#17 /srv/mediawiki/php-1.39.0-wmf.27/includes/exception/MWExceptionRenderer.php(183): OutputPage->output()
#18 /srv/mediawiki/php-1.39.0-wmf.27/includes/exception/MWExceptionRenderer.php(102): MWExceptionRenderer::reportHTML(Wikimedia\Rdbms\DBTransactionSizeError)
#19 /srv/mediawiki/php-1.39.0-wmf.27/includes/exception/MWExceptionHandler.php(131): MWExceptionRenderer::output(Wikimedia\Rdbms\DBTransactionSizeError, integer)
#20 /srv/mediawiki/php-1.39.0-wmf.27/includes/exception/MWExceptionHandler.php(228): MWExceptionHandler::report(Wikimedia\Rdbms\DBTransactionSizeError)
#21 /srv/mediawiki/php-1.39.0-wmf.27/includes/MediaWiki.php(581): MWExceptionHandler::handleException(Wikimedia\Rdbms\DBTransactionSizeError, string)
#22 /srv/mediawiki/php-1.39.0-wmf.27/index.php(50): MediaWiki->run()
#23 /srv/mediawiki/php-1.39.0-wmf.27/index.php(46): wfIndexMain()
#24 /srv/mediawiki/w/index.php(3): require(string)
#25 {main}
Notes
  • Happening at a low rate on ptwiki and enwiki
  • Seems to happen exclusively for Special:CreateAccount

Details

Request URL
https://pt.wikipedia.org/w/index.php?returnto=*&title=*

Event Timeline

Tgr subscribed.

The code in question is

MWEchoNotifUser::getCountsAndTimestamps('preference')['global']['alert']['timestamp']

which would imply that either it returns null, or that [$global][$section] is null in the returned array (or maybe [$global] is null).

(This error is new in PHP 7.4, 7.2 silently evaluates null['foo'] to null. So hard to tell if the underlying bug is new.)

Reading the code (getCountsAndTimestamps, computeLocalCountsAndTimestamps and computeGlobalCountsAndTimestamps in NotifUser.pgp), this seems strictly impossible unless WANObjectCache::getWithSetCallback somehow returns corrupted values.

The same request also complains about User::addToDatabase() taking 9.5 second. No idea if it's related, but that is unreasonably slow for a simple insert.

Krinkle renamed this task from PHP Notice: Trying to access array offset on value of type null to PHP Notice: Trying to access array offset on value of type null (in Echo NotifUser).Sep 14 2022, 12:33 PM
Krinkle subscribed.

I had a brief look as well and agree, "this seems strictly impossible".

However. I found a line that calls $memcKey = $this->getGlobalMemcKey( self::CACHE_KEY ). When this fails and returns false it will silently skip parts of the code that creates the array. The MWEchoNotifUser::getCountsAndTimestamps( true )['global'] element will contain null then. @Tgr, you are more familiar with this code. What do you think?

When User::addToDatabase() takes very long, that is/could be an indicator that database is under high load. The call to CentralIdLookup::centralIdFromLocalUser in getGlobalMemcKey is using READ_NORMAL and is using possible a lagged replica (when ChronologyProtector is not able to protect) and not found the global user entry created some miliseconds ago.

Just fall back to provide the local count.

I have created a patch set based on the helpful input about getGlobalMemcKey and the possible null result. It is possible there since d90e2d1

Change 833841 had a related patch set uploaded (by Umherirrender; author: Umherirrender):

[mediawiki/extensions/Echo@master] Fall back to local notification count when no global user was found

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

kostajh changed the task status from Open to In Progress.Oct 14 2022, 12:48 PM
kostajh triaged this task as Medium priority.

Change 833841 merged by jenkins-bot:

[mediawiki/extensions/Echo@master] Fall back to local notification count when no global user is found

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

Umherirrender claimed this task.