481406 - browser chrome test harness should report console errors (e.g. javascript exceptions) as real test errors

Status: VERIFIED FIXED

(Testing :: Mochitest, defect)

Description

[Marco Bonardo [:mak]]

Attachment: patch v1.0

spunf-off from bug 474081.
try executing the following browser-chrome test:

function test() {
  waitForExplicitFinish();

  function finish_test() {
    throw("test");
    finish(); 
  }

  setTimeout(finish_test,1);
}

"test" exception is caught in the error console, but the test log only reports "Timed Out", that is not a useful information.

This patch adds a message to the test log reporting any error seen in the console.But i could also change it to only look for "uncaught exception"s.
Taking this patch would force us to catch exceptions that tests could throw (this means some test could start failing after this).

I'd like to have ideas/suggestions about this approach.

A run in browser/base/content tests shows 11 failures:

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/../browser/browser/base/content/test/browser_bug422590.js | [JavaScript Error: "repositionDialog is not defined" {file: "chrome://global/content/customizeToolbar.js" line: 16}]

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/../browser/browser/base/content/test/browser_feed_tab.js | [JavaScript Error: "uncaught exception: [Exception... "'[JavaScript Error: "elem.ownerDocument.defaultView is null" {file: "chrome://browser/content/pageinfo/pageInfo.js" line: 567}]' when calling method: [nsIDOMNodeFilter::acceptNode]"  nsresult: "0x80570021 (NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS)"  location: "JS frame :: chrome://browser/content/pageinfo/pageInfo.js :: doGrab :: line 501"  data: yes]"]

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/../browser/browser/base/content/test/browser_page_style_menu.js | [JavaScript Error: "[Exception... "'JavaScript component does not have a method named: "observe"' when calling method: [nsIObserver::observe]"  nsresult: "0x80570030 (NS_ERROR_XPC_JSOBJECT_HAS_NO_FUNCTION_NAMED)"  location: "JS frame :: file:///c:/obj-i686-pc-mingw32/browser/dist/bin/components/nsSearchService.js :: notifyAction :: line 667"  data: no]" {file: "file:///c:/obj-i686-pc-mingw32/browser/dist/bin/components/nsSearchService.js" line: 667}]

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/../browser/browser/base/content/test/browser_page_style_menu.js | [JavaScript Error: "[Exception... "'JavaScript component does not have a method named: "observe"' when calling method: [nsIObserver::observe]"  nsresult: "0x80570030 (NS_ERROR_XPC_JSOBJECT_HAS_NO_FUNCTION_NAMED)"  location: "JS frame :: file:///c:/obj-i686-pc-mingw32/browser/dist/bin/components/nsSearchService.js :: notifyAction :: line 667"  data: no]" {file: "file:///c:/obj-i686-pc-mingw32/browser/dist/bin/components/nsSearchService.js" line: 667}]

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/../browser/browser/base/content/test/browser_page_style_menu.js | [JavaScript Error: "[Exception... "'JavaScript component does not have a method named: "observe"' when calling method: [nsIObserver::observe]"  nsresult: "0x80570030 (NS_ERROR_XPC_JSOBJECT_HAS_NO_FUNCTION_NAMED)"  location: "JS frame :: file:///c:/obj-i686-pc-mingw32/browser/dist/bin/components/nsSearchService.js :: notifyAction :: line 667"  data: no]" {file: "file:///c:/obj-i686-pc-mingw32/browser/dist/bin/components/nsSearchService.js" line: 667}]

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/../browser/browser/base/content/test/browser_page_style_menu.js | [JavaScript Error: "[Exception... "'JavaScript component does not have a method named: "observe"' when calling method: [nsIObserver::observe]"  nsresult: "0x80570030 (NS_ERROR_XPC_JSOBJECT_HAS_NO_FUNCTION_NAMED)"  location: "JS frame :: file:///c:/obj-i686-pc-mingw32/browser/dist/bin/components/nsSearchService.js :: notifyAction :: line 667"  data: no]" {file: "file:///c:/obj-i686-pc-mingw32/browser/dist/bin/components/nsSearchService.js" line: 667}]

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/../browser/browser/base/content/test/browser_page_style_menu.js | [JavaScript Error: "[Exception... "'JavaScript component does not have a method named: "observe"' when calling method: [nsIObserver::observe]"  nsresult: "0x80570030 (NS_ERROR_XPC_JSOBJECT_HAS_NO_FUNCTION_NAMED)"  location: "JS frame :: file:///c:/obj-i686-pc-mingw32/browser/dist/bin/components/nsSearchService.js :: notifyAction :: line 667"  data: no]" {file: "file:///c:/obj-i686-pc-mingw32/browser/dist/bin/components/nsSearchService.js" line: 667}]

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/../browser/browser/base/content/test/browser_page_style_menu.js | [JavaScript Error: "[Exception... "'JavaScript component does not have a method named: "observe"' when calling method: [nsIObserver::observe]"  nsresult: "0x80570030 (NS_ERROR_XPC_JSOBJECT_HAS_NO_FUNCTION_NAMED)"  location: "JS frame :: file:///c:/obj-i686-pc-mingw32/browser/dist/bin/components/nsSearchService.js :: notifyAction :: line 667"  data: no]" {file: "file:///c:/obj-i686-pc-mingw32/browser/dist/bin/components/nsSearchService.js" line: 667}]

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/../browser/browser/base/content/test/browser_page_style_menu.js | [JavaScript Error: "[Exception... "'JavaScript component does not have a method named: "observe"' when calling method: [nsIObserver::observe]"  nsresult: "0x80570030 (NS_ERROR_XPC_JSOBJECT_HAS_NO_FUNCTION_NAMED)"  location: "JS frame :: file:///c:/obj-i686-pc-mingw32/browser/dist/bin/components/nsSearchService.js :: notifyAction :: line 667"  data: no]" {file: "file:///c:/obj-i686-pc-mingw32/browser/dist/bin/components/nsSearchService.js" line: 667}]

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/../browser/browser/base/content/test/browser_page_style_menu.js | [JavaScript Error: "[Exception... "'JavaScript component does not have a method named: "observe"' when calling method: [nsIObserver::observe]"  nsresult: "0x80570030 (NS_ERROR_XPC_JSOBJECT_HAS_NO_FUNCTION_NAMED)"  location: "JS frame :: file:///c:/obj-i686-pc-mingw32/browser/dist/bin/components/nsSearchService.js :: notifyAction :: line 667"  data: no]" {file: "file:///c:/obj-i686-pc-mingw32/browser/dist/bin/components/nsSearchService.js" line: 667}]

TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/../browser/browser/base/content/test/browser_page_style_menu.js | [JavaScript Error: "[Exception... "'JavaScript component does not have a method named: "observe"' when calling method: [nsIObserver::observe]"  nsresult: "0x80570030 (NS_ERROR_XPC_JSOBJECT_HAS_NO_FUNCTION_NAMED)"  location: "JS frame :: file:///c:/obj-i686-pc-mingw32/browser/dist/bin/components/nsSearchService.js :: notifyAction :: line 667"  data: no]" {file: "file:///c:/obj-i686-pc-mingw32/browser/dist/bin/components/nsSearchService.js" line: 667}]

Comment 1

[Dave Townsend [:mossop]]

Using a getter for the console service doesn't seem worthwhile, it will be called once for every test anyway, just get the console service once somewhere more global, otherwise looks good

Comment 3

[(not currently active) Ted Mielczarek]

We should get a full list of exceptions we hit in a browser test run, and get bugs filed on all the unique exceptions. The nsSearchService.js one is already filed as bug 433796.

Comment 4

[Marco Bonardo [:mak]]

Attachment: patch v1.1

removed useless getter, and fixed a comment.

Comment 5

[Marco Bonardo [:mak]]

(In reply to comment #3)
> We should get a full list of exceptions we hit in a browser test run, and get
> bugs filed on all the unique exceptions.

Yes, i'll try to get a list of exceptions on a clobber build to attach here, then i hope to get some help filing all the dependancies.

Comment 6

[Marco Bonardo [:mak]]

Attachment: txt list of failures

This the list of failures from a complete browser-chrome run
total 124 errors, 10 unique sources.
For each test i've also reported the PASS so maybe it's easier to find the point where we fail.

Comment 7

[Marco Bonardo [:mak]]

i've filed a bug for each unique error i see in the above list, see dependancies.

Comment 8

[Dave Townsend [:mossop]]

I think we actually should be providing a way for some browser chrome tests to opt out of this. I'm writing a test at the moment which is added errors to the console perfectly validly. It is testing failure cases where additional information is provided for developers in the console.

Comment 9

[Marco Bonardo [:mak]]

What if we look for the Exception word, common errors would be discarded and only exceptions would be reported.
Or you could report messages/warnings to the console instead of errors.

Comment 10

[Dave Townsend [:mossop]]

We could perhaps do the former. I think though just an explicit opt-out might be better or I suspect we'll miss some cases. The design of the test harness shouldn't influence how a piece of code can report problems. Saying that logging an error to the the console is never ok is just plain wrong, there are plenty of cases where it is the right thing to do.

Comment 11

[Serge Gautherie (:sgautherie)]

Doing this for Browser Chrome is good news :-)
Later, could the other test suites have the same, or is there something which prevents that ?

Comment 12

[Serge Gautherie (:sgautherie)]

Comment on attachment 365428 [details] [diff] [review]
patch v1.1

>+    // nsIScriptError.flags is not realiable, some error and warning could be

Nit: s/realiable/reliable/

Comment 13

[Dave Townsend [:mossop]]

Attachment: logging patch

While I think there are still questions to be answered about making console errors into test failures I think it would be very useful to at least include them in the log for now. I have an intermittent failure that I'm pretty sure I can get more information on by seeing what is going to the error console.

This is a derivation of the previous patch, fixes a few issues with it and adds support for a TEST-INFO line in the logs and makes console messages get printed there. I think this is also useful for just general logging in tests where at the moment I use ok to log messages that aren't really test passes.

Comment 14

[Serge Gautherie (:sgautherie)]

Comment on attachment 377444 [details] [diff] [review]
logging patch

>+testResult.prototype = {
>+testMessage.prototype = {

It looks like testResult.prototype could be modified to handle testMessage.prototype case too...

Comment 15

[Serge Gautherie (:sgautherie)]

(In reply to comment #13)

> support for a TEST-INFO line in the logs

The (more general) idea seems interesting,
though I wonder whether reusing 'todo' would be enough in this bug context?

Comment 16

[Dave Townsend [:mossop]]

(In reply to comment #14)
> (From update of attachment 377444 [details] [diff] [review])
> >+testResult.prototype = {
> >+testMessage.prototype = {
> 
> It looks like testResult.prototype could be modified to handle
> testMessage.prototype case too...

It could, but I think they are suitably different that it is just easier and cleaner to do it separately.

(In reply to comment #15)
> (In reply to comment #13)
> 
> > support for a TEST-INFO line in the logs
> 
> The (more general) idea seems interesting,
> though I wonder whether reusing 'todo' would be enough in this bug context?

Todo has different semantics indicating something that you intend to fix in the future. That isn't the case for general log messages which are mainly useful so you can see where you are in the test in case something goes wrong, and not really true for console messages which may well be correct.

Comment 17

[Marco Bonardo [:mak]]

the approach looks promising, and probably has lowest targetted time than marking them as failures... i guess if we should go for it and discard initial idea... fixing all of the actual dependancies could take too long.

Comment 18

[Shawn Wilsher :sdwilsh]

Comment on attachment 377444 [details] [diff] [review]
logging patch

>+function testMessage(aPath, aMessage) {
>+  aMessage = aMessage || "";
>+
>+  this.info = true;
>+  this.path = aPath;
>+  this.msg = aMessage;
I know other existing code does it like this, but just do:
this.msg = aMessage || ""; here please

gavin indicated that I should do this review, but I'm not sure if that means that's all that is needed.  r=sdwilsh with these changes, and check with him if you still need his review.

Comment 19

[Marco Bonardo [:mak]]

I'm reassigning to Dave since i think his approach is feasible, while mine has a too far target.

Plus the fact if we report assertions and we fix bug 492467, those will be clearly visible to everyone. Gavin said he wants to fix that soon, to help solving some of the oranges, that will provide realtime dumps of test results while the tests are running, allowing to see exactly where we fail (or at least a better guess).

Comment 20

[Marco Bonardo [:mak]]

ops sorry for typos, clearly s/assertions/exceptions/

Comment 21

[Dave Townsend [:mossop]]

Comment on attachment 377444 [details] [diff] [review]
logging patch

I'm pretty sure gavin just meant you to review it so I've pushed this to trunk. Will land on branch if things look ok.

http://hg.mozilla.org/mozilla-central/rev/ddd616e58309

Comment 22

[Dave Townsend [:mossop]]

And backed out. We really need to update whatever generates tinderbox's short log before this can go in

Comment 23

[Serge Gautherie (:sgautherie)]

(In reply to comment #22)

See
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1243503681.1243510424.25713.gz
Linux mozilla-central unit test on 2009/05/28 02:41:21
as an example.

You could use Todo (or Pass) in the meantime...

Comment 24

[Dave Townsend [:mossop]]

(In reply to comment #23)
> (In reply to comment #22)
> 
> See
> http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1243503681.1243510424.25713.gz
> Linux mozilla-central unit test on 2009/05/28 02:41:21
> as an example.
> 
> You could use Todo (or Pass) in the meantime...

Actually no, due to how the brief log parser works that still wouldn't help.

Comment 25

[Dave Townsend [:mossop]]

Attachment: brief log parser patch rev 1 [Checkin: Comment 26]

This brief log has a long list of things that it will look for in a line to see if it has an error. One of them is "Error" which most console error messages have. This adds a filter to make the brief log ignore any line containing "TEST-INFO ".

Comment 26

[Dave Townsend [:mossop]]

Comment on attachment 380404 [details] [diff] [review]
brief log parser patch rev 1
[Checkin: Comment 26]

Checked this in to CVS

Comment 27

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

Comment on attachment 377444 [details] [diff] [review]
logging patch

Had a chance to look over this finally, thankfully it doesn't conflict much with my patch for bug 492467.

Only thing I'm not so keen about is the change to pass in .path for each testResult. It doesn't seem necessary - couldn't testMessage could just set it's .result appropriately? I guess the other difference is what class it gets in the HTML version, but we can just have it set .pass to true (for now), and add some logic in browserTestFile.htmlLog that checks .info in the future if we have a desire to style those differently, right?

Comment 28

[Dave Townsend [:mossop]]

Attachment: logging rev 2

Updated to trunk and stopped passing the path into the test results. Still using a separate testMessage since most of the arguments to testResult don't make sense there.

Comment 29

[Dave Townsend [:mossop]]

Attachment: logging rev 2 [Checkin: See comment 32 & 33]

This is the right one

Comment 30

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

Comment on attachment 383253 [details] [diff] [review]
logging rev 2
[Checkin: See comment 32 & 33]

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

>   this.todo_is = function test_todo_is(a, b, name) {

>   this.todo_isnot = function test_todo_isnot(a, b, name) {

>+  this.info = function(name) {

Name this one to match the others?

Comment 31

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

I noticed some other tests that use dump directly:

http://mxr.mozilla.org/mozilla-central/search?string=dump(&find=browser_

Should probably convert those too?

Comment 32

[Dave Townsend [:mossop]]

Landed: http://hg.mozilla.org/mozilla-central/rev/b7bb6c6689b2

Will follow up with a patch to change other uses of dump in browser chrome tests in a bit.

Comment 33

[Dave Townsend [:mossop]]

And on branch: http://hg.mozilla.org/releases/mozilla-1.9.1/rev/72a63125ceb9

Comment 34

[Dave Townsend [:mossop]]

Attachment: stop dumping

Comment 35

[Marco Bonardo [:mak]]

Comment on attachment 386956 [details] [diff] [review]
stop dumping

>diff --git a/browser/components/places/tests/browser/browser_bookmarksProperties.js b/browser/components/places/tests/browser/browser_bookmarksProperties.js

> function test() {
>-  dump("Starting test browser_bookmarksProperties.js\n");
>+  info("Starting test browser_bookmarksProperties.js");

This is no more needed, since now tests output is no more buffered, we can simply remove it.

> function runNextTest() {
>   // Cleanup from previous test.
>   if (gCurrentTest) {
>     gCurrentTest.cleanup();
>-    ok(true, "*** FINISHED TEST ***");
>+    info("*** FINISHED TEST ***");

please replace with "End of test: " + gCurrentTest.desc

>   }
> 
>   if (gTests.length > 0) {
>     // Goto next tests.
>     gCurrentTest = gTests.shift();
>-    ok(true, "*** TEST: " + gCurrentTest.desc);
>-    dump("*** TEST: " + gCurrentTest.desc + "\n");
>+    info("*** TEST: " + gCurrentTest.desc);

please replace with "Start of test: " + gCurrentTest.desc

>diff --git a/browser/components/places/tests/browser/browser_drag_bookmarks_on_toolbar.js b/browser/components/places/tests/browser/browser_drag_bookmarks_on_toolbar.js
>--- a/browser/components/places/tests/browser/browser_drag_bookmarks_on_toolbar.js
>+++ b/browser/components/places/tests/browser/browser_drag_bookmarks_on_toolbar.js
>@@ -234,18 +234,17 @@ var gTests = [
>       PlacesUtils.bookmarks.removeItem(itemId);
>     }
>   },
> ];
> 
> function nextTest() {
>   if (gTests.length) {
>     var test = gTests.shift();
>-    dump("TEST: " + test.desc + "\n");
>-    ok(true, "TEST: " + test.desc);
>+    info("TEST: " + test.desc);

please replace with "Start of test: " + test.desc

>diff --git a/browser/components/places/tests/browser/browser_library_left_pane_commands.js b/browser/components/places/tests/browser/browser_library_left_pane_commands.js

> function nextTest() {
>   if (gTests.length) {
>     var test = gTests.shift();
>-    ok(true, "TEST: " + test.desc);
>-    dump("TEST: " + test.desc + "\n");
>+    info("TEST: " + test.desc);

ditto


>@@ -189,17 +188,17 @@ var windowObserver = {
>           nextTest();
>         });
>       }, false);
>     }
>   }
> };
> 
> function test() {
>-  dump("Starting test browser_library_left_pane_commands.js\n");
>+  info("Starting test browser_library_left_pane_commands.js");

no more needed

>diff --git a/browser/components/places/tests/browser/browser_library_middleclick.js b/browser/components/places/tests/browser/browser_library_middleclick.js
>--- a/browser/components/places/tests/browser/browser_library_middleclick.js
>+++ b/browser/components/places/tests/browser/browser_library_middleclick.js
>@@ -249,17 +249,17 @@ gTests.push({
>     PlacesUtils.bookmarks.removeItem(this._queryId);
>   }
> });
> 
> //------------------------------------------------------------------------------
> 
> function test() {
>   waitForExplicitFinish();
>-  dump("Starting test browser_library_middleclick.js\n");
>+  info("Starting test browser_library_middleclick.js");

no more needed

>@@ -296,18 +296,17 @@ function test() {
> function runNextTest() {
>   // Cleanup from previous test.
>   if (gCurrentTest)
>     gCurrentTest.cleanup();
> 
>   if (gTests.length > 0) {
>     // Goto next test.
>     gCurrentTest = gTests.shift();
>-    ok(true, "*** TEST: " + gCurrentTest.desc);
>-    dump("*** TEST: " + gCurrentTest.desc + "\n");
>+    info("*** TEST: " + gCurrentTest.desc);

ditto

>diff --git a/browser/components/places/tests/browser/browser_views_liveupdate.js b/browser/components/places/tests/browser/browser_views_liveupdate.js
>--- a/browser/components/places/tests/browser/browser_views_liveupdate.js
>+++ b/browser/components/places/tests/browser/browser_views_liveupdate.js
>@@ -38,17 +38,17 @@
> /**
>  * Tests Places views (menu, toolbar, tree) for liveupdate.
>  */
> 
> const Cc = Components.classes;
> const Ci = Components.interfaces;
> 
> function test() {
>-  dump("Starting test browser_views_liveupdate.js\n");
>+  info("Starting test browser_views_liveupdate.js");

no more needed

r=me with the above

Comment 36

[Dave Townsend [:mossop]]

Attachment: stop dumping [Checkin: Comment 37]

Comment 37

[Dave Townsend [:mossop]]

Landed:

http://hg.mozilla.org/mozilla-central/rev/b4fee3813956
http://hg.mozilla.org/releases/mozilla-1.9.1/rev/c21d4f5fb12a

Comment 38

[Serge Gautherie (:sgautherie)]

V.Fixed & verified1.9.1, per tinderbox logs.

Comment 39

[Serge Gautherie (:sgautherie)]

(In reply to comment #11)
> Later, could the other test suites have the same, or is there something which
> prevents that ?

I filed bug 502603, to start with.