906713 - Intermittent browser_thumbnails_background.js | Thumb browser should exist immediately after capture. - Didn't expect undefined, but got it

Status: RESOLVED FIXED

(Toolkit :: General, defect)

Description

[Ed Morley [:emorley]]

Rev3 Fedora 12 mozilla-inbound debug test mochitest-browser-chrome on 2013-08-18 12:19:55 PDT for push 3790c84fc9db

slave: talos-r3-fed-060

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

{
14:02:55     INFO -  [Child 2979] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0xC1F30001: file nsThreadUtils.cpp, line 161
14:02:55     INFO -  [Child 2979] WARNING: NS_ENSURE_TRUE(mMainThread) failed: file ../../../xpcom/threads/nsThreadManager.cpp, line 251
14:02:55     INFO -  [Child 2979] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0xC1F30001: file nsThreadUtils.cpp, line 161
14:02:55     INFO -  [Child 2979] WARNING: NS_ENSURE_TRUE(mMainThread) failed: file ../../../xpcom/threads/nsThreadManager.cpp, line 251
14:02:55     INFO -  [Child 2979] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0xC1F30001: file nsThreadUtils.cpp, line 161
14:02:55     INFO -  [Child 2979] WARNING: NS_ENSURE_TRUE(mMainThread) failed: file ../../../xpcom/threads/nsThreadManager.cpp, line 251
14:02:55     INFO -  [Child 2979] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0xC1F30001: file nsThreadUtils.cpp, line 161
14:02:55     INFO -  [Child 2979] WARNING: NS_ENSURE_TRUE(mMainThread) failed: file ../../../xpcom/threads/nsThreadManager.cpp, line 251
14:02:55     INFO -  [Child 2979] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0xC1F30001: file nsThreadUtils.cpp, line 161
14:02:55     INFO -  [Child 2979] WARNING: NS_ENSURE_TRUE(mMainThread) failed: file ../../../xpcom/threads/nsThreadManager.cpp, line 251
14:02:55     INFO -  [Child 2979] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0xC1F30001: file nsThreadUtils.cpp, line 161
14:02:55     INFO -  [Child 2979] WARNING: NS_ENSURE_TRUE(mMainThread) failed: file ../../../xpcom/threads/nsThreadManager.cpp, line 251
14:02:55     INFO -  [Child 2979] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0xC1F30001: file nsThreadUtils.cpp, line 161
14:02:55     INFO -  [Child 2979] WARNING: NS_ENSURE_TRUE(mMainThread) failed: file ../../../xpcom/threads/nsThreadManager.cpp, line 251
14:02:55     INFO -  [Child 2979] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0xC1F30001: file nsThreadUtils.cpp, line 161
14:02:55     INFO -  [Child 2979] WARNING: NS_ENSURE_TRUE(compMgr) failed: file nsComponentManagerUtils.cpp, line 58
14:02:55     INFO -  [Child 2979] WARNING: NS_ENSURE_TRUE(svc) failed: file ../../../dom/ipc/ContentChild.cpp, line 578
14:02:55     INFO -  [Child 2979] WARNING: NS_ENSURE_TRUE(compMgr) failed: file nsComponentManagerUtils.cpp, line 58
14:02:55     INFO -  creating 1!
14:02:55     INFO -  [Child 2979] WARNING: nsWindow::GetNativeData not implemented for this type: file ../../../widget/xpwidgets/PuppetWidget.cpp, line 673
14:02:55     INFO -  ++DOCSHELL 0xa417a18 == 1 [id = 1]
14:02:55     INFO -  ++DOMWINDOW == 1 (0xa44bc68) [serial = 1] [outer = (nil)]
14:02:55     INFO -  [TabChild] SHOW (w,h)= (10, 10)
14:02:55     INFO -  loading about:blank, 1
14:02:55     INFO -  ++DOMWINDOW == 2 (0xa4ea190) [serial = 2] [outer = 0xa44bc68]
14:02:55     INFO -  [Parent 2593] WARNING: Could not get disk information from DiskSpaceWatcher: file ../../../../dom/src/storage/DOMStorageIPC.cpp, line 324
14:02:56     INFO -  ++DOMWINDOW == 3 (0xa60bdb0) [serial = 3] [outer = 0xa44bc68]
14:02:56     INFO -  [Child 2979] WARNING: NS_ENSURE_TRUE(startupCache) failed: file ../../../../content/xbl/src/nsXBLDocumentInfo.cpp, line 502
14:02:56     INFO -  [Child 2979] WARNING: NS_ENSURE_TRUE(startupCache) failed: file ../../../../content/xbl/src/nsXBLDocumentInfo.cpp, line 572
14:02:56     INFO -  ++DOMWINDOW == 4 (0xa62f3f0) [serial = 4] [outer = 0xa44bc68]
14:02:57     INFO -  [Child 2979] WARNING: NS_ENSURE_TRUE(mDocShell) failed: file ../../../../embedding/browser/webBrowser/nsWebBrowser.cpp, line 367
14:02:57     INFO -  [Child 2979] WARNING: NS_ENSURE_TRUE(domWindow) failed: file ../../../../embedding/browser/webBrowser/nsDocShellTreeOwner.cpp, line 87
14:02:57     INFO -  TEST-PASS | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Second file should exist after capture.
14:02:57  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumb browser should exist immediately after capture. - Didn't expect undefined, but got it
14:02:57     INFO -  Stack trace:
14:02:57     INFO -      JS frame :: chrome://mochikit/content/browser-test.js :: test_isnot :: line 564
14:02:57     INFO -      JS frame :: chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js :: destroyBrowserTimeout :: line 150
14:02:57     INFO -      JS frame :: resource://gre/modules/Task.jsm :: TaskImpl_run :: line 198
14:02:57     INFO -      JS frame :: resource://gre/modules/commonjs/sdk/core/promise.js :: resolve :: line 122
14:02:57     INFO -      JS frame :: resource://gre/modules/commonjs/sdk/core/promise.js :: then :: line 47
14:02:57     INFO -      JS frame :: resource://gre/modules/commonjs/sdk/core/promise.js :: resolve :: line 189
14:02:57     INFO -      JS frame :: chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js :: onDone :: line 309
14:02:57     INFO -      JS frame :: resource://gre/modules/BackgroundPageThumbs.jsm :: callOnDonesFn :: line 343
14:02:57     INFO -      JS frame :: resource://gre/modules/commonjs/sdk/core/promise.js :: resolve :: line 122
14:02:57     INFO -      JS frame :: resource://gre/modules/commonjs/sdk/core/promise.js :: then :: line 47
14:02:57     INFO -      JS frame :: resource://gre/modules/commonjs/sdk/core/promise.js :: resolve :: line 189
14:02:57     INFO -      JS frame :: resource://gre/modules/commonjs/sdk/core/promise.js :: resolve :: line 122
14:02:57     INFO -      JS frame :: resource://gre/modules/commonjs/sdk/core/promise.js :: then :: line 47
14:02:57     INFO -      JS frame :: resource://gre/modules/commonjs/sdk/core/promise.js :: resolve :: line 189
14:02:57     INFO -      JS frame :: resource://gre/modules/Task.jsm :: TaskImpl_run :: line 226
14:02:57     INFO -      JS frame :: resource://gre/modules/Promise.jsm :: <TOP_LEVEL> :: line 554
14:02:57     INFO -      JS frame :: resource://gre/modules/Promise.jsm :: <TOP_LEVEL> :: line 336
14:02:57     INFO -      native frame :: <unknown filename> :: <TOP_LEVEL> :: line 0
}

Comment 1

[Legacy TBPL/Treeherder Robot]

edmorley
https://tbpl.mozilla.org/php/getParsedLog.php?id=26874778&tree=Mozilla-Inbound
Windows 7 32-bit mozilla-inbound debug test mochitest-browser-chrome on 2013-08-22 07:41:10
revision: a155905a9d08
slave: t-w732-ix-122

TypeError: this._windows[aWindow.__SSi] is undefined
TypeError: this._windows[aWindow.__SSi] is undefined
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumb browser should exist immediately after capture. - Didn't expect undefined, but got it

Comment 2

[Legacy TBPL/Treeherder Robot]

philor
https://tbpl.mozilla.org/php/getParsedLog.php?id=26942010&tree=Fx-Team
Windows 7 32-bit fx-team debug test mochitest-browser-chrome on 2013-08-23 14:08:30
revision: 30d13245ff58
slave: t-w732-ix-035

TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumb browser should exist immediately after capture. - Didn't expect undefined, but got it

Comment 3

[Legacy TBPL/Treeherder Robot]

ttaubert
https://tbpl.mozilla.org/php/getParsedLog.php?id=27168435&tree=Try
Rev4 MacOSX Lion 10.7 try debug test mochitest-browser-chrome on 2013-08-29 02:44:35
revision: 650a62fbe6ec
slave: talos-r4-lion-065

TypeError: tabItem.$favImage is null
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumb browser should exist immediately after capture. - Didn't expect undefined, but got it

Comment 4

[Legacy TBPL/Treeherder Robot]

KWierso
https://tbpl.mozilla.org/php/getParsedLog.php?id=27451724&tree=Fx-Team
Windows XP 32-bit fx-team debug test mochitest-browser-chrome on 2013-09-05 13:36:45
revision: c70f74b72e32
slave: t-xp32-ix-109

TypeError: e is undefined: callback@chrome://mochitests/content/browser/browser/devtools/shared/test/browser_observableobject.js:53
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumb browser should exist immediately after capture. - Didn't expect undefined, but got it

Comment 5

[Legacy TBPL/Treeherder Robot]

KWierso
https://tbpl.mozilla.org/php/getParsedLog.php?id=27455875&tree=Mozilla-Inbound
Windows XP 32-bit mozilla-inbound debug test mochitest-browser-chrome on 2013-09-05 14:55:11
revision: 6f37f834802f
slave: t-xp32-ix-076

TypeError: e is undefined: callback@chrome://mochitests/content/browser/browser/devtools/shared/test/browser_observableobject.js:53
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumb browser should exist immediately after capture. - Didn't expect undefined, but got it

Comment 6

[Mark Hammond [:markh] [:mhammond]]

Attachment: 0001-Bug-906713-reset-default-capture-timeout-earlier-to-.patch

The problem here is that we are simply hitting the timeout again - the second capture may take longer than 1 second to complete.

The fix is to reset the default timeout after we wait for the timeout, so the second capture uses the default timeout, meaning the browser will still exist after it completes.

Comment 7

[Legacy TBPL/Treeherder Robot]

botond
https://tbpl.mozilla.org/php/getParsedLog.php?id=27461648&tree=Try
Ubuntu VM 12.04 try opt test mochitest-browser-chrome on 2013-09-05 17:36:57
revision: 407963c1063f
slave: tst-linux32-ec2-364

TypeError: e is undefined: callback@chrome://mochitests/content/browser/browser/devtools/shared/test/browser_observableobject.js:53
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Captured URL should be currently expected URL (i.e., capture() callbacks should be called in the correct order) - Got http://mochi.test:8888/browser/toolkit/components/thumbnails/test/thumbnails_background.sjs?%7B%22wait%22%3A2002%7D, expected http://www.example.com/1
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumbnail shouldn't exist for timed out capture: /tmp/tmpDxT43R/thumbnails/432964589d83dbdfc7e8e27c1734638e.png
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Captured URL should be currently expected URL (i.e., capture() callbacks should be called in the correct order) - Got http://www.example.com/1, expected http://mochi.test:8888/browser/toolkit/components/thumbnails/test/thumbnails_background.sjs?%7B%22wait%22%3A2002%7D
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumbnail should be cached after capture: /tmp/tmpDxT43R/thumbnails/91ebecd4eecce0a2f69b2803ce631bde.png

Comment 8

[Legacy TBPL/Treeherder Robot]

edmorley
https://tbpl.mozilla.org/php/getParsedLog.php?id=27497704&tree=Mozilla-Central
Windows XP 32-bit mozilla-central debug test mochitest-browser-chrome on 2013-09-06 09:50:40
revision: b818c7222968
slave: t-xp32-ix-104

TypeError: this.markup is undefined: InspectorPanel_onNavigatedAway/</<@resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/inspector/inspector-panel.js:312
TypeError: e is undefined: callback@chrome://mochitests/content/browser/browser/devtools/shared/test/browser_observableobject.js:53
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumb browser should exist immediately after capture. - Didn't expect undefined, but got it

Comment 9

[Drew Willcoxon :adw]

Comment on attachment 800602 [details] [diff] [review]
0001-Bug-906713-reset-default-capture-timeout-earlier-to-.patch

Review of attachment 800602 [details] [diff] [review]:
-----------------------------------------------------------------

Nice catch, thanks.  The precise problem seems to be that _store finishes after the destroy-browser timer fires, so I wonder if Capture._done should call captureCallback along with the doneCallbacks when PageThumbs._store() completes.  Your patch is still susceptible to failure when _store takes longer than _destroyBrowserTimeout.  Not likely, so r+, but maybe it becomes more likely if a bunch of _stores are queued up?

Comment 10

[Legacy TBPL/Treeherder Robot]

philor
https://tbpl.mozilla.org/php/getParsedLog.php?id=27525324&tree=Mozilla-Inbound
Windows XP 32-bit mozilla-inbound debug test mochitest-browser-chrome on 2013-09-06 19:44:52
revision: bc76d8a21d90
slave: t-xp32-ix-114

TypeError: this.markup is undefined: InspectorPanel_onNavigatedAway/</<@resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/inspector/inspector-panel.js:312
TypeError: e is undefined: callback@chrome://mochitests/content/browser/browser/devtools/shared/test/browser_observableobject.js:53
TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/toolkit/components/thumbnails/test/browser_thumbnails_background.js | Thumb browser should exist immediately after capture. - Didn't expect undefined, but got it

Comment 11

[Mark Hammond [:markh] [:mhammond]]

(In reply to Drew Willcoxon :adw from comment #9)
> Comment on attachment 800602 [details] [diff] [review]
> 0001-Bug-906713-reset-default-capture-timeout-earlier-to-.patch
> 
> Review of attachment 800602 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Nice catch, thanks.  The precise problem seems to be that _store finishes
> after the destroy-browser timer fires, so I wonder if Capture._done should
> call captureCallback along with the doneCallbacks when PageThumbs._store()
> completes.

Maybe - but I don't think the current behaviour is actually a problem - if this happens "for real", then we are just going to recreate the browser element and things should work fine.  Seeing we are just fixing this orange, I think we can defer this until there is evidence of an actual problem.

> Your patch is still susceptible to failure when _store takes
> longer than _destroyBrowserTimeout.  Not likely, so r+, but maybe it becomes
> more likely if a bunch of _stores are queued up?

This would imply something very bad is happening with the tests - and the mochi framework is going to time us out anyway.  So I think this too is fine for the sake of this orange.

https://hg.mozilla.org/integration/fx-team/rev/e89edb607559

Comment 12

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/e89edb607559

Comment 13

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/2a747593db9b
https://hg.mozilla.org/releases/mozilla-beta/rev/2cbff87e4417