Closed Bug 1277105 Opened 7 years ago Closed 7 years ago

Intermittent e10s browser_capture_doorhanger.js | Check the password changed - Got pass2, expected notifyp1 or Should only have 1 login - Got 0, expected 1

Categories

(Toolkit :: Password Manager, defect, P5)

Product:
Toolkit
Component:
Password Manager
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla51
Tracking Flags:
Tracking Status
e10s + ---
firefox48 --- unaffected
firefox49 --- disabled
firefox50 --- fixed
firefox51 --- fixed

People

(Reporter: KWierso, Assigned: evanxd)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

bug-1277105.patch
13.69 KB, patch
evanxd
: review+
Details | Diff | Splinter Review 
Wow, this kinda of exploded. Do you have any time to debug this?
Flags: needinfo?(timdream)
See Also: → 1273871
Hum, not easy to see who is at fault here... nsLoginManagerPrompter couldn't find the login to change that is supposedly in the store?

Anyway, made some small change to the test file and see if we could find the one test that trigger this.
https://treeherder.mozilla.org/#/jobs?repo=try&revision=bf2ff69d5704

 14:04:39     INFO -  495 INFO Console message: [JavaScript Error: "Error: Can't add a login with a null username." {file: "resource://gre/components/nsLoginManager.js" line: 274}]

 14:04:39     INFO -  496 INFO Console message: [JavaScript Error: "[Exception... "[JavaScript Error: "Can't add a login with a null username." {file: "resource://gre/components/nsLoginManager.js" line: 274}]'[JavaScript Error: "Can't add a login with a null username." {file: "resource://gre/components/nsLoginManager.js" line: 274}]' when calling method: [nsILoginManager::addLogin]"  nsresult: "0x80570021 (NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS)"  location: "JS frame :: resource://gre/components/nsLoginManagerPrompter.js :: _showLoginCaptureDoorhanger/persistData :: line 898"  data: yes]"]

 14:04:39     INFO -  _showLoginCaptureDoorhanger/persistData@resource://gre/components/nsLoginManagerPrompter.js:898:9

 14:04:39     INFO -  _showLoginCaptureDoorhanger/mainAction.callback@resource://gre/components/nsLoginManagerPrompter.js:929:9

 14:04:39     INFO -  _onButtonEvent@resource://gre/modules/PopupNotifications.jsm:1151:7

 14:04:39     INFO -  oncommand@chrome://browser/content/browser.xul:1:1

 14:04:39     INFO -  clickDoorhangerButton@chrome://mochitests/content/browser/toolkit/components/passwordmgr/test/browser/head.js:114:5

 14:04:39     INFO -  test_changePLoginOnPForm/<@chrome://mochitests/content/browser/toolkit/components/passwordmgr/test/browser/browser_capture_doorhanger.js:344:5

 14:04:39     INFO -  testSubmittingLoginForm/<@chrome://mochitests/content/browser/toolkit/components/passwordmgr/test/browser/head.js:46:14

 14:04:39     INFO -  TaskImpl_run@resource://gre/modules/Task.jsm:319:40

 14:04:39     INFO -  Handler.prototype.process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:937:23

 14:04:39     INFO -  this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:816:7

 14:04:39     INFO -  Promise*this.PromiseWalker.scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:747:11

 14:04:39     INFO -  this.PromiseWalker.schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:779:7

 14:04:39     INFO -  this.PromiseWalker.completePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:714:7

 14:04:39     INFO -  receiveMessage@resource://testing-common/ContentTask.jsm:113:9

 14:04:39     INFO -  497 INFO TEST-PASS | toolkit/components/passwordmgr/test/browser/browser_capture_doorhanger.js | Should only have 1 login -

14:04:39 INFO - 498 INFO TEST-PASS | toolkit/components/passwordmgr/test/browser/browser_capture_doorhanger.js | Check the username unchanged -
Assignee: nobody → timdream
Status: NEW → ASSIGNED
Flags: needinfo?(timdream)
Maybe we have a problem in storage-json.js impl since Mar 30? That would put the cause of this bug to bug 667233 -- but the patch doesn't look like it...

Here is another push that turn on the logger
https://treeherder.mozilla.org/#/jobs?repo=try&revision=183f918a9248279ad814153118745fed87971214
Keywords: leave-open
Summary: Intermittent browser_capture_doorhanger.js | Check the password changed - Got pass2, expected notifyp1 or Should only have 1 login - Got 0, expected 1 → Intermittent e10s browser_capture_doorhanger.js | Check the password changed - Got pass2, expected notifyp1 or Should only have 1 login - Got 0, expected 1
Whiteboard: [test disabled on e10s]
Pushed by philringnalda@gmail.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/b8d9d1486f5b
Disable browser_capture_doorhanger.js on e10s for constant failures
Blocks: e10s-tests
tracking-e10s: --- → +
Intermittent e10s test failure
Priority: -- → P5
Evan, do you have try access to figure out what's going on here? It's entirely possible the code rather than the test is at fault, so please spend some time debug into it.

(You can pull my changeset in https://treeherder.mozilla.org/#/jobs?repo=try&revision=1077db2a28c952a47e5b52ffb2701b470c168776 and going forward with it)
Flags: needinfo?(evan)
Hi Tim,

I have try access but I have problems of pushing try. I'll fix the try problems.

Now I'm working on some Firefox's good first bugs. Just get started to learn things. Currently I don't have enough knowledge to fix this bug.
Flags: needinfo?(evan)
I found it shocking for you to giving up on yourself before actually trying. This bug simply involves code reading, find out the call stack and isolate the cause of intermittent. It involves NO prior Firefox knowledge. You also already have patches pointed by me on the rough call stack.

Please get your Try access working by this week and start working on this bug.
Flags: needinfo?(evan)
Hi Tim,

Sure, let me try it.
Flags: needinfo?(evan)
Assignee: timdream → evan
Another approach we could try would be to borrow a machine and try to reproduce the bug there.
Since OrangeFactor Robot doesn't report failures anymore, let's try some more try pushes[1][2][3] without any change to test the current stability. We can set WORKSFORME once every try is good.

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=51a23383aee7
[2]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=f4b07bccfd64
[3]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=20438bc61f03
Re-trigger the browser_capture_doorhanger.js test for 10 times[1]. If the tests are all good, let's close the bug.

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=20438bc61f03
The test is disabled, you have to reenable it in your try push to learn anything.
Thanks, Phil.

I re-enabled the test to figure out the root cause. The try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=96270239befb
The error messages of the intermittent failures in Comment 44 is
```
TypeError: logins[0] is undefined
```

So the failures might be related with the `_searchLogins` method in `storage-json.js`[1] or `storage-mozStorage.js`[2] files. There are two implementations for `nsILoginManagerStorage.idl`[3]. Not sure which implementation is used in the test failures. But already added dump messages to check it and debug the failures, we can see the message in the try[4].

[1]: http://searchfox.org/mozilla-central/source/toolkit/components/passwordmgr/storage-json.js#282
[2]: http://searchfox.org/mozilla-central/source/toolkit/components/passwordmgr/storage-mozStorage.js#469
[3]: http://searchfox.org/mozilla-central/source/toolkit/components/passwordmgr/nsILoginManagerStorage.idl
[4]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=bb7a1d91989e
According to the try log[1], the implementation of `nsILoginManagerStorage.idl` in the try is `storage-json.js`. And already re-triggered the test multiple times to reproduce the intermittent failures. Start to debug!

[1]: https://archive.mozilla.org/pub/firefox/try-builds/itoyxd@gmail.com-bb7a1d91989ebd8fecc96d66d88a00149eeeb7ed/try-linux64/try_ubuntu64_vm_test-mochitest-e10s-browser-chrome-3-bm51-tests1-linux64-build475.txt.gz
A new error message:
```
440 INFO TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/browser/browser_capture_doorhanger.js | Uncaught exception - at chrome://mochitests/content/browser/toolkit/components/passwordmgr/test/browser/browser_capture_doorhanger.js:681 - TypeError: httpLogins[0] is undefined
```[1]

It is also about the `searchLogins`[2] method in `storage-json.js` file. Continue to dig deeper.

[1]: https://archive.mozilla.org/pub/firefox/try-builds/itoyxd@gmail.com-bb7a1d91989ebd8fecc96d66d88a00149eeeb7ed/try-linux64/try_ubuntu64_vm_test-mochitest-e10s-browser-chrome-3-bm51-tests1-linux64-build476.txt.gz
[2]: http://searchfox.org/mozilla-central/source/toolkit/components/passwordmgr/storage-json.js#245
Just guest maybe the intermittent failure is related with `yield this._store.load();`[1](load the data asynchronously). Continue to debug...

[1]: http://searchfox.org/mozilla-central/source/toolkit/components/passwordmgr/storage-json.js#56-58
Added new dump messages to debug the `_searchLogins` and `addLogin` methods in `storage-json.js` file.

The try:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=041c19d5674b
Found out some interesting things here. The below error message shows `Check http logins count - Got 0, expected 1`, but at same time `this._store.data.logins.length` is 1.
```
08:23:50     INFO -  evanxd debug: this._store.data.logins.length: 1
08:23:50     INFO -  Not taking screenshot here: see the one that was previously logged
08:23:50     INFO -  439 INFO TEST-UNEXPECTED-FAIL | toolkit/components/passwordmgr/test/browser/browser_capture_doorhanger.js | Check http logins count - Got 0, expected 1
```[1]

So maybe something wrong here[2], cannot add new item into `foundLogins` array.

[1]: https://archive.mozilla.org/pub/firefox/try-builds/itoyxd@gmail.com-041c19d5674b7aaca9ecfc2d1bf6a32a33da3d1f/try-linux64/try_ubuntu64_vm_test-mochitest-e10s-browser-chrome-3-bm51-tests1-linux64-build485.txt.gz
[2]: http://searchfox.org/mozilla-central/source/toolkit/components/passwordmgr/storage-json.js#341-360
A new try[1] to figure out the error message listed in Comment 50.

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=bf0fdad9158d
A new dump messages in the try[1] to check `this._store.data.logins`, `matchData`, and `aLogin` variables in the `_searchLogins` method.

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=341e3a5abc74
Somehow `login.username` is `null`(see the below log) so the intermittent failures happen. Need to continue to figure out why `login.username` is null here[2].

```
01:42:54     INFO -  389 INFO Console message: [JavaScript Error: "Error: Can't add a login with a null username." {file: "resource://gre/components/nsLoginManager.js" line: 276}]
01:42:54     INFO -  390 INFO Console message: [JavaScript Error: "[Exception... "[JavaScript Error: "Can't add a login with a null username." {file: "resource://gre/components/nsLoginManager.js" line: 276}]'[JavaScript Error: "Can't add a login with a null username." {file: "resource://gre/components/nsLoginManager.js" line: 276}]' when calling method: [nsILoginManager::addLogin]"  nsresult: "0x80570021 (NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS)"  location: "JS frame :: resource://gre/components/nsLoginManagerPrompter.js :: _showLoginCaptureDoorhanger/persistData :: line 877"  data: yes]"]
```[1]

[1]: https://archive.mozilla.org/pub/firefox/try-builds/itoyxd@gmail.com-341e3a5abc74f67eb68c210d6e24fb3534ef68f2/try-linux64/try_ubuntu64_vm_test-mochitest-e10s-browser-chrome-3-bm124-tests1-linux64-build1309.txt.gz
[2]: http://searchfox.org/mozilla-central/source/toolkit/components/passwordmgr/nsLoginManager.js#268-278
Push a new try[1].

Wait for 5 secs to click door hanger button to try to skip the `Error: Can't add a login with a null username.` error mentioned in Comment 53.

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=faf8c56e6b80
Pushed a new try[1].

Wait for 5 secs to click door hanger button to try to skip the `Error: Can't add a login with a null username.` error mentioned in Comment 53.

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=7dca6e78ba5b
Push a new try[1] to fix the `ReferenceError: beginDate is not defined` issue.

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=35ab57bc7274
New try[1]:

5 seconds are too long. Let's try to use 1.5 seconds. It's OK now. Now run the test for multiple times to reproduce the intermittent failures.

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=035df978a85f&selectedJob=27070616
Nice, there is no any intermittent failure[1] for over 50 times once wait for 1.5 seconds to return username and password from `testSubmittingLoginForm` function. Next step, add a new condition into [2] to fix the issue.

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=035df978a85f&selectedJob=27071438
[2]: http://searchfox.org/mozilla-central/source/toolkit/components/passwordmgr/test/browser/head.js#33-36
Added the new condition mentioned in Comment 59, and pushed a new try[1] to test it.

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=da57af9daf74
The patch[1] (looks like) fixed the intermittent failure, but it also caused test timed out issue[2]. Continue to fix that.

[1]: https://hg.mozilla.org/try/rev/5cfaaf384209e0a91aabaa8a1f9b9013e2aaf9f2
[2]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=da57af9daf74
Pushed a new try[1]: Fixed the test timeout issue(Comment 61)

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=89bb4a935185
The new test timeout issue still be happened intermittently. Investing...
But good news is the original intermittent failure is fixed by the patch[1].

[1]: https://hg.mozilla.org/try/rev/5cfaaf384209e0a91aabaa8a1f9b9013e2aaf9f2
Pushed try[1]: Added dump log to investigate the intermittent timeout issue.

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=409ca555eddd
Pushed a new try[1] to fix the timeout issue: Check door hanger's username and password before clicking the door hanger button. 

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=03744dc48800
Pushed a new try[1] to fix the errors on Comment 66.

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=aef0d24e80b0
Pushed a new try[1] to fix the intermittent failure. Finally...

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=40ad222fcad1
Attached patch bug-1277105.patch (obsolete) — — Splinter Review 
Hi Justin,

Could you help review the patch?
The "browser_capture_doorhanger.js" tests are passed for 50 times[1] continuously.

Thanks.

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=40ad222fcad1
Attachment #8790511 - Flags: review?(dolske)
Pushed a new try[1] for changing commit message on Comment 69.

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=1e7c381719df
Attachment #8790511 - Flags: review?(dolske) → review?(MattN+bmo)
Comment on attachment 8790511 [details] [diff] [review]
bug-1277105.patch

Review of attachment 8790511 [details] [diff] [review]:
-----------------------------------------------------------------

Great job, thanks!

Please update the commit message to be more clear about what file/feature is being changed and switch to "r=MattN"
Example: 
Bug 1277105 - Wait for the browser_capture_doorhanger.js doorhangers to be ready in order to pass with e10s. r=MattN
Attachment #8790511 - Flags: review?(MattN+bmo) → review+
Sure, Matthew. Thanks for the review.

Updated the commit message and pushed a new try[1] for that.

[1]: https://treeherder.mozilla.org/#/jobs?repo=try&revision=cbe26fa5881a
Comment on attachment 8790742 [details] [diff] [review]
bug-1277105.patch

Got r+ from Comment 71. Just updated commit message here.
Attachment #8790742 - Flags: review+
Attachment #8790511 - Attachment is obsolete: true
Keywords: checkin-needed
status-firefox50: disabled → affected
status-firefox51: --- → affected
Keywords: leave-open
Whiteboard: [test disabled on e10s]
Pushed by ryanvm@gmail.com:
https://hg.mozilla.org/integration/fx-team/rev/43168828161b
Wait for the browser_capture_doorhanger.js doorhangers to be ready in order to pass with e10s. r=MattN
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/43168828161b
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
status-firefox51: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla51
See Also: → 1313136
You need to log in before you can comment on or make changes to this bug.