1319060 - /_mozilla/fetch/api/redirect/redirect-referrer.https.html web-platform-test causing non-utf8 non-http request

Status: RESOLVED WORKSFORME

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

Description

[James Graham [:jgraham]]

Running this test like

./mach wpt /_mozilla/fetch/api/redirect/redirect-referrer.https.html

I see (with some extra logging added):

 0:09.79 LOG: Thread-Log INFO STDOUT: GET /fetch/api/resources/redirect.py?location=http%3A%2F%2Fwww1.web-platform.test%3A8000%2Ffetch%2Fapi%2Fresources%2Finspect-headers.py%3Fcors%26headers%3Dreferer&redirect_referrerpolicy=unsafe-url HTTP/1.1\r\n
 0:09.79 LOG: Thread-Log INFO STDOUT: http://www1.web-platform.test:8000/fetch/api/resources/inspect-headers.py?cors&headers=referer
 0:09.79 LOG: Thread-Log INFO STDOUT: ('127.0.0.1', 42428)
 0:09.88 LOG: Thread-Log INFO STDOUT: ('127.0.0.1', 58122)
 0:09.88 LOG: Thread-Log INFO STDOUT: \x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03\x0e\x87R~\xe2\x92UG\xe6\x18\xd6\xc1\xd1Et\x87\xc1\'8\xea\xda\x90\x8f/\x9f\xf0\xbeD\xfd\xc6\xe3\x98\x00\x00$\x13\x01\x13\x03\x13\x02\xc0+\xc0/\xcc\xa9\xcc\xa8\xc0,\xc00\xc0\n
 0:09.88 LOG: Thread-Log INFO STDERR: 127.0.0.1 - - [21/Nov/2016 10:30:53] code 400, message Bad request syntax ("\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03\x0e\x87R~\xe2\x92UG\xe6\x18\xd6\xc1\xd1Et\x87\xc1'8\xea\xda\x90\x8f/\x9f\xf0\xbeD\xfd\xc6\xe3\x98\x00\x00$\x13\x01\x13\x03\x13\x02\xc0+\xc0/\xcc\xa9\xcc\xa8\xc0,\xc00\xc0")
COMMAND     PID    USER   FD   TYPE  DEVICE SIZE/OFF NODE NAME
python2.7 19773 jgraham    9u  IPv4 3317476      0t0  TCP localhost:8000->localhost:58122 (ESTABLISHED)
firefox   19804 jgraham   82u  IPv4 3316205      0t0  TCP localhost:58122->localhost:8000 (ESTABLISHED)
 0:09.92 LOG: Thread-Log INFO STDOUT: 0
 0:09.92 LOG: Thread-4 wptserve WARNING Traceback (most recent call last):
  File "/home/jgraham/develop/gecko/testing/web-platform/tests/tools/wptserve/wptserve/server.py", line 219, in handle_one_request
    request_is_valid = self.parse_request()
  File "/usr/lib/python2.7/BaseHTTPServer.py", line 286, in parse_request
    self.send_error(400, "Bad request syntax (%r)" % requestline)
  File "/usr/lib/python2.7/BaseHTTPServer.py", line 365, in send_error
    self.send_response(code, message)
  File "/usr/lib/python2.7/BaseHTTPServer.py", line 396, in send_response
    self.log_request(code)
  File "/usr/lib/python2.7/BaseHTTPServer.py", line 433, in log_request
    self.requestline, str(code), str(size))
  File "/usr/lib/python2.7/BaseHTTPServer.py", line 469, in log_message
    format%args))
  File "/home/jgraham/develop/gecko/testing/web-platform/harness/wptrunner/wptlogging.py", line 83, in write
    data = data.decode("utf8")
  File "/usr/lib/python2.7/encodings/utf_8.py", line 16, in decode
    return codecs.utf_8_decode(input, errors, True)
UnicodeDecodeError: 'utf8' codec can't decode byte 0xfc in position 46: invalid start byte

 0:09.92 LOG: Thread-Log INFO STDOUT: ('127.0.0.1', 58124)
 0:09.92 LOG: Thread-Log INFO STDOUT: \x16\x03\x01\x00\xc6\x01\x00\x00\xc2\x03\x03\x00\xb4\xd6~\xd0\xfa\x84\xf6O#\x1d\xc0\xb3?y9\xa1P\x8c\xefo\x04\xb6\xfcAGG\xee;\xd5\xa2\xc5\x00\x00\x1e\xc0+\xc0/\xcc\xa9\xcc\xa8\xc0,\xc00\xc0\n
 0:09.93 LOG: Thread-Log INFO STDERR: 127.0.0.1 - - [21/Nov/2016 10:30:53] code 400, message Bad request syntax ('\x16\x03\x01\x00\xc6\x01\x00\x00\xc2\x03\x03\x00\xb4\xd6~\xd0\xfa\x84\xf6O#\x1d\xc0\xb3?y9\xa1P\x8c\xefo\x04\xb6\xfcAGG\xee;\xd5\xa2\xc5\x00\x00\x1e\xc0+\xc0/\xcc\xa9\xcc\xa8\xc0,\xc00\xc0')
COMMAND     PID    USER   FD   TYPE  DEVICE SIZE/OFF NODE NAME
python2.7 19773 jgraham    9u  IPv4 3319331      0t0  TCP localhost:8000->localhost:58124 (ESTABLISHED)
firefox   19804 jgraham   82u  IPv4 3321891      0t0  TCP localhost:58124->localhost:8000 (ESTABLISHED)
 0:09.96 LOG: Thread-Log INFO STDOUT: 0
 0:09.96 LOG: Thread-5 wptserve WARNING Traceback (most recent call last):
  File "/home/jgraham/develop/gecko/testing/web-platform/tests/tools/wptserve/wptserve/server.py", line 219, in handle_one_request
    request_is_valid = self.parse_request()
  File "/usr/lib/python2.7/BaseHTTPServer.py", line 286, in parse_request
    self.send_error(400, "Bad request syntax (%r)" % requestline)
  File "/usr/lib/python2.7/BaseHTTPServer.py", line 365, in send_error
    self.send_response(code, message)
  File "/usr/lib/python2.7/BaseHTTPServer.py", line 396, in send_response
    self.log_request(code)
  File "/usr/lib/python2.7/BaseHTTPServer.py", line 433, in log_request
    self.requestline, str(code), str(size))
  File "/usr/lib/python2.7/BaseHTTPServer.py", line 469, in log_message
    format%args))
  File "/home/jgraham/develop/gecko/testing/web-platform/harness/wptrunner/wptlogging.py", line 83, in write
    data = data.decode("utf8")
  File "/usr/lib/python2.7/encodings/utf_8.py", line 16, in decode
    return codecs.utf_8_decode(input, errors, True)
UnicodeDecodeError: 'utf8' codec can't decode byte 0xc6 in position 42: invalid continuation byte

From the http log I think this might be a HSTS pining request? But if I understood the spec correctly that should just be a HEAD request, so I'm not sure what's going on here. This causes issues on treeherder.

Comment 1

[James Graham [:jgraham]]

Wireshark dump of the TCP packet (from a different run):

16:03:01:02:00:01:00:01:fc:03:03:58:59:c6:8d:8a:28:ab:5f:00:6f:38:30:e7:06:81:aa:9a:71:df:23:79:21:34:e8:7d:46:8e:c7:54:c9:42:03:00:00:24:13:01:13:03:13:02:c0:2b:c0:2f:cc:a9:cc:a8:c0:2c:c0:30:c0:0a:c0:09:c0:13:c0:14:00:33:00:39:00:2f:00:35:00:0a:01:00:01:af:00:15:00:aa:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:1b:00:19:00:00:16:77:77:77:31:2e:77:65:62:2d:70:6c:61:74:66:6f:72:6d:2e:74:65:73:74:00:17:00:00:ff:01:00:01:00:00:0a:00:0e:00:0c:00:1d:00:17:00:18:00:19:01:00:01:01:00:0b:00:02:01:00:00:23:00:00:00:10:00:0e:00:0c:02:68:32:08:68:74:74:70:2f:31:2e:31:00:05:00:05:01:00:00:00:00:00:12:00:00:00:28:00:6b:00:69:00:1d:00:20:11:88:18:60:aa:2e:ed:17:2c:11:59:52:ca:8c:84:4a:ea:93:ed:9b:c4:8b:c7:93:91:09:32:13:48:f7:1d:73:00:17:00:41:04:49:25:2b:53:db:4b:7c:7f:1e:c5:ba:34:9e:82:f8:96:df:20:aa:df:fb:dd:3a:30:5d:90:63:d7:2c:41:8a:6a:f3:14:c6:2d:9b:bc:50:17:04:df:46:6b:46:42:be:b7:e6:1a:53:a2:ae:35:6e:1a:94:42:db:47:fa:be:b1:e9:00:2b:00:09:08:7f:12:03:03:03:02:03:01:00:0d:00:18:00:16:04:03:05:03:06:03:08:04:08:05:08:06:04:01:05:01:06:01:02:03:02:01:00:2d:00:02:01:01

Comment 2

[Thomas Nguyen (:tnguyen)]

I guess that hsts things caused that.
I try to disable HSTS by adding

--- a/testing/web-platform/mozilla/meta/fetch/api/redirect/redirect-referrer.https.html.ini
+++ b/testing/web-platform/mozilla/meta/fetch/api/redirect/redirect-referrer.https.html.ini
@@ -1,3 +1,3 @@
 [redirect-referrer.https.html]
   type: testharness
-  prefs: [security.mixed_content.block_active_content:false, security.mixed_content.block_display_content:false]
+  prefs: [security.mixed_content.block_active_content:false, security.mixed_content.block_display_content:false, security.mixed_content.send_hsts_priming:false, security.mixed_content.use_hsts:false]

Then the error disappeared. I think we could do that because HSTS is not the testing purpose of this file.

> From the http log I think this might be a HSTS pining request? But if I
> understood the spec correctly that should just be a HEAD request, so I'm not
> sure what's going on here. This causes issues on treeherder.
I don't know exactly the issue you met, could you please try to see if the above diff could fix your issue?

Comment 3

[James Graham [:jgraham]]

That works, but I'm still very confused about what it is that I'm seeing in the logs. I don't want to have to disable HSTS priming for every test that happens to trigger it, so if there's something that I need to change to make the server handle it (or a bug in gecko causing it to send a malformed request ofc), I'd like to know.

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/23fddf70a257
Disable HSTS priming in redirect test to avoid invalid request, a=testonly

Comment 5

[Thomas Nguyen (:tnguyen)]

In bug 1246540, something in the HEAD request is sent which Python's HTTP server doesn't understand as UTF-8, so it returns error 400. I think :kmckinley will have better idea.

Comment 6

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/23fddf70a257

Comment 7

[Kate McKinley [:kmckinley, :Kate]]

Python's BaseHttpServer claims it supports HEAD requests, but it actually doesn't, and it shows up as this error.

This is the line that causes the error. https://github.com/python/cpython/blob/2.7/Lib/BaseHTTPServer.py#L279

I don't think I ever figured out the exact reason it ends up as that garbled byte string, but python string/unicode en/decoding is fragile and error-prone. I believe that the string in "command" is UTF-16, but I don't recall.

Comment 8

[Andrew Overholt [:overholt]]

Is this something we can work around, James?

Comment 9

[James Graham [:jgraham]]

So I don't quite understand why that code would be hit… are we sending the HEAD request without specifying a HTTP version? That seems pretty quirky (and not conform to the http 0.9 "spec" such as it is [1]). I can make wptserve handle that case better I guess by rewriting the parse_request function, but I want to be sure that's actually what's goign on and that it's intentional.

[1] https://www.w3.org/Protocols/HTTP/AsImplemented.html

Comment 10

[Kate McKinley [:kmckinley, :Kate]]

After a bit more investigation, it doesn't look like this is a wptserve issue. The connection is attempting to send TLS over a non-encrypted socket, which doesn't error until it reaches that point in the python code. The reason this is happening is that the server uses a non-default port, so the port doesn't change when the priming request is sent. Bug 1328460 will turn that off, and bug 1325680 will re-enable all the web-platform tests.

Comment 11

[BugBot [:suhaib / :marco/ :calixte]]

The leave-open keyword is there and there is no activity for 6 months.
:hsinyi, maybe it's time to close this bug?

Comment 12

[Hsin-Yi Tsai (she/her) [:hsinyi]]

(In reply to Release mgmt bot [:sylvestre / :calixte] from comment #11)

The leave-open keyword is there and there is no activity for 6 months.
:hsinyi, maybe it's time to close this bug?

Hi James, could you kindly suggest if the bug is still valid? Thanks!