Open Bug 1261197 Opened 4 years ago Updated 3 years ago

Use StructuredOutputParser for parsing xpcshell test results

Categories

(Release Engineering :: Applications: MozharnessCore, defect)

defect
Not set

Tracking

(Not tracked)

People

(Reporter: ahal, Assigned: pyang)

References

(Depends on 1 open bug, Blocks 1 open bug)

Details

Attachments

(2 files, 1 obsolete file)

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.
Attached patch enable-xpc (obsolete) — Splinter Review
Enable structured log for xpc shell test suites.  result looks fine and supposedly we can try more complicated scenarios.
Assignee: nobody → pyang
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.
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.
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.
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.
By disabling structuredlog, the result remains.  Looks like some other problem rather than this patch.
Depends on: 1295093
Attached patch enable-configSplinter Review
following patch by enabling structured log for xpcshell
try https://treeherder.mozilla.org/#/jobs?repo=try&revision=506cbc5d7b19c26fc185144e72044bf3f22fc462
Attachment #8767869 - Attachment is obsolete: true
Attachment #8805023 - Flags: review?(ahalberstadt)
Depends on: 1313265
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.
Attachment #8805023 - Flags: review?(ahalberstadt) → review+
Pushed by ahalberstadt@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/d2ad6e385240
Use StructuredOutputParser for parsing xpcshell test results, r=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?
ya I guess the error wasn't found before but we can lower log level for specific log for sure.
Leave ni? for reminder.
Flags: needinfo?(pyang)
(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 on attachment 8808464 [details]
Bug 1261197 - Use StructuredOutputParser for parsing xpcshell test results

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

Thanks!
Attachment #8808464 - Flags: review?(ahalberstadt) → review+
Pushed by ahalberstadt@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/4777ed22d16d
Use StructuredOutputParser for parsing xpcshell test results r=ahal
It reminds me bug 1305583
which has same symptom, missing test_end randomly.
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.
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.
Depends on: 1316309
Pushed by ahalberstadt@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/3891a7e1ba76
Use StructuredOutputParser for parsing xpcshell test results r=ahal
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
Well, and opt too, once I found some opt runs.
Depends on: 1319472
You need to log in before you can comment on or make changes to this bug.