Mochitests prints raw JSON logs when running with a debugger

RESOLVED FIXED in Firefox 33

Status

defect
RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: akachkach, Assigned: akachkach)

Tracking

unspecified
mozilla34
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox33 fixed, firefox34 fixed)

Details

Attachments

(1 attachment, 1 obsolete attachment)

Assignee

Description

5 years ago
Bug 886570 introduced a regression: when using a debugger, the raw JSON logs are printed instead of being formatted first. (to produce the output we previously had)

Example:

./mach mochitest-plain --debugger=lldb
...
1903 INFO SUITE-START | Running 3644 tests
1904 INFO runtests.py | Running tests: start.

1905 INFO runtests.py | Application pid: 38788
Current executable set to '/Users/akachkach/workspace/gecko-dev/obj-x86_64-apple-darwin13.3.0/dist/Nightly.app/Contents/MacOS/firefox' (x86_64).
Executing commands in '/Users/akachkach/workspace/gecko-dev/.lldbinit'.
(lldb) run
Process 38789 launched: '/Users/akachkach/workspace/gecko-dev/obj-x86_64-apple-darwin13.3.0/dist/Nightly.app/Contents/MacOS/firefox' (x86_64)
-*- Webapps.jsm : Saving /var/folders/d8/dn7q5bvx0r3_qwzh8nqy2sr40000gn/T/tmp6eRydf.mozrunner/webapps/webapps.json
-*- Webapps.jsm : Saving /var/folders/d8/dn7q5bvx0r3_qwzh8nqy2sr40000gn/T/tmp6eRydf.mozrunner/webapps/webapps.json
ⰲ겿{"action":"log","time":1405968812467,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"SimpleTest START"}ⰲ겿
ⰲ겿{"action":"test_start","time":1405968812471,"thread":null,"pid":null,"source":"mochitest","test":"/tests/browser/base/content/test/general/test_bug364677.html"}ⰲ겿
ⰲ겿{"action":"test_status","time":1405968813579,"thread":null,"pid":null,"source":"mochitest","test":"/tests/browser/base/content/test/general/test_bug364677.html","subtest":"Feed served as text/xml without a channel/link should have been sniffed","status":"PASS"}ⰲ겿
Assignee

Comment 1

5 years ago
So I tried tracking the source of this regression, and it seems to be a bigger issue than I first thought because using the debugger bypasses all the process handling code:

http://dxr.mozilla.org/mozilla-central/source/testing/mozbase/mozrunner/mozrunner/base/runner.py#92

When using a debugger, the Firefox process is ran using subprocess.Popen, and so the logs are directly printed to stdout without any processing.

I tried using mozprocess.ProcessHandler instead, but it doesn't display anything and the process hangs.

Do you know what we can do at this point :ahal?
Flags: needinfo?(ahalberstadt)
So basically the problem is that the output isn't being formatted anymore, right?

I think you need to create a new Stream-like object that first formats the output before writing to sys.stdout. Then you'll need to redirect stdout and stderr to this new stream in the Popen call. You can maybe re-use the 'stream' parameter in self.process_args or you might need to add a new parameter to runner.start().
Flags: needinfo?(ahalberstadt)
This is really tricky to get right. We have this same bug on file for xpcshell somewhere. Interposing any output-handling code in between the user and an interactive debugger is likely to break things. The best I could think to do would be to reimplement a mach/tbpl-style formatter in JS, and pass down some argument to use that instead of raw structured logs when using an interactive debugger.
Assignee

Comment 4

5 years ago
So, because we're using a special delimiter for the mochitest logs, there's a hack-ish way of doing this:

Printing character per character what the debugger writes in stdout (to see the commands as you type them), except when we get the delimiter at the beginning of a line (then we read the whole line and format it before we print it).

I have a patch that's sort of working with this, just have to fix a bug with detecting the delimiter.

Obviously, it's *really* hacky. So yeah, maybe we really need to use a JS formatter if we need something robust.
Structured logging doesn't actually buy us anything when running with a debugger, nobody cares about the test results being tallied in that case. (I think we pretty much ignore everything anyway.)
Assignee

Comment 6

5 years ago
Posted patch debugger.patch (obsolete) — Splinter Review
This should do the trick (the --debugger param is passed to the JS side, and a formatter is used in that case). Had to move the "delimiter" code up to StructuredLogger because it would still print the delimiters when using the debugger otherwise.

Try push: https://tbpl.mozilla.org/?tree=Try&rev=66c198fedde1
Attachment #8460699 - Flags: review?(ahalberstadt)
(In reply to Ted Mielczarek [:ted.mielczarek] from comment #5)
> Structured logging doesn't actually buy us anything when running with a
> debugger, nobody cares about the test results being tallied in that case. (I

We don't have a way to turn it on and off though. So everything uses structured logging now, whether it needs to or not.
(In reply to Ahmed Kachkach [:akachkach] from comment #6)
> Created attachment 8460699 [details] [diff] [review]
> debugger.patch
> 
> This should do the trick (the --debugger param is passed to the JS side, and
> a formatter is used in that case). Had to move the "delimiter" code up to
> StructuredLogger because it would still print the delimiters when using the
> debugger otherwise.
> 
> Try push: https://tbpl.mozilla.org/?tree=Try&rev=66c198fedde1

Hm, this seems like it could be useful outside of mochitest. Can we add the formatter to the jsm introduced by bug 916265 ?

cc'ing chmanchester
Assignee

Updated

5 years ago
Blocks: 886570
Comment on attachment 8460699 [details] [diff] [review]
debugger.patch

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

So I'm ok landing this for now.. but we should file a new bug to get mochitest to use the jsm that Chris created in bug 916265. At that point we should also move the formatter over there. So r+ with filing of a new bug and nits addressed.

::: testing/mochitest/tests/SimpleTest/TestRunner.js
@@ +68,5 @@
> +/**
> + * StructuredFormatter: Formatter class turning structured messages
> + * into human-readable messages.
> + */
> +this.StructuredFormatter = function () {

nit: don't put a space between function and (, same for everything below

@@ +72,5 @@
> +this.StructuredFormatter = function () {
> +    this.testStartTimes = {};
> +};
> +
> +

nit: extra newline

@@ +77,5 @@
> +StructuredFormatter.prototype.log = function (message) {
> +  return message.message;
> +};
> +
> +

nit: extra newline

@@ +95,5 @@
> +    if (message.expected) {
> +        return "TEST-UNEXPECTED-" + message.status + " | " + statusInfo +
> +               " - expected: " + message.expected;
> +    }
> +    else {

nit: put else clauses on same line as closing brace for the if (same below)
Attachment #8460699 - Flags: review?(ahalberstadt) → review+
Assignee

Updated

5 years ago
Blocks: 1042998
Assignee

Comment 10

5 years ago
Fixed nits and filed bug 1042998 for using StructuredLog.jsm in the future
Attachment #8460699 - Attachment is obsolete: true
Attachment #8461168 - Flags: review+
Assignee

Updated

5 years ago
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/f0b4070ebc82
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla34
You need to log in before you can comment on or make changes to this bug.