1018907 - timestamps for build directories are off by timezone offset (7 hours)

Status: RESOLVED FIXED

(Release Engineering :: General, defect)

Description

[Elbart]

$ mozregression --bits=32 --inbound --good-rev=fda65b2f990a --bad-rev=2708630b4998
Getting inbound builds between fda65b2f990a and 2708630b4998
Oh noes, no (more) inbound revisions :(

===

https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=41a54c8add09&tochange=2708630b4998

fda65b2f990a
http://inbound-archive.pub.build.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-inbound-win32/1400357193/

62d1670e37d9:
http://inbound-archive.pub.build.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-inbound-win32/1400357908/

246aa86a5e0e:
http://inbound-archive.pub.build.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-inbound-win32/1400359532/

5bb98302ae5d:
http://inbound-archive.pub.build.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-inbound-win32/1400361992/

2708630b4998:
http://inbound-archive.pub.build.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-inbound-win32/1400367691/

Comment 1

[William Lachance (:wlach)]

Had a look at this, it's very confusing. It looks like the build times on inbound are *before* these patches were committed, so they're being missed. I.e. here's the json pushlog:

https://hg.mozilla.org/integration/mozilla-inbound/json-pushes?fromchange=41a54c8add09&tochange=2708630b4998

But if I actually scan the inbound archive using mozregression (http://inbound-archive.pub.build.mozilla.org/pub//mozilla.org/firefox/tinderbox-builds/mozilla-inbound-linux/) using a large range, here's when the corresponding builds inside that range are marked as being built:

--> Found 246aa86a5e0e 1400359532
   --> 246aa86a5e0e039f315c618021bfb603b12d6f33 Valid
--> Found 5bb98302ae5d 1400361992
   --> 5bb98302ae5d3ffa59382120539c93ca494e7e02 Valid
--> Found 2708630b4998 1400367691
   --> 2708630b4998462126ffa4e9a1befe4f46bdb02e Valid

For example, 246aa86a5e0e was supposed to have been pushed at 1400384702, almost 7 hours after the build. This doesn't make any sense to me: shouldn't builds come *after* pushes? Are we not adjusting for time zone differences or something? I asked RyanVM on irc, and he had no idea. Needinfo'ing :ted, who might?

Comment 2

[(not currently active) Ted Mielczarek]

The pushlog just inserts time.time() into the date field:
http://hg.mozilla.org/hgcustom/hghooks/file/0ee2f8335098/mozhghooks/pushlog.py#l65

I have no idea where the timestamp for the directory name comes from, it's way out of left field.

The pushlog shows:
"date": 1400384702, 

which is:
2014-05-17 20:45:02-07:00 (omg that's hard to calculate correctly in Python!)

the dated dir is:
1400359532

which comes out to:
2014-05-17 13:45:32-07:00

It looks like it's 7 hours off. The only thing that makes sense to me is if someone accidentally added the timezone offset into the timestamp here.

FWIW I surveyed some other dates and they all seem to match the pushlog's idea of date.

From firefox-32.0a1.en-US.linux-i686.txt:
20140517204532 (build ID)

From the Linux build log mozilla-inbound-linux-bm71-build1-build289.txt.gz:
starttime: 1400385287.41 (which is 2014-05-17 23:54:47.410000-07:00)
========= Started set props: basedir (results: 0, elapsed: 0 secs) (at 2014-05-17 20:54:47.407072) =========

Comment 3

[Chris AtLee [:catlee]]

yeah, smells like a timezone issue. Pacific time is UTC-7 at the moment I believe?

If you ignore the hour offset, it looks like the dated dir is about 30s later than the push time, which makes sense. We generate the buildid when scheduling jobs, which happens after detecting a new hg change. This generated buildid is used to create the directory names.

What are the buildids for these builds? Do they match the directory names?

Comment 4

[(not currently active) Ted Mielczarek]

The build ID is in comment 2, 20140517204532, compare vs. the pushlog date:

build id: 2014-05-17 20:45:32 
pushlog : 2014-05-17 20:45:02

But yeah, it's off by exactly 7 hours:
>>> pushdate = 1400384702
>>> dirdate = 1400359532
>>> dirdate - pushdate
-25170
>>> (dirdate + 7*60*60) - pushdate
30
>>>

Comment 5

[(not currently active) Ted Mielczarek]

I would say with 99% certainty that it's this function doing wrong datetime math:
http://hg.mozilla.org/build/tools/file/tip/stage/post_upload.py#l129

Comment 6

[(not currently active) Ted Mielczarek]

Attachment: Fix post_upload to get the right unix timestamp from Build IDs

This should fix it, this code snippet works right locally:
>>> buildid = '20140517204532'
>>> calendar.timegm(pt.localize(datetime.strptime(buildid, "%Y%m%d%H%M%S")).utctimetuple())
1400384732
>>> 1400384732 - 1400384702
30

(that's the calculated timestamp from the build ID - the pushlog timestamp)

The only quirk is that we need pytz installed. I'll file a bug to make sure that's installed on the upload hosts.

Comment 7

[(not currently active) Ted Mielczarek]

For sanity I tested this locally (post_upload.py is kind of a pain to set up):
luser@eye7:/build/tools$ python stage/post_upload.py --product=firefox --version=32.0a1 --branch=branch --buildid=20140517204532 --no-shortdir --tinderbox-builds-dir=/tmp/tbox --release-to-tinderbox-dated-builds /tmp/temp /tmp/temp/firefox-32.0a1.en-US.win32.zip
sys.argv: ['stage/post_upload.py', '--product=firefox', '--version=32.0a1', '--branch=branch', '--buildid=20140517204532', '--no-shortdir', '--tinderbox-builds-dir=/tmp/tbox', '--release-to-tinderbox-dated-builds', '/tmp/temp', '/tmp/temp/firefox-32.0a1.en-US.win32.zip']
https://pvtbuilds2.dmz.scl3.mozilla.com/pub/mozilla.org/firefox/tinderbox-builds//tmp/tbox/1400384732/firefox-32.0a1.en-US.win32.zip
 
$ ls /tmp/builds/firefox/tinderbox-builds/tmp/tbox/1400384732/
firefox-32.0a1.en-US.win32.zip

Comment 8

[(not currently active) Ted Mielczarek]

https://hg.mozilla.org/build/tools/rev/1ddf84a3dc8c

Comment 9

[William Lachance (:wlach)]

I pushed a workaround fix to mozregression, until the old builds expire: https://github.com/mozilla/mozregression/commit/5b0a02145b5f66adbfaa18e8d790457586a3e2f0