Closed Bug 1247519 Opened 8 years ago Closed 7 years ago

Intermittent test_bug1224790-2.xul | Test timed out.

Categories

(Core :: DOM: Core & HTML, defect, P3)

Product:
Core
Component:
DOM: Core & HTML
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla55
Tracking Flags:
Tracking Status
firefox52 --- wontfix
firefox-esr52 --- fixed
firefox53 --- fixed
firefox54 --- fixed
firefox55 --- fixed

People

(Reporter: philor, Assigned: arai)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell fixed])

Attachments

(1 file)

Trigger mouse click twice in case the first click is overlooked
(deleted), patch
smaug
: review+
Details | Diff | Splinter Review 
Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.
Priority: -- → P3
this isn't very clear what the root cause is, I see certain patterns, but it is green for many pushes, then orange for many others :(  This looks build related, so I think we need to investigate the test.

this test was added in bug 1224790 and has no changes since originally landing (rare find!)

here is the messages from the log:
11:45:11     INFO - TEST-START | dom/tests/mochitest/chrome/test_bug1224790-2.xul
11:45:11     INFO - ++DOMWINDOW == 43 (0x1310aa000) [pid = 1862] [serial = 43] [outer = 0x12e70fc00]
11:45:11     INFO - ++DOCSHELL 0x1311b7800 == 13 [pid = 1862] [id = {4de6dff9-dfc9-064f-b332-90cf794a9d4a}]
11:45:11     INFO - ++DOMWINDOW == 44 (0x1311b8800) [pid = 1862] [serial = 44] [outer = 0x0]
11:45:11     INFO - ++DOMWINDOW == 45 (0x1311ba000) [pid = 1862] [serial = 45] [outer = 0x1311b8800]
11:45:12     INFO - ++DOCSHELL 0x12a3b5800 == 14 [pid = 1862] [id = {abd61e8d-e3cf-3546-a7f8-0d8652619fbe}]
11:45:12     INFO - ++DOMWINDOW == 46 (0x131378000) [pid = 1862] [serial = 46] [outer = 0x0]
11:45:12     INFO - ++DOMWINDOW == 47 (0x13137a800) [pid = 1862] [serial = 47] [outer = 0x131378000]
11:45:12     INFO - --DOCSHELL 0x130cca000 == 13 [pid = 1862] [id = {fb38b02c-199f-5f49-a2db-7b06851e2d74}]
11:45:12     INFO - --DOCSHELL 0x130ef7800 == 12 [pid = 1862] [id = {3ea12f88-6510-fa49-abe6-a25d01627fec}]
11:45:12     INFO - --DOCSHELL 0x131374800 == 11 [pid = 1862] [id = {8855d890-301d-524c-9ed0-f4499b874c84}]
11:45:13     INFO - --DOCSHELL 0x130065000 == 10 [pid = 1862] [id = {d3ff916b-f404-4549-84b3-840052220a11}]
11:45:13     INFO - --DOCSHELL 0x130057000 == 9 [pid = 1862] [id = {e65e1b98-0a45-9b4d-adbb-5369fa650f4a}]
11:45:13     INFO - --DOCSHELL 0x12fd96800 == 8 [pid = 1862] [id = {4ce853fc-e2ee-ea44-9276-d60b4d328aff}]
11:45:13     INFO - --DOMWINDOW == 46 (0x12ff9ac00) [pid = 1862] [serial = 25] [outer = 0x0] [url = about:blank]
11:45:13     INFO - [1862] WARNING: getting z level of unregistered window: file /home/worker/workspace/build/src/xpfe/appshell/nsWindowMediator.cpp, line 616
11:45:13     INFO - [1862] WARNING: getting z level of unregistered window: file /home/worker/workspace/build/src/xpfe/appshell/nsWindowMediator.cpp, line 616
11:45:13     INFO - --DOCSHELL 0x1311b7800 == 7 [pid = 1862] [id = {4de6dff9-dfc9-064f-b332-90cf794a9d4a}]
11:45:16     INFO - --DOCSHELL 0x12a3b5800 == 6 [pid = 1862] [id = {abd61e8d-e3cf-3546-a7f8-0d8652619fbe}]
11:45:18     INFO - --DOMWINDOW == 45 (0x129270800) [pid = 1862] [serial = 37] [outer = 0x0] [url = chrome://mochitests/content/chrome/dom/tests/mochitest/chrome/test_bug1224790-1.xul]
11:45:18     INFO - --DOMWINDOW == 44 (0x130e6ec00) [pid = 1862] [serial = 36] [outer = 0x0] [url = chrome://mochikit/content/tests/SimpleTest/iframe-between-tests.html]
11:45:18     INFO - --DOMWINDOW == 43 (0x1310a9c00) [pid = 1862] [serial = 42] [outer = 0x0] [url = chrome://mochikit/content/tests/SimpleTest/iframe-between-tests.html]
11:45:18     INFO - --DOMWINDOW == 42 (0x130096400) [pid = 1862] [serial = 30] [outer = 0x0] [url = about:blank]
11:45:18     INFO - --DOMWINDOW == 41 (0x130c94000) [pid = 1862] [serial = 32] [outer = 0x0] [url = chrome://mochikit/content/tests/SimpleTest/iframe-between-tests.html]
11:45:18     INFO - --DOMWINDOW == 40 (0x125595800) [pid = 1862] [serial = 21] [outer = 0x0] [url = about:blank]
11:45:18     INFO - --DOMWINDOW == 39 (0x12ff91c00) [pid = 1862] [serial = 23] [outer = 0x0] [url = chrome://mochikit/content/tests/SimpleTest/iframe-between-tests.html]
11:45:18     INFO - --DOMWINDOW == 38 (0x13008cc00) [pid = 1862] [serial = 26] [outer = 0x0] [url = about:blank]
11:45:18     INFO - --DOMWINDOW == 37 (0x12fc53c00) [pid = 1862] [serial = 16] [outer = 0x0] [url = about:blank]
11:45:18     INFO - --DOMWINDOW == 36 (0x12e7cc800) [pid = 1862] [serial = 15] [outer = 0x0] [url = about:blank]
11:45:18     INFO - --DOMWINDOW == 35 (0x12d4e3400) [pid = 1862] [serial = 12] [outer = 0x0] [url = http://mochi.test:8888/redirect.html]
11:45:18     INFO - --DOMWINDOW == 34 (0x1293c0c00) [pid = 1862] [serial = 8] [outer = 0x0] [url = about:blank]
11:45:20     INFO - --DOMWINDOW == 33 (0x131375000) [pid = 1862] [serial = 40] [outer = 0x0] [url = chrome://mochitests/content/chrome/dom/tests/mochitest/chrome/file_bug1224790-1_nonmodal.xul]
11:45:20     INFO - --DOMWINDOW == 32 (0x130ef8800) [pid = 1862] [serial = 38] [outer = 0x0] [url = chrome://mochitests/content/chrome/dom/tests/mochitest/chrome/file_bug1224790-1_modal.xul]
11:45:20     INFO - --DOMWINDOW == 31 (0x130cca800) [pid = 1862] [serial = 34] [outer = 0x0] [url = chrome://mochitests/content/chrome/dom/tests/mochitest/chrome/window_activation.xul]
11:45:20     INFO - --DOMWINDOW == 30 (0x12fd92000) [pid = 1862] [serial = 18] [outer = 0x0] [url = chrome://mochitests/content/chrome/dom/tests/mochitest/chrome/DOMWindowCreated_chrome.xul]
11:45:20     INFO - --DOMWINDOW == 29 (0x1311b8800) [pid = 1862] [serial = 44] [outer = 0x0] [url = chrome://mochitests/content/chrome/dom/tests/mochitest/chrome/file_bug1224790-2_modal.xul]
11:45:20     INFO - --DOMWINDOW == 28 (0x13005d800) [pid = 1862] [serial = 27] [outer = 0x0] [url = chrome://mochitests/content/chrome/dom/tests/mochitest/chrome/file_DOM_element_instanceof.xul]
11:45:20     INFO - --DOMWINDOW == 27 (0x12573d800) [pid = 1862] [serial = 20] [outer = 0x0] [url = chrome://mochitests/content/chrome/dom/tests/mochitest/chrome/DOMWindowCreated_content.html]
11:45:20     INFO - --DOMWINDOW == 26 (0x130091c00) [pid = 1862] [serial = 29] [outer = 0x0] [url = about:blank]
11:45:25     INFO - --DOMWINDOW == 25 (0x128f1b000) [pid = 1862] [serial = 11] [outer = 0x0] [url = about:blank]
11:45:25     INFO - --DOMWINDOW == 24 (0x12925b000) [pid = 1862] [serial = 41] [outer = 0x0] [url = about:blank]
11:45:25     INFO - --DOMWINDOW == 23 (0x130ef9800) [pid = 1862] [serial = 39] [outer = 0x0] [url = about:blank]
11:45:25     INFO - --DOMWINDOW == 22 (0x130ccb800) [pid = 1862] [serial = 35] [outer = 0x0] [url = about:blank]
11:45:25     INFO - --DOMWINDOW == 21 (0x12ff96c00) [pid = 1862] [serial = 33] [outer = 0x0] [url = chrome://mochitests/content/chrome/dom/tests/mochitest/chrome/test_activation.xul]
11:45:25     INFO - --DOMWINDOW == 20 (0x12559d000) [pid = 1862] [serial = 24] [outer = 0x0] [url = chrome://mochitests/content/chrome/dom/tests/mochitest/chrome/test_DOM_element_instanceof.xul]
11:45:25     INFO - --DOMWINDOW == 19 (0x12fd93000) [pid = 1862] [serial = 19] [outer = 0x0] [url = about:blank]
11:45:25     INFO - --DOMWINDOW == 18 (0x12fc67800) [pid = 1862] [serial = 17] [outer = 0x0] [url = chrome://mochitests/content/chrome/dom/tests/mochitest/chrome/test_DOMWindowCreated.xul]
11:45:25     INFO - --DOMWINDOW == 17 (0x13005e800) [pid = 1862] [serial = 28] [outer = 0x0] [url = about:blank]
11:45:25     INFO - --DOMWINDOW == 16 (0x12559c800) [pid = 1862] [serial = 22] [outer = 0x0] [url = chrome://mochitests/content/chrome/dom/tests/mochitest/chrome/DOMWindowCreated_content.html]
11:45:25     INFO - --DOMWINDOW == 15 (0x130c90800) [pid = 1862] [serial = 31] [outer = 0x0] [url = about:blank]
11:45:25     INFO - --DOMWINDOW == 14 (0x1311ba000) [pid = 1862] [serial = 45] [outer = 0x0] [url = about:blank]
11:45:27     INFO - --DOMWINDOW == 13 (0x131378000) [pid = 1862] [serial = 46] [outer = 0x0] [url = chrome://mochitests/content/chrome/dom/tests/mochitest/chrome/file_bug1224790-2_nonmodal.xul]
11:45:32     INFO - --DOMWINDOW == 12 (0x13137a800) [pid = 1862] [serial = 47] [outer = 0x0] [url = about:blank]
11:50:39     INFO - TEST-INFO | started process screencapture
11:50:39     INFO - TEST-INFO | screencapture: exit 0
11:50:39     INFO - Buffered messages logged at 11:45:11
11:50:39     INFO - must wait for load
11:50:39     INFO - must wait for load
11:50:39     INFO - must wait for focus
11:50:39     INFO - Buffered messages logged at 11:45:12
11:50:39     INFO - must wait for load
11:50:39     INFO - must wait for focus
11:50:39     INFO - Buffered messages finished
11:50:39     INFO - TEST-UNEXPECTED-FAIL | dom/tests/mochitest/chrome/test_bug1224790-2.xul | Test timed out. 
11:50:39     INFO - reportError@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:120:7
11:50:39     INFO - TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:141:7
11:50:39     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
11:50:39     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
11:50:39     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
11:50:39     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
11:50:39     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
11:50:39     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
11:50:39     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
11:50:39     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
11:50:39     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
11:50:39     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
11:50:39     INFO - setTimeout handler*TestRunner._checkForHangs@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:162:5
11:50:39     INFO - TestRunner.runTests@chrome://mochikit/content/tests/SimpleTest/TestRunner.js:379:5
11:50:39     INFO - RunSet.runtests@chrome://mochikit/content/tests/SimpleTest/setup.js:190:3
11:50:39     INFO - RunSet.runall@chrome://mochikit/content/tests/SimpleTest/setup.js:169:5
11:50:39     INFO - hookupTests@chrome://mochikit/content/tests/SimpleTest/setup.js:262:5
11:50:39     INFO - parseTestManifest@chrome://mochikit/content/manifestLibrary.js:38:5
11:50:39     INFO - getTestManifest/req.onload@chrome://mochikit/content/manifestLibrary.js:49:11
11:50:39     INFO - EventHandlerNonNull*getTestManifest@chrome://mochikit/content/manifestLibrary.js:45:3
11:50:39     INFO - hookup@chrome://mochikit/content/tests/SimpleTest/setup.js:242:5
11:50:39     INFO - linkAndHookup@chrome://mochikit/content/harness.xul:59:3
11:50:39     INFO - parseTestManifest@chrome://mochikit/content/manifestLibrary.js:38:5
11:50:39     INFO - getTestManifest/req.onload@chrome://mochikit/content/manifestLibrary.js:49:11
11:50:39     INFO - EventHandlerNonNull*getTestManifest@chrome://mochikit/content/manifestLibrary.js:45:3
11:50:39     INFO - getTestList@chrome://mochikit/content/chrome-harness.js:260:3
11:50:39     INFO - loadTests@chrome://mochikit/content/harness.xul:38:3
11:50:39     INFO - EventListener.handleEvent*@chrome://mochikit/content/harness.xul:62:5
11:50:40     INFO - MEMORY STAT | vsize 4294MB | residentFast 346MB | heapAllocated 80MB
11:50:40     INFO - TEST-OK | dom/tests/mochitest/chrome/test_bug1224790-2.xul | took 328305ms


and the raw log file:
https://archive.mozilla.org/pub/firefox/tinderbox-builds/mozilla-inbound-macosx64-debug/mozilla-inbound_yosemite_r7-debug_test-mochitest-chrome-2-bm133-tests1-macosx-build43.txt.gz

here is the screenshot from the failure:
http://mozilla-releng-blobs.s3.amazonaws.com/blobs/mozilla-inbound/sha512/b5b413f3cfa7ed2382097127591b240e733c9519176c67545c1f56800ff9a981a3779506a04c57f09c77991a2040b50eb0946ca98c061de714d85580d1b42127

I am not sure if this is related to us not getting focus or not getting the onclick

as reference, here is the source code:
https://dxr.mozilla.org/mozilla-central/source/dom/tests/mochitest/chrome/test_bug1224790-2.xul?q=path%3Atest_bug1224790-2.xul&redirect_type=single
:mstange, as :arai doesn't seem to be on bugzilla anymore, I need to find an owner to look this failure.  With 19 failures yesterday, this is trending to be one of our top failures.  Can you help find someone to look at this bug?  Normally I would ask :overholt, but he is pto.
Flags: needinfo?(mstange)
Whiteboard: [stockwell needswork]
How is Tooru not in bugzilla anymore?

Tooru, could you take a look at this?
Flags: needinfo?(mstange) → needinfo?(arai.unmht)
in the original bug I saw :arai which didn't match, nor did Tooru as a name- thanks for making the association :smaug
hmm, the testcase uses native OSX event via js-ctypes, since otherwise it's not testable.
https://dxr.mozilla.org/mozilla-central/rev/34585620e529614c79ecc007705646de748e592d/testing/mochitest/tests/SimpleTest/EventUtils.js#1711

maybe that approach is unstable enough to cause the intermittent
(sorry, I didn't know it was causing so much intermittent :P

I'll try investigating.
if it's about focus, I could make it click twice.
I was hoping to see some logging, checks to help pinpoint it down, if we are not sure how to do this, possibly we can add more SimpleTest.ok() statements after receiving focus, sending the native events, etc.
just triggered try run with click twice if necessary:
  https://treeherder.mozilla.org/#/jobs?repo=try&revision=8ff920301694fd913da80aa6146a4225186b8b67

(the original bug is that the click doesn't work at all, so clicking twice still can verify the fix)
interestingly, the failure case happens when I run it with  --run-until-failure,
and I confirmed gotFocus() is called, but the click event dispatched by js-ctypes doesn't cause onClick.
and delaying the click 500ms solves it.
and also this intermittent is happening only on debug build.

I think, it's just that click event is dispatched too quickly after getting focus.
Flags: needinfo?(arai.unmht)
great find, glad you could reproduce it locally and debug does make sense.
the issue disappears even if I delay it to next event tick (setTimeout + 0ms)
maybe, Firefox itself is not yet ready while calling gotFocus ?
hmm, looks like OSX build on try isn't working at the moment :P

smaug, which way do you think is better?

  A. wait 0ms before click
  B. instantly click, and click again after 1000ms when no click happens
  C. wait 0ms before first click, and click again after 1000ms when no click happens
  D. something else (maybe, keep clicking until getting click event?)

all cases seems to work locally, but not sure on automation.
Flags: needinfo?(bugs)
can we get to a resolution here?  I see that :arai is going to be afk for a couple weeks and this is still a top intermittent- it sounds like we have a fix which I would rather see than disabling the test.
Assignee: nobody → arai.unmht
Status: NEW → ASSIGNED
luckily I'm available today :)

for now I'm going to go with plan B above
let me know if other way is better, or in case this doesn't help on automation
Comment on attachment 8847094 [details] [diff] [review]
Trigger mouse click twice in case the first click is overlooked

We can try this.

Do you need to mark these tests with requestFlakyTimeout?
Or perhaps chrome tests don't need that.

You should be able pass click as the callback to setTimeout. No need for function() { click(); }
Flags: needinfo?(bugs)
Attachment #8847094 - Flags: review?(bugs) → review+
thank you for reviewing

I don't think this needs special handling about timeout, as long as the issue on automation is the same thing as I confirmed locally.
https://hg.mozilla.org/integration/mozilla-inbound/rev/907a28cd35b045950df8f077383581c455f6af3c
Bug 1247519 - Trigger mouse click twice in case the first click is overlooked. r=smaug
https://hg.mozilla.org/mozilla-central/rev/907a28cd35b0
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
status-firefox55: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Whiteboard: [stockwell needswork] → [stockwell fixed]
Component: DOM → DOM: Core & HTML
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: