Closed Bug 1633960 Opened 5 years ago Closed 5 years ago

Intermittent toolkit/components/passwordmgr/test/browser/browser_doorhanger_autofill_then_save_password.js | Test timed out -

Categories

(Toolkit :: Password Manager, defect, P5)

Product:
Toolkit
Component:
Password Manager
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla78
Tracking Flags:
Tracking Status
firefox75 --- unaffected
firefox76 --- unaffected
firefox77 --- fixed
firefox78 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

Attachments

(1 file, 1 obsolete file)

Bug 1633960 - potential fix for intermittent test browser_doorhanger_autofill_then_save_password.js;r=MattN
47 bytes, text/x-phabricator-request
Details | Review

Filed by: cbrindusan [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=299897178&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/b1LotBlERS69YddrBAexjQ/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/b1LotBlERS69YddrBAexjQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2020-04-29T00:21:17.700Z] 00:21:17 INFO - TEST-START | toolkit/components/passwordmgr/test/browser/browser_doorhanger_autofill_then_save_password.js
[task 2020-04-29T00:21:17.840Z] 00:21:17 INFO - GECKO(9616) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to c:\users\task_1588118043\appdata\local\temp\tmpi1z9ki.mozrunner\runtests_leaks_tab_pid8392.log
[task 2020-04-29T00:21:17.840Z] 00:21:17 INFO - GECKO(9616) | [8392, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 224
[task 2020-04-29T00:21:17.850Z] 00:21:17 INFO - GECKO(9616) | [Parent 7904, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/generic/nsFrameSelection.cpp, line 1512
[task 2020-04-29T00:21:17.982Z] 00:21:17 INFO - GECKO(9616) | [Child 8392: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 000001CC57EAF800 == 1 [pid = 8392] [id = {b693b84c-5a44-4476-92ca-67b293ca99f4}]
[task 2020-04-29T00:21:17.982Z] 00:21:17 INFO - GECKO(9616) | [Child 8392: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (000001CC58864090) [pid = 8392] [serial = 1] [outer = 0000000000000000]
[task 2020-04-29T00:21:17.984Z] 00:21:17 INFO - GECKO(9616) | [Child 8392: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (000001CC58873800) [pid = 8392] [serial = 2] [outer = 000001CC58864090]
[task 2020-04-29T00:21:18.176Z] 00:21:18 INFO - GECKO(9616) | [Child 8392: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (000001CC57EAF000) [pid = 8392] [serial = 3] [outer = 000001CC58864090]
[task 2020-04-29T00:21:18.385Z] 00:21:18 INFO - GECKO(9616) | [Child 8392, 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, line 314
[task 2020-04-29T00:21:18.577Z] 00:21:18 INFO - GECKO(9616) | [Parent 7904, Main Thread] WARNING: IInputPane2::TryHide is failure: 'result', file /builds/worker/checkouts/gecko/widget/windows/OSKInputPaneManager.cpp, line 69
[task 2020-04-29T00:21:18.697Z] 00:21:18 INFO - GECKO(9616) | [Parent 7904, Main Thread] WARNING: IInputPane2::TryHide is failure: 'result', file /builds/worker/checkouts/gecko/widget/windows/OSKInputPaneManager.cpp, line 69
[task 2020-04-29T00:21:18.940Z] 00:21:18 INFO - GECKO(9616) | JavaScript error: resource://gre/modules/LoginManager.jsm, line 264: Error: Can't add a login with a null or empty password.[task 2020-04-29T00:21:18.978Z] 00:21:18 INFO - GECKO(9616) | [Child 8392: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 4 (000001CC5A16C000) [pid = 8392] [serial = 4] [outer = 000001CC58864090]
[task 2020-04-29T00:21:19.056Z] 00:21:19 INFO - GECKO(9616) | [Child 8392, 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, line 314
[task 2020-04-29T00:21:19.155Z] 00:21:19 INFO - GECKO(9616) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to c:\users\task_1588118043\appdata\local\temp\tmpi1z9ki.mozrunner\runtests_leaks_tab_pid1056.log
[task 2020-04-29T00:21:19.155Z] 00:21:19 INFO - GECKO(9616) | [1056, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 224
[task 2020-04-29T00:21:20.742Z] 00:21:20 INFO - GECKO(9616) | [Child 6116: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 000001A872FA7000 == 0 [pid = 6116] [id = {7ed0f0a1-61e1-4d2f-b1c0-f5c5f0ce3197}] [url = about:blank]
[task 2020-04-29T00:21:22.123Z] 00:21:22 INFO - GECKO(9616) | [Child 10156: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0000016CA00B7800 == 1 [pid = 10156] [id = {5f3e6a11-9da0-4217-a7f6-bc58173e2d23}] [url = chrome://gfxsanity/content/sanitytest.html]
[task 2020-04-29T00:21:24.700Z] 00:21:24 INFO - GECKO(9616) | [Parent 7904: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 12 (000001C291D84000) [pid = 7904] [serial = 10] [outer = 0000000000000000] [url = about:blank]
[task 2020-04-29T00:21:24.842Z] 00:21:24 INFO - GECKO(9616) | [Child 6116: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (000001A872FB4400) [pid = 6116] [serial = 2] [outer = 0000000000000000] [url = about:blank]
[task 2020-04-29T00:21:24.868Z] 00:21:24 INFO - GECKO(9616) | [Child 6116: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (000001A873455090) [pid = 6116] [serial = 1] [outer = 0000000000000000] [url = about:blank]
[task 2020-04-29T00:21:25.017Z] 00:21:25 INFO - GECKO(9616) | [Parent 7904: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (000001C28C6A5BC0) [pid = 7904] [serial = 1] [outer = 0000000000000000] [url = chrome://gfxsanity/content/sanityparent.html]
[task 2020-04-29T00:21:26.233Z] 00:21:26 INFO - GECKO(9616) | [Child 10156: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 4 (0000016CA00C5400) [pid = 10156] [serial = 2] [outer = 0000000000000000] [url = about:blank]
[task 2020-04-29T00:21:26.252Z] 00:21:26 INFO - GECKO(9616) | [Child 10156: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (0000016CA045A090) [pid = 10156] [serial = 1] [outer = 0000000000000000] [url = chrome://gfxsanity/content/sanitytest.html]
[task 2020-04-29T00:21:26.822Z] 00:21:26 INFO - GECKO(9616) | [Child 2304: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 14 (000001CFEA9C3400) [pid = 2304] [serial = 4] [outer = 0000000000000000] [url = about:blank]
[task 2020-04-29T00:21:26.822Z] 00:21:26 INFO - GECKO(9616) | [Child 2304: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 13 (000001CFEA9C5000) [pid = 2304] [serial = 6] [outer = 0000000000000000] [url = about:blank]
[task 2020-04-29T00:21:26.822Z] 00:21:26 INFO - GECKO(9616) | [Child 2304: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 12 (000001CFEA9CA800) [pid = 2304] [serial = 10] [outer = 0000000000000000] [url = about:blank]
[task 2020-04-29T00:21:26.822Z] 00:21:26 INFO - GECKO(9616) | [Child 2304: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (000001CFEA0EE400) [pid = 2304] [serial = 2] [outer = 0000000000000000] [url = about:blank]
[task 2020-04-29T00:21:26.822Z] 00:21:26 INFO - GECKO(9616) | [Child 2304: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (000001CFEA9C7C00) [pid = 2304] [serial = 8] [outer = 0000000000000000] [url = about:blank]
[task 2020-04-29T00:21:26.887Z] 00:21:26 INFO - GECKO(9616) | [Child 2304: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 9 (000001CFEA9997D0) [pid = 2304] [serial = 3] [outer = 0000000000000000] [url = moz-extension://4e244f73-c1c9-4a98-9585-bda01edf7b74/_generated_background_page.html]
[task 2020-04-29T00:21:26.887Z] 00:21:26 INFO - GECKO(9616) | [Child 2304: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 000001CFEA9C2400 == 4 [pid = 2304] [id = {57c6783b-e915-4bcc-b856-ccd6fae6f7fd}] [url = moz-extension://4e244f73-c1c9-4a98-9585-bda01edf7b74/_generated_background_page.html]
[task 2020-04-29T00:21:28.454Z] 00:21:28 INFO - GECKO(9616) | [Child 10220: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (00000198D0DBDC00) [pid = 10220] [serial = 2] [outer = 0000000000000000] [url = about:blank]
[task 2020-04-29T00:21:28.920Z] 00:21:28 INFO - GECKO(9616) | [Child 6116: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (000001A87347F000) [pid = 6116] [serial = 3] [outer = 0000000000000000] [url = about:blank]
[task 2020-04-29T00:21:28.920Z] 00:21:28 INFO - GECKO(9616) | [Child 6116: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (000001A87545E400) [pid = 6116] [serial = 4] [outer = 0000000000000000] [url = about:blank]
[task 2020-04-29T00:21:29.019Z] 00:21:29 INFO - GECKO(9616) | [Parent 7904: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (000001C28C68F800) [pid = 7904] [serial = 2] [outer = 0000000000000000] [url = about:blank]
[task 2020-04-29T00:21:30.302Z] 00:21:30 INFO - GECKO(9616) | [Child 10156: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (0000016CA048D400) [pid = 10156] [serial = 3] [outer = 0000000000000000] [url = chrome://gfxsanity/content/sanitytest.html]
[task 2020-04-29T00:21:30.363Z] 00:21:30 INFO - GECKO(9616) | [Child 8392: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (000001CC58873800) [pid = 8392] [serial = 2] [outer = 0000000000000000] [url = about:blank]
[task 2020-04-29T00:21:30.930Z] 00:21:30 INFO - GECKO(9616) | [Child 2304: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 8 (000001CFEC639400) [pid = 2304] [serial = 12] [outer = 0000000000000000] [url = moz-extension://4e244f73-c1c9-4a98-9585-bda01edf7b74/_generated_background_page.html]
[task 2020-04-29T00:22:47.747Z] 00:22:47 INFO - TEST-INFO | started process screenshot
[task 2020-04-29T00:22:47.817Z] 00:22:47 INFO - TEST-INFO | screenshot: exit 0
[task 2020-04-29T00:22:47.817Z] 00:22:47 INFO - Buffered messages logged at 00:21:17[task 2020-04-29T00:22:47.817Z] 00:22:47 INFO - Entering test bound common_initialize
[task 2020-04-29T00:22:47.817Z] 00:22:47 INFO - Leaving test bound common_initialize
[task 2020-04-29T00:22:47.817Z] 00:22:47 INFO - Entering test bound autofill, then delete u/p, then fill new u/p should show 'save'
[task 2020-04-29T00:22:47.818Z] 00:22:47 INFO - testing with: {"name":"autofill, then delete u/p, then fill new u/p should show 'save'","oldUsername":"oldUsername","oldPassword":"oldPassword","actions":[{"setUsername":"newUsername"},{"setPassword":"newPassword"}],"expectedNotification":"addLogin","expectedDoorhanger":"password-save"}
[task 2020-04-29T00:22:47.818Z] 00:22:47 INFO - Starting test: autofill, then delete u/p, then fill new u/p should show 'save'
[task 2020-04-29T00:22:47.818Z] 00:22:47 INFO - Buffered messages logged at 00:21:18
[task 2020-04-29T00:22:47.818Z] 00:22:47 INFO - Triggering a page navigation that is not initiated by the user
[task 2020-04-29T00:22:47.818Z] 00:22:47 INFO - As the user, update form with action: {"setUsername":"newUsername"}
[task 2020-04-29T00:22:47.818Z] 00:22:47 INFO - changeContentFormValues, update: #form-basic-username, to: newUsername
[task 2020-04-29T00:22:47.818Z] 00:22:47 INFO - changeContentInputValue: from "oldUsername" to "newUsername"
[task 2020-04-29T00:22:47.818Z] 00:22:47 INFO - Input value changed
[task 2020-04-29T00:22:47.819Z] 00:22:47 INFO - As the user, update form with action: {"setPassword":"newPassword"}
[task 2020-04-29T00:22:47.819Z] 00:22:47 INFO - changeContentFormValues, update: #form-basic-password, to: newPassword
[task 2020-04-29T00:22:47.819Z] 00:22:47 INFO - changeContentInputValue: from "oldPassword" to "newPassword"
[task 2020-04-29T00:22:47.819Z] 00:22:47 INFO - Input value changed
[task 2020-04-29T00:22:47.819Z] 00:22:47 INFO - listenForTestNotification, resolving for message: FormSubmit
[task 2020-04-29T00:22:47.819Z] 00:22:47 INFO - Waiting for doorhanger of type: password-save
[task 2020-04-29T00:22:47.819Z] 00:22:47 INFO - TEST-PASS | toolkit/components/passwordmgr/test/browser/browser_doorhanger_autofill_then_save_password.js | Looking for action at index button -
[task 2020-04-29T00:22:47.820Z] 00:22:47 INFO - TEST-PASS | toolkit/components/passwordmgr/test/browser/browser_doorhanger_autofill_then_save_password.js | at least one notification displayed -
[task 2020-04-29T00:22:47.820Z] 00:22:47 INFO - TEST-PASS | toolkit/components/passwordmgr/test/browser/browser_doorhanger_autofill_then_save_password.js | 1 notification(s) -
[task 2020-04-29T00:22:47.820Z] 00:22:47 INFO - TEST-PASS | toolkit/components/passwordmgr/test/browser/browser_doorhanger_autofill_then_save_password.js | Triggering main action -
[task 2020-04-29T00:22:47.820Z] 00:22:47 INFO - Console message: [JavaScript Error: "Error: Can't add a login with a null or empty password." {file: "resource://gre/modules/LoginManager.jsm" line: 264}]
[task 2020-04-29T00:22:47.820Z] 00:22:47 INFO - Console message: [JavaScript Error: "[Exception... "[JavaScript Error: "Can't add a login with a null or empty password." {file: "resource://gre/modules/LoginManager.jsm" line: 264}]'[JavaScript Error: "Can't add a login with a null or empty password." {file: "resource://gre/modules/LoginManager.jsm" line: 264}]' when calling method: [nsILoginManager::addLogin]" nsresult: "0x80570021 (NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS)" location: "JS frame :: resource://gre/modules/LoginManagerPrompter.jsm :: persistData :: line 342" data: yes]"]
[task 2020-04-29T00:22:47.820Z] 00:22:47 INFO - persistData@resource://gre/modules/LoginManagerPrompter.jsm:342:25
[task 2020-04-29T00:22:47.820Z] 00:22:47 INFO - callback@resource://gre/modules/LoginManagerPrompter.jsm:392:9
[task 2020-04-29T00:22:47.820Z] 00:22:47 INFO - _onButtonEvent@resource://gre/modules/PopupNotifications.jsm:1874:25
[task 2020-04-29T00:22:47.820Z] 00:22:47 INFO - oncommand@chrome://browser/content/browser.xhtml:1:20
[task 2020-04-29T00:22:47.820Z] 00:22:47 INFO - clickDoorhangerButton@chrome://mochitests/content/browser/toolkit/components/passwordmgr/test/browser/head.js:390:10
[task 2020-04-29T00:22:47.820Z] 00:22:47 INFO - test_save_change/<@chrome://mochitests/content/browser/toolkit/components/passwordmgr/test/browser/browser_doorhanger_autofill_then_save_password.js:136:13
[task 2020-04-29T00:22:47.820Z] 00:22:47 INFO - asyncwithNewTab@resource://testing-common/BrowserTestUtils.jsm:146:24[task 2020-04-29T00:22:47.821Z] 00:22:47 INFO - asynctest_save_change@chrome://mochitests/content/browser/toolkit/components/passwordmgr/test/browser/browser_doorhanger_autofill_then_save_password.js:76:26
[task 2020-04-29T00:22:47.821Z] 00:22:47 INFO - asyncautofill, then delete u/p, then fill new u/p should show 'save'@chrome://mochitests/content/browser/toolkit/components/passwordmgr/test/browser/browser_doorhanger_autofill_then_save_password.js:43:13
[task 2020-04-29T00:22:47.821Z] 00:22:47 INFO - Tester_execTest/<@chrome://mochikit/content/browser-test.js:1039:34
[task 2020-04-29T00:22:47.821Z] 00:22:47 INFO - asyncTester_execTest@chrome://mochikit/content/browser-test.js:1074:11
[task 2020-04-29T00:22:47.821Z] 00:22:47 INFO - nextTest/<@chrome://mochikit/content/browser-test.js:904:14
[task 2020-04-29T00:22:47.821Z] 00:22:47 INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:918:23
[task 2020-04-29T00:22:47.821Z] 00:22:47 INFO -
[task 2020-04-29T00:22:47.821Z] 00:22:47 INFO - Buffered messages finished
[task 2020-04-29T00:22:47.821Z] 00:22:47 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/browser/browser_doorhanger_autofill_then_save_password.js | Test timed out -

This fails on tier1: https://treeherder.mozilla.org/logviewer.html#?job_id=299975433&repo=try
Severin, please take a look over this. Thank you.

Flags: needinfo?(severin.mozilla)
Regressed by: 1632405
Summary: Intermittent [TV] toolkit/components/passwordmgr/test/browser/browser_doorhanger_autofill_then_save_password.js | Test timed out - → Intermittent toolkit/components/passwordmgr/test/browser/browser_doorhanger_autofill_then_save_password.js | Test timed out -
Has Regression Range: --- → yes
Keywords: regression
Assignee: nobody → severin.mozilla
Status: NEW → ASSIGNED
Flags: needinfo?(severin.mozilla)

We suspect that this problem may have been introduced by the fix to bug 1629174, before this test was added. We're backing that change out, and will watch to see if it fixes this failure. If not, I'll investigate further.

Leaving myself assigned.

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

status-firefox75: --- → unaffected
status-firefox76: --- → unaffected
status-firefox77: --- → affected

Kept tests, logs, and the addition of a curly brace to a switch statement.

I thought bug 1633351 would have fixed this but maybe it didn't?

Attachment #9145616 - Attachment is obsolete: true
Pushed by apavel@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/227f6fc9c5bf potential fix for intermittent test browser_doorhanger_autofill_then_save_password.js;r=MattN

https://hg.mozilla.org/mozilla-central/rev/227f6fc9c5bf

Status: ASSIGNED → RESOLVED
Closed: 5 years ago
status-firefox78: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla78

The patch landed in nightly and beta is affected.
:severin, is this bug important enough to require an uplift?
If not please set status_beta to wontfix.

For more information, please visit auto_nag documentation.

Flags: needinfo?(severin.mozilla)

There was only one failure on beta in the last week…

status-firefox77: affected → fix-optional
Flags: needinfo?(severin.mozilla)

Hey Severin, can this be verified manually by QA or not actionable on our side?

Flags: needinfo?(severin.mozilla)

Hi Timea. No need to verify this one.

I'm new to BZ, is there a label of some kind I should put on the ticket when that is the case?

Flags: needinfo?(severin.mozilla)

No worries, you can set up the "qe verify" to "+" if you want QA to verify the fix or "-" if it can't be done manually or verification is not needed. We follow that flag to see what needs to be done so feel free to use it to mark it for verification.

Flags: qe-verify-
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: