1554453 - Intermittent toolkit/components/passwordmgr/test/mochitest/{test_insecure_form_field_autocomplete.html,test_autocomplete_basic_form_insecure.html} | Test timed out.

Reporter

Description

•

5 years ago

treeherder

Filed by: dvarga [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=248373807&repo=mozilla-inbound
Full log: https://queue.taskcluster.net/v1/task/Pj1Jfn2_QoCv22ainnnl4w/runs/0/artifacts/public/logs/live_backing.log

23:02:49     INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_insecure_form_field_autocomplete.html | Checking form12 password is:  
23:02:49     INFO - Buffered messages finished
23:02:49     INFO - TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/mochitest/test_insecure_form_field_autocomplete.html | Test timed out. 
23:02:49     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:275:18
23:02:49     INFO -     reportError@SimpleTest/TestRunner.js:121:22
23:02:49     INFO -     TestRunner._checkForHangs@SimpleTest/TestRunner.js:142:7
23:02:49     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
23:02:49     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
23:02:49     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
23:02:49     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
23:02:49     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
23:02:49     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
23:02:49     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
23:02:49     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
23:02:49     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
23:02:49     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
23:02:49     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
23:02:49     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
23:02:49     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
23:02:49     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
23:02:49     INFO -     setTimeout handler*TestRunner._checkForHangs@SimpleTest/TestRunner.js:163:5
23:02:49     INFO -     TestRunner.runTests/<@SimpleTest/TestRunner.js:381:20
23:02:49     INFO -     promise callback*TestRunner.runTests@SimpleTest/TestRunner.js:368:50
23:02:49     INFO -     RunSet.runtests@SimpleTest/setup.js:201:14
23:02:49     INFO -     RunSet.runall@SimpleTest/setup.js:180:12
23:02:49     INFO -     hookupTests@SimpleTest/setup.js:273:12
23:02:49     INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:36:5
23:02:49     INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:49:11
23:02:49     INFO - EventHandlerNonNull*getTestManifest@http://mochi.test:8888/manifestLibrary.js:45:3
23:02:49     INFO -     hookup@SimpleTest/setup.js:253:5
23:02:49     INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fvar%2Ffolders%2F6d%2F47jl_1cd1dv_5tymn6mzk5wh00000x%2FT&cleanupCrashes=true:11:1
23:02:50     INFO - GECKO(2719) | Removing 1 popup notifications.
23:02:50     INFO - GECKO(2719) | MEMORY STAT | vsize 5152MB | residentFast 139MB | heapAllocated 13MB

Comment hidden (Intermittent Failures Robot)

Andreea Pavel [:apavel]

Comment 41

•

4 years ago

There are 48 total failures in the last 7 days on windows10-64-qr and windows10-64 debug

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=291519679&repo=autoland&lineNumber=18374

[task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.197Z] 23:36:12 [task 2020-03-03T23:36:12.198Z] 23:36:12 [task 2020-03-03T23:36:12.198Z] 23:36:12 [task 2020-03-03T23:36:12.198Z] 23:36:12 [task 2020-03-03T23:36:12.198Z] 23:36:12 [task 2020-03-03T23:36:12.198Z] 23:36:12 [task 2020-03-03T23:36:12.198Z] 23:36:12 [task 2020-03-03T23:36:12.198Z] 23:36:12 [task 2020-03-03T23:36:12.198Z] 23:36:12 [task 2020-03-03T23:36:12.198Z] 23:36:12 [task 2020-03-03T23:36:13.184Z] 23:36:13 [task 2020-03-03T23:36:13.203Z] 23:36:13 INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_insecure_form_field_autocomplete.html | Checking form12 username is:
INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_insecure_form_field_autocomplete.html | Checking form12 password is:
INFO - Buffered messages finished
INFO - TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/mochitest/test_insecure_form_field_autocomplete.html | Test timed out.
INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:299:16
INFO - reportError@SimpleTest/TestRunner.js:128:22
INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:150:18
INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
INFO - TestRunner.runTests/<@SimpleTest/TestRunner.js:420:16
INFO - promise callbackTestRunner.runTests@SimpleTest/TestRunner.js:407:48
INFO - RunSet.runtests@SimpleTest/setup.js:218:14
INFO - RunSet.runall@SimpleTest/setup.js:197:12
INFO - hookupTests@SimpleTest/setup.js:294:12
INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:48:13
INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:61:28
INFO - EventHandlerNonNullgetTestManifest@http://mochi.test:8888/manifestLibrary.js:57:3
INFO - hookup@SimpleTest/setup.js:270:20
INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=c%3A%5Cusers%5Ctask_1583276854%5Cappdata%5Clocal%5Ctemp&cleanupCrashes=true:11:1
INFO - GECKO(7032) | MEMORY STAT | vsize 2103853MB | vsizeMaxContiguous 70632520MB | residentFast 118MB | heapAllocated 18MB
INFO - TEST-OK | toolkit/components/passwordmgr/test/mochitest/test_insecure_form_field_autocomplete.html | took 319026ms

Matt can you assign someone to take a look?

Flags: needinfo?(MattN+bmo)

Whiteboard: [stockwell needswork:owner]

Comment hidden (Intermittent Failures Robot)

Andreea Pavel [:apavel]

Comment 44

•

4 years ago

There are 28 total failures in the last 7 days on

windows10-64-qr debug

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=294133894&repo=autoland&lineNumber=28316

[task 2020-03-20T21:43:17.642Z] 21:43:17 INFO - TEST-PASS | toolkit/components/passwordmgr/test/mochitest/test_insecure_form_field_autocomplete.html | Checking form12 password is:
[task 2020-03-20T21:43:17.642Z] 21:43:17 INFO - Buffered messages finished
[task 2020-03-20T21:43:17.642Z] 21:43:17 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/mochitest/test_insecure_form_field_autocomplete.html | Test timed out.
[task 2020-03-20T21:43:17.642Z] 21:43:17 INFO - SimpleTest.ok@SimpleTest/SimpleTest.js:299:16
[task 2020-03-20T21:43:17.642Z] 21:43:17 INFO - reportError@SimpleTest/TestRunner.js:128:22
[task 2020-03-20T21:43:17.642Z] 21:43:17 INFO - TestRunner._checkForHangs@SimpleTest/TestRunner.js:150:18
[task 2020-03-20T21:43:17.642Z] 21:43:17 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-03-20T21:43:17.642Z] 21:43:17 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-03-20T21:43:17.642Z] 21:43:17 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - setTimeout handlerTestRunner._checkForHangs@SimpleTest/TestRunner.js:184:15
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - TestRunner.runTests/<@SimpleTest/TestRunner.js:420:16
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - promise callbackTestRunner.runTests@SimpleTest/TestRunner.js:407:48
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - RunSet.runtests@SimpleTest/setup.js:218:14
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - RunSet.runall@SimpleTest/setup.js:197:12
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - hookupTests@SimpleTest/setup.js:294:12
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - parseTestManifest@http://mochi.test:8888/manifestLibrary.js:48:13
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - getTestManifest/req.onload@http://mochi.test:8888/manifestLibrary.js:61:28
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - EventHandlerNonNullgetTestManifest@http://mochi.test:8888/manifestLibrary.js:57:3
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - hookup@SimpleTest/setup.js:270:20
[task 2020-03-20T21:43:17.643Z] 21:43:17 INFO - EventHandlerNonNull*@http://mochi.test:8888/tests?autorun=1&closeWhenDone=1&consoleLevel=INFO&manifestFile=tests.json&dumpOutputDirectory=c%3A%5Cusers%5Ctask_1584738278%5Cappdata%5Clocal%5Ctemp&cleanupCrashes=true:11:1
[task 2020-03-20T21:43:18.561Z] 21:43:18 INFO - GECKO(6148) | Removing 1 popup notifications.
[task 2020-03-20T21:43:18.620Z] 21:43:18 INFO - GECKO(6148) | MEMORY STAT | vsize 2103826MB | vsizeMaxContiguous 74705020MB | residentFast 102MB | heapAllocated 11MB
[task 2020-03-20T21:43:18.630Z] 21:43:18 INFO - TEST-OK | toolkit/components/passwordmgr/test/mochitest/test_insecure_form_field_autocomplete.html | took 320596ms

Matt can you take a look?

Flags: needinfo?(MattN+bmo)

Andreea Pavel [:apavel]

Updated

•

4 years ago

Flags: needinfo?(MattN+bmo)

Whiteboard: [stockwell unknown] → [stockwell needswork:owner]

Comment hidden (Intermittent Failures Robot)

Matthew N. [:MattN]

Updated

•

4 years ago

Priority: P5 → P3

Matthew N. [:MattN]

Updated

•

4 years ago

Summary: Intermittent toolkit/components/passwordmgr/test/mochitest/test_insecure_form_field_autocomplete.html | Test timed out. → Intermittent toolkit/components/passwordmgr/test/mochitest/{test_insecure_form_field_autocomplete.html,test_autocomplete_basic_form.html} | Test timed out.

Matthew N. [:MattN]

Updated

•

4 years ago

Summary: Intermittent toolkit/components/passwordmgr/test/mochitest/{test_insecure_form_field_autocomplete.html,test_autocomplete_basic_form.html} | Test timed out. → Intermittent toolkit/components/passwordmgr/test/mochitest/{test_insecure_form_field_autocomplete.html,test_autocomplete_basic_form_insecure.html} | Test timed out.

Comment hidden (Intermittent Failures Robot)

Matthew N. [:MattN]

Updated

•

4 years ago

Flags: needinfo?(MattN+bmo)

Comment hidden (Intermittent Failures Robot)

Narcis Beleuzu [:NarcisB]

Comment 78

•

4 years ago

I did a few backfills and it seems that this started to almost perma-fail with the landing of Bug 1649613.
:michelle , can you please take a look?

Backfills: https://treeherder.mozilla.org/jobs?repo=autoland&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel&searchStr=os%2Cx%2C10.14%2Cwebrender%2Copt%2Cmochitests%2Ctest-macosx1014-64-qr%2Fopt-mochitest-plain-e10s%2C5&tochange=eefc090ff3369e152bc9e3fb08f8cce2563eada7&fromchange=916fe4f3e31ad4f9c61d4f031c3f426cbb63f0ec&selectedTaskRun=YPuto61sT3O5wjH5_5iDkg.0

Flags: needinfo?(michelle)

Razvan Maries

Comment 79

•

4 years ago

Backed out bug 1649613: https://hg.mozilla.org/integration/autoland/rev/33696c955659b898db9f7e98c0acee9d181e84fc

Razvan Maries

Updated

•

4 years ago

Flags: needinfo?(michelle)

Comment hidden (Intermittent Failures Robot)

Andreea Pavel [:apavel]

Updated

•

4 years ago

Whiteboard: [stockwell unknown] → [stockwell fixed:backout]]

Andreea Pavel [:apavel]

Updated

•

4 years ago

Status: NEW → RESOLVED

Closed: 4 years ago

Resolution: --- → FIXED

Whiteboard: [stockwell fixed:backout]] → [stockwell fixed:backout]

Ryan VanderMeulen [:RyanVM]

Updated

•

4 years ago

Keywords: regression

Narcis Beleuzu [:NarcisB]

Comment 81

•

4 years ago

New occurrence: https://treeherder.mozilla.org/logviewer?job_id=326076981&repo=autoland&lineNumber=20221

Status: RESOLVED → REOPENED

Resolution: FIXED → ---

Comment hidden (Intermittent Failures Robot)

Dimi Lee [:dimi]

Assignee

Updated

•

3 years ago

Assignee: nobody → dlee

Status: REOPENED → ASSIGNED

Dimi Lee [:dimi]

Assignee

Comment 124

•

3 years ago

Attached file Bug 1554453 - Reset nsAutocompleteController internal state when the login manager marks an focus field. r=sfoster,tgiles — Details

As far as I understand, there are at least 3 cases we trigger an autocomplete search:

Form history
CC/Address autocomplete
Login autocomplete

In nsAutocompleteController::HandleKeyNavigation, we might trigger a search operation (or open the popup)
However, when we find there is already a search result received previously, and the search string is the same
as the current one, we won't trigger a new search[1] because the result should be the same.
This might be true for most of the cases, but not true when clients that perform the search is differnt.
For example, the same search string might return different result when it is searched by the login manager
and by the form hisotry component.

So here is how the intermittent occurs:

The page is loaded
Password field is detected so the login manager fetches the login data from the parent asynchronously
The testcase continues to run. The username field is focused
Autocomplete search for the focus field is triggered. Since login manager has not yet told FormFillController
this is a field we care, we search the form history and get an empty result.
Login data is sent from parent to child, _fillForm is called. The LoginManagerChild calls MarkAsLoginManagerField
Key event occurs on the field. Autocomplete search is triggered again. However, the search is not executed because
[1]
Popup is not shown. Testcase timeout.

When #5 occurs before #3, the autocomplete search triggered in #4 is procesed by the login manager, we will get the result
and then open the popup.

In the current architecutre, I don't see an easy way that we can distinguish whether the autocomplete client will be different
in nsAutocompleteController. So this patch calls ResetInternalState() when we call MarkAsLoginManagerField on a focus field,
which tells nsAutocompleteController that previous result will no longer be update-to-date

[1] https://searchfox.org/mozilla-central/rev/fb8d77331582639ea6848a61dd8ee812fac31b77/toolkit/components/autocomplete/nsAutoCompleteController.cpp#516-521

Phabricator Automation

Updated

•

3 years ago

Attachment #9250912 - Attachment description: WIP: Bug 1554453 - Reset nsAutocompleteController internal state when the login manager marks an focus field. → Bug 1554453 - Reset nsAutocompleteController internal state when the login manager marks an focus field. r=sfoster,tgiles

Chris Peterson [:cpeterson]

Updated

•

3 years ago

Blocks: 1685798

Comment hidden (Intermittent Failures Robot)

Pulsebot

Comment 126

•

3 years ago

Pushed by dlee@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/090477f246a5
Reset nsAutocompleteController internal state when the login manager marks an focus field. r=tgiles

Marian-Vasile Laza

Comment 127

•

3 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/090477f246a5

Status: ASSIGNED → RESOLVED

Closed: 4 years ago → 3 years ago

status-firefox96: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → 96 Branch

Markus Stange [:mstange]

Comment 128

•

3 years ago

Thank you so much for fixing this!

Comment hidden (Intermittent Failures Robot)