Open Bug 1370056 Opened 4 years ago Updated 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)

defect

Tracking

()

REOPENED

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: 4 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 → ---
Status: REOPENED → RESOLVED
Closed: 4 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
You need to log in before you can comment on or make changes to this bug.