Mochitests no longer displaying "Assertion count N greater than expected range" log output

RESOLVED FIXED in Firefox 33

Status

defect
RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: baku, Assigned: chmanchester)

Tracking

(Depends on 1 bug, Blocks 1 bug)

unspecified
mozilla34
x86_64
Linux
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox33 fixed, firefox34 fixed)

Details

Attachments

(1 attachment, 1 obsolete attachment)

Reporter

Description

5 years ago
https://tbpl.mozilla.org/?tree=Try&rev=6fd4cd5d3b2e

I was testing a patch and this is the report I see for '2' tests: orange but no summary. In the log is not clear what went wrong.
Mmh, that is certainly surprising. I can see the summary in the logs:

08:08:55     INFO -  66208 INFO TEST-START | Shutdown
08:08:55     INFO -  66209 INFO Passed:  227085
08:08:55  WARNING -  66210 INFO Failed:  1
08:08:55  WARNING -  One or more unittests failed.
08:08:55     INFO -  66211 INFO Todo:    24267

It's even picked up by mozharness apparently (the Failed count has a WARNING level).
Reporter

Updated

5 years ago
Blocks: 1037715
I guess bug 1048559 might help here?
Blocks: 778688
Summary: Summary is empty. → Error summary is empty for failed mochitest-2 job
Posted patch summary_error (obsolete) — Splinter Review
This won't fix the problem where it is impossible to tell what is going wrong, but it should at least bump the failed count to an error (so tbpl should print it) as well as get rid of the "Summary is empty" message (my theory is that the extra line is causing the tbpl regex to break).

Also here's an Ash push with the change:
https://tbpl.mozilla.org/?tree=Ash&rev=e93c20d7930b
Assignee: nobody → ahalberstadt
Status: NEW → ASSIGNED
Attachment #8468206 - Flags: review?(jgriffin)
Reporter

Comment 5

5 years ago
I suspect that the reason why the mochitests-2 fails is this:

09:21:09     INFO -  13145 INFO [Parent 1835] ###!!! ASSERTION: Not a UTF-8 string. This code should only be used for converting from known UTF-8 strings.: 'Error', file /builds/slave/try-lx-d-000000000000000000000/build/xpcom/string/nsUTF8Utils.h, line 427

The actual mochitest (dom/encoding/test/test_submit_euckr.html) passes, but the assertion triggers some kind of orange failure without printing the reason. Could it be?

BTW that issue is know: bug 1032511
Comment on attachment 8468206 [details] [diff] [review]
summary_error

Thank you for taking a look at this :-)
However this patch will regress the SnR of the error summary for all failures, so I'd like to avoid doing this if possible.
Attachment #8468206 - Flags: feedback-
(In reply to Andrew Halberstadt [:ahal] from comment #4)
> This won't fix the problem where it is impossible to tell what is going
> wrong, but it should at least bump the failed count to an error (so tbpl
> should print it) as well as get rid of the "Summary is empty" message (my
> theory is that the extra line is causing the tbpl regex to break).

The extra line in this instance isn't affecting TBPL as far as I can tell?

(In reply to Andrea Marchesini (:baku) from comment #5)
> I suspect that the reason why the mochitests-2 fails is this:
> 
> 09:21:09     INFO -  13145 INFO [Parent 1835] ###!!! ASSERTION: Not a UTF-8
> string. This code should only be used for converting from known UTF-8
> strings.: 'Error', file
> /builds/slave/try-lx-d-000000000000000000000/build/xpcom/string/nsUTF8Utils.
> h, line 427
> 
> The actual mochitest (dom/encoding/test/test_submit_euckr.html) passes, but
> the assertion triggers some kind of orange failure without printing the
> reason. Could it be?

It sounds like structured logging for mochitest regressed the output for our checking of assertion counts:
http://mxr.mozilla.org/mozilla-central/source/testing/mochitest/tests/SimpleTest/TestRunner.js#720

These take the form:
> TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_playback_rate_playpause.html | Assertion count 2 is greater than expected range 0-0 assertions.

For example, there have been no new starred instances of this intermittent bug since around the time of the structured logging landing:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1031590&entireHistory=true&tree=trunk

Also compare some mozilla-beta Linux x64 mochitest-5 pushes that include expected-fails:
https://tbpl.mozilla.org/php/getParsedLog.php?id=45191000&full=1&branch=mozilla-beta
https://tbpl.mozilla.org/php/getParsedLog.php?id=45257737&full=1&branch=mozilla-beta
09:54:03     INFO -  1243 INFO TEST-KNOWN-FAIL | /tests/layout/generic/test/test_bug394239.html | Assertion count 1 within expected range 1-1 assertions.
(and 6 more similar lines in various tests)

With the same job on mozilla-central:
https://tbpl.mozilla.org/php/getParsedLog.php?id=45290916&full=1&branch=mozilla-central
17:49:47     INFO -  5445 INFO TEST-START | /tests/layout/generic/test/test_bug394239.html
17:49:47     INFO -  5446 INFO ++DOMWINDOW == 68 (0x7fed8cc82000) [pid = 1809] [serial = 1360] [outer = 0x7fed903c5c00]
17:49:47     INFO -  5447 INFO [Parent 1809] WARNING: Out-of-flow frame got reflowed before its placeholder: file /builds/slave/m-cen-l64-d-000000000000000000/build/layout/generic/nsPlaceholderFrame.cpp, line 132
17:49:48     INFO -  5448 INFO [Parent 1809] ###!!! ASSERTION: Placeholder relationship should have been torn down already; this might mean we have a stray placeholder in the tree.: '!placeholder || nsLayoutUtils::IsProperAncestorFrame(aDestructRoot, placeholder)', file /builds/slave/m-cen-l64-d-000000000000000000/build/layout/generic/nsFrame.cpp, line 621
<snip stack>
17:50:12     INFO -  5481 INFO [Parent 1809] WARNING: Out-of-flow frame got reflowed before its placeholder: file /builds/slave/m-cen-l64-d-000000000000000000/build/layout/generic/nsPlaceholderFrame.cpp, line 132
17:50:12     INFO -  5482 INFO TEST-OK | /tests/layout/generic/test/test_bug394239.html | took 1105ms

I guess we should also check mochitest-browser-chrome's equivalent:
http://mxr.mozilla.org/mozilla-central/source/testing/mochitest/browser-test.js#383
Blocks: 886570
Summary: Error summary is empty for failed mochitest-2 job → Mochitests no longer displaying "Assertion count N greater than expected range" log output
Duplicate of this bug: 1048080

Comment 9

5 years ago
(In reply to Ed Morley [:edmorley] from comment #7)
> I guess we should also check mochitest-browser-chrome's equivalent:
> http://mxr.mozilla.org/mozilla-central/source/testing/mochitest/browser-test.
> js#383

Per comment #1, I suspect mochitest-chrome is also broken (as that's the test at issue there).
Try run with expectAssertions() disabled; which would have previously cause many "Assertion count N is greater than expected range 0-0 assertions." for each of the known failing tests - but now shows nothing in the summary:
https://tbpl.mozilla.org/?tree=Try&rev=ff9709072aa6
Attachment #8468206 - Flags: review?(jgriffin)

Updated

5 years ago
Blocks: 1014062
The js logger does some validation against logging testEnd for a test not in progress and logs an error instead, but it looks like these are then buffered by python because they are translated into "log" actions.

A short-term fix to get these messages logged is to remove this validation and modify the tbplformatter so it wont throw an exception in these cases. Here it is on try with edmorley's assertion count changes from comment 10:

https://tbpl.mozilla.org/?tree=Try&rev=3b52b31cceb8
Attachment #8468540 - Flags: review?(ahalberstadt)
Assignee

Updated

5 years ago
Assignee: ahalberstadt → cmanchester
Attachment #8468206 - Attachment is obsolete: true
Comment on attachment 8468540 [details] [diff] [review]
Log test_end messages instead of errors to prevent useful messages about assertion counts from being buffered.

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

My understanding is this is a hack to get things working asap. What are the steps to fixing this properly?
Attachment #8468540 - Flags: review?(ahalberstadt) → review+
(In reply to Andrew Halberstadt [:ahal] from comment #12)
> Comment on attachment 8468540 [details] [diff] [review]
> Log test_end messages instead of errors to prevent useful messages about
> assertion counts from being buffered.
> 
> Review of attachment 8468540 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> My understanding is this is a hack to get things working asap. What are the
> steps to fixing this properly?

Right, this fix is problematic because it willfully permits test_end without a corresponding test_start, which we don't want to allow in general. Filed bug 1049827 with some ideas.
https://hg.mozilla.org/mozilla-central/rev/1dfcf17f47d9
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla34
Depends on: 1049827
Duplicate of this bug: 1043433
You need to log in before you can comment on or make changes to this bug.