1775118 - High frequency TEST-UNEXPECTED-FAIL | /focus/<random> | Check focus event after focusing same site iframe - assert_equals: expected <random>

Status: RESOLVED FIXED

(Testing :: web-platform-tests, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-06-20T15:31:57.223Z] 15:31:57     INFO - TEST-START | /focus/focus-event-after-focusing-iframes.html
[task 2022-06-20T15:31:57.226Z] 15:31:57     INFO - Closing window b78adbf8-b664-4a54-acb4-3fd27992938b
[task 2022-06-20T15:31:57.508Z] 15:31:57     INFO - 
[task 2022-06-20T15:31:57.508Z] 15:31:57     INFO - TEST-PASS | /focus/focus-event-after-focusing-iframes.html | Check focus event after focusing different site iframe 
[task 2022-06-20T15:31:57.508Z] 15:31:57     INFO - TEST-UNEXPECTED-FAIL | /focus/focus-event-after-focusing-iframes.html | Check focus event after focusing same site iframe - assert_equals: expected "outerlog:willfocusiframe,windowblur,didfocusiframe,innerlog:windowfocus," but got "outerlog:windowfocus,willfocusiframe,windowblur,didfocusiframe,innerlog:windowfocus,"
[task 2022-06-20T15:31:57.510Z] 15:31:57     INFO - runTest@http://web-platform.test:8000/focus/focus-event-after-focusing-iframes.html:42:16
[task 2022-06-20T15:31:57.510Z] 15:31:57     INFO - TEST-OK | /focus/focus-event-after-focusing-iframes.html | took 285ms
[task 2022-06-20T15:31:57.513Z] 15:31:57     INFO - PID 2660 | 1655739117511	Marionette	INFO	Stopped listening on port 63430
[task 2022-06-20T15:31:57.593Z] 15:31:57     INFO - PID 2660 | [Parent 5024, Main Thread] WARNING: ContentParent: id=1a296300 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3607
[task 2022-06-20T15:31:57.594Z] 15:31:57     INFO - PID 2660 | [Parent 5024, Main Thread] WARNING: ContentParent: id=1a296300 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1808
[task 2022-06-20T15:31:57.595Z] 15:31:57     INFO - PID 2660 | [Parent 5024, Main Thread] WARNING: ContentParent: id=1a614600 - BlockShutdown: CanSend.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3607
[task 2022-06-20T15:31:57.596Z] 15:31:57     INFO - PID 2660 | [Parent 5024, Main Thread] WARNING: ContentParent: id=1a614600 - ShutDownProcess: Sent shutdown message.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1808
[task 2022-06-20T15:31:57.598Z] 15:31:57     INFO - PID 2660 | [Parent 5024, Main Thread] WARNING: ContentParent: id=1a296300 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1843
[task 2022-06-20T15:31:57.599Z] 15:31:57     INFO - PID 2660 | [Parent 5024, Main Thread] WARNING: ContentParent: id=1a296300 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3709
[task 2022-06-20T15:31:57.600Z] 15:31:57     INFO - PID 2660 | [Parent 5024, Main Thread] WARNING: ContentParent: id=1a614600 - ShutDownProcess: Closing channel.: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:1843
[task 2022-06-20T15:31:57.601Z] 15:31:57     INFO - PID 2660 | [Parent 5024, Main Thread] WARNING: ContentParent: id=1a614600 - RemoveShutdownBlockers: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3709
[task 2022-06-20T15:31:58.056Z] 15:31:58     INFO - Browser exited with return code 0
[task 2022-06-20T15:31:58.059Z] 15:31:58     INFO - Closing logging queue
[task 2022-06-20T15:31:58.059Z] 15:31:58     INFO - queue closed
[task 2022-06-20T15:31:58.172Z] 15:31:58     INFO - Application command: Z:\task_165573574756123\build\application\firefox\firefox.exe -marionette about:blank --wait-for-browser -profile C:\Users\task_165573574756123\AppData\Local\Temp\tmp5hwvyxh7
[task 2022-06-20T15:31:58.181Z] 15:31:58     INFO - PID 8280 | 1655739091642	Marionette	INFO	Marionette enabled
[task 2022-06-20T15:31:58.182Z] 15:31:58     INFO - PID 8280 | 1655739091645	Marionette	INFO	Listening on port 63540
[task 2022-06-20T15:31:58.183Z] 15:31:58     INFO - PID 8280 | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at C:\\Users\\task_165573574756123\\AppData\\Local\\Temp\\tmppk4rotcv\\search.json.mozlz4", (void 0)))
[task 2022-06-20T15:31:58.183Z] 15:31:58     INFO - Starting runner
[task 2022-06-20T15:31:59.281Z] 15:31:59     INFO - TEST-START | /focus/focus-event-after-iframe-gets-focus.html

Comment 1

[Iulian Moraru]

Hi Hsin-Yi! Can you please take a look at this? It is almost permafailing on the files related to "/focus/".
The increase in frequency started around here somewhere: Backfill range and retriggers
Thank you!

Comment 2

[Sandor Molnar[:smolnar]]

@Gerald, retriggers and backfills ( another set of retriggers and backfills ) indicate this failure starts from bug 1767396

Can you take a look?

Comment 3

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1767396

Comment 4

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

I'm investigating now. If I can't fix it quickly, we'd better backout bug 1767396 before the software freeze at the end of the week.

Comment 5

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

I see that it was already an intermittent (bug 1680642, and similar bug 1727220), but the recent regressing bug 1767396 just made it happen much more "reliably".
The failure is from an unexpected "windowfocus" at the start of the outerwindow log.

Thoughts:

I'm guessing there may be a timing issue between setting the outerframe's onfocus handler, and the outerframe getting its initial focus?
Disclaimer: I'm not an expert in page loading order, I may need help to determine if the test is really correct (isn't the outerframe's initial focus out-of-scope for this iframe test?), or if Firefox was already taking timing risks that my regressing bug 1767396 made worse.

For more context here, regressing bug 1767396:

• Removed TimerThread wake-ups that happened at every timer cancellation/removal, and
• Added a TimerThread wake-up when adding a zero-delay timer (e.g., setTimeout(..., 0)).
  This latter change was needed because some other code&tests rely on fast setTimeout(..., 0) triggers, which were previously happening quickly enough thanks to frequent RemoveTimers (otherwise, "natural" timer wake-ups could introduce multiple-milliseconds delays).

But I'm guessing that in this case here, the windowsfocus event not usually being logged may have relied on setTimeout(..., 0) not happening too quickly.
I'll keep exploring...

Comment 6

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Some more intermittents with unexpected "windowfocus" at the start of the outerwindow log: bug 1743217, bug 1712149, bug 1697136, bug 1755162, bug 1770271.

Also, bug 1203917 has some possibly-relevant discussions about how tests may start running indeterminately before or after the test window has received its initial focus.

NI: Edgar, I believe you wrote this test and others in bug 1678349. I see in bug 1712149 comment 3 that you couldn't reproduce the intermittent issue then... Maybe my regressing bug 1767396 could help you with that now? 😅
Please see my (non-expert) thoughts in the previous comment, if they make any sense to you. In particular, do we really care about this spurious first "windowfocus", and should&could we ignore it?
If you don't think you/we can get this properly fixed this week, I'd be happy to get the regressing bug backed-out, we could still use it locally to reproduce these issues.

Comment 7

[Intermittent Failures Robot]

91 failures in 518 pushes (0.176 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 86
• mozilla-central: 5

Platform and build breakdown:

• windows10-32-2004-qr: 33
  • opt: 32
  • debug: 1
• windows10-64-2004-qr: 39
  • opt: 39
• macosx1015-64-qr: 15
  • debug: 9
  • opt: 6
• linux1804-64-qr: 1
  • debug: 1
• windows10-64-2004-shippable-qr: 1
  • opt: 1
• windows10-32-2004-shippable-qr: 1
  • opt: 1
• macosx1015-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1775118&startday=2022-06-20&endday=2022-06-20&tree=all

Comment 9

[Edgar Chen [:edgar]]

(In reply to Gerald Squelart [:gerald] (he/him) from comment #6)

In particular, do we really care about this spurious first "windowfocus", and should&could we ignore it?

I don't think we really care about the initial focus event, I didn't aware there is any spec ensure the order of load and focus event. And yes, the initial focus event is out-of-scope for the thing that the wpt would like to test. Maybe we could do something like what SimpleTest.promiseFocus does [1] to ignore the initial focus event. I am going to give it a shot first, but if thing doesn't goes well, I will need your help to back-out bug 1767396.

[1] See https://searchfox.org/mozilla-central/rev/b1a5802e0f73bfd6d2096e5fefc2b47831a50b2d/testing/mochitest/tests/SimpleTest/SimpleTest.js#931-1032

Comment 10

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Thank you Edgar.

Regarding a solution, could we do something simpler and sneakier inside the tests, like (await getLog(w)).replace("outerlog:windowfocus,", "outerlog:"), just to remove the spurious windowfocus if it's there at the beginning?

Anyway, please have a look at what makes most sense, it's your domain. 😅
And no problems to back out if you need more time to do this right...

Comment 11

[Edgar Chen [:edgar]]

(In reply to Gerald Squelart [:gerald] (he/him) from comment #10)

Thank you Edgar.

Regarding a solution, could we do something simpler and sneakier inside the tests, like (await getLog(w)).replace("outerlog:windowfocus,", "outerlog:"), just to remove the spurious windowfocus if it's there at the beginning?

That works, too. But the event logging is also used for detecting any unexpected focus event which should not happened during test.
Always stripping the first windowfocus makes test lose that ability as we can not really tell if the windowfocus is from initial focus event or a unexpected focus event during the test.

Comment 12

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

(In reply to Edgar Chen [:edgar] from comment #11)

Always stripping the first windowfocus makes test lose that ability as we can not really tell if the windowfocus is from initial focus event or a unexpected focus event during the test.

That makes sense, indeed we don't want to miss a truly-incorrect focus event.

I assume you're still working on the better solution as per comment 9.
Just in case you cannot get it done soon enough (say, by the end of your Wednesday) : Would you consider the quick fix I suggested, with a follow-up to implement the better solution? Otherwise please let me know and I'll request or push a back-out of bug 1767396.

Comment 13

[Edgar Chen [:edgar]]

(In reply to Gerald Squelart [:gerald] (he/him) from comment #12)

I assume you're still working on the better solution as per comment 9.
Just in case you cannot get it done soon enough (say, by the end of your Wednesday) : Would you consider the quick fix I suggested, with a follow-up to implement the better solution? Otherwise please let me know and I'll request or push a back-out of bug 1767396.

Yes, I am currently trying to verify whether my solution works on treeherder (It is still not reproducible locally even with verify mode).
If things doesn't go well tomorrow, I'll let you know to request back-out bug 1767396. Thanks!

Comment 14

[Intermittent Failures Robot]

25 failures in 538 pushes (0.046 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 10
• mozilla-central: 13
• try: 2

Platform and build breakdown:

• macosx1015-64-qr: 8
  • debug: 5
  • opt: 3
• windows10-64-2004-qr: 5
  • opt: 4
  • debug: 1
• windows10-64-2004-shippable-qr: 4
  • opt: 4
• macosx1015-64-shippable-qr: 3
  • opt: 3
• windows10-32-2004-qr: 2
  • opt: 1
  • debug: 1
• windows10-32-2004-shippable-qr: 2
  • opt: 2
• windows10-64-2004-devedition-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1775118&startday=2022-06-21&endday=2022-06-21&tree=all

Comment 15

[Edgar Chen [:edgar]]

Attachment: Bug 1775118 - Delay logging for focus event on toplevel window in order to ignore the inital focus event;

I didn't aware there is any spec that ensure the order of load event and initial
focus event. It could be possible that the initial focus event comes after load
event and cause test failures. But I didn't figure out a way to detect whether
we should wait for the initial focus event, so just delay logging for focus
event a bit to ignore the initial one.

Comment 16

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/7904b2f23010
Delay logging for focus event on toplevel window in order to ignore the inital focus event; r=hsivonen

Comment 17

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/34538 for changes under testing/web-platform/tests

Comment 18

[Norisz Fay [:noriszfay]]

Backed out for causing wpt failures on focus-event-after-focusing-iframes.html

Backout link

Push with failures

Failure log

Comment 19

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Upstream PR was closed without merging

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/57af2ae1491a
Delay logging for focus event on toplevel window in order to ignore the inital focus event; r=hsivonen

Comment 21

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/57af2ae1491a

Comment 22

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Upstream PR merged by moz-wptsync-bot

Comment 23

[Intermittent Failures Robot]

17 failures in 684 pushes (0.025 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 13
• mozilla-central: 2
• try: 2

Platform and build breakdown:

• windows10-32-2004-qr: 3
  • opt: 3
• windows10-64-2004-qr: 4
  • opt: 3
  • debug: 1
• windows10-64-2004-shippable-qr: 2
  • opt: 2
• windows10-64-2004-devedition-qr: 1
  • opt: 1
• macosx1015-64-shippable-qr: 1
  • opt: 1
• macosx1015-64-qr: 6
  • debug: 4
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1775118&startday=2022-06-22&endday=2022-06-22&tree=all

Comment 24

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

The "Orange Factor" graphs are looking promising, thank you for your quick work Edgar! 👏

Comment 25

[Intermittent Failures Robot]

133 failures in 3075 pushes (0.043 failures/push) were associated with this bug in the last 7 days.

This is the #6 most frequent failure this week.

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

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

Repository breakdown:

• autoland: 109
• mozilla-central: 20
• try: 4

Platform and build breakdown:

• windows10-32-2004-qr: 38
  • opt: 36
  • debug: 2
• macosx1015-64-qr: 29
  • debug: 18
  • opt: 11
• windows10-64-2004-qr: 48
  • opt: 46
  • debug: 2
• linux1804-64-qr: 1
  • debug: 1
• windows10-64-2004-shippable-qr: 7
  • opt: 7
• windows10-32-2004-shippable-qr: 3
  • opt: 3
• macosx1015-64-shippable-qr: 5
  • opt: 5
• windows10-64-2004-devedition-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1775118&startday=2022-06-20&endday=2022-06-26&tree=all

Comment 26

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1767396