931854 - buildapi/recent/ returns start and end times as a unix timestamp in _pacific_ time

Status: RESOLVED FIXED

(Release Engineering :: General, defect)

Description

[[e-mail] (:bhearsum)]

Not sure if this is a bug in buildapi or the statusdb itself, but the timestamps returned from queries like: https://secure.pub.build.mozilla.org/buildapi/recent/linux-ix-slave02?format=json&numbuilds=1 are unix timestamps, but they're US/Pacific instead of UTC. This means that you end up with times in the future. Some info from the db:
mysql> describe builds;
+-------------+--------------+------+-----+---------+----------------+
| Field       | Type         | Null | Key | Default | Extra          |
+-------------+--------------+------+-----+---------+----------------+
| id          | int(11)      | NO   | PRI | NULL    | auto_increment |
| buildnumber | int(11)      | NO   | MUL | NULL    |                |
| builder_id  | int(11)      | NO   | MUL | NULL    |                |
| slave_id    | int(11)      | NO   | MUL | NULL    |                |
| master_id   | int(11)      | NO   | MUL | NULL    |                |
| starttime   | datetime     | YES  | MUL | NULL    |                |
| endtime     | datetime     | YES  | MUL | NULL    |                |
| result      | int(11)      | YES  | MUL | NULL    |                |
| reason      | varchar(500) | YES  |     | NULL    |                |
| source_id   | int(11)      | YES  | MUL | NULL    |                |
| lost        | tinyint(1)   | NO   |     | NULL    |                |
+-------------+--------------+------+-----+---------+----------------+

mysql> select unix_timestamp(endtime) from builds order by endtime desc limit 1;
+-------------------------+
| unix_timestamp(endtime) |
+-------------------------+
|              1383003100 |
+-------------------------+
1 row in set (0.00 sec)

mysql> select endtime from builds order by endtime desc limit 1;
+---------------------+
| endtime             |
+---------------------+
| 2013-10-28 16:31:43 |
+---------------------+
1 row in set (0.01 sec)



Fixing this bug probably breaks every tool that looks at buildapi.

Comment 1

[Ed Morley [:emorley]]

Will this affect builds4hr.js and builds-running/pending?

Comment 2

[Nick Thomas [:nthomas] (UTC+12)]

tl;dr - I think this is a problem in the json version buildapi/recent/ only, which probably didn't have a consumer before. We don't anything to worry about with data TBPL is consuming.


Tracking this through for this build:
http://ftp.mozilla.org/pub/mozilla.org/b2g/tinderbox-builds/pine-emulator-debug/1382985037/pine_ubuntu64_vm-b2g-emulator-debug_test-reftest-6-bm68-tests1-linux-build1.txt.gz

The log contains:
> starttime: 1382992780.94
> ========= Started set props: master (results: 0, elapsed: 0 secs) (at 2013-10-28 13:39:40.941811) 

The starttime is a genuine unix epoch which converts to 2013-10-28 13:39:40 PDT, and matches the local times logged for each step (implicit Pacific timezone for masters & slaves).

In statusdb, the matching build is:
mysql> select id, starttime, unix_timestamp(starttime) from builds where id=29800178;
+----------+---------------------+---------------------------+
| id       | starttime           | unix_timestamp(starttime) |
+----------+---------------------+---------------------------+
| 29800178 | 2013-10-28 20:39:40 |                1383017980 |
+----------+---------------------+---------------------------+

So starttime is stored as UTC (as expected), but the unix_timestamp conversion goes wrong. The server itself is likely to have Pacific time on the clock, if you take this bit of the mysql doc:
http://dev.mysql.com/doc/refman/5.6/en/date-and-time-functions.html#function_unix-timestamp

If UNIX_TIMESTAMP() is called with a date argument, it returns the value of the argument as seconds since '1970-01-01 00:00:00' UTC. date may be a DATE string, a DATETIME string, a TIMESTAMP, or a number in the format YYMMDD or YYYYMMDD. The server interprets date as a value in the current time zone and converts it to an internal value in UTC
---

Checking buildapi:
https://secure.pub.build.mozilla.org/buildapi/recent/tst-linux64-ec2-353?numbuilds=1 has 'Start time' of '2013-10-28 13:39:40', so it's converting OK in the HTML version of the output.

https://secure.pub.build.mozilla.org/buildapi/recent/tst-linux64-ec2-353?numbuilds=1&format=json has
      "starttime": 1383017980
so it's wrong in the JSON.

https://secure.pub.build.mozilla.org/builddata/buildjson/builds-4hr.js.gz and 
https://secure.pub.build.mozilla.org/builddata/buildjson/builds-2013-10-28.js.gz have
      "starttime": 1382992780
so they're OK.

For a running build, I checked that buildapi/running matched the buildbot master for both HTML and JSON output.

Comment 3

[Nick Thomas [:nthomas] (UTC+12)]

So yeah, different timezone handling:
 https://hg.mozilla.org/build/buildapi/file/358a04471ef1/buildapi/controllers/recent.py#l37
 https://hg.mozilla.org/build/buildapi/file/358a04471ef1/buildapi/templates/recent.mako#l55

Comment 4

[[e-mail] (:bhearsum)]

Thanks so much Nick, it's nice to hear that this is an isolated issue! Though, this might only be because schedulerdb stores timestamps as INTEGER rather than DATETIME...

Perhaps I'm still confused, but this seems to say that DATETIME columns are extremely dangerous when the mysql server isn't in UTC time. Or maybe our client could be doing something better.

Comment 5

[[e-mail] (:bhearsum)]

I'm pretty sure that catlee fixed this in https://hg.mozilla.org/build/buildapi/rev/0bf540f0455d