1208102 - Treeherder is submitting the classification dates to ElasticSearch with the wrong timezone

Status: RESOLVED FIXED

(Tree Management :: Treeherder, defect, P2)

Description

[Ed Morley [:emorley]]

On:
http://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1207774&startday=2015-09-23&endday=2015-09-23&tree=all

There are both entries from 23rd and 24th Sept.

Must be more timezone related fun, sigh.

Comment 1

[Ed Morley [:emorley]]

This will likely be fixed by bug 1209339.

Comment 2

[Ed Morley [:emorley]]

(In reply to Ed Morley [:emorley] from comment #1)
> This will likely be fixed by bug 1209339.

Hmm or not.

So for this page:
http://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1207774&startday=2015-09-23&endday=2015-09-23&tree=all

Classifications are shown from midday 23rd sept through to almost 8am 24th sept, so this must be a pacific vs UTC timezone issue.

The API call for that page is:
http://brasstacks.mozilla.com/orangefactor/api/bybug?startday=2015-09-23&endday=2015-09-23&bugid=1207774

Picking the last occurrence:
* Job start time as shown in the OF UI: 24 Sep 2015, 07:38 UTC
* Job start time shown in the raw log: 1443080294.8 -> 09/24/2015 @ 7:38am (UTC)

From the OF API response:
    {
      "buildtype": "debug",
      "branch": "try",
      "treeherder_job_id": 11835104,
      "date": "2015-09-23",
      "bug": "1207774",
      "machinename": "t-w864-ix-040",
      "classification_time": "1443391353",
      "platform": "windows8-64",
      "starttime": "1443080294",
      "test": "mochitest-browser-chrome-2",
      "revision": "a96306a84fc8"
    }

classification_time -> 09/27/2015 @ 10:02pm (UTC)
starttime -> matches what the raw log says: 09/24/2015 @ 7:38am (UTC)

So basically "date" is wrong.

This is confirmed by looking at the raw data for that classification in ElasticSearch:
{
    "buildtype": "debug",
    "treeherder_job_id": 11835104,
    "os": "windows8-64",
    "tree": "try",
    "who": "SNIP",
    "buildname": "Windows 8 64-bit try debug test mochitest-browser-chrome-2",
    "date": "2015-09-23",
    "bug": "1207774",
    "machinename": "t-w864-ix-040",
    "rev": "a96306a84fc8",
    "starttime": "1443080294",
    "timestamp": "1443391353",
    "type": "Mochitest Browser Chrome"

},

So Treeherder is in fact submitting the 'date' field in Pacific, not UTC after all, even though the rabbitmq timezone is UTC:

[[e-mail]3 ~]$ date
Tue Sep 29 11:17:56 UTC 2015

Comment 3

[Ed Morley [:emorley]]

Hmm:

[[e-mail]3 treeherder-service]$ date
Tue Sep 29 11:40:50 UTC 2015

[[e-mail]3 ~]$ cat /etc/sysconfig/clock
ZONE="UTC"

[[e-mail]3 ~]$ ls -l /etc/localtime
lrwxrwxrwx 1 root root 23 May 30  2014 /etc/localtime -> /usr/share/zoneinfo/UTC

[[e-mail]3 treeherder-service]$ ../venv/bin/python ./manage.py shell
>>> import datetime
>>>  datetime.datetime.today()
datetime.datetime(2015, 9, 29, 4, 37, 11, 902909)

[[e-mail]3 treeherder-service]$ ../venv/bin/python
>>> import datetime
>>> datetime.datetime.today()
datetime.datetime(2015, 9, 29, 11, 39, 46, 530121)

So it looks like the Django python environment has overridden the timezone datetime uses, even though the Django docs imply that the settings/base.py line of:
TIME_ZONE = "America/Los_Angeles"
...should only affect internal Django functionality.

I've found this that shows that Django does mess with the environment variable TZ, which is presumably why datetime behaviour changes:
https://github.com/django/django/blob/593c9eb6608c660f9e2c1ade227670539ececd8e/django/conf/__init__.py#L119-L129

Either way, Treeherder should always have been using utcfromtimestamp() not fromtimestamp() (the latter is a big footgun, why it's called that in the std python library I don't know; localfromtimestamp() would be much more useful) - so let's fix that. In another bug we can look at changing TIME_ZONE in settings/base.py to UTC, but there might be wider implications so not going to do that here.

Comment 4

[Ed Morley [:emorley]]

Attachment: Submit the job start time date as UTC to ElasticSearch

Comment 5

[Treeherder GitHub Bugbot]

Commit pushed to master at https://github.com/mozilla/treeherder

https://github.com/mozilla/treeherder/commit/28d5708d7f285e82ca03b5c97608daa8d0c42cb2
Bug 1208102 - Submit the job start time date as UTC to ElasticSearch

Since `.fromtimestamp()` is being overridden by Django's TIME_ZONE and
so uses Pacific Time, even though rabbitmq's server time is UTC.