Page MenuHomePhabricator

Echo: Special:Notifications Exception from line of : DateTimeZone::__construct(): Unknown or bad timezone (+00:00)
Closed, ResolvedPublic

Description

While testing the backport of gerrit 163976 ("Add Echo job to keep user notifications in reasonable volume") on testwiki, I got exceptions from Special:Notifications and from the Echo flyout. These continue after the backport was reverted.

From a test account I added a section and a mention to https://test.wikipedia.org/wiki/User_talk:SPage_%28WMF%29 , and now SPage (WMF) gets this exception clicking the Echo [NN] badge or visiting Special:Notifications. I assume it isn't happening on other wikis.

Page source includes "wgPoweredByHHVM":true;, but beta labs is also running HHVM.

Unexpected non-MediaWiki exception encountered, of type "Exception"
[08fd482a] /wiki/Special:Notifications Exception from line of : DateTimeZone::construct(): Unknown or bad timezone (+00:00)
Backtrace:
#0 /srv/mediawiki/php-1.25wmf1/extensions/Echo/model/Event.php(225): DateTime->
wakeup()
#1 /srv/mediawiki/php-1.25wmf1/extensions/Echo/model/Event.php(285): EchoEvent->loadFromRow(stdClass)
#2 /srv/mediawiki/php-1.25wmf1/extensions/Echo/model/Notification.php(184): EchoEvent::newFromRow(stdClass)
#3 /srv/mediawiki/php-1.25wmf1/extensions/Echo/includes/mapper/NotificationMapper.php(174): EchoNotification::newFromRow(stdClass)
#4 /srv/mediawiki/php-1.25wmf1/extensions/Echo/special/SpecialNotifications.php(51): EchoNotificationMapper->fetchByUser(User, integer, NULL, array)
#5 /srv/mediawiki/php-1.25wmf1/includes/specialpage/SpecialPage.php(363): SpecialNotifications->execute(NULL)
#6 /srv/mediawiki/php-1.25wmf1/includes/specialpage/SpecialPageFactory.php(562): SpecialPage->run(NULL)
#7 /srv/mediawiki/php-1.25wmf1/includes/MediaWiki.php(275): SpecialPageFactory::executePath(Title, RequestContext)
#8 /srv/mediawiki/php-1.25wmf1/includes/MediaWiki.php(584): MediaWiki->performRequest()
#9 /srv/mediawiki/php-1.25wmf1/includes/MediaWiki.php(435): MediaWiki->main()
#10 /srv/mediawiki/php-1.25wmf1/index.php(46): MediaWiki->run()
#11 /srv/mediawiki/w/index.php(3): include(string)
#12 {main}


Version: master
Severity: normal

Details

Reference
bz71489
Related Gerrit Patches:

Event Timeline

bzimport raised the priority of this task from to Needs Triage.Nov 22 2014, 3:52 AM
bzimport added a project: Notifications.
bzimport set Reference to bz71489.
bzimport added a subscriber: Unknown Object (MLST).

It could also be that my only notifications on testwiki are very very old.

Change 163979 had a related patch set uploaded by Spage:
Don't fatal if a notification fails to initialize

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

Change 163979 merged by jenkins-bot:
Don't fatal if a notification fails to initialize

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

Gerrit 163979 logs the problem to the 'Echo' debug log. We still need to figure out why the problem occurs.

With the change to log the exceptions, the Echo debug log when I visit contains three lines

2014-10-09 02:15:02 mw1017 testwiki: EchoNotificationMapper::fetchByUser: Failed initializing event: 2325
2014-10-09 02:15:02 mw1017 testwiki: EchoNotificationMapper::fetchByUser: Failed initializing event: 2091
2014-10-09 02:15:02 mw1017 testwiki: EchoNotificationMapper::fetchByUser: Failed initializing event: 1895

while the exception.log contains three exceptions in DateTimeZone::__construct(), the same as above.

ErikB comments "the problem with spage Special:Notifications is that an unserializable string was written to the echo db. I'm not sure the exact bug number but thats probably related to a recent production problem where the igbinary serialization format was mis-configured onto a server causing other production serialization problems as well."

Mattflaschen-WMF triaged this task as High priority.Jan 9 2015, 6:43 PM
Quiddity renamed this task from Echo: on testwiki only, Special:Notifications Exception from line of : DateTimeZone::__construct(): Unknown or bad timezone (+00:00) to Echo: Special:Notifications Exception from line of : DateTimeZone::__construct(): Unknown or bad timezone (+00:00).Jan 10 2015, 9:26 PM
Quiddity set Security to None.

Changing title, because the merged bug from Reedy has an error from enwiki:

2015-01-09 14:20:58 mw1134 enwiki: [7da582d6] /w/api.php?action=query&format=json&meta=notifications&notsections=alert%7Cmessage&notgroupbysection=1&notmessageunreadfirst=1&notformat=flyout&notlimit=25&notprop=index%7Clist%7Ccount&uselang=en&_=1420813256080   Exception from line  of : DateTimeZone::__construct(): Unknown or bad timezone (+00:00)
#0 /srv/mediawiki/php-1.25wmf13/extensions/Echo/model/Event.php(225): DateTime->__wakeup()
#1 /srv/mediawiki/php-1.25wmf13/extensions/Echo/model/Event.php(285): EchoEvent->loadFromRow()
#2 /srv/mediawiki/php-1.25wmf13/extensions/Echo/model/Notification.php(184): EchoEvent::newFromRow()
#3 /srv/mediawiki/php-1.25wmf13/extensions/Echo/includes/mapper/NotificationMapper.php(183): EchoNotification::newFromRow()
#4 /srv/mediawiki/php-1.25wmf13/extensions/Echo/api/ApiEchoNotifications.php(143): EchoNotificationMapper->fetchByUser()
#5 /srv/mediawiki/php-1.25wmf13/extensions/Echo/api/ApiEchoNotifications.php(96): ApiEchoNotifications->getPropList()
#6 /srv/mediawiki/php-1.25wmf13/extensions/Echo/api/ApiEchoNotifications.php(31): ApiEchoNotifications->getSectionPropList()
#7 /srv/mediawiki/php-1.25wmf13/includes/api/ApiQuery.php(297): ApiEchoNotifications->execute()
#8 /srv/mediawiki/php-1.25wmf13/includes/api/ApiMain.php(954): ApiQuery->execute()
#9 /srv/mediawiki/php-1.25wmf13/includes/api/ApiMain.php(392): ApiMain->executeAction()
#10 /srv/mediawiki/php-1.25wmf13/includes/api/ApiMain.php(363): ApiMain->executeActionWithErrorHandling()
#11 /srv/mediawiki/php-1.25wmf13/api.php(85): ApiMain->execute()
#12 /srv/mediawiki/w/api.php(3): include()
#13 {main}

I was going to report this issue, but saw it was already done. The numbers are not too large, but they confirm it happens on several wikis:

Last 7 days: 61 occurrences - meta.wikimedia.org (48) en.wikipedia.org (11) www.mediawiki.org (2)

The referrer is Special:Watchlist.

It looks like flow-post-reply events used to have a DateTime object in event_extra, but don't any more. The newest event I could find that had one of these was at 2014-04-09T00:06:12Z. Furthermore, it appears that there was a breaking change in how DateTimeZone serializes/unserializes, because these event_extra blobs don't unserialize cleanly any more. My best suggestion is that we re-encode all these old blobs.

This would only affect requests that try to view an old (i.e. before April 2014) "someone replied to your Flow post" notification.

Wikis that had Flow enabled in April 2014:

  • testwiki
  • test2wiki
  • mediawikiwiki
  • metawiki
  • enwiki
Legoktm claimed this task.May 13 2016, 11:31 PM

Change 288730 had a related patch set uploaded (by Legoktm):
Avoid exceptions when event_extra can't be unserialized

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

Change 288730 merged by jenkins-bot:
Avoid exceptions when event_extra can't be unserialized

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

Catrope closed this task as Resolved.May 16 2016, 9:43 PM
mmodell changed the subtype of this task from "Task" to "Production Error".Aug 28 2019, 11:12 PM