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"

RESOLVED FIXED

Status

()

P3
normal
RESOLVED FIXED
2 years ago
10 months ago

People

(Reporter: intermittent-bug-filer, Unassigned)

Tracking

({intermittent-failure})

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [stockwell fixed])

Comment 1

2 years ago
Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.
Priority: -- → P3
10 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 5
* autoland: 5

Platform breakdown:
* linux64: 10

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1292735&startday=2016-10-03&endday=2016-10-09&tree=all
10 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 5
* autoland: 4
* graphics: 1

Platform breakdown:
* android-4-3-armv7-api15: 10

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1292735&startday=2016-11-07&endday=2016-11-13&tree=all
16 failures in 715 pushes (0.022 failures/push) were associated with this bug in the last 7 days.  

Repository breakdown:
* mozilla-inbound: 8
* autoland: 7
* try: 1

Platform breakdown:
* android-4-3-armv7-api15: 16

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1292735&startday=2016-11-14&endday=2016-11-20&tree=all
10 failures in 623 pushes (0.016 failures/push) were associated with this bug in the last 7 days.  

Repository breakdown:
* autoland: 5
* mozilla-inbound: 2
* mozilla-aurora: 2
* mozilla-beta: 1

Platform breakdown:
* android-4-3-armv7-api15: 9
* linux64: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1292735&startday=2016-11-21&endday=2016-11-27&tree=all
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
26 failures in 137 pushes (0.19 failures/push) were associated with this bug yesterday.  
Repository breakdown:
* autoland: 15
* mozilla-inbound: 8
* mozilla-central: 2
* graphics: 1

Platform breakdown:
* android-4-3-armv7-api15: 26

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1292735&startday=2017-03-09&endday=2017-03-09&tree=all
: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]
27 failures in 172 pushes (0.157 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* autoland: 13
* mozilla-inbound: 9
* try: 2
* mozilla-central: 2
* graphics: 1

Platform breakdown:
* android-4-3-armv7-api15: 27

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1292735&startday=2017-03-10&endday=2017-03-10&tree=all
67 failures in 790 pushes (0.085 failures/push) were associated with this bug in the last 7 days. 

This is the #30 most frequent failure this week.  

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. ** 

Repository breakdown:
* autoland: 31
* mozilla-inbound: 23
* mozilla-central: 6
* graphics: 4
* try: 2
* oak: 1

Platform breakdown:
* android-4-3-armv7-api15: 67

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1292735&startday=2017-03-06&endday=2017-03-12&tree=all
(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.
24 failures in 777 pushes (0.031 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* autoland: 12
* mozilla-inbound: 7
* mozilla-central: 2
* graphics: 2
* try: 1

Platform breakdown:
* android-4-3-armv7-api15: 24

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1292735&startday=2017-03-13&endday=2017-03-19&tree=all
Status: NEW → RESOLVED
Last Resolved: 2 years ago
Resolution: --- → FIXED
Whiteboard: [stockwell needswork] → [stockwell fixed]
1 failures in 792 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 1

Platform breakdown:
* android-4-3-armv7-api16: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1292735&startday=2017-11-27&endday=2017-12-03&tree=all
You need to log in before you can comment on or make changes to this bug.