Ahmed Kachkach [:akachkach] Assignee
	Description • 10 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"}ⰲ겿

	Ahmed Kachkach [:akachkach] Assignee
	Comment 1 • 10 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?

	Andrew Halberstadt [:ahal]
	Comment 2 • 10 years ago

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().

	(not currently active) Ted Mielczarek
	Comment 3 • 10 years ago

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.

	Ahmed Kachkach [:akachkach] Assignee
	Comment 4 • 10 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.

	(not currently active) Ted Mielczarek
	Comment 5 • 10 years ago

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.)

	Ahmed Kachkach [:akachkach] Assignee
	Comment 6 • 10 years ago

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

	Andrew Halberstadt [:ahal]
	Comment 7 • 10 years ago

(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.

	Andrew Halberstadt [:ahal]
	Comment 8 • 10 years ago

(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

	Andrew Halberstadt [:ahal]
	Comment 9 • 10 years ago

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)

	Ahmed Kachkach [:akachkach] Assignee
	Comment 10 • 10 years ago

Fixed nits and filed bug 1042998 for using StructuredLog.jsm in the future

	Carsten Book [:Tomcat]
	Comment 11 • 10 years ago

https://hg.mozilla.org/integration/mozilla-inbound/rev/f0b4070ebc82

	Carsten Book [:Tomcat]
	Comment 12 • 10 years ago

https://hg.mozilla.org/mozilla-central/rev/f0b4070ebc82

	Ryan VanderMeulen [:RyanVM]
	Comment 13 • 10 years ago

https://hg.mozilla.org/releases/mozilla-aurora/rev/251037f4b6c9