1286293 - Make mozharness action messages more easily machine parseable

Status: RESOLVED FIXED

(Release Engineering :: Applications: MozharnessCore, defect, P1)

Description

[William Lachance (:wlach)]

I'd like to start storing mozharness step data in treeherder (especially their timings), but the current formatting makes it more difficult than it should be to extract a date from them (it involves a lot of munging of the full log messages, which only include the clock time). I'd like to consider changing our format from:

#####
##### Finished run-tests step (success)
#####

to:

[mozharness: 2016-07-11 21:35:08.292Z] Finished run-tests step (success)

The latter format is the same as what taskcluster uses (except using `mozharness` instead of `taskcluster`). Yay consistency.

I believe the only thing currently parsing mozharness stepdata is activedata, which no one is currently depending on and can be easily updated to use the new format. If we apply this change to central, it won't include old jobs, but I think that's ok -- I'm most interested in analyzing this data from new jobs.

Comment 1

[William Lachance (:wlach)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=77b56e2f359c

Comment 2

[William Lachance (:wlach)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=d0b0ae3294d5

Comment 3

[William Lachance (:wlach)]

Attachment: Bug 1286293 - Make mozharness action steps more machine parseable;

Review commit: https://reviewboard.mozilla.org/r/63732/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/63732/

Comment 4

[William Lachance (:wlach)]

Comment on attachment 8770225 [details]
Bug 1286293 - Make mozharness action steps more machine parseable;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/63732/diff/1-2/

Comment 5

[Gregory Szorc [:gps]]

Comment on attachment 8770225 [details]
Bug 1286293 - Make mozharness action steps more machine parseable;

https://reviewboard.mozilla.org/r/63732/#review60760

\o/

My only suggestion would be to use a `T` instead of a space in the date string. But if TaskCluster is already using the space, go for consistency.

Comment 6

[Jordan Lund (:jlund)]

Comment on attachment 8770225 [details]
Bug 1286293 - Make mozharness action steps more machine parseable;

https://reviewboard.mozilla.org/r/63732/#review60886

I have no problem with this. as far as I know, there are no consumers for the `#### $message` logging syntax in any of the self.action_message calls. It might be a bit strange having two timestamps on the log line for this but I think ppl who actually look at the logs will get over it. +1 to unified pattern matching.

wlach: I'm assuming you have things set up in Treeherder to grep for lines produced from this patch instead of https://hg.mozilla.org/mozilla-central/diff/ac4a5896be44/testing/mozharness/mozharness/base/script.py#l1726 ?

Comment 7

[Kyle Lahnakoski [:ekyle]]

It would be nice if the timestamp was a consistent length.  Please explicitly format the time.

https://docs.python.org/2/library/datetime.html#datetime.datetime.isoformat

Example python session:

    >>> print("%s"%datetime.datetime(2016,7,8,11,34,25))
    2016-07-08 11:34:25
    >>> print("%s"%datetime.datetime(2016,7,8,11,34,25, 200))
    2016-07-08 11:34:25.000200
    >>>

Comment 8

[William Lachance (:wlach)]

(In reply to Kyle Lahnakoski [:ekyle] from comment #7)
> It would be nice if the timestamp was a consistent length.  Please
> explicitly format the time.
> 
> https://docs.python.org/2/library/datetime.html#datetime.datetime.isoformat
> 
> Example python session:
> 
>     >>> print("%s"%datetime.datetime(2016,7,8,11,34,25))
>     2016-07-08 11:34:25
>     >>> print("%s"%datetime.datetime(2016,7,8,11,34,25, 200))
>     2016-07-08 11:34:25.000200
>     >>>

According to iso8601, the behavior you're describing is expected -- if we have no millisecond/microsecond information, there will be no ".XXXXXX" appended to the end. I'm happy to do an explicit call to isoformat though, just to make sure we get a consistent output.

Comment 9

[William Lachance (:wlach)]

Comment on attachment 8770225 [details]
Bug 1286293 - Make mozharness action steps more machine parseable;

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/63732/diff/2-3/

Comment 10

[William Lachance (:wlach)]

Updated implementation to use isoformat, which should be slightly more deterministic. Running through try before autolanding, but carrying forward r+.

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/3a98a8d38833
Make mozharness action steps more machine parseable; r=gps,jlund

Comment 12

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/3a98a8d38833