Closed Bug 772823 Opened 12 years ago Closed 10 years ago

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

Categories

(Core :: DOM: Navigation, defect)

x86_64
Linux
defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla31
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)

598.78 KB, image/png
Details
2.34 KB, patch
Details | Diff | Splinter Review
2.29 KB, patch
Details | Diff | Splinter Review
2.70 KB, patch
Details | Diff | Splinter Review
35.22 KB, patch
Details | Diff | Splinter Review
1.60 MB, application/x-gzip
Details
1016.05 KB, application/x-gzip
Details
12.18 KB, text/plain
Details
10.53 KB, text/plain
Details
2.15 KB, patch
Gavin
: review+
Details | Diff | Splinter Review
Attached image Screenshot
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 #2Splinter 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 #3Splinter 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 ago12 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) — 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) —
Here's the full log from a test run where the test passes.
Attached file failing log with debug output (obsolete) —
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.
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: → 886782, 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 fixSplinter 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)
See Also: → 632290
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 ago10 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.