Intermittent dom/xhr/tests/test_xhr_progressevents.html | total while running data for cacheable data for blob[0] - got +0, expected 65536

RESOLVED FIXED in Firefox 52

Status

()

defect
P1
normal
RESOLVED FIXED
3 years ago
4 months ago

People

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

Tracking

({intermittent-failure})

unspecified
mozilla52
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox50 unaffected, firefox51 unaffected, firefox52 fixed)

Details

Attachments

(1 attachment)

This is extremely frequent.
Blocks: 1306235
Flags: needinfo?(amarchesini)
See Also: → 1308347, 1308620
With no response from amarchesini, it is time to get more visibility on this bug.  :baku, can you find someone or take this upon yourself to figure out why we are failing in this test so frequently?
baku's been on PTO but I'll follow up with him on Monday.
I will try to help this bug.
Assignee: nobody → shuang
(In reply to Shawn Huang [:shawnjohnjr] from comment #26)
> I will try to help this bug.

That's awesome, thank you:)
I can hit similar bug, not exactly the same after passing 41529 test cases.

Test File Name:	Test:	Error message:
/tests/dom/xhr/tests/test_xhr_progressevents.html	total while running data for with length for blob[2]	got +0, expected 20
Currently running rr leads content process crash, set "security.sandbox.content.level" to 0 can resolve it.

diff --git a/testing/profiles/prefs_general.js b/testing/profiles/prefs_general.js
--- a/testing/profiles/prefs_general.js
+++ b/testing/profiles/prefs_general.js
@@ -353,8 +353,9 @@ user_pref("startup.homepage_welcome_url.
 
 // For Firefox 52 only, ESR will support non-Flash plugins while release will
 // not, so we keep testing the non-Flash pathways
 user_pref("plugin.load_flash_only", false);
 
 // Don't block old libavcodec libraries when testing, because our test systems
 // cannot easily be upgraded.
 user_pref("media.libavcodec.allow-obsolete", true);
+user_pref("security.sandbox.content.level", 0);
(In reply to Shawn Huang [:shawnjohnjr] from comment #28)
> I can hit similar bug, not exactly the same after passing 41529 test cases.
> 
> Test File Name:	Test:	Error message:
> /tests/dom/xhr/tests/test_xhr_progressevents.html	total while running data
> for with length for blob[2]	got +0, expected 20

That's bug 1308620!

There are several similar bugs.
P1 due to it being on top of OrangeFactor.
Priority: -- → P1
(In reply to Hsin-Yi Tsai [:hsinyi] from comment #32)
> P1 due to it being on top of OrangeFactor.

I'm actively investigate it now.
(In reply to Hsin-Yi Tsai [:hsinyi] from comment #32)
> P1 due to it being on top of OrangeFactor.

I'm actively investigating it now.
What I saw in gdb, mLoadTotal set to 0, because mBlobStorage->GetBlobWhenReady() called in OnStopRequest.
http://searchfox.org/mozilla-central/source/dom/xhr/XMLHttpRequestMainThread.cpp#2064

Old value = -1
New value = 20
mozilla::dom::XMLHttpRequestMainThread::OnProgress (this=0x7f200bede000, aRequest=0x7f200adb6088, aContext=0x0, aProgress=5, aProgressMax=20) at /home/shawnjohnjr/code/mozilla-inbound/dom/xhr/XMLHttpRequestMainThread.cpp:3341
3341	    mLoadTransferred = aProgress;
(rr) p mLoadTotal
$4 = 20

Old value = 20
New value = 0
0x00007f202f51206c in mozilla::dom::XMLHttpRequestMainThread::OnStopRequest (this=0x7f200bede000, request=0x7f200adb6088, ctxt=<optimized out>, status=nsresult::NS_OK) at /home/shawnjohnjr/code/mozilla-inbound/dom/xhr/XMLHttpRequestMainThread.cpp:2065
2065	          mBlobStorage->GetBlobWhenReady(GetOwner(), contentType, this);
Just want to clarify Comment 35, it's not related to OnStopRequest.

 test [i] = 8
 testState.index 1
 responseType.type blob
 testState.name with length for blob
sending
waiting for more bytes: 10
received 'send' command
got event: readystatechange (3)
 readystatechange continue 
waiting for more bytes: 10
 OnStopRequest 3: mLoadTotal: 0 
 OnStopRequest 1: mLoadTotal: 0
  ChangeStateToDone : mLoadTotal: 2 
 ChangeStateToDone : mLoadTotal: 20 
got event: progress (3)
 updateProgress, test:  while running data for with length for blob[2]
TEST-PASS | /tests/dom/xhr/tests/test_xhr_progressevents.html | lengthComputable while running data for with length for blob[2]
-- total in data total: e.total: 20, data.total: 20

I compared good cases and bad cases, the differences are:
ChangeStateToDone get called, update mLoadTotal to 2
Then in bad cases, HandleProgressTimerCallback get called, update mLoadTotal to 0 
But in good case, ChangeStateToDone get called again, update mLoadTotal to 20

So I changed NS_PROGRESS_EVENT_INTERVAL(#1) to 200, passed 40000 test cases (before change that interval value, we can hit failure at 8000 test cases), so it looks like it's related to HandleProgressTimerCallback.

http://searchfox.org/mozilla-central/source/dom/xhr/XMLHttpRequestMainThread.cpp#127
We don't wait for BlobStoreCompleted. BlobStoreCompleted calls ChangeStateToDone, and it updates mLoadTotal. Since |HandleProgressTimerCallback| get fired every 50 millisecond, sometimes HandleProgressTimerCallback fired before BlobStoreCompleted. Then we could see mLoadTotal is 0.
There are several bustage and errors, and it doesn't look like problems of this patch. So push to try again:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=925f732fc0a84ef95a41eebefdfaa6a9a09103e9
Comment on attachment 8808134 [details] [diff] [review]
Bug 1308341 - Don't fire the progress event if the length is 0

Here what happened:
1. The test case failed at test_xhr_progressevents.html
(http://searchfox.org/mozilla-central/source/dom/xhr/tests/test_xhr_progressevents.html#86)

2.|HandleProgressTimerCallback| get fired every 50 millisecond, sometimes HandleProgressTimerCallback fired before BlobStoreCompleted.
(http://searchfox.org/mozilla-central/source/dom/xhr/XMLHttpRequestMainThread.cpp#127), so we update mLoadTotal=0 with progress event (http://searchfox.org/mozilla-central/source/dom/xhr/XMLHttpRequestMainThread.cpp#3552).

3. We don't wait for BlobStoreCompleted. BlobStoreCompleted calls ChangeStateToDone, and it updates mLoadTotal to the correct value.

This patch just skip dispatching progress event when mLoadTotal equals to 0. Since XHR specification 6.1 mentions "If length is not 0, set the lengthComputable attribute value to true and the total attribute value to length". So we should not send progress event if total is 0.

When we skip dispatching progress event, |OnDataAvailable| would call |StartProgressEventTimer| again. So we don't need to call StartProgressEventTimer after skipping progress event in |HandleProgressTimerCallback|.
Attachment #8808134 - Flags: review?(amarchesini)
Comment on attachment 8808134 [details] [diff] [review]
Bug 1308341 - Don't fire the progress event if the length is 0

Review of attachment 8808134 [details] [diff] [review]:
-----------------------------------------------------------------

Thank you so much for taking this bug.
Attachment #8808134 - Flags: review?(amarchesini) → review+
Thank you. I clear ni flag if you don't mind.
Flags: needinfo?(amarchesini)
Pushed by shuang@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/3b3503e3443f
Don't fire the progress event if the length is 0, r=baku
https://hg.mozilla.org/mozilla-central/rev/3b3503e3443f
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla52
Awesome, thanks Shawn :)
Component: DOM → DOM: Core & HTML
You need to log in before you can comment on or make changes to this bug.