1310307 - web-platform-tests broken on Windows 10 due to invalid structured log messages

Status: RESOLVED FIXED

(Testing :: web-platform-tests, defect)

Description

[Ryan VanderMeulen [:RyanVM]]

I've bisected this issue on Try down to bug 1305877.

Talking to James, I believe he's having the same issues on other versions of Windows as well when testing his most recent wpt import.

https://archive.mozilla.org/pub/firefox/try-builds/[e-mail]-22141ace3fd96af49d267dbc999d9b69c3b865e1/try-win64/try_win10_64_test-web-platform-tests-1-bm109-tests1-windows-build6.txt.gz

11:12:39 CRITICAL - Test harness output was not a valid structured log message: 
11:12:39 CRITICAL - T-W1064-IX-0002.releng.ad.mozilla.com - - [14/Oct/2016 11:01:04] code 400, message Bad HTTP/0.9 request type ('\x16\x03\x01\x00\xce\x01\x00\x00\xca\x03\x03u\x97\xa8\xaa\xdfQ?\x8b\xa0\x06\x81\x1e\x94&G\xe0\xd7\xb8')
11:12:39 CRITICAL - Test harness output was not a valid structured log message: 
11:12:39 CRITICAL - T-W1064-IX-0002.releng.ad.mozilla.com - - [14/Oct/2016 11:01:04] "�����u����Q?���
11:12:39 CRITICAL - �&G�׸	��꿷��s�x|���
11:12:39 CRITICAL - �+�/̨̩�,�0�" 400 -

Comment 1

[Gregory Szorc [:gps]]

I'm not sure why I'm needinfo'd here, as I'm not much of a subject matter expert on WPT.

The error message "Bad HTTP/0.9 request type" does seem to point to a client sending bad input to an HTTP server or the internal state of some HTTP server getting out of whack. This can happen when multiple HTTP requests are sent to the same TCP socket and either the client or server aborts sending/receiving an HTTP request body and the server tries to process a new HTTP request starting from the body of a previous request. That would explain the binary bytes being interpreted as the HTTP request method (the first line of a HTTP request is e.g. "GET HTTP/1.1"). Well behaved clients/servers need to abort the TCP connection if they can't guarantee the entire HTTP request body was consumed.

Comment 2

[James Graham [:jgraham]]

So I tracked this down in a wpt import; it seems like with the websockets tests on Windows the websocket server has always been complaining about this for some reason, but previously the warning message wasn't being logged. I don't know why this would have changed in win 10 after the rechunking specifically (on my branch it changed because another change affected the global logging configuration; I guess a similar thing could have happened here is another test reconfigures the logging).

Comment 3

[Ryan VanderMeulen [:RyanVM]]

Still busted from the looks of it.
https://treeherder.mozilla.org/#/jobs?repo=try&revision=a9103ce0cbb1&group_state=expanded

Comment 4

[James Graham [:jgraham]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=d8cb87cd4838ab2e20b6b29ada608a56933a8909&selectedJob=32198741 is this with HSTS priming disabled for a few tests. I don't know why that causes the issue, but it seems that it does.

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/b03bd6dc3d8f
Disable HSTS priming in some mixed content tests where it causes a bogus request, a=testonly

Comment 6

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

https://hg.mozilla.org/mozilla-central/rev/b03bd6dc3d8f