443090 - Unify logging unittest failures during a build

Status: RESOLVED FIXED

(Release Engineering :: General, defect)

Description

[Mike Schroepfer]

We already post-process to get the failed/skiped/run count but it is non-trivial to answer basic questions like does test x fail only on windows because we do not have the testname in ever test failure and we don't log in any centralized fashion. 

Lukas has been playing with splunk to get us better visibility into the unit test failures to separate out system from test issues.   

I'm likely missing some really dumb stuff - so forgive me - but it seems with a bit of work we can make the process of finding unit test failures much easier.  If we make sure every test failure logs:

1) Clear indication of failure (looks like even this varies from UNEXPECTED to FAILURE, etc)

2) Test Name

3) Any additional information

eg:

TEST FAILURE | TEST NAME | ADDITIONAL INFORMATION

We should be able to quickly modify the test suites to do this:

1) Reftests we can do this automatically in the framework (reftest failures already report the file

2) For XPCShell we can walk the stackframe (http://mxr.mozilla.org/mozilla-central/source/tools/test-harness/xpcshell-simple/head.js#95) to find the name of the file in which the test failed

3) MochiTests we should be able to get the framework to do it as well

4) C++ tests we'll just have to have some style recommendations

(junit/junitreport does this really well)

We can then simply grep the logs, and assuming we know the machine name can dump basic structured log info somewhere:

BUILDID/BUILDTIME | TESTTIME | TESTNAME | MACHINE(from this we can map to OS)

Comment 1

[Mike Schroepfer]

cc'd original authors of each test suite to see if we can get some help getting every test failure to log the basics in a consistent fashion

Comment 2

[(not currently active) Ted Mielczarek]

Yes, please. Note that we'll have to coordinate changes to log output with changes to the unittest buildbot log scrapers, and the Tinderbox error parser.

Comment 3

[Mike Schroepfer]

DBaron just educated me that there are a total of 2 test states (PASS/FAIL) and 3 expectations (PASS/FAIL/RANDOM) leading to a total of 6 output states.

ExpectedPass->Pass
ExpectedPass->Fail
ExpectedFail->Pass
ExpectedFail->Fail
Random->Pass
Random->Pass

(better explained: http://mxr.mozilla.org/mozilla-central/source/layout/tools/reftest/reftest.js#453 )

So we just need to account for all 6 states:

TEST-PASS
TEST-UNEXPECTED-FAIL
TEST-UNEXPECTED-PASS
TEST-KNOWN-FAIL
TEST-PASS(EXPECTED RANDOM)
TEST-FAIL(EXPECTED RANDOM)

Followed by a test identifier (file name or test name) followed by additional debugging output

Comment 4

[Mike Schroepfer]

Note if we log all test results into a separate file we don't have to have a unique test identifier.  If we don't/can't than we want some hard-to-mistake prefix to make parsing fullproof

(EG MOZ-AUTOMATED-TEST-*)

Comment 5

[Mike Schroepfer]

Ted can you help shepard this bug to completion?

Comment 6

[Mike Schroepfer]

This bug is just about getting our test suites to all report their test results in a consistent manner - consolidated reporting is split out into bug 443329 

Comment 7

[(not currently active) Ted Mielczarek]

Attachment: reformat browser-chrome test output

This reformats the output of the browser chrome tests. Gavin: the hunks at the bottom are just adding some semicolons to fix JS2-mode warnings, and JS2-mode apparently removing some trailing whitespace for me.

Here's some sample output:

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/testing/mochitest/tests/browser/browser_pass.js | pass ok
TEST-PASS | chrome://mochikit/content/browser/testing/mochitest/tests/browser/browser_pass.js | pass is - Got true, expected true
TEST-UNEXPECTED-PASS | chrome://mochikit/content/browser/testing/mochitest/tests/browser/browser_pass.js | pass todo
TEST-KNOWN-FAIL | chrome://mochikit/content/browser/testing/mochitest/tests/browser/browser_pass.js | pass todo_is - Got false, expected true

Comment 8

[:Gavin Sharp [email: [e-mail]]]

Comment on attachment 328052 [details] [diff] [review]
reformat browser-chrome test output

>diff --git a/testing/mochitest/browser-harness.xul b/testing/mochitest/browser-harness.xul

> function testResult(aCondition, aName, aDiag, aIsTodo) {

>+  if (aDiag)
>+    this.msg += " - " + aDiag;

r=me with this moved into the !this.pass branch as discussed on IRC.

Comment 9

[Mike Schroepfer]

Ted - this is awesome are you going to cover all the other test suites as well or do you need help?

Comment 10

[(not currently active) Ted Mielczarek]

Attachment: [checked in] browser chrome + mochitest logging changes

Contains the previous patch (with Gavin's suggested change) + the changes for Mochitest. Mochitest output looks like this:
*** 2 INFO TEST-PASS | /tests/MochiKit_Unit_Tests/test_MochiKit-Async.html | this should pass
*** 3 ERROR TEST-UNEXPECTED-FAIL | /tests/MochiKit_Unit_Tests/test_MochiKit-Async.html | this should fail
*** 4 INFO TEST-KNOWN-FAIL | /tests/MochiKit_Unit_Tests/test_MochiKit-Async.html | todo
*** 5 ERROR TEST-UNEXPECTED-PASS | /tests/MochiKit_Unit_Tests/test_MochiKit-Async.html | passing a todo
*** 6 INFO TEST-PASS | /tests/MochiKit_Unit_Tests/test_MochiKit-Async.html | this should pass
*** 7 ERROR TEST-UNEXPECTED-FAIL | /tests/MochiKit_Unit_Tests/test_MochiKit-Async.html | this should fail - got 1, expected 2

Comment 11

[(not currently active) Ted Mielczarek]

Attachment: [checked in] xpcshell test output changes

I dunno who actually owns xpcshell-simple, but robcee wfm!

Sample output:
TEST-UNEXPECTED-FAIL | ../../../../_tests/xpcshell-simple/test_harness_xpcshell_simple/unit/test_sample.js | test failed, see log
../../../../_tests/xpcshell-simple/test_harness_xpcshell_simple/unit/test_sample.js.log:
>>>>>>>
*** test pending
*** exiting
*** TEST-UNEXPECTED-FAIL | ../../../../_tests/xpcshell-simple/test_harness_xpcshell_simple/unit/test_sample.js | 57 == 58
JS frame :: d:/build/mozilla-central/tools/test-harness/xpcshell-simple/head.js :: do_throw :: line 101

Comment 12

[(not currently active) Ted Mielczarek]

Comment on attachment 328144 [details] [diff] [review]
[checked in] xpcshell test output changes

Apparently I own this, I'm not sure when that happened.

Comment 13

[(not currently active) Ted Mielczarek]

Attachment: reftest output patch

Changes reftest output, fixes perl scripts.

Sample output:
REFTEST TEST-PASS | data:text/html,<body> | 
REFTEST TEST-PASS | data:text/plain, | 
REFTEST TEST-PASS | data:text/plain,HELLO | (!=) 
REFTEST TEST-UNEXPECTED-FAIL | data:text/plain,HELLO | 
(image data URIs elided)
REFTEST TEST-FAIL(EXPECTED RANDOM) | data:text/plain,HELLO | 
REFTEST TEST-PASS(EXPECTED RANDOM) | data:text/plain, | 
REFTEST TEST-KNOWN-FAIL | data:text/plain,HELLO | 
REFTEST TEST-UNEXPECTED-PASS | data:text/html,<body> | 
REFTEST TEST-KNOWN-FAIL | data:text/plain, | (SKIP)

Comment 14

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Comment on attachment 328157 [details] [diff] [review]
reftest output patch

Could you also update reftest-analyzer.xhtml ?

Did you test the updates to the perl scripts?  

(I'd note that the code inside the additional if-else case in reftest-to-html and the one after it has some redundancy, since randomresult is guaranteed false for the first and true for the second; probably worth at least leaving a comment pointing that out if not cleaning it up.)

Comment 15

[(not currently active) Ted Mielczarek]

Yeah, I realized I forgot reftest-analyzer after the fact. I did test the perl scripts, with all combinations of output (I believe), and they looked correct.

Yeah, that last one is a little weird, it makes me think that we should just use TEST-UNEXPECTED-FAIL(EXPECTED RANDOM) for the output in that case. I could simplify that branch a bit. I'll get that updated when I get back to my computer...

Comment 16

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

(In reply to comment #15)
> Yeah, that last one is a little weird, it makes me think that we should just
> use TEST-UNEXPECTED-FAIL(EXPECTED RANDOM) for the output in that case. I could
> simplify that branch a bit. I'll get that updated when I get back to my
> computer...

That could be misleading if "UNEXPECTED" is what you're look for to find the thing that turned tinderbox orange...

Comment 17

[(not currently active) Ted Mielczarek]

Re-reading the code, I think I meant TEST-KNOWN-FAIL(EXPECTED RANDOM), which would let me join those two branches.

Comment 18

[(not currently active) Ted Mielczarek]

Attachment: [checked in] reftest output patch, take 2

Reftest changes, includes reftest-analyzer changes. I changed the output in the case I mentioned to
TEST-KNOWN-FAIL(EXPECTED RANDOM). I think that's more consistent with the other output. Reftest is currently our only test suite with an expected random state, so the other patches should be fine.

dbaron: I noticed while editing reftest-analyzer, that in the build_viewer function, there's a variable called "rowclass" that's declared and assigned, but never used. Is that just an oversight, or intentional?

Comment 19

[(not currently active) Ted Mielczarek]

Oh, forgot some links:
Sample log:
http://people.mozilla.com/~tmielczarek/reftest.log
Output of clean-reftest / reftest-to-html:
http://people.mozilla.com/~tmielczarek/reftest-clean.html
http://people.mozilla.com/~tmielczarek/reftest.html
Patched reftest-analyzer:
http://people.mozilla.com/~tmielczarek/reftest-analyzer.xhtml

Comment 20

[(not currently active) Ted Mielczarek]

Attachment: [checked in] change runtests.py leaks output

This changes the output for runtests.py's leak logging. This will fix bug 441550 as a side effect.

Comment 21

[(not currently active) Ted Mielczarek]

Attachment: [checked in] handle new error output in tinderbox error parser

This makes the tinderbox unittest error parser handle this new output. I didn't fix the "link to file" bits because tinderbox just links to bonsai, which doesn't work with Mercurial anyway, so it seemed sort of pointless.

Comment 22

[Mike Schroepfer]

Do you need to also change has_errorline for tinderbox?

Comment 23

[(not currently active) Ted Mielczarek]

has_errorline is the "link to file" bits I mentioned above. Sorry, could have been clearer there. That's just for getting links back to bonsai for filenames mentioned in an error, but links to bonsai aren't going to help us in mercurial anyway.

Comment 24

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Comment on attachment 328326 [details] [diff] [review]
[checked in] reftest output patch, take 2

r=dbaron

Could you make the line you added in reftest-analyzer.xhtml use tabs like the surrounding lines?

Comment 25

[(not currently active) Ted Mielczarek]

Attachment: [checked in] handle new error output in buildbot unittest steps

Ok, here's the unittest buildbot bits. This hasn't been tested, of course, Lukas has agreed to be the guinea pig here and test this on a staging system. In the meantime I'll get the test suite changes pushed to a repo that she can pull from to test with.

Comment 26

[(not currently active) Ted Mielczarek]

lsblakk:
http://hg.mozilla.org/users/tmielczarek_mozilla.com/index.cgi/unittest-unified-output/

You can build from there, and apply the buildbotcustom patch above locally to test.

Comment 27

[(not currently active) Ted Mielczarek]

Comment on attachment 328359 [details] [diff] [review]
[checked in] handle new error output in tinderbox error parser

This is checked in, but we'll need IT to update the production tinderbox.

Comment 28

[Rob Campbell [:rc] (:robcee)]

Comment on attachment 328527 [details] [diff] [review]
[checked in] handle new error output in buildbot unittest steps

looks good to me.

Comment 30

[Lukas Blakk [:lsblakk] use ?needinfo]

Test running on http://staging-master.build.mozilla.org:2010/waterfall

First attempt at 11:08 am = Builds 37, 16, 2 (from left to right)

Backed it out and ran from mozilla-central, then set it up again - starting at Builds 44, 22, 8 at 15:34

Comment 31

[(not currently active) Ted Mielczarek]

Test runs on staging look good. Thanks to lsblakk for setting that up for me.

Comment 32

[(not currently active) Ted Mielczarek]

Comment on attachment 328527 [details] [diff] [review]
[checked in] handle new error output in buildbot unittest steps

I've checked this in, we still need to update the master and restart it to get this live. We'll have to coordinate it with landing the unittest output changes as well.

Comment 33

[(not currently active) Ted Mielczarek]

Comment on attachment 328359 [details] [diff] [review]
[checked in] handle new error output in tinderbox error parser

Filed bug 445206 on getting production tinderbox updated to pick up this change.

Comment 35

[Nick Thomas [:nthomas] (UTC+12)]

Comment on attachment 328108 [details] [diff] [review]
[checked in] browser chrome + mochitest logging changes

Pushed to mozilla-central - rev:b2d1c3093a84

Comment 36

[Nick Thomas [:nthomas] (UTC+12)]

Comment on attachment 328144 [details] [diff] [review]
[checked in] xpcshell test output changes

Pushed to mozilla-central - rev:d3f2561990ab

Comment 37

[Nick Thomas [:nthomas] (UTC+12)]

Comment on attachment 328326 [details] [diff] [review]
[checked in] reftest output patch, take 2

Pushed to mozilla-central - rev:03a87160d7a2

Comment 38

[Nick Thomas [:nthomas] (UTC+12)]

Comment on attachment 328352 [details] [diff] [review]
[checked in] change runtests.py leaks output

Pushed to mozilla-central - rev:2beee8ac413e

Comment 39

[Nick Thomas [:nthomas] (UTC+12)]

Comment on attachment 328527 [details] [diff] [review]
[checked in] handle new error output in buildbot unittest steps

qm-moz2-unittest01:/tools/buildbotcustom/unittest/steps.py updated to rev 1.6 to pick up this change. Master restarted

Comment 40

[(not currently active) Ted Mielczarek]

Thanks Nick!

Comment 41

[(not currently active) Ted Mielczarek]

I don't think there's anything else to do here.