Since the new structure logging got added any test failures is no longer reported at the end of a test run. No matter if you run a whole directory of tests or a single one, during the test execution the failure is properly logged, but when Firefox quits and you get your command line back the last thing I see is a TEST-PASS from leakcheck, but no mentioning of the encountered test failure like we used to have. This is obviously seriously annoying as you have to watch the test execution your self, or have to search through the test output to verify if any failure occurred.

Could you give me an example of "test failures reported at the end of a test"? If you're referring to the summary that shows the number of passed/failed/todo, it's still being printed: ... 46 INFO TEST-START | Shutdown 47 INFO Passed: 5 48 INFO Failed: 0 49 INFO Todo: 0 ...

So here a screenshot of a single test getting executed and producing a failure

I ran this command: './mach mochitest-plain dom/media/tests/mochitest/test_getUserMedia_basicScreenshare.html' to make the screenshot and this is the end of the test run. I'm expecting a line at the very end which tells me the details of the test failure encountered, but there is nothing like that. 116 INFO [85650] WARNING: Leaking the RDF Service.: file /Users/nohlmeier/src/mozilla-central/rdf/build/nsRDFModule.cpp, line 165 117 INFO [85650] WARNING: '!compMgr', file /Users/nohlmeier/src/mozilla-central/xpcom/glue/nsComponentManagerUtils.cpp, line 63 118 INFO [85650] WARNING: NS_ENSURE_TRUE(mTextInputHandler) failed: file /Users/nohlmeier/src/mozilla-central/widget/cocoa/nsChildView.mm, line 5525 119 INFO [85650] WARNING: OOPDeinit() without successful OOPInit(): file /Users/nohlmeier/src/mozilla-central/toolkit/crashreporter/nsExceptionHandler.cpp, line 2630 120 INFO nsStringStats 121 INFO => mAllocCount: 52041 122 INFO => mReallocCount: 6324 123 INFO => mFreeCount: 52041 124 INFO => mShareCount: 81191 125 INFO => mAdoptCount: 3952 126 INFO => mAdoptFreeCount: 3952 127 INFO => Process ID: 85650, Thread ID: 140735304631056 TEST-INFO | Main app process: exit 0 128 INFO runtests.py | Application ran for: 0:00:30.004049 129 INFO zombiecheck | Reading PID log: /var/folders/3g/bm146dzn2zs42vgkw80svyx80000gn/T/tmprmTAH8pidlog 130 INFO Stopping web server 131 INFO Stopping web socket server 132 INFO Stopping ssltunnel 0:34.21 0:34.21 == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, default process 85650 0:34.21 0:34.21 |<----------------Class--------------->|<-----Bytes------>|<----------------Objects---------------->|<--------------References-------------->| 0:34.21 Per-Inst Leaked Total Rem Mean StdDev Total Rem Mean StdDev 0:34.21 0 TOTAL 27 0 1220753 0 ( 6135.53 +/- 10180.24) 1436863 0 ( 4432.24 +/- 8526.57) 0:34.21 0:34.21 nsTraceRefcnt::DumpStatistics: 1099 entries 0:34.21 0:34.21 TEST-PASS | leakcheck | no leaks detected! 133 INFO runtests.py | Running tests: end. 134 INFO SUITE-END | took 30s

This is the out put from './mach mochitest-plain dom/media/tests/mochitest/test_getUserMedia_basicWindowshare.html' with no test failure. No difference at all to me?!? 116 INFO [85730] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /Users/nohlmeier/src/mozilla-central/xpcom/base/nsCycleCollector.cpp, line 3523 117 INFO [85730] WARNING: Leaking the RDF Service.: file /Users/nohlmeier/src/mozilla-central/rdf/build/nsRDFModule.cpp, line 165 118 INFO [85730] WARNING: '!compMgr', file /Users/nohlmeier/src/mozilla-central/xpcom/glue/nsComponentManagerUtils.cpp, line 63 119 INFO [85730] WARNING: NS_ENSURE_TRUE(mTextInputHandler) failed: file /Users/nohlmeier/src/mozilla-central/widget/cocoa/nsChildView.mm, line 5525 120 INFO [85730] WARNING: OOPDeinit() without successful OOPInit(): file /Users/nohlmeier/src/mozilla-central/toolkit/crashreporter/nsExceptionHandler.cpp, line 2630 121 INFO nsStringStats 122 INFO => mAllocCount: 48585 123 INFO => mReallocCount: 5899 124 INFO => mFreeCount: 48585 125 INFO => mShareCount: 73023 126 INFO => mAdoptCount: 3543 127 INFO => mAdoptFreeCount: 3543 128 INFO => Process ID: 85730, Thread ID: 140735304631056 TEST-INFO | Main app process: exit 0 129 INFO runtests.py | Application ran for: 0:00:17.018978 130 INFO zombiecheck | Reading PID log: /var/folders/3g/bm146dzn2zs42vgkw80svyx80000gn/T/tmpKwDBCzpidlog 131 INFO Stopping web server 132 INFO Stopping web socket server 133 INFO Stopping ssltunnel 0:21.20 0:21.20 == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, default process 85730 0:21.20 0:21.20 |<----------------Class--------------->|<-----Bytes------>|<----------------Objects---------------->|<--------------References-------------->| 0:21.20 Per-Inst Leaked Total Rem Mean StdDev Total Rem Mean StdDev 0:21.20 0 TOTAL 28 0 1045812 0 ( 5762.67 +/- 9680.72) 1289732 0 ( 4364.37 +/- 8307.95) 0:21.21 0:21.21 nsTraceRefcnt::DumpStatistics: 1109 entries 0:21.21 0:21.21 TEST-PASS | leakcheck | no leaks detected! 134 INFO runtests.py | Running tests: end. 135 INFO SUITE-END | took 17s

And in case of the test failure: the actual test failure got recorded in the logs like this: 65 INFO Call getUserMedia for {"video":{"mozMediaSource":"screen","mediaSource":"screen"},"fake":false} | undefined 66 INFO unknown test url | TEST-UNEXPECTED-FAIL | but it does not get repeated at the end, how it used to be.

Screenshot from executing a whole directory of tests like this: './mach mochitest-plain dom/media/tests/mochitest/'

This is the end of running the directory of test: 20685 INFO [85865] WARNING: Leaking the RDF Service.: file /Users/nohlmeier/src/mozilla-central/rdf/build/nsRDFModule.cpp, line 165 20686 INFO [85865] WARNING: '!compMgr', file /Users/nohlmeier/src/mozilla-central/xpcom/glue/nsComponentManagerUtils.cpp, line 63 20687 INFO [85865] WARNING: OOPDeinit() without successful OOPInit(): file /Users/nohlmeier/src/mozilla-central/toolkit/crashreporter/nsExceptionHandler.cpp, line 2630 20688 INFO nsStringStats 20689 INFO => mAllocCount: 128476 20690 INFO => mReallocCount: 10464 20691 INFO => mFreeCount: 128476 20692 INFO => mShareCount: 292617 20693 INFO => mAdoptCount: 11699 20694 INFO => mAdoptFreeCount: 11699 20695 INFO => Process ID: 85865, Thread ID: 140735304631056 TEST-INFO | Main app process: exit 0 20696 INFO runtests.py | Application ran for: 0:02:08.268619 20697 INFO zombiecheck | Reading PID log: /var/folders/3g/bm146dzn2zs42vgkw80svyx80000gn/T/tmpakssAnpidlog 20698 INFO Stopping web server 20699 INFO Stopping web socket server 20700 INFO Stopping ssltunnel 2:12.50 2:12.50 == BloatView: ALL (cumulative) LEAK AND BLOAT STATISTICS, default process 85865 2:12.50 2:12.50 |<----------------Class--------------->|<-----Bytes------>|<----------------Objects---------------->|<--------------References-------------->| 2:12.50 Per-Inst Leaked Total Rem Mean StdDev Total Rem Mean StdDev 2:12.50 0 TOTAL 18 0 13389481 0 (10924.28 +/- 15809.32) 7394916 0 ( 3734.71 +/- 8093.97) 2:12.50 2:12.50 nsTraceRefcnt::DumpStatistics: 1206 entries 2:12.50 2:12.50 TEST-PASS | leakcheck | no leaks detected! 20701 INFO runtests.py | Running tests: end. 20702 INFO SUITE-END | took 128s

Approximately 700 lines above that I can find the test summary: 19970 INFO ++DOMWINDOW == 63 (0x140ce7c00) [pid = 85865] [serial = 127] [outer = 0x13627f000] 19971 INFO TEST-START | Shutdown 19972 INFO Passed: 2415 19973 INFO Failed: 1 19974 INFO Todo: 0 19975 INFO Slowest: 8070ms - /tests/dom/media/tests/mochitest/test_dataChannel_basicAudio.html 19976 INFO SimpleTest FINISHED 19977 INFO TEST-INFO | Ran 1 Loops 19978 INFO SimpleTest FINISHED 19979 INFO ++DOMWINDOW == 64 (0x140ce8000) [pid = 85865] [serial = 128] [outer = 0x13627f000] Which is not helpful if I have to scroll up that much. But the main point about this bug is that I used to get a list of all TEST-UNEXPECTED-FAIL events as the very last output before mochitest finished and returned my command line. That list is missing!

So here is the output from a failed test case on beta: 0:09.38 20 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_getUserMedia_basicAudio.html | Current src should still be an empty string 0:09.42 21 INFO TEST-INFO | MEMORY STAT vsize after test: 3134394368 0:09.42 22 INFO TEST-INFO | MEMORY STAT vsizeMaxContiguous not supported in this build configuration. 0:09.42 23 INFO TEST-INFO | MEMORY STAT residentFast after test: 186232832 0:09.42 24 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 72195072 0:09.42 25 INFO TEST-END | /tests/dom/media/tests/mochitest/test_getUserMedia_basicAudio.html | finished in 1193ms 0:09.43 26 INFO TEST-START | Shutdown 0:09.43 27 INFO Passed: 17 0:09.43 28 INFO Failed: 1 0:09.43 29 INFO Todo: 0 0:09.43 30 INFO Slowest: 1193ms - /tests/dom/media/tests/mochitest/test_getUserMedia_basicAudio.html 0:09.43 31 INFO SimpleTest FINISHED 0:09.43 32 INFO TEST-INFO | Ran 1 Loops 0:09.43 33 INFO SimpleTest FINISHED TEST-INFO | Main app process: exit 0 0:09.76 INFO | runtests.py | Application ran for: 0:00:03.324619 0:09.76 INFO | zombiecheck | Reading PID log: /var/folders/3g/bm146dzn2zs42vgkw80svyx80000gn/T/tmprIklOtpidlog 0:09.76 Stopping web server 0:09.78 Stopping web socket server 0:09.78 Stopping ssltunnel 0:09.78 WARNING | leakcheck | refcount logging is off, so leaks can't be detected! 0:09.78 runtests.py | Running tests: end. 0:09.79 3 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_getUserMedia_basicAudio.html | foobar Notice the very last line here. That is what is missing now after mochitest runs.

And in case of running a whole directory of tests is used to look like this: ... 0:19.78 2923 INFO TEST-END | /tests/dom/media/tests/mochitest/test_zmedia_cleanup.html | finished in 18ms 0:19.79 2924 INFO TEST-START | /tests/dom/media/tests/mochitest/test_zmedia_cleanup.html 0:19.80 2925 INFO TEST-PASS | /tests/dom/media/tests/mochitest/test_zmedia_cleanup.html | no need to cleanup network interface 0:19.80 2926 INFO TEST-INFO | MEMORY STAT vsize after test: 3322109952 0:19.80 2927 INFO TEST-INFO | MEMORY STAT residentFast after test: 275111936 0:19.80 2928 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 73282504 0:19.80 2929 INFO TEST-END | /tests/dom/media/tests/mochitest/test_zmedia_cleanup.html | finished in 17ms 0:19.81 2930 INFO TEST-START | Shutdown 0:19.81 2931 INFO Passed: 1484 0:19.81 2932 INFO Failed: 1 0:19.81 2933 INFO Todo: 0 0:19.81 2934 INFO Slowest: 1707ms - /tests/dom/media/tests/mochitest/test_dataChannel_basicAudio.html 0:19.81 2935 INFO SimpleTest FINISHED 0:19.81 2936 INFO TEST-INFO | Ran 1 Loops 0:19.82 2937 INFO SimpleTest FINISHED 0:19.90 2111243024[1003322d0]: Shutting down SCTP ... ... 0:19.99 539971584[120bb6420]: [SIPStack task|cpr] cpr_darwin_stdio.c:152: cprDestroyThread: Destroying Thread 2 0:19.99 2111243024[1003322d0]: [main|CallControlManager] CallControlManagerImpl.cpp:48: ~CallControlManagerImpl() 0:19.99 2111243024[1003322d0]: [main|CallControlManager] CallControlManagerImpl.cpp:54: destroy() 0:19.99 2111243024[1003322d0]: [main|CallControlManager] CallControlManagerImpl.cpp:227: disconnect() TEST-INFO | Main app process: exit 0 0:20.17 INFO | runtests.py | Application ran for: 0:00:16.789919 0:20.17 INFO | zombiecheck | Reading PID log: /var/folders/3g/bm146dzn2zs42vgkw80svyx80000gn/T/tmpvvHpsjpidlog 0:20.17 Stopping web server 0:20.19 Stopping web socket server 0:20.19 Stopping ssltunnel 0:20.19 WARNING | leakcheck | refcount logging is off, so leaks can't be detected! 0:20.19 runtests.py | Running tests: end. 0:20.20 528 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_getUserMedia_basicAudio.html | foobar Again the test summary is hundreds of lines above the actual end. I don't care. But the very last line is super important to identify what went wrong during a test run!

So, this was caused by the fact that we no longer use the logging module: a handler was attached to mach's "structured logger" and parsed each line for "TEST-UNEXPECTED-" and printed those at the end of the tests' execution. With this patch, we'll now output something like this: ... 54 INFO runtests.py | Running tests: end. 55 INFO SUITE-END | took 3s 56 INFO The following tests failed: 57 INFO TEST-UNEXPECTED-FAIL | /tests/dom/ipc/tests/test_CrashService_crash.html | This first test failed TEST-INFO | expected PASS 58 INFO TEST-UNEXPECTED-FAIL | /tests/dom/ipc/tests/test_CrashService_crash.html | This second one did too TEST-INFO | expected PASS ... Try push: https://tbpl.mozilla.org/?tree=Try&rev=3c0158272793

Is this something that people want in other testsuites? It seems likely to be. Assuming it is I'm not super happy about doing it in mochitest-specific code. We should be able to add it to the mach formatter or create another formatter that just prints a summary, for example.

Comment on attachment 8460392 [details] [diff] [review] 0001-Bug-1041944-Printing-mochitest-failures-at-the-end-o.patch Review of attachment 8460392 [details] [diff] [review]: ----------------------------------------------------------------- Lgtm. ::: testing/mochitest/runtests.py @@ +157,5 @@ > > # test_status messages buffering > if is_error: > if self.buffered_messages: > number_messages = min(self.BUFFERING_THRESHOLD, len(self.buffered_messages)) I think you can also move this if statement up above under the other 'if is_error' statement as well. Though the context cuts off here, so I'm not really sure.

Thanks for the review! We pass the error message even if there are no buffered messages, that's why I didn't include that under the same if statement.

jgraham: Sorry, didn't see your comment. So this was originally only for desktop_mochitest, with mach. (and affects the code returned by mach) We can probably add this to the mach formatter, but currently we're using the TBPL formatter by default (even when launching the tests through mach) and adding this to the TBPL formatter would duplicate error messages on TBPL.

By the way, the plan is to switch to the mach formatter by default for local tests.