Closed Bug 857984 Opened 9 years ago Closed 9 years ago

mach mochitest-* no longer produces colored output or lists the failures at the end of test run

Categories

(Firefox Build System :: Mach Core, enhancement)

enhancement
Not set
normal

Tracking

(Not tracked)

RESOLVED FIXED
mozilla23

People

(Reporter: past, Assigned: gps)

References

Details

Attachments

(1 file, 1 obsolete file)

I'm pretty sure this worked in the past, but right now on fx-team cset b467a96d1e3e:

./mach mochitest-browser browser/devtools/debugger/test/browser_dbg_bfcache.js

ends with:


TEST-PASS | leakcheck | no leaks detected!

INFO | runtests.py | Running tests: end.


...even though I can see this earlier in the output:


INFO TEST-START | Shutdown
Browser Chrome Test Summary
	Passed: 21
	Failed: 7
	Todo: 0


No coloring of TEST-PASS or TEST-UNEXPECTED-FAIL either.
I should add that make works as before:

make -C obj-ff-dbg mochitest-browser-chrome TEST_PATH=browser/devtools/debugger/test/browser_dbg_bfcache.js

[...]

TEST-PASS | leakcheck | no leaks detected!

INFO | runtests.py | Running tests: end.
mochitest-browser-chrome failed:
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js | uncaught exception - TypeError: aGrip is undefined at resource://gre/modules/devtools/dbg-client.jsm:1198
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js | Found the expected number of scripts. - Got 3, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js | Found the expected number of scripts. - Got 3, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js | Found the expected number of scripts. - Got 3, expected 2
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js | Found the expected number of scripts. - Got 3, expected 1
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js | Found the expected number of scripts. - Got 3, expected 2
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js | Found the expected number of scripts. - Got 3, expected 2
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js | Found the expected number of scripts. - Got 3, expected 1
make: *** [mochitest-browser-chrome] Error 1
This is a regression from bug 818819. In order to get auto coloring, we need to send the output through mach's logging mechanism. Currently, it goes straight to stdout. This should hopefully be a simple fix.
Depends on: 818819
This seems to apply to any kind of mochitest. I see it when running mochitest-plain for webrtc.
OS: Mac OS X → All
Hardware: x86 → All
Summary: mach mochitest-browser no longer produces colored output or lists the failures at the end of test run → mach mochitest-* no longer produces colored output or lists the failures at the end of test run
I'll try to have a patch within an hour. Although, I have a stream of meetings in 45 minutes. Wish me luck...
Assignee: nobody → gps
Status: NEW → ASSIGNED
Attached patch colorize and print summary, v1 (obsolete) — Splinter Review
Slightly hacky solution, but it works!
Attachment #733423 - Flags: review?(Ms2ger)
Comment on attachment 733423 [details] [diff] [review]
colorize and print summary, v1

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

I'm not going to claim I understand the logging setup, but if this works, go for it.

::: testing/mochitest/mach_commands.py
@@ +159,5 @@
> +
> +        # Output processing is a little funky here. The old make targets
> +        # grepped the log output from TEST-UNEXPECTED-* and printed these lines
> +        # after test execution. Ideally the test runner would expose a Python
> +        # API for obtaining test results and we could just format failuress

failuress? My preciouss?

@@ +161,5 @@
> +        # grepped the log output from TEST-UNEXPECTED-* and printed these lines
> +        # after test execution. Ideally the test runner would expose a Python
> +        # API for obtaining test results and we could just format failuress
> +        # appropriately. Unfortunately, it doesn't yet do that. So, we capture
> +        # all output to a buffer then "grep" the buffer after test execution.

We've been talking about that, but file a bug and mention it here?

@@ +165,5 @@
> +        # all output to a buffer then "grep" the buffer after test execution.
> +        test_output = StringIO()
> +        handler = logging.StreamHandler(test_output)
> +        handler.addFilter(UnexpectedFilter())
> +        handler.setFormatter(StructuredHumanFormatter(0, write_times=False))

(I think I'd like times, actually... That's for another day, though.)
Attachment #733423 - Flags: review?(Ms2ger) → review+
https://hg.mozilla.org/integration/mozilla-inbound/rev/e1bddda508fe

Friggin inbound closures.
Target Milestone: --- → mozilla23
Color is back, \o/, but it seems that output is now duplicated, like this:

INFO TEST-START | Shutdown
 1:21.40 INFO TEST-START | Shutdown
Browser Chrome Test Summary
 1:21.40 Browser Chrome Test Summary
	Passed: 14
 1:21.40 	Passed: 14
	Failed: 0
 1:21.40 	Failed: 0
	Todo: 0
 1:21.40 	Todo: 0


Is this to be expected?
And also the failure summary at the end is the only thing that doesn't appear twice, but isn't colored either:

INFO TEST-START | Shutdown
 0:08.20 INFO TEST-START | Shutdown
Browser Chrome Test Summary
 0:08.20 Browser Chrome Test Summary
	Passed: 13
 0:08.20 	Passed: 13
	Failed: 1
 0:08.20 	Failed: 1
	Todo: 0
 0:08.20 	Todo: 0

[...]

TEST-PASS | leakcheck | no leaks detected!
 0:09.17 TEST-PASS | leakcheck | no leaks detected!

INFO | runtests.py | Running tests: end.
 0:09.17 
INFO | runtests.py | Running tests: end.
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/debugger/test/browser_dbg_bfcache.js | tabNavigated event was fired.
https://hg.mozilla.org/mozilla-central/rev/e1bddda508fe
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Only parts of this bug are fixed. I can also see that the final output is not colored and parts of the output are duplicated. Looks like we need a follow-up here.
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Note also:

INFO | automation.py | Application ran for: 0:00:37.921869
 0:41.33 INFO | automation.py | Application ran for: %s
INFO | zombiecheck | Reading PID log: /tmp/tmpeRhS5Wpidlog
 0:41.33 INFO | zombiecheck | Reading PID log: %s
I tried to fix the issues, but didn't manage to. IMO, the cure is worse than the disease here, so I backed it out:

https://hg.mozilla.org/integration/mozilla-inbound/rev/48ae802598f5
This fixes duplicate output and colorizes the summary as requested.

I could probably carry r+ forward. But, I'd at least like a rubber stamp.

This is somewhat hacky. I can't wait for automation.py to disappear and for mach's logging code to be more sane.
Attachment #733423 - Attachment is obsolete: true
Attachment #734795 - Flags: review?(Ms2ger)
Comment on attachment 734795 [details] [diff] [review]
colorize and print summary, v2

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

r=me with the additional fix to ConvertToStructuredFilter you mentioned, and assuming it works.

::: testing/mochitest/mach_commands.py
@@ +97,5 @@
>  
>          automation = Automation()
> +
> +        # Automation installs its own stream handler to stdout. Since we want
> +        # all logging to go through us, we just remove their handler.

Evil. I like it.
Attachment #734795 - Flags: review?(Ms2ger) → review+
https://hg.mozilla.org/mozilla-central/rev/9133673bb8a4
Status: REOPENED → RESOLVED
Closed: 9 years ago9 years ago
Resolution: --- → FIXED
Duplicate of this bug: 797884
Product: Core → Firefox Build System
You need to log in before you can comment on or make changes to this bug.