Closed Bug 482175 Opened 16 years ago Closed 14 years ago

Intermittent failure of test_prompt.html: An error occurred - uncaught exception: No matching logins at :0

Categories

(Toolkit :: Password Manager, defect)

Product:
Toolkit
Component:
Password Manager
Platform:
x86
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED

People

(Reporter: cpearce, Assigned: Dolske)

References

Details

(Keywords: intermittent-failure, Whiteboard: [debugging, see comments 16, 101, 291 and 353])

Attachments

(1 file, 2 obsolete files)

Rely on password manager notifications instead of timeouts in tests.
(deleted), patch
Dolske
: review+
Details | Diff | Splinter Review 
Two consecutive "Linux mozilla-central unit test" runs had different results on test_prompt.html when building/running http://hg.mozilla.org/mozilla-central/index.cgi/rev/7a6071857512

First run - fail: http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1236565924.1236574299.16251.gz
rev:7a6071857512

Following run - pass: http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1236566505.1236571944.11107.gz
rev:7a6071857512
Adding CC: beltzner because he seems interested in [orange].
Whiteboard: [orange]
The end of subtest 1003's handleLoad() sets an iframe src to a URL that triggers an authentication prompt. Then subtest 1004's handleDialog() finds the prompt, verifies its contents, and clicks OK.

The next expected thing to happen should be a "load" event firing from the iframe (triggering handleLoad again). This never happens, and so the test times out.

It would be interesting to know if this test_prompt.html has ever failed before (first I've heard of it). This particular subtest was added 5 months ago in bug 394611, but it's just cut'n'paste of other subtests that are ~12 months old.

IIRC, I've seen various other tests in the tree fail due to onload not firing; I wonder if there's a common bug somewhere. I don't see anything else to look at in this test or password manager code, unfortunately.
Blocks: 438871
This happened a bunch today (all on Linux mochitest boxes):
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1254172936.1254175535.12805.gz
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1254171028.1254173685.24517.gz
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1254172373.1254175527.12761.gz
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1254169763.1254173049.17329.gz
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1254169523.1254172494.11086.gz

The actual errors for context:
91646 ERROR TEST-UNEXPECTED-FAIL | /tests/toolkit/components/passwordmgr/test/test_prompt.html | focus correct for test10 - got [object XULElement], expected [object HTMLInputElement]
91653 ERROR TEST-UNEXPECTED-FAIL | /tests/toolkit/components/passwordmgr/test/test_prompt.html | Checking dialog return value (cancel)
91695 ERROR TEST-UNEXPECTED-FAIL | /tests/toolkit/components/passwordmgr/test/test_prompt.html | Checking dialog return value (cancel)
91761 ERROR TEST-UNEXPECTED-FAIL | /tests/toolkit/components/passwordmgr/test/test_prompt.html | Checking dialog return value (cancel)
(In reply to comment #3)
> This happened a bunch today (all on Linux mochitest boxes):

Disregard comment 3 -- those failures don't appear to be intermittent -- it looks like they were all caused by this checkin:
  http://hg.mozilla.org/mozilla-central/rev/29e8f7716f6d
Neil's currently backing this changeset out, to fix those.
This bug is worthless: nobody can know what the first failure was, the second failure was a freshly landed regression that we missed, the third failure might have been another different freshly landed regression, and the fourth failure is clearly a different freshly landed regression. I'm killing this, and erasing its tracks, so the next person who sees a failure in test_prompt.html will have to accept that it's not some generic "failure of".
No longer blocks: 438871
Status: NEW → RESOLVED
Closed: 14 years ago
Resolution: --- → INCOMPLETE
Whiteboard: [orange]
And I'm going to reopen and make it about what the last five comments are about, since they are a useful bug.

bent, I think you should back out to see if you're the cause of the new failure here
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Summary: Intermittent failure of test_prompt.html → Intermittent failure of test_prompt.html: An error occurred - uncaught exception: No matching logins at :0
I don't think bent's stuff, indexedDB isn't used by password manager.

Looks like this error can only be thrown when trying to remove or modify a login whose specification does not match anything in the DB. But I'm not sure what would cause this to happen intermittently. It's failing in test_prompt.html's finishTest(), where it cleans up logins added during the test.

Might help to debug in the tree, by having this function dump out details of every login stored in pwmgr, and the contents of every login it's trying to delete (lest memory corruption be causing problems?).
I was going to claim that Bug Numbers Are Cheap and this bug while having to ignore comments 0 through 8 didn't offer anything that a new one wouldn't, but then I realized that that fan of [orange] in March 2009, beltzner, is cc'ed, so I guess it does.
Blocks: 438871
Status: REOPENED → NEW
Whiteboard: [orange]
I added a bit of debugging to try and narrow down what exactly is failing: http://hg.mozilla.org/mozilla-central/rev/dca6eff8d8a0

This should pin down which login removal is failing, which might help with understanding why it's randomly failing.
Whiteboard: [orange] → [orange][debugging, see comment 16 and 101]
Hmm, looking at the logging added in comment 101, most of the recent logs seem to error out before recording the extra logging. Maybe it's lost to buffering? Maybe it's being thrown somewhere earlier? But one log had it:

5295 INFO TEST-PASS | /tests/toolkit/components/passwordmgr/test/test_prompt.html | Looking for action at index 0
5296 INFO TEST-PASS | /tests/toolkit/components/passwordmgr/test/test_prompt.html | at least one notification displayed
5297 INFO TEST-PASS | /tests/toolkit/components/passwordmgr/test/test_prompt.html | 1 notifications
5298 INFO TEST-PASS | /tests/toolkit/components/passwordmgr/test/test_prompt.html | Triggering main action
5299 INFO TEST-PASS | /tests/toolkit/components/passwordmgr/test/test_prompt.html | finishTest removing testing logins...
5300 INFO TEST-PASS | /tests/toolkit/components/passwordmgr/test/test_prompt.html | currently have 9 logins.
5301 INFO TEST-PASS | /tests/toolkit/components/passwordmgr/test/test_prompt.html | removing login 2A...
5302 INFO TEST-PASS | /tests/toolkit/components/passwordmgr/test/test_prompt.html | removing login 2B...
5303 INFO TEST-PASS | /tests/toolkit/components/passwordmgr/test/test_prompt.html | removing login 2C...
5304 INFO TEST-PASS | /tests/toolkit/components/passwordmgr/test/test_prompt.html | removing login 2D...
5305 INFO TEST-PASS | /tests/toolkit/components/passwordmgr/test/test_prompt.html | removing login 2E...
5306 INFO TEST-PASS | /tests/toolkit/components/passwordmgr/test/test_prompt.html | removing login 3A...
5307 INFO TEST-PASS | /tests/toolkit/components/passwordmgr/test/test_prompt.html | removing login 3B...
5308 INFO TEST-PASS | /tests/toolkit/components/passwordmgr/test/test_prompt.html | removing login 4...
5309 ERROR TEST-UNEXPECTED-FAIL | /tests/toolkit/components/passwordmgr/test/test_prompt.html

So, that implies it's failing to remove login4, or else the ok(true, "removing proxyLogin..."); and ok(true, "whee, done!"); lines would have output something.
Indeed, a green run has "currently have 10 logins", so we're ending up 1 login short.

The login is being changed and then re-added in the tests at the end of the run. I bet there's something async about clicking the button (or we're not waiting for the doorhanger popup properly?).
Attached patch Patch v.1 (obsolete) (deleted) — — Splinter Review 
Let's see if this fixes the problem.

Pushed as http://hg.mozilla.org/mozilla-central/rev/bb01ede65782
Assignee: nobody → dolske
The recent logs show these logs:

handleLoad running for test 1003
handleDialog was invoked
Checking for successful authentication - "PASS" should equal "PASS"
Checking for echoed username - "mochiuser1" should equal "mochiuser1"
Checking for echoed password - "mochipass1-new" should equal "mochipass1-new"
Looking for password-change popup notification
got popup notification
Looking for action at index 0
at least one notification displayed
1 notifications
Triggering main action

followed the the exception in the title.
Pushed the attachment from comment 292 as http://hg.mozilla.org/mozilla-central/rev/b1b6968c3054.  Maybe we'll start getting another set of different failures now!
Whiteboard: [orange][debugging, see comment 16 and 101] → [orange][debugging, see comments 16, 101 and 291]
Triggering main action
handleDialog running for test 1004
Checking filled username - "mochiuser3" should equal "mochiuser3"
Checking filled password - "mochipass3-old" should equal "mochipass3-old"
handleDialog done
handleLoad running for test 1004
handleDialog was invoked
Checking for successful authentication - "PASS" should equal "PASS"
Checking for echoed username - "mochiuser3" should equal "mochiuser3"
Checking for echoed password - "mochipass3-new" should equal "mochipass3-new"
Looking for password-change popup notification
got popup notification
Looking for action at index 0
at least one notification displayed
1 notifications
Triggering main action
[SimpleTest/SimpleTest.js, window.onerror] An error occurred - uncaught exception: No matching logins at :0

My patch did make a difference - we've now moved on to the next test, which is supposedly addressed by dolske's earlier patch.  Unfortunately, it apparently isn't addressed properly.
I've got a plan of attack for this.  The setTimeout hack is obviously just that; instead, we should be observing passwordmgr-storage-changed notifications and executing the callbacks then instead.  I'll put together a patch and throw it at tryserver tomorrow.
Whiteboard: [orange][debugging, see comments 16, 101 and 291] → [orange][debugging, see comments 16, 101, 291 and 353]
Attachment #478151 - Attachment is obsolete: true
Attachment #483971 - Attachment is obsolete: true
A try run has shown no problems with these changes, but I'd like to get somebody's agreement that they're sensible before I put them in the tree.
Attachment #486429 - Flags: review?(dolske)
Attachment #486429 - Flags: review?(dolske) → review+
Comment on attachment 486429 [details] [diff] [review]
Rely on password manager notifications instead of timeouts in tests.

This should resolve our orange woes with this bug, which plagues us numerous times per day.
Attachment #486429 - Flags: approval2.0?
Attachment #486429 - Flags: approval2.0?
http://hg.mozilla.org/mozilla-central/rev/ce1801c6ba95

If we see any further instances on m-c after this push, please reopen.
Status: NEW → RESOLVED
Closed: 14 years ago → 14 years ago
Resolution: --- → FIXED
I've filed bug 608206 on the new intermittent time out that's cropped up :(
Blocks: 608206
Whiteboard: [orange][debugging, see comments 16, 101, 291 and 353] → [debugging, see comments 16, 101, 291 and 353]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: