526323 - Mochitest failure: test_access_control.html

Status: RESOLVED FIXED

(Core :: Audio/Video, defect)

Description

[(no longer active)]

WINNT 5.2 mozilla-central test debug mochitests-1/5 on 2009/11/03 12:25:45
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257279945.1257282103.27276.gz

39698 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_access_control.html | Can load when redirected to different domain with allow-origin - got "error", expected "loaded"
39699 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_access_control.html | Won't load when redirected to subdomain - got "loaded", expected "error"
39700 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_access_control.html | Can load when redirected to subdomain with allow-origin - got "error", expected "loaded"
39703 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_access_control.html | Won't load from differnet port on same domain - got "loaded", expected "error"
39707 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_access_control.html | Can load from subdomain with allow-origin - got "error", expected "loaded"

This is from http://hg.mozilla.org/mozilla-central/rev/8857ad3785a3, and I'm not sure if it's intermittent or not.  Roc said on IRC that he's investigating it, and I'm just filing the bug to make sure that it doesn't fall off-track.

Comment 1

[Robert O'Callahan (:roc) (email my personal email if necessary)]

It's definitely intermittent. Applying record/replay airstrike.

Comment 2

[Phil Ringnalda (:philor)]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257287895.1257289945.18052.gz
WINNT 5.2 mozilla-central test debug mochitests-1/5 on 2009/11/03 14:38:15

Comment 3

[Phil Ringnalda (:philor)]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257295771.1257297790.9592.gz
WINNT 5.2 mozilla-central test debug mochitests-1/5 on 2009/11/03 16:49:31

Comment 4

[Phil Ringnalda (:philor)]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257305876.1257307035.14392.gz
WINNT 5.2 mozilla-central test debug mochitests-1/5 on 2009/11/03 19:37:56

Comment 5

[Phil Ringnalda (:philor)]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257312083.1257313096.16604.gz
WINNT 5.2 mozilla-central test debug mochitests-1/5 on 2009/11/03 21:21:23

Comment 6

[Timothy Nikkel (:tnikkel)]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257320544.1257321595.12566.gz

Comment 7

[Phil Ringnalda (:philor)]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257351115.1257352271.11257.gz
WINNT 5.2 mozilla-central test debug mochitests-1/5 on 2009/11/04 08:11:55

Comment 8

[Shawn Wilsher :sdwilsh]

WINNT 5.2 mozilla-central test debug mochitests-1/5 [testfailed] Started 12:12, finished 12:41
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257361928.1257363661.14929.gz&fulltext=1

Comment 9

[Serge Gautherie (:sgautherie)]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257389260.1257390809.24068.gz
WINNT 5.2 mozilla-central test debug mochitests-1/5 on 2009/11/04 18:47:40

Comment 10

[Dão Gottwald [:dao]]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257419189.1257420366.24720.gz

Comment 11

[Dão Gottwald [:dao]]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257490066.1257491610.19738.gz

Comment 12

[Robert O'Callahan (:roc) (email my personal email if necessary)]

We captured a failure of this test in a VMWare recording. I'll look into it on Monday.

Comment 13

[Daniel Holbert [:dholbert]]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257530923.1257531903.25558.gz
WINNT 5.2 mozilla-central debug test mochitests-1/5 on 2009/11/06 10:08:43

Comment 14

[Daniel Holbert [:dholbert]]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257539460.1257540496.26881.gz
WINNT 5.2 mozilla-central debug test mochitests-1/5 on 2009/11/06 12:31:00

Comment 15

[Daniel Holbert [:dholbert]]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257541441.1257542605.17809.gz
WINNT 5.2 mozilla-central debug test mochitests-1/5 on 2009/11/06 13:04:01

This failure has happened in 6 out of the last 7 cycles in the Windows debug test mochitests-1/5 column.

Given that roc's got data to debug this (comment 12), perhaps we should temporarily disable this test for now, to stop the almost-permanent-orange that it's causing?

Comment 16

[Daniel Holbert [:dholbert]]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1257551623.1257552796.2087.gz
WINNT 5.2 mozilla-central debug test mochitests-1/5 on 2009/11/06 15:53:43

Given that this test is failing the majority of the time, it's just adding noise to the tinderbox page at this point.  I'm going to disable it for now.

Comment 17

[Daniel Holbert [:dholbert]]

I disabled this specifically on windows for now -- conveniently, there was already a section of the Makefile for doing that. :)
  http://hg.mozilla.org/mozilla-central/rev/5480861605ad

Comment 18

[Robert O'Callahan (:roc) (email my personal email if necessary)]

With some intense debugging and a great deal of VMWare replay, I've figured out what caused this in the test run that we recorded.

* Test 7 loads http://example.org:8000/tests/content/media/test/320x240.allow-origin.ogv cross-origin and tries to verify that it loads correctly.
* The resource does load correctly, but there was a suspend event during the load.
* Because of that, when we get an OnStopRequest, we think maybe the server just timed us out while we were suspended. So we try to read more data from the end of the resource.
* The server returns 416 Range Request Not Satisfiable.
* nsMediaChannelStream::OnStartRequest knows that that's not fatal and does not report it an as an error. However nsCrossSiteListenerProxy *does* treat it as fatal and Cancels the channel with NS_ERROR_DOM_BAD_URI. So in nsMediaChannelStream::OnStopRequest we see that there was an error and we report a NetworkError to the element.
* HOWEVER by this time loadeddata has already fired on the element, so we've reported Test 7 as passing and moved on to the next test!
* Test 8 is expecting an error. So Test 8 kicks off a cross-domain load that's supposed to fail, and then gets an error: the spurious error generated by Test 7. So we move on to Test 9.
* Test 9 gets is not expecting an error, but it gets one: the error generated by Test 8. So Test 9 fails.

Comment 19

[Robert O'Callahan (:roc) (email my personal email if necessary)]

So there are two things we should do here:
1) fix test_access_control so that we associate video events with the correct test. If a subtest generates an extra unexpected event, we should report a failure associated with that subtest, not a failure associated with some later subtest.
2) When we get a 416 error, mark the nsMediaChannelStream so that if/when we later get an NS_ERROR_DOM_BAD_URI in OnStopRequest we ignore it.

Comment 20

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Attachment: Part 1: Make nsCrossSiteListenerProxy support treating certain HTTP response codes as non-errors

Comment 21

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Attachment: Part 2: fix the bug by having nsCrossSiteListenerProxy treat 416 responses as non-errors for media loads

Comment 22

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Attachment: Part 3: fix test and reenable

Comment 23

[Robert O'Callahan (:roc) (email my personal email if necessary)]

These patches won't actually fix the problem, I think, because the 416 send by the server doesn't include Access-Control-Allow-Origin:*, so nsCrossSiteListenerProxy will still reject the request.

But we can't just have nsCrossSiteListenerProxy return OK for an HTTP error that we've flagged as benign. There could be an information leak. For example we could determine the size of a resource by triggering seek requests to different offsets of a cross-site resource and seeing which ones lead to an error and which ones don't.

I think we should have the server return Access-Control-Allow-Origin:*, or more generally the resource ^headers^, when it returns a 416. Waldo, how do you feel about that?

Comment 24

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Attachment: Part 4: serve headers with 416 responses

Comment 25

[Chris Pearce [:cpearce (Not reading bugmail)]]

(In reply to comment #24)
> Created an attachment (id=412501) [details]
> Part 4: serve headers with 416 responses

Not quite there yet, not sending access-controls header on 416:

(With mochitest server running)
$ curl -I -r 28942- http://127.0.0.1:8888/tests/content/media/test/320x240.allow-origin.ogv
HTTP/1.1 416 Requested Range Not Satisfiable
content-type: text/html
connection: close
server: httpd.js
date: Sun, 15 Nov 2009 22:23:44 GMT
content-length: 379



$ curl -I http://127.0.0.1:8888/tests/content/media/test/320x240.allow-origin.ogv
HTTP/1.1 200 OK
last-modified: Wed, 21 Oct 2009 21:27:14 GMT
content-type: video/ogg
access-control-allow-origin: *
content-length: 28942
connection: close
server: httpd.js
date: Sun, 15 Nov 2009 22:24:32 GMT

Comment 26

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Attachment: v2

Ooops. This works.

Comment 27

[Chris Pearce [:cpearce (Not reading bugmail)]]

I have been running test_access_controls in a loop with these patches for the past two hours, and not seen it fail, so I think we're good to go with these patches.

Comment 28

[Jeff Walden [:Waldo]]

Comment on attachment 412505 [details] [diff] [review]
v2

The current error-response-generation system is more inflexible than it should be; this is a reasonable stopgap until I get around to thinking of something better.


>diff --git a/netwerk/test/httpserver/httpd.js b/netwerk/test/httpserver/httpd.js
>@@ -2053,16 +2052,18 @@ function maybeAddHeaders(file, metadata,
>     }
> 
>     // headers
>     while (more || line.value != "")
>     {
>       var header = line.value;
>       var colon = header.indexOf(":");
> 
>+      dump("### Set header " + header.substring(0, colon) +
>+           " to " + header.substring(colon + 1, header.length) + "\n");

Use dumpn here so you can get rid of the + "\n" at the end, also to avoid debug-spew outside of server uses where debug output is enabled.


>@@ -2222,16 +2223,19 @@ ServerHandler.prototype =
>       {
>         if (!(e instanceof HttpError))
>           throw e;
> 
>         errorCode = e.code;
>         dumpn("*** errorCode == " + errorCode);
> 
>         response = new Response(connection);
>+        if (e.customErrorHandling) {
>+          e.customErrorHandling(response);
>+        }

No braces around a single-line if.


>-      if (start !== undefined && start >= file.fileSize)
>+      if (start !== undefined && start >= file.fileSize) {
>+        var HTTP_416 = new HttpError(416, "Requested Range Not Satisfiable");
>+        HTTP_416.customErrorHandling = function(errorResponse) {
>+          maybeAddHeaders(file, metadata, errorResponse);
>+        };
>         throw HTTP_416;
>+      }

if (...)
{
  ...
  HTTP_416.customErrorHandling = function(errorResponse)
  {
    maybeAddHeaders(file, metadata, errorResponse);
  };
}


I rely heavily on the xpcshell server tests when making changes to httpd.js, and if this functionality is only tested in a single Mochitest under esoteric timing circumstances, it's much more likely I'll unknowingly break it and only find out when I've "finished" the patch.  r=me if you add netwerk/test/httpserver/test/data/ranges/headers.txt with some sort of contents in it, netwerk/test/httpserver/test/data/ranges/headers.txt^headers^ with this in it:

X-SJS-Header: customized

and something like this stuff to netwerk/test/httpserver/test/test_byte_range.js in the right places:

  new Test(PREFIX + "/headers.txt",
           init_byterange13, start_byterange13, null),


function init_byterange13(ch)
{
  ch.setRequestHeader("Range", "bytes=9999999-", false);
}

function start_byterange13(ch, cx)
{
  do_check_eq(ch.responseStatus, 416);
  do_check_eq(ch.getResponseHeader("X-SJS-Header"), "customized");
}

Comment 29

[Robert O'Callahan (:roc) (email my personal email if necessary)]

> >+      dump("### Set header " + header.substring(0, colon) +
> >+           " to " + header.substring(colon + 1, header.length) + "\n");
> 
> Use dumpn here so you can get rid of the + "\n" at the end, also to avoid
> debug-spew outside of server uses where debug output is enabled.

I'll take it out, I didn't mean to get that checked in.

> No braces around a single-line if.

OK.

> if (...)
> {
>   ...
>   HTTP_416.customErrorHandling = function(errorResponse)
>   {
>     maybeAddHeaders(file, metadata, errorResponse);
>   };
> }

Isn't this quite dangerous? If we could ever have multiple 416-error-objects in flight at the same time, this would break. What's wrong with my way?

> I rely heavily on the xpcshell server tests when making changes to httpd.js,
> and if this functionality is only tested in a single Mochitest under esoteric
> timing circumstances, it's much more likely I'll unknowingly break it and only
> find out when I've "finished" the patch.  r=me if you add
> netwerk/test/httpserver/test/data/ranges/headers.txt with some sort of contents
> in it, netwerk/test/httpserver/test/data/ranges/headers.txt^headers^ with this
> in it:
> 
> X-SJS-Header: customized
> 
> and something like this stuff to
> netwerk/test/httpserver/test/test_byte_range.js in the right places:
> 
>   new Test(PREFIX + "/headers.txt",
>            init_byterange13, start_byterange13, null),
> 
> 
> function init_byterange13(ch)
> {
>   ch.setRequestHeader("Range", "bytes=9999999-", false);
> }
> 
> function start_byterange13(ch, cx)
> {
>   do_check_eq(ch.responseStatus, 416);
>   do_check_eq(ch.getResponseHeader("X-SJS-Header"), "customized");
> }

Sure, thanks.

Comment 30

[Jeff Walden [:Waldo]]

On the general topic of error responses not including A-C-A-O:*, this seems like a wrinkle that's worth raising on some W3C mailing list, that error responses to CORS requests that aren't simply complete failures but that are intended to transmit information may need to be careful to enable cross-origin access.  Maybe a cautionary note is worth adding somewhere in the CORS spec or something.

This is something a service like S3 would need to worry about (or so I gather if our relatively-correct implementation is generating these spurious requests).  I would imagine the add-specific-headers logic on content hosting services might not always have been written to apply to server-generated specific-information-communicating errors.  Broader dissemination of this information to web authors seems like a good idea.

Comment 31

[Jeff Walden [:Waldo]]

(In reply to comment #29)
> > if (...)
> > {
> >   ...
> >   HTTP_416.customErrorHandling = function(errorResponse)
> >   {
> >     maybeAddHeaders(file, metadata, errorResponse);
> >   };
> > }
> 
> Isn't this quite dangerous? If we could ever have multiple 416-error-objects
> in flight at the same time, this would break. What's wrong with my way?

Just the placement of the brace after if (...) and after function(errorResponse), nothing more.  My intent was to say both braces should be on new lines, without laboriously spelling it out -- I guess the way I said it was just confusing, sorry about that.

Comment 32

[Robert O'Callahan (:roc) (email my personal email if necessary)]

ah ok

Comment 33

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

I saw that you raised this issue with the webapps WG. Was the result that any returned response with the appropriate headers should be accepted, no matter what the status code was? Or was it something else?

Comment 34

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Yes, Anne says that headers can be sent with any response code, including any errors. I didn't want to change too much here though, which is why I'm only adding support to whitelist a particular set of response codes.

Comment 35

[Phil Ringnalda (:philor)]

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox-Unittest/1259110580.1259111725.25201.gz
OS X 10.5.2 mozilla-central opt test mochitests-1/5 on 2009/11/24 16:56:20
s: moz2-darwin9-slave07

Comment 36

[Robert O'Callahan (:roc) (email my personal email if necessary)]

http://hg.mozilla.org/mozilla-central/rev/61a17fedca4a
http://hg.mozilla.org/mozilla-central/rev/f99d0f439d59
http://hg.mozilla.org/mozilla-central/rev/7a048955e22b
http://hg.mozilla.org/mozilla-central/rev/c1b429b5eb99

Comment 37

[Legacy TBPL/Treeherder Robot]

philringnalda%gmail.com
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.6/1290160962.1290162972.15411.gz
Linux mozilla-1.9.2 test mochitests on 2010/11/19 02:02:42

s: mv-moz2-linux-ix-slave04
40202 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_access_control.html | Can load cross domain with allow-origin - "error" should equal "loaded"
40204 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_access_control.html | Won't load from subdomain - "loaded" should equal "error"