Closed Bug 1668945 Opened 4 years ago Closed 3 years ago

[M-fis-xorig] Intermittent TEST-UNEXPECTED-TIMEOUT | http://mochi.test:8888/tests/dom/events/test/test_bug1581192.html | application timed out after 370 seconds with no output

Categories

(Core :: DOM: Events, defect, P5)

Product:
Core
Component:
DOM: Events
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
92 Branch
Project Flags:
Fission Milestone MVP
Tracking Flags:
Tracking Status
firefox-esr91 --- fixed
firefox89 --- disabled
firefox90 --- disabled
firefox91 --- disabled
firefox92 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: masayuki)

References

(Depends on 1 open bug, Blocks 1 open bug)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Bug 1668945 - Make `test_bug1581192.html` wait for the click target interactive r=smaug!
48 bytes, text/x-phabricator-request
Details | Review

Filed by: ncsoregi [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=317407869&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/BVhlEMZDRx6dVSN6nPMxEw/runs/0/artifacts/public/logs/live_backing.log

[task 2020-10-02T16:14:08.134Z] 16:14:08     INFO - TEST-START | http://mochi.test:8888/tests/dom/events/test/test_bug1581192.html
[task 2020-10-02T16:14:08.324Z] 16:14:08     INFO - GECKO(1496) | [2701, Unnamed thread 7f9cbbe5d5e0] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp, line 202
[task 2020-10-02T16:14:08.326Z] 16:14:08     INFO - GECKO(1496) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpMuKnAB.mozrunner/runtests_leaks.log
[task 2020-10-02T16:14:08.326Z] 16:14:08     INFO - GECKO(1496) | [2701, Unnamed thread 7f9cbbe5d5e0] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/worker/checkouts/gecko/xpcom/base/nsTraceRefcnt.cpp, line 202
[task 2020-10-02T16:14:08.327Z] 16:14:08     INFO - GECKO(1496) | [2701, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-10-02T16:14:08.510Z] 16:14:08     INFO - GECKO(1496) | [Child 2701, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp, line 626
[task 2020-10-02T16:14:08.525Z] 16:14:08     INFO - GECKO(1496) | [Child 2598, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-10-02T16:14:08.594Z] 16:14:08     INFO - GECKO(1496) | [Child 2598, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4287
[task 2020-10-02T16:14:08.642Z] 16:14:08     INFO - GECKO(1496) | [Child 1792, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp, line 348
[task 2020-10-02T16:19:34.306Z] 16:19:34     INFO - GECKO(1496) | JavaScript error: http://mochi.xorigin-test:8888/tests/SimpleTest/TestRunner.js, line 162: SecurityError: Permission denied to access property "wrappedJSObject" on cross-origin object
[task 2020-10-02T16:23:56.056Z] 16:23:56     INFO - GECKO(1496) | 1601655836048	addons.xpi	ERROR	System addon update list error Error: got node name: html, expected: updates
[task 2020-10-02T16:30:06.062Z] 16:30:06     INFO - Buffered messages logged at 16:14:08
[task 2020-10-02T16:30:06.063Z] 16:30:06     INFO - must wait for load
[task 2020-10-02T16:30:06.063Z] 16:30:06     INFO - must wait for focus
[task 2020-10-02T16:30:06.064Z] 16:30:06     INFO - Buffered messages finished
[task 2020-10-02T16:30:06.065Z] 16:30:06    ERROR - TEST-UNEXPECTED-TIMEOUT | http://mochi.test:8888/tests/dom/events/test/test_bug1581192.html | application timed out after 370 seconds with no output
[task 2020-10-02T16:30:06.065Z] 16:30:06    ERROR - Force-terminating active process(es).```

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE

New occurrence:
https://treeherder.mozilla.org/logviewer?job_id=324083975&repo=mozilla-central&lineNumber=2724

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

ahal hit this test failure when trying to to enable mochitest-plan in fission-xorigin mode on more platforms in bug 1694835.

https://treeherder.mozilla.org/jobs?repo=try&revision=a4813c46eff128482994870bf8a06677022cee24&selectedTaskRun=Qsw0nYMWQsS8FH7RYROgXw.0

This intermittent failure probably doesn't need to block Fission MVP because it is so infrequent (only about once a week).

Blocks: 1694835, fission-tests
Fission Milestone: --- → Future
status-firefox89: --- → affected
No longer blocks: 1694835
Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | http://mochi.test:8888/tests/dom/events/test/test_bug1581192.html | application timed out after 370 seconds with no output → [M-fis-xorig] Intermittent TEST-UNEXPECTED-TIMEOUT | http://mochi.test:8888/tests/dom/events/test/test_bug1581192.html | application timed out after 370 seconds with no output

We haven't seen this test fail in almost two months. When it used to fail 2–8 months ago, it failed only 1–3 times per week. I think we can probably close this bug as WORKSFORME.

We currently run this test only on linux1804-64/debug on autoland, so we might see failures again when we enable the test on Windows, macOS, and Linux ASan/TSan in bug 1700781.

Status: REOPENED → RESOLVED
Closed: 4 years ago → 3 years ago
Resolution: --- → WORKSFORME

(In reply to Chris Peterson [:cpeterson] from comment #20)

We haven't seen this test fail in almost two months. When it used to fail 2–8 months ago, it failed only 1–3 times per week. I think we can probably close this bug as WORKSFORME.

We currently run this test only on linux1804-64/debug on autoland, so we might see failures again when we enable the test on Windows, macOS, and Linux ASan/TSan in bug 1700781.

Reopening this bug because this failure was reproduced (on Windows and macOS)

This test is currently skipped for Window and macOS opt builds in fission+xorigin mode:

[test_bug1581192.html]
skip-if =
  fission && xorigin && (os == "win" || os == "mac") && !debug  # Bug 1716405 - New fission platform triage

https://searchfox.org/mozilla-central/rev/5e955a47c4af398e2a859b34056017764e7a2252/dom/events/test/mochitest.ini#264-266

Status: RESOLVED → REOPENED
Fission Milestone: Future → ?
status-firefox91: --- → affected
Resolution: WORKSFORME → ---

Change the status for beta to have the same as nightly and release.
For more information, please visit auto_nag documentation.

status-firefox90: --- → affected

masayuki, would you have time to look at this a bit?
I assume this is just some timing issue in the test.

Flags: needinfo?(masayuki)

FWIW, I don't think this needs to be m7a.

Fission Milestone: ? → MVP

According to the log, click event is not fired with synthesizing a set of mouse button events on it. So, it must be the parent document's reflow or something similar issue which blocks event dispatching via the parent process. So, it does not need to block the release.

Anyway, I take a look a bit, but perhaps, this is caused by a my backlog issue.

Flags: needinfo?(masayuki)

(In reply to Masayuki Nakano [:masayuki] (he/him)(JST, +0900) from comment #25)

Anyway, I take a look a bit, but perhaps, this is caused by a my backlog issue.

Thanks! In that case, I will assign this bug to you for now.

Assignee: nobody → masayuki

I briefly checked what it happens.

When the timeout occurs, mousedown and mouseup events are fired on <iframe> in http://mochi.xorigin-test:8888/tests instead of <button> element in the <iframe>. At this time, the document.readyState is complete, but HTMLIFrameElement::GetContentDocument() returns nullptr. I.e., the child document is loaded and starts to running its script (the test body), but the document hasn't been attached to the parent's <iframe> element yet. I think that the mochitest framework shouldn't run SimpleTest.waitForFocus until the document is attached to the parent <iframe> or the frame should be attached forcibly when async event synthesizer runs in Gecko. WDYT, smaug?

Flags: needinfo?(bugs)

In the case, BrowsingContext::GetDOMWindow() returns nullptr due to its mDocShell is nullptr.

Trying to make SimpleTest.waitForFocus wait for the <iframe> to be interactive.
https://treeherder.mozilla.org/jobs?repo=try&revision=558049aa5732cdbd1bb7587b8c16e1ba7180e310

(In reply to Masayuki Nakano [:masayuki] (he/him)(JST, +0900) from comment #29)

Trying to make SimpleTest.waitForFocus wait for the <iframe> to be interactive.
https://treeherder.mozilla.org/jobs?repo=try&revision=558049aa5732cdbd1bb7587b8c16e1ba7180e310

Oops, this does not retry the hack. And that makes odd result in other tests.

Anyway, iframe.contentDocument is null from the TestRunner...

Hmm, currently, I have no idea how to check whether the <iframe> in the parent (TestRunner) is loaded or not from TestRunner running in the parent. $("testframe").contentDocument is always null (using with SpecialPowers.wrap is also same result). And adding new chrome only readonly attribute to HTMLIFrameElement does not solve it too. Is the HTMLIFrameElement::mDocShell never set for OOP <iframe>?

Hmm, it might be caused by the race of IPC messages (I'm not sure whether the Content#CreateBrowsingContext is used for initializing OOP <iframe> though).
https://searchfox.org/mozilla-central/rev/f351e19360729b351bfc7c1386d6e4ca4ea676e2/dom/ipc/PBrowser.ipdl#631
https://searchfox.org/mozilla-central/rev/f351e19360729b351bfc7c1386d6e4ca4ea676e2/dom/ipc/PContent.ipdl#1756

Status: REOPENED → ASSIGNED

When the test times out, the <iframe> element in the parent document receives
the mouse button events. This may happen if APZC has not received layout
information from subframe's document yet.

For solving this issue, this patch adds a utility method into EventUtils.js
that waits a mousemove event synthesized on the given target.

Pushed by masayuki@d-toybox.com:
https://hg.mozilla.org/integration/autoland/rev/1a8f49829ec4
Make `test_bug1581192.html` wait for the click target interactive r=smaug

https://hg.mozilla.org/mozilla-central/rev/1a8f49829ec4

Status: ASSIGNED → RESOLVED
Closed: 3 years ago → 3 years ago
status-firefox92: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 92 Branch
status-firefox91: affected → disabled
Flags: needinfo?(bugs)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: