Convert automationutils.py to use structured logging

RESOLVED FIXED in mozilla34

Status

Testing
Mochitest
RESOLVED FIXED
4 years ago
4 years ago

People

(Reporter: jgraham, Assigned: chmanchester)

Tracking

(Blocks: 2 bugs)

unspecified
mozilla34
x86_64
Linux
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment, 4 obsolete attachments)

(Probably in the wrong component).

automationutils.py needs to be converted to use structured logging when available.
Created attachment 8463879 [details] [diff] [review]
structured.diff

Attached a very basic patch that seems to cause output to happen, but doesn't get the semantics right.
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.
"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"))
Summary: Convert automationutilis.py to use structured logging → Convert automationutils.py to use structured logging
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.
Bug 1039833 should fix that for mochitest. (just doing a new try push now)
(Assignee)

Updated

4 years ago
See Also: → bug 1044206, bug 1045255
(Assignee)

Updated

4 years ago
Blocks: 916295
(Assignee)

Updated

4 years ago
Blocks: 1049827
(Assignee)

Comment 6

4 years ago
Created attachment 8479114 [details] [diff] [review]
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
(Assignee)

Updated

4 years ago
Assignee: nobody → cmanchester
Status: NEW → ASSIGNED
(Assignee)

Comment 7

4 years ago
Created attachment 8480289 [details] [diff] [review]
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
Attachment #8480289 - Flags: review?(ahalberstadt)
(Assignee)

Updated

4 years ago
Attachment #8479114 - Attachment is obsolete: true
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
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 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.
Attachment #8480289 - Flags: review?(ahalberstadt) → review+
(Assignee)

Comment 11

4 years ago
(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.
(Assignee)

Comment 12

4 years ago
Created attachment 8481049 [details] [diff] [review]
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
(Assignee)

Updated

4 years ago
Attachment #8480289 - Attachment is obsolete: true
(Assignee)

Comment 13

4 years ago
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
Attachment #8481049 - Flags: review+
(Assignee)

Updated

4 years ago
Attachment #8463879 - Attachment is obsolete: true
(Assignee)

Comment 14

4 years ago
Created attachment 8481058 [details] [diff] [review]
Convert automationutils and remaining python loggin' to use mozlog.structured.

Missed some stdlib style string formatting that needed conversion.
(Assignee)

Updated

4 years ago
Attachment #8481049 - Attachment is obsolete: true
(Assignee)

Comment 15

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

r=ahal
Attachment #8481058 - Flags: review+
(Assignee)

Updated

4 years ago
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/5ca1a1ec89d3
Status: ASSIGNED → RESOLVED
Last Resolved: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla34
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?
(Assignee)

Comment 19

4 years ago
(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.
Great, thanks!
(Assignee)

Updated

4 years ago
Duplicate of this bug: 1042933
You need to log in before you can comment on or make changes to this bug.