1696323 - Permanent [fission][tier2][xorigin] http://mochi.test:8888/tests/toolkit/components/passwordmgr/test/mochitest/test_input_events_for_identical_values.html | called finish() multiple times

Status: RESOLVED FIXED

(Toolkit :: Password Manager, defect, P3)

Description

[Treeherder Bug Filer]

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

---

[task 2021-03-04T04:49:16.461Z] 04:49:16     INFO - TEST-START | http://mochi.test:8888/tests/toolkit/components/passwordmgr/test/mochitest/test_input_events_for_identical_values.html
[task 2021-03-04T04:49:16.638Z] 04:49:16     INFO - GECKO(7378) | [Child 8144, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3365
[task 2021-03-04T04:49:16.666Z] 04:49:16     INFO - GECKO(7378) | [Child 8144, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4377
[task 2021-03-04T04:49:17.587Z] 04:49:17     INFO - GECKO(7378) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpHuBhq9.mozrunner/runtests_leaks_tab_pid8246.log
[task 2021-03-04T04:49:17.588Z] 04:49:17     INFO - GECKO(7378) | [8246, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:251
[task 2021-03-04T04:49:17.647Z] 04:49:17     INFO - GECKO(7378) | [Child 8246, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:619
[task 2021-03-04T04:49:17.850Z] 04:49:17     INFO - GECKO(7378) | MEMORY STAT | vsize 2557MB | residentFast 149MB | heapAllocated 8MB
[task 2021-03-04T04:49:17.866Z] 04:49:17     INFO - TEST-OK | http://mochi.test:8888/tests/toolkit/components/passwordmgr/test/mochitest/test_input_events_for_identical_values.html | took 1405ms
[task 2021-03-04T04:49:18.873Z] 04:49:18     INFO - GECKO(7378) | console.warn: LoginRecipes: "getRecipes: falling back to a synchronous message for:" "http://mochi.test:8888"
[task 2021-03-04T04:49:18.882Z] 04:49:18    ERROR - TEST-UNEXPECTED-FAIL | SimpleTest | this test already called finish!
[task 2021-03-04T04:49:18.903Z] 04:49:18    ERROR - addAssertionCount should only be called by a cross origin test
[task 2021-03-04T04:49:18.904Z] 04:49:18     INFO - GECKO(7378) | [Parent 7378, Main Thread] WARNING: Received `load` event on unbridged BrowserParent!: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:4021
[task 2021-03-04T04:49:18.906Z] 04:49:18     INFO - GECKO(7378) | [Parent 7378, Main Thread] WARNING: Received `load` event on unbridged BrowserParent!: file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:4021
[task 2021-03-04T04:49:18.911Z] 04:49:18     INFO - GECKO(7378) | [Child 8169, Main Thread] WARNING: SendNotifyIMEFocus got rejected.: file /builds/worker/checkouts/gecko/widget/PuppetWidget.cpp:773
[task 2021-03-04T04:49:18.927Z] 04:49:18     INFO - TEST-UNEXP```

Comment 1

[Natalia Csoregi [:nataliaCs]]

The high failure rate appeared once Bug 1682517 has landed. - it is currently permafailing on tier 2 on mozilla-central.

Retriggers/Backfills custom range: https://treeherder.mozilla.org/jobs?repo=autoland&searchStr=linux%2C18.04%2Cx64%2Cdebug%2Cmochitests%2Cwith%2Ccross-origin%2Cand%2Cfission%2Cenabled%2Ctest-linux1804-64%2Fdebug-mochitest-plain-fis-xorig-e10s%2C8&tochange=3ab3618ceed9b970b893b55b6a06ef5aab92db6f&fromchange=34803577fc5d8befb40bcf07e42d73219c5203ca&group_state=expanded

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=332259065&repo=mozilla-central&lineNumber=8341

[task 2021-03-06T10:17:56.473Z] 10:17:56 INFO - TEST-START | http://mochi.test:8888/tests/toolkit/components/passwordmgr/test/mochitest/test_input_events_for_identical_values.html
[task 2021-03-06T10:17:56.654Z] 10:17:56 INFO - GECKO(7352) | [Child 8122, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3365
[task 2021-03-06T10:17:56.674Z] 10:17:56 INFO - GECKO(7352) | [Child 8122, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4377
[task 2021-03-06T10:17:57.620Z] 10:17:57 INFO - GECKO(7352) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpgh_C2N.mozrunner/runtests_leaks_tab_pid8224.log
[task 2021-03-06T10:17:57.621Z] 10:17:57 INFO - GECKO(7352) | [8224, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:251
[task 2021-03-06T10:17:57.696Z] 10:17:57 INFO - GECKO(7352) | [Child 8224, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:619
[task 2021-03-06T10:17:57.887Z] 10:17:57 INFO - GECKO(7352) | MEMORY STAT | vsize 2558MB | residentFast 148MB | heapAllocated 8MB
[task 2021-03-06T10:17:57.902Z] 10:17:57 INFO - TEST-OK | http://mochi.test:8888/tests/toolkit/components/passwordmgr/test/mochitest/test_input_events_for_identical_values.html | took 1436ms
[task 2021-03-06T10:17:58.906Z] 10:17:58 INFO - GECKO(7352) | console.warn: LoginRecipes: "getRecipes: falling back to a synchronous message for:" "http://mochi.test:8888"
[task 2021-03-06T10:17:58.922Z] 10:17:58 ERROR - TEST-UNEXPECTED-FAIL | SimpleTest | this test already called finish!
[task 2021-03-06T10:17:58.924Z] 10:17:58 INFO - TEST-UNEXPECTED-ERROR | http://mochi.test:8888/tests/toolkit/components/passwordmgr/test/mochitest/test_input_events_for_identical_values.html | called finish() multiple times
[task 2021-03-06T10:17:58.924Z] 10:17:58 INFO - TEST-INFO

Tom, could you take a look at this?
Thank you.

Comment 2

[Intermittent Failures Robot]

56 failures in 3683 pushes (0.015 failures/push) were associated with this bug in the last 7 days.

This is the #16 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: 13
• autoland: 43

Platform and build breakdown:

• linux1804-64: 56
  • debug: 56

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1696323&startday=2021-03-01&endday=2021-03-07&tree=all

Comment 3

[Tom Tung [:tt, :ttung]]

If I execute ./mach test toolkit/components/passwordmgr/test/mochitest/test_input_events_for_identical_values.html --headless --enable-fission --enable-xorigin-tests, I couldn't reproduce this issue. However, if I execute ./mach test toolkit/components/passwordmgr/test/mochitest/ --headless --enable-fission --enable-xorigin-tests, I could reproduce the issue.
Such that, I suspect that something is not cleaned properly between tests.

Comment 4

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

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

Comment 5

[Tom Tung [:tt, :ttung]]

I can also reproduce this failure with ./mach test toolkit/components/passwordmgr/test/mochitest/test_input_events_for_identical_values.html --headless --enable-fission --enable-xorigin-tests --verify. So, that probably means that it's something related to the iframe.

Looking into the test and adding some logs, I found this onfocus was called twice and thus caused this issue. So, it looks like that something in nsFocusManager is wrong.

Comment 6

[Jens Stutte [:jstutte]]

Hi Henri, can you take a look here? Tom will not be able to get to this.

Comment 7

[Henri Sivonen (:hsivonen)]

I'll take a look.

Comment 8

[Intermittent Failures Robot]

29 failures in 4622 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

This is the #49 most frequent failure this week.

Repository breakdown:

• try: 12
• mozilla-central: 17

Platform and build breakdown:

• linux1804-64: 29
  • debug: 29

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

Comment 9

[Intermittent Failures Robot]

24 failures in 4257 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 9
• mozilla-central: 15

Platform and build breakdown:

• linux1804-64: 24
  • debug: 24

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1696323&startday=2021-03-15&endday=2021-03-21&tree=all

Comment 10

[Intermittent Failures Robot]

23 failures in 3967 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 21
• try: 2

Platform and build breakdown:

• linux1804-64: 23
  • debug: 23

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1696323&startday=2021-03-22&endday=2021-03-28&tree=all

Comment 11

[Intermittent Failures Robot]

20 failures in 3125 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 2
• mozilla-central: 18

Platform and build breakdown:

• linux1804-64: 20
  • debug: 20

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

Comment 12

[Intermittent Failures Robot]

22 failures in 3854 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 19
• try: 3

Platform and build breakdown:

• linux1804-64: 22
  • debug: 22

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

Comment 13

[Henri Sivonen (:hsivonen)]

(In reply to Tom Tung [:tt, :ttung] from comment #3)

If I execute ./mach test toolkit/components/passwordmgr/test/mochitest/test_input_events_for_identical_values.html --headless --enable-fission --enable-xorigin-tests, I couldn't reproduce this issue. However, if I execute ./mach test toolkit/components/passwordmgr/test/mochitest/ --headless --enable-fission --enable-xorigin-tests, I could reproduce the issue.
Such that, I suspect that something is not cleaned properly between tests.

The minimal test sequence for repro is:

[test_formless_submit_navigation_negative.html]
skip-if = toolkit == 'android' && debug # bug 1397615
[test_input_events_for_identical_values.html]

Frustratingly, I can't get this to repro in rr even with both the rr chaos mode and the Gecko chaos mode.

Comment 14

[Henri Sivonen (:hsivonen)]

The second call to finish happens with this C++ stack:

nsFocusManager::Focus(nsPIDOMWindowOuter*, mozilla::dom::Element*, unsigned int, bool, bool, bool, bool, unsigned long, mozilla::Maybe<nsFocusManager::BlurredElementInfo> const&) (/opt/Projects/gecko/dom/base/nsFocusManager.cpp:2601)
nsFocusManager::WindowRaised(mozIDOMWindowProxy*, unsigned long) (/opt/Projects/gecko/dom/base/nsFocusManager.cpp:776)
nsWebBrowser::FocusActivate(unsigned long) (/opt/Projects/gecko/toolkit/components/browser/nsWebBrowser.cpp:0)
mozilla::dom::BrowserChild::RecvActivate(unsigned long) (/opt/Projects/gecko/dom/ipc/BrowserChild.cpp:1411)

Comment 15

[Henri Sivonen (:hsivonen)]

The first call is what is wanted: From

synthesizeKey(aKey = ""VK_TAB"", aEvent = "[object Object]", aWindow = "undefined") ["http://mochi.test:8888/tests/SimpleTest/EventUtils.js":1307:10]

Etc.

Comment 16

[Henri Sivonen (:hsivonen)]

Possibly relevant:

2:34.26 TEST_END: OK
2:35.60 GECKO(495674) [Parent 495674, Main Thread] WARNING: Received load event on unbridged BrowserParent!: file /opt/Projects/gecko/dom/ipc/BrowserParent.cpp:4016
2:35.60 GECKO(495674) [Parent 495674, Main Thread] WARNING: Received load event on unbridged BrowserParent!: file /opt/Projects/gecko/dom/ipc/BrowserParent.cpp:4016
2:35.66 GECKO(495674) ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
2:35.76 TEST_START: http://mochi.test:8888/tests/toolkit/components/passwordmgr/test/mochitest/test_input_events_for_identical_values.html
2:36.01 GECKO(495674) [Parent 495674, Main Thread] WARNING: WebProgress Ignored: no longer current window global: file /opt/Projects/gecko/dom/ipc/BrowserParent.cpp:2881

Comment 17

[Henri Sivonen (:hsivonen)]

Something refocuses the test iframe so that it blurs and immediately refocuses. With that, it makes sense why this is xorigin only.

Comment 18

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 22
• try: 4

Platform and build breakdown:

• linux1804-64: 26
  • debug: 26

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

Comment 19

[Henri Sivonen (:hsivonen)]

(In reply to Henri Sivonen (:hsivonen) from comment #17)

Something refocuses the test iframe so that it blurs and immediately refocuses. With that, it makes sense why this is xorigin only.

By selective logging (fortunately, the test is stable enough that it's possible to write conditions based on the action id; dumping everything changes the timing too much), it looks like this is a matter of calling WebIDL focus() on the iframe in the process that contains the xorigin iframe element.

Instead of that action blurring the iframe and immediately restoring focus to it, we should probably detect that situation and make it a no-op.

Comment 20

[Henri Sivonen (:hsivonen)]

Minimized test case: Compare outer.html with outer-cross-origin.html by clicking the input field in the iframe to focus it.
https://hsivonen.com/test/moz/iframe-focus/

Comment 21

[Henri Sivonen (:hsivonen)]

Attachment: Bug 1696323 - Return early when attempting to focus a remote iframe whose BrowsingContext is already the focused one.

Comment 22

[Henri Sivonen (:hsivonen)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=29467d2703eea2f086660ddbd3c6f8d11e16a98f

Comment 23

[Henri Sivonen (:hsivonen)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=6b75ce3320800d5b42fc9fadb0bb488a6ff08bee

Comment 24

[Henri Sivonen (:hsivonen)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=ece08c7b06129703f9447c4e650fa4a8d3cd2031

Comment 25

[Henri Sivonen (:hsivonen)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=fd6884d3e299c531dc075f08ae7603e0c8f3649b

Comment 26

[Henri Sivonen (:hsivonen)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=4b6b171bad86e6712862566c23ca6ac8ace7f351

Comment 27

[Henri Sivonen (:hsivonen)]

Sigh. Now the very first test in this test directory permafails: test_autocomplete_autofill_related_realms_no_dupes.html

Comment 28

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 2
• mozilla-central: 19

Platform and build breakdown:

• linux1804-64: 21
  • debug: 21

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

Comment 29

[Henri Sivonen (:hsivonen)]

Locally, I get:

toolkit/components/passwordmgr/test/mochitest/test_autocomplete_autofill_related_realms_no_dupes.html
FAIL Checking form1 username is: exactUser1 - got "", expected "exactUser1"
SimpleTest.is@https://example.org/tests/SimpleTest/SimpleTest.js:500:14
checkLoginForm@https://example.org/tests/toolkit/components/passwordmgr/test/mochitest/pwmgr_common.js:220:5
test_no_duplicates_autocomplete_autofill@https://example.org/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_autofill_related_realms_no_dupes.html?currentTestURL=toolkit%2Fcomponents%2Fpasswordmgr%2Ftest%2Fmochitest%2Ftest_autocomplete_autofill_related_realms_no_dupes.html&closeWhenDone=1&showTestReport=false&expected=pass:79:17
FAIL Checking form1 password is: exactPass1 - got "", expected "exactPass1"
SimpleTest.is@https://example.org/tests/SimpleTest/SimpleTest.js:500:14
checkLoginForm@https://example.org/tests/toolkit/components/passwordmgr/test/mochitest/pwmgr_common.js:225:5
test_no_duplicates_autocomplete_autofill@https://example.org/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_autofill_related_realms_no_dupes.html?currentTestURL=toolkit%2Fcomponents%2Fpasswordmgr%2Ftest%2Fmochitest%2Ftest_autocomplete_autofill_related_realms_no_dupes.html&closeWhenDone=1&showTestReport=false&expected=pass:79:17
FAIL Test timed out. -

toolkit/components/passwordmgr/test/mochitest/test_autocomplete_basic_form_related_realms.html
FAIL Test timed out. -

Comment 30

[Henri Sivonen (:hsivonen)]

(In reply to Henri Sivonen (:hsivonen) from comment #27)

Now the very first test in this test directory permafails: test_autocomplete_autofill_related_realms_no_dupes.html

Pernosco says that when this fails, the early return that my patch added never gets executed. That's a bit curious as far as causality goes.

Comment 31

[Henri Sivonen (:hsivonen)]

I see the test_autocomplete_autofill_related_realms_no_dupes.html failure locally even without my patch.

I don't see the log from comment 1 running that test at all. I also don't see an annotation to disable it. I'm not sure what I'm missing.

Comment 32

[Henri Sivonen (:hsivonen)]

Try run without patch to get the same config as with the patch:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=b474354916577bf06fd742264a1760c22b682859

With patch:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=c14b78ec967c627621fc5097d24793e54d381d45

Comment 33

[Henri Sivonen (:hsivonen)]

(In reply to Henri Sivonen (:hsivonen) from comment #32)

Try run without patch to get the same config as with the patch:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=b474354916577bf06fd742264a1760c22b682859

With patch:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=c14b78ec967c627621fc5097d24793e54d381d45

Looks like the other failure is there regardless of this patch.

Comment 34

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/12893215ed66
Return early when attempting to focus a remote iframe whose BrowsingContext is already the focused one. r=edgar

Comment 35

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

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

Comment 36

[Iulian Moraru]

Backed out for OS X build bustages on BrowserBridgeChild.cpp.

Push with failures

Failure log

Backout link

Comment 37

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

Upstream PR was closed without merging

Comment 38

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/5c4c4c9aa022
Return early when attempting to focus a remote iframe whose BrowsingContext is already the focused one. r=edgar

Comment 39

[Narcis Beleuzu [:NarcisB]]

https://hg.mozilla.org/mozilla-central/rev/5c4c4c9aa022

Comment 40

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

Since the status are different for nightly and release, what's the status for beta?
For more information, please visit auto_nag documentation.

Comment 41

[Henri Sivonen (:hsivonen)]

(In reply to Release mgmt bot [:sylvestre / :calixte / :marco for bugbug] from comment #40)

Since the status are different for nightly and release, what's the status for beta?
For more information, please visit auto_nag documentation.

I expect us not to uplift tier 2 test fixes to beta.

Comment 42

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

Upstream PR merged by moz-wptsync-bot

Comment 43

[Intermittent Failures Robot]

14 failures in 3706 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 12
• try: 2

Platform and build breakdown:

• linux1804-64: 14
  • debug: 14

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