Closed Bug 1344346 Opened 8 years ago Closed 8 years ago

All gecko output is logged at the 'info' level thus bypassing mozharness' error lists

Categories

(Testing :: Mochitest, enhancement)

Product:
Testing
Component:
Mochitest
Type:
enhancement
Priority:
Not set
Severity:
normal

Tracking

(firefox55 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla55
Tracking Flags:
Tracking Status
firefox55 --- fixed

People

(Reporter: ahal, Assigned: ahal)

References

Details

Attachments

(3 files, 1 obsolete file)

Bug 1344346 - [mochitest] Log unstructured output as 'process_output',
59 bytes, text/x-review-board-request
jgraham
: review+
Details
Bug 1344346 - [mozlog] Use less verbose formatting on 'process_output' messages,
59 bytes, text/x-review-board-request
jgraham
: review+
Details
Bug 1344346 - [mozharness] Ensure StructuredOutputParser runs 'process_output' messages through the error lists,
59 bytes, text/x-review-board-request
jgraham
: review+
Details 
Mochitest converts all unstructured output into a 'log' action at the 'info' level:
https://dxr.mozilla.org/mozilla-central/rev/b23d6277acca34a4b1be9a4c24efd3b999e47ec3/testing/mochitest/runtests.py#214

This means the StructuredOutputParser on the mozharness side of things, won't run these logs through the error_list. In bug 1343659 kats was trying to add a new regex to the error list, but we were both confused as to why it wasn't working.

I can think of 4 solutions to this, none of which are perfect:

1) Run all 'info' messages through the 'error_list' check from the StructuredOutputParser. This is easy to do but kind of goes against the point of structured logging. It will also result in unnecessary processing for non-mochitest harnesses.

2) Bypass the structured logger to output these messages. This might be as easy as printing them to stdout. The downside here is that they will no longer show up in the structured log, which is definitely useful.

3) Log these messages as 'process_output' instead of 'log.info'. The downside here is that the tbplformatter currently prepends 'PROCESS' to the message string. This would look really bad on practically every single line, but perhaps it wouldn't be terrible to modify the tbplformatter to simply print the message as is.

I honestly have no idea what the better solution here is. James, do you have any ideas or preferences?
Flags: needinfo?(james)
(I originally had 4 solutions, but decided one of them wasn't worth writing about after the fact. I swear I can count to 3)
James commented 3) is the correct solution on IRC. I think I have a good solution by adding a 'main' key to the the 'process_start' action. This way formatters can treat 'main' processes differently from other subprocesses and everyone can be happy.
Flags: needinfo?(james)
Attachment #8844001 - Attachment is obsolete: true
Attachment #8844001 - Flags: review?(james)
Comment on attachment 8844002 [details]
Bug 1344346 - [mochitest] Log unstructured output as 'process_output',

https://reviewboard.mozilla.org/r/117572/#review119570

::: testing/mozharness/mozharness/mozilla/structuredlog.py:87
(Diff revision 2)
> +        if action == "process_output":
> +            # Run process output through the error lists, but make sure the super parser
> +            # doesn't print them to stdout (they should go through the log formatter).
> +            orig = self.log_output
> +            self.log_output = False
> +            self._handle_unstructured_output(data['data'])

Might be nicer to change this to 

`handle_unstructured_output(line, output_log)`

rather than doing the disable/enable dance, but up to you.
Attachment #8844002 - Flags: review?(james) → review+
Comment on attachment 8844106 [details]
Bug 1344346 - [mozlog] Use less verbose formatting on 'process_output' messages,

https://reviewboard.mozilla.org/r/117636/#review119572
Attachment #8844106 - Flags: review?(james) → review+
Assignee: nobody → ahalberstadt
Status: NEW → ASSIGNED
I can't land this because somehow the mochitest-clipboard tests aren't using structured logging or something, and all of their TEST-START/PASS and summary get the 'GECKO' prefix which then makes the harness not able to find the summary at the end:
https://treeherder.mozilla.org/logviewer.html#?job_id=82253308&repo=try&lineNumber=5450

I have no idea what the clipboard tests are doing differently..
In that try push it looks like most, if not all, of the mochitests have the GECKO(pid) prefix in their output. See e.g. https://treeherder.mozilla.org/logviewer.html#?job_id=82253398&repo=try&lineNumber=6750
Oh, I see what you mean. The clipboard and jetpack tests seem to have the summary also printed with the prefix, presumably because the summary is coming from jetpack somewhere? Both of those tests have "Jetpack Package Test Summary" which is coming from [1], where as the other tests (e.g. browser-chrome) is printing a summary from [2] via structured logging.

[1] http://searchfox.org/mozilla-central/rev/d4adaabd6d2f88be0d0b151e022c06f6554909da/testing/mochitest/jetpack-package-harness.js#217
[2] http://searchfox.org/mozilla-central/rev/d4adaabd6d2f88be0d0b151e022c06f6554909da/testing/mochitest/browser-test.js#375
Yeah, it's not just the summary, all the TEST-START/TEST-PASS messages too, which means they're apparently just not using structured logging at all. Looks like there are a smattering of browser-chrome test failures as well.

I don't want to block bug 1343659 on fixing all of this, as it will take a long time (and I'm about to go on an extended PTO). James, would you be ok with adding a hack to the tbplformatter to strip out all formatting if the 'process' starts with "GECKO"? Otherwise, my initial "main" based patch would be another alternative.

Either way I still need to dig into how this more.. if JP/cl are not using the structured logger, but are using the StructuredOutputParser in mozharness.. then I'm not sure how we'd be picking up failures :/
Flags: needinfo?(james)
It looks like both JP and clipboard use a JavaScript based framework here:
http://searchfox.org/mozilla-central/source/addon-sdk/source/lib/sdk/test/harness.js#524

At least we are excluding 'jetpack' flavors (which I think clipboard falls under?) from using the StructuredOutputParser:
http://searchfox.org/mozilla-central/source/testing/mozharness/configs/unittests/linux_unittest.py#298

So there aren't existing issues with detecting flavors. I'll file a bug to convert the addon-sdk harness to use the structured logger.

Side rant: We really need a moratorium on adding new mochitest-like suites that don't actually use mochitest and enforce it better via the module system. I know back then there wasn't much alternative, which is why we also really need a generic marionette-based bootstrapper that will give people an easy way to run JS based harnesses like this.
I think a better way to work around this would be to use "log.info" (like we were before) if options.flavor == jetpack.. Otherwise use "proces_output". I'll get a new series up for review soon.
Flags: needinfo?(james)
Sounds good.
I re-jiggered the commits a bit, and mozreview isn't great at figuring out what needs to be re-reviewed or not. So for convenience, here's the squashed interdiff since the last time you reviewed everything:
https://reviewboard.mozilla.org/r/117568/diff/3-4/
Latest push fixes a minor bug I noticed. Here's the updated squashed interdiff:
https://reviewboard.mozilla.org/r/117568/diff/3-5/
Comment on attachment 8845077 [details]
Bug 1344346 - [mozharness] Ensure StructuredOutputParser runs 'process_output' messages through the error lists,

https://reviewboard.mozilla.org/r/118292/#review120540
Attachment #8845077 - Flags: review?(james) → review+
Actually, probably not worth working on converting jetpack to structured logging. My understanding is it will be gone in 2 releases.
Pushed by ahalberstadt@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e6376870fa41
[mochitest] Log unstructured output as 'process_output', r=jgraham
https://hg.mozilla.org/integration/autoland/rev/9d49627bc457
[mozharness] Ensure StructuredOutputParser runs 'process_output' messages through the error lists, r=jgraham
https://hg.mozilla.org/integration/autoland/rev/896205d8a760
[mozlog] Use less verbose formatting on 'process_output' messages, r=jgraham
Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=896205d8a760c1004fe6e864a720b169f9f8a830&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=retry&filter-resultStatus=usercancel&filter-resultStatus=runnable

Failure log robocop: https://treeherder.mozilla.org/logviewer.html#?job_id=82814759&repo=autoland
[task 2017-03-09T17:20:22.068082Z] 17:20:22     INFO -  Traceback (most recent call last):
[task 2017-03-09T17:20:22.068357Z] 17:20:22     INFO -    File "/home/worker/workspace/build/tests/mochitest/runrobocop.py", line 589, in <module>
[task 2017-03-09T17:20:22.068537Z] 17:20:22     INFO -      sys.exit(main())
[task 2017-03-09T17:20:22.069790Z] 17:20:22     INFO -    File "/home/worker/workspace/build/tests/mochitest/runrobocop.py", line 586, in main
[task 2017-03-09T17:20:22.069832Z] 17:20:22     INFO -      return run_test_harness(parser, options)
[task 2017-03-09T17:20:22.069866Z] 17:20:22     INFO -    File "/home/worker/workspace/build/tests/mochitest/runrobocop.py", line 550, in run_test_harness
[task 2017-03-09T17:20:22.069892Z] 17:20:22     INFO -      robocop = RobocopTestRunner(auto, options.dm, options)
[task 2017-03-09T17:20:22.069923Z] 17:20:22     INFO -    File "/home/worker/workspace/build/tests/mochitest/runrobocop.py", line 45, in __init__
[task 2017-03-09T17:20:22.069945Z] 17:20:22     INFO -      MochitestDesktop.__init__(self, options)
[task 2017-03-09T17:20:22.069969Z] 17:20:22     INFO -  TypeError: __init__() takes at least 3 arguments (2 given)
[task 2017-03-09T17:20:22.080370Z] 17:20:22    ERROR - Return code: 1
[task 2017-03-09T17:20:22.080764Z] 17:20:22    ERROR - No tests run or test summary not found

Failure log wpt: https://treeherder.mozilla.org/logviewer.html#?job_id=82813800&repo=autoland
[task 2017-03-09T17:22:41.968737Z] 17:22:41     INFO - TEST-START | /webgl/conformance-1.0.3/conformance/ogles/GL/swizzlers/swizzlers_113_to_120.html
[task 2017-03-09T17:22:41.968897Z] 17:22:41     INFO - TEST-SKIP | /webgl/conformance-1.0.3/conformance/ogles/GL/swizzlers/swizzlers_113_to_120.html | took 0ms
[task 2017-03-09T17:22:41.968945Z] 17:22:41     INFO - Setting up ssl
[task 2017-03-09T17:22:41.969003Z] 17:22:41 CRITICAL - Test harness output was not a valid structured log message: 
[task 2017-03-09T17:22:41.969042Z] 17:22:41     INFO - certutil | 
[task 2017-03-09T17:22:41.969142Z] 17:22:41 CRITICAL - Test harness output was not a valid structured log message:
Flags: needinfo?(ahalberstadt)
Backout by archaeopteryx@coole-files.de:
https://hg.mozilla.org/integration/autoland/rev/4782fb1a555b
Backed out changeset 896205d8a760 
https://hg.mozilla.org/integration/autoland/rev/d5ed557a87d4
Backed out changeset 9d49627bc457 
https://hg.mozilla.org/integration/autoland/rev/7ccc5f516593
Backed out changeset e6376870fa41 for failing at least web-platform-tests and robocop tests. r=backout
Sorry, I had previously pushed this to try, but had only run mochitests. Both errors are easily fixed, patch shortly.
Flags: needinfo?(ahalberstadt)
Sorry for all the requests, but you said you wanted to try the "no r+ with nits" policy, and I can't unset your r+ on mozreview. Mind taking a quick look at the fixes?

Here's the squashed interdiff that fixes the bugs in the backout:
https://reviewboard.mozilla.org/r/117568/diff/5-6/

And here's a passing try run with wpt and robocop:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=25104df4f95039d56be1f35c4793db39100f9922

(The windows 2012 build failures and browser-chrome autocomplete failures are pretty much permafail on pushes prior to mine, so I'm assuming they're unrelated).
Flags: needinfo?(james)
lgtm Thanks!
Flags: needinfo?(james)
Pushed by ahalberstadt@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/8e03e57d44aa
[mochitest] Log unstructured output as 'process_output', r=jgraham
https://hg.mozilla.org/integration/autoland/rev/cd8993e4d0dd
[mozharness] Ensure StructuredOutputParser runs 'process_output' messages through the error lists, r=jgraham
https://hg.mozilla.org/integration/autoland/rev/71e3443cdc43
[mozlog] Use less verbose formatting on 'process_output' messages, r=jgraham
Didn't run OSX/Windows debug this time. Latest backout happened because the leak checker was still looking at 'log' messages instead of 'process_output'. We still need to inspect both 'log' and 'process_output' though due to jetpack flavors still being unstructured.

Interdiff:
https://reviewboard.mozilla.org/r/117568/diff/6-7/

Try run showing it's fixed:
https://treeherder.mozilla.org/#/jobs?repo=try&author=ahalberstadt@mozilla.com

Still waiting for some results to come in, will push if they look good. Third time's the charm.
Flags: needinfo?(ahalberstadt)
Pushed by ahalberstadt@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/6fdb052f6745
[mochitest] Log unstructured output as 'process_output', r=jgraham
https://hg.mozilla.org/integration/autoland/rev/fa7b9f95bbfa
[mozharness] Ensure StructuredOutputParser runs 'process_output' messages through the error lists, r=jgraham
https://hg.mozilla.org/integration/autoland/rev/03ea17d7be98
[mozlog] Use less verbose formatting on 'process_output' messages, r=jgraham
https://hg.mozilla.org/mozilla-central/rev/6fdb052f6745
https://hg.mozilla.org/mozilla-central/rev/fa7b9f95bbfa
https://hg.mozilla.org/mozilla-central/rev/03ea17d7be98
Status: ASSIGNED → RESOLVED
Closed: 8 years ago
status-firefox55: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Depends on: 1353858
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: