742766 - Application errors in Error Console cause tests to fail

Status: RESOLVED FIXED

(Testing Graveyard :: Mozmill, defect)

Description

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Attachment: Console log with failure

I get the following error regularly when running a Mozmill test using a build from master:

ERROR | Test Failure: {"message": "[JavaScript Error: \"TelemetryStopwatch: key \"FX_SESSION_RESTORE_COLLECT_DATA_MS\" was already initialized\" {file: \"resource://gre/modules/TelemetryStopwatch.jsm\" line: 53}]"}

It appears that if this occurs early in the test that it causes the test to fail. I have attached two console logs, one where the error occurs, and one where it does not.

Comment 1

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Attachment: Console log without failure

Comment 2

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Initial reproduced in: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.7; rv:14.0) Gecko/20120404 Firefox/14.0a1

Also replicated in: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.7; rv:13.0) Gecko/20120404 Firefox/13.0a2

Unable to replicate in: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.7; rv:12.0) Gecko/20100101 Firefox/12.0

Comment 3

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Taras: Can you provide more details regarding this exception? Is there a way I can trigger it to assist me in replicating the issue?

Comment 4

[Nathan Froyd [:froydnj]]

I think Felipe (CC'd) wrote the code here, so he'd have a better shot than Taras of answering your question.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Dave, does it only apply to Mozmill 2 or even for Mozmill 1.5.x?

Comment 6

[Dave Hunt [:davehunt] [he/him] ⌚BST]

This was initially reported against master. It also occurs on hotfix-2.0, although the results appear differently due to bug 743050. I am unable to replicate the issue with hotfix-1.5.

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+2]]

So this reported error in the console doesn't cause a test to fail:

TEST-PASS | ../../mozmill-tests/nightly/tests/functional/testTabbedBrowsing/testNewTab.js | testNewTab
TEST-START | ../../mozmill-tests/nightly/tests/functional/testTabbedBrowsing/testNewTab.js | teardownModule
ERROR | Test Failure: {"message": "[JavaScript Error: \"TelemetryStopwatch: key \"FX_SESSION_RESTORE_COLLECT_DATA_MS\" was already initialized\" {file: \"resource://gre/modules/TelemetryStopwatch.jsm\" line: 53}]"}
INFO | Passed: 1
INFO | Failed: 0
INFO | Skipped: 0

It's simply listed as failure in the console nothing more. Dave, can you please verify that?

Comment 8

[Dave Hunt [:davehunt] [he/him] ⌚BST]

See my attached logs. A single test would apparently only fail if this had been logged to the console. Not sure what you're doing differently. I can attempt to reproduce this with latest from master.

Comment 9

[Dave Hunt [:davehunt] [he/him] ⌚BST]

I have rerun this and still see the same issue, even with the latest upstream code and using the same test from comment 7. In comment 7 the TelemetryStopwatch error occurred after the TEST-PASS. It seems if it occurs before the test it causes the overall result to be failed. Please rerun a few times to see if you can replicate it.

Comment 10

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Ok, so I can reproduce it with the test you have used for. It's a question when the TelemetryStopwatch exception is happening. The test only fails when the actual test method is executed at this time. In some cases it happened for me when teardownModule was running and the test passed.

Comment 11

[Jeff Hammel]

I haven't seen this cause  test failure.  While I do see the error, it doesn't cause the test to fail (fwiw, nightly/linux):

<snip/>
TEST-START | tests/functional/testAddons/testManagerKeyboardShortcut.js | teardownModule
INFO | Step Pass: {"function": "MozMillElement.click()"}
INFO | Step Pass: {"function": "controller.waitFor()"}
ERROR | Test Failure: {"message": "[JavaScript Error: \"TelemetryStopwatch: key \"FX_SESSION_RESTORE_COLLECT_DATA_MS\" was already initialized\" {file: \"resource://gre/modules/TelemetryStopwatch.jsm\" line: 53}]"}
RESULTS | Passed: 1
RESULTS | Failed: 0
RESULTS | Skipped: 0

Comment 12

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Attachment: Reduced test case

Reduced test attached. It appears to be caused by opening/closing the addons manager. There also appears to be

Comment 13

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Submitting the last comment too soon...

There also appears to be another failure in the console with this reduced test. The console log is below:

$ mozmill -t tests/functional/testBug742766.js -b /Applications/FirefoxNightly.app/
TEST-START | tests/functional/testBug742766.js | setupModule
TEST-START | tests/functional/testBug742766.js | testBug742766
INFO | Step Pass: {"function": "MozMillElement.keypress()"}
ERROR | Test Failure: {"message": "[JavaScript Error: \"TelemetryStopwatch: key \"FX_SESSION_RESTORE_COLLECT_DATA_MS\" was already initialized\" {file: \"resource://gre/modules/TelemetryStopwatch.jsm\" line: 53}]"}
INFO | Step Pass: {"function": "MozMillElement.keypress()"}
TEST-UNEXPECTED-FAIL | tests/functional/testBug742766.js | testBug742766
ERROR | Test Failure: {"message": "[JavaScript Error: \"this._messages is null\" {file: \"resource://gre/modules/DOMRequestHelper.jsm\" line: 88}]"}
ERROR | Test Failure: {"message": "[JavaScript Error: \"TelemetryStopwatch: key \"FX_SESSION_RESTORE_COLLECT_DATA_MS\" was already initialized\" {file: \"resource://gre/modules/TelemetryStopwatch.jsm\" line: 53}]"}
RESULTS | Passed: 0
RESULTS | Failed: 1
RESULTS | Skipped: 0

Comment 14

[cmtalbert]

This has to be fixed by the Firefox and/or telemetry guys. Looks like that is going to happen in bug 732874, so duping there.  I can take a look at that side if they don't get to it soon but for now I'll concentrate on other mozmill failures.

FWIW, this also happens on great regularity with this test case on windows as well as mac.

Comment 15

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I have just checked again and this is clearly a regression in Mozmill hotfix-2.0 and master. On the hotfix-1.5 branch we do not see this exception and also don't fail in running the test. So something we have changed in Mozmill 2 is causing it. Given that it fails on hotfix-2.0 and master it cannot be because of the message broker. Instead is it somehow related to keypress? We do not use anything else in our test.

Comment 16

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I did a regression test with git bisect and the patch which has been caused this regression in Mozmill is on bug 664566.

Clint, so as we talked it looks like that this is really caused by the console listener which has been implemented by Heather. With it we do not only fail on our own errors/exceptions but also for those thrown by the application itself.

Comment 17

[Henrik Skupin [:whimboo][⌚️UTC+2]]

We cannot really debug error messages until bug 754851 has been solved. So it makes it hard to find the right fix here.

Comment 18

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Widen it up to all errors which are pushed via Cu.reportError() to the Error Console.

Comment 19

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Attachment: Patch

Pointer to Github pull-request

Comment 20

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Comment on attachment 643648 [details]
Patch

This will only report a failure if internal code fails. Keep in mind that when a module has a syntax error it will not be executed! In that case sending a fail event will not succeed and it will not be visible in the test report. Therefore i have put in a dump statement.

We should probably reorganize the modules to do the initialization process in a component with less as possible dependencies on other modules. That way we could register the console listener as early as possible and also report failures for driver/mozmill.js.

Comment 21

[Henrik Skupin [:whimboo][⌚️UTC+2]]

https://github.com/mozautomation/mozmill/commit/ee49208547b6eedefe7bd4645f68b430ef44f92e

Comment 22

[Andrew Halberstadt [:ahal]]

For what it's worth, I think this patch is a bad idea. You'll potentially be hiding valuable debugging information. Maybe you could use that regex to log Errors and then use the original to log Warnings?

Henrik, when you say this is a regression in mozmill, I assume you are talking about the fact that it causes the test to fail, and not the fact that the Error happens in the first place? The error has nothing to do with mozmill, I see it in error console right now as I type this.

Also why is the message getting dump()'ed and broker.fail()'ed?

Comment 23

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to Andrew Halberstadt [:ahal] from comment #22)
> For what it's worth, I think this patch is a bad idea. You'll potentially be
> hiding valuable debugging information. Maybe you could use that regex to log
> Errors and then use the original to log Warnings?

What debugging information?

> Henrik, when you say this is a regression in mozmill, I assume you are
> talking about the fact that it causes the test to fail, and not the fact
> that the Error happens in the first place? The error has nothing to do with
> mozmill, I see it in error console right now as I type this.

Correct, as stated multiple times in this bug the test should not fail.

> Also why is the message getting dump()'ed and broker.fail()'ed?

Andrew please read my comment 20. Under some conditions there is no chance in getting the failure transmitted to the Python side. If we fail to load e.g. frame.js none if it's code will be executed, and as result the actual failure is lost in the nirvana. Then dump() will at least show the problem in the console. If other modules are affected and we can make a test to fail we obviously want to do that. That's why both calls are right in there.

Just as an addition, on Wednesday I have started some code locally (sorry no bug has been filed yet) to move most of the initialization code in a real component with nearly no dependencies on other modules. I believe that this is the only way we can ensure to get failures across modules correctly reported to the framework and marking tests as failed. I will hopefully be able to finish this up today and even upload a patch, which should handle this condition better.

That sad I don't think that this patch is bad. I have tested it in various ways to ensure that the real failure is printed to the console.

Comment 24

[Henrik Skupin [:whimboo][⌚️UTC+2]]

So I have filed bug 775811 now.