1281412 - Taskcluster uses wrong timestamps (+8h drift) when submitting job information to Treeherder

Status: RESOLVED FIXED

(Tree Management :: Treeherder: Data Ingestion, defect)

Description

[Henrik Skupin [:whimboo][⌚️UTC+2]]

The following task has been created on TC via the API around 8:08am UTC. The results on Treeherder show a timestamp of 18:08 local time. This is a time drift of about 8h to my MEZ timezone (UTC+2).

Treeherder result:

https://treeherder.allizom.org/#/jobs?repo=mozilla-aurora&revision=23c56144e51c56304df9620bb18fb8786e087e40&filter-tier=3&filter-searchStr=tc-fxfn&selectedJob=2618464

Task (run 0):
https://tools.taskcluster.net/task-inspector/#HqACx9MmRc6bQXawCo2cJw/0

When you check the live log on Taskcluster you can see that the time is correct.

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Here the job details on Treeherder:

https://treeherder.allizom.org/api/project/mozilla-aurora/jobs/2618464/

"submit_timestamp": 1466611698 => Wed, 22 Jun 2016 16:08:18 GMT

Comment 2

[Pete Moore [:pmoore][:pete]]

Looks like it is getting set here:
https://github.com/taskcluster/mozilla-taskcluster/blob/156c6a1d360cf13900dd53f0320a54e30ccb0d56/src/treeherder/job_handler.js#L190

Comment 3

[Pete Moore [:pmoore][:pete]]

So, strangely, some jobs seem to set the date correctly, and some don't.

I'm wondering if we have two components that potentially submit data to treeherder: both mozilla-taskcluster and taskcluster-treeherder. If this was the case, it could explain why some jobs submit timestamps correctly (e.g. jobs that are a result of an hg push) and others might not.

Based on this hunch, I'm going to see if I can find where taskcluster-treeherder submits job data...

Comment 4

[Pete Moore [:pmoore][:pete]]

So it looks like in taskcluster-treeherder, we publish messages to a pulse exchange, and there is even a json schema, yay.

I see we are setting a timestamp e.g. here in the published message:
https://github.com/taskcluster/taskcluster-treeherder/blob/f82fa25f3145eaaa0bdd15d8987017864f09b7ba/src/handler.js#L207

I suspect this may be a problem on the treeherder side, ingesting the message. However we can easily validate this by listening on the exchange to see what is in the message body.

Comment 5

[Pete Moore [:pmoore][:pete]]

So digging deeper, I found we are publishing to one of our own exchanges, 

exchange/taskcluster-treeherder/v1/jobs

which is not yet added to https://wiki.mozilla.org/Auto-tools/Projects/Pulse/Exchanges#Treeherder

There is an exchange api reference (although not registered yet in http://references.taskcluster.net/manifest.json):

http://references.taskcluster.net/taskcluster-treeherder/v1/exchanges.json

and in turn, a message body schema:

http://schemas.taskcluster.net/taskcluster-treeherder/v1/pulse-job.json

Comment 6

[Greg Arndt [:garndt]]

While there is a schema published, these exchanges are not used for consuming jobs and publishing to treeherder production.  Things are stabilizing and can be consumed soon, but not yet.  Treeherder staging is consuming from this exchange currently as we work out some details.

Comment 7

[Greg Arndt [:garndt]]

The wiki has been updated to include this exchange, but beware, it's still experimental until fully used in production.

I see that manifest.json has been updated, but shouldn't it be TreeherderEvents for exchanges.json similar to the other services?

Comment 8

[Greg Arndt [:garndt]]

I just noticed in the bug description that the link is for a treeeherder staging instance and that is *only* consuming from the pulse exchange at exchange/taskcluster-treeherder-staging/v1/jobs

As an example, here are timestamps from a pulse message when f2IvrHifSiurj7Gc4EsQyw completed: 

timeScheduled:2016-06-22T12:29:26.481Z
timeStarted:2016-06-22T13:28:54.157Z
timeCompleted:2016-06-22T13:56:29.150Z

And here is the treeherder job info that was stored:
https://treeherder.allizom.org/api/project/mozilla-inbound/jobs/27723062/

Taking a look at the completed timestamp treeherder stored, it translates to 21:56 UTC instead (8 hour drift)

>>> datetime.utcfromtimestamp(1466632589).isoformat()
'2016-06-22T21:56:29'

Comment 9

[Pete Moore [:pmoore][:pete]]

(In reply to Greg Arndt [:garndt] from comment #7)
> I see that manifest.json has been updated, but shouldn't it be
> TreeherderEvents for exchanges.json similar to the other services?

Whoops, fixed now! Thanks for highlighting that!

Comment 10

[Pete Moore [:pmoore][:pete]]

From comment 8, looks like this is a treeherder bug interpreting RFC3339 dates from the exchange/taskcluster-treeherder-staging/v1/jobs exchange. Section 2 of the RFC defines 'Z' as meaning UTC, but it looks like this timezone information is not interpreted.

Comment 11

[Ed Morley [:emorley]]

Thank you for the diagnosis above! :-)

Comment 12

[Cameron Dawson [:camd]]

Yep, this is definitely my bug.  I was using a string to timestamp function that always assumed local time.  Testing my fix now...

Comment 13

[GitHub Autolander Bot]

Attachment: [treeherder] mozilla:pulse-timezone-fix > mozilla:master

Comment 14

[Cameron Dawson [:camd]]

Comment on attachment 8765661 [details] [review]
[treeherder] mozilla:pulse-timezone-fix > mozilla:master

Awesome sleuthing to find sus this one out.  Thanks so much for doing that!

I've tested this locally and it works well.  I'll test on stage tomorrow.

Comment 15

[Ed Morley [:emorley]]

Comment on attachment 8765661 [details] [review]
[treeherder] mozilla:pulse-timezone-fix > mozilla:master

r+ but I think we really should change the Pulse schema to use unix timestamps instead.

Comment 16

[Treeherder GitHub Bugbot]

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

https://github.com/mozilla/treeherder/commit/3aea1cb3e094da465d0fac3640527ff932168a79
Bug 1281412 - Fix timezones with pulse ingestion (#1619)

The pulse ingestion was throwing away the UTC timezone
that came from Task Cluster and applying the local
timezone.  That's how ``time.mktime`` works.  Now we
parse the time, get the time tuple in UTC and create
the timextamp with ``calendar.timegm`` which expects UTC
times.