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

Status: RESOLVED FIXED

(Firefox Build System :: Mach Core, enhancement)

Description

[Panos Astithas (he/him) [:past] (please ni?)]

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.

Comment 1

[Panos Astithas (he/him) [:past] (please ni?)]

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

Comment 2

[Gregory Szorc [:gps]]

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.

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2]]

This seems to apply to any kind of mochitest. I see it when running mochitest-plain for webrtc.

Comment 4

[Gregory Szorc [:gps]]

I'll try to have a patch within an hour. Although, I have a stream of meetings in 45 minutes. Wish me luck...

Comment 5

[Gregory Szorc [:gps]]

Attachment: colorize and print summary, v1

Slightly hacky solution, but it works!

Comment 6

[:Ms2ger (he/him; ⌚ UTC+1/+2)]

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.)

Comment 7

[Gregory Szorc [:gps]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/e1bddda508fe

Friggin inbound closures.

Comment 8

[Panos Astithas (he/him) [:past] (please ni?)]

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?

Comment 9

[Panos Astithas (he/him) [:past] (please ni?)]

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.

Comment 10

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/e1bddda508fe

Comment 11

[Henrik Skupin [:whimboo][⌚️UTC+2]]

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.

Comment 12

[:Ms2ger (he/him; ⌚ UTC+1/+2)]

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

Comment 13

[:Ms2ger (he/him; ⌚ UTC+1/+2)]

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

Comment 14

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/48ae802598f5

Comment 15

[Gregory Szorc [:gps]]

Attachment: colorize and print summary, v2

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.

Comment 16

[:Ms2ger (he/him; ⌚ UTC+1/+2)]

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.

Comment 17

[Gregory Szorc [:gps]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/9133673bb8a4

Comment 18

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/9133673bb8a4