Closed Bug 772823 Opened 12 years ago Closed 11 years ago

Intermittent test_mozFrameType.xul | Test timed out (and more)

Categories

(Core :: DOM: Navigation, defect)

Product:
Core
Component:
DOM: Navigation
Platform:
x86_64
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla31
Tracking Flags:
Tracking Status
firefox29 --- wontfix
firefox30 --- fixed
firefox31 --- fixed
firefox-esr24 --- fixed
b2g-v1.2 --- fixed
b2g-v1.3 --- fixed
b2g-v1.3T --- fixed
b2g-v1.4 --- fixed
b2g-v2.0 --- fixed

People

(Reporter: emorley, Assigned: ehsan.akhgari)

References

Details

(Keywords: intermittent-failure)

Attachments

(10 files, 5 obsolete files)

Screenshot
(deleted), image/png
Details
attempt #1
(deleted), patch
Details | Diff | Splinter Review
attempt #2
(deleted), patch
Details | Diff | Splinter Review
attempt #3
(deleted), patch
Details | Diff | Splinter Review
updated debugging patch
(deleted), patch
Details | Diff | Splinter Review
complete failing log with LOGFOCUS logging
(deleted), application/x-gzip
Details
complete passing log with LOGFOCUS logging
(deleted), application/x-gzip
Details
excerpt of passing log (test start to test end)
(deleted), text/plain
Details
excerpt of failing log (test start to test timeout)
(deleted), text/plain
Details
Final fix
(deleted), patch
Gavin
: review+
Details | Diff | Splinter Review
Attached image Screenshot (deleted) —
Rev3 Fedora 12x64 mozilla-inbound opt test mochitest-other on 2012-07-11 03:12:28 PDT for push e800d39d1600 slave: talos-r3-fed64-014 https://tbpl.mozilla.org/php/getParsedLog.php?id=13421317&tree=Mozilla-Inbound { 4384 INFO TEST-START | chrome://mochitests/content/chrome/docshell/test/chrome/test_mozFrameType.xul 4385 INFO TEST-PASS | chrome://mochitests/content/chrome/docshell/test/chrome/test_mozFrameType.xul | normal iframe in chrome document is typeChrome - 0 should equal 0 4386 INFO TEST-PASS | chrome://mochitests/content/chrome/docshell/test/chrome/test_mozFrameType.xul | iframe with mozFrameType='content' in chrome document is typeContent - 1 should equal 1 4387 INFO TEST-INFO | chrome://mochitests/content/chrome/docshell/test/chrome/test_mozFrameType.xul | must wait for focus 4388 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/docshell/test/chrome/test_mozFrameType.xul | Test timed out. XScreenSaver state: Disabled User input has been idle for 731 seconds args: ['/home/cltbld/talos-slave/test/build/bin/screentopng'] SCREENSHOT: <attached> 4389 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/docshell/test/chrome/test_mozFrameType.xul | [SimpleTest.finish()] waitForFocus() was called a different number of times from the number of callbacks run. Maybe the test terminated prematurely -- be sure to use SimpleTest.waitForExplicitFinish(). - got 1, expected 0 4390 INFO TEST-END | chrome://mochitests/content/chrome/docshell/test/chrome/test_mozFrameType.xul | finished in 310511ms 4391 INFO TEST-START | chrome://mochitests/content/chrome/docshell/test/chrome/test_principalInherit.xul 4392 INFO TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/docshell/test/chrome/test_principalInherit.xul | finished in a non-clean fashion (in chrome://mochitests/content/chrome/docshell/test/chrome/test_mozFrameType.xul) }
Blocks: 769771
Mysterious. Seems to be timing out waiting for the main window to be focused after closing the child window. Other docshell tests use essentially the same code (from docshell_helpers.js) and don't seem to have any issues (I see no oranges reported).
Attached patch attempt #1 (deleted) — — Splinter Review
https://hg.mozilla.org/integration/mozilla-inbound/rev/4f7bff5aa1ba
Assignee: nobody → gavin.sharp
Status: NEW → ASSIGNED
Attached patch attempt #2 (deleted) — — Splinter Review
This is on top of the previous patch, and undoes it since that apparently wasn't successful: http://hg.mozilla.org/integration/mozilla-inbound/rev/c0f65614b0e0
https://hg.mozilla.org/mozilla-central/rev/c0f65614b0e0
Status: ASSIGNED → RESOLVED
Closed: 12 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → mozilla18
Sorry, I forgot [leave-open] (or whatever it is)
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Attached patch attempt #3 (deleted) — — Splinter Review
When the failure occurs, we are waiting for focus to occur (when it doesn't occur, the focus is already set to the opener, apparently). Maybe it's possible for that window to still be loading or something? https://hg.mozilla.org/integration/mozilla-inbound/rev/8b530f1d1726
https://hg.mozilla.org/mozilla-central/rev/8b530f1d1726
Status: REOPENED → RESOLVED
Closed: 12 years ago → 12 years ago
Resolution: --- → FIXED
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Whiteboard: [orange]
FWIW I am still trying to track this down.
Attached patch debugging patch (obsolete) (deleted) — — Splinter Review
Here's a patch I ran through try repeatedly to try to get a useful debug log out of.
Attached file passing log with debug output (obsolete) (deleted) —
Here's the full log from a test run where the test passes.
Attached file failing log with debug output (obsolete) (deleted) —
Here's a log from when the test failed.
Attachment #719719 - Attachment is patch: false
Attachment #719719 - Attachment mime type: text/plain → application/x-gzip
Attachment #719721 - Attachment mime type: text/plain → application/x-gzip
The logs don't seem to show anything too interesting. In the failure case, after we waitForFocus() the main window at the end of the test, we timeout waiting for a "Window XXX Raised" message. That matches what seems to be shown in the screenshot - the window is still open but is not raised. Neil, does this ring a bell at all? Linux-only, child window closes itself and then calls SimpleTest.waitForFocus(function() { SimpleTest.finish(); }, opener); from the domwindow closed notification (http://mxr.mozilla.org/mozilla-central/source/docshell/test/chrome/mozFrameType_window.xul). The waitForFocus callback never runs. (see also earlier patches here for some shot-in-the-dark attempts at avoiding the problem)
Flags: needinfo?(enndeakin)
It would also be useful to have gtk window prlogging enabled for these logs. Both 'Widget' and 'WidgetFocus' (see gtk2/nsAppShell::Init)
Flags: needinfo?(enndeakin)
(In reply to Neil Deakin from comment #190) > It would also be useful to have gtk window prlogging enabled for these logs. > Both 'Widget' and 'WidgetFocus' (see gtk2/nsAppShell::Init) Hrm, I thought I had enabled that, but I see now it didn't work :( I'll try again.
Attached patch updated debugging patch (deleted) — — Splinter Review
Attachment #719718 - Attachment is obsolete: true
Attachment #719719 - Attachment is obsolete: true
Attachment #719721 - Attachment is obsolete: true
Attachment #719729 - Attachment is obsolete: true
Attachment #719732 - Attachment is obsolete: true
The difference seems to be that the passing log has an additional bit at the end: 13:08:31 INFO - TEST-INFO: 1905620768[7fa371727150]: OnContainerFocusInEvent [7fa36673e1a0] 13:08:31 INFO - TEST-INFO: 1905620768[7fa371727150]: Window 7fa35f5dac18 Raised [Currently: 0 0] 13:08:31 INFO - TEST-INFO: 1905620768[7fa371727150]: Raised Window: 7fa35f5dac18 chrome://browser/content/browser.xul 13:08:31 INFO - TEST-INFO: 1905620768[7fa371727150]: <<Focus begin>> 13:08:31 INFO - TEST-INFO: nsFocusManager::Focus 13:08:31 INFO - TEST-INFO: nsFocusManager::Focus doing stuff 13:08:31 INFO - TEST-INFO: 1905620768[7fa371727150]: Element (none) has been focused 13:08:31 INFO - TEST-INFO: 1905620768[7fa371727150]: from window 13:08:31 INFO - TEST-INFO: 1905620768[7fa371727150]: [Newdoc: 1 FocusChanged: 0 Raised: 1 Flags: 0] 13:08:31 INFO - TEST-INFO nsWindow::SetFocus 13:08:31 INFO - TEST-INFO: 1905620768[7fa371727150]: SetFocus 0 [7fa36673e1a0] 13:08:31 INFO - TEST-INFO nsWindow::SetFocus: mIMModule 13:08:31 INFO - TEST-INFO: 1905620768[7fa371727150]: widget now has focus in SetFocus() [7fa36673e1a0] 13:08:31 INFO - TEST-INFO: SendFocusOrBlurEvent focus 13:08:31 INFO - 3855 INFO TEST-INFO | chrome://mochitests/content/chrome/docshell/test/chrome/test_mozFrameType.xul | waitForFocus: waitForEvent: focus 13:08:31 INFO - 3856 INFO TEST-INFO | chrome://mochitests/content/chrome/docshell/test/chrome/test_mozFrameType.xul | waitForFocus: maybeRunTests 13:08:31 INFO - TEST-INFO: SendFocusOrBlurEvent focus 13:08:31 INFO - TEST-INFO: 1905620768[7fa371727150]: Update Caret: 0 1 13:08:31 INFO - TEST-INFO: 1905620768[7fa371727150]: Events sent from focus in event [7fa36673e1a0] 13:08:31 INFO - 3857 INFO TEST-END | chrome://mochitests/content/chrome/docshell/test/chrome/test_mozFrameType.xul | finished in 176ms
Flags: needinfo?(enndeakin)
Enn, 1 year needinfo? ping!
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #633) > Enn, 1 year needinfo? ping! Ehsan, maybe you wouldn't mind taking a look? :)
Flags: needinfo?(ehsan)
FWIW this is the same focus manager bug as bug 886782 and bug 919016 I think. Contacting Neil offline. Here is an idea: https://tbpl.mozilla.org/?tree=Try&rev=4b9a28bde7e6
See Also: → https://bugzilla.mozilla.org/show_bug.cgi?id=886782, https://bugzilla.mozilla.org/show_bug.cgi?id=919016
(In reply to :Ehsan Akhgari (lagging on bugmail, needinfo? me!) from comment #705) > Here is an idea: https://tbpl.mozilla.org/?tree=Try&rev=4b9a28bde7e6 Make that https://tbpl.mozilla.org/?tree=Try&rev=b923061d9f0c
Attached patch Final fix (deleted) — — Splinter Review
This seems to work around the focus manager bug here. The idea is to focus the main test window before attempting to close the newly opened window in this test. It seems like the focus manager is suffering from a bug which prevents setting the focus to work correctly if another window has been closed recently. At least that theory explains why this workaround works.
Assignee: gavin.sharp → ehsan
Status: REOPENED → ASSIGNED
Attachment #8408702 - Flags: review?(enndeakin)
Flags: needinfo?(ehsan)
Comment on attachment 8408702 [details] [diff] [review] Final fix It feels perhaps risky to call finish() (and thus synchronously start the next test, IIRC) directly from the domwindowclosed observer, though I don't know that it would actually be problematic. An executeSoon might be warranted.
Attachment #8408702 - Flags: review?(enndeakin) → review+
Flags: needinfo?(enndeakin)
Landed with the suggested executeSoon: https://hg.mozilla.org/integration/mozilla-inbound/rev/d80b56079e66
https://hg.mozilla.org/mozilla-central/rev/d80b56079e66
Status: ASSIGNED → RESOLVED
Closed: 12 years ago → 11 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: