613023 - Add line numbers to the log messages generated by the browser chrome harness

Status: NEW

(Testing :: Mochitest, defect)

Description

[Dave Townsend [:mossop]]

Makes it easy to find the exact point in the file that generated it even when the same message is logged multiple times.

Comment 1

[Dave Townsend [:mossop]]

Attachment: patch rev 1

This includes the exact file and line with each logged message, it is either the line that called the logging function or it is the line that generated the exception passed to the logging function.

One downside here is that sometimes the file is not the main test file, can be in the head file or anything else included f.e. This could make it harder to identify the exact test that was running from the tinderbox summary.

Another potential problem is that this might break anything that tries to parse our log files (brasstacks f.e.).

Comment 2

[Dave Townsend [:mossop]]

Attachment: example log

This is an example of what is generated

Comment 3

[:Gavin Sharp [email: [e-mail]]]

Comment on attachment 491318 [details] [diff] [review]
patch rev 1

I think we shouldn't switch away from using this.path, it's going to confuse too many people. Perhaps we should only include this information for failing tests, on a separate line?

Comment 4

[Dave Townsend [:mossop]]

Attachment: patch rev 2

So something like this. Not sure about the output, currently it is like this:

TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/mozapps/extensions/test/browser/browser_list.js | Name should be correct - Got Test add-on, expected Tesst add-on
AT chrome://mochitests/content/browser/toolkit/mozapps/extensions/test/browser/browser_list.js:131

I presume that starting the second line with TEST-UNEXPECTED-FAIL would lead to over-counting fails so I went with something different. I guess with a but of work it is probably possible to get a full stack for the failures too.

Comment 5

[:Gavin Sharp [email: [e-mail]]]

Comment on attachment 531790 [details] [diff] [review]
patch rev 2

>diff --git a/testing/mochitest/browser-harness.xul b/testing/mochitest/browser-harness.xul

>       addResult: function addResult(result) {

>+        if (!result.info && !result.pass)
>+          this.dumper.dump("AT " + result.fileName + ":" + result.lineNumber + "\n");

maybe prefix with a \t?

>diff --git a/testing/mochitest/browser-test.js b/testing/mochitest/browser-test.js

>+  if (aDiag && typeof aDiag == "object" && "fileName" in aDiag) {
>+    // we have an exception use it for filename and linenumber information
>+    this.fileName = aDiag.fileName;
>+    this.lineNumber = aDiag.lineNumber;
>+  }
>+  else {
>+    var frame = Components.stack.caller.caller.caller;
>+    this.fileName = frame.filename;
>+    this.lineNumber = frame.lineNumber;
>+  }

I wonder whether we should bother with the special handling of aDiag - it's a bit odd to use a different source for the lineNumber/fileName only for certain cases, particularly since that information from the exception should be printed in its toString (which is appended to this.msg). I'm not sure in which cases exactly they would differ.

> function testMessage(aName) {

>+  var frame = Components.stack.caller.caller;
>+  this.fileName = frame.filename;
>+  this.lineNumber = frame.lineNumber;

Not sure this is useful given that they're never used (this.info is true), but I suppose it doesn't hurt.

>diff --git a/toolkit/mozapps/extensions/test/browser/browser_list.js b/toolkit/mozapps/extensions/test/browser/browser_list.js

Doesn't look related to this patch :)

Comment 6

[:Gavin Sharp [email: [e-mail]]]

(In reply to comment #5)
> >diff --git a/toolkit/mozapps/extensions/test/browser/browser_list.js b/toolkit/mozapps/extensions/test/browser/browser_list.js
> 
> Doesn't look related to this patch :)

Oh I see, you were using it to tesst!

Comment 7

[Dave Townsend [:mossop]]

(In reply to comment #5)
> >diff --git a/testing/mochitest/browser-test.js b/testing/mochitest/browser-test.js
> 
> >+  if (aDiag && typeof aDiag == "object" && "fileName" in aDiag) {
> >+    // we have an exception use it for filename and linenumber information
> >+    this.fileName = aDiag.fileName;
> >+    this.lineNumber = aDiag.lineNumber;
> >+  }
> >+  else {
> >+    var frame = Components.stack.caller.caller.caller;
> >+    this.fileName = frame.filename;
> >+    this.lineNumber = frame.lineNumber;
> >+  }
> 
> I wonder whether we should bother with the special handling of aDiag - it's
> a bit odd to use a different source for the lineNumber/fileName only for
> certain cases, particularly since that information from the exception should
> be printed in its toString (which is appended to this.msg). I'm not sure in
> which cases exactly they would differ.

They'll differ because the exception can be thrown from a different link to that that adds the test result (see the exception catching from running the test f.e.). The exception line is likely more interesting.

Comment 8

[Dave Townsend [:mossop]]

Attachment: patch rev 3

Wanted to quickly confirm you're ok with what I said above, also added printing of exceptions from executeSoon callbacks here

Comment 9

[:Gavin Sharp [email: [e-mail]]]

Comment on attachment 532056 [details] [diff] [review]
patch rev 3

(In reply to comment #7)
> The exception line is likely more interesting.

Right, but the exception line shows up either way, since we print the exception entirely, right? It just seems odd to have the source of the actual line number differ in the case where there's an exception. But that's probably fine I guess.

>diff --git a/testing/mochitest/browser-test.js b/testing/mochitest/browser-test.js

>   this.executeSoon = function test_executeSoon(func) {
>     let tm = Cc["@mozilla.org/thread-manager;1"].getService(Ci.nsIThreadManager);
> 
>     tm.mainThread.dispatch({
>       run: function() {
>+        try {
>+          func();
>+        } catch (ex) {
>+          self.__brwoserTest.addResult(new testResult(false, "Exception thrown",
>+                                                      ex, false));

This isn't going to work until the brwoser-chrome harness is up and running. Also I don't think "self" is defined here.

Comment 10

[Sylvestre Ledru [:Sylvestre]]

No assignee, updating the status.

Comment 11

[Sylvestre Ledru [:Sylvestre]]

No assignee, updating the status.