1704741 - Intermittent dom/events/test/test_focus_blur_on_click_in_deep_cross_origin_iframe.html | Test timed out. -

Status: RESOLVED FIXED

(Core :: DOM: UI Events & Focus Handling, defect, P5)

Description

[Treeherder Bug Filer]

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

---

INFO - TEST-START | dom/events/test/test_focus_blur_on_click_in_deep_cross_origin_iframe.html
[task 2021-04-13T05:42:37.973Z] 05:42:37     INFO - GECKO(3358) | PromiseApzRepaintsFlushed: Flushed APZ repaints, waiting for callback...
[task 2021-04-13T05:42:37.980Z] 05:42:37     INFO - GECKO(3358) | PromiseApzRepaintsFlushed: APZ flush done
[task 2021-04-13T05:42:38.057Z] 05:42:38     INFO - GECKO(3358) | WaitUntilApzStable: flushed APZ repaints in parent proc, waiting for callback...
[task 2021-04-13T05:42:38.061Z] 05:42:38     INFO - GECKO(3358) | WaitUntilApzStable: APZ flush done in parent proc
[task 2021-04-13T05:42:38.062Z] 05:42:38     INFO - GECKO(3358) | WaitUntilApzStable: got apz-flush-done in child proc
[task 2021-04-13T05:42:38.063Z] 05:42:38     INFO - GECKO(3358) | WaitUntilApzStable: done promiseFocus
[task 2021-04-13T05:42:38.064Z] 05:42:38     INFO - GECKO(3358) | WaitUntilApzStable: done promiseAllPaintsDone
[task 2021-04-13T05:42:38.065Z] 05:42:38     INFO - GECKO(3358) | PromiseApzRepaintsFlushed: Flushed APZ repaints, waiting for callback...
[task 2021-04-13T05:42:38.066Z] 05:42:38     INFO - GECKO(3358) | PromiseApzRepaintsFlushed: APZ flush done
[task 2021-04-13T05:42:38.067Z] 05:42:38     INFO - GECKO(3358) | WaitUntilApzStable: all done
[task 2021-04-13T05:48:03.767Z] 05:48:03     INFO - TEST-INFO | started process screentopng
[task 2021-04-13T05:48:03.916Z] 05:48:03     INFO - TEST-INFO | screentopng: exit 0
[task 2021-04-13T05:48:03.918Z] 05:48:03     INFO - Buffered messages logged at 05:42:37
[task 2021-04-13T05:48:03.918Z] 05:48:03     INFO - add_task | Entering test 
[task 2021-04-13T05:48:03.918Z] 05:48:03     INFO - Buffered messages logged at 05:42:38
[task 2021-04-13T05:48:03.918Z] 05:48:03     INFO - receive innerfocus
[task 2021-04-13T05:48:03.918Z] 05:48:03     INFO - Buffered messages finished
[task 2021-04-13T05:48:03.918Z] 05:48:03     INFO - TEST-UNEXPECTED-FAIL | dom/events/test/test_focus_blur_on_click_in_deep_cross_origin_iframe.html | Test timed out. - 
[task 2021-04-13T05:48:04.775Z] 05:48:04     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-04-13T05:48:04.779Z] 05:48:04     INFO - TEST-UNEXPECTED-FAIL | dom/events/test/test_focus_blur_on_click_in_deep_cross_origin_iframe.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-04-13T05:48:04.780Z] 05:48:04     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2021-04-13T05:48:04.780Z] 05:48:04     INFO -     afterCleanup@SimpleTest/SimpleTest.js:1571:18
[task 2021-04-13T05:48:04.780Z] 05:48:04     INFO -     executeCleanupFunction@SimpleTest/SimpleTest.js:1636:7
[task 2021-04-13T05:48:04.781Z] 05:48:04     INFO -     executeCleanupFunction@SimpleTest/SimpleTest.js:1652:7
[task 2021-04-13T05:48:04.782Z] 05:48:04     INFO -     SimpleTest.finish@SimpleTest/SimpleTest.js:1656:3
[task 2021-04-13T05:48:04.783Z] 05:48:04     INFO -     killTest@SimpleTest/TestRunner.js:194:22
[task 2021-04-13T05:48:04.784Z] 05:48:04     INFO - GECKO(3358) | MEMORY STAT | vsize 2598MB | residentFast 142MB | heapAllocated 12MB
[task 2021-04-13T05:48:04.806Z] 05:48:04     INFO - TEST-OK | dom/events/test/test_focus_blur_on_click_in_deep_cross_origin_iframe.html | took 327181ms
[task 2021-04-13T05:48:04.807Z] 05:48:04    ERROR - TEST-UNEXPECTED-FAIL | /tests/dom/events/test/test_focus_blur_on_click_in_deep_cross_origin_iframe.html logged result after SimpleTest.finish(): [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-04-13T05:48:04.823Z] 05:48:04     INFO - TEST-START | dom/events/test/test_hover_mouseleave.html```

Comment 2

[Intermittent Failures Robot]

16 failures in 649 pushes (0.025 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 14
• mozilla-central: 2

Platform and build breakdown:

• macosx1015-64-qr: 10
  • opt: 10
• linux1804-64-shippable-qr: 1
  • opt: 1
• macosx1015-64-shippable-qr: 5
  • opt: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1704741&startday=2021-04-13&endday=2021-04-13&tree=all

Comment 3

[Sandor Molnar[:smolnar]]

@Andrei, could you take a look?
it started (almost) perma failing from your push

https://treeherder.mozilla.org/jobs?repo=autoland&fromchange=f7b0cdc3aeb09323d637a25b61ebe1a07074ad1b&searchStr=OS%2CX%2C10.15%2CWebRender%2Copt%2CMochitests%2Cwith%2Cfission%2Cenabled%2Ctest-macosx1015-64-qr%2Fopt-mochitest-plain-fis-e10s%2C4&tochange=0daf1f22db6ceecb1266e189f910b84e85cb7575&selectedTaskRun=H6qapWl_S-uJlNfAipC0XQ.0

Comment 4

[Edgar Chen [:edgar]]

So the mouse events still aren't dispatched to the expecting process.

And I add some APZ log and try to reproduce on in https://treeherder.mozilla.org/jobs?repo=try&group_state=expanded&revision=4296267603cf14055745dc11d4fae6b0b68eccf4.

This is log for the normal case, https://treeherder.mozilla.org/logviewer?job_id=336487802&repo=try:

[task 2021-04-14T12:41:37.877Z] 12:41:37 INFO - GECKO(1320) | (1324) test: promiseApzFlushedRepaints
[task 2021-04-14T12:41:37.877Z] 12:41:37 INFO - GECKO(1320) | PromiseApzRepaintsFlushed: Flushed APZ repaints, waiting for callback...
[task 2021-04-14T12:41:37.877Z] 12:41:37 INFO - GECKO(1320) | (1320) apz.manager: Flushing repaints for layers id 0x100000009
[task 2021-04-14T12:41:37.877Z] 12:41:37 INFO - GECKO(1320) | PromiseApzRepaintsFlushed: APZ flush done
...
[task 2021-04-14T12:41:37.878Z] 12:41:37 INFO - GECKO(1320) | (1324) test: waitUntilApzStable
[task 2021-04-14T12:41:37.903Z] 12:41:37 INFO - GECKO(1320) | WaitUntilApzStable: flushed APZ repaints in parent proc, waiting for callback...
[task 2021-04-14T12:41:37.903Z] 12:41:37 INFO - GECKO(1320) | (1320) apz.manager: Flushing repaints for layers id 0x100000006
[task 2021-04-14T12:41:37.903Z] 12:41:37 INFO - GECKO(1320) | WaitUntilApzStable: APZ flush done in parent proc
[task 2021-04-14T12:41:37.903Z] 12:41:37 INFO - GECKO(1320) | WaitUntilApzStable: got apz-flush-done in child proc
[task 2021-04-14T12:41:37.903Z] 12:41:37 INFO - GECKO(1320) | WaitUntilApzStable: done promiseFocus
[task 2021-04-14T12:41:37.903Z] 12:41:37 INFO - GECKO(1320) | WaitUntilApzStable: done promiseAllPaintsDone
[task 2021-04-14T12:41:37.904Z] 12:41:37 INFO - GECKO(1320) | PromiseApzRepaintsFlushed: Flushed APZ repaints, waiting for callback...
[task 2021-04-14T12:41:37.904Z] 12:41:37 INFO - GECKO(1320) | (1320) apz.manager: Flushing repaints for layers id 0x100000009
[task 2021-04-14T12:41:37.904Z] 12:41:37 INFO - GECKO(1320) | PromiseApzRepaintsFlushed: APZ flush done
[task 2021-04-14T12:41:37.904Z] 12:41:37 INFO - GECKO(1320) | WaitUntilApzStable: all done
...
[task 2021-04-14T12:41:37.904Z] 12:41:37 INFO - GECKO(1320) | (1324) test: synthesize native mouse event 1
[task 2021-04-14T12:41:37.904Z] 12:41:37 INFO - GECKO(1320) | (1320) apz.manager: Hit-testing point (31,362) with WR
[task 2021-04-14T12:41:37.904Z] 12:41:37 INFO - GECKO(1320) | (1320) apz.manager: Examining result with guid { l=0x100000023, p=0, v=0 } hit info 0x1...
[task 2021-04-14T12:41:37.905Z] 12:41:37 INFO - GECKO(1320) | (1320) apz.manager: no corresponding node found, falling back to root.
[task 2021-04-14T12:41:37.905Z] 12:41:37 INFO - GECKO(1320) | (1320) apz.manager: selecting as chosen result.
[task 2021-04-14T12:41:37.905Z] 12:41:37 INFO - GECKO(1320) | (1320) apz.manager: Successfully matched APZC 0x18ccc3000 (hit result 0x1)

We can see that test wait the layers id 0x100000009 (test document process) and 0x100000006 (parent process) to be flushed, but the mouse event is dispatch to the layers id 0x100000023 (iframe process).

I found that the promiseApzFlushedRepaints() and waitUntilApzStable() doesn't flush all layer, but only layer that request flush and parent-process layer tree. So I think it worth to try calling promiseApzFlushedRepaints() in oop iframe to flush its layer and wait it done to see if that helps.

Comment 5

[Edgar Chen [:edgar]]

Attachment: Bug 1704741 - Wait for iframe's layer flushed before starting the test;

promiseApzFlushedRepaints() and waitUntilApzStable() only flush the layer
that makes the request and also parent-process layer tree. And since test tries
to dispatch mouse events to oop iframe, so call promiseApzFlushedRepaints()
in oop iframe to flush its layer and wait it done as well.

Comment 6

[Edgar Chen [:edgar]]

• Without patch: https://treeherder.mozilla.org/jobs?repo=try&group_state=expanded&resultStatus=usercancel%2Csuperseded%2Cpending%2Crunning%2Ctestfailed%2Cbusted%2Cexception%2Csuccess%2Crunnable&test_paths=dom%2Fevents%2Ftest&searchStr=mochitest%2Cfission%2Cmac&revision=f3cb7e1314fada5e626d0c47fa82c1722557ca5a
• With patch: https://treeherder.mozilla.org/jobs?repo=try&group_state=expanded&resultStatus=usercancel%2Csuperseded%2Cpending%2Crunning%2Ctestfailed%2Cbusted%2Cexception%2Csuccess%2Crunnable&test_paths=dom%2Fevents%2Ftest&searchStr=mochitest%2Cfission%2Cmac&revision=26f6a5c5d1afcd8c313610aca1b3c0855dfaa756

(I pinned the unrelated failures)

Comment 7

[Intermittent Failures Robot]

20 failures in 1076 pushes (0.019 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 18
• mozilla-central: 2

Platform and build breakdown:

• macosx1015-64-qr: 14
  • opt: 14
• linux1804-64-shippable-qr: 2
  • opt: 2
• macosx1015-64-shippable-qr: 4
  • opt: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1704741&startday=2021-04-14&endday=2021-04-14&tree=all

Comment 8

[Intermittent Failures Robot]

61 failures in 4255 pushes (0.014 failures/push) were associated with this bug in the last 7 days.

This is the #27 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-central: 8
• autoland: 53

Platform and build breakdown:

• linux1804-64-shippable-qr: 4
  • opt: 4
• macosx1015-64-qr: 36
  • opt: 36
• macosx1015-64-shippable-qr: 20
  • opt: 20
• linux1804-64-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1704741&startday=2021-04-12&endday=2021-04-18&tree=all

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/9a7fef4f7226
Wait for iframe's layer flushed before starting the test; r=hsivonen

Comment 10

[Dorel Luca [:dluca]]

https://hg.mozilla.org/mozilla-central/rev/9a7fef4f7226

Comment 11

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/b71a93198566

Comment 12

[Intermittent Failures Robot]

5 failures in 3224 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3
• mozilla-central: 2

Platform and build breakdown:

• macosx1015-64-qr: 1
  • opt: 1
• macosx1014-64-qr: 1
  • opt: 1
• linux1804-64: 1
  • opt: 1
• macosx1015-64-shippable-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1704741&startday=2021-04-19&endday=2021-04-25&tree=all

Comment 13

[Intermittent Failures Robot]

1 failures in 3444 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-esr91: 1

Platform and build breakdown:

• linux1804-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1704741&startday=2022-01-17&endday=2022-01-23&tree=all