Closed
Bug 1079635
Opened 10 years ago
Closed 10 years ago
Implement verbose mode for the mach formatter
Categories
(Testing :: Mozbase, defect)
Tracking
(Not tracked)
RESOLVED
FIXED
mozilla36
People
(Reporter: chmanchester, Assigned: chmanchester)
References
Details
Attachments
(1 file, 1 obsolete file)
8.14 KB,
patch
|
jgraham
:
review+
|
Details | Diff | Splinter Review |
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.
Assignee | ||
Comment 1•10 years ago
|
||
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 | ||
Updated•10 years ago
|
Assignee: nobody → cmanchester
Status: NEW → ASSIGNED
Comment 2•10 years ago
|
||
What if passing in --log-mach-level 'debug' turned off buffering? Kind of seems like verbosity and level mean the same thing..
Assignee | ||
Comment 3•10 years ago
|
||
(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 4•10 years ago
|
||
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-
Assignee | ||
Comment 5•10 years ago
|
||
(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.
Comment 6•10 years ago
|
||
(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.
Comment 7•10 years ago
|
||
(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.
Assignee | ||
Comment 8•10 years ago
|
||
Attachment #8506432 -
Flags: review?(james)
Assignee | ||
Updated•10 years ago
|
Attachment #8505642 -
Attachment is obsolete: true
Comment 9•10 years ago
|
||
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+
Assignee | ||
Comment 10•10 years ago
|
||
https://hg.mozilla.org/integration/mozilla-inbound/rev/61df477b1505
Comment 11•10 years ago
|
||
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.
Description
•