Open Bug 942543 Opened 7 years ago Updated 3 years ago

Mochitest failures claiming that a test which has finished timed out four times, followed by "4 test timeouts, giving up"

Categories

(Testing :: Mochitest, defect)

defect
Not set
major

Tracking

(firefox27 affected, firefox28 affected, firefox29 affected)

Tracking Status
firefox27 --- affected
firefox28 --- affected
firefox29 --- affected

People

(Reporter: philor, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, regression)

Destroying a run because a test which had already finished "timed out" after it finished, four times over, is naughty.

I know of bug 942522, bug 942527, bug 934052 and https://tbpl.mozilla.org/php/getParsedLog.php?id=31016598&tree=Mozilla-Inbound, but there are undoubtedly others where we didn't put the "4 test timeouts, giving up" in the summary, and undoubtedly more that we didn't file.

22:28:33     INFO -  12647 INFO TEST-END | /tests/content/base/test/test_bug368972.html | finished in 154ms
(screenshot)
22:33:44     INFO -  12648 ERROR TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug368972.html | Test timed out.
22:33:44     INFO -  12649 ERROR TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug368972.html | [SimpleTest.finish()] this test already called finish!
22:33:44     INFO -  12650 ERROR TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug368972.html | called finish() multiple times
22:34:13     INFO -  Not taking screenshot here: see the one that was previously logged
22:34:13     INFO -  12651 ERROR TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug368972.html | Test timed out.
22:34:14     INFO -  12652 ERROR TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug368972.html | [SimpleTest.finish()] this test already called finish!
22:34:14     INFO -  12653 ERROR TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug368972.html | called finish() multiple times
22:34:43     INFO -  Not taking screenshot here: see the one that was previously logged
22:34:43     INFO -  12654 ERROR TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug368972.html | Test timed out.
22:34:44     INFO -  12655 ERROR TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug368972.html | [SimpleTest.finish()] this test already called finish!
22:34:44     INFO -  12656 ERROR TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug368972.html | called finish() multiple times
22:35:13     INFO -  Not taking screenshot here: see the one that was previously logged
22:35:13     INFO -  12657 ERROR TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug368972.html | Test timed out.
22:35:13     INFO -  12658 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up.
22:35:13     INFO -  12659 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 1163 remaining tests.
22:35:14     INFO -  12660 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | [SimpleTest.finish()] this test already called finish!
22:35:14     INFO -  12661 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | called finish() multiple times
22:40:44  WARNING -  TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug368972.html | application timed out after 330 seconds with no output
22:40:44     INFO -  Not taking screenshot here: see the one that was previously logged
22:40:46  WARNING -  TEST-UNEXPECTED-FAIL | /tests/content/base/test/test_bug368972.html | application terminated with exit code 3221225477
Duplicate of this bug: 942522
Duplicate of this bug: 942527
Duplicate of this bug: 934052
Duplicate of this bug: 919361
Duplicate of this bug: 919363
Duplicate of this bug: 942517
Duplicate of this bug: 940209
Duplicate of this bug: 936809
Duplicate of this bug: 936296
Duplicate of this bug: 936282
Duplicate of this bug: 934055
Duplicate of this bug: 927758
Duplicate of this bug: 931644
Duplicate of this bug: 921197
So, started in late September?
Blocks: 746243
Keywords: regression
Flags: needinfo?(jhammel)
Flags: needinfo?(jhammel)
So, just eyeballing the logs, it's hard to see how this would be caused by bug 746243, since all the errors are local to the JS harness.  But, I've learned never to say 'never'.
Sorry, didn't mean to cancel this flag
Flags: needinfo?(jhammel)
(In reply to Jonathan Griffin (:jgriffin) from comment #18)
> So, just eyeballing the logs, it's hard to see how this would be caused by
> bug 746243, since all the errors are local to the JS harness.  But, I've
> learned never to say 'never'.

I'm guessing that since these occur following screenshot output that it is a strong possibility that this is a harness problem, likely a regression from bug 746243.  since all of these are mac, likely a mac peculiarity? :/
Flags: needinfo?(jhammel)
Duplicate of this bug: 947155
Poor little Android tried so hard, but https://tbpl.mozilla.org/php/getParsedLog.php?id=31660807&tree=Mozilla-Inbound only managed three timeouts in a test which had already finished before it blew up, rather than four.
I'll take a stab at this one.
Assignee: nobody → dminor
Must be possible for a test to contribute to this, or we're conflating some separate bustage with this, since the bulk of the recent ones are b2g emulator mochitest-7 hitting this in dom/inputmethod/mochitest/test_sendkey_cancel.html.

https://tbpl.mozilla.org/php/getParsedLog.php?id=35842548&tree=B2g-Inbound
Though https://tbpl.mozilla.org/php/getParsedLog.php?id=35843090&tree=B2g-Inbound is the same suite, but dom/inputmethod/mochitest/test_delete_focused_element.html, so dunno.
Blocks: 983015
I haven't looked at this in close to 18 months and it's unlikely I'll find time in the foreseeable future.
Assignee: dminor → nobody
This is still happening over in bug 1421775, so far entirely on OSX 10.10 debug.
See Also: → 1421775
You need to log in before you can comment on or make changes to this bug.