Closed Bug 1321127 Opened 3 years ago Closed 3 years ago

Something is seriously broken about assertion detection in our infra

Categories

(Testing :: Reftest, defect)

defect
Not set

Tracking

(firefox53 fixed)

RESOLVED FIXED
mozilla53
Tracking Status
firefox53 --- fixed

People

(Reporter: bzbarsky, Assigned: jgraham)

References

Details

Attachments

(2 files)

Today I pushed a patch (part 2 of bug 504622) that removed some assertions from the tree.  We had a test (layout/forms/crashtests/378413-1.xhtml) that was annotated like so:

  asserts(4-10) load 378413-1.xhtml # bug 424225, bug 402850?

because it triggered those assertions.  Removing them should have caused every single debug crashtest run, including the one in the try runs I had done, to go orange, since the test no longer asserted.

However, the _only_ crashtest run that went orange was the "Android 4.3 API15+ debug" tc-R(6) run, with an UNEXPECTED-PASS.  You can see the push results at https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=c024721d9b03fac54eee5730a34f8e7bfbff2129

I have double-checked that on the previous push (<https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=d254eb61360d3c20172eb7aba1154e2779850263&selectedJob=40057296>) the assertions are in fact triggering on the various debug crashtest runs involved.  I have also double-checked that they are not in fact happening with my patch (which is good, because I removed them!).  What I don't understand is why all those runs did not go orange.  Something is seriously broken here.

Wes, do you have any idea whom I should really be ccing on this bug?
Flags: needinfo?(wkocher)
Could this be fallout from structured logging?
Flags: needinfo?(james)
So in the linux64-debug logs I see:

[task 2016-11-29T21:37:31.981439Z] 21:37:31     INFO - REFTEST TEST-UNEXPECTED-PASS | file:///home/worker/workspace/build/tests/reftest/tests/layout/forms/crashtests/378413-1.xhtml | assertion count 0 is less than expected 4 to 10 assertions

So the problem is that in the structured logs this is being logged as random process output, and mozharness doesn't look at that when determining the job status. I think the right way to fix this is to change the reftest harness to log this in some way that mozharness will pay attention to. I will look at fixing that.
Flags: needinfo?(james)
Flags: needinfo?(wkocher)
Blocks: 1034290
See Also: → 1244739
See Also: → 1267020
See Also: 1267020
This is more accurately fallout from 1261199 which started using the structured logs only for determining job status in mozharness and hence treeherder.
Blocks: 1261199
No longer blocks: 1034290
Also https://treeherder.mozilla.org/#/jobs?repo=try&revision=391597c1549ee4208a38fd75d9a056d0aba3fd9a&selectedJob=32161553

I can get the patch reviewed, but I'm not sure what to do about these oranges that have crept in in the meantime.
(In reply to James Graham [:jgraham] from comment #5)
> Also
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=391597c1549ee4208a38fd75d9a056d0aba3fd9a&selectedJob=3
> 2161553
> 
> I can get the patch reviewed, but I'm not sure what to do about these
> oranges that have crept in in the meantime.

We need to get this landed asap, so probably file a bug and add an expected assertion to the failing tests. I'll volunteer.
Comment on attachment 8816103 [details]
Bug 1321127 - Add a assertion_count action to mozlog,

https://reviewboard.mozilla.org/r/96898/#review97124

Thanks for jumping on this. This looks good, we should also get mochitest et al to use this as well.

::: testing/mozbase/mozlog/mozlog/formatters/machformatter.py:283
(Diff revision 1)
>                                                             data["expected"],
>                                                             message))
>          return rv
>  
> +    def assertion_count(self, data):
> +        term = self.terminal if self.terminal is not None else NullTerminal()

This is out of scope for this bug, but I wrote a handy drop-in replacement NullTerminal for blessings.Terminal here:
https://dxr.mozilla.org/mozilla-central/source/python/mozlint/mozlint/formatters/stylish.py#15

It can handle everything a regular Terminal can.

::: testing/mozbase/mozlog/mozlog/formatters/machformatter.py:304
(Diff revision 1)
> +                (color(status if status == expected else ("%s expected %s" %
> +                                                          (status, expected))),

In the event of expected fail, I think this should print EXPECTED-FAIL in the first substitution. Just printing FAIL will look like something went wrong and might even be flagged by treeherder.
Attachment #8816103 - Flags: review?(ahalberstadt) → review+
Comment on attachment 8816103 [details]
Bug 1321127 - Add a assertion_count action to mozlog,

https://reviewboard.mozilla.org/r/96898/#review97124

> In the event of expected fail, I think this should print EXPECTED-FAIL in the first substitution. Just printing FAIL will look like something went wrong and might even be flagged by treeherder.

Treeherder never gets mach formatter input, only tbpl formatter input, so that isn't a concern.

I agree that this looks too much like the tbplformatter style though and it should probably not print anything if the asssertions are in the expected range and something like Assertion count: expected 1-3, got 4" if it fails
Comment on attachment 8816154 [details]
Bug 1321127 - Add temporary annotations for asserts missed by CI,

https://reviewboard.mozilla.org/r/96932/#review97188

::: layout/generic/crashtests/crashtests.list:15
(Diff revision 1)
>  load 264937-1.html
>  load 265867-1.html
>  load 265867-2.html
>  load 286491.html
>  load 289864-1.html
> -load 295292-1.html
> +asserts(1) load 295292-1.html

I'm a little confused as to why this is all-platforms if the assertion detection wasn't broken on Android.  Does this need to be platform-specific?

(Also, please file a bug on it and note the bug number in a comment at the end of the line.)

::: layout/generic/crashtests/crashtests.list:632
(Diff revision 1)
>  load text-overflow-bug713610.html
>  load text-overflow-form-elements.html
>  load text-overflow-iframe.html
>  asserts-if(Android,2-4) asserts-if(!Android,4) load 1225005.html # bug 682647 and bug 448083
>  load 1233191.html
> -skip-if(Android) load 1271765.html
> +skip-if(Android) asserts(3) load 1271765.html

It's not clear why the skip-if(Android) was added -- it was between bug 1271765 comment 124 and bug 1271765 comment 146 -- in the diff in bug 1271765 comment 133 -- but I bet you can remove it.

Also, again, please file bug and comment here.
Attachment #8816154 - Flags: review?(dbaron) → review+
Comment on attachment 8816103 [details]
Bug 1321127 - Add a assertion_count action to mozlog,

https://reviewboard.mozilla.org/r/96898/#review98022

I re-reviewed the 1-3 interdiff, and lgtm.
Pushed by james@hoppipolla.co.uk:
https://hg.mozilla.org/integration/mozilla-inbound/rev/2be3e937ecd9
Add a assertion_count action to mozlog, r=ahal
https://hg.mozilla.org/integration/mozilla-inbound/rev/48ce71d365d8
Add temporary annotations for asserts missed by CI, r=dbaron
https://hg.mozilla.org/mozilla-central/rev/2be3e937ecd9
https://hg.mozilla.org/mozilla-central/rev/48ce71d365d8
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla53
Assignee: nobody → james
You need to log in before you can comment on or make changes to this bug.