Closed
Bug 1041944
Opened 10 years ago
Closed 10 years ago
Structured logging no longer reports test failures at the end
Categories
(Testing :: Mochitest, defect, P1)
Testing
Mochitest
Tracking
(firefox33 fixed, firefox34 fixed)
RESOLVED
FIXED
mozilla34
People
(Reporter: drno, Assigned: akachkach)
References
Details
Attachments
(3 files)
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.
Assignee | ||
Comment 1•10 years ago
|
||
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
...
Reporter | ||
Comment 2•10 years ago
|
||
So here a screenshot of a single test getting executed and producing a failure
Reporter | ||
Comment 3•10 years ago
|
||
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
Reporter | ||
Comment 4•10 years ago
|
||
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
Reporter | ||
Comment 5•10 years ago
|
||
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.
Reporter | ||
Comment 6•10 years ago
|
||
Screenshot from executing a whole directory of tests like this: './mach mochitest-plain dom/media/tests/mochitest/'
Reporter | ||
Comment 7•10 years ago
|
||
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
Reporter | ||
Comment 8•10 years ago
|
||
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!
Reporter | ||
Comment 9•10 years ago
|
||
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.
Reporter | ||
Comment 10•10 years ago
|
||
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!
Assignee | ||
Comment 11•10 years ago
|
||
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
Attachment #8460392 -
Flags: review?(ahalberstadt)
Comment 12•10 years ago
|
||
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 13•10 years ago
|
||
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.
Attachment #8460392 -
Flags: review?(ahalberstadt) → review+
Assignee | ||
Comment 14•10 years ago
|
||
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.
Assignee | ||
Comment 15•10 years ago
|
||
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.
Assignee | ||
Comment 16•10 years ago
|
||
By the way, the plan is to switch to the mach formatter by default for local tests.
Keywords: checkin-needed
Comment 17•10 years ago
|
||
Keywords: checkin-needed
Comment 18•10 years ago
|
||
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla34
Comment 19•10 years ago
|
||
status-firefox33:
--- → fixed
status-firefox34:
--- → fixed
You need to log in
before you can comment on or make changes to this bug.
Description
•