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 created this task.May 18 2015, 9:55 PM
bd808 updated the task description. (Show Details)
bd808 raised the priority of this task from to Needs Triage.
bd808 added a project: MediaWiki-Debug-Logger.
bd808 added subscribers: bd808, faidon.
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptMay 18 2015, 9:55 PM
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.
bd808 claimed this task.May 20 2015, 11:16 PM

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.

bd808 added a comment.Jun 1 2015, 10:00 PM

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.

bd808 moved this task from To Do to In Dev/Progress on the User-bd808 board.Jun 18 2015, 8:46 PM

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

hoo added a subscriber: hoo.Jun 24 2015, 7:19 PM

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.

bd808 closed this task as Resolved.Jul 6 2015, 4:21 PM

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.

bd808 moved this task from Needs Review/Feedback to Done on the User-bd808 board.Jul 11 2015, 9:40 PM
bd808 moved this task from Done to Archive on the User-bd808 board.Jul 24 2015, 5:18 PM