Closed Bug 915384 Opened 7 years ago Closed 7 years ago

Intermittent ASAN browser_thumbnails_background.js,browser_thumbnails_update.js,browser_thumbnails_background_crash.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N)

Categories

(Firefox :: General, defect)

x86_64
Linux
defect
Not set

Tracking

()

RESOLVED FIXED
Firefox 27
Tracking Status
firefox25 --- fixed
firefox26 --- fixed
firefox27 --- fixed
firefox-esr24 --- fixed

People

(Reporter: RyanVM, Assigned: decoder)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Bug 910563 is the only thumbnail-related patch that I see having landed around the time this regressed. As decoder will point out, ASAN often exposes slow-running tests more easily than regular opt/debug builds. Is it possible that bug 910563 is somehow making browser_thumbnails_background.js run slower?

Also, maybe the right solution is a requestLongerTimeout, but it might be good if we at least understood why this test got slower all of a sudden.

https://tbpl.mozilla.org/php/getParsedLog.php?id=27710505&tree=Mozilla-Inbound

Ubuntu ASAN VM 12.04 x64 mozilla-inbound opt test mochitest-browser-chrome on 2013-09-11 08:33:28 PDT for push bc729c5726bb
slave: tst-linux64-ec2-101

09:54:14     INFO -  TEST-INFO | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | starting sub-test noAlert
09:54:14     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumbnail file should not already exist.
09:54:14     INFO -  JavaScript error: , line 0: uncaught exception: out of memory
09:54:14     INFO -  TEST-INFO | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Console message: [JavaScript Error: "uncaught exception: out of memory"]
09:54:14     INFO -  TEST-INFO | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "data:text/html,<script>alert('yo!');</script>" line: 0}]
09:54:14     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Captured URL should be URL passed to capture.
09:54:14     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumbnail file should exist even though it alerted.
09:54:14     INFO -  TEST-INFO | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | starting sub-test noDuplicates
09:54:14     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumbnail file should not already exist.
09:54:14     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | called back with correct url
09:54:14     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumbnail file should now exist.
09:54:14     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | called back with correct url
09:54:14     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumbnail file should still be deleted.
09:54:14  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort.
09:54:14     INFO -  INFO TEST-END | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | finished in 31885ms
https://tbpl.mozilla.org/php/getParsedLog.php?id=27720581&tree=Mozilla-Central
Summary: Intermittent ASAN browser_thumbnails_background.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. → Intermittent ASAN browser_thumbnails_background.js,browser_thumbnails_update.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort.
One more reason for slowing down by a lot is hitting the memory limit on the tester. We've had this a few times because ASan builds are not only slower but also consume a decent amount of additional memory. However, right now, none of the tests hit the memory limit with the settings we're using. But we should at least consider that as one possible reason in case the test itself is very memory intensive in general.
09:54:14     INFO -  JavaScript error: , line 0: uncaught exception: out of memory
09:54:14     INFO -  TEST-INFO | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Console message: [JavaScript Error: "uncaught exception: out of memory"]

interesting...
The bg thumbnail tests run run in this order:

browser_thumbnails_background.js
browser_thumbnails_background_crash.js
browser_thumbnails_update.js

Two of the logs here failed in browser_thumbnails_background.js:

comment 0: https://tbpl.mozilla.org/php/getParsedLog.php?id=27710505&tree=Mozilla-Inbound
comment 2: https://tbpl.mozilla.org/php/getParsedLog.php?id=27715065&tree=Mozilla-Inbound

The other two failed in browser_thumbnails_update.js:

comment 1: https://tbpl.mozilla.org/php/getParsedLog.php?id=27720581&tree=Mozilla-Central
comment 2: https://tbpl.mozilla.org/php/getParsedLog.php?id=27717710&tree=Mozilla-Inbound

It's the same timeout-exceeded failure in all four logs.

All four also have the same OOM error at the same point, during the noAlert sub-test in browser_thumbnails_background.js, apparently when the test begins another background capture:

> 09:54:14     INFO -  TEST-INFO | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | starting sub-test noAlert
> 09:54:14     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumbnail file should not already exist.
> 09:54:14     INFO -  JavaScript error: , line 0: uncaught exception: out of memory
Those memory errors are worrying, but it doesn't really look like they are causing an issue with the tests - eg, in the first log Drew points at, we have:

09:53:42     INFO -  TEST-START | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js
...
09:54:14     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumbnail file should still be deleted.
09:54:14  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort.

(ie, the test appeared to be running normally and passing all tests, it just took longer than 30 seconds.)

The timeouts in browser_thumbnails_update.js look similar - while there are gaps of ~ 7 seconds between output lines, this test relies heavily on .sjs files.  Given we know these runs are slow and apparently the machine is struggling with memory, I think it's the same problem - just much slower than expected.

I think a requestLongerTimeout is probably reasonable as a first cut here...
The OOM error is erroneous but harmless.  What happens is some other error is thrown, and while XPConnect is trying to handle it, there's another error, which causes XPConnect to bail and make a blanket OOM assumption.

Details: openModalWindow in nsPrompter.js calls winUtils.isParentWindowMainWidgetVisible, which throws an nsIException with a NS_ERROR_NOT_AVAILABLE nsresult [1].  XPConnect tries to wrap this nsIException [2], I think to reflect it to the window.alert JS caller, but that fails with NS_ERROR_XPC_SECURITY_MANAGER_VETO because the security manager doesn't allow it [3].  This second error foils XPConnect's attempt to throw the first error, and it traps the second error with a call to JS_ReportOutOfMemory [4].

[1] http://mxr.mozilla.org/mozilla-central/source/dom/base/nsDOMWindowUtils.cpp#3235
[2] http://mxr.mozilla.org/mozilla-central/source/dom/bindings/Exceptions.cpp#62
[3] http://mxr.mozilla.org/mozilla-central/source/js/xpconnect/src/XPCWrappedNative.cpp#1881
[4] http://mxr.mozilla.org/mozilla-central/source/js/xpconnect/src/XPCThrower.cpp#62

This is the message of the underlying error thrown by the security manager, which you can see if you prevent the OOM error from being thrown:

>  0:27.56 JavaScript error: data:text/html,<script>alert('yo!');</script>, line 1: Permission denied for <moz-safe-about:blank> to create wrapper for object of class UnnamedClass

It seems messed up that XPConnect can't reflect nsIExceptions created by JS to content.  If nsPrompter catches the nsIException and throws Cr.NS_ERROR_NOT_AVAILABLE instead -- the nsresult, not an nsIException -- then that is reflected to content.

Regardless of whether the exception thrown by window.alert is the "right" one or not, by design the alert is supposed to fail, so the test should catch the error to prevent it from showing up in the console.  I'll file a bug.
(In reply to Drew Willcoxon :adw from comment #7)
> Regardless of whether the exception thrown by window.alert is the "right"
> one or not, by design the alert is supposed to fail, so the test should
> catch the error to prevent it from showing up in the console.  I'll file a
> bug.

Bug 917609.  I also filed bug 917610 for a problem with preventFurtherDialogs I found while debugging this.
From one of the most recent failures (in the subtest capIfMissing):

18:25:09     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumbnail file should not already exist.
18:25:34     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Captured URL should be URL passed to capture
18:25:34     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumbnail should be cached after capture: /tmp/tmpGCo0G5/thumbnails/a6bf1757fff057f266b697df9cf176fd.png
18:25:34     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Last modified time should stick!

So this test is taking 25 seconds to capture http://example.com which seems very excessive!  It works, so it doesn't really look like anything is going wrong here, but still..
https://tbpl.mozilla.org/php/getParsedLog.php?id=28199501&tree=Mozilla-Inbound
Summary: Intermittent ASAN browser_thumbnails_background.js,browser_thumbnails_update.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. → Intermittent ASAN browser_thumbnails_background.js,browser_thumbnails_update.js,browser_thumbnails_background_crash.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N)
Blocks: 919438
At least one failure in here is permanent and it's because a test was recently added, that doesn't work without the crash reporter, but it's not appropriately ifdef'ed out. Fix coming in bug 919438.
Mark Hammond suggested on IRC to use a slightly longer timeout for one of the tests and made try runs for that which were successful. So in combination with the perma-orange fix that just landed, this fix should resolve the intermittent failures.
Assignee: nobody → choller
Status: NEW → ASSIGNED
Attachment #808476 - Flags: review?(mhammond)
Attachment #808476 - Flags: review?(mhammond) → review+
https://hg.mozilla.org/mozilla-central/rev/f083bb8085a3
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
Flags: in-testsuite-
Resolution: --- → FIXED
Target Milestone: --- → Firefox 27
Blocks: 931889
You need to log in before you can comment on or make changes to this bug.