Closed Bug 1344346 Opened 3 years ago Closed 3 years ago
All gecko output is logged at the 'info' level thus bypassing mozharness' error lists
59 bytes, text/x-review-board-request
59 bytes, text/x-review-board-request
Bug 1344346 - [mozharness] Ensure StructuredOutputParser runs 'process_output' messages through the error lists,
59 bytes, text/x-review-board-request
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?
(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.
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 , where as the other tests (e.g. browser-chrome) is printing a summary from  via structured logging.  http://searchfox.org/mozilla-central/rev/d4adaabd6d2f88be0d0b151e022c06f6554909da/testing/mochitest/jetpack-package-harness.js#217  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 :/
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.
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 email@example.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:
Backout by firstname.lastname@example.org: 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.
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).
Pushed by email@example.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
sorry had to back this out for mochitest shutdownleaks like https://treeherder.mozilla.org/logviewer.html#?job_id=82892102&repo=autoland&lineNumber=3678 https://hg.mozilla.org/integration/autoland/rev/c593315237b8
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://firstname.lastname@example.org Still waiting for some results to come in, will push if they look good. Third time's the charm.
Pushed by email@example.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
You need to log in before you can comment on or make changes to this bug.