1261197 - Use StructuredOutputParser for parsing xpcshell test results

Status: NEW

(Release Engineering :: Applications: MozharnessCore, defect)

Description

[Andrew Halberstadt [:ahal]]

XPCShell emits structured logs, but mozharness currently doesn't consume them. It is still parsing the old formatted logs using a set of regexes. We should make sure to use the StructuredOutputParser class instead of DesktopUnittestParser:
https://dxr.mozilla.org/mozilla-central/source/testing/mozharness/mozharness/mozilla/testing/testbase.py#502

We'll need to be careful that we don't miss failures that are hidden in unstructured output. This might mean running the same set of regexes when we come across unstructured output.

Comment 1

[Paul Yang [:pyang] (away)]

Attachment: enable-xpc

Enable structured log for xpc shell test suites.  result looks fine and supposedly we can try more complicated scenarios.

Comment 2

[Paul Yang [:pyang] (away)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=6aa6b5c9738516fe6e0828d9666a633b5954ee59

Try results

Comment 3

[Andrew Halberstadt [:ahal]]

I did some testing here with the same patch I used to test reftest:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=5ee267bb2352f147f638d440e75f63ae62747df8&filter-searchStr=xpcshell
https://treeherder.mozilla.org/#/jobs?repo=try&revision=ae082a11a51f8b7a519a1b2cd6af9724b9bd0dd9

The red X in the second push means that the structured log output parser returned TBPL_FAILURE whereas the old parser returned TBPL_SUCCESS. However both parsers returned an "error" log level. So I don't think that means there will be a new intermittent after landing this change (though maybe that particular failure will make the job red instead of orange or vice versa).

Anyway we should still do the normal testing in addition to the OutputParser differential patch.

Comment 4

[Phil Ringnalda (:philor)]

That will be a new failure, and a rather ugly one if it's going to look just like that, with the autoclassify panel seeing a line of output and the failure summary panel seeing nothing.

Comment 5

[Andrew Halberstadt [:ahal]]

No, it won't look like that. The stdout from that log is solely from the DesktopUnittestOutputParser, so whatever the structured one is flagging isn't visible in there (to us or to treeherder). The red X basically just tells us we need to do more testing. Good to know that would be a new intermittent though.

Comment 6

[Paul Yang [:pyang] (away)]

I have same result from those intentional failures.
https://treeherder.mozilla.org/#/jobs?repo=try&revision=797a980944ac32a6d128234c139069c7484efa08&selectedJob=26497289
2 kinds of falures/errors triggered, however assertion failures were considered as errors (red ones), and force killed process was marked as orange.
Expected result should be opposite. Since reftest can differentiate states I think we might need to look into xpcshell.

Comment 7

[Paul Yang [:pyang] (away)]

By disabling structuredlog, the result remains.  Looks like some other problem rather than this patch.

Comment 8

[Paul Yang [:pyang] (away)]

Attachment: enable-config

following patch by enabling structured log for xpcshell
try https://treeherder.mozilla.org/#/jobs?repo=try&revision=506cbc5d7b19c26fc185144e72044bf3f22fc462

Comment 9

[Andrew Halberstadt [:ahal]]

Comment on attachment 8805023 [details] [diff] [review]
enable-config

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

Thanks, looks good. I'll land this tomorrow when after I have a chance to do the usual testing.

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/d2ad6e385240
Use StructuredOutputParser for parsing xpcshell test results, r=ahal

Comment 11

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

I had to back this out for WinXP opt/pgo failures like https://treeherder.mozilla.org/logviewer.html#?job_id=38773982&repo=mozilla-inbound

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

Comment 12

[Andrew Halberstadt [:ahal]]

Looks like this is a pre-existing problem that was being hidden:
https://dxr.mozilla.org/mozilla-central/source/testing/xpcshell/runxpcshelltests.py#1009

Kind of scary is the fact that calling self.log.error *wasn't* turning the job red before. This patches behaviour is definitely the correct one. Seeing as that failure doesn't seem to matter, maybe we can just change the log.error to a warning. Paul, would you mind attaching a new patch and testing that it fixes this on try?

Comment 13

[Paul Yang [:pyang] (away)]

ya I guess the error wasn't found before but we can lower log level for specific log for sure.
Leave ni? for reminder.

Comment 14

[Paul Yang [:pyang] (away)]

Attachment: Bug 1261197 - Use StructuredOutputParser for parsing xpcshell test results

Review commit: https://reviewboard.mozilla.org/r/91294/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/91294/

Comment 15

[Paul Yang [:pyang] (away)]

treeherder result
https://treeherder.mozilla.org/#/jobs?repo=try&revision=e939ddb33e37caa4865a9fbcfea9668db25d9748

Comment 16

[Andrew Halberstadt [:ahal]]

(In reply to Paul Yang [:pyang] from comment #15)
> treeherder result
> https://treeherder.mozilla.org/#/
> jobs?repo=try&revision=e939ddb33e37caa4865a9fbcfea9668db25d9748

Ah, that's how this slipped through.. Looks like the xpcshell tests don't run on XP on try. Sigh, another case of things running on inbound but not try. I triggered the job in question on that push, so we'll see if it still turns orange.

Also thanks for using mozreview! :)

Comment 17

[Andrew Halberstadt [:ahal]]

Comment on attachment 8808464 [details]
Bug 1261197 - Use StructuredOutputParser for parsing xpcshell test results

https://reviewboard.mozilla.org/r/91294/#review91276

Thanks!

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/4777ed22d16d
Use StructuredOutputParser for parsing xpcshell test results r=ahal

Comment 19

[Phil Ringnalda (:philor)]

Backed out in https://hg.mozilla.org/integration/autoland/rev/ab5b5e1a8fc0d4f21de1a9f4d24269f922e7c201 for telling us that various different WinXP debug (and much more rarely Win7/Win8/opt) tests "logged while not in progress. Logged with data: {"status": "PASS",", like

https://treeherder.mozilla.org/logviewer.html#?job_id=6342927&repo=autoland
https://treeherder.mozilla.org/logviewer.html#?job_id=6344314&repo=autoland
https://treeherder.mozilla.org/logviewer.html#?job_id=6356669&repo=autoland
https://treeherder.mozilla.org/logviewer.html#?job_id=6359262&repo=autoland
https://treeherder.mozilla.org/logviewer.html#?job_id=6351538&repo=autoland
https://treeherder.mozilla.org/logviewer.html#?job_id=6363879&repo=autoland
https://treeherder.mozilla.org/logviewer.html#?job_id=6366573&repo=autoland
https://treeherder.mozilla.org/logviewer.html#?job_id=6365670&repo=autoland (WinXP opt)
https://treeherder.mozilla.org/logviewer.html#?job_id=6344876&repo=autoland (Win7)
https://treeherder.mozilla.org/logviewer.html#?job_id=6367458&repo=autoland (Win8)

Comment 20

[Paul Yang [:pyang] (away)]

It reminds me bug 1305583
which has same symptom, missing test_end randomly.

Comment 21

[Andrew Halberstadt [:ahal]]

Xpcshell runs tests in parallel, so the START/END messages don't get logged in order.. I don't know why this would be intermittent and more prevalent on debug than opt though.

(In reply to Paul Yang [:pyang] from comment #20)
> It reminds me bug 1305583
> which has same symptom, missing test_end randomly.

I think this is a separate issue, if anything it's a missing test_start.. But it's definitely something to do with the OutputParser, as that is the only thing that changed with this patch. So I doubt it's a harness issue.

Comment 22

[Andrew Halberstadt [:ahal]]

Ah, so yet again this is a case of the error existing previously but not turning the job orange:
https://archive.mozilla.org/pub/firefox/tinderbox-builds/mozilla-central-win32-debug/1478640923/mozilla-central_xp_ix-debug_test-xpcshell-bm119-tests1-windows-build38.txt.gz

Before this patch, mozharness was happily turning self.log.error(...) messages into INFO ones. I'll file a new bug to tackle this latest issue, nothing needs to change with this patch.

Comment 23

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/3891a7e1ba76
Use StructuredOutputParser for parsing xpcshell test results r=ahal

Comment 24

[Phil Ringnalda (:philor)]

Backed out in https://hg.mozilla.org/integration/mozilla-inbound/rev/55eb93732d99 - I don't doubt that they deserve to look like that, but 100% of the Win8 debug runs looked like https://treeherder.mozilla.org/logviewer.html#?job_id=39408261&repo=mozilla-inbound

Comment 25

[Phil Ringnalda (:philor)]

Well, and opt too, once I found some opt runs.

Comment 26

[BugBot [:suhaib / :marco/ :calixte]]

The bug assignee is inactive on Bugzilla, so the assignee is being reset.