1038813 - Make the job bisection bleedthrough log output parsable by TBPL & Treeherder

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[Vaibhav (:vaibhav1994)]

There is a need to show the tests causing a failure determined by --bisect-chunk in the summary section of logs. For example: https://tbpl.mozilla.org/php/getParsedLog.php?id=42815619&tree=Try&full=1 , the "TEST-BLEEDTRHOUGH" are at the bottom, we need to show them at the top in summary.

Comment 1

[Vaibhav (:vaibhav1994)]

Attachment: bug1038813.patch

Comment 2

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

Ed's out on PTO for the rest of this week. Ryan, can you look at this patch?

Comment 3

[Ryan VanderMeulen [:RyanVM]]

Per my IRC discussion with Vaibhav, I'd prefer Ed look at this as he's better with regex than I am and more familiar with the pitfalls of messing with this particular code.

Comment 4

[Ed Morley [:emorley]]

Comment on attachment 8456304 [details] [diff] [review]
bug1038813.patch

I don't understand why we need a new prefix?
The number of consumers that will need changing, if we go ahead with this is quite large aiui.

Comment 5

[Vaibhav (:vaibhav1994)]

Hi Ed!
I have worked on bug 1014125. So, in it we find the causes of failure, which we represent by "TEST-BLEEDTHROUGH". For example, in log: https://tbpl.mozilla.org/php/getParsedLog.php?id=42815619&tree=Try&full=1

we have: 
TEST-BLEEDTHROUGH - found failure, testing/mochitest/tests/Harness_sanity/test_harness_pre_bisection2.html . Now, since it is difficult to look for it unless someone already knows about it, :RyanVM suggested that we should put this in the summary section, and hence I have made a patch for it to get recognised for the "summary" section. If the patch is wrong, could you tell me where I should look for adding it to the "summary" section of logs. Thanks.

Comment 6

[Ed Morley [:emorley]]

I mean why "TEST-BLEEDTHROUGH" and not "TEST-UNEXPECTED-FAIL" ? Also, does this fit in with the structured logging (and transition away from the traditional logs) plans?

Comment 7

[Vaibhav (:vaibhav1994)]

Ed, so "TEST-BLEEDTHROUGH" tells us the "cause" of why a test is failing (A test may be failing because of some previous test due to changed prefs or because there is some problem in the test itself). So it is different from "TEST-UNEXPECTED-FAIL". We need to highlight "TEST-BLEEDTHROUGH", so it becomes easier to see, hence I want to put that in summary section of the logs.

And yes, it fits with the structure logging patch for mochitests :)

Comment 8

[Ed Morley [:emorley]]

Sorry I should have made comment 6 clearer, I meant I think it would be better if we output something like:

TEST-UNEXPECTED-FAIL | testing/mochitest/tests/Harness_sanity/test_harness_pre_bisection2.html | Test causes bleadthrough!

This matches log output we already have for various sanity checks that are outside of the test that was run eg:
http://mxr.mozilla.org/mozilla-central/source/build/mobile/remoteautomation.py#94

Otherwise every consumer of the logs needs to handle a new line prefix for each new harness sanity checking feature.

Comment 9

[Ed Morley [:emorley]]

(In reply to Ed Morley [:edmorley] from comment #8)
> This matches log output we already have for various sanity checks that are
> outside of the test that was run eg:
> http://mxr.mozilla.org/mozilla-central/source/build/mobile/remoteautomation.
> py#94

And also:
http://mxr.mozilla.org/mozilla-central/search?string=TEST-UNEXPECTED-FAIL&case=1&find=\.py&tree=mozilla-central

Comment 10

[Vaibhav (:vaibhav1994)]

Ed Morley, ah, I mis-interpreted before :)
Based on your suggestion, I did a try push: https://tbpl.mozilla.org/?tree=Try&rev=22b62c145cfa , and we are getting it inside the summary section. One interesting thing I noticed is that the job turns orange even though in the last run the number of 'failed' tests is 0 and the return code is also 0 : https://tbpl.mozilla.org/php/getParsedLog.php?id=44334088&tree=Try&full=1#error22

Afaik, we decide the color of the job based on return code, which it seems is not following here. Do you know the reason for this (btw, in this case, this is advantageous as it also solves bug 1036524)?

Another concern, is that the "test-bleedthrough" part is at the bottom of a long list in the summary, and I am wondering whether it makes sense to keep it there.

Comment 11

[Ed Morley [:emorley]]

(In reply to Vaibhav from comment #10)
> Afaik, we decide the color of the job based on return code, which it seems
> is not following here. Do you know the reason for this (btw, in this case,
> this is advantageous as it also solves bug 1036524)?

Buildbot/mozharness uses both the return code and also log parsing to determine success/failure (it's a bit of a mess tbh), but yeah it's helpful here.

> Another concern, is that the "test-bleedthrough" part is at the bottom of a
> long list in the summary, and I am wondering whether it makes sense to keep
> it there.

I don't mind too much; I'm happy to defer on this part to Joel since he reviewed bug 1014125.

Comment 12

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

When we run this with test-bleedthrough, we get a bunch of test-unexpected-fail messages, but the job turns green.  So why is it turning orange now?  

as for the bleedthrough info at the bottom, that has me concerned a bit.  we will show a higher volume of errors due to rerunning the test, this means that we could break the 20 errors shown by default- the chance of clicking to the last error is very small.  For developers fix the first warning/error, and that should fix many future ones.  In many ways that holds true to our tests.

I really would like to see this more front and center, even if it is a couple of spots down in the list.  Also the format isn't a 100% match to that of the existing messages, that could mess up some other random forms of log parsing.  

Ed, As a sheriff, do you always look at the errors at the bottom of the list?

Comment 13

[Vaibhav (:vaibhav1994)]

Ed, :jmaher is talking about the try run: https://tbpl.mozilla.org/?tree=Try&rev=0a6914b91de6 , if you see the logs: https://tbpl.mozilla.org/php/getParsedLog.php?id=43446447&tree=Try&full=1 , we are having a number of test-failures and we have a "test-bleedthrough" at the end, but the job is green.

Comment 14

[Ed Morley [:emorley]]

(In reply to Joel Maher (:jmaher) from comment #12)
> When we run this with test-bleedthrough, we get a bunch of
> test-unexpected-fail messages, but the job turns green.  So why is it
> turning orange now?  

The earlier TEST-UNEXPECTED-FAILs have line number prefixes which the buildbot/mozharness regex might not like, or they occur in part of the log that isn't being parsed; not really sure. It's all a bit of a mess tbh, the sooner we stop parser unstructured logs as the means to determine job result, the better :-)

> as for the bleedthrough info at the bottom, that has me concerned a bit.  we
> will show a higher volume of errors due to rerunning the test, this means
> that we could break the 20 errors shown by default- the chance of clicking
> to the last error is very small.  For developers fix the first
> warning/error, and that should fix many future ones.  In many ways that
> holds true to our tests.

If you can show the failure higher up in the log, I certainly wouldn't complain, however I guess the real way to fix the problem is to have a "this test failed N conditions, skipping the rest", the same as we have to 4 or more mochitest timeouts in a row.

> I really would like to see this more front and center, even if it is a
> couple of spots down in the list.  Also the format isn't a 100% match to
> that of the existing messages, that could mess up some other random forms of
> log parsing.  

The format is fine as far as I can see

> Ed, As a sheriff, do you always look at the errors at the bottom of the list?

The brief log view shows upto the first 100 failures (in the list of links at the top), and in most cases one will open that to see the root cause, so yeah this shouldn't go unnoticed.

Comment 15

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

maybe once we start the bisection loop (as we have already discovered a failure), we can output:
TEST-UNEXPECTED-FAIL | Bisection | Please ignore repeats and look for 'TEST-BLEEDTHROUGH' at the end of the failure list

That would show up much earlier in the failure list and would require less hacking in general :)

In general we are dealing with a bunch of failures (could be repeat failures) and a summary at the end (with a single status message).  

Why is this important:
* we are investigating a random orange and have pushed to try (developer will be looking for bleedthrough)
* we make intermittent mode an option for try server where we turn it green if it really is an intermittent.  In this case a developer won't be looking for bleedthrough, but quite possible caring more about orange on their try push.

So I think the two use cases above are not concerning at all.  Who knows what other use cases we will uncover, so thinking about this ahead of time is a good idea.

With that said, any other thoughts, concerns?

Comment 16

[Vaibhav (:vaibhav1994)]

Attachment: tbplsummary.patch

I have tested what :jmaher has suggested and I think it is a good option. Here is the try push: https://tbpl.mozilla.org/?tree=Try&rev=9e0139a1371d
and the log: https://tbpl.mozilla.org/php/getParsedLog.php?id=44425700&tree=Try&full=1

Comment 17

[Ed Morley [:emorley]]

I'm struggling to understand exactly what all the cases are that bug 1036372 is intended to solve, since bug 1036372 comment 0 doesn't really say much.

Depending on the expected usage of this, the proposal in comment 15 might be fine, though I think we should still use "TEST-UNEXPECTED-FAIL | testname | <some message>" instead of TEST-BLEEDTHROUGH.

Comment 18

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

Comment on attachment 8460862 [details] [diff] [review]
tbplsummary.patch

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

ed, would this message be ideal at the end:
TEST-UNEXPECTED-FAIL | <testname> | Bleedthrough detected, this test is the root cause for many of the above failures


r=me with the one issue addressed and assuming we have agreement from all parties in this bug :)

::: testing/mochitest/runtests.py
@@ +1547,5 @@
>        if options.bisectChunk:
>          testsToRun = bisect.pre_test(options, testsToRun, status)
> +        # To inform that we are in the process of bisection, and to look for bleedthrough
> +        if options.bisectChunk is not "default" and not bisection_log:
> +            log.info("TEST-UNEXPECTED-FAIL | Bisection | Please ignore repeats and look for 'TEST-BLEEDTHROUGH' (if any) at the end of the failure list")

we don't have test-bleedthrough in the log, can this be 'Bleedthough' instead?

Comment 19

[Vaibhav (:vaibhav1994)]

Attachment: tbplsummary.patch

Joel, thanks for the review. Ed, added you as the reviewer, let me know if the approach is correct.

btw, like in https://tbpl.mozilla.org/php/getParsedLog.php?id=44425700&tree=Try&full=1 , the summary section will have this:

(somewhere in the middle)
TEST-UNEXPECTED-FAIL | Bisection | Please ignore repeats and look for 'Bleedthrough' (if any) at the end of the failure list

(at the end of summary)
TEST-UNEXPECTED-FAIL | testing/mochitest/tests/Harness_sanity/test_harness_bisection.html | Bleedthrough detected, this test is the root cause for many of the above failures

I think this now follows the approach suggested by you :)

Comment 20

[Vaibhav (:vaibhav1994)]

Attachment: tbplsummary.patch

Fixed a nit in the previous patch.

Comment 21

[Ed Morley [:emorley]]

Comment on attachment 8461003 [details] [diff] [review]
tbplsummary.patch

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

lgtm, thank you :-)

Comment 22

[Carsten Book [:Tomcat]]

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

Comment 23

[Carsten Book [:Tomcat]]

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