Closed Bug 772823 Opened 8 years ago Closed 7 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)

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: 8 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: 8 years ago8 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)