Page MenuHomePhabricator

Monolog processed log events have dates in $wgLocaltimezone rather than UTC
Closed, ResolvedPublic

Description

@faidon pointed out on irc that he had seen log events on fluorine with dates in timezones other than UTC. I poked around a bit in the Monolog source and found that this is feature added in Monolog 1.12.0. Each log event gets a DateTime object that eventually is formatted to a string via DateTime::format(). Since Monolog 1.12.0 these events are explicitly cast into the timezone returned by date_default_timezone_get().

At this point I'm not exactly sure where in the wiki startup cycle we use $wgLocaltimezone to set the timezone, but it certainly happens:

terbium:~
bd808$ mwscript eval.php enwiki
> echo date_default_timezone_get();
UTC

terbium:~
bd808$ mwscript eval.php barwiki
> echo date_default_timezone_get();
Europe/Berlin

We need to find a way to control the behavior of Monolog to allow us to force the log event DateTimes into UTC.

Event Timeline

bd808 raised the priority of this task from to Needs Triage.
bd808 updated the task description. (Show Details)
bd808 added a project: MediaWiki-Debug-Logger.
bd808 added subscribers: bd808, faidon.
faidon triaged this task as High priority.May 20 2015, 5:34 PM
faidon added a project: Scrum-of-Scrums.
faidon set Security to None.

I think we are going to have to submit a patch upstream to Monolog to fix this. When we have a working patch we can cherry-pick it into mediawiki/vagrant.git until there is an upstream release that supports our feature. Luckily we thought about this when we drafted the rules for using Composer at WMF.

The upstream patch I made has been merged as https://github.com/Seldaek/monolog/commit/5d7db08106dc276b6693b64a4a87428ab8c62779 with a small API change as a followup in https://github.com/Seldaek/monolog/commit/8c4b1be4a2116751c16e75a8efb97f11ce2f4a47.

It would be trivial to backport this change to a fork but if we can wait a bit longer on this it seems likely that upstream will release an official version that includes the patch and then we can close out T99498 as well by upgrading.

Monolog 1.14.0 has been released which includes my patch to allow us to control the timezone.

Change 220781 had a related patch set uploaded (by BryanDavis):
Upgrade Monolog to v1.14.0

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

Change 220784 had a related patch set uploaded (by BryanDavis):
logging: Force Monolog logger timezone to UTC

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

Change 220781 merged by jenkins-bot:
Upgrade Monolog to v1.14.0

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

Change 220784 merged by jenkins-bot:
logging: Force Monolog logger timezone to UTC

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

The config change needed for this is live and the Monolog change needed to work with it will ride the train with 1.26wmf12 which should start hitting the wikis on 2015-06-30.

This change is on all wikis now and seems to be working as intended. I used grep -C 1 hewiki /a/mw-log/CentralAuth.log to check logs on fluorine and visually confirmed that the timestamps on the hewiki ($wgLocaltimezone = 'Asia/Tel_Aviv') events fit chronologically with the surrounding events. In log samples from prior to the 1.26wmf12 changes timestamps for hewiki are 3 hours ahead of UTC.

Change 963661 had a related patch set uploaded (by Krinkle; author: Krinkle):

[mediawiki/core@master] debug: Optimize createLogger() and set UTC timezone by default

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

Change 963662 had a related patch set uploaded (by Krinkle; author: Krinkle):

[operations/mediawiki-config@master] logging: Remove redundant setTimezone() call for UTC

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

Change 963661 merged by jenkins-bot:

[mediawiki/core@master] debug: Optimize createLogger() and set UTC timezone by default

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

Change 963662 merged by jenkins-bot:

[operations/mediawiki-config@master] logging: Remove redundant setTimezone() call for UTC

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