1152574 - Aborted XHR requests are reported as "CORS Same Origin Policy disallows" in web console

Status: RESOLVED FIXED

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

Description

[Chris Peterson [:cpeterson]]

STR:
1. Play the first video ("Sintel (Multilanguage & Subtitles) - SegmentTemplate") at http://www.dash-player.com/demo/streaming-server-and-encoder-support/
2. Watch the web console for the video player making XHR requests for MSE video segments.
3. Quickly seek ahead a few times in the video progress bar.

RESULT:
The video player will abort some of the XHR requests to bitcdn-global1.bitmovin.com before it seeks ahead. The aborted requests will "fail" with unexpected CORS Same-Origin errors, but subsequent XHR requests to bitcdn-global1.bitmovin.com succeed.


Cross-Origin Request Blocked: The Same Origin Policy disallows reading the remote resource at http://bitcdn-global1.bitmovin.com/content/sintel/audio/stereo/en/128kbit/segment_142.m4s. (Reason: CORS request failed). <unknown>
Cross-Origin Request Blocked: The Same Origin Policy disallows reading the remote resource at http://bitcdn-global1.bitmovin.com/content/sintel/video/800kbit/segment_134.m4s. (Reason: CORS request failed). <unknown>
GET 
XHR 
http://bitcdn-global1.bitmovin.com/content/sintel/audio/stereo/en/128kbit/segment_158.m4s [HTTP/1.1 200 OK 445ms]
GET 
XHR 
http://bitcdn-global1.bitmovin.com/content/sintel/video/250kbit/segment_156.m4s [HTTP/1.1 200 OK 516ms]

Comment 1

[Alex Vincent [:WeirdAl]]

Can this be reproduced with an ordinary XHR and a call to .abort()?  (That is, can the test be done without the video player aspect?)

Comment 2

[Chris Peterson [:cpeterson]]

I don't have a simpler test case, but this looks like the same problem reported in bug 1094911.

Comment 3

[Chris Peterson [:cpeterson]]

This issue makes debugging more confusing, but does not need to block Adobe EME MVP.

Comment 4

[Boris Zbarsky [:bzbarsky]]

Yeah, this is slightly bogus.  In nsCORSListenerProxy::CheckRequestApproved, it seems like if there was a necko-level failure we should just silently return that error and not log anything to the console instead of logging a string with the CORSRequestFailed message.  Jonas, do you recall why we're doing this, exactly?

Comment 5

[Jonas Sicking (:sicking) No longer reading bugmail consistently]

Generally the CORS code wants to ensure that any network error or CORS errors just looks like a generic "something went wrong with the request" error to the calling page.

That means that the in theory, the CORS code might in some cases might hide some information from the webpage. In that case you could make an argument for exposing that hidden information in the error console.

However we don't expose particularly detailed error information through XHR anyway, so I doubt that we're actually hiding anything. So not putting anything in the console seems totally fine.

The network panel in the developer console is likely the best way to debug any problems here anyway.

Comment 6

[Anthony Jones (:ajones, :kentuckyfriedtakahe, :k17e)]

Can we get this issue cleaned up. It is a red herring for people who have playback issue.

Comment 7

[Jonas Sicking (:sicking) No longer reading bugmail consistently]

I think we know what needs to be done. We just need someone to do it. I don't really have time for writing patches these days so we'll need to find someone else.

What needs to be done here is to remove the two calls to LogBlockedRequest here:

http://mxr.mozilla.org/mozilla-central/source/dom/security/nsCORSListenerProxy.cpp#540
http://mxr.mozilla.org/mozilla-central/source/dom/security/nsCORSListenerProxy.cpp#544

Comment 8

[Jonas Sicking (:sicking) No longer reading bugmail consistently]

We should also remove that error message from the localization files, since that's the only place it is used.

Comment 10

[Christoph Kerschbaumer [:ckerschb]]

Attachment: bug_1152574_xhr_cors.patch

In fact the problem was introduced within Bug 1121824 which landed in 38. If that incorrect console messaging is bothering people a lot, we might consider uplifting since it's a trivial fix.

Comment 11

[Jonas Sicking (:sicking) No longer reading bugmail consistently]

Comment on attachment 8636222 [details] [diff] [review]
bug_1152574_xhr_cors.patch

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

Thanks!!

Comment 12

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/cc377dd50503

Comment 13

[Carsten Book [:Tomcat]]

sorry had to back this out for causing memory leaks like https://treeherder.mozilla.org/logviewer.html#?job_id=11940396&repo=mozilla-inbound

Comment 14

[Pulsebot]

Backout:
https://hg.mozilla.org/integration/mozilla-inbound/rev/bba8855ab99e

Comment 15

[Christoph Kerschbaumer [:ckerschb]]

(In reply to Carsten Book [:Tomcat] from comment #13)
> sorry had to back this out for causing memory leaks like
> https://treeherder.mozilla.org/logviewer.html#?job_id=11940396&repo=mozilla-
> inbound

Carsten, Ryan, are you sure that this patch is causing the problem? Looking at the patch that seems to be very unlikely, since we are just not logging a particular error to the console anymore. I am very willing to figure out what's going on but at the moment I can't see that this patch might cause the problem. Any suggestions?

Comment 16

[Ryan VanderMeulen [:RyanVM]]

I haven't seen any leaks on inbound since it was backed out.

Comment 17

[Ryan VanderMeulen [:RyanVM]]

https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-searchStr=10.6%20debug%20mochitest-3&fromchange=a4dd53b2940a&tochange=bba8855ab99e looks pretty convincing to me as well.

Comment 18

[Boris Zbarsky [:bzbarsky]]

Were there leaks on other platform too, or just mac 10.6?  Because I agree with comment 15; it's hard to see how this patch could cause leaks....

Comment 19

[Jonas Sicking (:sicking) No longer reading bugmail consistently]

My guess would be that the removed error string somehow moved stuff around that we're triggering an existing bug. I can't think of any possible other ways that this could cause a leak.

So maybe we can try to land a change that simply doesn't remove that string?

Comment 20

[Christoph Kerschbaumer [:ckerschb]]

Attachment: bug_1152574_xhr_cors_v2.patch

(In reply to Jonas Sicking (:sicking) from comment #19)
> My guess would be that the removed error string somehow moved stuff around
> that we're triggering an existing bug. I can't think of any possible other
> ways that this could cause a leak.
> 
> So maybe we can try to land a change that simply doesn't remove that string?

Ryan, what do you think? Can we try that? If so, here is the patch without removing the error string in security.properties.

Comment 21

[Ryan VanderMeulen [:RyanVM]]

Sounds like something you could test on Try first. I have no opinion beyond "don't turn the tree orange" :)

Comment 22

[Christoph Kerschbaumer [:ckerschb]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=a112fcb3d8b7

Comment 23

[Christoph Kerschbaumer [:ckerschb]]

(In reply to Christoph Kerschbaumer [:ckerschb] from comment #22)
> https://treeherder.mozilla.org/#/jobs?repo=try&revision=a112fcb3d8b7

Not a clue what might go wrong here, but it's still perma-orange. Let's wait a few days and push to try again, unless someone has any other suggestions :-(

Comment 24

[Boris Zbarsky [:bzbarsky]]

Is it orange on other platforms too?

Comment 25

[Christoph Kerschbaumer [:ckerschb]]

(In reply to Boris Zbarsky [:bz] from comment #24)
> Is it orange on other platforms too?

Let's find out and let's try this once again, I can't imagine what might go wrong here:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=da17c1333278

Comment 26

[Chris Peterson [:cpeterson]]

Christoph, this leak looks real. Your try push is orange on Linux, OS X, and Windows XP–8. Who is familiar with this code that might recognize this mystery leak?

 TEST-UNEXPECTED-FAIL | leakcheck | default process: 494518 bytes leaked (AsyncLatencyLogger, AsyncStatement, AtomImpl, BackstagePass, BodyRule, ...)

Comment 27

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

If it happens reliably on Linux get it in rr and debug it.

Comment 28

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

FWIW, that leak is reproducible on my machine if I run that test by itself without your patch.

Comment 29

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

My theory is that the console messages that you are no longer sending were evicting other messages from the console service that are the ones causing the leak.

Comment 30

[Jonas Sicking (:sicking) No longer reading bugmail consistently]

Yeah, I was thinking that too.

Whatever the reason, I can with almost 100% certainty say that this patch is not the *cause* of the leak. Unfortunately that doesn't really change anything since we can't check in a patch which causes mochitest to permanently go orange.

Comment 31

[Christoph Kerschbaumer [:ckerschb]]

At least we have a testcase that can reliably reproduce the problem:
http://mxr.mozilla.org/mozilla-central/source/dom/tests/mochitest/bugs/test_bug414291.html?force=1#21
you can even comment out the other two tests underneath.

Comment 32

[Christoph Kerschbaumer [:ckerschb]]

Andrew, Nathan, when browsing through the logs I see you have worked on the console quite a bit, any ideas what might go wrong here?

Comment 33

[Andrew McCreight [:mccr8]]

Nathan and I don't really know anything about Console. baku might be able to provide some useful information. I do know about generic leak finding stuff.

Comment 34

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

I have it under control.

Comment 35

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Attachment: 0001-Bug-1152574-Fix-console-service-discarding-to-run-wh.patch

http://hg.mozilla.org/mozilla-central/rev/3e98575b1f9d is bogus, because ScriptErrorEvent is asynchronous.  We should do the clearing off of inner-window-destroyed instead.

ckerschb, want to try this with your patch?

Comment 36

[Christoph Kerschbaumer [:ckerschb]]

Works just (In reply to Kyle Huey [:khuey] ([e-mail]) from comment #35)
> ckerschb, want to try this with your patch?

No more leaks - hurray - thanks khuey!

Comment 37

[Nathan Froyd [:froydnj]]

Comment on attachment 8641233 [details] [diff] [review]
0001-Bug-1152574-Fix-console-service-discarding-to-run-wh.patch

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

So the problem is that somebody was injecting console messages for a window between the point where we cleared them, and the point where the inner window actually went away?

::: dom/ipc/ContentParent.cpp
@@ +4301,5 @@
>      // just an nsIConsoleService). This allows us to call the non-idl function
>      // nsConsoleService::LogMessageWithMode.
>      NS_DEFINE_CID(consoleServiceCID, NS_CONSOLESERVICE_CID);
> +    nsCOMPtr<nsIConsoleService> consoleService(do_GetService(consoleServiceCID));
> +    mConsoleService = static_cast<nsConsoleService*>(consoleService.get());

Please file a followup for making this less lame.

::: xpcom/base/nsConsoleService.cpp
@@ +92,5 @@
>      NS_RELEASE(mMessages[i]);
>  
>      uint32_t j = i;
>      // Now shift all the following messages
> +    // XXXkhuey this is not an efficient way to iterate through an array ...

Can you file a followup bug to fix this?  I suck for OK'ing accidentally quadratic things here, and doing this on every window destruction isn't going to be particularly efficient.

Comment 38

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

(In reply to Nathan Froyd [:froydnj][:nfroyd] from comment #37)
> Comment on attachment 8641233 [details] [diff] [review]
> 0001-Bug-1152574-Fix-console-service-discarding-to-run-wh.patch
> 
> Review of attachment 8641233 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> So the problem is that somebody was injecting console messages for a window
> between the point where we cleared them, and the point where the inner
> window actually went away?

Yes.

Comment 39

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/2b518fc1e8a4

Comment 40

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

(In reply to Nathan Froyd [:froydnj][:nfroyd] from comment #37)
> Comment on attachment 8641233 [details] [diff] [review]
> 0001-Bug-1152574-Fix-console-service-discarding-to-run-wh.patch
> 
> Review of attachment 8641233 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> So the problem is that somebody was injecting console messages for a window
> between the point where we cleared them, and the point where the inner
> window actually went away?
> 
> ::: dom/ipc/ContentParent.cpp
> @@ +4301,5 @@
> >      // just an nsIConsoleService). This allows us to call the non-idl function
> >      // nsConsoleService::LogMessageWithMode.
> >      NS_DEFINE_CID(consoleServiceCID, NS_CONSOLESERVICE_CID);
> > +    nsCOMPtr<nsIConsoleService> consoleService(do_GetService(consoleServiceCID));
> > +    mConsoleService = static_cast<nsConsoleService*>(consoleService.get());
> 
> Please file a followup for making this less lame.

Bug 1189827.

> ::: xpcom/base/nsConsoleService.cpp
> @@ +92,5 @@
> >      NS_RELEASE(mMessages[i]);
> >  
> >      uint32_t j = i;
> >      // Now shift all the following messages
> > +    // XXXkhuey this is not an efficient way to iterate through an array ...
> 
> Can you file a followup bug to fix this?  I suck for OK'ing accidentally
> quadratic things here, and doing this on every window destruction isn't
> going to be particularly efficient.

Bug 1189829.

Comment 41

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/2b518fc1e8a4

Comment 42

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

You should be able to land your stuff now.

Comment 43

[Christoph Kerschbaumer [:ckerschb]]

url:        https://hg.mozilla.org/integration/mozilla-inbound/rev/0b05974fd3b0c351cdd93143d0de0652a99f626d
changeset:  0b05974fd3b0c351cdd93143d0de0652a99f626d
user:       Christoph Kerschbaumer <[e-mail]>
date:       Mon Jul 20 13:59:19 2015 -0700
description:
Bug 1152574 - Do not report aborted XHR requests in web console (r=sicking)

Comment 44

[Christoph Kerschbaumer [:ckerschb]]

(In reply to Kyle Huey [:khuey] ([e-mail]) from comment #42)
> You should be able to land your stuff now.

Thanks Kyle!

Comment 45

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/0b05974fd3b0