1098700 - Mochitests that are annotated fails-if don't output a useful error if they unexpectedly pass

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[Ryan VanderMeulen [:RyanVM]]

Found this out by accident tonight when adding another condition to what I thought was a skip-if condition. Turns out it was a fails-if, which rightfully turned the run orange (since the test was now unexpectedly passing on that platform).

However, instead of outputting TEST-UNEXPECTED-PASS as would be expected in that situation, it instead showed TEST-OK and just turned the run orange instead. Thankfully it was my push that did it and I was able to track down pretty quickly what had happened. I could forsee this being a nightmare for a someone to track down otherwise.

Example log:
http://ftp.mozilla.org/pub/mozilla.org/b2g/tinderbox-builds/mozilla-inbound-linux64-mulet/1415914808/mozilla-inbound_ubuntu64_vm-mulet_test-mochitest-1-bm53-tests1-linux64-build132.txt.gz

test_hidden_alpha.html was the test in question.

Comment 1

[Chris Manchester (limited bugmail, email directly)]

I don't know how these tests are run, but looks like failureInfo around http://hg.mozilla.org/mozilla-central/file/7f0d92595432/testing/mochitest/tests/SimpleTest/SimpleTest.js#l847 should be:

{status:"PASS", expected:"FAIL", message:"TEST-UNEXPECTED-PASS"}

Comment 2

[Chris Manchester (limited bugmail, email directly)]

These would be green according to the structured log.

Comment 3

[Kaustabh Datta Choudhury]

Attachment: unexpected_pass.patch

Comment 4

[Joel Maher ( :jmaher ) (UTC -8)]

Comment on attachment 8541124 [details] [diff] [review]
unexpected_pass.patch

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

let me push to try, if all goes well we can land this!  Thanks!

Comment 5

[Joel Maher ( :jmaher ) (UTC -8)]

https://tbpl.mozilla.org/?tree=Try&rev=47cb2191ff87

Comment 6

[Joel Maher ( :jmaher ) (UTC -8)]

try is green

Comment 7

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/9e126e97e347

Comment 8

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/9e126e97e347

Comment 9

[Joel Maher ( :jmaher ) (UTC -8)]

oh fun, looking at this I realized that the jobs are green even though mochitest returns a code of 1 because we didn't update the unittests and now print TEST-UNEXPECTED-PASS.

So this is good- we have a logical error printed and a valid return code from the entire harness, but still we fail to turn the job orange.

Ryan, what are your thoughts on this?  Obviously we need to fix the unittests, but for the error message and turning the job orange.  For an example of the error look on win7 m-oth

Comment 10

[Ryan VanderMeulen [:RyanVM]]

I think we should backout for now. Can you please do the honors?

Comment 11

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/8850aa0f5332

Comment 12

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/integration/fx-team/rev/8850aa0f5332

Comment 13

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/integration/b2g-inbound/rev/8850aa0f5332

Comment 14

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/8850aa0f5332

Comment 16

[Joel Maher ( :jmaher ) (UTC -8)]

I am really confused by this bug, Kaustabh and I have been looking at it.  There exists some failure condition where we annotate fail-if and we don't print test-unexpected-* while returning non zero.  

Replicating this is not straightforward.  In fact, the unittests cover expected failures, and switching something to use or not use fail-if output the proper behaviour.

Maybe there is something we are overlooking, please chime in with some specifics about what we should be doing here, or otherwise lets close this bug out.

Comment 17

[Ryan VanderMeulen [:RyanVM]]

I'm not sure how to better clarify comment 0. The status quo at the moment is that the test unexpectedly passes, turns the run orange, and provides *zero* usable output to indicate what is wrong. That's not acceptable.

I'm not sure what the way forward is. Maybe Chris or someone have an idea.

Comment 18

[Joel Maher ( :jmaher ) (UTC -8)]

well comment 0 makes no sense to me.  if I set up a test to unexpectedly pass, it reports 'test-unexpected-pass' and returns a non zero, something like this:
INFO TEST-FAIL | /path/test.html | fail-if condition in manifest - We expected at least one failure

If that is what we currently have, should it be changed?  Is there a random corner case that doesn't yield this?

Comment 19

[Chris Manchester (limited bugmail, email directly)]

I can reproduce the issue by changing the assertion in test_sanity_manifest.html from "ok(false, "We expect this to fail");" to "ok(true, "This test unexpectedly passes")" and running |./mach mochitest-plain testing/mochitest/tests/Harness_sanity/ --quiet| (the "--quiet" keeps the relevant info out of logs running in our infrastructure). The output for this test in the run is:

35 INFO TEST-START | testing/mochitest/tests/Harness_sanity/test_sanity_manifest.html
-*-*- UserCustomizations (parent): document created: http://mochi.test:8888/tests/testing/mochitest/tests/Harness_sanity/test_sanity_manifest.html
-*-*- UserCustomizations (parent): _injectInWindow
-*-*- UserCustomizations (parent): principal status: 0
36 INFO TEST-OK | testing/mochitest/tests/Harness_sanity/test_sanity_manifest.html | took 21ms

I believe comment 1 is the right fix. With it the test outputs:

35 INFO TEST-START | testing/mochitest/tests/Harness_sanity/test_sanity_manifest.html
-*-*- UserCustomizations (parent): document created: http://mochi.test:8888/tests/testing/mochitest/tests/Harness_sanity/test_sanity_manifest.html
-*-*- UserCustomizations (parent): _injectInWindow
-*-*- UserCustomizations (parent): principal status: 0
36 INFO TEST-PASS | testing/mochitest/tests/Harness_sanity/test_sanity_manifest.html | This test unexpectedly passes 
37 INFO TEST-UNEXPECTED-PASS | testing/mochitest/tests/Harness_sanity/test_sanity_manifest.html | fail-if condition in manifest - We expected at least one failure
TEST-INFO | expected FAIL
38 INFO MEMORY STAT vsize after test: 842244096
39 INFO MEMORY STAT residentFast after test: 147369984
40 INFO MEMORY STAT heapAllocated after test: 58838120
41 INFO TEST-OK | testing/mochitest/tests/Harness_sanity/test_sanity_manifest.html | took 26ms

Comment 20

[Phil Ringnalda (:philor)]

https://treeherder.mozilla.org/ui/#/jobs?repo=mozilla-inbound&revision=9e126e97e347 (when this landed), b2g opt mochitest-3 and debug mochitest-6. Crapload of webgl things are annotated fail-if b2g, they apparently don't fail, so with this landed they at least came slightly closer to showing the real state, expected to fail but not failing anything. No idea whether there are others, someone would have to look at every single suite run by the mochitest harness, on every OS, opt and debug, and thus across several pushes since that didn't get 10.8 debug and had a bunch of Win jobs coalesced away.

Comment 21

[Kaustabh Datta Choudhury]

Attachment: bug.patch

Comment 22

[Joel Maher ( :jmaher ) (UTC -8)]

Comment on attachment 8546070 [details] [diff] [review]
bug.patch

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

Overall this is exactly what we need.  We do need to look at browser-test.js as browser-chrome tests are reporting test-unexpected-fail when they should be reporting test-unexpected-pass.

Comment 23

[Kaustabh Datta Choudhury]

Attachment: fail_if.patch

Comment 24

[Joel Maher ( :jmaher ) (UTC -8)]

Comment on attachment 8546835 [details] [diff] [review]
fail_if.patch

looks good to me!

Comment 25

[Joel Maher ( :jmaher ) (UTC -8)]

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

Comment 26

[Ryan VanderMeulen [:RyanVM]]

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