Closed Bug 1292735 Opened 6 years ago Closed 5 years ago

Intermittent dom/xhr/tests/test_worker_xhr_timeout.html | load fires normally with same timeout set twice, original timeout at 5000, reset at 2000 to 5000 - got "timeout", expected "load"

Categories

(Core :: DOM: Core & HTML, defect, P3)

defect

Tracking

()

RESOLVED FIXED

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell fixed])

Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.
Priority: -- → P3
This test started failing frequently, on Android Debug only, on March 7. 

Comment 6 suggests this is a regression from bug 1333799, but I don't see an immediate connection between that change and this test. On the other hand, bug 1335751 is just 2 changesets earlier, and that caused a significant reduction in performance in several other tests on Android Debug. I'll dig deeper on try.
Flags: needinfo?(gbrown)
I notice that almost all the current failures are slightly different from the bug title.

https://public-artifacts.taskcluster.net/feXG20e8TW6VWHBzi1oEBQ/0/public/logs/live_backing.log seems typical:


[task 2017-03-09T05:32:58.582416Z] 05:32:58     INFO -  145 INFO TEST-START | dom/xhr/tests/test_worker_xhr_timeout.html
[task 2017-03-09T05:34:22.859130Z] 05:34:22     INFO -  Buffered messages logged at 05:33:10
[task 2017-03-09T05:34:22.859251Z] 05:34:22     INFO -  146 INFO TEST-PASS | dom/xhr/tests/test_worker_xhr_timeout.html | no time out scheduled, load fires normally, timeout scheduled at 0
[task 2017-03-09T05:34:22.859306Z] 05:34:22     INFO -  Buffered messages logged at 05:33:19
[task 2017-03-09T05:34:22.859369Z] 05:34:22     INFO -  147 INFO TEST-PASS | dom/xhr/tests/test_worker_xhr_timeout.html | load fires normally, timeout scheduled at 5000
[task 2017-03-09T05:34:22.859413Z] 05:34:22     INFO -  Buffered messages logged at 05:33:28
[task 2017-03-09T05:34:22.859487Z] 05:34:22     INFO -  148 INFO TEST-PASS | dom/xhr/tests/test_worker_xhr_timeout.html | timeout hit before load, timeout scheduled at 2000
[task 2017-03-09T05:34:22.859541Z] 05:34:22     INFO -  Buffered messages logged at 05:33:36
[task 2017-03-09T05:34:22.860653Z] 05:34:22     INFO -  149 INFO TEST-PASS | dom/xhr/tests/test_worker_xhr_timeout.html | load fires normally with no timeout set, twice, original timeout at 0, reset at 2000 to 0
[task 2017-03-09T05:34:22.861298Z] 05:34:22     INFO -  Buffered messages logged at 05:33:48
[task 2017-03-09T05:34:22.862602Z] 05:34:22     INFO -  150 INFO TEST-PASS | dom/xhr/tests/test_worker_xhr_timeout.html | load fires normally with same timeout set twice, original timeout at 5000, reset at 2000 to 5000
[task 2017-03-09T05:34:22.862652Z] 05:34:22     INFO -  Buffered messages logged at 05:33:55
[task 2017-03-09T05:34:22.862705Z] 05:34:22     INFO -  151 INFO TEST-PASS | dom/xhr/tests/test_worker_xhr_timeout.html | timeout fires normally with same timeout set twice, original timeout at 2000, reset at 1000 to 2000
[task 2017-03-09T05:34:22.862729Z] 05:34:22     INFO -  Buffered messages logged at 05:34:03
[task 2017-03-09T05:34:22.863055Z] 05:34:22     INFO -  152 INFO TEST-PASS | dom/xhr/tests/test_worker_xhr_timeout.html | timeout disabled after initially set, original timeout at 5000, reset at 2000 to 0
[task 2017-03-09T05:34:22.863247Z] 05:34:22     INFO -  Buffered messages finished
[task 2017-03-09T05:34:22.863725Z] 05:34:22     INFO -  153 INFO TEST-UNEXPECTED-FAIL | dom/xhr/tests/test_worker_xhr_timeout.html | timeout overrides load after a delay, original timeout at 5000, reset at 1000 to 2000 - got "load", expected "timeout"
[task 2017-03-09T05:34:22.864140Z] 05:34:22     INFO -      SimpleTest.is@SimpleTest/SimpleTest.js:310:5
[task 2017-03-09T05:34:22.864602Z] 05:34:22     INFO -      @dom/xhr/tests/test_worker_xhr_timeout.html:38:7
[task 2017-03-09T05:34:33.298888Z] 05:34:33     INFO -  154 INFO TEST-PASS | dom/xhr/tests/test_worker_xhr_timeout.html | timeout enabled after initially disabled, original timeout at 0, reset at 2000 to 5000
[task 2017-03-09T05:34:33.299321Z] 05:34:33     INFO -  155 INFO TEST-PASS | dom/xhr/tests/test_worker_xhr_timeout.html | timeout set to expiring value after load fires, original timeout at 5000, reset at 4000 to 1000
[task 2017-03-09T05:34:43.744093Z] 05:34:43     INFO -  156 INFO TEST-UNEXPECTED-FAIL | dom/xhr/tests/test_worker_xhr_timeout.html | timeout set to expired value before load fires, original timeout at 5000, reset at 2000 to 1000 - got "load", expected "timeout"
[task 2017-03-09T05:34:43.744261Z] 05:34:43     INFO -      SimpleTest.is@SimpleTest/SimpleTest.js:310:5
[task 2017-03-09T05:34:43.744555Z] 05:34:43     INFO -      @dom/xhr/tests/test_worker_xhr_timeout.html:38:7
[task 2017-03-09T05:34:54.182224Z] 05:34:54     INFO -  157 INFO TEST-PASS | dom/xhr/tests/test_worker_xhr_timeout.html | timeout set to non-expiring value after timeout fires, original timeout at 1000, reset at 2000 to 5000
[task 2017-03-09T05:35:04.629524Z] 05:35:04     INFO -  158 INFO TEST-PASS | dom/xhr/tests/test_worker_xhr_timeout.html | No events should fire for an unsent, unaborted request
[task 2017-03-09T05:35:04.629828Z] 05:35:04     INFO -  159 INFO TEST-PASS | dom/xhr/tests/test_worker_xhr_timeout.html | time to abort is -1, timeout set at 2000
[task 2017-03-09T05:35:15.067413Z] 05:35:15     INFO -  160 INFO TEST-PASS | dom/xhr/tests/test_worker_xhr_timeout.html | time to abort is 5000, timeout set at 2000
[task 2017-03-09T05:35:25.514409Z] 05:35:25     INFO -  161 INFO TEST-PASS | dom/xhr/tests/test_worker_xhr_timeout.html | no time out scheduled, load fires normally, timeout scheduled at 0
[task 2017-03-09T05:35:25.514699Z] 05:35:25     INFO -  162 INFO TEST-PASS | dom/xhr/tests/test_worker_xhr_timeout.html | load fires normally, timeout scheduled at 5000
[task 2017-03-09T05:35:35.961767Z] 05:35:35     INFO -  163 INFO TEST-PASS | dom/xhr/tests/test_worker_xhr_timeout.html | timeout hit before load, timeout scheduled at 2000
[task 2017-03-09T05:35:46.507350Z] 05:35:46     INFO -  164 INFO TEST-OK | dom/xhr/tests/test_worker_xhr_timeout.html | took 159587ms


Current failures have 

'...original timeout at 5000, reset at 2000 to 1000 - got "load", expected "timeout"'

rather than 

'...original timeout at 5000, reset at 2000 to 5000 - got "timeout", expected "load"', as in bug title.
(In reply to Geoff Brown [:gbrown] from comment #7)
> This test started failing frequently, on Android Debug only, on March 7. 
> 
> Comment 6 suggests this is a regression from bug 1333799, but I don't see an
> immediate connection between that change and this test. On the other hand,
> bug 1335751 is just 2 changesets earlier, and that caused a significant
> reduction in performance in several other tests on Android Debug. I'll dig
> deeper on try.

https://treeherder.mozilla.org/#/jobs?repo=try&author=gbrown@mozilla.com&tochange=e12db62debf5e2af25420f380ccc49ec19768123&fromchange=2b2c5003626c5e65db7db8815a0c04ae87d696ed

Failures persist if I backout bug 1333799, but I get a green run if I backout bug 1335751.
Blocks: 1335751
:sfink is working on a few other bugs related to this, this will most likely get fixed when a fix is in place.
Whiteboard: [stockwell needswork]
(In reply to Joel Maher ( :jmaher) from comment #11)
> :sfink is working on a few other bugs related to this, this will most likely
> get fixed when a fix is in place.

Actually, after bug 1284763 comment 13 I wasn't. But this bug seems like it may require more than just making more chunks and/or increasing timeouts.

Bug 1346874 should resolve this (or at least, return it back to its previous frequency.)
Depends on: 1346874
this is still a problem, we started up on March 7th and the frequency is cut down about 1/3, but that is still too often.
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Whiteboard: [stockwell needswork] → [stockwell fixed]
Component: DOM → DOM: Core & HTML
You need to log in before you can comment on or make changes to this bug.