Closed Bug 1370056 Opened 8 years ago Closed 2 years ago

Intermittent /XMLHttpRequest/send-response-event-order.htm | XMLHttpRequest: The send() method: event order when synchronous flag is unset - assert_equals: expected "upload.progress(12,12,true)" but got "upload.load(12,12,true)"

Categories

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

Product:
Core
Component:
DOM: Core & HTML
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

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

this is failing on many different configurations, heavier on windows and windows 10. here is a recent win10 debug failure: https://treeherder.mozilla.org/logviewer.html#?repo=autoland&job_id=124728588&lineNumber=4596 and related data from the above log: 00:40:01 INFO - TEST-START | /XMLHttpRequest/send-response-event-order.htm 00:40:01 INFO - PID 7076 | ++DOCSHELL 000002248310C800 == 12 [pid = 6176] [id = {6946d5c0-1d37-4000-b95f-87fd7e4582b7}] 00:40:01 INFO - PID 7076 | ++DOMWINDOW == 31 (000002248310D000) [pid = 6176] [serial = 582] [outer = 0000000000000000] 00:40:01 INFO - PID 7076 | [Parent 7076] WARNING: [nsFrameLoader] ReallyStartLoadingInternal tried but couldn't show remote browser. 00:40:01 INFO - PID 7076 | : file z:/build/build/src/dom/base/nsFrameLoader.cpp, line 794 00:40:01 INFO - PID 7076 | ++DOMWINDOW == 32 (000002248310D800) [pid = 6176] [serial = 583] [outer = 000002248310D000] 00:40:01 INFO - PID 7076 | 1503362401473 Marionette DEBUG Register listener.js for window 4294967878 00:40:01 INFO - PID 7076 | ++DOMWINDOW == 33 (0000022483116000) [pid = 6176] [serial = 584] [outer = 000002248310D000] 00:40:01 INFO - PID 7076 | --DOCSHELL 00000224824E5000 == 11 [pid = 6176] [id = {6cbbe6eb-b677-4ec6-b0c2-ff83c05e26c1}] 00:40:01 INFO - PID 7076 | --DOCSHELL 0000022482160800 == 10 [pid = 6176] [id = {e5fd95d2-827f-4637-9cc1-25f3208ef785}] 00:40:01 INFO - PID 7076 | --DOCSHELL 0000022481FAB800 == 9 [pid = 6176] [id = {6468d903-7de6-4c85-a918-12aa7def24ff}] 00:40:01 INFO - PID 7076 | --DOCSHELL 0000022481BE8800 == 8 [pid = 6176] [id = {4b4aa8a3-2b8e-4c8e-b9a5-f0972e951eb3}] 00:40:01 INFO - PID 7076 | --DOCSHELL 000002248197A800 == 7 [pid = 6176] [id = {f2215d53-9581-4b05-a5a8-08d33e0bff18}] 00:40:01 INFO - PID 7076 | --DOCSHELL 000002248149D000 == 6 [pid = 6176] [id = {43b908e9-32d6-4988-84d8-c6099230ce7f}] 00:40:01 INFO - PID 7076 | --DOCSHELL 0000022480E4F000 == 5 [pid = 6176] [id = {1c3d42d5-1463-43d9-95ff-6cc0112741d0}] 00:40:01 INFO - PID 7076 | --DOCSHELL 0000022480ADC800 == 4 [pid = 6176] [id = {ee31b2b5-8a1e-4d0a-a267-abbb8d27f131}] 00:40:01 INFO - PID 7076 | --DOCSHELL 00000224839AC000 == 3 [pid = 6176] [id = {3b6979b3-6bc8-4141-9034-454373c047ae}] 00:40:02 INFO - 00:40:02 INFO - TEST-UNEXPECTED-FAIL | /XMLHttpRequest/send-response-event-order.htm | XMLHttpRequest: The send() method: event order when synchronous flag is unset - assert_equals: expected "upload.progress(12,12,true)" but got "upload.load(12,12,true)" 00:40:02 INFO - global.assert_xhr_event_order_matches@http://web-platform.test:8000/XMLHttpRequest/resources/xmlhttprequest-event-order.js:74:7 00:40:02 INFO - @http://web-platform.test:8000/XMLHttpRequest/send-response-event-order.htm:31:17 00:40:02 INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1441:20 00:40:02 INFO - Test.prototype.step_func/<@http://web-platform.test:8000/resources/testharness.js:1465:20 00:40:02 INFO - EventListener.handleEvent*@http://web-platform.test:8000/XMLHttpRequest/send-response-event-order.htm:30:13 00:40:02 INFO - Test.prototype.step@http://web-platform.test:8000/resources/testharness.js:1441:20 00:40 :02 INFO - @http://web-platform.test:8000/XMLHttpRequest/send-response-event-order.htm:25:9 00:40:02 INFO - TEST-OK | /XMLHttpRequest/send-response-event-order.htm | took 694ms :jgraham, I don't know which group/team/person at Mozilla would be good to look into this, can you help find the right owner?
Flags: needinfo?(james)
Whiteboard: [stockwell needswork]
shuang: You seem to have worked on XHR recently; are you the right person to look at this, or do you know who is?
Flags: needinfo?(james) → needinfo?(shuang)
Assignee: nobody → shuang
Flags: needinfo?(shuang)
I can't reproduce this bug using rr. So I will add more logs to try-server.
08:34:18 INFO - TEST-START | /XMLHttpRequest/send-response-event-order.htm 08:34:18 INFO - PID 9676 | ++DOCSHELL 000002C125DDE800 == 6 [pid = 10328] [id = {1a11189c-48bc-4568-9c64-d8d99cb1e100}] 08:34:18 INFO - PID 9676 | ++DOMWINDOW == 77 (000002C125EA3800) [pid = 10328] [serial = 582] [outer = 0000000000000000] 08:34:18 INFO - PID 9676 | [Parent 9676] WARNING: [nsFrameLoader] ReallyStartLoadingInternal tried but couldn't show remote browser. 08:34:18 INFO - PID 9676 | : file z:/build/build/src/dom/base/nsFrameLoader.cpp, line 794 08:34:18 INFO - PID 9676 | ++DOMWINDOW == 78 (000002C125EA4000) [pid = 10328] [serial = 583] [outer = 000002C125EA3800] 08:34:18 INFO - PID 9676 | 1504082058335 Marionette DEBUG Register listener.js for window 4294967878 08:34:18 INFO - PID 9676 | ++DOMWINDOW == 79 (000002C125EB7000) [pid = 10328] [serial = 584] [outer = 000002C125EA3800] 08:34:18 INFO - PID 9676 | ##### line: 2017 load ###### 08:34:18 INFO - PID 9676 | mozilla::dom::XMLHttpRequestMainThread::OnDataAvailable: line: 1900, mProgressSinceLastProgressEvent = true 08:34:18 INFO - PID 9676 | mozilla::dom::XMLHttpRequestMainThread::OnDataAvailable: line: 1947, mProgressSinceLastProgressEvent = false 08:34:18 INFO - 08:34:18 INFO - TEST-UNEXPECTED-FAIL | /XMLHttpRequest/send-response-event-order.htm | XMLHttpRequest: The send() method: event order when synchronous flag is unset - assert_equals: expected "upload.progress(12,12,true)" but got "upload.load(12,12,true)" 08:34:18 INFO - global.assert_xhr_event_order_matches@http://web-platform.test:8000/XMLHttpRequest/resources/xmlhttprequest-event-order.js:74:7
It looks like the bad case, it doesn't set mProgressSinceLastProgressEvent in |OnProgress|. 0:10.04 TEST_START: Thread-TestrunnerManager-1 /XMLHttpRequest/send-response-event-order.htm 0:10.07 LOG: Thread-TestrunnerManager-1 INFO Setting pref dom.xhr.lowercase_header.enabled (true) 0:10.11 LOG: Thread-TestrunnerManager-1 INFO Setting pref javascript.options.streams (true) 0:10.64 PROCESS_OUTPUT: ProcessReader (pid:18419) "OnProgress: line: 3537, mProgressSinceLastProgressEvent = true" 0:10.68 PROCESS_OUTPUT: ProcessReader (pid:18419) "##### OnStartRequest line: 2009 progress ######" 0:10.68 PROCESS_OUTPUT: ProcessReader (pid:18419) "OnStartRequest: line: 2012, mProgressSinceLastProgressEvent = false" 0:10.68 PROCESS_OUTPUT: ProcessReader (pid:18419) "##### line: 2017 load ######"
I'm still trying to add more logs on try but now I can't reproduce I may increase more hits anyway.
(In reply to Shawn Huang [:shawnjohnjr] from comment #17) > try: > https://treeherder.mozilla.org/#/ > jobs?repo=try&revision=f08513277c6d8bddd36c4013b0cc85afa4669593&selectedJob=1 > 27657124 > > log: > https://treeherder.mozilla.org/logviewer. > html#?job_id=127657124&repo=try&lineNumber=7410 It looks like this log shows that the progress event was missing since it's not in upload phase. 06:17:09 INFO - TEST-START | /XMLHttpRequest/send-response-event-order.htm 06:17:10 INFO - PID 5236 | ##### line: 2018 load ###### 06:17:10 INFO - PID 5236 | ###### Entering OnProgress ##### 06:17:10 INFO - PID 5236 | ####### InUploadPhase state: 2 ###### 06:17:10 INFO - PID 5236 | mozilla::dom::XMLHttpRequestMainThread::OnProgress: line: 3546, not in upload phase 06:17:10 INFO - PID 5236 | ###### Entering OnProgress ##### 06:17:10 INFO - PID 5236 | ####### InUploadPhase state: 2 ###### 06:17:10 INFO - PID 5236 | mozilla::dom::XMLHttpRequestMainThread::OnProgress: line: 3546, not in upload phase 06:17:10 INFO - PID 5236 | mozilla::dom::XMLHttpRequestMainThread::OnDataAvailable: line: 1901, mProgressSinceLastProgressEvent = true 06:17:10 INFO - PID 5236 | mozilla::dom::XMLHttpRequestMainThread::OnDataAvailable: line: 1948, mProgressSinceLastProgressEvent = false
Because IsUploadPhase checks if mState is opened but however mState already changed to headers_received.
In normal situation, onProgress() will be executed after open() and before load event gets issued, and set mProgressSinceLastProgressEvent to true, then progress event will be sent in OnStartRequest(). In bad situation, it seems onProgress() event delay a bit, and we check the current state is in headers_received so we don't fire progress event.
Unfortunately this looks like a timing issue from necko side. OnProgress is triggered by nsBaseChannel::OnDataAvailable, it seems like necko doesn't trigger onProgress in time. Then load event was sent first. I have to check why OnDataAvailable doesn't call in time.
Switch to critical 56 beta bug a few days, now I'm focusing this again.
disabled the test: https://hg.mozilla.org/integration/mozilla-inbound/rev/24626e602a6bc25463da5746ea85c33d4eba4ff2 :shawnjohnjr, when working on a fix for this bug, please remember to enable this in the manifest.
Flags: needinfo?(shuang)
Keywords: leave-open
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Flags: needinfo?(shuang)
Component: web-platform-tests → DOM
Product: Testing → Core
Version: Version 3 → Trunk
Status: NEW → RESOLVED
Closed: 7 years ago
Priority: -- → P3
Resolution: --- → WORKSFORME
Component: DOM → DOM: Core & HTML

Reopening; this is still disabled and still needs to be re-enabled.

Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Status: REOPENED → RESOLVED
Closed: 7 years ago → 6 years ago
Resolution: --- → INCOMPLETE

New failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=259748148&repo=autoland&lineNumber=3800

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Severity: normal → S3

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Status: REOPENED → RESOLVED
Closed: 6 years ago → 2 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.