Closed Bug 1690358 Opened 4 years ago Closed 2 years ago

Intermittent toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Check all rows are correct - got 2, expected 1

Categories

(Toolkit :: Password Manager, defect, P5)

defect

Tracking

()

RESOLVED DUPLICATE of bug 1777035
Tracking Status
firefox-esr78 --- unaffected
firefox85 --- unaffected
firefox86 --- unaffected
firefox87 --- wontfix
firefox88 --- fix-optional

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Blocks 1 open bug, Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [retriggered][stockwell unknown])

Attachments

(2 files)

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


[task 2021-02-02T17:36:34.148Z] 17:36:34     INFO - Opening the AC menu
[task 2021-02-02T17:36:34.148Z] 17:36:34     INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | checkAutoCompleteResults: hostname must be a string 
[task 2021-02-02T17:36:34.149Z] 17:36:34     INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | There should be items in the autocomplete popup: ["No username (Feb 2, 2021)","Use a Securely Generated Password","View Saved Logins"] 
[task 2021-02-02T17:36:34.150Z] 17:36:34     INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | the footer text is shown correctly 
[task 2021-02-02T17:36:34.150Z] 17:36:34     INFO - Buffered messages finished
[task 2021-02-02T17:36:34.151Z] 17:36:34     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Checking array values: Check all rows are correct - got 2, expected 1
[task 2021-02-02T17:36:34.151Z] 17:36:34     INFO - SimpleTest.is@https://example.com/tests/SimpleTest/SimpleTest.js:500:14
[task 2021-02-02T17:36:34.151Z] 17:36:34     INFO - checkArrayValues@https://example.com/tests/toolkit/components/satchel/test/satchel_common.js:72:5
[task 2021-02-02T17:36:34.151Z] 17:36:34     INFO - checkAutoCompleteResults@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/pwmgr_common.js:126:19
[task 2021-02-02T17:36:34.151Z] 17:36:34     INFO - fillWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:115:27
[task 2021-02-02T17:36:34.151Z] 17:36:34     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-02T17:36:34.152Z] 17:36:34     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Check all rows are correct Checking array entry #0 - got "No username (Feb 2, 2021)", expected "Use a Securely Generated Password"
[task 2021-02-02T17:36:34.152Z] 17:36:34     INFO - SimpleTest.is@https://example.com/tests/SimpleTest/SimpleTest.js:500:14
[task 2021-02-02T17:36:34.152Z] 17:36:34     INFO - checkArrayValues@https://example.com/tests/toolkit/components/satchel/test/satchel_common.js:78:7
[task 2021-02-02T17:36:34.152Z] 17:36:34     INFO - checkAutoCompleteResults@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/pwmgr_common.js:126:19
[task 2021-02-02T17:36:34.153Z] 17:36:34     INFO - fillWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:115:27
[task 2021-02-02T17:36:34.153Z] 17:36:34     INFO - waiting for the password field to be filled with the generated password
[task 2021-02-02T17:36:37.043Z] 17:36:37     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-02T17:36:37.044Z] 17:36:37     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Check generated pw filled 
[task 2021-02-02T17:36:37.044Z] 17:36:37     INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:417:16
[task 2021-02-02T17:36:37.045Z] 17:36:37     INFO - SimpleTest.waitForCondition/interval<@https://example.com/tests/SimpleTest/SimpleTest.js:1403:9
[task 2021-02-02T17:36:37.046Z] 17:36:37     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-02T17:36:37.051Z] 17:36:37     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Check generated password length - got +0, expected 15
[task 2021-02-02T17:36:37.051Z] 17:36:37     INFO - SimpleTest.is@https://example.com/tests/SimpleTest/SimpleTest.js:500:14
[task 2021-02-02T17:36:37.053Z] 17:36:37     INFO - testConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:156:5
[task 2021-02-02T17:36:37.054Z] 17:36:37     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-02T17:36:37.055Z] 17:36:37     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Check generated password format 
[task 2021-02-02T17:36:37.056Z] 17:36:37     INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:417:16
[task 2021-02-02T17:36:37.056Z] 17:36:37     INFO - testConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:157:5
[task 2021-02-02T17:36:37.140Z] 17:36:37     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-02T17:36:37.141Z] 17:36:37     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Check autoMaskingEnabled: After fill - true == false 
[task 2021-02-02T17:36:37.141Z] 17:36:37     INFO - {u'columnNumber': 12, u'formattedStack': u'checkPasswordMasked@resource://testing-common/LoginTestUtils.jsm:542:12\ndoApply@resource://specialpowers/WrapPrivileged.jsm:118:18\napply/<@resource://specialpowers/WrapPrivileged.jsm:260:30\nwrapExceptions@resource://specialpowers/WrapPrivileged.jsm:206:12\napply@resource://specialpowers/WrapPrivileged.jsm:244:12\ntestConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:158:21\n', u'caller': {u'columnNumber': 18, u'formattedStack': u'doApply@resource://specialpowers/WrapPrivileged.jsm:118:18\napply/<@resource://specialpowers/WrapPrivileged.jsm:260:30\nwrapExceptions@resource://specialpowers/WrapPrivileged.jsm:206:12\napply@resource://specialpowers/WrapPrivileged.jsm:244:12\ntestConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:158:21\n', u'caller': {u'columnNumber': 30, u'formattedStack': u'apply/<@resource://specialpowers/WrapPrivileged.jsm:260:30\nwrapExceptions@resource://specialpowers/WrapPrivileged.jsm:206:12\napply@resource://specialpowers/WrapPrivileged.jsm:244:12\ntestConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:158:21\n', u'caller': {u'columnNumber': 12, u'formattedStack': u'wrapExceptions@resource://specialpowers/WrapPrivileged.jsm:206:12\napply@resource://specialpowers/WrapPrivileged.jsm:244:12\ntestConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:158:21\n', u'caller': {u'columnNumber': 12, u'formattedStack': u'apply@resource://specialpowers/WrapPrivileged.jsm:244:12\ntestConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:158:21\n', u'caller': {u'columnNumber': 21, u'formattedStack': u'testConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:158:21\n', u'caller': None, u'name': u'testConfirmPasswordFieldFilledWithGeneratedPassword', u'sourceLine': u'', u'sourceId': 191, u'asyncCause': None, u'nativeSavedFrame': {}, u'filename': u'https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html', u'lineNumber': 158, u'asyncCaller': None}, u'name': u'apply', u'sourceLine': u'', u'sourceId': 26, u'asyncCause': None, u'nativeSavedFrame': {}, u'filename': u'resource://specialpowers/WrapPrivileged.jsm', u'lineNumber': 244, u'asyncCaller': None}, u'name': u'wrapExceptions', u'sourceLine': u'', u'sourceId': 26, u'asyncCause': None, u'nativeSavedFrame': {}, u'filename': u'resource://specialpowers/WrapPrivileged.jsm', u'lineNumber': 206, u'asyncCaller': None}, u'name': u'apply/<', u'sourceLine': u'', u'sourceId': 26, u'asyncCause': None, u'nativeSavedFrame': {}, u'filename': u'resource://specialpowers/WrapPrivileged.jsm', u'lineNumber': 260, u'asyncCaller': None}, u'name': u'doApply', u'sourceLine': u'', u'sourceId': 26, u'asyncCause': None, u'nativeSavedFrame': {}, u'filename': u'resource://specialpowers/WrapPrivileged.jsm', u'lineNumber': 118, u'asyncCaller': None}, u'name': u'checkPasswordMasked', u'sourceLine': u'', u'sourceId': 47, u'asyncCause': None, u'nativeSavedFrame': {}, u'filename': u'resource://testing-common/LoginTestUtils.jsm', u'lineNumber': 542, u'asyncCaller': None}
[task 2021-02-02T17:36:37.141Z] 17:36:37     INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | unmaskedStart is 0: After fill - 0 == 0 
[task 2021-02-02T17:36:37.144Z] 17:36:37     INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Unmasked to the end: After fill - 0 == 0 
[task 2021-02-02T17:36:37.145Z] 17:36:37     INFO - Check the expected password fields are filled
[task 2021-02-02T17:36:37.245Z] 17:36:37     INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Field (uname) field has the expected value 
[task 2021-02-02T17:36:42.373Z] 17:36:42     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-02T17:36:42.373Z] 17:36:42     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Highlight was successfully applied to the (pword) field - timed out after 50 tries. - Should not throw any errors
[task 2021-02-02T17:36:42.374Z] 17:36:42     INFO - nextTick/<@https://example.com/tests/SimpleTest/SimpleTest.js:2258:26
[task 2021-02-02T17:36:42.411Z] 17:36:42     INFO - GECKO(4009) | MEMORY STAT | vsize 2574MB | residentFast 167MB | heapAllocated 12MB
[task 2021-02-02T17:36:42.411Z] 17:36:42     INFO - GECKO(4009) | Removing 1 popup notifications.
[task 2021-02-02T17:36:42.492Z] 17:36:42     INFO - TEST-OK | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | took 17521ms
[task 2021-02-02T17:36:42.500Z] 17:36:42     INFO - GECKO(4009) | console.warn: LoginRecipes: "getRecipes: falling back to a synchronous message for:" "https://example.com"
[task 2021-02-02T17:36:42.557Z] 17:36:42     INFO - TEST-START | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_open.html
[task 2021-02-02T17:36:45.671Z] 17:36:45     INFO - GECKO(4009) | MEMORY STAT | vsize 2572MB | residentFast 168MB | heapAllocated 14MB
[task 2021-02-02T17:36:45.692Z] 17:36:45     INFO - TEST-OK | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_open.html | took 3134ms
[task 2021-02-02T17:36:45.699Z] 17:36:45     INFO - GECKO(4009) | console.warn: LoginRecipes: "getRecipes: falling back to a synchronous message for:" "https://example.com"
[task 2021-02-02T17:36:45.836Z] 17:36:45     INFO - TEST-START | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_sandboxed.html```

Bug 1633541 also got hit once after a long time. All failures are on Linux debug with WebRender.

Masayuki, Sam, could these failures be triggered by the changes which landed with bug 1685491 (a few more bugs landed with it)? The retriggers indicate this.

Flags: needinfo?(masayuki)

Yeah, could be. The test API improvement causes a little bit running tests slower and synthesizing arrow keys may flush pending reflow only on Linux and macOS. That may change race conditions if there are.

I'll take a look today.

Assignee: nobody → masayuki
Status: NEW → ASSIGNED
Flags: needinfo?(masayuki)
Summary: Intermittent toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Check all rows are correct Checking array entry #0 - got "No username (Feb 2, 2021)", expected "Use a Securely Generated Password" → Intermittent toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Check all rows are correct - got 2, expected 1
Has Regression Range: --- → yes
Whiteboard: [retriggered][stockwell needswork:owner]

There are 24 total failures in the last 7 days on linux1804-64-qr debug

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

[task 2021-02-13T20:42:08.373Z] 20:42:08 INFO - TEST-START | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html
[task 2021-02-13T20:42:09.145Z] 20:42:09 INFO - GECKO(3656) | [Child 3757, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0xC1F30001 (NS_ERROR_NOT_INITIALIZED): file /builds/worker/checkouts/gecko/layout/forms/nsTextControlFrame.cpp:310
[task 2021-02-13T20:42:09.146Z] 20:42:09 INFO - GECKO(3656) | [Child 3757, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0xC1F30001 (NS_ERROR_NOT_INITIALIZED): file /builds/worker/checkouts/gecko/layout/forms/nsTextControlFrame.cpp:310
[task 2021-02-13T20:42:10.119Z] 20:42:10 INFO - GECKO(3656) | [Child 3757, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1591
[task 2021-02-13T20:42:10.148Z] 20:42:10 INFO - GECKO(3656) | [Child 3757, Main Thread] WARNING: '!mBoundFrame', file /builds/worker/checkouts/gecko/dom/html/TextControlState.cpp:2378
[task 2021-02-13T20:42:10.391Z] 20:42:10 INFO - GECKO(3656) | [Child 3757, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0xC1F30001 (NS_ERROR_NOT_INITIALIZED): file /builds/worker/checkouts/gecko/layout/forms/nsTextControlFrame.cpp:310
[task 2021-02-13T20:42:10.392Z] 20:42:10 INFO - GECKO(3656) | [Child 3757, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0xC1F30001 (NS_ERROR_NOT_INITIALIZED): file /builds/worker/checkouts/gecko/layout/forms/nsTextControlFrame.cpp:310
[task 2021-02-13T20:42:11.080Z] 20:42:11 INFO - GECKO(3656) | [Child 3757, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1591
[task 2021-02-13T20:42:11.080Z] 20:42:11 INFO - GECKO(3656) | [Child 3757, Main Thread] WARNING: '!mBoundFrame', file /builds/worker/checkouts/gecko/dom/html/TextControlState.cpp:2378
[task 2021-02-13T20:42:11.197Z] 20:42:11 INFO - GECKO(3656) | [Child 3757, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1591
[task 2021-02-13T20:42:12.010Z] 20:42:12 INFO - GECKO(3656) | [Child 3757, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1591
[task 2021-02-13T20:42:13.086Z] 20:42:13 INFO - GECKO(3656) | [Child 3757, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1591
[task 2021-02-13T20:42:13.948Z] 20:42:13 INFO - GECKO(3656) | [Child 3757, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1591
[task 2021-02-13T20:42:14.798Z] 20:42:14 INFO - GECKO(3656) | [Child 3757, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1591
[task 2021-02-13T20:42:15.038Z] 20:42:15 INFO - GECKO(3656) | [Child 3757, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0xC1F30001 (NS_ERROR_NOT_INITIALIZED): file /builds/worker/checkouts/gecko/layout/forms/nsTextControlFrame.cpp:310
[task 2021-02-13T20:42:15.038Z] 20:42:15 INFO - GECKO(3656) | [Child 3757, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0xC1F30001 (NS_ERROR_NOT_INITIALIZED): file /builds/worker/checkouts/gecko/layout/forms/nsTextControlFrame.cpp:310
[task 2021-02-13T20:42:15.981Z] 20:42:15 INFO - GECKO(3656) | [Child 3757, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp:1591
[task 2021-02-13T20:42:16.239Z] 20:42:16 INFO - TEST-INFO | started process screentopng
[task 2021-02-13T20:42:16.503Z] 20:42:16 INFO - TEST-INFO | screentopng: exit 0
[task 2021-02-13T20:42:16.504Z] 20:42:16 INFO - <snipped 139 output lines - if you need more context, please use SimpleTest.requestCompleteLog() in your test>
[task 2021-02-13T20:42:16.504Z] 20:42:16 INFO - Buffered messages logged at 20:42:13
[task 2021-02-13T20:42:16.504Z] 20:42:16 INFO - got loginsAndGeneratedPasswordsReset message
[task 2021-02-13T20:42:16.504Z] 20:42:16 INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Locating form 1
[task 2021-02-13T20:42:16.504Z] 20:42:16 INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Test value of field uname in form 1
[task 2021-02-13T20:42:16.504Z] 20:42:16 INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Test value of field pword in form 1

[task 2021-02-13T20:42:16.561Z] 20:42:16 INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Test value of field uname in form 2
[task 2021-02-13T20:42:16.562Z] 20:42:16 INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Test value of field pword in form 2
[task 2021-02-13T20:42:16.562Z] 20:42:16 INFO - Opening the AC menu
[task 2021-02-13T20:42:16.562Z] 20:42:16 INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | checkAutoCompleteResults: hostname must be a string
[task 2021-02-13T20:42:16.563Z] 20:42:16 INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | There should be items in the autocomplete popup: ["No username (Feb 13, 2021)","Use a Securely Generated Password","View Saved Logins"]
[task 2021-02-13T20:42:16.563Z] 20:42:16 INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | the footer text is shown correctly
[task 2021-02-13T20:42:16.563Z] 20:42:16 INFO - Buffered messages finished
[task 2021-02-13T20:42:16.563Z] 20:42:16 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Checking array values: Check all rows are correct - got 2, expected 1
[task 2021-02-13T20:42:16.564Z] 20:42:16 INFO - SimpleTest.is@https://example.com/tests/SimpleTest/SimpleTest.js:500:14
[task 2021-02-13T20:42:16.564Z] 20:42:16 INFO - checkArrayValues@https://example.com/tests/toolkit/components/satchel/test/satchel_common.js:72:5
[task 2021-02-13T20:42:16.564Z] 20:42:16 INFO - checkAutoCompleteResults@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/pwmgr_common.js:126:19
[task 2021-02-13T20:42:16.564Z] 20:42:16 INFO - fillWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:115:27
[task 2021-02-13T20:42:16.564Z] 20:42:16 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-13T20:42:16.565Z] 20:42:16 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Check all rows are correct Checking array entry #0 - got "No username (Feb 13, 2021)", expected "Use a Securely Generated Password"
[task 2021-02-13T20:42:16.565Z] 20:42:16 INFO - SimpleTest.is@https://example.com/tests/SimpleTest/SimpleTest.js:500:14
[task 2021-02-13T20:42:16.565Z] 20:42:16 INFO - checkArrayValues@https://example.com/tests/toolkit/components/satchel/test/satchel_common.js:78:7
[task 2021-02-13T20:42:16.565Z] 20:42:16 INFO - checkAutoCompleteResults@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/pwmgr_common.js:126:19
[task 2021-02-13T20:42:16.565Z] 20:42:16 INFO - fillWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:115:27
[task 2021-02-13T20:42:16.566Z] 20:42:16 INFO - waiting for the password field to be filled with the generated password
[task 2021-02-13T20:42:19.473Z] 20:42:19 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-13T20:42:19.473Z] 20:42:19 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Check generated pw filled
[task 2021-02-13T20:42:19.473Z] 20:42:19 INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:417:16
[task 2021-02-13T20:42:19.474Z] 20:42:19 INFO - SimpleTest.waitForCondition/interval<@https://example.com/tests/SimpleTest/SimpleTest.js:1403:9
[task 2021-02-13T20:42:19.474Z] 20:42:19 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-13T20:42:19.475Z] 20:42:19 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Check generated password length - got +0, expected 15
[task 2021-02-13T20:42:19.476Z] 20:42:19 INFO - SimpleTest.is@https://example.com/tests/SimpleTest/SimpleTest.js:500:14
[task 2021-02-13T20:42:19.476Z] 20:42:19 INFO - testConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:156:5
[task 2021-02-13T20:42:19.477Z] 20:42:19 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-13T20:42:19.478Z] 20:42:19 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Check generated password format
[task 2021-02-13T20:42:19.478Z] 20:42:19 INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:417:16
[task 2021-02-13T20:42:19.479Z] 20:42:19 INFO - testConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:157:5
[task 2021-02-13T20:42:19.565Z] 20:42:19 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-13T20:42:19.569Z] 20:42:19 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Check autoMaskingEnabled: After fill - true == false
[task 2021-02-13T20:42:19.569Z] 20:42:19 INFO - {u'columnNumber': 12, u'formattedStack': u'checkPasswordMasked@resource://testing-common/LoginTestUtils.jsm:544:12\ndoApply@resource://specialpowers/WrapPrivileged.jsm:118:18\napply/<@resource://specialpowers/WrapPrivileged.jsm:260:30\nwrapExceptions@resource://specialpowers/WrapPrivileged.jsm:206:12\napply@resource://specialpowers/WrapPrivileged.jsm:244:12\ntestConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:158:21\n', u'caller': {u'columnNumber': 18, u'formattedStack': u'doApply@resource://specialpowers/WrapPrivileged.jsm:118:18\napply/<@resource://specialpowers/WrapPrivileged.jsm:260:30\nwrapExceptions@resource://specialpowers/WrapPrivileged.jsm:206:12\napply@resource://specialpowers/WrapPrivileged.jsm:244:12\ntestConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:158:21\n', u'caller': {u'columnNumber': 30, u'formattedStack': u'apply/<@resource://specialpowers/WrapPrivileged.jsm:260:30\nwrapExceptions@resource://specialpowers/WrapPrivileged.jsm:206:12\napply@resource://specialpowers/WrapPrivileged.jsm:244:12\ntestConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:158:21\n', u'caller': {u'columnNumber': 12, u'formattedStack': u'wrapExceptions@resource://specialpowers/WrapPrivileged.jsm:206:12\napply@resource://specialpowers/WrapPrivileged.jsm:244:12\ntestConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:158:21\n', u'caller': {u'columnNumber': 12, u'formattedStack': u'apply@resource://specialpowers/WrapPrivileged.jsm:244:12\ntestConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:158:21\n', u'caller': {u'columnNumber': 21, u'formattedStack': u'testConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:158:21\n', u'caller': None, u'name': u'testConfirmPasswordFieldFilledWithGeneratedPassword', u'sourceLine': u'', u'sourceId': 190, u'asyncCause': None, u'nativeSavedFrame': {}, u'filename': u'https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html', u'lineNumber': 158, u'asyncCaller': None}, u'name': u'apply', u'sourceLine': u'', u'sourceId': 26, u'asyncCause': None, u'nativeSavedFrame': {}, u'filename': u'resource://specialpowers/WrapPrivileged.jsm', u'lineNumber': 244, u'asyncCaller': None}, u'name': u'wrapExceptions', u'sourceLine': u'', u'sourceId': 26, u'asyncCause': None, u'nativeSavedFrame': {}, u'filename': u'resource://specialpowers/WrapPrivileged.jsm', u'lineNumber': 206, u'asyncCaller': None}, u'name': u'apply/<', u'sourceLine': u'', u'sourceId': 26, u'asyncCause': None, u'nativeSavedFrame': {}, u'filename': u'resource://specialpowers/WrapPrivileged.jsm', u'lineNumber': 260, u'asyncCaller': None}, u'name': u'doApply', u'sourceLine': u'', u'sourceId': 26, u'asyncCause': None, u'nativeSavedFrame': {}, u'filename': u'resource://specialpowers/WrapPrivileged.jsm', u'lineNumber': 118, u'asyncCaller': None}, u'name': u'checkPasswordMasked', u'sourceLine': u'', u'sourceId': 46, u'asyncCause': None, u'nativeSavedFrame': {}, u'filename': u'resource://testing-common/LoginTestUtils.jsm', u'lineNumber': 544, u'asyncCaller': None}
[task 2021-02-13T20:42:19.570Z] 20:42:19 INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | unmaskedStart is 0: After fill - 0 == 0
[task 2021-02-13T20:42:19.570Z] 20:42:19 INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Unmasked to the end: After fill - 0 == 0
[task 2021-02-13T20:42:19.571Z] 20:42:19 INFO - Check the expected password fields are filled
[task 2021-02-13T20:42:19.666Z] 20:42:19 INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Field (uname) field has the expected value
[task 2021-02-13T20:42:24.788Z] 20:42:24 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-02-13T20:42:24.790Z] 20:42:24 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | Highlight was successfully applied to the (pword) field - timed out after 50 tries. - Should not throw any errors
[task 2021-02-13T20:42:24.791Z] 20:42:24 INFO - nextTick/<@https://example.com/tests/SimpleTest/SimpleTest.js:2258:26
[task 2021-02-13T20:42:24.809Z] 20:42:24 INFO - GECKO(3656) | MEMORY STAT | vsize 2577MB | residentFast 167MB | heapAllocated 13MB
[task 2021-02-13T20:42:24.812Z] 20:42:24 INFO - GECKO(3656) | Removing 1 popup notifications.
[task 2021-02-13T20:42:24.868Z] 20:42:24 INFO - TEST-OK | toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html | took 16488ms

Masayuki, are there any updates here?

Flags: needinfo?(masayuki)

Unfortunately, I still don't have concrete idea about what's going on. I tried to reproduce this with flushing pending layout intentionally at the changeset before landing bug 1685491. However, I've not succeeded to reproduce this intermittent failure yet.

When the test starts, looks like that the password manager's DB is cleared here.
https://searchfox.org/mozilla-central/rev/1b7ed77360ed02de111cf2098b2b48648c382fa1/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html#400

Then, the test disables an input element, this might cause a pending reflow.
https://searchfox.org/mozilla-central/rev/1b7ed77360ed02de111cf2098b2b48648c382fa1/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html#405

Finally, opens the dropdown list with ArrowDown key press and try to count its entry:
https://searchfox.org/mozilla-central/rev/1b7ed77360ed02de111cf2098b2b48648c382fa1/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html#113

However, at this time, there is an entry which should've been deleted by the first one, and this is the cause of this orange. After bug 1685491, the ArrowDown key press may cause flushing pending layout only on Linux and macOS (like actual operation), but I have no idea why that causes this behavior change. I was thinking that the flushing pending layout causes closing dropdown and that caused the odd result...

sfoster: You wrote this test. Do you have any ideas?

Flags: needinfo?(masayuki) → needinfo?(sfoster)

(In reply to Masayuki Nakano [:masayuki] (he/him)(JST, +0900)(Still not recoverd perfectly) from comment #7)

However, at this time, there is an entry which should've been deleted by the first one, and this is the cause of this orange. After bug 1685491, the ArrowDown key press may cause flushing pending layout only on Linux and macOS (like actual operation), but I have no idea why that causes this behavior change. I was thinking that the flushing pending layout causes closing dropdown and that caused the odd result...

sfoster: You wrote this test. Do you have any ideas?

So, it doesn't surprise me that autocomplete tests are racey, but I'm a little surprised that bug 1685491 has caused such a jump in frequency. But this theory sounds plausible. I wonder if the test should wait after the beforeFn - as it seems impossible for the kind of changes made there to complete in the same frame as the user triggering the autocomplete menu. Something like:

diff --git a/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html b/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html
--- a/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html
+++ b/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html
@@ -142,6 +142,7 @@ async function testConfirmPasswordFieldF
  
   if (beforeFn) {
     await beforeFn(document.getElementById(`form${formNumber}`));
+    await TestUtils.waitForTick();
   }
   let pword = $_(formNumber, passwordInputName || "pword");
   let pword2 = $_(formNumber, confirmInputName || "pword-next");
Flags: needinfo?(sfoster)

Masayuki did you get a chance to look at comment 9?

Flags: needinfo?(masayuki)

Sorry for the delay to reply.

Indeed, the patch of sfoster prevents the failure as far as I run the test locally with --verify. But not yet becomes stable. I'll check deeper when I have spare time for this.

Flags: needinfo?(masayuki)
Unexpected Results
------------------
toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html
  FAIL There should be items in the autocomplete popup: [] - didn't expect +0, but got it
SimpleTest.isnot@https://example.com/tests/SimpleTest/SimpleTest.js:519:14
checkAutoCompleteResults@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/pwmgr_common.js:104:8
fillWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:115:27
  FAIL the footer text is shown correctly - got undefined, expected "View Saved Logins"
SimpleTest.is@https://example.com/tests/SimpleTest/SimpleTest.js:500:14
checkAutoCompleteResults@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/pwmgr_common.js:113:5
fillWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:115:27
  FAIL Checking array values: Check all rows are correct - got +0, expected 1
SimpleTest.is@https://example.com/tests/SimpleTest/SimpleTest.js:500:14
checkArrayValues@https://example.com/tests/toolkit/components/satchel/test/satchel_common.js:72:5
checkAutoCompleteResults@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/pwmgr_common.js:126:19
fillWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:115:27
  FAIL Check all rows are correct Checking array entry #0 - got undefined, expected "Use a Securely Generated Password"
SimpleTest.is@https://example.com/tests/SimpleTest/SimpleTest.js:500:14
checkArrayValues@https://example.com/tests/toolkit/components/satchel/test/satchel_common.js:78:7
checkAutoCompleteResults@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/pwmgr_common.js:126:19
fillWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:115:27
  FAIL Check generated pw filled
SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:417:16
SimpleTest.waitForCondition/interval<@https://example.com/tests/SimpleTest/SimpleTest.js:1403:9
  FAIL Check generated password length - got +0, expected 15
SimpleTest.is@https://example.com/tests/SimpleTest/SimpleTest.js:500:14
testConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:157:5
  FAIL Check generated password format
SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:417:16
testConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:158:5
  FAIL Check autoMaskingEnabled: After fill - true == false
{'filename': 'resource://testing-common/LoginTestUtils.jsm', 'name': 'checkPasswordMasked', 'sourceId': 52, 'lineNumber': 544, 'columnNumber': 12, 'sourceLine': '', 'asyncCause': None, 'asyncCaller': None, 'caller': {'filename': 'resource://specialpowers/WrapPrivileged.jsm', 'name': 'doApply', 'sourceId': 32, 'lineNumber': 118, 'columnNumber': 18, 'sourceLine': '', 'asyncCause': None, 'asyncCaller': None, 'caller': {'filename': 'resource://specialpowers/WrapPrivileged.jsm', 'name': 'apply/<', 'sourceId': 32, 'lineNumber': 260, 'columnNumber': 30, 'sourceLine': '', 'asyncCause': None, 'asyncCaller': None, 'caller': {'filename': 'resource://specialpowers/WrapPrivileged.jsm', 'name': 'wrapExceptions', 'sourceId': 32, 'lineNumber': 206, 'columnNumber': 12, 'sourceLine': '', 'asyncCause': None, 'asyncCaller': None, 'caller': {'filename': 'resource://specialpowers/WrapPrivileged.jsm', 'name': 'apply', 'sourceId': 32, 'lineNumber': 244, 'columnNumber': 12, 'sourceLine': '', 'asyncCause': None, 'asyncCaller': None, 'caller': {'filename': 'https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html', 'name': 'testConfirmPasswordFieldFilledWithGeneratedPassword', 'sourceId': 75, 'lineNumber': 159, 'columnNumber': 21, 'sourceLine': '', 'asyncCause': None, 'asyncCaller': None, 'caller': None, 'formattedStack': 'testConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:159:21\n', 'nativeSavedFrame': {}}, 'formattedStack': 'apply@resource://specialpowers/WrapPrivileged.jsm:244:12\ntestConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:159:21\n', 'nativeSavedFrame': {}}, 'formattedStack': 'wrapExceptions@resource://specialpowers/WrapPrivileged.jsm:206:12\napply@resource://specialpowers/WrapPrivileged.jsm:244:12\ntestConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:159:21\n', 'nativeSavedFrame': {}}, 'formattedStack': 'apply/<@resource://specialpowers/WrapPrivileged.jsm:260:30\nwrapExceptions@resource://specialpowers/WrapPrivileged.jsm:206:12\napply@resource://specialpowers/WrapPrivileged.jsm:244:12\ntestConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:159:21\n', 'nativeSavedFrame': {}}, 'formattedStack': 'doApply@resource://specialpowers/WrapPrivileged.jsm:118:18\napply/<@resource://specialpowers/WrapPrivileged.jsm:260:30\nwrapExceptions@resource://specialpowers/WrapPrivileged.jsm:206:12\napply@resource://specialpowers/WrapPrivileged.jsm:244:12\ntestConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:159:21\n', 'nativeSavedFrame': {}}, 'formattedStack': 'checkPasswordMasked@resource://testing-common/LoginTestUtils.jsm:544:12\ndoApply@resource://specialpowers/WrapPrivileged.jsm:118:18\napply/<@resource://specialpowers/WrapPrivileged.jsm:260:30\nwrapExceptions@resource://specialpowers/WrapPrivileged.jsm:206:12\napply@resource://specialpowers/WrapPrivileged.jsm:244:12\ntestConfirmPasswordFieldFilledWithGeneratedPassword@https://example.com/tests/toolkit/components/passwordmgr/test/mochitest/test_autocomplete_password_generation_confirm.html:159:21\n', 'nativeSavedFrame': {}}
  FAIL Highlight was successfully applied to the (pword) field - timed out after 50 tries. - Should not throw any errors
nextTick/<@https://example.com/tests/SimpleTest/SimpleTest.js:2258:26

The result on my environment.

MozAutocompleteRichlistboxPopup sets its mPopupOpen to false when it
receives popuphiding instead of popuphidden.
https://searchfox.org/mozilla-central/rev/63fcc3f1a2cc73488d8986f4cf91fce2cd4b7564/toolkit/content/widgets/autocomplete-popup.js#575,582

Therefore, getPopupState in satchel's parent_utils.js may run before
popuphidden, and remote content may synthesize another event before
popuphidden. This may cause intermittent failure of any tests which
use satchel_common.js.

This patch makes getPopupState send the reply message after the popup
state stable.

The beforeFn and afterFn may cause some pending reflow. Then, synthesizing
arrow keys or mouse button events causes flushing the layout. At this time,
autocomplete popup may be closed with different reason and that may cause
unexpected login database.

Depends on D107172

I found those possible causes, but they are not enough. I confirmed that they don't fix this bug completely, but I hope that they should decrease the frequency.

Keywords: leave-open
Pushed by masayuki@d-toybox.com: https://hg.mozilla.org/integration/autoland/rev/bee239dfeb4f part 1: Make `getPopupState` in satchel's `parent_utils.js` wait to reply stabler state of the popup r=dimi https://hg.mozilla.org/integration/autoland/rev/96a98aacb719 part 2: Make `testConfirmPasswordFieldFilledWithGeneratedPassword` flush before and after running a test r=dimi
Regressions: 1669117

I'm not working on this because of enough low frequency and perhaps big patches required.

Assignee: masayuki → nobody
Status: ASSIGNED → NEW
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: