1055863 - server.js logs printed to stdout when running mochitests

Status: NEW

(Testing :: Mochitest, defect)

Description

[Ahmed Kachkach [:akachkach]]

mwargers reported some differences he noticed between the JSON logs saved to a file and the logs printed to stdout when he runs this command (on MacOSX 10.9.5, with a debug build):

  ./mach mochitest-plain --log-mach=- --log-raw=mochi.json testing/mochitest/tests/Harness_sanity/

Here are the logs dumped to stdout:

https://pastebin.mozilla.org/6060051

Here are the raw JSON logs:

https://pastebin.mozilla.org/6060022

The problem here is some lines in stdout that seem to be dumped directly to stdout (instead of going through our structured logger) like this one:

System JS : WARNING /Users/mwargers/mozilla-central/obj-x86_64-apple-darwin13.3.0/_tests/testing/mochitest/server.js:444 - assignment to undeclared variable pathPieces

These lines are easily recognizable because they're not formatted (and can't be found in the JSON logs).

I'm not sure what causes this (since we transform unstructured logs to INFO messages: http://dxr.mozilla.org/mozilla-central/source/testing/mochitest/runtests.py#129)

Comment 1

[Ahmed Kachkach [:akachkach]]

Attachment: Logs in stdout

Since the pastebin links are going to expire in a day, here's the stdout logs.

Comment 2

[Ahmed Kachkach [:akachkach]]

Attachment: JSON logs

... and here are the JSON logs.

Comment 3

[Ed Morley [:emorley]]

The example in comment 0 comes from:

http://mxr.mozilla.org/mozilla-central/source/js/xpconnect/src/nsXPConnect.cpp#232

231     if (nsContentUtils::DOMWindowDumpEnabled()) {
232         fprintf(stderr, "System JS : %s %s:%d - %s\n",
233                 JSREPORT_IS_WARNING(rep->flags) ? "WARNING" : "ERROR",
234                 rep->filename, rep->lineno,
235                 message ? message : "<no message>");
236     }

Comment 4

[Ahmed Kachkach [:akachkach]]

Yep, and the others too. They seem to be all printed to stderr so I wonder what makes us miss some of these and get the others.

NI? ted since he seemed to know something about this on IRC.

Comment 5

[(not currently active) Ted Mielczarek]

After puzzling over this for a bit I figured it out. If you look closely at the filenames involved:
System JS : WARNING /Users/mwargers/mozilla-central/obj-x86_64-apple-darwin13.3.0/_tests/testing/mochitest/server.js:444 - assignment to undeclared variable pathPieces

That's server.js, which is running in the xpcshell process we use for the HTTP server. :)

Comment 6

[Ahmed Kachkach [:akachkach]]

Thanks ted! Didn't notice that at all, uh :/.

I guess this is sort of problematic (we don't want these logs to be lost when printing structured logs to a file) but probably not high priority.