Closed Bug 1079635 Opened 10 years ago Closed 10 years ago

Implement verbose mode for the mach formatter

Categories

(Testing :: Mozbase, defect)

x86_64
Linux
defect
Not set
normal

Tracking

(Not tracked)

RESOLVED FIXED
mozilla36

People

(Reporter: chmanchester, Assigned: chmanchester)

References

Details

Attachments

(1 file, 1 obsolete file)

I'd like to land xpcshell structured logging with the machformatter as the default, but I can think of a few ways this might be perceived as a regression. For those trying to debug tests I think we'll need a verbose mode that logs test_status messages as they are emitted.
I made FAIL red and PASS green independent of expected status, that might be debatable.
Excerpt of output:

 0:00.97 TEST_STATUS: Thread-17 Test PASS run_test [run_test : 15] 57 == 57
 0:00.97 TEST_STATUS: Thread-17 Test PASS run_test [run_test : 16] 1 != 2
 0:00.97 TEST_STATUS: Thread-17 Test PASS run_test [run_test : 17] true == true
 0:00.97 LOG: Thread-17 INFO (xpcshell/head.js) | test pending (2)
 0:00.97 LOG: Thread-17 INFO (xpcshell/head.js) | test MAIN run_test finished (2)
 0:00.97 LOG: Thread-17 INFO running event loop
 0:00.98 LOG: Thread-2 INFO (xpcshell/head.js) | test MAIN run_test pending (1)
 0:00.98 TEST_STATUS: Thread-2 Test FAIL run_test [run_test : 5] do_check_throws_nsIException: func should throw an nsIException whose 'result' is Components.results.NS_NOINTERFACE, threw Error: I find your relaxed dishabille unpalatable instead
/home/chris/m-c/obj-opt/_tests/xpcshell/testing/xpcshell/example/unit/test_check_nsIException_failing.js:run_test:5
/home/chris/m-c/testing/xpcshell/head.js:_execute_test:370
-e:null:1
null:null:0
 0:00.98 LOG: Thread-2 INFO exiting test
Attachment #8505642 - Flags: review?(james)
Assignee: nobody → cmanchester
Status: NEW → ASSIGNED
What if passing in --log-mach-level 'debug' turned off buffering? Kind of seems like verbosity and level mean the same thing..
(In reply to Andrew Halberstadt [:ahal] from comment #2)
> What if passing in --log-mach-level 'debug' turned off buffering? Kind of
> seems like verbosity and level mean the same thing..

I agree they mean about the same thing, but as far as we're supporting level based logging, I think it will be least surprising if the level option only applies to that part of the API. Verbosity is an idea in the unittest library, we might want it for the unittest formatter at some point.

To be clear, this is a separate issue from xpcshell's process level buffering. This patch addresses the fact that the machformatter doesn't ever produce output at the time a test_status message is logged (it keeps a count of subtests and outputs more details on failure).
Comment on attachment 8505642 [details] [diff] [review]
Implement a verbose option for the machformatter for those debugging tests locally

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

::: testing/mozbase/mozlog/mozlog/structured/commandline.py
@@ +34,4 @@
>  fmt_options = {
>      # <option name>: (<wrapper function>, description, <applicable formatters>)
> +    'verbosity': (verbose_wrapper,
> +                  "A level of verbosity for the given formatter (1 or 2).",

Still seems nicer to just make this --log-mach-verbose even if it means extending the API a bit here.

::: testing/mozbase/mozlog/mozlog/structured/formatters/machformatter.py
@@ +237,5 @@
> +            self.status_buffer[test]["pass"] += 1
> +
> +        self._update_summary(data)
> +
> +        if self.verbosity > 1:

I'm not really sure why verbosity is an integer when there are only really two states.

@@ +240,5 @@
> +
> +        if self.verbosity > 1:
> +            status = data["status"]
> +            if status == 'FAIL':
> +                color = self.terminal.red

This should be based on the expected status, not the absolute status.

@@ +243,5 @@
> +            if status == 'FAIL':
> +                color = self.terminal.red
> +            elif status == 'PASS':
> +                color = self.terminal.green
> +            status_str = "Test %s" % color(status)

I don't think the word "Test" here is needed, is it?

@@ +244,5 @@
> +                color = self.terminal.red
> +            elif status == 'PASS':
> +                color = self.terminal.green
> +            status_str = "Test %s" % color(status)
> +            return ' '.join([status_str, data["subtest"], message])

How do you know which bit is the test name and which bit is the message?

@@ +247,5 @@
> +            status_str = "Test %s" % color(status)
> +            return ' '.join([status_str, data["subtest"], message])
> +
> +        # We only append an unexpected summary if it was not logged
> +        # directly in verbose mode.

I don't see the logic this is referring to.
Attachment #8505642 - Flags: review?(james) → review-
(In reply to James Graham [:jgraham] from comment #4)
> Comment on attachment 8505642 [details] [diff] [review]
> Implement a verbose option for the machformatter for those debugging tests
> locally
> 
> Review of attachment 8505642 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: testing/mozbase/mozlog/mozlog/structured/commandline.py
> @@ +34,4 @@
> >  fmt_options = {
> >      # <option name>: (<wrapper function>, description, <applicable formatters>)
> > +    'verbosity': (verbose_wrapper,
> > +                  "A level of verbosity for the given formatter (1 or 2).",
> 
> Still seems nicer to just make this --log-mach-verbose even if it means
> extending the API a bit here.

Ok.

> ::: testing/mozbase/mozlog/mozlog/structured/formatters/machformatter.py
> @@ +237,5 @@
> > +            self.status_buffer[test]["pass"] += 1
> > +
> > +        self._update_summary(data)
> > +
> > +        if self.verbosity > 1:
> 
> I'm not really sure why verbosity is an integer when there are only really
> two states.

The unittest api. Not great, but not 100% arbitrary.

> 
> @@ +240,5 @@
> > +
> > +        if self.verbosity > 1:
> > +            status = data["status"]
> > +            if status == 'FAIL':
> > +                color = self.terminal.red
> 
> This should be based on the expected status, not the absolute status.

Red "PASS" strings would look like a bug in the formatter. Let's make known fails blue I guess.

> 
> @@ +243,5 @@
> > +            if status == 'FAIL':
> > +                color = self.terminal.red
> > +            elif status == 'PASS':
> > +                color = self.terminal.green
> > +            status_str = "Test %s" % color(status)
> 
> I don't think the word "Test" here is needed, is it?
> 
> @@ +244,5 @@
> > +                color = self.terminal.red
> > +            elif status == 'PASS':
> > +                color = self.terminal.green
> > +            status_str = "Test %s" % color(status)
> > +            return ' '.join([status_str, data["subtest"], message])
> 
> How do you know which bit is the test name and which bit is the message?
> 
> @@ +247,5 @@
> > +            status_str = "Test %s" % color(status)
> > +            return ' '.join([status_str, data["subtest"], message])
> > +
> > +        # We only append an unexpected summary if it was not logged
> > +        # directly in verbose mode.
> 
> I don't see the logic this is referring to.

It's the early return.
(In reply to Chris Manchester [:chmanchester] from comment #5)
> (In reply to James Graham [:jgraham] from comment #4)
> > @@ +240,5 @@
> > > +
> > > +        if self.verbosity > 1:
> > > +            status = data["status"]
> > > +            if status == 'FAIL':
> > > +                color = self.terminal.red
> > 
> > This should be based on the expected status, not the absolute status.
> 
> Red "PASS" strings would look like a bug in the formatter. Let's make known
> fails blue I guess.

If the pass is unexpected it should be red. If you are worried about that prepend UNEXPECTED to the status for an unexpected pass, and EXPECTED to the status for an expected fail/crash/error/timeout.

> 
> > 
> > @@ +243,5 @@
> > > +            if status == 'FAIL':
> > > +                color = self.terminal.red
> > > +            elif status == 'PASS':
> > > +                color = self.terminal.green
> > > +            status_str = "Test %s" % color(status)
> > 
> > I don't think the word "Test" here is needed, is it?
> > 
> > @@ +244,5 @@
> > > +                color = self.terminal.red
> > > +            elif status == 'PASS':
> > > +                color = self.terminal.green
> > > +            status_str = "Test %s" % color(status)
> > > +            return ' '.join([status_str, data["subtest"], message])
> > 
> > How do you know which bit is the test name and which bit is the message?
> > 
> > @@ +247,5 @@
> > > +            status_str = "Test %s" % color(status)
> > > +            return ' '.join([status_str, data["subtest"], message])
> > > +
> > > +        # We only append an unexpected summary if it was not logged
> > > +        # directly in verbose mode.
> > 
> > I don't see the logic this is referring to.
> 
> It's the early return.
(In reply to James Graham [:jgraham] from comment #6)
> (In reply to Chris Manchester [:chmanchester] from comment #5)
> > (In reply to James Graham [:jgraham] from comment #4)
> > > @@ +247,5 @@
> > > > +            status_str = "Test %s" % color(status)
> > > > +            return ' '.join([status_str, data["subtest"], message])
> > > > +
> > > > +        # We only append an unexpected summary if it was not logged
> > > > +        # directly in verbose mode.
> > > 
> > > I don't see the logic this is referring to.
> > 
> > It's the early return.

(and replying to this too), I think that suggests the early return isn't the most readable thing here.
Attachment #8505642 - Attachment is obsolete: true
Comment on attachment 8506432 [details] [diff] [review]
Implement a verbose option for the machformatter for those debugging tests locally

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

::: testing/mozbase/mozlog/mozlog/structured/formatters/machformatter.py
@@ +242,5 @@
> +        status, subtest = data["status"], data["subtest"]
> +        unexpected = "expected" in data
> +        if self.verbose:
> +            color = self.terminal.red if unexpected else self.terminal.green
> +            rv = " ".join([subtest, color(status), message])

So I see why you did it like this, but maybe it's going to be weird with all the coloured data not aligned in the middle?

I might do

rv = "%s %s" % (color(status), subtest)
if message:
  rv += "\n%s" % message

or something. But it's up to you, no more review needed.
Attachment #8506432 - Flags: review?(james) → review+
https://hg.mozilla.org/mozilla-central/rev/61df477b1505
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla36
You need to log in before you can comment on or make changes to this bug.