Closed Bug 1307840 Opened 8 years ago Closed 6 years ago

Intermittent UnicodeDecodeError: 'utf8' codec can't decode byte 0xce in position 42: invalid continuation byte in /mixed-content/optionally-blockable/no-opt-in/cross-origin-http/link-prefetch-tag/top-level/keep-scheme-redirect/no-opt-in-allows.https.html

Categories

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

Version 3
defect
Not set
normal

Tracking

(Not tracked)

RESOLVED WORKSFORME

People

(Reporter: aryx, Unassigned)

References

Details

(Keywords: intermittent-failure)

This is a new line in the logs:

https://treeherder.mozilla.org/logviewer.html#?job_id=37091682&repo=mozilla-inbound

https://treeherder.mozilla.org/logviewer.html#?job_id=4531252&repo=autoland

[task 2016-10-05T15:22:09.505548Z] 15:22:09     INFO - TEST-START | /mixed-content/optionally-blockable/no-opt-in/cross-origin-http/link-prefetch-tag/top-level/keep-scheme-redirect/no-opt-in-allows.https.html
[task 2016-10-05T15:22:09.505625Z] 15:22:09     INFO - Clearing pref security.mixed_content.send_hsts_priming
[task 2016-10-05T15:22:09.506493Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929504	Marionette	TRACE	conn3 -> [0,493,"getContext",null]
[task 2016-10-05T15:22:09.509853Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929507	Marionette	TRACE	conn3 <- [1,493,null,{"value":"content"}]
[task 2016-10-05T15:22:09.513273Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929510	Marionette	TRACE	conn3 -> [0,494,"setContext",{"value":"chrome"}]
[task 2016-10-05T15:22:09.514396Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929512	Marionette	TRACE	conn3 <- [1,494,null,{}]
[task 2016-10-05T15:22:09.522253Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929517	Marionette	TRACE	conn3 -> [0,495,"executeScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"executormarionette.py","script":"\n            let prefInterface = Components.classes[\"@mozilla.org/preferences-service;1\"]\n                                          .getService(Components.interfaces.nsIPrefBranch);\n            let pref = 'security.mixed_content.send_hsts_priming';\n            prefInterface.clearUserPref(pref);\n            ","sandbox":"default","line":214}]
[task 2016-10-05T15:22:09.529833Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929527	Marionette	TRACE	conn3 <- [1,495,null,{"value":null}]
[task 2016-10-05T15:22:09.551687Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929550	Marionette	TRACE	conn3 -> [0,496,"setContext",{"value":"content"}]
[task 2016-10-05T15:22:09.555083Z] 15:22:09     INFO - Clearing pref security.mixed_content.use_hsts
[task 2016-10-05T15:22:09.555828Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929552	Marionette	TRACE	conn3 <- [1,496,null,{}]
[task 2016-10-05T15:22:09.559354Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929557	Marionette	TRACE	conn3 -> [0,497,"getContext",null]
[task 2016-10-05T15:22:09.560792Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929559	Marionette	TRACE	conn3 <- [1,497,null,{"value":"content"}]
[task 2016-10-05T15:22:09.564610Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929563	Marionette	TRACE	conn3 -> [0,498,"setContext",{"value":"chrome"}]
[task 2016-10-05T15:22:09.568652Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929566	Marionette	TRACE	conn3 <- [1,498,null,{}]
[task 2016-10-05T15:22:09.572384Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929570	Marionette	TRACE	conn3 -> [0,499,"executeScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"executormarionette.py","script":"\n            let prefInterface = Components.classes[\"@mozilla.org/preferences-service;1\"]\n                                          .getService(Components.interfaces.nsIPrefBranch);\n            let pref = 'security.mixed_content.use_hsts';\n            prefInterface.clearUserPref(pref);\n            ","sandbox":"default","line":214}]
[task 2016-10-05T15:22:09.588410Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929579	Marionette	TRACE	conn3 <- [1,499,null,{"value":null}]
[task 2016-10-05T15:22:09.589391Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929582	Marionette	TRACE	conn3 -> [0,500,"setContext",{"value":"content"}]
[task 2016-10-05T15:22:09.590102Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929584	Marionette	TRACE	conn3 <- [1,500,null,{}]
[task 2016-10-05T15:22:09.590866Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929587	Marionette	TRACE	conn3 -> [0,501,"timeouts",{"script":35000}]
[task 2016-10-05T15:22:09.592878Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929592	Marionette	TRACE	conn3 <- [1,501,null,{}]
[task 2016-10-05T15:22:09.596850Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929595	Marionette	TRACE	conn3 -> [0,502,"executeScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"executormarionette.py","script":"if (window.wrappedJSObject.win) {window.wrappedJSObject.win.close()}","sandbox":"default","line":396}]
[task 2016-10-05T15:22:09.748350Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929744	Marionette	TRACE	conn3 <- [1,502,null,{"value":null}]
[task 2016-10-05T15:22:09.873999Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929869	Marionette	TRACE	conn3 -> [0,503,"executeAsyncScript",{"scriptTimeout":null,"sandbox":"default","debug_script":false,"script":"/* This Source Code Form is subject to the terms of the Mozilla Public\n * License, v. 2.0. If a copy of the MPL was not distributed with this\n * file, You can obtain one at http://mozilla.org/MPL/2.0/. */\n\nwindow.wrappedJSObject.timeout_multiplier = 3;\nwindow.wrappedJSObject.explicit_timeout = 0;\n\nwindow.wrappedJSObject.addEventListener(\"message\", function listener(event) {\n    if (event.data.type != \"complete\") {\n        return;\n    }\n    window.wrappedJSObject.removeEventListener(\"message\", listener);\n    clearTimeout(timer);\n    var tests = event.data.tests;\n    var status = event.data.status;\n\n    var subtest_results = tests.map(function(x) {\n        return [x.name, x.status, x.message, x.stack]\n    });\n\n    marionetteScriptFinished([\"/mixed-content/optionally-blockable/no-opt-in/cross-origin-http/link-prefetch-tag/top-level/keep-scheme-redirect/no-opt-in-allows.https.html\",\n                              status.status,\n                              status.message,\n                              status.stack,\n                              subtest_results]);\n}, false);\n\nwindow.wrappedJSObject.win = window.open(\"https://web-platform.test:8443/mixed-content/optionally-blockable/no-opt-in/cross-origin-http/link-prefetch-tag/top-level/keep-scheme-redirect/no-opt-in-allows.https.html\", \"753d6373-d46c-4c0e-bce6-d60de59f77a4\");\n\nvar timer = null;\nif (30000) {\n    timer = setTimeout(function() {\n        log(\"Timeout fired\");\n        window.wrappedJSObject.win.timeout();\n    }, 30000);\n}\n","newSandbox":false,"line":410,"args":[],"filename":"executormarionette.py"}]
[task 2016-10-05T15:22:09.893947Z] 15:22:09     INFO - PROCESS | 2830 | ++DOCSHELL 0x7f3824d04800 == 52 [pid = 2830] [id = 155]
[task 2016-10-05T15:22:09.894468Z] 15:22:09     INFO - PROCESS | 2830 | ++DOMWINDOW == 92 (0x7f3822fa2c00) [pid = 2830] [serial = 552] [outer = (nil)]
[task 2016-10-05T15:22:09.921996Z] 15:22:09     INFO - PROCESS | 2830 | ++DOMWINDOW == 93 (0x7f3826ad5000) [pid = 2830] [serial = 553] [outer = 0x7f3822fa2c00]
[task 2016-10-05T15:22:09.929759Z] 15:22:09     INFO - PROCESS | 2830 | 1475680929927	Marionette	DEBUG	loaded listener.js
[task 2016-10-05T15:22:10.010993Z] 15:22:10     INFO - PROCESS | 2830 | ++DOMWINDOW == 94 (0x7f37fdce7c00) [pid = 2830] [serial = 554] [outer = 0x7f3822fa2c00]
[task 2016-10-05T15:22:10.334923Z] 15:22:10     INFO - STDERR: 127.0.0.1 - - [05/Oct/2016 15:22:10] code 400, message Bad request syntax ('\x16\x03\x01\x00\xce\x01\x00\x00\xca\x03\x03\xd5\xdfQ|]\x89\x81\x16.\xbe\x9f+\xe8\x84Em^\x80h\xa0Ol\xa7\xf6\xe5O\x1d\x1f"\xa1\x8f\x19\x00\x00\x1e\xc0+\xc0/\xcc\xa9\xcc\xa8\xc0,\xc00\xc0')
[task 2016-10-05T15:22:10.336833Z] 15:22:10  WARNING - wptserve Traceback (most recent call last):
[task 2016-10-05T15:22:10.336935Z] 15:22:10  WARNING -   File "/home/worker/workspace/build/tests/web-platform/tests/tools/wptserve/wptserve/server.py", line 214, in handle_one_request
[task 2016-10-05T15:22:10.337674Z] 15:22:10  WARNING -     request_is_valid = self.parse_request()
[task 2016-10-05T15:22:10.340427Z] 15:22:10  WARNING -   File "/usr/lib/python2.7/BaseHTTPServer.py", line 286, in parse_request
[task 2016-10-05T15:22:10.340505Z] 15:22:10  WARNING -     self.send_error(400, "Bad request syntax (%r)" % requestline)
[task 2016-10-05T15:22:10.340566Z] 15:22:10  WARNING -   File "/usr/lib/python2.7/BaseHTTPServer.py", line 365, in send_error
[task 2016-10-05T15:22:10.340616Z] 15:22:10  WARNING -     self.send_response(code, message)
[task 2016-10-05T15:22:10.340674Z] 15:22:10  WARNING -   File "/usr/lib/python2.7/BaseHTTPServer.py", line 396, in send_response
[task 2016-10-05T15:22:10.340719Z] 15:22:10  WARNING -     self.log_request(code)
[task 2016-10-05T15:22:10.340775Z] 15:22:10  WARNING -   File "/usr/lib/python2.7/BaseHTTPServer.py", line 433, in log_request
[task 2016-10-05T15:22:10.341212Z] 15:22:10  WARNING -     self.requestline, str(code), str(size))
[task 2016-10-05T15:22:10.341708Z] 15:22:10  WARNING -   File "/usr/lib/python2.7/BaseHTTPServer.py", line 469, in log_message
[task 2016-10-05T15:22:10.342201Z] 15:22:10  WARNING -     format%args))
[task 2016-10-05T15:22:10.342707Z] 15:22:10  WARNING -   File "/home/worker/workspace/build/tests/web-platform/harness/wptrunner/wptlogging.py", line 83, in write
[task 2016-10-05T15:22:10.343201Z] 15:22:10  WARNING -     data = data.decode("utf8")
[task 2016-10-05T15:22:10.343704Z] 15:22:10  WARNING -   File "/home/worker/workspace/build/venv/lib/python2.7/encodings/utf_8.py", line 16, in decode
[task 2016-10-05T15:22:10.344190Z] 15:22:10  WARNING -     return codecs.utf_8_decode(input, errors, True)
[task 2016-10-05T15:22:10.344721Z] 15:22:10  WARNING - UnicodeDecodeError: 'utf8' codec can't decode byte 0xce in position 42: invalid continuation byte
[task 2016-10-05T15:22:10.345203Z] 15:22:10  WARNING - 
[task 2016-10-05T15:22:10.420891Z] 15:22:10     INFO - PROCESS | 2830 | 1475680930415	Marionette	TRACE	conn3 <- [1,503,null,{"value":["/mixed-content/optionally-blockable/no-opt-in/cross-origin-http/link-prefetch-tag/top-level/keep-scheme-redirect/no-opt-in-allows.https.html",0,null,null,[["opt_in_method: no-opt-in\n                                 origin: cross-origin-http\n                                 source_scheme: https\n                                 context_nesting: top-level\n                                 redirection: keep-scheme-redirect\n                                 subresource: link-prefetch-tag\n                                 expectation: allowed",1,"assert_equals: The resource request should be 'allowed'. expected \"allowed\" but got \"blocked\"","runTest/</<@https://web-platform.test:8443/mixed-content/generic/mixed-content-test-case.js?pipe=sub:153:12\nTest.prototype.step@https://web-platform.test:8443/resources/testharness.js:1403:20\nrunTest/<@https://web-platform.test:8443/mixed-content/generic/mixed-content-test-case.js?pipe=sub:152:10\nAsync*runTest@https://web-platform.test:8443/mixed-content/generic/mixed-content-test-case.js?pipe=sub:121:5\n@https://web-platform.test:8443/mixed-content/optionally-blockable/no-opt-in/cross-origin-http/link-prefetch-tag/top-level/keep-scheme-redirect/no-opt-in-allows.https.html:24:7\n"]]]}]
[task 2016-10-05T15:22:10.461783Z] 15:22:10     INFO - .
[task 2016-10-05T15:22:10.462798Z] 15:22:10     INFO - TEST-OK | /mixed-content/optionally-blockable/no-opt-in/cross-origin-http/link-prefetch-tag/top-level/keep-scheme-redirect/no-opt-in-allows.https.html | took 959ms
Flags: needinfo?(james)
This seems to be related to HSTS priming requests. I have no idea why they are resulting in invalid UTF8, but disabling it for these tests causes the problem to go away.
Flags: needinfo?(james)
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.