1045525 - Convert automationutils.py to use structured logging

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[James Graham [:jgraham]]

(Probably in the wrong component).

automationutils.py needs to be converted to use structured logging when available.

Comment 1

[James Graham [:jgraham]]

Attachment: structured.diff

Attached a very basic patch that seems to cause output to happen, but doesn't get the semantics right.

Comment 2

[(not currently active) Ted Mielczarek]

Ideally I'd like to move everything from automationutils.py to live in mozbase instead, but anything you need to do to ease the pain right now is fine.

Comment 3

[Ahmed Kachkach [:akachkach]]

"setup_structured_logging" doesn't seem to be called.

(another solution here is to initialize the log to None, and in all functions it's used get it with some accessor get_logger() that returns log or structuredlog.get_default_logger("automationutils"))

Comment 4

[James Graham [:jgraham]]

setup_structured_logging has to be called from whatever imports this e.g. mochitest. I seem to have not included those changes in my patch but it's rather straightforward.

Comment 5

[Ahmed Kachkach [:akachkach]]

Bug 1039833 should fix that for mochitest. (just doing a new try push now)

Comment 6

[Chris Manchester (limited bugmail, email directly)]

Attachment: Convert automationutils and remaining python loggin' to use mozlog.structured

There are at least two interpretations of this bug: pass existing unstructured logging emanating from automationutils to the structured logger so they end up in the raw structured log, and rewrite the checks done in automationutils to use the structured logging api in a more meaningful way. This is a work in progress addressing the former.

Try so we can inspect output and confirm we get what's expected:

https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=cab0c5e1fde8
https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=10fecc0284b6

Comment 7

[Chris Manchester (limited bugmail, email directly)]

Attachment: Convert automationutils and remaining python loggin' to use mozlog.structured.

Except for a problem with android this produced the expected output. The indentation situation in runtests.py is pretty untenable.

Try:

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

Comment 8

[Ahmed Kachkach [:akachkach]]

Comment on attachment 8480289 [details] [diff] [review]
Convert automationutils and remaining python loggin' to use mozlog.structured.

Review of attachment 8480289 [details] [diff] [review]:
-----------------------------------------------------------------

This is great! It's not only converting automationutils.py, it will also turn back structured logging for logs generated in runtests.py, runtestsb2g.py and runtestsremote.py

Comment 9

[Nick Alexander :nalexander [he/him]]

Can't come soon enough for me.  This gives me a colorized log in my WIP |mach robocop|, and makes it possible to actually see the relevant output.

Comment 10

[Andrew Halberstadt [:ahal]]

Comment on attachment 8480289 [details] [diff] [review]
Convert automationutils and remaining python loggin' to use mozlog.structured.

Review of attachment 8480289 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good, r+ with comments addressed.

::: build/automationutils.py
@@ +45,5 @@
> +resetGlobalLog()
> +
> +def set_automation_log(alt_logger):
> +  global log
> +  log = alt_logger

This is kind of horrible, but I guess when the code is horrible to begin with, then who cares :)

::: testing/mochitest/runtests.py
@@ +96,5 @@
> +           output = '%d %s %s' % (MochitestFormatter.log_num, log_level, output)
> +           MochitestFormatter.log_num += 1
> +        elif log_level == 'ERROR':
> +           output = '%d %s %s' % (MochitestFormatter.log_num, log_level, output)
> +           MochitestFormatter.log_num += 1

I think this would be better written as:

if 'js_source' in data or log_level == 'ERROR':
    data.pop('js_source', None)
    output = '%d %s %s' % (MochitestFormatter.log_num, log_level, output)
    MochitestFormatter.log_num += 1

@@ +437,5 @@
> +                                             "Mochitest specific tbpl formatter")
> +      self.log = commandline.setup_logging("mochitest",
> +                                           logger_options,
> +                                           {
> +                                              "tbpl": sys.stdout

Is automation depending on tbpl being the default? If not, let's be adventurous and make the format something more exciting, like 'mach'. If so, let's file a bug to get mozharness to pass in --log-tbpl so that we can use a different format locally.

::: testing/mochitest/tests/SimpleTest/TestRunner.js
@@ +243,5 @@
>          var allData = {action: action,
>                         time: new Date().getTime(),
>                         thread: "",
> +                       // This is a directive to python to format these messages
> +                       // for compatibility with mozharness.

Maybe add a bug number and mention this can be removed when it gets fixed.

Comment 11

[Chris Manchester (limited bugmail, email directly)]

(In reply to Andrew Halberstadt [:ahal] from comment #10)
> Comment on attachment 8480289 [details] [diff] [review]
> Convert automationutils and remaining python loggin' to use
> mozlog.structured.
> 
> Review of attachment 8480289 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Looks good, r+ with comments addressed.
> 
> ::: build/automationutils.py
> @@ +45,5 @@
> > +resetGlobalLog()
> > +
> > +def set_automation_log(alt_logger):
> > +  global log
> > +  log = alt_logger
> 
> This is kind of horrible, but I guess when the code is horrible to begin
> with, then who cares :)

Horrible is the word, but I'm open to any ideas to help clean this up. At least now the global side effect happends in the same file that depends on it.

> 
> ::: testing/mochitest/runtests.py
> @@ +96,5 @@
> > +           output = '%d %s %s' % (MochitestFormatter.log_num, log_level, output)
> > +           MochitestFormatter.log_num += 1
> > +        elif log_level == 'ERROR':
> > +           output = '%d %s %s' % (MochitestFormatter.log_num, log_level, output)
> > +           MochitestFormatter.log_num += 1
> 
> I think this would be better written as:
> 
> if 'js_source' in data or log_level == 'ERROR':
>     data.pop('js_source', None)
>     output = '%d %s %s' % (MochitestFormatter.log_num, log_level, output)
>     MochitestFormatter.log_num += 1
> 
> @@ +437,5 @@
> > +                                             "Mochitest specific tbpl formatter")
> > +      self.log = commandline.setup_logging("mochitest",
> > +                                           logger_options,
> > +                                           {
> > +                                              "tbpl": sys.stdout
> 
> Is automation depending on tbpl being the default? If not, let's be
> adventurous and make the format something more exciting, like 'mach'. If so,
> let's file a bug to get mozharness to pass in --log-tbpl so that we can use
> a different format locally.

bug 1060189

> 
> ::: testing/mochitest/tests/SimpleTest/TestRunner.js
> @@ +243,5 @@
> >          var allData = {action: action,
> >                         time: new Date().getTime(),
> >                         thread: "",
> > +                       // This is a directive to python to format these messages
> > +                       // for compatibility with mozharness.
> 
> Maybe add a bug number and mention this can be removed when it gets fixed.

Comment 12

[Chris Manchester (limited bugmail, email directly)]

Attachment: Convert automationutils and remaining python loggin' to use mozlog.structured.

Sanity check with nits addressed:
https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=2c0e7f618ce2

Comment 13

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8481049 [details] [diff] [review]
Convert automationutils and remaining python loggin' to use mozlog.structured.

Review of attachment 8481049 [details] [diff] [review]:
-----------------------------------------------------------------

r=ahal

Comment 14

[Chris Manchester (limited bugmail, email directly)]

Attachment: Convert automationutils and remaining python loggin' to use mozlog.structured.

Missed some stdlib style string formatting that needed conversion.

Comment 15

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8481058 [details] [diff] [review]
Convert automationutils and remaining python loggin' to use mozlog.structured.

r=ahal

Comment 16

[Chris Manchester (limited bugmail, email directly)]

 https://hg.mozilla.org/integration/mozilla-inbound/rev/5ca1a1ec89d3

Comment 17

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/5ca1a1ec89d3

Comment 18

[Tim Taubert [:ttaubert] (inactive)]

Looks like this broke coloring for log output - TEST-PASS used to be green and TEST-UNEXPECTED-FAIL red in my console. Is that a deliberate change?

Comment 19

[Chris Manchester (limited bugmail, email directly)]

(In reply to Tim Taubert [:ttaubert] from comment #18)
> Looks like this broke coloring for log output - TEST-PASS used to be green
> and TEST-UNEXPECTED-FAIL red in my console. Is that a deliberate change?

Color was added to those logs by mach, so this is an effect of the change, but the loss of that feature isn't intended or inevitable. Mozlog's mach formatter supports colored output, I filed bug 1061670 to get these logged at a level that will turn these messages red. Until bug 1060189 lands, passing "--log-mach -" will set up this formatter.

Comment 20

[Tim Taubert [:ttaubert] (inactive)]

Great, thanks!