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

VERIFIED FIXED in mozilla1.9.2a1

Status

Testing
Mochitest
VERIFIED FIXED
9 years ago
3 months ago

People

(Reporter: mak, Assigned: mossop)

Tracking

(Blocks: 1 bug, {verified1.9.1.1})

Trunk
mozilla1.9.2a1
verified1.9.1.1
Points:
---
Dependency tree / graph
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(4 attachments, 5 obsolete attachments)

Created attachment 365426 [details] [diff] [review]
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}]
(Assignee)

Comment 1

9 years ago
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
(Assignee)

Updated

9 years ago
Duplicate of this bug: 456890
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.
Depends on: 433796
Created attachment 365428 [details] [diff] [review]
patch v1.1

removed useless getter, and fixed a comment.
Attachment #365426 - Attachment is obsolete: true
(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.
Blocks: 474081
Created attachment 365450 [details]
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.
Depends on: 481437
Depends on: 481438
Depends on: 481439
Depends on: 481441
Depends on: 481442
Depends on: 481443
Depends on: 481446
i've filed a bug for each unique error i see in the above list, see dependancies.
No longer depends on: 481442
(Assignee)

Comment 8

9 years ago
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.
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.
(Assignee)

Comment 10

9 years ago
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.
Doing this for Browser Chrome is good news :-)
Later, could the other test suites have the same, or is there something which prevents that ?
Version: unspecified → Trunk
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/
(Assignee)

Comment 13

9 years ago
Created attachment 377444 [details] [diff] [review]
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.
Attachment #377444 - Flags: review?(gavin.sharp)
Attachment #365428 - Attachment is obsolete: true
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...
(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?
(Assignee)

Comment 16

9 years ago
(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.
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 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.
Attachment #377444 - Flags: review+
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).
Assignee: mak77 → dtownsend
ops sorry for typos, clearly s/assertions/exceptions/
(Assignee)

Updated

9 years ago
Attachment #377444 - Flags: review?(gavin.sharp)
(Assignee)

Comment 21

9 years ago
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
(Assignee)

Comment 22

9 years ago
And backed out. We really need to update whatever generates tinderbox's short log before this can go in
(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...
(Assignee)

Comment 24

9 years ago
(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.
(Assignee)

Comment 25

9 years ago
Created attachment 380404 [details] [diff] [review]
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 ".
Attachment #380404 - Flags: review?
(Assignee)

Updated

9 years ago
Attachment #380404 - Flags: review? → review?(cls)

Updated

9 years ago
Attachment #380404 - Flags: review?(cls) → review+
(Assignee)

Comment 26

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

Checked this in to CVS
Attachment #380404 - Attachment description: brief log parser patch rev 1 → brief log parser patch rev 1 [checked in]
(Assignee)

Updated

9 years ago
Depends on: 496604
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?
(Assignee)

Comment 28

9 years ago
Created attachment 383251 [details] [diff] [review]
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.
Attachment #377444 - Attachment is obsolete: true
Attachment #383251 - Flags: review?(gavin.sharp)
(Assignee)

Comment 29

9 years ago
Created attachment 383253 [details] [diff] [review]
logging rev 2
[Checkin: See comment 32 & 33]

This is the right one
Attachment #383251 - Attachment is obsolete: true
Attachment #383253 - Flags: review?(gavin.sharp)
Attachment #383251 - Flags: review?(gavin.sharp)
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?
Attachment #383253 - Flags: review?(gavin.sharp) → review+
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?
Summary: browser chrome test harness should report console errors as real test errors → browser chrome test harness should report console errors (e.g. javascript exceptions) as real test errors
Blocks: 481438
No longer depends on: 481438
(Assignee)

Comment 32

9 years ago
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.
(Assignee)

Comment 34

9 years ago
Created attachment 386956 [details] [diff] [review]
stop dumping
Attachment #386956 - Flags: review?(sdwilsh)
Attachment #386956 - Flags: review?(sdwilsh) → review+
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
(Assignee)

Comment 36

9 years ago
Created attachment 386959 [details] [diff] [review]
stop dumping
[Checkin: Comment 37]
Attachment #386956 - Attachment is obsolete: true
Attachment #386959 - Flags: review+
(Assignee)

Comment 37

9 years ago
Landed:

http://hg.mozilla.org/mozilla-central/rev/b4fee3813956
http://hg.mozilla.org/releases/mozilla-1.9.1/rev/c21d4f5fb12a
Status: ASSIGNED → RESOLVED
Last Resolved: 9 years ago
Resolution: --- → FIXED
No longer blocks: 431503
No longer blocks: 494397
No longer blocks: 483391
No longer blocks: 488745
No longer depends on: 481437, 481439, 481441, 481443, 481446
Blocks: 433796
No longer depends on: 433796
Blocks: 310955
No longer depends on: 310955
Attachment #386959 - Attachment description: stop dumping → stop dumping [Checkin: Comment 37]
Attachment #380404 - Attachment description: brief log parser patch rev 1 [checked in] → brief log parser patch rev 1 [Checkin: Comment 26]
Attachment #383253 - Attachment description: logging rev 2 → logging rev 2 [Checkin: Comment 32 & 33]
Attachment #383253 - Attachment description: logging rev 2 [Checkin: Comment 32 & 33] → logging rev 2 [Checkin: See comment 32 & 33]
V.Fixed & verified1.9.1, per tinderbox logs.
Status: RESOLVED → VERIFIED
Flags: in-testsuite+
Keywords: verified1.9.1
Whiteboard: [fixed1.9.1+]
Target Milestone: --- → mozilla1.9.2a1
(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.
Keywords: verified1.9.1 → verified1.9.1.1
Whiteboard: [fixed1.9.1+]
Component: BrowserTest → Mochitest
Product: Testing → Testing
You need to log in before you can comment on or make changes to this bug.