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

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[Andrea Marchesini [:baku]]

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.

Comment 1

[:Gijs (he/him)]

Same on e.g. https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=78d5dd9a98f4 :-(

(different patch)

Comment 2

[Ahmed Kachkach [:akachkach]]

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

Comment 3

[Martijn Wargers (dead)]

I guess bug 1048559 might help here?

Comment 4

[Andrew Halberstadt [:ahal]]

Attachment: summary_error

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

Comment 5

[Andrea Marchesini [:baku]]

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 6

[Ed Morley [:emorley]]

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.

Comment 7

[Ed Morley [:emorley]]

(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

Comment 9

[:Gijs (he/him)]

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

Comment 10

[Ed Morley [:emorley]]

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

Comment 11

[Chris Manchester (limited bugmail, email directly)]

Attachment: Log test_end messages instead of errors to prevent useful messages about assertion counts from being buffered.

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

Comment 12

[Andrew Halberstadt [:ahal]]

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?

Comment 13

[Chris Manchester (limited bugmail, email directly)]

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

Comment 14

[Chris Manchester (limited bugmail, email directly)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/1dfcf17f47d9

Comment 15

[Nigel Babu [:nigelb]]

https://hg.mozilla.org/mozilla-central/rev/1dfcf17f47d9

Comment 17

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/ea403b4aa951