Closed Bug 1319306 Opened 6 years ago Closed 6 years ago

Intermittent /XMLHttpRequest/event-readystatechange-loaded.htm | XMLHttpRequest: the LOADING state change may be emitted multiple times - assert_equals: LOADING state change may be emitted multiple times expected 10 but got 9

Categories

(Testing :: web-platform-tests, defect)

Product:
Testing
Component:
web-platform-tests
Version:
Version 3
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox52 unaffected, firefox-esr52 unaffected, firefox53 fixed, firefox54 fixed, firefox55 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla55
Tracking Flags:
Tracking Status
firefox52 --- unaffected
firefox-esr52 --- unaffected
firefox53 --- fixed
firefox54 --- fixed
firefox55 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: shawnjohnjr)

References

Details

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

Attachments

(2 files, 2 obsolete files)

http.log.gz
92.80 KB, application/gzip
Details
Bug 1319306 - Change onreadystatechange assertion to a minimum of 2 rather than 10, r=annevk
1.21 KB, patch
Details | Diff | Splinter Review 
this bug has crossed our threshold of 30 failures for the week and we want to get this resolved in the next 2 weeks.

this is primarily linux32-debug wpt-9.


from this log[0], I see this in the output:
[task 2017-02-05T01:44:23.974371Z] 01:44:23     INFO - TEST-START | /XMLHttpRequest/event-readystatechange-loaded.htm
[task 2017-02-05T01:44:24.107580Z] 01:44:24     INFO - PROCESS | 1113 | ++DOCSHELL 0xcd377800 == 5 [pid = 1166] [id = {3d933a41-5b4f-4337-b023-973d01061f96}]
[task 2017-02-05T01:44:24.108294Z] 01:44:24     INFO - PROCESS | 1113 | ++DOMWINDOW == 71 (0xcd378400) [pid = 1166] [serial = 83] [outer = (nil)]
[task 2017-02-05T01:44:24.168908Z] 01:44:24     INFO - PROCESS | 1113 | ++DOMWINDOW == 72 (0xcd37fc00) [pid = 1166] [serial = 84] [outer = 0xcd378400]
[task 2017-02-05T01:44:24.249944Z] 01:44:24     INFO - PROCESS | 1113 | ++DOMWINDOW == 73 (0xcd3ce800) [pid = 1166] [serial = 85] [outer = 0xcd378400]
[task 2017-02-05T01:44:26.690499Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 72 (0xce75d800) [pid = 1166] [serial = 65] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/event-error.sub.html]
[task 2017-02-05T01:44:26.690620Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 71 (0xce760000) [pid = 1166] [serial = 59] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/event-abort.htm]
[task 2017-02-05T01:44:26.690698Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 70 (0xcd3d2c00) [pid = 1166] [serial = 68] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/event-load.htm]
[task 2017-02-05T01:44:26.690808Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 69 (0xcd373800) [pid = 1166] [serial = 62] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/event-error-order.sub.html]
[task 2017-02-05T01:44:26.690898Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 68 (0xce8e3800) [pid = 1166] [serial = 26] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/abort-during-open.worker.html]
[task 2017-02-05T01:44:26.691003Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 67 (0xcc9d7c00) [pid = 1166] [serial = 71] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/event-loadend.htm]
[task 2017-02-05T01:44:26.691089Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 66 (0xce7ae400) [pid = 1166] [serial = 23] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/abort-during-open.htm]
[task 2017-02-05T01:44:26.691210Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 65 (0xcd9a5400) [pid = 1166] [serial = 44] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/abort-event-order.htm]
[task 2017-02-05T01:44:26.691331Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 64 (0xcf1b3000) [pid = 1166] [serial = 32] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/abort-during-upload.htm]
[task 2017-02-05T01:44:26.691552Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 63 (0xce80cc00) [pid = 1166] [serial = 47] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/abort-upload-event-abort.htm]
[task 2017-02-05T01:44:26.692368Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 62 (0xcda61000) [pid = 1166] [serial = 20] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/abort-during-done.htm]
[task 2017-02-05T01:44:26.692846Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 61 (0xdcc09000) [pid = 1166] [serial = 35] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/abort-event-abort.htm]
[task 2017-02-05T01:44:26.693336Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 60 (0xcfc77c00) [pid = 1166] [serial = 50] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/abort-upload-event-loadend.htm]
[task 2017-02-05T01:44:26.693756Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 59 (0xcd9a5c00) [pid = 1166] [serial = 17] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/abort-after-timeout.htm]
[task 2017-02-05T01:44:26.694322Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 58 (0xcd9b4400) [pid = 1166] [serial = 14] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/abort-after-stop.htm]
[task 2017-02-05T01:44:26.694812Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 57 (0xdd619c00) [pid = 1166] [serial = 38] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/abort-event-listeners.htm]
[task 2017-02-05T01:44:26.695299Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 56 (0xcd66c400) [pid = 1166] [serial = 41] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/abort-event-loadend.htm]
[task 2017-02-05T01:44:26.695979Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 55 (0xce8eec00) [pid = 1166] [serial = 29] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/abort-during-unsent.htm]
[task 2017-02-05T01:44:26.696460Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 54 (0xcd00a800) [pid = 1166] [serial = 53] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/anonymous-mode-unsupported.htm]
[task 2017-02-05T01:44:26.696971Z] 01:44:26     INFO - PROCESS | 1113 | --DOMWINDOW == 53 (0xce915400) [pid = 1166] [serial = 56] [outer = (nil)] [url = http://web-platform.test:8000/XMLHttpRequest/data-uri.htm]
[task 2017-02-05T01:44:29.579397Z] 01:44:29     INFO - PROCESS | 1113 | --DOCSHELL 0xcc9d7800 == 4 [pid = 1166] [id = {1e932f91-cd23-458f-861d-f5e53124dfc1}]
[task 2017-02-05T01:44:29.580188Z] 01:44:29     INFO - PROCESS | 1113 | --DOCSHELL 0xcc507000 == 3 [pid = 1166] [id = {f58673b2-738f-48f4-8102-2805a60681bd}]
[task 2017-02-05T01:44:29.581414Z] 01:44:29     INFO - PROCESS | 1113 | --DOCSHELL 0xcd005c00 == 2 [pid = 1166] [id = {cb070033-7d64-406a-be16-3036623a309c}]
[task 2017-02-05T01:44:29.582170Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 52 (0xcc9da800) [pid = 1166] [serial = 72] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.582825Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 51 (0xcc9de000) [pid = 1166] [serial = 73] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.583514Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 50 (0xcd3d7c00) [pid = 1166] [serial = 69] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.584027Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 49 (0xcd3d9c00) [pid = 1166] [serial = 70] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.584734Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 48 (0xcd3cc000) [pid = 1166] [serial = 66] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.585440Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 47 (0xcd3cf400) [pid = 1166] [serial = 67] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.586138Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 46 (0xcd37a400) [pid = 1166] [serial = 63] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.586792Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 45 (0xcd37cc00) [pid = 1166] [serial = 64] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.587376Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 44 (0xce762800) [pid = 1166] [serial = 60] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.588053Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 43 (0xcfc73c00) [pid = 1166] [serial = 61] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.588751Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 42 (0xcec72c00) [pid = 1166] [serial = 57] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.589387Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 41 (0xcf14e400) [pid = 1166] [serial = 58] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.589848Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 40 (0xcd00d000) [pid = 1166] [serial = 54] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.590160Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 39 (0xcd00f000) [pid = 1166] [serial = 55] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.590445Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 38 (0xdcc2b400) [pid = 1166] [serial = 51] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.591181Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 37 (0xdd88d400) [pid = 1166] [serial = 52] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.591298Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 36 (0xce8ec800) [pid = 1166] [serial = 48] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.591498Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 35 (0xcece1400) [pid = 1166] [serial = 49] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.591812Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 34 (0xcdbb0800) [pid = 1166] [serial = 45] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.592089Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 33 (0xcdbbac00) [pid = 1166] [serial = 46] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.592833Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 32 (0xcd66f000) [pid = 1166] [serial = 42] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.592915Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 31 (0xcd66e400) [pid = 1166] [serial = 43] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.593013Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 30 (0xf71c6800) [pid = 1166] [serial = 39] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.593244Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 29 (0xcd665400) [pid = 1166] [serial = 40] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.593698Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 28 (0xdcc28c00) [pid = 1166] [serial = 36] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.593944Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 27 (0xdcc30800) [pid = 1166] [serial = 37] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.594179Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 26 (0xcfba3400) [pid = 1166] [serial = 33] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.594477Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 25 (0xcfc78000) [pid = 1166] [serial = 34] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.594728Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 24 (0xcece4800) [pid = 1166] [serial = 30] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.595012Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 23 (0xcece7800) [pid = 1166] [serial = 31] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.595267Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 22 (0xce8e9800) [pid = 1166] [serial = 27] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.595561Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 21 (0xce8ed000) [pid = 1166] [serial = 28] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.596119Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 20 (0xce7b3000) [pid = 1166] [serial = 24] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.596432Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 19 (0xce802000) [pid = 1166] [serial = 25] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.596704Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 18 (0xcdbb8c00) [pid = 1166] [serial = 21] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.597004Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 17 (0xcdbbc400) [pid = 1166] [serial = 22] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.597282Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 16 (0xcda54c00) [pid = 1166] [serial = 18] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.597727Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 15 (0xcda5fc00) [pid = 1166] [serial = 19] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.597957Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 14 (0xcd704400) [pid = 1166] [serial = 16] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:29.598276Z] 01:44:29     INFO - PROCESS | 1113 | --DOMWINDOW == 13 (0xcc503000) [pid = 1166] [serial = 75] [outer = (nil)] [url = about:blank]
[task 2017-02-05T01:44:30.506796Z] 01:44:30     INFO - 
[task 2017-02-05T01:44:30.507426Z] 01:44:30     INFO - TEST-UNEXPECTED-FAIL | /XMLHttpRequest/event-readystatechange-loaded.htm | XMLHttpRequest: the LOADING state change may be emitted multiple times - assert_equals: LOADING state change may be emitted multiple times expected 10 but got 9
[task 2017-02-05T01:44:30.507933Z] 01:44:30     INFO - client.onreadystatechange<@http://web-platform.test:8000/XMLHttpRequest/event-readystatechange-loaded.htm:29:13
[task 2017-02-05T01:44:30.508367Z] 01:44:30     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1406:20
[task 2017-02-05T01:44:30.508717Z] 01:44:30     INFO - Test.prototype.step_func/<@http://web-platform.test:8000/resources/testharness.js:1430:20
[task 2017-02-05T01:44:30.509102Z] 01:44:30     INFO - EventHandlerNonNull*@http://web-platform.test:8000/XMLHttpRequest/event-readystatechange-loaded.htm:23:33
[task 2017-02-05T01:44:30.509500Z] 01:44:30     INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1406:20
[task 2017-02-05T01:44:30.509907Z] 01:44:30     INFO - @http://web-platform.test:8000/XMLHttpRequest/event-readystatechange-loaded.htm:19:1
[task 2017-02-05T01:44:30.510428Z] 01:44:30     INFO - TEST-OK | /XMLHttpRequest/event-readystatechange-loaded.htm | took 6533ms


:Ms2ger, I see your name in the owners file, can you help find someone to look at this?  Our goal is to get this figured out in the next 2 weeks. also if you know what component to move this to, it would be better to use that in bugzilla than testing::web-platform-tests


[0] https://public-artifacts.taskcluster.net/A5xGF3eDRZOWgJsPG0165g/0/public/logs/live_backing.log
Flags: needinfo?(Ms2ger)
this has greatly reduced.
Flags: needinfo?(Ms2ger)
Whiteboard: [stockwell unknown]
If i will investigate this intermittent bug. If anyone knows the solution, feel free to take this bug.
Assignee: nobody → shuang
Thanks Shawn, this bug has picked up the frequency since March 5th.
Whiteboard: [stockwell unknown] → [stockwell needswork]
Running this test case in chaos mode, I can hit the problem.
 
2:13.66 TEST_END: Thread-TestrunnerManager-1 Harness OK. Subtests passed 0/1. Unexpected 1
XMLHttpRequest: the LOADING state change may be emitted multiple times
----------------------------------------------------------------------
Expected PASS, got FAIL
assert_equals: LOADING state change may be emitted multiple times expected 10 but got 6
client.onreadystatechange<@http://web-platform.test:8000/XMLHttpRequest/event-readystatechange-loaded.htm:29:13
Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1409:20
Test.prototype.step_func/<@http://web-platform.test:8000/resources/testharness.js:1433:20
EventHandlerNonNull*@http://web-platform.test:8000/XMLHttpRequest/event-readystatechange-loaded.htm:23:33
Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1409:20
@http://web-platform.test:8000/XMLHttpRequest/event-readystatechange-loaded.htm:19:1
OnStopRequest called then ChangeStateToDone called. So changing state to DONE seems to be normal. I'm wondering OnStopRequest is unexpected or not.
Checking network log, the first time OnDataAvailable count =26.

2017-03-14 09:26:02.352314 UTC - [Main Thread]: D/nsHttp Preparing to write data into the cache [uri=http://web-platform.test:8000/XMLHttpRequest/resources/trickle.py?count=10]
2017-03-14 09:26:02.352322 UTC - [Main Thread]: D/nsHttp Trading cache input stream for output stream [channel=0x4f7265b84000]
2017-03-14 09:26:02.352333 UTC - [Main Thread]: D/nsHttp nsHttpChannel::InstallCacheListener sync tee 0x7fa656137330 rv=0 cacheIOTarget=(nil)
2017-03-14 09:26:02.352339 UTC - [Main Thread]: D/nsStreamPump   OnStateTransfer [this=0x1bf828bf1740]
2017-03-14 09:26:02.352342 UTC - [Main Thread]: D/nsStreamPump   Available returned [stream=0x7fa648b65fb0 rv=0 avail=26]
2017-03-14 09:26:02.352345 UTC - [Main Thread]: D/nsStreamPump   calling OnDataAvailable [offset=0 count=26(26)]
2017-03-14 09:26:02.352347 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnDataAvailable [this=0x4f7265b84000 request=0x1bf828bf1740 offset=0 count=26]
2017-03-14 09:26:02.352349 UTC - [Main Thread]: D/nsHttp OnDataAvailable 0x4f7265b84000 requestFromCache: 0 mFirstResponseSource: 0
2017-03-14 09:26:02.352351 UTC - [Main Thread]: D/nsHttp sending progress notification [this=0x4f7265b84000 status=804b0006 progress=26/-1]
....

Until

2017-03-14 09:26:06.047585 UTC - [Main Thread]: D/nsStreamPump   calling OnDataAvailable [offset=117 count=13(13)]
2017-03-14 09:26:06.047587 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnDataAvailable [this=0x4f7265b84000 request=0x1bf828bf1740 offset=117 count=13]
2017-03-14 09:26:06.047589 UTC - [Main Thread]: D/nsHttp OnDataAvailable 0x4f7265b84000 requestFromCache: 0 mFirstResponseSource: 0
2017-03-14 09:26:06.047592 UTC - [Main Thread]: D/nsHttp sending progress notification [this=0x4f7265b84000 status=804b0006 progress=130/-1]


It looks like data already received, but we still expected LOADING event fired for 10 times.
I try to add flush [1] after write_content()[2], it won't help. So I guess we probably read more data one time than the test case expected.
[1] http://wptserve.readthedocs.io/en/latest/response.html#wptserve.response.ResponseWriter.flush
[2] https://github.com/w3c/web-platform-tests/blob/master/XMLHttpRequest/resources/trickle.py#L14
Hi Anne,
This test case [1] expects browser is supposed to fire onreadstatechange LOADING 10 times.

I tried with Chromium 56, and we got error "assert_equals: LOADING state change may be emitted multiple times expected 10 but got 1" constantly.

So I think this assumption seems to be strange to me. It's possible that socket layer might optimize somehow and we can't expect browser side received readystate LOADING 10 times. It's possible that we have more buffers and we soon change ready state to DONE instead of LOADING.

Does the XHR specification expect that onreadystatechange LOADING state should be received every time from wptserve wrote data to body?

[1] http://searchfox.org/mozilla-central/source/testing/web-platform/tests/XMLHttpRequest/event-readystatechange-loaded.htm
Flags: needinfo?(annevk)
Yeah, https://xhr.spec.whatwg.org/#the-send()-method under "process response" says that each time the stream gets new bytes and more than 50ms have passed, you need to dispatch an event.
Flags: needinfo?(annevk)
Hi S.C,
As we discussed off-line, can you comment on why sometimes count is more than 13 in |OnDataAvailable|?
Flags: needinfo?(schien)
As long as the total received bytes are correct (130 bytes in your case), the number of OnDataAvailable doesn't seem to have problem since it just reflects how many notification system told necko. Do you have corresponding NSPR log for me to double check?.
Flags: needinfo?(schien) → needinfo?(shuang)
(In reply to Shih-Chiang Chien [:schien] (UTC+8) (use ni? plz) from comment #29)
> As long as the total received bytes are correct (130 bytes in your case),
> the number of OnDataAvailable doesn't seem to have problem since it just
> reflects how many notification system told necko. Do you have corresponding
> NSPR log for me to double check?.

Is the http.log enough? I've attached in this bug. 

You can see below, progress=130.
2017-03-14 09:26:06.047587 UTC - [Main Thread]: D/nsHttp nsHttpChannel::OnDataAvailable [this=0x4f7265b84000 request=0x1bf828bf1740 offset=117 count=13]
2017-03-14 09:26:06.047589 UTC - [Main Thread]: D/nsHttp OnDataAvailable 0x4f7265b84000 requestFromCache: 0 mFirstResponseSource: 0
2017-03-14 09:26:06.047592 UTC - [Main Thread]: D/nsHttp sending progress notification [this=0x4f7265b84000 status=804b0006 progress=130/-1]
Flags: needinfo?(shuang) → needinfo?(schien)
Not sure where the number "13" comes from. From the log in attachment, there are only 10 OnDataAvailable associated for that nsHttpChannel (search term "nsHttpChannel::OnDataAvailable [this=0x4f7265b84000"). Other ODA are for loading html/js/css while running the test case. If "13" comes from the error message in this test case, it's probably the dummy onprogress event @annavk mentioned in comment #25.
Flags: needinfo?(schien)
:shawnjohnjr, checking in here to make sure you are not stuck.  Thanks for working on this bug- it is one of our top issues and I would prefer to see this fixed soon vs temporarily disabling, so do ask for information when you need it.
Flags: needinfo?(shuang)
(In reply to Anne (:annevk) from comment #25)
> Yeah, https://xhr.spec.whatwg.org/#the-send()-method under "process
> response" says that each time the stream gets new bytes and more than 50ms
> have passed, you need to dispatch an event.

Yes. But looking into the test case, it simply expects to receive 10 LOADING onreadstatechange [1].

What happened here is sometimes OnDataAvailable() reports the size more than one chunk (13 bytes) [2], so |OnDataAvailable| got called less than 10 times, and we soon got |OnStopRequest| because all data already received. Running chaos mode with rr, I even saw |OnDataAvailable| got called only twice.

I don't see anything can improve the situation from xhr side. It seems possible that necko might optimize and it could queue more data than we expected. Chromium constantly only sends onreadstatechange once.

baku, what do you think? Is there anything we can do from dom?

[1] http://searchfox.org/mozilla-central/source/testing/web-platform/tests/XMLHttpRequest/event-readystatechange-loaded.htm#27
[2] http://searchfox.org/mozilla-central/source/testing/web-platform/tests/XMLHttpRequest/resources/trickle.py#4
Flags: needinfo?(shuang) → needinfo?(amarchesini)
10x readystatechange is indeed what it should expect per the standard, but if the network layer sometimes decides to combine chunks, even though they were delivered about 500ms apart, the test no longer holds.

Changing the assertion to a minimum of 2 rather than 10 works for me, but it sounds like that could still be flaky given how the system sometimes decides to combine things (even though we haven't observed 1 yet in Firefox).
(In reply to Anne (:annevk) from comment #37)
> 10x readystatechange is indeed what it should expect per the standard, but
> if the network layer sometimes decides to combine chunks, even though they
> were delivered about 500ms apart, the test no longer holds.
> 
> Changing the assertion to a minimum of 2 rather than 10 works for me, but it
> sounds like that could still be flaky given how the system sometimes decides
> to combine things (even though we haven't observed 1 yet in Firefox).

Yeah, twice is very rare and it could be the worst case when I ran test cases using rr choas mode.
I think I will change assertion to 2, since now I really don't have any good solution from network layer perspective.
Per http://web-platform-tests.org/writing-tests/testharness-api.html the second argument should be 1. Otherwise you end up requiring it to be 3, which we know will remain to be flaky under certain extremes.

(Removing request for baku since we're moving ahead anyway.)
Flags: needinfo?(amarchesini)
Attachment #8849950 - Attachment is obsolete: true
Attachment #8849950 - Flags: review?(annevk)
Attachment #8849970 - Flags: review?(annevk) → review+
Pushed by shuang@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/b6c3cdc5ac09
Change onreadystatechange assertion to a minimum of 2 rather than 10, r=annevk
Whiteboard: [stockwell needswork] → [stockwell fixed]
https://hg.mozilla.org/mozilla-central/rev/b6c3cdc5ac09
Status: NEW → RESOLVED
Closed: 6 years ago
status-firefox55: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Whiteboard: [stockwell fixed] → [stockwell needswork]
(In reply to Sebastian Hengst [:aryx][:archaeopteryx] (needinfo on intermittent or backout) from comment #48)
> This is still occurring, see the two W(9) failures in
> https://treeherder.mozilla.org/#/
> jobs?repo=autoland&revision=01e61eff9b62792fe018936eefc9e142d29613f0&filter-
> resultStatus=testfailed&filter-resultStatus=busted&filter-
> resultStatus=exception&filter-resultStatus=retry&filter-
> resultStatus=usercancel&filter-resultStatus=runnable

It's a bit strange here.
The test case is simple and there is only one assertion here. And the test doesn't import extra scripts.

https://hg.mozilla.org/mozilla-central/file/tip/testing/web-platform/tests/XMLHttpRequest/event-readystatechange-loaded.htm#l27

And from the log shows, the assertion doesn't seem to change at all.
My patch replaces assert_equals to assert_greater_than, but the log shows 'assert_equals'.
Can we check the file "event-readystatechange-loaded.htm" on servers?
Sorry, I don't have any idea or good explanation.
Flags: needinfo?(shuang)
Flags: needinfo?(aryx.bugmail)
I don't see this error on mozilla-inbound on try. Let's keep monitor a few days.
this error seems to have died down about 12+ hours ago.
Whiteboard: [stockwell needswork] → [stockwell fixed]
Can we close this bug? The error has gone for a few days.
Ok, set again to RESOLVED FIXED.
Status: REOPENED → RESOLVED
Closed: 6 years ago → 6 years ago
Flags: needinfo?(aryx.bugmail)
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.