Closed Bug 579540 Opened 15 years ago Closed 15 years ago

Intermittent timeout in browser/base/content/test/browser_bug553455.js, followed by various failures about number of installed extensions or notifications, probably depending on when it timed out

Categories

(Toolkit :: Add-ons Manager, defect)

Product:
Toolkit
Component:
Add-ons Manager
Platform:
All
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
VERIFIED FIXED
Milestone:
mozilla2.0b7

People

(Reporter: ehsan.akhgari, Assigned: mossop)

References

Details

(Keywords: intermittent-failure)

Attachments

(7 files, 1 obsolete file)

additional logging [checked in]
2.57 KB, patch
Gavin
: review+
Details | Diff | Splinter Review
longer timeout [checked in]
535 bytes, patch
Details | Diff | Splinter Review
timeout screenshot
273.50 KB, image/png
Details
Reordering and log observer notifications [checked in]
21.85 KB, patch
Gavin
: review+
Details | Diff | Splinter Review
better cleanup
1.28 KB, patch
Gavin
: review+
Details | Diff | Splinter Review
Patch (v2)
1.30 KB, patch
Gavin
: review+
Details | Diff | Splinter Review
wait for focus
3.53 KB, patch
Gavin
: review+
Details | Diff | Splinter Review
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1279297543.1279304016.20629.gz Rev3 MacOSX Snow Leopard 10.6.2 mozilla-central debug test mochitest-other on 2010/07/16 09:25:43 NEXT ERROR TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug553455.js | Timed out TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug553455.js | Found a tab after previous test timed out: http://example.com/browser/toolkit/mozapps/extensions/test/xpinstall/installtrigger.html?%7B%22XPI%22%3A%22incompatible.xpi%22%7D WARNING: NS_ENSURE_TRUE(bCollapsed) failed: file /builds/slave/mozilla-central-macosx64-debug/build/editor/libeditor/text/nsTextEditRules.cpp, line 1009 TEST-INFO | checking window state TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_bug553455.js | before wait for focus -- loaded: complete active window: ([object ChromeWindow @ 0x10a0a85c0 (native @ 0x10a0a09b8)]) chrome://browser/content/browser.xul focused window: ([object XPCNativeWrapper [object Window @ 0x10f274440 (native @ 0x10f345728)]]) about:blank desired window: ([object ChromeWindow @ 0x10a0a85c0 (native @ 0x10a0a09b8)]) chrome://browser/content/browser.xul child window: ([object XPCNativeWrapper [object Window @ 0x10f274440 (native @ 0x10f345728)]]) about:blank docshell visible: true TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_bug553455.js | already focused TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_bug553455.js | maybe run tests <load:true, focus:true> -- loaded: complete active window: ([object ChromeWindow @ 0x10a0a85c0 (native @ 0x10a0a09b8)]) chrome://browser/content/browser.xul focused window: ([object XPCNativeWrapper [object Window @ 0x10f274440 (native @ 0x10f345728)]]) about:blank desired window: ([object ChromeWindow @ 0x10a0a85c0 (native @ 0x10a0a09b8)]) chrome://browser/content/browser.xul child window: ([object XPCNativeWrapper [object Window @ 0x10f274440 (native @ 0x10f345728)]]) about:blank docshell visible: true Skipping 2280 Lines... TEST-INFO | chrome://mochikit/content/browser/browser/base/content/test/browser_pluginnotification.js | Console message: [JavaScript Warning: "WARN addons.manager: Exception calling callback: ReferenceError: Ci is not defined"] ++DOMWINDOW == 48 (0x11475e748) [serial = 438] [outer = 0x11ad2d3e0] WARNING: NS_ENSURE_TRUE(bCollapsed) failed: file /builds/slave/mozilla-central-macosx64-debug/build/editor/libeditor/text/nsTextEditRules.cpp, line 1009 WARNING: We should have hit the document element...: file /builds/slave/mozilla-central-macosx64-debug/build/layout/xul/base/src/nsBoxObject.cpp, line 213 TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_pluginnotification.js | Test 6, Should have displayed the missing plugin notification TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_pluginnotification.js | Test 6, Should not have displayed the blocked plugin notification TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_pluginnotification.js | Test 6, Should be a missing plugin list TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_pluginnotification.js | Test 6, Should know about application/x-unknown TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_pluginnotification.js | Test 6, Should know about application/x-test ++DOMWINDOW == 49 (0x10fd04cb8) [serial = 439] [outer = 0x11ad2d3e0] WARNING: NS_ENSURE_TRUE(bCollapsed) failed: file /builds/slave/mozilla-central-macosx64-debug/build/editor/libeditor/text/nsTextEditRules.cpp, line 1009 WARNING: We should have hit the document element...: file /builds/slave/mozilla-central-macosx64-debug/build/layout/xul/base/src/nsBoxObject.cpp, line 213 WARNING: We should have hit the document element...: file /builds/slave/mozilla-central-macosx64-debug/build/layout/xul/base/src/nsBoxObject.cpp, line 213 TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_pluginnotification.js | Test 7, Should have displayed the missing plugin notification TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_pluginnotification.js | Test 7, Should not have displayed the blocked plugin notification TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_pluginnotification.js | Test 7, Should be a missing plugin list TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_pluginnotification.js | Test 7, Should know about application/x-unknown TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_pluginnotification.js | Test 7, Should know about application/x-test WARNING: NS_ENSURE_TRUE(bCollapsed) failed: file /builds/slave/mozilla-central-macosx64-debug/build/editor/libeditor/text/nsTextEditRules.cpp, line 1009 TEST-INFO | checking window state TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_pluginnotification.js | before wait for focus -- loaded: complete active window: ([object ChromeWindow @ 0x10a0a85c0 (native @ 0x10a0a09b8)]) chrome://browser/content/browser.xul focused window: ([object XPCNativeWrapper [object Window @ 0x10fd96790 (native @ 0x10fddd718)]]) about:blank desired window: ([object ChromeWindow @ 0x10a0a85c0 (native @ 0x10a0a09b8)]) chrome://browser/content/browser.xul child window: ([object XPCNativeWrapper [object Window @ 0x10fd96790 (native @ 0x10fddd718)]]) about:blank docshell visible: true TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_pluginnotification.js | already focused TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_pluginnotification.js | maybe run tests <load:true, focus:true> -- loaded: complete active window: ([object ChromeWindow @ 0x10a0a85c0 (native @ 0x10a0a09b8)]) chrome://browser/content/browser.xul focused window: ([object XPCNativeWrapper [object Window @ 0x10fd96790 (native @ 0x10fddd718)]]) about:blank desired window: ([object ChromeWindow @ 0x10a0a85c0 (native @ 0x10a0a09b8)]) chrome://browser/content/browser.xul child window: ([object XPCNativeWrapper [object Window @ 0x10fd96790 (native @ 0x10fddd718)]]) about:blank docshell visible: true TEST-START | chrome://mochikit/content/browser/browser/base/content/test/browser_popupNotification.js Chrome file doesn't exist: /Users/cltbld/talos-slave/mozilla-central-snowleopard-debug-u-mochitest-other/build/mochitest/browser/browser/base/content/test/head.js TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_popupNotification.js | PopupNotifications object exists TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_popupNotification.js | PopupNotifications panel exists TEST-INFO | chrome://mochikit/content/browser/browser/base/content/test/browser_popupNotification.js | [Test #0] added listeners; panel state: false TEST-INFO | chrome://mochikit/content/browser/browser/base/content/test/browser_popupNotification.js | [Test #0] running test TEST-INFO | chrome://mochikit/content/browser/browser/base/content/test/browser_popupNotification.js | [Test #0] popup showing TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug553455.js | Should have seen the install fail - Got test-notification, expected addon-install-failed TEST-PASS | chrome://mochikit/content/browser/browser/base/content/test/browser_bug553455.js | Should be no active installs
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1279291238.1279292046.5336.gz Rev3 MacOSX Leopard 10.5.8 mozilla-central opt test mochitest-other
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1279289149.1279289999.29464.gz Rev3 MacOSX Snow Leopard 10.6.2 mozilla-central opt test mochitest-other
philringnalda%gmail.com http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1281924304.1281925557.21069.gz Rev3 MacOSX Snow Leopard 10.6.2 mozilla-central opt test mochitest-other on 2010/08/15 19:05:04 s: talos-r3-snow-004 TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug553455.js | Timed out TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug553455.js | Found a tab after previous test timed out: http://example.com/browser/toolkit/mozapps/extensions/test/xpinstall/installtrigger.html?%7B%22Theme%20XPI%22%3A%22theme.xpi%22%7D TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug553455.js | Should have seen the install complete - Got test-notification, expected addon-install-complete TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug553455.js | Should have seen the right button - Got Main Action, expected Restart Now TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug553455.js | Should have seen the right message - Got This is popup notification test-notification from test 0, expected Theme Test will be installed after you restart Minefield. TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_popupNotification.js | application timed out after 330 seconds with no output
philringnalda%gmail.com http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1281936712.1281939155.10599.gz Rev3 MacOSX Snow Leopard 10.6.2 mozilla-central debug test mochitest-other on 2010/08/15 22:31:52 s: talos-r3-snow-004 TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug553455.js | Timed out TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug553455.js | Found a tab after previous test timed out: http://example.com/browser/toolkit/mozapps/extensions/test/xpinstall/installtrigger.html?%7B%22Theme%20XPI%22%3A%22theme.xpi%22%7D TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/browser/base/content/test/browser_bug553455.js | Should have seen the right window open - Got chrome://browser/content/pageinfo/pageInfo.xul, expected chrome://mozapps/content/xpinstall/xpinstallConfirm.xul TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/toolkit/mozapps/extensions/test/browser/browser_manualupdates.js | Update item should have version number of the update - Got 1.0, expected 1.1 TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/toolkit/mozapps/extensions/test/browser/browser_manualupdates.js | - Got false, expected true TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/toolkit/mozapps/extensions/test/browser/browser_manualupdates.js | Release notes toggle should be visible - Got false, expected true TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/toolkit/mozapps/extensions/test/browser/browser_manualupdates.js | Timed out TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/toolkit/mozapps/extensions/test/browser/browser_manualupdates.js | Found a tab after previous test timed out: about:addons TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/toolkit/mozapps/extensions/test/browser/browser_uninstalling.js | Timed out TEST-UNEXPECTED-FAIL | chrome://mochikit/content/browser/toolkit/mozapps/extensions/test/browser/browser_uninstalling.js | Found a tab after previous test timed out: about:addons
Summary: Intermittent timeout in browser/base/content/test/browser_bug553455.js, followed by two failures (found a tab "installtrigger.html?%7B%22XPI%22%3A%22incompatible.xpi%22%7D" and "Got test-notification, expected addon-install-failed" → Intermittent timeout in browser/base/content/test/browser_bug553455.js, followed by various failures about number of installed extensions or notifications, probably depending on when it timed out
Just looking at the tinderbox notifications here, this is happening on more than just OSX.
OS: Mac OS X → All
Hardware: x86 → All
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1287095183.1287096048.3236.gz Rev3 Fedora 12x64 mozilla-central opt test mochitest-other on 2010/10/14 15:26:23 s: talos-r3-fed64-024 TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Test timed out TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Found a tab after previous test timed out: about:blank TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_bug592338.js | Should be no active installs - Got 1, expected 0 TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_bug592338.js | Should be no active installs - Got 1, expected 0 TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Should have seen the install complete - Got addon-theme-change-notification, expected addon-install-complete-notification TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Should have seen the right message - Got Test Background will be installed after you restart., expected XPI Test will be installed after you restart Minefield. TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Should have seen the install fail - Got test-notification-notification, expected addon-install-failed-notification TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Should have seen the right message - Got This is popup notification test-notification from test 0, expected This add-on could not be installed because it appears to be corrupt. TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_popupNotification.js | application timed out after 330 seconds with no output PROCESS-CRASH | chrome://mochitests/content/browser/browser/base/content/test/browser_popupNotification.js | application crashed (minidump found)
Adds some extra logging and timing info to help track this down. I believe that we may just need a longer timeout here but this will help confirm that by showing how long all the bits leading up to any timeout took.
Attachment #483325 - Flags: review?(gavin.sharp)
Attachment #483325 - Flags: review?(gavin.sharp) → review+
Comment on attachment 483325 [details] [diff] [review] additional logging [checked in] Pushed: http://hg.mozilla.org/mozilla-central/rev/a46433bf2181
Attachment #483325 - Attachment description: additional logging → additional logging [checked in]
The logs are showing that each part of the test is taking 2-3 seconds and there are 14 parts to the test so I think we just need a longer timeout here
Attachment #483507 - Flags: review?(gavin.sharp)
Comment on attachment 483507 [details] [diff] [review] longer timeout [checked in] rs=sdwilsh
Attachment #483507 - Flags: review?(gavin.sharp)
Comment on attachment 483507 [details] [diff] [review] longer timeout [checked in] Landed: http://hg.mozilla.org/mozilla-central/rev/45d041f47fdf
Attachment #483507 - Attachment description: longer timeout → longer timeout [checked in]
Most of the logs since the longer timeout got checked in are actually a different failures that has now been backed out.
Attached image timeout screenshot —
The log for comment 352 shows this screenshot, so this isn't a case of the notification popping up but us not detecting it, it is a case of the notification not appearing at all
Since we increased the timeout this failure has only occurred on Linux (aside from a few logs that were reported from tracemonkey which it seems hasn't merged the timeout change yet).
OS: All → Linux
There are a bunch of cases where the test performs some operation and then adds a listener of some kind to wait for the result of that operation. It might be possible for the operation to happen before the listener is added so this flips that around to add the listener first. Based on the screenshot we have I'm not convinced that this is the problem but there is certainly no harm in doing it. I've also added logging of the observer notifications that are the main link between the backend add-ons manager and browser.js to see exactly what it is getting to help narrow this down further.
Attachment #485139 - Flags: review?(gavin.sharp)
Comment on attachment 485139 [details] [diff] [review] Reordering and log observer notifications [checked in] I'm pretty sure that the ordering changes won't fix anything - either the actions being triggered are synchronous or they're not. If they are these tests would fail all the time. If they aren't, it's impossible for them to race with the adding of the event listeners, since that happens synchronously for both wait_for_install_dialog and wait_for_notification.
Attachment #485139 - Flags: review?(gavin.sharp) → review+
Comment on attachment 485139 [details] [diff] [review] Reordering and log observer notifications [checked in] Landed the test change: http://hg.mozilla.org/mozilla-central/rev/c81efbbacc62
Attachment #485139 - Attachment description: Reordering and log observer notifications → Reordering and log observer notifications [checked in]
So far it looks like this is a focus problem on Linux. I've narrowed down that what happens is sometimes during the test run the notification gets shown but immediately the focus switches to the browser harness window and back to the browser window again. I'm not sure why that is happening but that is enough to make the notification never finish showing and never show again.
Attached patch better cleanup — — Splinter Review
Not a fix but this makes the test cleanup a little better hopefully avoiding all the subsequent failures. However I'm not sure whether we should keep this test running right now, I have no idea how long it'd take me to figure out why the focus problem is happening so I don't know when this is likely to be fixed.
Attachment #486112 - Flags: review?(gavin.sharp)
Attachment #486112 - Flags: review?(gavin.sharp) → review+
I'm fairly confident that bug 608210 has fixed this.
Assignee: nobody → robert.bugzilla
Status: NEW → RESOLVED
Closed: 15 years ago
Flags: in-testsuite+
Flags: in-litmus-
Resolution: --- → FIXED
Target Milestone: --- → mozilla2.0b7
Looks like tbpl can't bear to comment on this bug again any more than I can. http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1288510454.1288511386.16448.gz Rev3 Fedora 12 mozilla-central opt test mochitest-other on 2010/10/31 00:34:14 s: talos-r3-fed-007 TEST-INFO | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Console message: LOG addons.xpi: Starting install of http://example.com/browser/toolkit/mozapps/extensions/test/xpinstall/unsigned.xpi TEST-INFO | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Console message: LOG addons.xpi: Addon unsigned-xpi@tests.mozilla.org will be installed as a packed xpi TEST-INFO | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Console message: LOG addons.xpi: Install of http://example.com/browser/toolkit/mozapps/extensions/test/xpinstall/unsigned.xpi completed. TEST-INFO | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Longer timeout required, waiting longer... Remaining timeouts: 1 TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Test timed out (screenshot) *** LOG addons.xpi: Cancelling install of unsigned-xpi@tests.mozilla.org INFO TEST-END | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | finished in 60018ms NEXT ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Found a tab after previous test timed out: about:blank ... ... TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/browser_bug592338.js | Theme should have immediately enabled TEST-INFO | chrome://mochitests/content/browser/browser/base/content/test/browser_bug592338.js | Console message: LOG addons.xpi: Updating add-on state TEST-INFO | chrome://mochitests/content/browser/browser/base/content/test/browser_bug592338.js | Console message: LOG addons.xpi: Updating add-on state TEST-INFO | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Saw notification TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Should have seen the install complete - Got addon-theme-change-notification, expected addon-install-complete-notification TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Should have seen the right button TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Should have seen the right message - Got Test Background will be installed after you restart., expected XPI Test will be installed after you restart Minefield. TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Should be one pending install - Got 0, expected 1 *** WARN addons.manager: Exception calling callback: TypeError: aInstalls[0] is undefined TEST-PASS | chrome://mochitests/content/browser/browser/base/content/test/browser_bug592338.js | Should not have installed the test lwtheme
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Assignee: robert.bugzilla → nobody
No longer depends on: 608210
Flags: in-testsuite+
Flags: in-litmus-
This test takes around 60 seconds (sometimes a bit more and other times a bit less) on my system and it has a 60 second time out. Timed out with failure and finished in 60703ms Passed and finished in 57383ms
Attached patch Patch (v1) (obsolete) — — Splinter Review
Assignee: nobody → ehsan
Status: REOPENED → ASSIGNED
Attachment #487294 - Flags: review?(dtownsend)
Comment on attachment 487294 [details] [diff] [review] Patch (v1) There's already a requestLongerTimeout later in the file (under test(), where it needs to be, IIRC).
Attachment #487294 - Flags: review?(dtownsend) → review-
Attached patch Patch (v2) — — Splinter Review
Attachment #487294 - Attachment is obsolete: true
Attachment #487371 - Flags: review?(gavin.sharp)
Attachment #487371 - Flags: review?(gavin.sharp) → review+
http://hg.mozilla.org/mozilla-central/rev/009dccc732d5
Status: ASSIGNED → RESOLVED
Closed: 15 years ago → 15 years ago
Resolution: --- → FIXED
(In reply to comment #466) > http://hg.mozilla.org/mozilla-central/rev/009dccc732d5 I really doubt that a longer timeout is going to fix this focus-related bug
(In reply to comment #467) > (In reply to comment #466) > > http://hg.mozilla.org/mozilla-central/rev/009dccc732d5 > > I really doubt that a longer timeout is going to fix this focus-related bug I don't see what's focus related about this. See below for an example from the most recent log: TEST-INFO | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Longer timeout required, waiting longer... Remaining timeouts: 1 NEXT ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Test timed out args: ['/home/cltbld/talos-slave/mozilla-central_fedora64_test-mochitest-other/build/bin/screentopng'] XScreenSaver state: Disabled User input has been idle for 2305 seconds SCREENSHOT: data:image/png;base64,... *** LOG addons.xpi: Cancelling install of unsigned-xpi@tests.mozilla.org INFO TEST-END | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | finished in 60018ms The test has took more than 60 seconds to run.
(In reply to comment #468) > (In reply to comment #467) > > (In reply to comment #466) > > > http://hg.mozilla.org/mozilla-central/rev/009dccc732d5 > > > > I really doubt that a longer timeout is going to fix this focus-related bug > > I don't see what's focus related about this. See below for an example from the > most recent log: Here is a more complete version of the log with some explanations: > TEST-INFO | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Waiting for notification Here the test starts waiting for a popup to appear > TEST-INFO | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Observed addon-install-complete for 1 installs Here the test sees the notification that browser.js is meant to use to show the popup, it should normally appear immediately after this. > TEST-INFO | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Longer timeout required, waiting longer... Remaining timeouts: 1 Here the test has now been running for 30 seconds, not sure how long since we started waiting for the popup but we're still waiting. > NEXT ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/base/content/test/browser_bug553455.js | Test timed out Here another 30 seconds have expired so it is over 30 seconds since we started waiting for the notification and also more than 30 seconds since browser.js should have received the message to show the popup.
Hmm, according to the screenshot in the bug, no popup is actually being displayed, but there's an addon icon in the location bar... So I guess this should be reopened?
(In reply to comment #470) > Hmm, according to the screenshot in the bug, no popup is actually being > displayed, but there's an addon icon in the location bar... So I guess this > should be reopened? That is consistent with what I said in comment 393.
Assignee: ehsan → nobody
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
I suspect that the couple of windows failures in this bug will no longer happen so the increased timeout is a good thing. I've been looking at several of the intermittent failures and it appears that many of them have multiple reasons for failing and this bug is one of those.
Attached patch wait for focus — — Splinter Review
I believe I have worked out what the main failure is and this patch fixes it. It's possible that there are still yet more problems, there were a couple of mysterious failures I saw that didn't quite match the main problem I was seeing but it's possible they were also caused by the same problem and so may go away anyway. Either way I think one this patch is landed and confirmed we should close this bug and open a new one for any other problems in this test, we'll have already fixed 3 issues here, the bug is not going to be helpful much longer. The problem seems to be one cause by asynchronous dispatch of focus events. Normally when the install dialog is opened we see something like these events: xpinstallConfirm.xul onWindowOpen event xpinstallConfirm.xul load event (test triggers an executeSoon to wait for load handlers to complete) browser.xul deactivate event xpinstallConfirm.xul activate event xpinstallConfirm.xul focus event (executeSoon completes and test accepts the install dialog) (browser.js receives install complete message. showing the notification is deferred since browser.xul is in the background) xpinstallConfirm.xul deactivate event browser.xul activate event (the notification now gets displayed) In the problem case the executeSoon executes before the focus events are dispatched and we see the following: xpinstallConfirm.xul onWindowOpen event xpinstallConfirm.xul load event (test triggers an executeSoon to wait for load handlers to complete) (executeSoon completes and test accepts the install dialog) (browser.js receives install complete message and the notification starts to be shown) browser.xul deactivate event (showing the notification is cancelled because the window has lost focus) browser.xul (or sometimes browser-harness.xul) activate event browser.xul (or whatever the preceding activate event was for) deactivate event browser.xul activate event The focus events after the window has been closed seem bogus to me but I haven't managed to narrow down whether they are caused by gtk or gecko. Certainly they are dispatched from the gtk focus_in_event and focus_out_event events but I guess gecko might still be causing them somehow. The wallpaper fix is straightforward, just don't dismiss the install dialog until it has become properly focused. It is probably better for someone with better knowledge of the focus code (Neil? Ehsan?) to consider whether to delve in and fix the bogus focus events properly. This patch uses waitForFocus rather than load events for this test and also for the main xpinstall dialog tests.
Assignee: nobody → dtownsend
Status: REOPENED → ASSIGNED
Attachment #487955 - Flags: review?(gavin.sharp)
Attachment #487955 - Flags: review?(gavin.sharp) → review+
Landed and tentatively closed: http://hg.mozilla.org/mozilla-central/rev/4bfbc7353fda
Status: ASSIGNED → RESOLVED
Closed: 15 years ago → 15 years ago
Resolution: --- → FIXED
Blocks: 565259
Blocks: 589636
The previous log was based on a mozilla-central tree from a week ago and so didn't include the fix
This test used to fail around 5 times a day if not more and since the fix it hasn't failed once which is pretty strong confirmation that this is now fixed. Yay! I've filed bug 609921 on the bogus focus events, while we can work around them I think fixing them would make the platform somewhat saner.
Status: RESOLVED → VERIFIED
Again the previous log was based on a mozilla-central changeset from Oct 28th so before the fix here landed.
Whiteboard: [orange]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: