886570 - Mochitest should have ability to output structured messages

Status: RESOLVED FIXED

(Testing :: Mochitest, defect, P2)

Description

[Chris Manchester (limited bugmail, email directly)]

The mochitest harness should have the ability to output structured messages to a file

Comment 1

[Chris Manchester (limited bugmail, email directly)]

Attachment: Add ability for mochitest plain to log structured messages to a file;

Note that this patch will not apply cleanly without the changes from bug 884397.

Comment 2

[Chris Manchester (limited bugmail, email directly)]

Attachment: Add ability for mochitest plain to log structured messages to a file;

This includes a small fix to the included test.

Comment 3

[Andrew Halberstadt [:ahal]]

Comment on attachment 768424 [details] [diff] [review]
Add ability for mochitest plain to log structured messages to a file;

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

I'm not really familiar with Log4Moz/SimpleTest etc. so my feedback is mostly around the runtests.py changes. But the approach looks good to me. Just a few comments.

::: testing/mochitest/runtests.py
@@ +76,5 @@
>  
> +    self.add_option("--enable-structured-output",
> +                    action = "store_true", dest = "structuredEnabled",
> +                    help = "enable structured output to be written to a file")
> +    defaults["structuredEnabled"] = True

If this is going to default to True then it needs to be "--disable-structured-output". Is there a reason to just not have it enabled all the time? I.e do we need this at all?

@@ +82,5 @@
> +    self.add_option("--structured-log-file",
> +                    action = "store", type = "string",
> +                    dest = "logFile", metavar = "FILE",
> +                    help = "file to which strucuted messages are written")
> +    defaults["structuredLogFile"] = ""

If we do have the option of disabling structured logging, we should raise an error if this is specified but structured logging was disabled.

@@ +314,5 @@
>  
>      options.profilePath = mochitest.getFullPath(options.profilePath)
>  
> +    options.structuredLogFile = options.structuredLogFile or \
> +                                os.path.join(options.profilePath, "mochitest.log")

I'd rather not use profilePath here as that is often just a temporary directory. It should be somewhere in SCRIPT_DIR. Though I think "mochitest.log" is already used for the normal log file so you might want to put "structured" in there or something.

@@ +829,5 @@
> +        obj = json.loads(line)
> +        if u'action' in obj:
> +          if obj[u'action'] == u'test_summary':
> +            print "passCount: %d\nfailCount: %d\ntodoCount: %d\n" % \
> +              (obj[u'passCount'], obj[u'failCount'], obj[u'todoCount'])

I don't think there's any need to coerce these string literals to unicode. It's more if we have externally specified strings that we need to worry about it.

Comment 4

[William Lachance (:wlach)]

Comment on attachment 768424 [details] [diff] [review]
Add ability for mochitest plain to log structured messages to a file;

This all looks pretty reasonable to me, though I'm not much of an expert on javascript style. I don't have any comments but what ahal already pointed out.

Comment 5

[(not currently active) Ted Mielczarek]

Comment on attachment 768424 [details] [diff] [review]
Add ability for mochitest plain to log structured messages to a file;

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

Ideally we'll probably want to stream the structured log data to stdout so that we could replace all of the current log-parsing-interpretation junk in runtests.py with a simpler "read a structured log message" setup.

::: testing/mochitest/runtests.py
@@ +83,5 @@
> +                    action = "store", type = "string",
> +                    dest = "logFile", metavar = "FILE",
> +                    help = "file to which strucuted messages are written")
> +    defaults["structuredLogFile"] = ""
> +

I don't think these should be separate options. You should just have --structured-log-file, and specifying it will indicate that structured logging is enabled.

Comment 6

[Gregory Szorc [:gps]]

Comment on attachment 768424 [details] [diff] [review]
Add ability for mochitest plain to log structured messages to a file;

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

::: services/common/log4moz.js
@@ +382,5 @@
>      if (!output.message) {
>        output.message = logMessage.message;
>      }
>  
> +    return JSON.stringify(output) + "\n";

This may break some things.

@@ +433,5 @@
>  DumpAppender.prototype = {
>    __proto__: Appender.prototype,
>  
>    doAppend: function DApp_doAppend(message) {
> +    dump(message + "\n");

This may also do weirdness.

::: testing/mochitest/runtests.py
@@ +16,5 @@
>  import time
> +try:
> +  import json
> +except ImportError:
> +  import simplejson as json

Do we seriously not have json available everywhere? simplejson is an artifact of the dark ages before python 2.6 (which added the json module to the core). Unless you are living in the dark ages (like Talos), don't even reference simplejson.

::: testing/mochitest/tests/SimpleTest/SimpleTest.js
@@ +307,3 @@
>          }
>      } else if (typeof dump === "function") {
> +        dump(test.message + "\n");

OK, now I'm starting to ask why you need to add \n everywhere and why this is seemingly OK everywhere else.

::: testing/mochitest/tests/SimpleTest/TestRunner.js
@@ +335,5 @@
>          {
>            // No |$('testframe').contentWindow|, so manually update: ...
>            // ... the log,
> +          TestRunner.error("TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | No checks actually run.",
> +                          {action: "test_fail"});

Should probably be "test_fail_no_checks" or {action: "test_fail", fail_reason: "no_tests"} or similar.

Comment 7

[Chris Manchester (limited bugmail, email directly)]

Attachment: Expose an optional generic output processor in automation.py;

The idea behind this patch is to decouple the "respond to failure or timeout"
behaviour from the "parse and report output" in automation.py, so that parsing
and reporting can be updated for structured logging.

This output processor doesn't offer any behavior in addition to automation.py,
but if it seems like this is going in the right direction, this would be the
place we do things like parse a structured message, reconcile timestamps between
log sources, and write to a file or other consumer of test output.

Something along these lines would also allow for more generic output processors
to be defined in someplace like moztest, so our various harnesses could take
advantage of shared behavior.

Comment 8

[Jonathan Griffin (:jgriffin)]

Note that we'll "soon" be replacing this code in automation.py with mozprocess/mozrunner.  To make that effort smoother, can you add a couple of comments to your patch that describe what they're doing and why?

Comment 9

[Chris Manchester (limited bugmail, email directly)]

(In reply to Jonathan Griffin (:jgriffin) from comment #8)
> Note that we'll "soon" be replacing this code in automation.py with
> mozprocess/mozrunner.  To make that effort smoother, can you add a couple of
> comments to your patch that describe what they're doing and why?

Absolutely. I will add detailed comments in the next iteration of the patch.

Comment 10

[Chris Manchester (limited bugmail, email directly)]

Attachment: Part 1 - Expose an optional generic output processor in automation.py;

Unbitrotted.

Comment 11

[Chris Manchester (limited bugmail, email directly)]

Attachment: Part 2 - Add ability for mochitest plain to output structured messages;

This will apply on top of the patch marked part 1. This makes the js side of mochitests
output structured messages, which are then consumed by the output processor. The end
result of this patch is console output compatible with the current behavior, however
outputting these messages to a file or other resource would be a matter of attaching
an appender/formatter combination to the logger in runtests.py that understands
structured messages.

Comment 12

[Gregory Szorc [:gps]]

Comment on attachment 784100 [details] [diff] [review]
Part 1 - Expose an optional generic output processor in automation.py;

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

I like what you are trying to do - decouple the processing of results so we can have pluggable reporters - but I don't like the implementation.

Invoking a function with other functions as arguments (onTestStart, etc) feels very hacky to me. At the point your processing function accepts so many arguments corresponding to events, I think you might as well just codify the interface with a class.

Furthermore, I have literally no clue why this logic is in automation.py. It seems like the kind of thing that should belong squarely in the test harness or a shared module (is automation.py that module?). Ted can provide more context on this front.

Comment 13

[Chris Manchester (limited bugmail, email directly)]

(In reply to Gregory Szorc [:gps] from comment #12)
> Comment on attachment 784100 [details] [diff] [review]
> Part 1 - Expose an optional generic output processor in automation.py;
> 
> Review of attachment 784100 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> I like what you are trying to do - decouple the processing of results so we
> can have pluggable reporters - but I don't like the implementation.
> 
> Invoking a function with other functions as arguments (onTestStart, etc)
> feels very hacky to me. At the point your processing function accepts so
> many arguments corresponding to events, I think you might as well just
> codify the interface with a class.
> 

Yes. It is a hack. I will come up with something that's more flexible. I think it will still need to involve callbacks in some way (see below), but I will find a way to make it more flexible in the events it specifies, and less cumbersome wrt the number of arguments it passes around.

> Furthermore, I have literally no clue why this logic is in automation.py. It
> seems like the kind of thing that should belong squarely in the test harness
> or a shared module (is automation.py that module?). Ted can provide more
> context on this front.

As jgriffin noted, there are plans to move this to mozbase "soon". Mozprocess has a notion of output handlers that get called on each line of output: https://github.com/mozilla/mozbase/blob/3fdd9dae906d8b6602c3190af965f1fae661c8d1/mozprocess/mozprocess/processhandler.py#L659 . An "output processor" will ideally be such a handler, whose purpose is to let the test runner (and ultimately any interested party) specify actions to be taken by the runner in response to particular output. Because these actions interact with the test runner internals, callbacks seem like a natural solution.

A bit odd now that I'm thinking about it is that if we maintain behavior similar to that of automation.py, the test runner's handler is special, because on of its callbacks might need to hijack the flow of execution, kill the process, and end the test run. This will have to be done gracefully in the presence of multiple handlers.

I'm open to feedback on other ways to solve this if it seems like I'm overlooking a simpler solution.

Comment 14

[Chris Manchester (limited bugmail, email directly)]

Attachment: Expose an optional generic output processor in automation.py;

This version keeps callbacks in a dict, so we can extend the set of events or
make some optional as future applications dictate. The OutputProcessor is
callable, so this will be able to be registered as a handler in mozprocess.

Comment 15

[Gregory Szorc [:gps]]

Comment on attachment 789702 [details] [diff] [review]
Expose an optional generic output processor in automation.py;

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

I think this patch is squarely in the land of automation voodoo and my comments risk stemming from ignorance.

::: build/automation.py.in
@@ +692,5 @@
>        #TODO: kill the process such that it triggers Breakpad on OS X (bug 525296)
>      self.log.info("Can't trigger Breakpad, just killing process")
>      self.killPid(processPID)
>  
> +  def waitForFinish(self, proc, utilityPath, timeout, maxTime, startTime, debuggerInfo, symbolsPath, ProcessorClass):

processorClass

Comment 16

[Chris Manchester (limited bugmail, email directly)]

Because this impacts reftests as well, I filed bug 907270 for allowing another way to parse output coming from a process managed by automation.py

Comment 17

[Chris Manchester (limited bugmail, email directly)]

Attachment: Add ability for mochitest plain to output structured messages;

This is a version of structured output for mochitests that applies on top of
the output parser in bug 907270.

Comment 18

[Chris Manchester (limited bugmail, email directly)]

Attachment: Add ability for mochitest plain to output structured messages;

Unbitrot with respect to bug 907270.

Comment 19

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

I recently started working on this bug to integrate structured logs in mochitest.

Almost all log messages are now structured, but to keep backward compatibility they are being converted back into a (hopefully) "TBPL compliant" formating, using a formatter built by jgraham.

WIP obviously, and feedback greatly appreciated.

Comment 20

[Andrew Halberstadt [:ahal]]

Here's a simple try push just to see what happens:
https://tbpl.mozilla.org/?tree=Try&rev=40ab6e064db0

Comment 21

[Andrew Halberstadt [:ahal]]

Another try run with a fix from Ahmed:
https://tbpl.mozilla.org/?tree=Try&rev=07556aff17a4

Comment 22

[Andrew Halberstadt [:ahal]]

Oops, that last one had a typo:
https://tbpl.mozilla.org/?tree=Try&rev=3bccaf5d3924

Comment 23

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

Fixed missing suiteStart, ignored tests logging "null" and hopefully fixed formatting of suite end stats (number of passed, failed and todos).

Comment 24

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

Many fixes, implemented the structured logging in the B2G runner and the browser tests (missing the suite start / suite end messages though, but that's not an issue right now).

The patch seems to pass all tests (the only oranges are known intermittent failures). Here's a try push with different platforms/chunks:

https://tbpl.mozilla.org/?tree=Try&rev=e48bc7f00d13

Comment 25

[Andrew Halberstadt [:ahal]]

Woohoo, that's awesome! It looks like that mochitest-3 failing test might be a problem, unless it got landed on m-c right before you pushed? I'd like to see a try run with "-p all -u mochitests" too.

Anyway, nice work, this makes me really happy. Feel free to flag me for review when you have a patch that is ready.

Comment 26

[James Graham [:jgraham]]

So, we probably need to make some changes to the mozharness side so that the structured logging data is actually available as a blobber download. That should be pretty straightforward; web-platform-tests already does it. Then the data is available for offline analysis, and can be used in e.g. treeherder.

But yes, this looks like great progress.

Comment 27

[Andrew Halberstadt [:ahal]]

Yep, that part should be easy. We just need to save the structured log to a file in addition to dumping the formatted version to stdout.

Comment 28

[Ahmed Kachkach [:akachkach]]

Here's a try push with more platforms:
https://tbpl.mozilla.org/?tree=Try&rev=865609f435d7

ahal was actually right, that particular test does some regex magic on the log messages which caused it to fail consistently.

I also need to fix android support ("build/mobile/remoteautomation.py")

Comment 29

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

A couple fixes + some work on the Android automation (remoteautomation.py and runtestsremote.py). Tests should be passing now, except for Android (still timing-out because the logs aren't dumped).

Comment 30

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

Fixed a couple bugs (thanks chmanchester!), merged with some changes that landed recently (in runtests.py). Also fixed some of the android part to handle multiline logs. (but the tests are still failing!)

Comment 31

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

Try push: https://tbpl.mozilla.org/php/getParsedLog.php?id=41166333&tree=Try&full=1

Finally getting some green with Android! Time-outs were caused by bypassing LogController for the structured logging. Also solves the bug caused by using LogController with bc tests.

Still have to solve a problem with android logging: it seems like the test_status messages of a particular test ("/tests/content/base/test/test_bug416317-1.html") are displayed directly. The first message (and most of the following ones) is actually split on two lines, which cause it to be incorrectly interpreted as an info message.

Comment 32

[Ahmed Kachkach [:akachkach]]

Woops, correct link for the try push: https://tbpl.mozilla.org/?rev=0d6b42193ca3&tree=Try

Comment 33

[Andrew Halberstadt [:ahal]]

CC'ing :froydnj

Nathan, in this bug Ahmed is getting the mochitest JS harness to log raw structured (json) logs instead of the classic tbpl format. This will make it easier for various tools to consume test result data. Because some tools may care about subtest results, we want to move your subtest hiding algorithm over to the python side so the full raw logs are available. The python side will take the raw data and format it back into the classic tbpl format for human consumption.

This is just a heads up, we'll flag you for review on those particular bits when the patch is ready.

Comment 34

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

Better messages buffering (when the "--quiet" commandline argument is supplied. still have to work on deactivating it from the JS side). Also converted "testharnessreport.js" (imptests) to structured logging. Now using the "StructuredLogger" class. All/most logs generated on the Python side should also be structured now (replaced the regular loggers by structured loggers). A couple bugfixes / modified tests too.

Should still have some bugs where JSON messages are dumped inside a line of raw logs (will have to investigate that)

Try push: https://tbpl.mozilla.org/?tree=Try&rev=5bd974066fc5

Comment 35

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8438994 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

::: build/mobile/remoteautomation.py
@@ +302,4 @@
>                      break
>  
>              # Flush anything added to stdout during the sleep
> +            self.stdout

I don't know exactly how this works, but aren't you losing these messages now?

::: content/base/test/test_fileapi.html
@@ +145,4 @@
>  
>  // Test loading an empty file works (and doesn't crash!)
>  var emptyFile = createFileWithData("");
> +dump("hello nurse\n");

Like we talked about, don't think this is going to be sufficient.

::: testing/mochitest/runtests.py
@@ +97,5 @@
> +        line = line.rstrip().decode("UTF-8", "ignore")
> +        try:
> +            message = json.loads(line)
> +            if message is None or not isinstance(message, dict) or not 'action' in message:
> +                # TODO: Output an error message?

In what cases is this path executed?

@@ +1602,2 @@
>      else:
> +      log.info("TEST-UNEXPECTED-FAIL | %s | application timed out after %d seconds with no output" % (self.lastTestSeen, int(timeout)))

Time for a "test_end" action, status='TIMEOUT'?

@@ +1700,4 @@
>          self.stackFixerProcess.communicate()
>          status = self.stackFixerProcess.returncode
>          if status and not didTimeout:
> +          log.info("TEST-UNEXPECTED-FAIL | runtests.py | Stack fixer process exited with code %d during test run" % status)

Hmm. May be time to extend out output format for errors in the harness that don't come directly from a test? We don't want to stay tied to "TEST-UNEXPECTED-FAIL".

Comment 36

[Ahmed Kachkach [:akachkach]]

(In reply to Chris Manchester [:chmanchester] from comment #35)
> Comment on attachment 8438994 [details] [diff] [review]
> 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch
> 
> Review of attachment 8438994 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: build/mobile/remoteautomation.py
> @@ +302,4 @@
> >                      break
> >  
> >              # Flush anything added to stdout during the sleep
> > +            self.stdout
> 
> I don't know exactly how this works, but aren't you losing these messages
> now?
> 

stdout is a property that used to return a string, and instead of doing "print self.stdout" now calling stdout just passes the content read from the file (if any) to the MessageLogger and it takes care of getting it displayed.

> ::: content/base/test/test_fileapi.html
> @@ +145,4 @@
> >  
> >  // Test loading an empty file works (and doesn't crash!)
> >  var emptyFile = createFileWithData("");
> > +dump("hello nurse\n");
> 
> Like we talked about, don't think this is going to be sufficient.
> 

I'm currently running a couple tests to see how many remaining messages we still have, trying to pinpoint what causes that. I'm already pretty sure most of the Android bugs are caused by something else (encoding/escaping problems when writing to the log files from the JS side).

> ::: testing/mochitest/runtests.py
> @@ +97,5 @@
> > +        line = line.rstrip().decode("UTF-8", "ignore")
> > +        try:
> > +            message = json.loads(line)
> > +            if message is None or not isinstance(message, dict) or not 'action' in message:
> > +                # TODO: Output an error message?
> 
> In what cases is this path executed?
>

So, for some reason, some tests dump a big number of "null" that the first test would ignore. Also, sometimes a test can dump valid JSON that isn't a structured message (looking at the action field is a first way to verify this, but maybe I should do a full test checking if the action is a valid one).

> @@ +1602,2 @@
> >      else:
> > +      log.info("TEST-UNEXPECTED-FAIL | %s | application timed out after %d seconds with no output" % (self.lastTestSeen, int(timeout)))
> 
> Time for a "test_end" action, status='TIMEOUT'?

Yes, I'm probably still missing a couple of special-case Python side test failures.
 
> @@ +1700,4 @@
> >          self.stackFixerProcess.communicate()
> >          status = self.stackFixerProcess.returncode
> >          if status and not didTimeout:
> > +          log.info("TEST-UNEXPECTED-FAIL | runtests.py | Stack fixer process exited with code %d during test run" % status)
> 
> Hmm. May be time to extend out output format for errors in the harness that
> don't come directly from a test? We don't want to stay tied to
> "TEST-UNEXPECTED-FAIL".

Yes, there are a couple of TEST-UNEXPECTED-FAIL logs that we should make structured. I could've used testEnd with runtests.py as the test, but that would crash the formatter and wouldn't make a lot of sense.

Maybe we should have a failure message (that our formatter would also log as TEST-UNEXPECTED-FAIL) but that can be linked to any element (usually a filename).

Comment 37

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

Fixed some of the points raised by :chmanchester. Still have to make the "TEST-UNEXPECTED-FAIL" messages structured (by adding a new action).

Comment 38

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

Had to change the MozillaFileLogger class to use a UTF8 "convertor" (nsIConverterOutputStream). The logs were just dumped as bytes which caused many problems with non-ASCII characters, but we probably didn't notice that because they were just dumped without any parsing (which isn't the case now that we use JSON).

Doing seem to have solved all "unparsable logs" bugs we had.

A couple things we're missing now: 

* Making sure the "buffering"'s behavior is the same as the JS version. I buffer all INFO messages where the old version didn't do this I believe, but it's really easy to modify this behavior (see the write function of the MessageLogger class in "runtests.py"). I already integrated the "quiet" parameter (the buffering is only done when --quiet is passed).
We'll also have to find a way to deactivate the buffering from the JS side, probably send a structured "info" log with a certain message ("buffering-off"?). Even if it seems "dirty", this feature doesn't deserve a specific action.

Another bug: I currently deactivate the buffering and print all the buffer messages when receiving a "suite_end". This usually works, but the problem is some imported tests will make us print "SUITE-END" twice (example: https://tbpl.mozilla.org/php/getParsedLog.php?id=41834103&tree=Try&full=1, search for SUITE-END). I wonder if this behavior is OK (printing two SUITE-START/SUITE-END in the same run) and so I should find another way to dump the last buffered messages or if I'd rather try to avoid this behavior.

* Taking commandline arguments into account to dump the structured logs to a file. (?)

Try push: https://tbpl.mozilla.org/?tree=Try&rev=4b04365a702b

Comment 39

[Nathan Froyd [:froydnj]]

Comment on attachment 8441095 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

Thanks for this work!  I've not had much contact with you, so I'm unfamiliar with how you work, how you work with your team, experience level, etc. etc., so apologies if you have heard this before.  If this is just how things are with your team, then please accept my comments as an outsider.

This is a pretty big patch; I think it would have been easier to review separated into several parts:

1. All the changes to dump() to add newlines.
2. All the whitespace changes, ;-additions, etc.  Maybe include the "delete useless Python imports" in here too.
3. All the changes to log calls to use %-formatting instead of *rest args.
4. Everything else (and maybe those could be split into multiple changes too).

The advantage is that the first three patches can be skim-checked for correctness, and then real thought can be put into part 4 for whether those changes are good.  Also easier to see what's going on with parts 1-3 out of the way.

I've mostly commented on small-scale things; I'll leave the big-picture stuff for the testing experts.

::: build/automationutils.py
@@ -78,4 @@
>    # semi-deliberately leaked, so we set '--show-possibly-lost=no' to avoid
>    # uninteresting output from those objects. We set '--smc-check==all-non-file'
>    # and '--vex-iropt-register-updates=allregs-at-mem-access' so that valgrind
> -  # deals properly with JIT'd JavaScript code.  

You may want to configure your editor to not trim whitespace like this and/or do whitespace fixups in a separate patch.

::: build/mobile/remoteautomation.py
@@ +301,4 @@
>                      break
>  
>              # Flush anything added to stdout during the sleep
> +            self.stdout

This seems too magical; maybe the guts of stdout() could be moved to a flushStdout function and that be called from both here and stdout()?

::: dom/imptests/testharnessreport.js
@@ +139,5 @@
>      if (this.runner) {
> +        // Structured logging
> +        var resultData = this.runner.stLogger.getStatusAndExpected(resultString);
> +        var status = resultData.status;
> +        var expected = resultData.expected;

You might just do:

var { status, expected } = ...getStatusAndExpected(...);

or whatever the destructuring syntax is.  Here and elsewhere for getStatusAndExpected.

@@ +144,5 @@
> +        this.runner.stLogger.testStatus(url, // test
> +                                        test.message, // subtest
> +                                        status, // status
> +                                        expected, // expected
> +                                        message // message

We have these comments on every call to testStatus; maybe it would be better to have testStatus take an object:

...testStatus({ test: url, subtest: test.message, status: status ... });

So things are named for us?

::: dom/inputmethod/mochitest/test_bug944397.html
@@ +23,4 @@
>  function appFrameScript() {
>    let input = content.document.getElementById('test-input');
>    input.oninput = function() {
> +    dump('oninput was called in file_test_app.html.\n');

I see that you are changing dump() calls to end with newlines; are un-newline'd dump calls going to cause problems with this scheme further down the line (some unwary developer adding them, perhaps)?

::: testing/mochitest/runtests.py
@@ +130,5 @@
> +        # test_status messages buffering
> +        if is_error:
> +            if self.buffered_messages:
> +                self.logger.info("TEST-INFO | dumping last {} message(s)".format(len(self.buffered_messages)))
> +                self.logger.info("TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test")

This message seems wrong now that we moved buffering into Python: SimpleTest.requestCompleteLog sets flags for JavaScript and has nothing to do with the Python harness.

requestCompleteLog was also unchanged in this patch, AFAICS, which seems incorrect.  And since requestCompleteLog no longer works, we have a regression--though I'm really not sure what you'd do beyond adding a 'really_output' field or somesuch to the messages, which seems inelegant.

::: testing/mochitest/tests/SimpleTest/TestRunner.js
@@ +150,5 @@
> +    /* log action: human readable logs */
> +
> +    this.log = function(level, message) {
> +        var data = {level: level, message: message};
> +        this.logData('log', data);

Should |log| and |logData| really be exposed on |this|?  Maybe they should just be internal functions.

@@ +195,5 @@
> +
> +        this.dumpMessage(allData);
> +    };
> +
> +    this.dumpMessage = function(message) {

Should this be exposed on |this|?

@@ +230,5 @@
> +        }
> +        else if (testResult == "TEST-PASS") {
> +            status = 'PASS';
> +            expected = 'PASS';
> +        }

Throw an error here for an unexpected testResult?

::: testing/mozbase/mozlog/mozlog/structured/formatters/machformatter.py
@@ +170,4 @@
>  
>          return result
>  
> +

Nit: extra line.

::: testing/specialpowers/content/MozillaLogger.js
@@ +116,3 @@
>    close : function() {
> +    if (this._converter) {
> +      this._converter.close();

Does this (a) flush any buffered data, and (b) close the wrapped file stream?

Comment 40

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8441095 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

suite_end should only be called once. If this is hard to enforce in javascript I would might advocate putting the suite_end call in python.

You'll want to hook into the option parser here: http://mxr.mozilla.org/mozilla-central/source/testing/mochitest/runtests.py#1767 and in the corresponding place in the remote harness. http://mozbase.readthedocs.org/en/latest/mozlog_structured.html#integration-with-argparse has an example of how to do this with argparse. It also works with optparse now, see my patch in bug 956739 for another example.

::: testing/mochitest/runtests.py
@@ +76,5 @@
> +class MochitestStructuredLogger(StructuredLogger):
> +    def __init__(self, *args, **kwargs):
> +        super(MochitestStructuredLogger, self).__init__(*args, **kwargs)
> +        stream_handler = StreamHandler(stream=sys.stdout, formatter=MochitestFormatter())
> +        self.add_handler(stream_handler)

Is a subclass really necessary here? Why not just add the handler after object creation?

Comment 41

[Ahmed Kachkach [:akachkach]]

(In reply to Nathan Froyd (:froydnj) from comment #39)
> Comment on attachment 8441095 [details] [diff] [review]
> 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch
> 
> Review of attachment 8441095 [details] [diff] [review]:
> -----------------------------------------------------------------
> 

> 
> This is a pretty big patch; I think it would have been easier to review
> separated into several parts:
> 

I agree, that would probably make things easier.

Not sure the changes to log calls (using %-formatting) should be in a separate patch, because this is specifically done for this patch (because we use a log function that doesn't support the other style of logging) and wouldn't make sense alone.

> 
> I've mostly commented on small-scale things; I'll leave the big-picture
> stuff for the testing experts.
> 
> ::: build/automationutils.py
> @@ -78,4 @@
> >    # semi-deliberately leaked, so we set '--show-possibly-lost=no' to avoid
> >    # uninteresting output from those objects. We set '--smc-check==all-non-file'
> >    # and '--vex-iropt-register-updates=allregs-at-mem-access' so that valgrind
> > -  # deals properly with JIT'd JavaScript code.  
> 
> You may want to configure your editor to not trim whitespace like this
> and/or do whitespace fixups in a separate patch.
> 

Yeah, my text-editor has been a bit zealous. I think it's still nice to get rid of them, probably in a separate patch.

> ::: build/mobile/remoteautomation.py
> @@ +301,4 @@
> >                      break
> >  
> >              # Flush anything added to stdout during the sleep
> > +            self.stdout
> 
> This seems too magical; maybe the guts of stdout() could be moved to a
> flushStdout function and that be called from both here and stdout()?
> 

I just changed "print self.stdout" to "self.stdout" here, and I'm not sure exactly how that function "flushes anything added to stdout during the sleep", so better leave it that way.
I think the best thing to do here would be to rename `stdout` to `read_stdout` and make it a normal function, not a property. (it does a lot of stuff and has side effects)

> ::: dom/imptests/testharnessreport.js
> @@ +139,5 @@
> >      if (this.runner) {
> > +        // Structured logging
> > +        var resultData = this.runner.stLogger.getStatusAndExpected(resultString);
> > +        var status = resultData.status;
> > +        var expected = resultData.expected;
> 
> You might just do:
> 
> var { status, expected } = ...getStatusAndExpected(...);
> 
> or whatever the destructuring syntax is.  Here and elsewhere for
> getStatusAndExpected.
> 

Thanks, didn't know about this syntax. Will try to use it in this case.

> @@ +144,5 @@
> > +        this.runner.stLogger.testStatus(url, // test
> > +                                        test.message, // subtest
> > +                                        status, // status
> > +                                        expected, // expected
> > +                                        message // message
> 
> We have these comments on every call to testStatus; maybe it would be better
> to have testStatus take an object:
> 
> ...testStatus({ test: url, subtest: test.message, status: status ... });
> 
> So things are named for us?
> 

Mmh, that would avoid having comments all over, but it may also be nice to keep the same API as the Python lib (StructuredLogger is just a JS version of our StructuredLogger Python API). Unfortunately javascript doesn't have keyword arguments!

> ::: dom/inputmethod/mochitest/test_bug944397.html
> @@ +23,4 @@
> >  function appFrameScript() {
> >    let input = content.document.getElementById('test-input');
> >    input.oninput = function() {
> > +    dump('oninput was called in file_test_app.html.\n');
> 
> I see that you are changing dump() calls to end with newlines; are
> un-newline'd dump calls going to cause problems with this scheme further
> down the line (some unwary developer adding them, perhaps)?
> 

Yes, but that's alreayd an issue now. If you go to TBPL logs, and look for "hello nurse", you'll find something like "INFO 511 hello nurseINFO 512 TEST-INFO....". It didn't cause any bugs only because the output was unstructured and the regexes didn't match for line beginning/end. I think we should enforce adding new lines when using "dump".
People writing tests should use the dedicated functions to output log messages, and there's no magical way to always have one message per line.

> ::: testing/mochitest/runtests.py
> @@ +130,5 @@
> > +        # test_status messages buffering
> > +        if is_error:
> > +            if self.buffered_messages:
> > +                self.logger.info("TEST-INFO | dumping last {} message(s)".format(len(self.buffered_messages)))
> > +                self.logger.info("TEST-INFO | if you need more context, please use SimpleTest.requestCompleteLog() in your test")
> 
> This message seems wrong now that we moved buffering into Python:
> SimpleTest.requestCompleteLog sets flags for JavaScript and has nothing to
> do with the Python harness.
> 
> requestCompleteLog was also unchanged in this patch, AFAICS, which seems
> incorrect.  And since requestCompleteLog no longer works, we have a
> regression--though I'm really not sure what you'd do beyond adding a
> 'really_output' field or somesuch to the messages, which seems inelegant.
> 

Yes, we have to fix that. That's what I was refering to in my message as "deactivating the buffering from the JS side". Probably by sending a special log message.

> ::: testing/mochitest/tests/SimpleTest/TestRunner.js
> @@ +150,5 @@
> > +    /* log action: human readable logs */
> > +
> > +    this.log = function(level, message) {
> > +        var data = {level: level, message: message};
> > +        this.logData('log', data);
> 
> Should |log| and |logData| really be exposed on |this|?  Maybe they should
> just be internal functions.
> 
> @@ +195,5 @@
> > +
> > +        this.dumpMessage(allData);
> > +    };
> > +
> > +    this.dumpMessage = function(message) {
> 
> Should this be exposed on |this|?
> 

You're right, they shouldn't! Fixed.
(dumpMessage is actually used by a single test, for "bypassing" log messages, but I guess it's still OK to make it an internal function because it shouldn't be used except for a special case like this one)

> @@ +230,5 @@
> > +        }
> > +        else if (testResult == "TEST-PASS") {
> > +            status = 'PASS';
> > +            expected = 'PASS';
> > +        }
> 
> Throw an error here for an unexpected testResult?
> 

I think testResult can also be TEST-INFO or similar strings, in that case they are just interpreted as "raw" logs, no need to output an error message. 

> ::: testing/mozbase/mozlog/mozlog/structured/formatters/machformatter.py
> @@ +170,4 @@
> >  
> >          return result
> >  
> > +
> 
> Nit: extra line.
> 

Fixed.

> ::: testing/specialpowers/content/MozillaLogger.js
> @@ +116,3 @@
> >    close : function() {
> > +    if (this._converter) {
> > +      this._converter.close();
> 
> Does this (a) flush any buffered data, and (b) close the wrapped file stream?

a) Mmh, so I used this based on this snippet:

https://developer.mozilla.org/en-US/Add-ons/Code_snippets/File_I_O#Writing_a_File

They don't do any flushing before closing the file, but when I read the source:
http://dxr.mozilla.org/mozilla-central/source/xpcom/io/nsIUnicharOutputStream.idl?from=nsIUnicharOutputStream.idl#1
The close method doesn't mention any flushing, so I'll try to use flush before closing to make sure it's done.

b) Yes it does close the wrapped file stream. (see source)

Comment 42

[Ahmed Kachkach [:akachkach]]

(In reply to Chris Manchester [:chmanchester] from comment #40)
> Comment on attachment 8441095 [details] [diff] [review]
> 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch
> 
> Review of attachment 8441095 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> suite_end should only be called once. If this is hard to enforce in
> javascript I would might advocate putting the suite_end call in python.
> 

This will make a couple things a bit harder (since test runner manage tests in different ways) but it might be the only viable solution.

> You'll want to hook into the option parser here:
> http://mxr.mozilla.org/mozilla-central/source/testing/mochitest/runtests.
> py#1767 and in the corresponding place in the remote harness.
> http://mozbase.readthedocs.org/en/latest/mozlog_structured.html#integration-
> with-argparse has an example of how to do this with argparse. It also works
> with optparse now, see my patch in bug 956739 for another example.
> 

Great! Hopefully the tegra boards won't mind importing commandliune now.

> ::: testing/mochitest/runtests.py
> @@ +76,5 @@
> > +class MochitestStructuredLogger(StructuredLogger):
> > +    def __init__(self, *args, **kwargs):
> > +        super(MochitestStructuredLogger, self).__init__(*args, **kwargs)
> > +        stream_handler = StreamHandler(stream=sys.stdout, formatter=MochitestFormatter())
> > +        self.add_handler(stream_handler)
> 
> Is a subclass really necessary here? Why not just add the handler after
> object creation?

Different mochitest test runners (runtests.py, runtestsb2g.py, remoteautomation.py) use the same type of logger, so I figured having a class would make it easier to use / modify.

Comment 43

[:Ms2ger (he/him; ⌚ UTC+1/+2)]

Comment on attachment 8441095 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

::: dom/imptests/testharnessreport.js
@@ +139,2 @@
>      if (this.runner) {
> +        // Structured logging

This file uses two-space indentation.

Comment 44

[Nathan Froyd [:froydnj]]

(In reply to Ahmed Kachkach [:akachkach] from comment #41)
> (In reply to Nathan Froyd (:froydnj) from comment #39)
> > This is a pretty big patch; I think it would have been easier to review
> > separated into several parts:
> 
> I agree, that would probably make things easier.
> 
> Not sure the changes to log calls (using %-formatting) should be in a
> separate patch, because this is specifically done for this patch (because we
> use a log function that doesn't support the other style of logging) and
> wouldn't make sense alone.

You're right, the case is not as clear for that, because you'll be changing all the function calls anyway when you change the loggers around.  I still think it's valuable to do the formatting change separately, which may make it more obvious that just the function name is being changed in a later patch.  (And the later patch could even be split up for ease of review into "actual" changes and "renaming" changes, but folded for commit.  It's somewhat a matter of preference on the part of the patch author and the patch reviewer; I know we have a couple people who dislike things being split up.)

> > ::: build/mobile/remoteautomation.py
> > @@ +301,4 @@
> > >                      break
> > >  
> > >              # Flush anything added to stdout during the sleep
> > > +            self.stdout
> > 
> > This seems too magical; maybe the guts of stdout() could be moved to a
> > flushStdout function and that be called from both here and stdout()?
>
> I just changed "print self.stdout" to "self.stdout" here, and I'm not sure
> exactly how that function "flushes anything added to stdout during the
> sleep", so better leave it that way.
> I think the best thing to do here would be to rename `stdout` to
> `read_stdout` and make it a normal function, not a property. (it does a lot
> of stuff and has side effects)

A normal function call here would be even better!

> > We have these comments on every call to testStatus; maybe it would be better
> > to have testStatus take an object:
> > 
> > ...testStatus({ test: url, subtest: test.message, status: status ... });
> > 
> > So things are named for us?
> 
> Mmh, that would avoid having comments all over, but it may also be nice to
> keep the same API as the Python lib (StructuredLogger is just a JS version
> of our StructuredLogger Python API). Unfortunately javascript doesn't have
> keyword arguments!

The object-with-fields is the javascript-y way of doing keyword arguments.  It makes "parsing" the "keyword" arguments on the callee side a little tedious, though.

> People writing tests should use the dedicated functions to output log
> messages, and there's no magical way to always have one message per line.

OK, great.

> (dumpMessage is actually used by a single test, for "bypassing" log
> messages, but I guess it's still OK to make it an internal function because
> it shouldn't be used except for a special case like this one)

Exposing it on |this|, but prefixing it with '_' is the way to go, then.
> > @@ +230,5 @@
> > > +        }
> > > +        else if (testResult == "TEST-PASS") {
> > > +            status = 'PASS';
> > > +            expected = 'PASS';
> > > +        }
> > 
> > Throw an error here for an unexpected testResult?
> 
> I think testResult can also be TEST-INFO or similar strings, in that case
> they are just interpreted as "raw" logs, no need to output an error message. 

Ah, OK.  Just so long as the callers are all prepared to handle that.

> > ::: testing/specialpowers/content/MozillaLogger.js
> > @@ +116,3 @@
> > >    close : function() {
> > > +    if (this._converter) {
> > > +      this._converter.close();
> > 
> > Does this (a) flush any buffered data, and (b) close the wrapped file stream?
> 
> a) Mmh, so I used this based on this snippet:
> b) Yes it does close the wrapped file stream. (see source)

Thanks for verifying!

Comment 45

[Chris Manchester (limited bugmail, email directly)]

> > ::: dom/inputmethod/mochitest/test_bug944397.html
> > @@ +23,4 @@
> > >  function appFrameScript() {
> > >    let input = content.document.getElementById('test-input');
> > >    input.oninput = function() {
> > > +    dump('oninput was called in file_test_app.html.\n');
> > 
> > I see that you are changing dump() calls to end with newlines; are
> > un-newline'd dump calls going to cause problems with this scheme further
> > down the line (some unwary developer adding them, perhaps)?
> > 
> 
> Yes, but that's alreayd an issue now. If you go to TBPL logs, and look for
> "hello nurse", you'll find something like "INFO 511 hello nurseINFO 512
> TEST-INFO....". It didn't cause any bugs only because the output was
> unstructured and the regexes didn't match for line beginning/end. I think we
> should enforce adding new lines when using "dump".
> People writing tests should use the dedicated functions to output log
> messages, and there's no magical way to always have one message per line.

I don't see that this has been adequately addressed. If our log parsing depends on every call to "dump" including a newline, than this really needs to be enforced systematically, because new test files may call dump, and as I understand it both those writing them and reviewing them may be unaware of the requirement that lines in the log be valid json. Is there something wrong with the "newline isolated" approach, putting a new line on either side of messages in the javascript logger just to delimit?

Comment 46

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

Fixed issues raised by :chmanchester, :froydnj and :Ms2ger.

Moved suite_start/suite_end to the Python side, adding new lines before all structured logs, added support for "requestCompleteLog" (sending a special message from the JS to the Python side), flushing the log file before closing it and code-style fixes (indentation, new line, etc.)

I had a discussion with :ahal and we decided that it might not be worth it to split this patch into multiple bugs now, but I'll definitely try to avoid the same situation with bugs in the future!

Also, it's probably better to land this asap, and do the commandline stuff later (seeing how the loggers are currently... in the global scope, it might be troublesome to initialize them when commandline arguments are parsed).

Try push:
https://tbpl.mozilla.org/?tree=Try&rev=ceea3b76e79b

@ahal: Any idea when bug 997244 will land so I can rebase this on top of it?

Comment 47

[James Graham [:jgraham]]

I will read the patch in more detail, but I don't immediately see why using the command line stuff is a problem. The fact that the logger is used as a global isn't a problem; just as soon as you get the logger out of the command line arguments you can set it as a global variable. It's also necessary to integrate with the mozharness changes that chmanchester has made.

I also don't see the need for the MochitestStructuredLog class. Subclassing just to set up the handlers seems unnecessary, especially since it's incompatible with the command line handling.

Comment 48

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8442439 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

Thanks Ahmed! Just a few nits below.

::: build/automationutils.py
@@ +602,4 @@
>    def process(self):
>      for test in self._parseLeakingTests():
>        for url, count in self._zipLeakedWindows(test["leakedWindows"]):
> +        self.logger("TEST-UNEXPECTED-FAIL | %s | leaked %d window(s) until shutdown [url = %s]" % (test["fileName"], count, url))

While we're here we could change this to pass in the logger itself and call .error, but I'm not acquainted with this file at all, and I guess this is fine for now.

::: build/mobile/remoteautomation.py
@@ +214,5 @@
>              # The benefit of the following sleep is unclear; it was formerly 15 seconds
>              time.sleep(1)
>  
> +            # Used to buffer log messages until we meet a line break
> +            self.logBuffer = str()

Just "" here?

::: dom/imptests/testharnessreport.js
@@ +144,5 @@
> +      this.runner.stLogger.testStatus(url, // test
> +                                      test.message, // subtest
> +                                      status, // status
> +                                      expected, // expected
> +                                      message // message

Just my 2c, but I would leave off these comments on the parameters everywhere.

::: dom/indexedDB/ipc/test_ipc.html
@@ +80,5 @@
> +
> +        let details = message.test + " | " + message.message;
> +        if (message.action == 'test_status') {
> +            let pass = message.expected === undefined;
> +            ok(pass, details);

You're staying faithful to the way it was, but looks like this should be:

ok(pass, message.test, message.message);

::: testing/mochitest/browser-test.js
@@ +158,4 @@
>      if (gConfig.repeat)
>        this.repeat = gConfig.repeat;
>  
> +    this.dumper.stLogger.info("*** Start BrowserChrome Test Results ***\n");

No newline, right?

@@ +254,4 @@
>        Services.obs.removeObserver(this, "chrome-document-global-created");
>        Services.obs.removeObserver(this, "content-document-global-created");
>        this.Promise.Debugging.clearUncaughtErrorObservers();
> +      this.dumper.stLogger.info("INFO TEST-START | Shutdown");

Leave off "INFO" and probably also "TEST-START".

::: testing/mochitest/runtests.py
@@ +680,5 @@
> +
> +    # suite_end message
> +    self.message_logger.logger.suite_end()
> +    self.message_logger.dump_buffered()
> +    self.message_logger.buffering = False

I think these belong somewhere up in Mochitest.runTests

@@ +1400,4 @@
>                     interactive=interactive,
>                     outputTimeout=timeout)
>        proc = runner.process_handler
> +      log.info("INFO | runtests.py | Application pid: %d" % proc.pid)

Don't add "INFO" here or elsewhere. Leave it to the formatter.

@@ +1735,4 @@
>          self.stackFixerProcess.communicate()
>          status = self.stackFixerProcess.returncode
>          if status and not didTimeout:
> +          log.info("TEST-UNEXPECTED-FAIL | runtests.py | Stack fixer process exited with code %d during test run" % status)

What I'm thinking for cases like these is we should log the message at the error level, but not include 'TEST-UNEXPECTED-FAIL' at all in the message. Then we can prepend 'TEST-UNEXPECTED-FAIL' in the TbplFormatter for things logged at this level, because it's what tbpl expects, and that's the purpose of the formatter.

::: testing/mochitest/runtestsb2g.py
@@ +3,4 @@
>  # You can obtain one at http://mozilla.org/MPL/2.0/.
>  
>  import json
> +import logging

Unused import.

::: testing/mochitest/runtestsremote.py
@@ +413,5 @@
>          fail_found = False
>          for line in data:
> +            try:
> +                message = json.loads(line)
> +                if message is None or not isinstance(message, dict) or not 'action' in message:

'message is None' implies 'not isinstance(message, dict)', you can leave out 'message is None'.

::: testing/mochitest/tests/SimpleTest/TestRunner.js
@@ +233,5 @@
> +            expected = 'PASS';
> +        }
> +
> +        return {status: status, expected: expected};
> +    };

Would it be possible to modify where these strings are created rather than implementing more log parsing here?

Comment 49

[Chris Manchester (limited bugmail, email directly)]

I also meant to mention that this patch changes the output of running the mach target for mochitests significantly, I would take a look at making mozlog.structured and mach play well together.

Comment 50

[Ahmed Kachkach [:akachkach]]

Comment on attachment 8442439 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

::: build/automationutils.py
@@ +602,4 @@
>    def process(self):
>      for test in self._parseLeakingTests():
>        for url, count in self._zipLeakedWindows(test["leakedWindows"]):
> +        self.logger("TEST-UNEXPECTED-FAIL | %s | leaked %d window(s) until shutdown [url = %s]" % (test["fileName"], count, url))

Mmh, also not familiar with this. Maybe we can fix this part later?

::: build/mobile/remoteautomation.py
@@ +214,5 @@
>              # The benefit of the following sleep is unclear; it was formerly 15 seconds
>              time.sleep(1)
>  
> +            # Used to buffer log messages until we meet a line break
> +            self.logBuffer = str()

Updated.

Is "" usually prefered to using the str constructor?

::: dom/indexedDB/ipc/test_ipc.html
@@ +80,5 @@
> +
> +        let details = message.test + " | " + message.message;
> +        if (message.action == 'test_status') {
> +            let pass = message.expected === undefined;
> +            ok(pass, details);

Updated.

::: testing/mochitest/browser-test.js
@@ +158,4 @@
>      if (gConfig.repeat)
>        this.repeat = gConfig.repeat;
>  
> +    this.dumper.stLogger.info("*** Start BrowserChrome Test Results ***\n");

Yup, removed.

@@ +254,4 @@
>        Services.obs.removeObserver(this, "chrome-document-global-created");
>        Services.obs.removeObserver(this, "content-document-global-created");
>        this.Promise.Debugging.clearUncaughtErrorObservers();
> +      this.dumper.stLogger.info("INFO TEST-START | Shutdown");

Removed INFO. I think we should still keep that "TEST-START". It doesn't make any sense but I remember seeing some regex using this.

::: testing/mochitest/runtests.py
@@ +1400,4 @@
>                     interactive=interactive,
>                     outputTimeout=timeout)
>        proc = runner.process_handler
> +      log.info("INFO | runtests.py | Application pid: %d" % proc.pid)

Fixed!

@@ +1735,4 @@
>          self.stackFixerProcess.communicate()
>          status = self.stackFixerProcess.returncode
>          if status and not didTimeout:
> +          log.info("TEST-UNEXPECTED-FAIL | runtests.py | Stack fixer process exited with code %d during test run" % status)

I also thought about doing this, but those messages are also generated by the JS side from parts that don't seem to have access to TestRunner (ex: manifestLibrary.js). But maybe we can still let those as is and transform those that we can?

::: testing/mochitest/runtestsb2g.py
@@ +3,4 @@
>  # You can obtain one at http://mozilla.org/MPL/2.0/.
>  
>  import json
> +import logging

Removed, thanks.

::: testing/mochitest/runtestsremote.py
@@ +413,5 @@
>          fail_found = False
>          for line in data:
> +            try:
> +                message = json.loads(line)
> +                if message is None or not isinstance(message, dict) or not 'action' in message:

Yes! Fixed this inside the MessageLogger class but forgot it here. Fixed now.

::: testing/mochitest/tests/SimpleTest/TestRunner.js
@@ +233,5 @@
> +            expected = 'PASS';
> +        }
> +
> +        return {status: status, expected: expected};
> +    };

I couldn't find where the test objects were populated with data at first, but after re-reading the parts of code that use this function, I could refactor them to give objects that have a "status" and "expected" field to avoid parsing the "result string" that was usually given! Yay for no string parsing :)

Will run a try push to see if it didn't break anything.

Comment 51

[James Graham [:jgraham]]

Comment on attachment 8442439 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

This looks like a great start, but I think there are still some rough edges to iron out.

::: build/automationutils.py
@@ +602,4 @@
>    def process(self):
>      for test in self._parseLeakingTests():
>        for url, count in self._zipLeakedWindows(test["leakedWindows"]):
> +        self.logger("TEST-UNEXPECTED-FAIL | %s | leaked %d window(s) until shutdown [url = %s]" % (test["fileName"], count, url))

Uh, why are we still writing TEST-UNEXPECTED-FOO directly? That just won't work with anything other than tbpl, which defeats the point of structured logging.

As far as I can tell this should be something like:

for test in self._parseLeakingTests():
    self.logger.test_start(test=some_test_id)
    for url, count in self._zipLeakedWindows(test["leakedWindows"]):
        self.logger.test_status(test=some_test_id, status="FAIL", subtest=url, message="Leaked %d windows until shutdown" % count)
    self.logger.test_end(test=some_test_id)

@@ +606,3 @@
>  
>        if test["leakedDocShells"]:
> +        self.logger("TEST-UNEXPECTED-FAIL | %s | leaked %d docShell(s) until shutdown" % (test["fileName"], len(test["leakedDocShells"])))

More unstructured logging

@@ +614,4 @@
>  
>      # log line has invalid format
>      if not pid or not serial:
> +      self.logger("TEST-UNEXPECTED-FAIL | ShutdownLeaks | failed to parse line <%s>" % line)

More unstructured logging

@@ +635,4 @@
>  
>      # log line has invalid format
>      if not pid or not id:
> +      self.logger("TEST-UNEXPECTED-FAIL | ShutdownLeaks | failed to parse line <%s>" % line)

More unstructured logging

::: build/mobile/remoteautomation.py
@@ +214,5 @@
>              # The benefit of the following sleep is unclear; it was formerly 15 seconds
>              time.sleep(1)
>  
> +            # Used to buffer log messages until we meet a line break
> +            self.logBuffer = str()

Yes

::: dom/imptests/testharnessreport.js
@@ +156,1 @@
>        dump(msg + "\n");

What's this unstructured codepath needed for?

::: testing/mochitest/runtests.py
@@ +68,5 @@
> +        self.log_num = 0
> +
> +    def __call__(self, data):
> +        tbpl_output = super(MochitestFormatter, self).__call__(data)
> +        output = u'{0} INFO {1}'.format(self.log_num, tbpl_output)

Should this be in mozlog, or is it really mochitest-specific?

Frankly it seems a little strange to partially number the log entries, so I wonder if this is the best way to solve whateer the use case is.

@@ +72,5 @@
> +        output = u'{0} INFO {1}'.format(self.log_num, tbpl_output)
> +        self.log_num += 1
> +        return output
> +
> +class MochitestStructuredLogger(StructuredLogger):

This is unnecessary

@@ +136,5 @@
> +        # test_status messages buffering
> +        if is_error:
> +            if self.buffered_messages:
> +                number_messages = min(self.BUFFERING_THRESHOLD, len(self.buffered_messages))
> +                self.logger.info("TEST-INFO | dumping last {0} message(s)".format(number_messages))

Is this TEST-INFO stuff important?

@@ +153,5 @@
> +    def flush(self):
> +        sys.stdout.flush()
> +
> +    def log_message(self, message):
> +        self.logger.log_raw(message)

This indirection seems a bit unnecessary

@@ +157,5 @@
> +        self.logger.log_raw(message)
> +
> +    def dump_buffered(self, limit=False):
> +        if limit:
> +            dumped_messages = self.buffered_messages[-self.BUFFERING_THRESHOLD:]

So, I'm confused. We seem to dump the last 100 messages, and then clear the buffer below. Won't this cause any earlier messages to simply be lost?

@@ +167,5 @@
> +        # Cleaning the list of buffered messages
> +        self.buffered_messages = []
> +
> +# Global logger
> +log = MochitestStructuredLogger('mochitest')

This should come from the command line arguments. You can have a function like:

log = None
def setup_logging(logger):
    global log
    log = logger

and call this as soon as you have the command line args.

@@ +759,4 @@
>  
>      # Call installChromeJar().
>      if not os.path.isdir(os.path.join(SCRIPT_DIR, self.jarDir)):
> +      log.error(message="TEST-UNEXPECTED-FAIL | invalid setup: missing mochikit extension")

Unstructured logging.

@@ +1136,4 @@
>      # TODO: this should really be upstreamed somewhere, maybe mozprofile
>      certificateStatus = self.fillCertificateDB(options)
>      if certificateStatus:
> +      log.error("TEST-UNEXPECTED-FAIL | runtests.py | Certificate integration failed")

Unstructured logging

@@ +1251,3 @@
>        if isPidAlive(processPID):
>          foundZombie = True
> +        log.info("TEST-UNEXPECTED-FAIL | zombiecheck | child process %d still alive after shutdown" % processPID)

More unstructured messages. Zombiecheck is a test and should be logged as such.

@@ +1428,4 @@
>  
>        # record post-test information
>        if status:
> +        log.test_end(test=self.lastTestSeen, status='FAIL', message="application terminated with exit code %s" % status)

Is that a FAIL or a CRASH? Also, are we sure that latest_test_seen won't already have a test_end message?

@@ +1735,4 @@
>          self.stackFixerProcess.communicate()
>          status = self.stackFixerProcess.returncode
>          if status and not didTimeout:
> +          log.info("TEST-UNEXPECTED-FAIL | runtests.py | Stack fixer process exited with code %d during test run" % status)

This is unstructured.

Why is the stackfixer being modelled as a test rather than as a thing that can run or fail, with the latter giving an error in the log i.e. why is there a TEST-* here at all?

@@ +1776,5 @@
> +        self.harness.lastTestSeen = message['test']
> +      return message
> +
> +    def dumpScreenOnTimeout(self, message):
> +      if not self.dump_screen_on_fail and self.dump_screen_on_timeout\

Prefer using () around multiline expressions than line continuation characters.

::: testing/mochitest/runtestsb2g.py
@@ +30,2 @@
>  
> +log = MochitestStructuredLogger('Mochitest')

This should be the command-line provided logger

::: testing/mochitest/runtestsremote.py
@@ +25,4 @@
>  import moznetwork
>  
>  SCRIPT_DIR = os.path.abspath(os.path.realpath(os.path.dirname(__file__)))
> +log = MochitestStructuredLogger('Mochi-Remote')

Command-line provided logger

@@ +487,4 @@
>          printed = 0
>          for name in self._dm.listFiles(screenShotDir):
>              fullName = screenShotDir + "/" + name
> +            log.info("SCREENSHOT: FOUND: [%s]" % fullName)

FWIW if we can associate this with at test, I think this should go in the extras on test_end or something. I believe that's what marionette does, and having some compat here would be good.

::: testing/mochitest/tests/SimpleTest/SimpleTest.js
@@ +357,3 @@
>          }
>  
> +        parentRunner.stLogger.testStatus(url, // test

I think someone else already mentioned that these comments aren't adding much.

::: testing/mochitest/tests/SimpleTest/TestRunner.js
@@ +531,5 @@
>          {
> +            // No |$('testframe').contentWindow|, so manually update: ...
> +            // ... the log,
> +            TestRunner.stLogger.testEnd('SimpleTest/TestRunner.js', // test
> +                                  'ERROR', // status

Indentation is weird

@@ +545,5 @@
>          }
>  
>          SpecialPowers.unregisterProcessCrashObservers();
>  
> +        TestRunner.stLogger.info("TEST-START | Shutdown");

This looks unstructured

@@ +568,4 @@
>          } else {
>            // Loops are finished
>            if (TestRunner.logEnabled) {
> +            TestRunner.stLogger.info("TEST-INFO | Ran " + TestRunner._currentLoop + " Loops");

Is TEST-INFO needed?

@@ +696,5 @@
>          var max = TestRunner._expectedMaxAsserts;
>          var min = TestRunner._expectedMinAsserts;
>          if (numAsserts > max) {
> +            TestRunner.stLogger.testEnd(url, // test
> +                                        'FAIL', // status

Weird mix of ' and " (also elsewhere)

@@ +706,4 @@
>              TestRunner.updateUI([{ result: false }]);
>          } else if (numAsserts < min) {
> +            TestRunner.stLogger.testEnd(url, // test
> +                                        'PASS', // status

This seems pretty weird.

test_end should either produce (OK, ERROR, TIMEOUT, CRASH) or (PASS, FAIL, ERROR, TIMEOUT, CRASH), depending on whether there are subtests. We seem to have some mix of these. Are you modelling each assert as a subtest? If so the harness should either OK or ERROR. If not it can PASS or FAIL.

@@ +715,4 @@
>              TestRunner.updateUI([{ result: false }]);
>          } else if (numAsserts > 0) {
> +            TestRunner.stLogger.testEnd(url, // test
> +                                        'FAIL', // status

Same comment about FAIL.

::: testing/mozbase/mozlog/mozlog/structured/formatters/machformatter.py
@@ +5,2 @@
>  import base
> +import time

Why did these get rearrange? The convention is to split up stdlib imports and local imports.

Also, is sys being used?

Comment 52

[Andrew Halberstadt [:ahal]]

(In reply to James Graham [:jgraham] from comment #51)
> ::: build/automationutils.py
> @@ +602,4 @@
> >    def process(self):
> >      for test in self._parseLeakingTests():
> >        for url, count in self._zipLeakedWindows(test["leakedWindows"]):
> > +        self.logger("TEST-UNEXPECTED-FAIL | %s | leaked %d window(s) until shutdown [url = %s]" % (test["fileName"], count, url))
> 
> Uh, why are we still writing TEST-UNEXPECTED-FOO directly? That just won't
> work with anything other than tbpl, which defeats the point of structured
> logging.
> 
> As far as I can tell this should be something like:
> 
> for test in self._parseLeakingTests():
>     self.logger.test_start(test=some_test_id)
>     for url, count in self._zipLeakedWindows(test["leakedWindows"]):
>         self.logger.test_status(test=some_test_id, status="FAIL",
> subtest=url, message="Leaked %d windows until shutdown" % count)
>     self.logger.test_end(test=some_test_id)

I'm actually not too sure about this. This is processed after all the tests are finished running. The only reason TEST-UNEXPECTED-FAIL is being printed is to turn the job orange on tbpl, this isn't actually a test failure. Given that this message is specifically crafted for tbpl, I don't think we should change it until we can create a new type of "leak failure" message that mozharness can understand.


> ::: testing/mochitest/runtests.py
> @@ +68,5 @@
> > +        self.log_num = 0
> > +
> > +    def __call__(self, data):
> > +        tbpl_output = super(MochitestFormatter, self).__call__(data)
> > +        output = u'{0} INFO {1}'.format(self.log_num, tbpl_output)
> 
> Should this be in mozlog, or is it really mochitest-specific?
> 
> Frankly it seems a little strange to partially number the log entries, so I
> wonder if this is the best way to solve whateer the use case is.

I think a lot of this feedback stems from the assumption that we are going to use the structured logging right away. I told Ahmed to get the ability to perform structured logging landed ASAP, because working with mochitest is horrible and prone to bitrot. So right now, this patch is just trying to log structured, and immediately convert it right back to the old format without breaking any of the mozharness or tbpl regexes. I believe this is here for that reason.


> @@ +157,5 @@
> > +        self.logger.log_raw(message)
> > +
> > +    def dump_buffered(self, limit=False):
> > +        if limit:
> > +            dumped_messages = self.buffered_messages[-self.BUFFERING_THRESHOLD:]
> 
> So, I'm confused. We seem to dump the last 100 messages, and then clear the
> buffer below. Won't this cause any earlier messages to simply be lost?

Yes, mochitests have a --quiet option which when set only prints info/status messages if the test failed. This is to keep the log size under 50MB (some tests spam hundreds of thousands of TEST-INFO and TEST-PASS messages). Ahmed had to move this mechanism out of the JS side and into the python side.


> @@ +1251,3 @@
> >        if isPidAlive(processPID):
> >          foundZombie = True
> > +        log.info("TEST-UNEXPECTED-FAIL | zombiecheck | child process %d still alive after shutdown" % processPID)
> 
> More unstructured messages. Zombiecheck is a test and should be logged as
> such.

How is it a test? This is more of an assertion. Again TEST-UNEXPECTED-FAIL is only printed to turn the job orange.

 
> @@ +1735,4 @@
> >          self.stackFixerProcess.communicate()
> >          status = self.stackFixerProcess.returncode
> >          if status and not didTimeout:
> > +          log.info("TEST-UNEXPECTED-FAIL | runtests.py | Stack fixer process exited with code %d during test run" % status)
> 
> This is unstructured.
> 
> Why is the stackfixer being modelled as a test rather than as a thing that
> can run or fail, with the latter giving an error in the log i.e. why is
> there a TEST-* here at all?

To turn the job letters orange :). Again, we can't really change this until mozharness/tbpl are updated.

To summarize, I agree that all of these instances of unstructured logging should be fixed. But I'd like to see them fixed in a follow up patch. In my experience, when working on mochitest if you have a patch that's green on tbpl that gets you part of the way there, you land it while you can!

Comment 53

[James Graham [:jgraham]]

The tests implemented at harness level are still tests; they are inspecting some property of the product under test and have a clear binary pass condition. Therefore it makes sense to model them as such in structured logs.

Per the conversation on irc, I understand the plan is to land one set of changes here and then keep working to make the structured logging externally observable. Given this, I am happy if my feedback is addressed after the initial patch lands.

Comment 54

[Andrew Halberstadt [:ahal]]

Comment on attachment 8442439 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

Overall this looks really good. But there are too many nits/comments from the three of us to give this an r+. So please try to address as much as you can and upload a new patch. I think the things that are there to prevent existing mozharness or tbpl regexes from breaking can be fixed in a follow-up patch.. though if you'd rather fix everything (including mozharness) at once, I'll leave that up to you.

::: build/mobile/remoteautomation.py
@@ +239,5 @@
> +            except DMError:
> +                # we currently don't retry properly in the pullFile
> +                # function in dmSUT, so an error here is not necessarily
> +                # the end of the world
> +                return []

If the fix is simple can we just fix pullFile instead? If not, please file a bug if there isn't one on file already.

::: dom/imptests/testharnessreport.js
@@ +144,5 @@
> +      this.runner.stLogger.testStatus(url, // test
> +                                      test.message, // subtest
> +                                      status, // status
> +                                      expected, // expected
> +                                      message // message

Agreed with chmanchester, the comments seem unnecessary.

::: dom/indexedDB/ipc/test_ipc.html
@@ +64,4 @@
>  
>      let seenTestMessage = false;
>  
> +    var VALID_ACTIONS = ['suite_start', 'suite_end', 'test_start', 'test_end', 'test_status', 'process_output', 'log'];

nit: use let

::: dom/tests/mochitest/localstorage/test_localStorageEnablePref.html
@@ -6,4 @@
>  <link rel="stylesheet" type="text/css" href="/tests/SimpleTest/test.css" />
>  
>  <script type="text/javascript">
> -

nit: remove this file from you patch.

::: testing/mochitest/browser-harness.xul
@@ +11,4 @@
>          width="1024">
>    <script type="application/javascript" src="chrome://mochikit/content/tests/SimpleTest/MozillaLogger.js"/>
>    <script type="application/javascript" src="chrome://mochikit/content/tests/SimpleTest/LogController.js"/>
> +  <script type="application/javascript" src="chrome://mochikit/content/tests/SimpleTest/TestRunner.js"/>

I wonder if StructuredLogger should be defined in its own file? This probably ok as is for now though.

@@ +155,5 @@
> +        this.dumper.stLogger.testStatus(this.path, // test
> +                                        result.msg, // subtest
> +                                        status, // status
> +                                        expected, // expected
> +                                        result.msg // message

Remove comments here.

::: testing/mochitest/runtests.py
@@ +93,5 @@
> +        self.buffered_messages = []
> +
> +    def write(self, line):
> +        # Decoding messages (structured or not)
> +        line = line.rstrip().decode("UTF-8", "ignore")

I tend to prefer 'replace' to 'ignore', but I guess it's not that important.

@@ +109,5 @@
> +        if not self.tests_started and message['action'] == 'test_start':
> +            self.tests_started = True
> +
> +        # Activation/deactivating message buffering from the JS side
> +        if message['action'] == 'log':

I think we had talked about not hiding this in a 'log' action. Just a reminder.

@@ +150,5 @@
> +
> +        return message
> +
> +    def flush(self):
> +        sys.stdout.flush()

Is this message logger guaranteed to be streaming to stdout?

@@ +1740,5 @@
>        if self.shutdownLeaks:
>          self.shutdownLeaks.process()
>  
> +    def unexpected_fail(self, message):
> +      """ Help function to check for unexpected fails in structured logs """

Why is unexpected_fail a special case over unexpected_pass?

::: testing/mochitest/runtestsremote.py
@@ +454,4 @@
>                  failed += 1
> +            elif message['status'] == 'PASS':
> +                passed += 1
> +            # TODO: is "INFO TEST-KNOWN" equivalent to an expected fail?

Yes, I think TEST-KNOWN-FAIL is treated as a skip here. I should double check.

@@ +556,4 @@
>          # it trying to set up ssltunnel as well
>          kwargs['runSSLTunnel'] = False
>  
> +        # BUGFIX : we shouldn't pass the "quiet" argument to the constructor

This comment seems unnecessary.

::: testing/mochitest/tests/SimpleTest/TestRunner.js
@@ +70,5 @@
> + * StructuredLogger: Structured logger class following the mozlog.structured protocol
> + *
> + *
> +**/
> +var VALID_ACTIONS = ['suite_start', 'suite_end', 'test_start', 'test_end', 'test_status', 'process_output', 'log'];

use let, also throughout the rest of this file.

@@ +545,5 @@
>          }
>  
>          SpecialPowers.unregisterProcessCrashObservers();
>  
> +        TestRunner.stLogger.info("TEST-START | Shutdown");

Oddly enough, this is what the harness looks for to tell when the tests have stopped running :/

Comment 55

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

This should fix the issues raised in all the previous review/feedbacks (too numerous to count!).

Also, hopefully fixed a couple IPC tests I previously missed (Ms2ger should help review those) and also moved the suite_end message because it could cause an error in a special case.

A couple of things I didn't fix:
. The unstructured logs. Those are all over the code. and considering some of them as a test can be troublesome (unclear when they start/end). Also, some of them should disappear in favor of the processing of structured logs (ex: "TEST-START | Shutdown" replaced by "SUITE-END").
. Settting up the structured loggers with commandline args: Gave it a try, ran into a couple problems (also currently using a custom formatter)

We can solve them in a future bug.

Try push: https://tbpl.mozilla.org/?tree=Try&rev=f13199f9d9e9

Comment 56

[Andrew Halberstadt [:ahal]]

Comment on attachment 8443198 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

I really sorry, but I just landed bug 997244 so you're going to have to rebase. I suggest we do the review/feedback cycle after that. I can help you with any merge conflicts, just let me know!

Comment 57

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

Merged with the mozrunner/marionette refactor.
I also found a bug when a test times-out caused by the message buffering, so I added some logic to dump all buffered messages before showing a timeout error, which should solve the issue.

Try push: https://tbpl.mozilla.org/?tree=Try&rev=07e0a2d7e428

Comment 58

[Ed Morley [:emorley]]

Before this lands - please may we submit some try runs with intentional TEST-UNEXPECTED-FAILs, harness managed timeouts, hangs-where-the-app-is-killed & crashes to check the log output is as expected? :-)

Comment 59

[Ahmed Kachkach [:akachkach]]

Do we have tools in place to do this (create arbitrary errors) or should I modify some tests so I can get the said errors?

Comment 60

[Ed Morley [:emorley]]

(In reply to Ahmed Kachkach [:akachkach] from comment #59)
> Do we have tools in place to do this (create arbitrary errors) or should I
> modify some tests so I can get the said errors?

We don't have tools for this - I'd just change some of the mochitest test assertions and on a separate run insert some MOZ_CRASH statements in cpp files that are not at startup (so the crash reporter has time to kick in) etc.

Comment 61

[(not currently active) Ted Mielczarek]

I've been using this patch to add intentional hangs to mochitest-plain and xpcshell:
http://hg.mozilla.org/users/tmielczarek_mozilla.com/mq/raw-file/8186b13d6f0d/hangs

Comment 62

[Andrew Halberstadt [:ahal]]

Comment on attachment 8443877 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

I'd give this an r+ except for the mozrunner/marionette comment. Please update that and I'll flip the bit to a +. I also didn't look at the ipc test stuff too closely, but I think that is what Ms2ger is reviewing. Let me know if any comments don't make sense.

::: build/mobile/remoteautomation.py
@@ +192,5 @@
>      class RProcess(object):
>          # device manager process
>          dm = None
> +        def __init__(self, dm, cmd, stdout = None, stderr = None, env = None, cwd = None, app = None,
> +                     messageLogger = None):

mind fixing the spaces around the '=' while you are here?

::: testing/marionette/client/marionette/marionette.py
@@ +450,4 @@
>                   emulator_binary=None, emulator_res=None, connect_to_running_emulator=False,
>                   gecko_log=None, homedir=None, baseurl=None, no_window=False, logdir=None,
>                   busybox=None, symbols_path=None, timeout=None, device_serial=None,
> +                 adb_path=None, message_logger=None):

Instead of passing 'message_logger' through here, I think you should pass the 'process_args' mozrunner argument through. 'process_args' has a key called processOutputLine which can be a list of output handlers. We can use this to append an additional output handler that has the message_logger stuff in it.

::: testing/mochitest/runtests.py
@@ +554,4 @@
>        testURL = "about:blank"
>      return testURL
>  
> +  def buildTestPath(self, options, disabled=True, logger=None):

logger seems unused? Is this to satisfy a subclass?

@@ +1453,5 @@
>      self.setTestRoot(options)
>  
>      if not options.runByDir:
> +      status = self.doTests(options, onLaunch)
> +      

nit: whitespace

::: testing/mochitest/runtestsb2g.py
@@ +121,5 @@
>  
> +        # configuring the message logger's buffering
> +        self.message_logger.buffering = options.quiet
> +
> +       

nit: whitespace

::: testing/mozbase/mozrunner/mozrunner/base/device.py
@@ +22,5 @@
> +
> +        process_args = {'stream': sys.stdout,
> +                        'processOutputLine': self.on_output,
> +                        'onTimeout': self.on_timeout }
> +        process_args.update(kwargs.get('process_args', {}))

Requiring a message_logger here is probably going to break things that don't use structured logging yet. See my previous comment about piggybacking off of process_args instead. You'll need to re-create the "on_output" function inside the mochitest harness, which as it turns out helps fix bug 1025051 :). As a bonus you could also re-define the on_timeout function in the mochitest harness, though that's not required as part of this bug.

Comment 63

[Ahmed Kachkach [:akachkach]]

Fixed the unused logger and the white-space issues, thanks!

For "piggybacking off of process_args", that's the initial solution I tried for doing the logging now that the runner is instantiated in marionette, but I couldn't do it because the current "on_output" function modifies the runner (last_test attribute), and I obviously can't get a reference to that runner since it's instantiated when we instantiate Mochitest. Any thoughts about how we could change that? (otherwise I could just add a test for message_logger==None, and put it to None by default in the mochitest class too)

btw, :ted and : and :edmorley -> I'm currently testing MOZ_CRASH, hangs, etc. ; Already found a bug (on timeout, we display 2 error messages: the timeout + the process exited with status != 0, that used to break the formatter). I think MOZ_CRASH gives the info we used to have (stack, etc.) ; Will link to a try push when done!

Comment 64

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8443877 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

I don't think I have much else to add. I would run through try with some seeded failures in addition to hangs before landing.

::: content/base/test/test_fileapi.html
@@ +149,4 @@
>  
>  // Test loading an empty file works (and doesn't crash!)
>  var emptyFile = createFileWithData("");
> +dump("hello nurse\n");

I think if we've done our job right, this patch wont require any modifications to test files.

::: dom/devicestorage/ipc/test_ipc.html
@@ +44,5 @@
>  
> +    let VALID_ACTIONS = ['suite_start', 'suite_end', 'test_start', 'test_end', 'test_status', 'process_output', 'log'];
> +    function validStructuredMessage(message) {
> +        return message.action !== undefined && VALID_ACTIONS.indexOf(message.action) > -1;
> +    };

This is duplicated above (and below), can you expose it from the global Runner/Logger?

::: testing/marionette/client/marionette/marionette.py
@@ +515,5 @@
>  
>          if connect_to_running_emulator:
>              self.runner = B2GEmulatorRunner(b2g_home=homedir,
> +                                            logdir=logdir,
> +                                            message_logger=message_logger)

Passing a mochitest-specific message logger through the marionette constructor seems a bit weird. Is there no other way?

::: testing/mochitest/tests/SimpleTest/TestRunner.js
@@ +610,5 @@
> +                                        'ERROR',
> +                                        'OK',
> +                                        "This test left crash dumps behind, but we " +
> +                                        "weren't expecting it to!",
> +                                        {unexpected_crashdump_files: unexpectedCrashDumpFiles}

I think jgraham mentioned this, but please make uses of ' vs. " consistent.

Comment 65

[Andrew Halberstadt [:ahal]]

Comment on attachment 8443877 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

I think this accidentally got reset

Comment 66

[Ed Morley [:emorley]]

(In reply to Ahmed Kachkach [:akachkach] from comment #63)
> btw, :ted and : and :edmorley -> I'm currently testing MOZ_CRASH, hangs,
> etc. ; Already found a bug (on timeout, we display 2 error messages: the
> timeout + the process exited with status != 0, that used to break the
> formatter). I think MOZ_CRASH gives the info we used to have (stack, etc.) ;
> Will link to a try push when done!

That's great - thank you :-)

Comment 67

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

Fixed a couple issues the patch created on some use-cases (errors, timeouts, etc.). Changed the way we pass the message logger to RemoteAutomation and Marionette (to avoid adding mochitest-related parameters to those classes). Also fixed a couple encoding bugs (when reading logcat in runtestsremote, and when adding some text around the tbpl formatter)

Try run with all tests/platforms: https://tbpl.mozilla.org/?tree=Try&rev=180a5d65ab74

Try run with added MOZ_CRASH / timeout: https://tbpl.mozilla.org/?tree=Try&rev=ac736b531894

Comment 68

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

Forgot to fix some nits in the previous patch.

Comment 69

[:Ms2ger (he/him; ⌚ UTC+1/+2)]

Please provide patches with 8 lines of context.

Comment 70

[Andrew Halberstadt [:ahal]]

Comment on attachment 8445666 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

I was on the verge of giving this a conditional r+, but then noticed something funny going on in tbe B2G emulator mochitests of that last try run: https://tbpl.mozilla.org/?tree=Try&rev=ac736b531894
All it says is 'return code 1'.. that isn't a very helpful message. Do you know what's happening? Is it a timeout not working properly? Is the emulator dying? I think we should investigate this before landing.

Please also:
1) Update the patch based on my comments below
2) Update the commit message with r=ahal,Ms2ger
3) Update the patch with more context for Ms2ger, add this to your configs:
https://github.com/ahal/configs/blob/master/.gitconfig#L7 and 
https://github.com/ahal/configs/blob/master/.hgrc#L9

::: testing/marionette/client/marionette/marionette.py
@@ +465,4 @@
>          self._test_name = None
>          self.timeout = timeout
>          self.device_serial = device_serial
> +        process_args = process_args or {};

nit: this isn't necessary.. B2GEmulatorRunner should know what to do when process_args is None.

::: testing/mochitest/runtestsb2g.py
@@ +137,5 @@
>          try:
> +            def on_output(line):
> +                message = self.message_logger.write(line)
> +                if message and message['action'] == 'test_start':
> +                    self.last_test = message['test']

nit: put a newline here

@@ +141,5 @@
> +                    self.last_test = message['test']
> +            # The logging is handled by on_output, so we pass dev/null as the stream
> +            devnull = open(os.devnull, 'w')
> +            process_args = {'processOutputLine': on_output,
> +                            'stream': devnull}

I think setting this to None is sufficient, no need to open os.devnull.

::: testing/mozbase/mozrunner/mozrunner/base/device.py
@@ +77,4 @@
>              print("timed out waiting for '%s' process to start" % self.app_ctx.remote_process)
>  
>      def on_output(self, line):
> +        message = self.message_logger.write(line)

self.message logger doesn't exist anymore :p. Since mochitests aren't using this function I think you should just leave it untouched. It *might* even be ok to delete it completely, though that could break :jgraham's wptrunner.

Comment 71

[Ahmed Kachkach [:akachkach]]

Fixed the points you raised, except for that B2G crash (or timeout) reporting. Unsure why it doesn't print the timeout info (as it's supposed to be on the Python side, so probably not a buffering issue). I'll see if I can find what caused this and post the updated patch for review.

Comment 72

[Ed Morley [:emorley]]

Comment on attachment 8445666 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

(Will have a look when the B2G crash issue is resolved :-))

Comment 73

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

This is the updated patch (also removed the MochitestStructuredLogger class as requested by chmanchester and jgraham, forgot to do that previously).

That B2G bug isn't apparently related to this patch. Here is a try push that just adds a timeout/crash without this patch, and we still only get "Return code: 1" : https://tbpl.mozilla.org/?tree=Try&rev=5e610705e7b0

I filed a separate bug for it (Bug 1030330).

Comment 74

[Ahmed Kachkach [:akachkach]]

By the way, here's a fresh try push to make sure those changes didn't break anything: https://tbpl.mozilla.org/?tree=Try&rev=9888adfc59d4

Comment 75

[Andrew Halberstadt [:ahal]]

Comment on attachment 8446131 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

Thank you! r+ on everything except the ipc tests.

::: testing/mozbase/mozrunner/mozrunner/base/device.py
@@ +21,5 @@
>      def __init__(self, device_class, device_args=None, **kwargs):
> +        process_args = {'stream': sys.stdout,
> +                        'processOutputLine': self.on_output,
> +                        'onTimeout': self.on_timeout }
> +        process_args.update(kwargs.get('process_args') or {})

Fyi get() has a second parameter for the default, so this could be written as kwargs.get('process_args', {}).. but this is fine too :)

Comment 76

[Ahmed Kachkach [:akachkach]]

(In reply to Andrew Halberstadt [:ahal] from comment #75)
> Comment on attachment 8446131 [details] [diff] [review]
> 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch
> 
> Review of attachment 8446131 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Thank you! r+ on everything except the ipc tests.
> 
> ::: testing/mozbase/mozrunner/mozrunner/base/device.py
> @@ +21,5 @@
> >      def __init__(self, device_class, device_args=None, **kwargs):
> > +        process_args = {'stream': sys.stdout,
> > +                        'processOutputLine': self.on_output,
> > +                        'onTimeout': self.on_timeout }
> > +        process_args.update(kwargs.get('process_args') or {})
> 
> Fyi get() has a second parameter for the default, so this could be written
> as kwargs.get('process_args', {}).. but this is fine too :)

Thanks for the review! ; I actually changed this because now, marionette will always pass a `process_args` parameter (`None` by default). so `kwargs.get('process_args', {})` will return `None` instead of `{}`.

Comment 77

[:Ms2ger (he/him; ⌚ UTC+1/+2)]

Comment on attachment 8446131 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

::: build/automationutils.py
@@ +606,5 @@
>      if line[2:11] == "DOMWINDOW":
>        self._logWindow(line)
>      elif line[2:10] == "DOCSHELL":
>        self._logDocShell(line)
>      elif line.startswith("TEST-START"):

It's weird that this still uses startswith

::: content/base/test/test_fileapi.html
@@ +148,5 @@
>    "result in test reader get result without reading");
>  
>  // Test loading an empty file works (and doesn't crash!)
>  var emptyFile = createFileWithData("");
> +dump("hello nurse\n");

Remove this call

::: content/media/webspeech/synth/ipc/test/file_ipc.html
@@ +37,5 @@
>            oldComplete();
>          }
>        };
>  
> +      TestRunner._dumpMessage = function(msg) {

Do you still need to put this on TestRunner?

@@ +44,5 @@
>      }
>  
> +    let VALID_ACTIONS = ['suite_start', 'suite_end', 'test_start', 'test_end', 'test_status', 'process_output', 'log'];
> +    function validStructuredMessage(message) {
> +        return message.action !== undefined && VALID_ACTIONS.indexOf(message.action) > -1;

2-space indentation throughout this file, and use >= 0

@@ +45,5 @@
>  
> +    let VALID_ACTIONS = ['suite_start', 'suite_end', 'test_start', 'test_end', 'test_status', 'process_output', 'log'];
> +    function validStructuredMessage(message) {
> +        return message.action !== undefined && VALID_ACTIONS.indexOf(message.action) > -1;
> +    };

No semicolon

@@ +52,5 @@
> +
> +      if (validStructuredMessage(message)) {
> +        if (message.test === undefined || message.message === undefined) {
> +            return;
> +        };

No semicolon

@@ +55,5 @@
> +            return;
> +        };
> +
> +        let details = message.test + " | " + message.message;
> +        if (message.action == 'test_status' || message.action == 'test_end') {

switch on message.action is cleaner, I think

::: dom/devicestorage/ipc/test_ipc.html
@@ +40,5 @@
>          sendAsyncMessage("test:DeviceStorage:ipcTestMessage", { msg: msg });
>        }
>      }
>  
> +    let VALID_ACTIONS = ['suite_start', 'suite_end', 'test_start', 'test_end', 'test_status', 'process_output', 'log'];

I know this isn't your fault, but this code should move somewhere common (preferably in a separate patch).

::: dom/imptests/testharnessreport.js
@@ +40,5 @@
>     */
>    "runner": parent === this ? null : parent.TestRunner || parent.wrappedJSObject.TestRunner,
>  
>    /**
>     * Prefixes for the error logging. Indexed first by int(todo) and second by

Fix references to "prefixes".

@@ +44,5 @@
>     * Prefixes for the error logging. Indexed first by int(todo) and second by
>     * int(result).
>     */
>    "prefixes": [
> +    [{status:'FAIL', expected:'PASS', message:"TEST-UNEXPECTED-FAIL"},

Spaces after :s

@@ +47,5 @@
>    "prefixes": [
> +    [{status:'FAIL', expected:'PASS', message:"TEST-UNEXPECTED-FAIL"},
> +     {status:'PASS', expected:'PASS', message:"TEST-PASS"}],
> +    [{status:'FAIL', expected:'FAIL', message:"TEST-KNOWN-FAIL"},
> +     {status:'PASS', expected:'FAIL', message:"TEST-UNEXPECTED-PASS"}]

Format as

[
  [
    {status...},
    {status...}
  ],
  [
    {status...},
    {status...}
  ]
]

@@ +141,3 @@
>      if (this.runner) {
> +      // Structured logging
> +      this.runner.stLogger.testStatus(url,

stLogger isn't too readable... Since code is read much more often than it is written, make it structuredLogger or some such.

@@ +144,5 @@
> +                                      test.message,
> +                                      result.status,
> +                                      result.expected,
> +                                      message
> +      );

Goes at the end of the previous line

::: testing/mochitest/browser-harness.xul
@@ +142,5 @@
>          this.lastOutputTime = Date.now();
>          this.results.push(result);
>  
> +        if (result.info) {
> +            if (result.msg) {

2-space

@@ +153,5 @@
> +                                        result.msg,
> +                                        result.status,
> +                                        result.expected,
> +                                        result.msg
> +        );

Previous line

Comment 78

[Ahmed Kachkach [:akachkach]]

Comment on attachment 8446131 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

Thanks for the feedback!
Was missing a couple parts of the code because I didn't run the tests against a debug build. I also found a couple other edge cases while talking with :chmanchester (like bugs "manually" dumping "TEST-UNEXPECTED-FAIL"), so I tried to fix those too. 'will update the patch once I have a passing try run (with opt & debug).
(also fixed the nits I didn't address in this comment)

::: build/automationutils.py
@@ +606,5 @@
>      if line[2:11] == "DOMWINDOW":
>        self._logWindow(line)
>      elif line[2:10] == "DOCSHELL":
>        self._logDocShell(line)
>      elif line.startswith("TEST-START"):

Nice catch! I didn't run this against debug logs so this part didn't execute. Should be fixed now, will do a try run with opt AND debug this time!

::: content/media/webspeech/synth/ipc/test/file_ipc.html
@@ +37,5 @@
>            oldComplete();
>          }
>        };
>  
> +      TestRunner._dumpMessage = function(msg) {

This should be TestRunner.stLogger._dumpMessage instead. Fixed.

@@ +55,5 @@
> +            return;
> +        };
> +
> +        let details = message.test + " | " + message.message;
> +        if (message.action == 'test_status' || message.action == 'test_end') {

True, fixed.

::: dom/devicestorage/ipc/test_ipc.html
@@ +40,5 @@
>          sendAsyncMessage("test:DeviceStorage:ipcTestMessage", { msg: msg });
>        }
>      }
>  
> +    let VALID_ACTIONS = ['suite_start', 'suite_end', 'test_start', 'test_end', 'test_status', 'process_output', 'log'];

The problem here is that I couldn't get access to the structured logger from here, so I had to duplicate this code. And yup, all this IPC code should probably be shared instead of being duplicated (but as you said maybe that should be done in a different patch)

::: dom/imptests/testharnessreport.js
@@ +141,3 @@
>      if (this.runner) {
> +      // Structured logging
> +      this.runner.stLogger.testStatus(url,

Changed to structuredLogger.

@@ +144,5 @@
> +                                      test.message,
> +                                      result.status,
> +                                      result.expected,
> +                                      message
> +      );

Fixed this here and in all other calls of testStatus or testEnd.

Comment 79

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

Fixed a bug with the IPC tests, some debug-builds related bugs (with the stack-fixer, leak checker, ...) and points raised in previous comments.

Try run: https://tbpl.mozilla.org/?tree=Try&rev=758707663b34
Try run with errors: https://tbpl.mozilla.org/?tree=Try&rev=51a988655d48

Comment 80

[Ed Morley [:emorley]]

(In reply to Ahmed Kachkach [:akachkach] from comment #79)
> Try run with errors: https://tbpl.mozilla.org/?tree=Try&rev=51a988655d48

This failure doesn't look right:
https://tbpl.mozilla.org/php/getParsedLog.php?id=42588867&tree=Try
20:09:35     INFO -  403 INFO TEST-UNEXPECTED-FAIL | /tests/layout/generic/test/test_bug391747.html | uncaught exception | expected PASS | NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIDOMWindowUtils.sendMouseEvent] at chrome://specialpowers/content/specialpowersAPI.js:116

Presumably same root cause as bug 956739 comment 34 onwards (for which bug 1030845 was filed).

Comment 81

[Andrew Halberstadt [:ahal]]

Comment on attachment 8446938 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

Thanks! I guess we should fix bug 1030845 before landing though

Comment 82

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8446938 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

::: dom/imptests/testharnessreport.js
@@ +145,4 @@
>      if (this.runner) {
> +      // Structured logging
> +      this.runner.structuredLogger.testStatus(url,
> +                                      test.message,

The second parameter is for the subtest.

::: testing/mochitest/browser-harness.xul
@@ +149,5 @@
> +          return;
> +        }
> +
> +        this.dumper.structuredLogger.testStatus(this.path,
> +                                        result.msg,

And here.

Comment 83

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

carry forward r+ from ahal

Small change to "dom/imptests/testharnessreport.js" (test.message -> test.name) for better reporting.

Also removed TBPL formatter changes I've done previously as bug 1030845 is now landed in mozilla-inbound. (so disregard the TEST-UNEXPECTED-FAILURE with too many pipes in the try run, that's just because it didn't land on master uet)

Try run: https://tbpl.mozilla.org/?tree=Try&rev=40c2cc689e03

Comment 84

[Chris Manchester (limited bugmail, email directly)]

I was just looking at the robocop harness with jmaher, and it looks like it passes a lot of unstructured logging through runtestsremote.py. If you open up the logs for rc* from the last try run, it looks like something's gone wrong (although not in a way that turned the job orange.

Comment 85

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

We decided we'd try to maintain compatibility with the current (unstructured) robocop logging, and convert it to structured logging in a separate bug, bug 1034267 (since it requires to dive in some Java code, etc.). We also have to implement the structured logging API in Java (already started in bug 1034236).

The patch was updated to maintain unstructured logging in robocop, which should fix the issues raised by :chmanchester.

Try push including Talos (because those share some code with the mochitest robocop tests) - https://tbpl.mozilla.org/?tree=Try&rev=0aeecb9ba4ca

Comment 86

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

A recently landed patch (probably bug 1034212?) caused the dt chunk to fail in the previously linked try run because one test was using the "info" function to dump an object (which would just print '[object Object]'), so I updated the patch to coerce all logs (info, warning and such).

Comment 87

[Ahmed Kachkach [:akachkach]]

And another try run just to test everything is still working correctly: https://tbpl.mozilla.org/?tree=Try&rev=fd6f25ca0018

Comment 88

[Chris Manchester (limited bugmail, email directly)]

Two comments looking at the changes to robocop logs from the most recent try run:

Line counters have changed. There used to be a start from 0 for each test file, now it looks like there's one counter for test files, one for the harness. I don't know if anyone's relying on these counters, so this may not be a problem, but it would be nice to do something sensible.

There are multiple suite_end actions logged (one per file?). The structured format expects just one per run, so I think this needs to be addressed.

Comment 89

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

I had to unbitrot the patch because bug 1014125 landed today (it does tests bisection based on the log output).

Also made the log line-number a class argument (for the formatter) to have consistent line numbering across different loggers and tried to factor the code we do on suite_end (as it's called from runtests.py / runtestsb2g.py and runtestsremote.py) ; Robocop will still output multiple SUITE-END messages as it runs the tests multiple times (already used to do this with unstructured logs, "TEST-START | Shutdown"), unsure what I can do to 'fix' this.

Try push: https://bugzilla.mozilla.org/show_bug.cgi?id=1014125

Comment 90

[Ahmed Kachkach [:akachkach]]

Attachment: interdiff

Interdiff for :ahal (since the last review); might not be 100% accurate since the patch wouldn't apply on master, so I had to merge some modifications to generate this interdiff.

Comment 91

[Ahmed Kachkach [:akachkach]]

Correct link for the try push: https://tbpl.mozilla.org/?tree=Try&rev=03c1e88406e9

Comment 92

[Andrew Halberstadt [:ahal]]

Comment on attachment 8452082 [details] [diff] [review]
interdiff

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

Thanks!

::: testing/mochitest/runtestsremote.py
@@ +624,5 @@
> +        logFile.append("%s INFO Failed: %s" % (incr, failed))
> +        incr += 1
> +        logFile.append("%s INFO Todo: %s" % (incr, todo))
> +        incr += 1
> +        logFile.append("%s INFO SimpleTest FINISHED" % incr)

nit: I think it would be cleaner to store these strings in a list and use a loop

Comment 93

[Andrew Halberstadt [:ahal]]

Comment on attachment 8452080 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

Did you intend to have Ms2ger review everything? Or just the ipc tests part? If it's the latter, you may want to upload a new patch that only has those changes in it.

Comment 94

[Chris Manchester (limited bugmail, email directly)]

> Also made the log line-number a class argument (for the formatter) to have
> consistent line numbering across different loggers and tried to factor the
> code we do on suite_end (as it's called from runtests.py / runtestsb2g.py
> and runtestsremote.py) ; Robocop will still output multiple SUITE-END
> messages as it runs the tests multiple times (already used to do this with
> unstructured logs, "TEST-START | Shutdown"), unsure what I can do to 'fix'
> this.

Right, we can just say that Robocop logs aren't structured as a result of this patch, but we will need to address this with bug 1034267.

Comment 95

[:Ms2ger (he/him; ⌚ UTC+1/+2)]

Comment on attachment 8452080 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

r=me modulo a promise to deduplicate the test_ipc code.

::: content/media/webspeech/synth/ipc/test/file_ipc.html
@@ +51,4 @@
>  
> +      if (validStructuredMessage(message)) {
> +        if (message.test === undefined || message.message === undefined) {
> +            return;

Two-space

@@ +56,2 @@
>  
> +        let details = message.test + " | " + message.message;

I'd move this into the switch

@@ +56,4 @@
>  
> +        let details = message.test + " | " + message.message;
> +
> +        switch(message.action) {

Space after switch

::: dom/devicestorage/ipc/test_ipc.html
@@ +1,1 @@
> +t <!DOCTYPE HTML>

Revert

::: dom/imptests/testharnessreport.js
@@ +145,2 @@
>      if (this.runner) {
> +      // Structured logging

Not sure this comment is useful

@@ +145,4 @@
>      if (this.runner) {
> +      // Structured logging
> +      this.runner.structuredLogger.testStatus(url,
> +                                      test.name,

Indentation is off

::: testing/mochitest/browser-harness.xul
@@ +143,5 @@
>          this.results.push(result);
>  
> +        if (result.info) {
> +          if (result.msg) {
> +              this.dumper.structuredLogger.info(result.msg);

Two-space

@@ +149,5 @@
> +          return;
> +        }
> +
> +        this.dumper.structuredLogger.testStatus(this.path,
> +                                        result.msg,

Indentation

::: testing/mochitest/browser-test.js
@@ +223,5 @@
>          if (this.currentTest)
>            this.currentTest.addResult(new testResult(false, msg, "", false));
>          else
> +          this.dumper.structuredLogger.testEnd("browser-test.js",
> +                                       "FAIL",

Indentation

@@ +263,3 @@
>        } else {
> +        this.dumper.structuredLogger.testEnd("browser-test.js",
> +                                     "FAIL",

Indentation

@@ +268,1 @@
>        }

ms?

@@ +428,5 @@
>  
>        // Note the test run time
>        let time = Date.now() - this.lastStartTime;
> +      this.dumper.structuredLogger.testEnd(this.currentTest.path,
> +                                  "OK",

Indentation

@@ +709,5 @@
> +    if (aIsTodo) {
> +      this.status = "FAIL";
> +      this.expected = "FAIL";
> +    }
> +    else{

} else {

@@ +740,5 @@
> +    if (aIsTodo) {
> +      this.status = "PASS";
> +      this.expected = "FAIL";
> +    }
> +    else {

Ditto

::: testing/mochitest/runtestsremote.py
@@ +7,3 @@
>  import tempfile
>  import re
> +import json

Sort the list of imports

::: testing/mochitest/tests/SimpleTest/LogController.js
@@ +63,5 @@
>  };
>  
>  /* log with level ERROR */
>  LogController.error = function(message/*, ...*/) {
> +    LogController.logWithLevel("ERROR", message);

Pointless change

::: testing/mochitest/tests/SimpleTest/SimpleTest.js
@@ +338,5 @@
>  
> +SimpleTest._logResult = function (test, passInfo, failInfo) {
> +    var url = SimpleTest._getCurrentTestURL();
> +    var result = test.result ? passInfo : failInfo;
> +    var diagnostic = test.diag ? test.diag : null;

This can be test.diag || null

@@ +345,2 @@
>  
> +    // BUGFIX : coercing the subtest to a string, because some a11y tests pass an xpconnect object

Do |var subtest = String(…);| above instead

@@ +359,4 @@
>          }
>  
> +        parentRunner.structuredLogger.testStatus(url,
> +                                         subtest,

Indentation

::: testing/mochitest/tests/SimpleTest/TestRunner.js
@@ +84,5 @@
> +        this._logData("test_start", data);
> +    };
> +
> +    this.testStatus = function(test, subtest, status, expected, message) {
> +        expected = typeof expected !== "undefined" ? expected : "PASS";

Use function(test, subtest, status, expected="PASS", message=null) {

@@ +506,5 @@
>      } else {
>          $("current-test").innerHTML = "<b>Finished</b>";
>          TestRunner._makeIframe("about:blank", 0);
>  
> +        var passCount = parseInt($("pass-count").innerHTML);

Always pass the radix argument

@@ +517,5 @@
>          {
> +            // No |$('testframe').contentWindow|, so manually update: ...
> +            // ... the log,
> +            TestRunner.structuredLogger.testEnd('SimpleTest/TestRunner.js',
> +                                  "ERROR",

Indentation

@@ +576,5 @@
>      // have a chance to unload it.
>      if (TestRunner._currentTest == TestRunner._lastTestFinished &&
>          !TestRunner._loopIsRestarting) {
> +        TestRunner.structuredLogger.testEnd(TestRunner.currentTestURL,
> +                                    "ERROR",

Ditto

@@ +596,5 @@
>  
>      function cleanUpCrashDumpFiles() {
>          if (!SpecialPowers.removeExpectedCrashDumpFiles(TestRunner._expectingProcessCrash)) {
> +            TestRunner.structuredLogger.testEnd(TestRunner.currentTestURL,
> +                                        "ERROR",

Ditto (more below)

::: testing/specialpowers/content/MozillaLogger.js
@@ +41,5 @@
>    },
>  
>    getLogCallback : function () {
>      return function (msg) {
> +      var data =  '\n' + msg.info.join(' ').trim() + '\n';

Single space after =

@@ +94,5 @@
>    },
>  
>    getLogCallback : function() {
>      return function (msg) {
> +      var data =  '\n' + msg.info.join(' ').trim() + '\n';

Ditto

Comment 96

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

Carry r+ forward from ahal and Ms2ger.

Fixed the points raised by Ms2ger's review. (and will fix the duplicated IPC tests code issue in a different bug, to isolate it from the changes of this one)

Try run: https://tbpl.mozilla.org/?tree=Try&rev=76ebbfb8ca52

Comment 97

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

Previously uploaded the wrong patch (this one includes a one-line fix in ShutdownLeaks).

(carry r+ forward)

Comment 98

[:Ms2ger (he/him; ⌚ UTC+1/+2)]

https://tbpl.mozilla.org/?tree=Try&rev=76ebbfb8ca52

Comment 99

[Carsten Book [:Tomcat]]

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

Comment 100

[Carsten Book [:Tomcat]]

sorry had to backout this change - this checkin seems to have caused some timeouts on windows mochitest 3 like:

04:16:47     INFO -  761 INFO TEST-OK | /tests/dom/media/tests/mochitest/test_peerConnection_errorCallbacks.html | took 586ms
04:16:48     INFO -  Exception in thread Thread-12:
04:16:48     INFO -  Traceback (most recent call last):
04:16:48     INFO -    File "c:\mozilla-build\python27\Lib\threading.py", line 551, in __bootstrap_inner
04:16:48     INFO -      self.run()
04:16:48     INFO -    File "c:\mozilla-build\python27\Lib\threading.py", line 504, in run
04:16:48     INFO -      self.__target(*self.__args, **self.__kwargs)
04:16:48     INFO -    File "C:\slave\test\build\venv\lib\site-packages\mozprocess\processhandler.py", line 774, in _processOutput
04:16:48     INFO -      self.processOutputLine(line.rstrip())
04:16:48     INFO -    File "C:\slave\test\build\venv\lib\site-packages\mozprocess\processhandler.py", line 719, in processOutputLine
04:16:48     INFO -      handler(line)
04:16:48     INFO -    File "C:\slave\test\build\tests\mochitest/runtests.py", line 1769, in processOutputLine
04:16:48     INFO -      self.harness.message_logger.write(line)
04:16:48     INFO -    File "C:\slave\test\build\tests\mochitest/runtests.py", line 128, in write
04:16:48     INFO -      self.logger.log_raw(message)
04:16:48     INFO -    File "C:\slave\test\build\venv\lib\site-packages\mozlog\structured\structuredlog.py", line 120, in log_raw
04:16:48     INFO -      self._handle_log(data)
04:16:48     INFO -    File "C:\slave\test\build\venv\lib\site-packages\mozlog\structured\structuredlog.py", line 132, in _handle_log
04:16:48     INFO -      handler(data)
04:16:48     INFO -    File "C:\slave\test\build\venv\lib\site-packages\mozlog\structured\handlers\__init__.py", line 60, in __call__
04:16:48     INFO -      formatted = self.formatter(data)
04:16:48     INFO -    File "C:\slave\test\build\tests\mochitest/runtests.py", line 72, in __call__
04:16:48     INFO -      tbpl_output = super(MochitestFormatter, self).__call__(data)
04:16:48     INFO -    File "C:\slave\test\build\venv\lib\site-packages\mozlog\structured\formatters\tbplformatter.py", line 17, in __call__
04:16:48     INFO -      return getattr(self, data["action"])(data)
04:16:48     INFO -    File "C:\slave\test\build\venv\lib\site-packages\mozlog\structured\formatters\tbplformatter.py", line 51, in test_end
04:16:48     INFO -      start_time = self.test_start_times.pop(self.test_id(data["test"]))
04:16:48     INFO -  KeyError: u'/tests/dom/media/tests/mochitest/test_peerConnection_offerRequiresReceiveAudio.html'
04:33:28     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['C:\\slave\\test\\build\\venv\\Scripts\\python', '-u', 'C:\\slave\\test\\build\\tests\\mochitest/runtests.py', '--total-chunks', '5', '--this-chunk', '3', '--appname=C:\\slave\\test\\build\\application\\firefox\\firefox.exe', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=https://ftp-ssl.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/mozilla-inbound-win32/1405073293/firefox-33.0a1.en-US.win32.crashreporter-symbols.zip', '--certificate-path=tests/certs', '--autorun', '--close-when-done', '--console-level=INFO', '--quiet', '--chunk-by-dir=4']
04:33:28    ERROR - timed out after 1000 seconds of no output

Comment 101

[Carsten Book [:Tomcat]]

https://tbpl.mozilla.org/php/getParsedLog.php?id=43604435&tree=Mozilla-Inbound is one complete log of that failure

Comment 102

[Ahmed Kachkach [:akachkach]]

Yeah, sorry about that, I knew we'd have some related issue because we now require a unique TEST-END for each TEST-START... it seems like this test somehow generates multiple TEST-END messages. I'll try to see if this is related to the test (and it just wasn't detected before) or the test-harness.

Comment 103

[Chris Manchester (limited bugmail, email directly)]

(In reply to Ahmed Kachkach [:akachkach] from comment #102)
> Yeah, sorry about that, I knew we'd have some related issue because we now
> require a unique TEST-END for each TEST-START... it seems like this test
> somehow generates multiple TEST-END messages. I'll try to see if this is
> related to the test (and it just wasn't detected before) or the test-harness.

The patch in bug 1036427 might be helpful in debugging this.

Comment 104

[Ed Morley [:emorley]]

This also caused timeout error messages to lose their test names, eg:

DeviceRunner TEST-UNEXPECTED-FAIL | automation | application timed out after 450.0 seconds with no output

Instead of:
DeviceRunner TEST-UNEXPECTED-FAIL | /tests/dom/crypto/test/test_WebCrypto.html | application timed out after 450.0 seconds with no output

Comment 105

[Ed Morley [:emorley]]

Tomcat, when this is ready to reland, can you make sure it lands in it's own push - since it's a fairly substantial change.

Comment 106

[Ed Morley [:emorley]]

Also when this goes to try, check that the failures being suggested aren't bug 965705, since that's the bug that was being suggested for all timeouts when this landed, even though the failures weren't intermittent.

Comment 107

[Ahmed Kachkach [:akachkach]]

@edmorley: I think I found where the missing test names come from (the on_output handler passed in runtestsb2g.py updated the last_test attribute on B2GMochitest instead of doing it on the runner).

Still looking for what causes the missing TEST-START. I could reproduce it on try after a couple retriggers, and the error rate is pretty pretty high :). ( https://tbpl.mozilla.org/?tree=Try&rev=e05100e7d1d9 )

Comment 108

[Nils Ohlmeier [:drno]]

Ahmed: regarding the test_peerConnection_errorCallbacks.html failure: that test is from my WebRTC area. I don't think it requires multiple TEST-START, but it does nasty things with overloading the error handlers and such. Ping me if you need help with that tests or if I should look into that specific failure.

Comment 109

[Andrew Halberstadt [:ahal]]

CC'ing dminor.

Dan, I heard you are running steeplechase on ec2 somewhere. Just want to give you a heads up that this changes how the mochitests log messages on the JS side and might cause you some bustage. If it does, hopefully it won't be hard to fix, just wanted to give you a heads up.

Comment 110

[Nils Ohlmeier [:drno]]

(In reply to Andrew Halberstadt [:ahal] from comment #109)
> CC'ing dminor.
> 
> Dan, I heard you are running steeplechase on ec2 somewhere. Just want to
> give you a heads up that this changes how the mochitests log messages on the
> JS side and might cause you some bustage. If it does, hopefully it won't be
> hard to fix, just wanted to give you a heads up.

We (:sydpolk, :geo and me) actually run nightly steeplechase runs on servers in the QA lab.
I have not looked at the patch itself yet. I can give it a try on my local dev setup.

Comment 111

[Nils Ohlmeier [:drno]]

ahal thanks for the heads up.
I just tried the patch locally with my steeplechase dev setup. And it does not seem to cause any problems. Probably because steeplechase has its own logging.

Comment 112

[Ahmed Kachkach [:akachkach]]

Thanks for checking this :drno

After a dozen try runs and reading logs, we could finally find the error (which ended up being an issue with stdout/stderr being sometime interleaved on windows, especially on a high load of NSPR logging like it's the case for the WebRTC tests). We've experimented many solutions and the best one seems to add a special delimiter for structured logs (in addition to the line break) to separate them from the rest of the input.

I also fixed a couple issues I found while reading the patch to understand where that bug comes from (like handlers not being applied to buffered logs, etc.) and switched to showing "unstructured" logs (= dumped by tests and the browser) even when the buffering is activated, to keep the same output we had before.

Try run looks green so far: https://tbpl.mozilla.org/?tree=Try&rev=5ad0275be696

Comment 113

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

carry r+ forward

As said previously, this should fix the intermittent error we had with a particular WebRTC test ( "dom/media/tests/mochitest/test_peerConnection_offerRequiresReceiveAudio.html" ) because of the interleaved logs on Windows. This patch also logs all unstructured messages (from gecko or dumped with "dump") like it was the case in the previous buffering system. (this is just to keep compatibility, in the future we should probably buffer everything we can as the complete logs can be seen with SimpleTest.requestCompleteLog).

Comment 114

[Chris Manchester (limited bugmail, email directly)]

Comment on attachment 8456976 [details] [diff] [review]
0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

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

This looks good. Like we talked about maybe use a longer delimeter to avoid collisions. From everything that's been said so far, we're going to need to fix mozprocess and/or log over a socket or to a seperate file sooner rather than later.

Just so this is documented somewhere, the unparsed json we lost in context looked something like this:

18:26:00     INFO -  16825 INFO 0[1a2c8c90]: [GSM Task|tnp] ui.c:654: SIPCC-UI_API: 1/50, ui_set_call_status: the stat string =�
18:26:00     INFO -  16826 INFO 0[1a2c8c90]: [GSM Task|tnp] ui.c:616: SIPCC-UI_API: 1/50, ui_set_call_status_display: the stat string =�, timeout= 0, priority=0
18:26:00     INFO -  16827 INFO 0[1a2c8c90]: [GSM Task|tnp] ui.c:104: SIPCC-UI_API: 1/50, ui_call_state: event=1
18:26:00     INFO -  16828 INFO {"action":"test_start","time":1405387560056,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/media/tests/mochitest/test_peerConnection_offerRequiresReceiveAudio.html"}0[1a2c8c90]: [GSM Task|def] fsm.c:346: SIPCC-FSM: 1/50, fsm_change_state: DEF: STABLE -> CLOSED
18:26:00     INFO -  16829 INFO 0[1a2c8b40]: [CCAPP Task|def] ccprovider.c:1613: SIPCC-SIP_CC_PROV: ccappUpdateSessionData: Call_STATE:. state=1, attr=0, cause=5, instance=0
18:26:00     INFO -  16830 INFO 0[1a2c8c90]: [GSM Task|def] dcsm.c:397: SIPCC-DCSM: dcsm_update_gsm_state: 50 : DCSM_READY --> DCSM_READY
18:26:00     INFO -  16831 INFO 0[1a2c8b40]: [CCAPP Task|CC_SIPCCService] CC_SIPCCService.cpp:724: onCallEvent(CCAPI_CALL_EV_STATE, 10032, [ONHOOK|]

If I'm reading this correctly, the log we get interleaved with originates here: 

http://hg.mozilla.org/mozilla-central/annotate/f6e46d1fc903/media/webrtc/signaling/src/sipcc/core/gsm/fsm.c#l341

::: testing/mochitest/runtests.py
@@ +77,5 @@
> +### output processing
> +class MessageLogger(object):
> +    """File-like object for logging messages (structured logs)"""
> +    BUFFERING_THRESHOLD = 100
> +    DELIMITER = u'\uabba\u2edc'

This is worth a comment.

@@ +81,5 @@
> +    DELIMITER = u'\uabba\u2edc'
> +    BUFFERED_ACTIONS = set(['test_status', 'log'])
> +    VALID_ACTIONS = set(['suite_start', 'suite_end', 'test_start', 'test_end',
> +                         'test_status', 'process_output', 'log',
> +                         'buffering_on', 'buffering_off'])

Are we actually getting all these actions from js? Because the purpose of this set right now is to enforce invariants for logging in this harness, maybe leave out actions we don't expect to produce in the browser.

@@ +108,5 @@
> +                message = json.loads(fragment)
> +                if not self.valid_message(message):
> +                    message = dict(action='log', level='info', message=fragment, unstructured=True)
> +            except ValueError:
> +                message = dict(action='log', level='info', message=fragment, unstructured=True)

Maybe log these directly, right here, rather than keeping track of this "unstructured" parameter?

::: testing/specialpowers/content/MozillaLogger.js
@@ +4,5 @@
>  
>  function MozillaLogger(aPath) {
>  }
>  
> +var LOG_DELIMITER = String.fromCharCode(0xabba) + String.fromCharCode(0x2edc);

Also would comment here.

Comment 115

[Nils Ohlmeier [:drno]]

(In reply to Chris Manchester [:chmanchester] from comment #114)
> 18:26:00     INFO -  16828 INFO
> {"action":"test_start","time":1405387560056,"thread":null,"pid":null,
> "source":"mochitest","test":"/tests/dom/media/tests/mochitest/
> test_peerConnection_offerRequiresReceiveAudio.html"}0[1a2c8c90]: [GSM
> Task|def] fsm.c:346: SIPCC-FSM: 1/50, fsm_change_state: DEF: STABLE -> CLOSED
>
> If I'm reading this correctly, the log we get interleaved with originates
> here: 
> 
> http://hg.mozilla.org/mozilla-central/annotate/f6e46d1fc903/media/webrtc/
> signaling/src/sipcc/core/gsm/fsm.c#l341

Just to make sure we are all on the same page here: we get interleaved logs from stdout all the time. It is not specifically that line above which causes interleaved logs.
Locally I always specify a separate log file for NSPR to avoid interleaves. Not sure if that is something we should look into for build servers.

Comment 116

[Andrew Halberstadt [:ahal]]

(In reply to Nils Ohlmeier [:drno] from comment #115)
> Just to make sure we are all on the same page here: we get interleaved logs
> from stdout all the time. It is not specifically that line above which
> causes interleaved logs.
> Locally I always specify a separate log file for NSPR to avoid interleaves.
> Not sure if that is something we should look into for build servers.

Yes that's correct (though I wouldn't say "all the time"). If it can happen with NSPR it can happen with anything else that happens to use stdout in another thread. Making NSPR log elsewhere might help, but would still leave us open to this happening again in the future. I'd rather just fix it properly.

Comment 117

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

carry r+ forward
try run: https://tbpl.mozilla.org/?tree=Try&rev=5ad0275be696

Fixes the issues raised by chmanchester. (except that "unstructured" field that is temporarily added, should be fine for now)

Comment 118

[Nils Ohlmeier [:drno]]

(In reply to Andrew Halberstadt [:ahal] from comment #116)
> Yes that's correct (though I wouldn't say "all the time"). If it can happen
> with NSPR it can happen with anything else that happens to use stdout in
> another thread. Making NSPR log elsewhere might help, but would still leave
> us open to this happening again in the future. I'd rather just fix it
> properly.

Absolutely. I did not mean to suggest that a separate NSPR log file is a solution to the problem of interleaved log lines on stdout. This piece of code should do as much as it can to be prepared to handle interleaved output on stdout!
NSPR into a separate file was more a general suggestion to look into.

Comment 119

[Carsten Book [:Tomcat]]

seems this patch don't apply cleanly and failed when i was working on this c-n bug see:

applying 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch
patching file testing/specialpowers/content/MozillaLogger.js
Hunk #1 FAILED at 0
Hunk #3 FAILED at 70
2 out of 3 hunks FAILED -- saving rejects to file testing/specialpowers/content/MozillaLogger.js.rej
patch failed, unable to continue (try -v)
patch failed, rejects left in working dir

could you take a look and maybe rebase, thanks!

Comment 120

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

rebased the patch, sorry about that!

Comment 121

[Ryan VanderMeulen [:RyanVM]]

Still doesn't apply. Please make sure your tree is up to date before rebasing.

Comment 122

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-886570-Initial-integration-of-structured-logs-in.patch

rebased (this time I got the conflict with MozillaLogger.js and fixed it, so it should work fine).

Comment 123

[Carsten Book [:Tomcat]]

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

Comment 124

[Ryan VanderMeulen [:RyanVM]]

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