Closed Bug 1675902 Opened 5 years ago Closed 3 years ago

Intermittent dom/base/test/test_bug622117.html, test_bug622246.html, test_copypaste_disabled.html | Test timed out.

Categories

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

Product:
Core
Component:
DOM: Core & HTML
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
96 Branch

People

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

References

Details

(Keywords: intermittent-failure)

Attachments

(8 files)

Bug 1675902 - Wait until apz stable before synthesizing mouse input r=smaug
48 bytes, text/x-phabricator-request
Details | Review
Bug 1675902 - Disable test_bug622117.html on Android for frequent failures. r?#intermittent-reviewers
48 bytes, text/x-phabricator-request
Details | Review
Bug 1675902 - Try forcing focus on iframes r=smaug
48 bytes, text/x-phabricator-request
Details | Review
Bug 1675902 - disable test_bug622117.html, test_bug622246.html, test_copypaste_disabled.html on Android_7_debug for frequent failures. r=#intermittent-reviewers
48 bytes, text/x-phabricator-request
Details | Review
Bug 1675902 - update android condition r=Aryx
48 bytes, text/x-phabricator-request
Details | Review
Bug 1675902 - Remove an unused variable from test_bug622117.html. r=tnikkel
48 bytes, text/x-phabricator-request
Details | Review
Bug 1675902 - Disable the zoom part of zoom-to-focused-input in dom/base/test. r=tnikkel
48 bytes, text/x-phabricator-request
Details | Review
Bug 1675902 - Re-enable test_{bug622117,bug622246,copypaste_disabled}.html on android. r=tnikkel
48 bytes, text/x-phabricator-request
Details | Review

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

[task 2020-11-06T23:46:11.156Z] 23:46:11     INFO -  Buffered messages logged at 23:41:01
[task 2020-11-06T23:46:11.156Z] 23:46:11     INFO -  588 INFO must wait for load
[task 2020-11-06T23:46:11.156Z] 23:46:11     INFO -  Buffered messages finished
[task 2020-11-06T23:46:11.157Z] 23:46:11  WARNING -  589 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug622117.html | Test timed out.
[task 2020-11-06T23:46:11.157Z] 23:46:11     INFO -      SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2020-11-06T23:46:11.157Z] 23:46:11     INFO -      reportError@SimpleTest/TestRunner.js:143:22
[task 2020-11-06T23:46:11.157Z] 23:46:11     INFO -      TestRunner._checkForHangs@SimpleTest/TestRunner.js:165:18
[task 2020-11-06T23:46:11.157Z] 23:46:11     INFO -  590 INFO TEST-OK | dom/base/test/test_bug622117.html | took 301692ms
[task 2020-11-06T23:46:11.158Z] 23:46:11     INFO -  591 INFO TEST-START | dom/base/test/test_bug622246.html
[task 2020-11-06T23:51:36.433Z] 23:51:36     INFO -  Buffered messages logged at 23:46:04
[task 2020-11-06T23:51:36.433Z] 23:51:36     INFO -  592 INFO must wait for load
[task 2020-11-06T23:51:36.433Z] 23:51:36     INFO -  Buffered messages finished
[task 2020-11-06T23:51:36.434Z] 23:51:36  WARNING -  593 INFO TEST-UNEXPECTED-FAIL | dom/base/test/test_bug622246.html | Test timed out.
[task 2020-11-06T23:51:36.434Z] 23:51:36     INFO -      SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2020-11-06T23:51:36.434Z] 23:51:36     INFO -      reportError@SimpleTest/TestRunner.js:143:22
[task 2020-11-06T23:51:36.434Z] 23:51:36     INFO -      TestRunner._checkForHangs@SimpleTest/TestRunner.js:165:18
[task 2020-11-06T23:51:36.434Z] 23:51:36     INFO -  594 INFO TEST-OK | dom/base/test/test_bug622246.html | took 328964ms```

This bug failed 40 times in the last 7 days. Occurs on android-em-7-0-x86_64 and android-em-7-0-x86_64-qr on debug build types.

Recent log:
https://treeherder.mozilla.org/logviewer?job_id=336810248&repo=autoland

Jens: Can you please take a look at this bug?

Flags: needinfo?(jstutte)
Whiteboard: [stockwell:needsowner]

smaug:, do you remember what this 10-years old regression test is doing?

Flags: needinfo?(jstutte) → needinfo?(bugs)

My guess here is that we call synthesizeMouseAtCenter(a, {}, win); a bit too soon before the layout of the iframe has stabilized.
But I couldn't reproduce this even with --verify on Android.

Flags: needinfo?(bugs)

I wonder the fix for bug 1672141 may also fix this.

Assignee: nobody → krosylight
Pushed by krosylight@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/0db412525773 Wait until apz stable before synthesizing mouse input r=smaug

Hmm, it still happens and always happens together with failures in dom/base/test/test_copypaste_disabled.html, maybe a conflict with another test?

Okay, test_bug622117.html, test_bug622246.html, test_copypaste_disabled.html always fail together, only fail in Android debug build, and they all interacts with <iframe srcdoc> via synthesizeMouse().

Per logcat-emulator-*.log, GeckoView does receive a click but intermittently does not get any other relevant events:

When the test succeeds:

04-30 23:41:49.247  3287  3307 I GeckoDump: WaitUntilApzStable: all done
04-30 23:41:49.261  3287  3307 D GeckoViewAutofill[C]: handleEvent: focusin
04-30 23:41:49.265  3287  3307 E Web Content: [JavaScript Error: "uncaught exception: 1" {file: "about:srcdoc" line: 1}]
04-30 23:41:49.265  3287  3307 E Web Content: onclick@about:srcdoc:1:1
04-30 23:41:49.265  3287  3307 E Web Content: synthesizeMouseAtPoint@http://mochi.test:8888/tests/SimpleTest/EventUtils.js:605:13
04-30 23:41:49.265  3287  3307 E Web Content: synthesizeMouse@http://mochi.test:8888/tests/SimpleTest/EventUtils.js:508:10
04-30 23:41:49.265  3287  3307 E Web Content: synthesizeMouseAtCenter@http://mochi.test:8888/tests/SimpleTest/EventUtils.js:681:10
04-30 23:41:49.265  3287  3307 E Web Content: @http://mochi.test:8888/tests/dom/base/test/test_bug622117.html:42:26
04-30 23:41:49.267  3287  3307 D GeckoViewPrompt[C]: handleEvent: click
04-30 23:41:49.286  3287  3307 I Gecko   : [Child 3287, Main Thread] WARNING: early callback, or time went backwards: '!aAllowIdleDispatch', file /builds/worker/checkouts/gecko/xpcom/threads/IdleTaskRunner.cpp:179
04-30 23:41:49.290  3287  3307 D GeckoViewSelectionActionDelegate[C]: handleEvent: visibilitychange
04-30 23:41:49.291  3287  3307 D GeckoViewAutofill[C]: handleEvent: pagehide
04-30 23:41:49.292  3287  3307 D GeckoViewAutofill[C]: handleEvent: focusout
04-30 23:41:49.295  3261  3335 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
04-30 23:41:49.304  3261  3276 D GeckoViewNavigation: onLocationChange
04-30 23:41:49.305  3261  3261 D GeckoSession: handleMessage GeckoView:LocationChange uri=http://mochi.test:8888/tests/dom/base/test/PASS.html
04-30 23:41:49.307  3287  3307 W Web Content: [JavaScript Warning: "The character encoding of a framed document was not declared. The document may appear different if viewed without the document framing it." {file: "http://mochi.test:8888/tests/dom/base/test/PASS.html" line: 0}]
04-30 23:41:49.309  3287  3307 D GeckoViewContentDelegateChild[C]: handleEvent: DOMContentLoaded
04-30 23:41:49.317  3287  3307 I GeckoDump: ⰲ겿{"action":"test_status","time":1619822509317,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/base/test/test_bug622117.html","subtest":"Should have loaded link","status":"PASS","js_source":"TestRunner.js"}ⰲ겿

And when fails:

04-30 21:58:37.149  3266  3281 I GeckoDump: WaitUntilApzStable: all done
04-30 21:58:37.162  3266  3281 D GeckoViewPrompt[C]: handleEvent: click
04-30 21:58:37.191  3235  3310 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
04-30 21:58:37.995  3235  3250 W GeckoEventDispatcher: No listener for GeckoView:StateUpdated
04-30 22:00:00.027  1617  1617 D ConditionProviders.SCP: onReceive ScheduleConditionProvider.EVALUATE
04-30 22:00:00.027  1617  1617 D ConditionProviders.SCP: notifyCondition condition://android/schedule?days=6.7&start=23.30&end=10.0&exitAtAlarm=false STATE_FALSE reason=!meetsSchedule
04-30 22:00:00.028  1617  1617 D ConditionProviders.SCP: notifyCondition condition://android/schedule?days=1.2.3.4.5&start=22.0&end=7.0&exitAtAlarm=false STATE_FALSE reason=!meetsSchedule
04-30 22:00:00.028  1617  1617 D ConditionProviders.SCP: Scheduling evaluate for Fri Apr 30 23:30:00 GMT+01:00 2021 (1619821800000), in +1h29m59s973ms, now=Fri Apr 30 22:00:00 GMT+01:00 2021 (1619816400027)
04-30 22:04:06.092  3266  3281 I GeckoDump: ⰲ겿{"action":"test_status","time":1619816646089,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/base/test/test_bug622117.html","subtest":"Test timed out.","status":"FAIL","expected":"PASS","message":"","stack":"","js_source":"TestRunner.js"}ⰲ겿
04-30 22:04:07.114  3266  3281 I GeckoDump: ⰲ겿

But there is no good log about why the difference happens.

Update:

There have been 82 failures within the last 7 days, all of them on Android 7.0 x86-64 WebRender and Android 7.0 x86-64 DEBUG.

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=339099741&repo=autoland&lineNumber=2235

[task 2021-05-07T19:51:35.083Z] 19:51:35     INFO -  TEST-START | dom/base/test/test_bug622117.html
[task 2021-05-07T19:56:59.701Z] 19:56:59     INFO -  Buffered messages logged at 19:51:30
[task 2021-05-07T19:56:59.701Z] 19:56:59     INFO -  must wait for load
[task 2021-05-07T19:56:59.702Z] 19:56:59     INFO -  Buffered messages finished
[task 2021-05-07T19:56:59.703Z] 19:56:59  WARNING -  TEST-UNEXPECTED-FAIL | dom/base/test/test_bug622117.html | Test timed out. -
[task 2021-05-07T19:56:59.703Z] 19:56:59  WARNING -  TEST-UNEXPECTED-FAIL | dom/base/test/test_bug622117.html | [SimpleTest.finish()] No checks actually run. (You need to call ok(), is(), or similar functions at least once.  Make sure you use SimpleTest.waitForExplicitFinish() if you need it.)
[task 2021-05-07T19:56:59.703Z] 19:56:59     INFO -      SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2021-05-07T19:56:59.703Z] 19:56:59     INFO -      afterCleanup@SimpleTest/SimpleTest.js:1571:18
[task 2021-05-07T19:56:59.703Z] 19:56:59     INFO -      executeCleanupFunction@SimpleTest/SimpleTest.js:1636:7
[task 2021-05-07T19:56:59.703Z] 19:56:59     INFO -      executeCleanupFunction@SimpleTest/SimpleTest.js:1652:7
[task 2021-05-07T19:56:59.703Z] 19:56:59     INFO -      SimpleTest.finish@SimpleTest/SimpleTest.js:1656:3
[task 2021-05-07T19:56:59.703Z] 19:56:59     INFO -      killTest@SimpleTest/TestRunner.js:194:22
[task 2021-05-07T19:56:59.703Z] 19:56:59     INFO -  TEST-OK | dom/base/test/test_bug622117.html | took 325480ms
Whiteboard: [stockwell disable-recommended] → [stockwell disable-recommended][stockwell needswork:owner]
Pushed by nbeleuzu@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/80e567cf7ef7 Disable test_bug622117.html on Android for frequent failures. r=intermittent-reviewers,ahal
Whiteboard: [stockwell disable-recommended][stockwell needswork:owner] → [stockwell needswork:owner][stockwell disabled]

Disabling test_bug622117.html let the next test (test_bug622246.html) fail - bug 1711349.

Flags: needinfo?(krosylight)
Regressions: 1711349
Flags: needinfo?(krosylight)
Summary: Intermittent dom/base/test/test_bug622117.html | Test timed out. → Intermittent dom/base/test/test_bug622117.html, test_bug622246.html, test_copypaste_disabled.html | Test timed out.

There have been 68 total failures in the last 7 days (recent failure log).
Affected platforms are:

  • android-em-7-0-x86_64 debug
  • android-em-7-0-x86_64-qr debug

Kagami, are there any updates on this?

Flags: needinfo?(krosylight)
Flags: needinfo?(krosylight)

There have been 47 failures in the last 7 days(failure rate is dropping)

Happens on: android-em-7-0-x86_64 and android-em-7-0-x86_64-qr debug build type.

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=343182064&repo=autoland&lineNumber=2540

There are 51 total failures in the last 7 days, recent failure log.
Affected platforms are:

  • android-em-7-0-x86_64
  • android-em-7-0-x86_64-qr

Kagami, are there any updates on this?

Flags: needinfo?(krosylight)

Not sure there's anything left that I can do from DOM perspective... Anyway, from the log:

06-18 05:00:33.609  3673  3688 D GeckoViewPrompt[C]: handleEvent: click
06-18 05:00:33.892  3648  3663 W GeckoEventDispatcher: No listener for GeckoView:StateUpdated

This looks suspicious. Pinging triage owner of GeckoView:

Hi Emily, could you find some people to take a look at those failures (after wellness? 😉)

Flags: needinfo?(krosylight) → needinfo?(etoop)

@agi, can you please take a quick look at this?

Flags: needinfo?(etoop) → needinfo?(agi)

This might be something with layout/APZ? I know we have some android-only weirdness there. Given that we do get the click event I'm thinking maybe either the iframe is not actually ready or somehow APZ is not able to detect what we're clicking on?

Flags: needinfo?(agi)

(In reply to Agi Sferro | :agi | ni? for questions | ⏰ PST | he/him from comment #63)

Given that we do get the click event I'm thinking maybe either the iframe is not actually ready or somehow APZ is not able to detect what we're clicking on?

https://phabricator.services.mozilla.com/D117595 tried to make sure those won't happen, but it could be that waitUntilApzStable is still not enough.

Given that those three tests succeed together and fail together, I also suspect there is some global issue that persists during the whole test session.

Anyway, I think I did everything I can here 😬

Assignee: krosylight → nobody

botond, any ideas here?

Flags: needinfo?(botond)
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]

Update:

There have been a total of 49 failures in the past 7 days all of the on android-em-7-0-x86_64/qr debug

Recent failure log

[task 2021-07-17T06:27:40.398Z] 06:27:40     INFO -  must wait for focus
[task 2021-07-17T06:27:40.398Z] 06:27:40     INFO -  Buffered messages finished
[task 2021-07-17T06:27:40.399Z] 06:27:40  WARNING -  TEST-UNEXPECTED-FAIL | dom/base/test/test_bug622117.html | Test timed out. -
[task 2021-07-17T06:27:40.399Z] 06:27:40     INFO -  TEST-OK | dom/base/test/test_bug622117.html | took 329195ms```
Attachment #9231883 - Attachment description: Bug 1675902 - disable test_bug622117.html on Android_7_debug for frequent failures. r=#intermittent-reviewers → Bug 1675902 - disable test_bug622117.html, test_bug622246.html, test_copypaste_disabled.html on Android_7_debug for frequent failures. r=#intermittent-reviewers
Pushed by abutkovits@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/74ab1023138b disable test_bug622117.html, test_bug622246.html, test_copypaste_disabled.html on Android_7_debug for frequent failures. r=intermittent-reviewers,ahal DONTBUILD
Whiteboard: [stockwell needswork:owner] → [stockwell disabled]

Update:
There have been 36 failures within the last 7 days:
• 18 failures on android-em-7-0-x86_64-lite-qr debug
• 18 failures on Android 7.0 x86-64 WebRender debug
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=347732093&repo=autoland&lineNumber=2295

[task 2021-08-07T11:20:30.399Z] 11:20:30     INFO -  TEST-START | dom/base/test/test_bug622117.html
[task 2021-08-07T11:25:35.421Z] 11:25:35     INFO -  Buffered messages logged at 11:20:26
[task 2021-08-07T11:25:35.421Z] 11:25:35     INFO -  must wait for load
[task 2021-08-07T11:25:35.421Z] 11:25:35     INFO -  TEST-PASS | dom/base/test/test_bug622117.html | iframe is not loaded yet?
[task 2021-08-07T11:25:35.421Z] 11:25:35     INFO -  must wait for focus
[task 2021-08-07T11:25:35.421Z] 11:25:35     INFO -  Buffered messages finished
[task 2021-08-07T11:25:35.421Z] 11:25:35  WARNING -  TEST-UNEXPECTED-FAIL | dom/base/test/test_bug622117.html | Test timed out. -
[task 2021-08-07T11:25:35.422Z] 11:25:35     INFO -  TEST-OK | dom/base/test/test_bug622117.html | took 301657ms
[task 2021-08-07T11:25:35.422Z] 11:25:35     INFO -  TEST-START | dom/base/test/test_bug622246.html
[task 2021-08-07T11:31:00.803Z] 11:31:00     INFO -  Buffered messages logged at 11:25:28
[task 2021-08-07T11:31:00.803Z] 11:31:00     INFO -  must wait for load
[task 2021-08-07T11:31:00.804Z] 11:31:00     INFO -  TEST-PASS | dom/base/test/test_bug622246.html | iframe is not loaded yet?
[task 2021-08-07T11:31:00.804Z] 11:31:00     INFO -  must wait for focus
[task 2021-08-07T11:31:00.804Z] 11:31:00     INFO -  Buffered messages finished
[task 2021-08-07T11:31:00.804Z] 11:31:00  WARNING -  TEST-UNEXPECTED-FAIL | dom/base/test/test_bug622246.html | Test timed out. -
[task 2021-08-07T11:31:00.804Z] 11:31:00     INFO -  TEST-OK | dom/base/test/test_bug622246.html | took 328948ms
[task 2021-08-07T11:31:00.805Z] 11:31:00     INFO -  TEST-START | dom/base/test/test_bug625722.html
Whiteboard: [stockwell disabled] → [stockwell disabled][stockwell needswork:owner]
Pushed by apavel@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/8c7c61d40a5c update android condition r=aryx DONTBUILD

Sorry for the long turnaround time here. I debugged this over Try and it looks like previous tests in the directory are triggering zoom-to-focused-input which zooms the root content document containing the mochitest iframe (and then scrolls the visual viewport of the RCD away from the layout viewport origin), in some cases scrolling parts of the mochitest iframe offscreen and interfering with event synthesization in subsequent tests.

We've already disabled zoom-to-focused-input in some subdirectories of dom/base/test, I'm going to suggest that we disable it for the entire directory. Given the iframe setup in which mochitests run, it's hard to imagine a scenario where it's something we want to happen.

Assignee: nobody → botond
Flags: needinfo?(botond)

This feature causes problems on Android, where it can cause the
root content document to zoom in and its visual viewport to
scroll when an input element gets focus.

Since mochitests run inside iframes, manipulating the root
content document in this way is not something they expect
or want, and it can cause subsequent tests to fail.

The feature is already disabled in the forms/ and useractivation/
subdirectories.

Depends on D131178

Attachment #9250812 - Attachment description: Bug 1675902 - Disable zoom-to-focused-input in dom/base/test. r=tnikkel → Bug 1675902 - Disable the zoom part of zoom-to-focused-input in dom/base/test. r=tnikkel
Pushed by bballo@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/715efd911d40 Remove an unused variable from test_bug622117.html. r=tnikkel https://hg.mozilla.org/integration/autoland/rev/245ca4dd272c Disable the zoom part of zoom-to-focused-input in dom/base/test. r=tnikkel https://hg.mozilla.org/integration/autoland/rev/1697f05383ed Re-enable test_{bug622117,bug622246,copypaste_disabled}.html on android. r=tnikkel

This should have been closed when the fix landed.

Status: NEW → RESOLVED
Closed: 3 years ago
Keywords: leave-open
Resolution: --- → FIXED
Whiteboard: [stockwell disabled][stockwell needswork:owner]
Target Milestone: --- → 96 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: