1661607 - mozregression with -B debug option fails a weird time data mismatch error

Status: RESOLVED FIXED

(Testing :: mozregression, defect)

Description

[Hiroyuki Ikezoe (:hiro)]

When I run "./mach mozregression -B debug -g 79", it fails;

ValueError: time data '2020-08-27T21:51:55.78826+00:00' does not match format '%Y-%m-%dT%H:%M:%S.%fZ'

Comment 1

[William Lachance (:wlach)]

(In reply to Hiroyuki Ikezoe (:hiro) from comment #0)

When I run "./mach mozregression -B debug -g 79", it fails;

ValueError: time data '2020-08-27T21:51:55.78826+00:00' does not match format '%Y-%m-%dT%H:%M:%S.%fZ'

Strange, without the -B debug things seem to work. Not sure what's going on.

Comment 2

[Bob Clary [:bc] (inactive)]

I see the same with mozregression -n gve --repo autoland --good 2020-08-27 --bad 2020-08-28

Comment 3

[Bob Clary [:bc] (inactive)]

This works though mozregression -n gve --repo autoland --good 2020-08-20 --bad 2020-08-26. But mozregression -n gve --repo autoland --good 2020-08-20 --bad 2020-08-27 doesn't work. Change in how taskcluster reports datetimes?

Comment 4

[William Lachance (:wlach)]

This does indeed seem taskcluster related.

Here's a traceback:

ValueError: time data '2020-08-27T21:57:02.817766+00:00' does not match format '%Y-%m-%dT%H:%M:%S.%fZ'
Traceback (most recent call last):
  File "/Users/wlach/src/mozregression/venv38/bin/mozregression", line 33, in <module>
    sys.exit(load_entry_point('mozregression', 'console_scripts', 'mozregression')())
  File "/Users/wlach/src/mozregression/mozregression/main.py", line 341, in main
    sys.exit(method())
  File "/Users/wlach/src/mozregression/mozregression/main.py", line 155, in bisect_integration
    return self._bisect_integration(
  File "/Users/wlach/src/mozregression/mozregression/main.py", line 169, in _bisect_integration
    result = self._do_bisect(handler, good_rev, bad_rev, expand=expand)
  File "/Users/wlach/src/mozregression/mozregression/main.py", line 225, in _do_bisect
    return self.bisector.bisect(handler, good, bad, **kwargs)
  File "/Users/wlach/src/mozregression/mozregression/bisector.py", line 600, in bisect
    return self._bisect(handler, build_range)
  File "/Users/wlach/src/mozregression/mozregression/bisector.py", line 620, in _bisect
    result = bisection.init_handler(index)
  File "/Users/wlach/src/mozregression/mozregression/bisector.py", line 398, in init_handler
    self.handler.initialize()
  File "/Users/wlach/src/mozregression/mozregression/bisector.py", line 75, in initialize
    repo = self.build_range[-1].repo_url
  File "/Users/wlach/src/mozregression/mozregression/build_range.py", line 93, in __getitem__
    return self._future_build_infos[item].build_info
  File "/Users/wlach/src/mozregression/mozregression/build_range.py", line 37, in build_info
    self._build_info = self._fetch()
  File "/Users/wlach/src/mozregression/mozregression/build_range.py", line 31, in _fetch
    return self.build_info_fetcher.find_build_info(self.data)
  File "/Users/wlach/src/mozregression/mozregression/fetch_build_info.py", line 137, in find_build_info
    build_date = datetime.strptime(run["resolved"], "%Y-%m-%dT%H:%M:%S.%fZ")
  File "/usr/local/Cellar/python@3.8/3.8.4/Frameworks/Python.framework/Versions/3.8/lib/python3.8/_strptime.py", line 568, in _strptime_datetime
    tt, fraction, gmtoff_fraction = _strptime(data_string, format)
  File "/usr/local/Cellar/python@3.8/3.8.4/Frameworks/Python.framework/Versions/3.8/lib/python3.8/_strptime.py", line 349, in _strptime
    raise ValueError("time data %r does not match format %r" %
ValueError: time data '2020-08-27T21:57:02.817766+00:00' does not match format '%Y-%m-%dT%H:%M:%S.%fZ'

Relevant code is here:

https://github.com/mozilla/mozregression/blob/62c1344bf695fa4ed4d2b463f0e9da9a0b01a852/mozregression/fetch_build_info.py#L137

Dustin, do you have any thoughts here? I assume we just need to be more flexible in how we parse timestamps?

Comment 5

[Dustin J. Mitchell [:dustin] (he/him)]

Ugh, we shouldn't be returning things in that format -- that's a postgres-formatted ISO timestamp, rather than one from Node (which is what we promise to include in our APIs).

In the interim, yes, being more flexible in parsing times is the fix.

But, we should fix that API method to return an appropriately-formatted datestamp. https://github.com/taskcluster/taskcluster/issues/3464 It will be mid-September before that gets deployed, though.

Comment 6

[GitHub Bugzilla PR Linker]

Attachment: Link to GitHub pull-request: https://github.com/mozilla/mozregression/pull/725

Comment 7

[William Lachance (:wlach)]

Thanks Dustin! mozregression 4.0.13 released with a temporary workaround.

Comment 8

[Bob Clary [:bc] (inactive)]

That fixes it for me. Thanks!

Comment 9

[Botond Ballo [:botond]]

I'm still seeing this with 4.0.13:

ValueError: time data '2020-08-28T15:56:43.178742+00:00' does not match format '%Y-%m-%dT%H:%M:%S.%f%z'

The format string has changed, so I know I've picked up the patch, but the time string still isn't matching for some reason.

Comment 10

[Botond Ballo [:botond]]

From the strptime() docs:

Changed in version 3.7: When the %z directive is provided to the strptime() method, the UTC offsets can have a colon as a separator between hours, minutes and seconds. For example, '+01:00:00' will be parsed as an offset of one hour. In addition, providing 'Z' is identical to '+00:00'.

I'm using python 3.6, so for me %z is not matching the colon.

Comment 11

[William Lachance (:wlach)]

(In reply to Botond Ballo [:botond] from comment #10)

From the strptime() docs:

Changed in version 3.7: When the %z directive is provided to the strptime() method, the UTC offsets can have a colon as a separator between hours, minutes and seconds. For example, '+01:00:00' will be parsed as an offset of one hour. In addition, providing 'Z' is identical to '+00:00'.

I'm using python 3.6, so for me %z is not matching the colon.

Got it, we'll need to revisit this then. Did you manage to find an approach that worked locally? If you have time, could you submit a PR?

Comment 12

[Botond Ballo [:botond]]

(In reply to William Lachance (:wlach) (use needinfo!) from comment #11)

Got it, we'll need to revisit this then. Did you manage to find an approach that worked locally? If you have time, could you submit a PR?

I observed that the timezone strings were always +00:00, at least for the bisection I was doing, and changed the format string to be "%Y-%m-%dT%H:%M:%S.%f+00:00", which fixed it for me locally.

If you think that's an acceptable change to land, I'm happy to submit a PR.

Comment 13

[William Lachance (:wlach)]

(In reply to Botond Ballo [:botond] from comment #12)

(In reply to William Lachance (:wlach) (use needinfo!) from comment #11)

Got it, we'll need to revisit this then. Did you manage to find an approach that worked locally? If you have time, could you submit a PR?

I observed that the timezone strings were always +00:00, at least for the bisection I was doing, and changed the format string to be "%Y-%m-%dT%H:%M:%S.%f+00:00", which fixed it for me locally.

If you think that's an acceptable change to land, I'm happy to submit a PR.

I suspect the timezones are always in UTC but we should probably be more flexible about timezone, as long as we're doing this. I'll do up an alternate approach later today.

Comment 14

[Dustin J. Mitchell [:dustin] (he/him)]

They are all in UTC. This is a workaround and I'm working on the fix right now, so don't work too hard :)

Note that the +00:00 will disappear when the fix is deployed!

Comment 15

[William Lachance (:wlach)]

(In reply to Dustin J. Mitchell [:dustin] (he/him) from comment #14)

They are all in UTC. This is a workaround and I'm working on the fix right now, so don't work too hard :)

Note that the +00:00 will disappear when the fix is deployed!

Ok, great! :botond could you submit that PR? :)

Comment 16

[GitHub Bugzilla PR Linker]

Attachment: Link to GitHub pull-request: https://github.com/mozilla/mozregression/pull/728

Comment 17

[Botond Ballo [:botond]]

Submitted.

Comment 19

[William Lachance (:wlach)]

PSA: Just released 4.0.14 with the fix.

Comment 20

[BugBot [:suhaib / :marco/ :calixte]]

The severity field is not set for this bug.
:wlach, could you have a look please?

For more information, please visit auto_nag documentation.