1400181 - Error messages prefixed with numbers, so treeherder classification doesn't find bug suggestions - drop them

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Connection error messages started to get prefixed with a number during the last days, e.g. https://treeherder.mozilla.org/logviewer.html#?job_id=131191229&repo=autoland&lineNumber=2085

> [task 2017-09-15T05:03:22.524Z] 05:03:22     INFO -  0 ERROR Automation Error: Received unexpected exception while running application

Now Treeherder's "Failure summary" tab doesn't suggested bug 1261598 for that line anymore.

This seems to have started during the last 2 days as https://treeherder.mozilla.org/logviewer.html#?job_id=131210045&repo=autoland&lineNumber=38647 hasn't these numbers.

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+1]]

This is actually a Mochitest job and not Marionette. Having a look at the error message it appears only once in the tree in testing/mochitest/runtests.py. Changes to this file have been done in the last two days by Geoff via bug 1394910 and bug 1399769.

Both bugs change things around result values but not what we print out. But maybe that is connected. Geoff, do you have an idea?

Comment 2

[Geoff Brown [:gbrown]]

It's not just error messages, but all "interior" INFO or ERROR or WARNING messages:

[task 2017-09-15T05:05:47.687Z] 05:05:47     INFO -  GECKO(1214) | MEMORY STAT | vsize 912MB | residentFast 226MB | heapAllocated 86MB
[task 2017-09-15T05:05:47.691Z] 05:05:47     INFO -  5 INFO TEST-OK | browser/base/content/test/alerts/browser_notification_close.js | took 12867ms
[task 2017-09-15T05:05:48.014Z] 05:05:48     INFO -  6 INFO checking window state
[task 2017-09-15T05:05:48.151Z] 05:05:48     INFO -  GECKO(1214) | --DOMWINDOW == 11 (0xda350800) [pid = 1214] [serial = 7] [outer = (nil)] [url = about:blank]
[task 2017-09-15T05:05:48.169Z] 05:05:48     INFO -  7 INFO TEST-START | browser/base/content/test/alerts/browser_notification_do_not_disturb.js

I don't think this is related to my changes, but will have a closer look.

Comment 3

[Geoff Brown [:gbrown]]

This started with https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=e5414216229f41390263910a8ec2fb73975ba15c, bug 1371065 / bug 1399216.

:kmag -- Do you know what happened here?

Comment 4

[(not currently active) Ted Mielczarek]

This looks like maybe something is going wrong with the structured log handling in the Mochitest harness.

The log from comment 0 ( https://public-artifacts.taskcluster.net/AKvlwugwRvu1XsGNp5A67g/0/public/logs/live_backing.log ) has this line:
[task 2017-09-15T05:03:22.628Z] 05:03:22    ERROR -  1 ERROR TEST-UNEXPECTED-FAIL | leakcheck | default process: missing output line for total leaks!

and the raw structured log ( https://public-artifacts.taskcluster.net/AKvlwugwRvu1XsGNp5A67g/0/public/test_info//browser-chrome-chunked_raw.log ) has this line:
{"source": "mochitest", "thread": "MainThread", "time": 1505451802627, "action": "log", "message": "TEST-UNEXPECTED-FAIL | leakcheck | default process: missing output line for total leaks!", "level": "ERROR", "pid": 1050}

Which looks sensible, so this must be breaking at the "format structured log" stage of things.

Comment 5

[Kris Maglione [:kmag]]

I double checked those patches and don't see anything that should have caused those changes. There are some places where I changed the structured log settings to remove 'jetpack' references, but it doesn't look like any of them should have affected other mochitest flavors.

Comment 6

[Geoff Brown [:gbrown]]

Thanks kmag; your changes look OK to me too, but...


Mochitest logs from before kmag's changes show

  "Structured output parser in use for mochitest"

Emitted by https://dxr.mozilla.org/mozilla-central/rev/f9a5e9ed62103c84e4cde915f4d08f1ce71be83e/testing/mozharness/scripts/desktop_unittest.py#516, which is dependent on the mozharness config's "unstructured_flavors".

Current mochitest logs, with the extra numbers, do not have "Structured output parser in use for mochitest".

Comment 7

[(not currently active) Ted Mielczarek]

Oh! I think this just exposed a dumb bug in the existing mozharness code then.

kmag's changes emptied out the 'unstructured_flavors' entry for mochitest (rightfully so):
https://hg.mozilla.org/integration/mozilla-inbound/diff/f725597fa0b4/testing/mozharness/configs/unittests/linux_unittest.py#l1.32

but the check in `structured_output` does:
        if not unstructured_flavors.get(suite_category) or flavor in unstructured_flavors.get(suite_category):
            return False

https://dxr.mozilla.org/mozilla-central/rev/f9a5e9ed62103c84e4cde915f4d08f1ce71be83e/testing/mozharness/scripts/desktop_unittest.py#508

...and since `unstructured_flavors.get(suite_category)` is now an empty list, that will return False. That seems wrong.

Comment 8

[Kris Maglione [:kmag]]

Hm. Intersting. It seems to be caused by this check:

http://searchfox.org/mozilla-central/rev/2c9a5993ac40ec1db8450e3e0a85702fa291b9e2/testing/mozharness/scripts/desktop_unittest.py#507-508

since an empty array is treated as falsy.

That doesn't seem right... or at least doesn't seem intuitive... since an empty array is treated completely differently than an array with any other number of items.

Are all of the other suites listed intended to have unstructured output?

http://searchfox.org/mozilla-central/rev/2c9a5993ac40ec1db8450e3e0a85702fa291b9e2/testing/mozharness/configs/unittests/linux_unittest.py#297-304

If so, I'll just remove the `"mochitest": []` entries, which should fix the problem.

Comment 9

[Kris Maglione [:kmag]]

(mid-aired Ted's nearly identical comment)

Comment 10

[Geoff Brown [:gbrown]]

ahal -- Can you confirm: Other than mochitest, are all of these unstructured?

   "unstructured_flavors": {"mochitest": [],
                            "xpcshell": [],
                            "gtest": [],
                            "mozmill": [],
                            "cppunittest": [],
                            "jittest": [],
                            "mozbase": [],
                            },

Comment 11

[Geoff Brown [:gbrown]]

Attachment: enable structured logging support for mochitest in mozharness

I'm pretty sure that's the case; that is,

"xpcshell": []

means "xpcshell is unstructured, regardless of flavor", and this only got confusing because there was

"mochitest": ["jetpack"]

meaning, "only jetpack mochitests are unstructured".

Comment 12

[Andrew Halberstadt [:ahal]]

Comment on attachment 8908763 [details] [diff] [review]
enable structured logging support for mochitest in mozharness

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

Yes this looks good.

I agree this behaviour is weird and confusing. Now that none of the suites have subsuites that need to be stay unstructured, we should just turn this into a list, e.g:
unstructured_suites = ['xpcshell', 'cppunittest', ...]

But let's leave that to a follow up.

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/8a5a46b8c9d1
Return mochitests to structured logging; r=ahal

Comment 14

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/8a5a46b8c9d1