Skip to content

/ servo

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

HTTP connection pooling occasionally terminates response bodies early #15694

Closed
jdm opened this issue Feb 22, 2017 · 5 comments
Closed

HTTP connection pooling occasionally terminates response bodies early #15694

jdm opened this issue Feb 22, 2017 · 5 comments
Assignees
@nox
Labels
A-network

Comments

@jdm
Copy link
Member

@jdm jdm commented Feb 22, 2017

With #14620 applied, when I run ./mach test-wpt tests/wpt/web-platform-tests/fetch/nosniff/parsing-nosniff.html, I see two consistent test failures. When I apply the following patch:

diff --git a/components/net/resource_thread.rs b/components/net/resource_thread.rs
index 925b5e1..f70a210 100644
--- a/components/net/resource_thread.rs
+++ b/components/net/resource_thread.rs
@@ -325,7 +325,7 @@ impl CoreResourceManager {
             cookie_jar: group.cookie_jar.clone(),
             auth_cache: group.auth_cache.clone(),
             blocked_content: BLOCKED_CONTENT_RULES.clone(),
-            connector_pool: group.connector.clone(),
+            connector_pool: create_http_connector("certs"),
         };
         let ua = self.user_agent.clone();
         let dc = self.devtools_chan.clone();

the test failures consistently go away. The trace output from hyper shows the following the problematic case (when I comment out all but the two failing cases):

 0:04.75 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "DEBUG:hyper::http::h1: request line: Get "/fetch/nosniff/resources/nosniff-quoted.asis" Http11"
 0:04.75 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "DEBUG:hyper::http::h1: headers=Headers { Accept: */*"
 0:04.75 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", Accept-Language: en-US, en; q=0.5"
 0:04.75 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", Referer: http://web-platform.test:8000/fetch/nosniff/parsing-nosniff.html"
 0:04.75 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", User-Agent: Servo/wptrunner"
 0:04.75 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", Host: web-platform.test:8000"
 0:04.75 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", Accept-Encoding: gzip, deflate, br"
 0:04.75 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", }"
 0:04.75 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::client::response: Response::with_message"
 0:04.75 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::client::pool: previous_response_expected_no_content false"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::http::h1: previous_response_expected_no_content = false"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::buffer: get_buf []"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::buffer: read_into_buf buf[0..4096]"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::buffer: get_buf [u8; 4096][0..131]"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::http::h1: try_parse([72, 84, 84, 80, 47, 49, 46, 49, 32, 50, 48, 48, 32, 89, 79, 85, 32, 72, 65, 86, 69, 32, 78, 79, 32, 80, 79, 87, 69, 82, 32, 72, 69, 82, 69, 10, 67, 111, 110, 116, 101, 110, 116, 45, 76, 101, 110, 103, 116, 104, 58, 32, 50, 50, 10, 67, 111, 110, 116, 101, 110, 116, 45, 84, 121, 112, 101, 58, 32, 120, 47, 120, 10, 88, 45, 67, 111, 110, 116, 101, 110, 116, 45, 84, 121, 112, 101, 45, 79, 112, 116, 105, 111, 110, 115, 58, 32, 34, 110, 111, 115, 110, 105, 70, 70, 34, 10, 10, 47, 47, 32, 110, 111, 116, 104, 105, 110, 103, 32, 116, 111, 32, 115, 101, 101, 32, 104, 101, 114, 101, 10])"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::http::h1: Response.try_parse([Header; 100], [u8; 131])"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::http::h1: Response.try_parse Complete(108)"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: raw header: "Content-Length"=[50, 50]"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: raw header: "Content-Type"=[120, 47, 120]"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: raw header: "X-Content-Type-Options"=[34, 110, 111, 115, 110, 105, 70, 70, 34]"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::http::h1: should_have_response_body(Get, 200)"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::client::pool: set_previous_response_expected_no_content false"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::http::h1: Http11Message.reader = SizedReader(remaining=22)"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "DEBUG:hyper::client::response: version=Http11, status=Ok"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "DEBUG:hyper::client::response: headers=Headers { Content-Length: 22"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", Content-Type: x/x"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", X-Content-Type-Options: "nosniFF""
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", }"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.set( "Content-Type", ContentType(Mime(Ext("x"), Ext("x"), [])) )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.set( "Content-Type", ContentType(Mime(Ext("x"), Ext("x"), [])) )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::http::h1: Sized read, remaining=22"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.set( "Content-Type", ContentType(Mime(Ext("x"), Ext("x"), [])) )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::http::h1: Sized read: 22"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::http::h1: Sized read, remaining=0"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::client::response: Response.drop is_drained=true"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::http: should_keep_alive( Http11, None )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::client::pool: PooledStream.drop, is_closed=false"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::client::pool: reuse ("127.0.0.1", 8000, Http)"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.set_raw( "Content-Length", [[50, 50]] )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.set_raw( "Content-Type", [[120, 47, 120]] )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.set_raw( "X-Content-Type-Options", [[34, 110, 111, 115, 110, 105, 70, 70, 34]] )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.set( "Accept", Accept([QualityItem { item: Mime(Star, Star, []), quality: Quality(1000) }]) )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.set( "Accept-Language", AcceptLanguage([QualityItem { item: LanguageTag { language: Some("en"), extlangs: [], script: None, region: Some("US"), variants: [], extensions: {}, privateuse: [] }, quality: Quality(1000) }, QualityItem { item: LanguageTag { language: Some("en"), extlangs: [], script: None, region: None, variants: [], extensions: {}, privateuse: [] }, quality: Quality(500) }]) )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.remove( "Referer" )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.set( "Referer", Referer("http://web-platform.test:8000/fetch/nosniff/parsing-nosniff.html") )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.set( "User-Agent", UserAgent("Servo/wptrunner") )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.set( "Host", Host { hostname: "web-platform.test", port: Some(8000) } )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.set( "Accept-Encoding", AcceptEncoding([QualityItem { item: Gzip, quality: Quality(1000) }, QualityItem { item: Deflate, quality: Quality(1000) }, QualityItem { item: EncodingExt("br"), quality: Quality(1000) }]) )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.set_raw( "Content-Length", [[50, 50]] )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::client: host="127.0.0.1""
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::client: port=8000"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::client::pool: Pool had connection, using"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::client: host="127.0.0.1""
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::client: port=8000"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.set( "Host", Host { hostname: "127.0.0.1", port: Some(8000) } )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "DEBUG:hyper::http::h1: request line: Get "/fetch/nosniff/resources/nosniff-no-x.asis" Http11"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "DEBUG:hyper::http::h1: headers=Headers { Accept: */*"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", Accept-Language: en-US, en; q=0.5"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", Referer: http://web-platform.test:8000/fetch/nosniff/parsing-nosniff.html"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", User-Agent: Servo/wptrunner"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", Host: web-platform.test:8000"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", Accept-Encoding: gzip, deflate, br"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", }"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::client::response: Response::with_message"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::client::pool: previous_response_expected_no_content false"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::http::h1: previous_response_expected_no_content = false"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.set_raw( "Content-Type", [[120, 47, 120]] )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.set_raw( "X-Content-Type-Options", [[34, 110, 111, 115, 110, 105, 70, 70, 34]] )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::buffer: get_buf []"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::buffer: read_into_buf buf[0..4096]"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::client::pool: PooledStream.drop, is_closed=true"
@jdm jdm added the A-network label Feb 22, 2017
@jdm
Copy link
Member Author

@jdm jdm commented Feb 22, 2017

I propose disabling pooling for the time being and seeing if anything changes after upgrading hyper.
This was referenced Feb 22, 2017
Merged
Merged
bors-servo added a commit that referenced this issue Feb 22, 2017
@bors-servo
Auto merge of #15696 - jdm:no-http-pool, r=<try>
Loading status checks…
3ae9ca3 
Do not pool HTTP connections.

HTTP connection pooling triggers consistent failures in #14620. Let's disable it until there's more time to solve the underlying problem in #15694.

---
- [X] `./mach build -d` does not report any errors
- [X] `./mach test-tidy` does not report any errors
- [X] There are tests for these changes
bors-servo added a commit that referenced this issue Feb 23, 2017
@bors-servo
Auto merge of #15696 - jdm:no-http-pool, r=<try>
Loading status checks…
3e6c200 
Do not pool HTTP connections.

HTTP connection pooling triggers consistent failures in #14620. Let's disable it until there's more time to solve the underlying problem in #15694.

---
- [X] `./mach build -d` does not report any errors
- [X] `./mach test-tidy` does not report any errors
- [X] There are tests for these changes

<!-- Reviewable:start -->
---
This change is [<img src="https://reviewable.io/review_button.svg" height="34" align="absmiddle" alt="Reviewable"/>](https://reviewable.io/reviews/servo/servo/15696)
<!-- Reviewable:end -->
bors-servo added a commit that referenced this issue Feb 23, 2017
@bors-servo
Auto merge of #15696 - jdm:no-http-pool, r=emilio
Loading status checks…
a780f6f 
Do not pool HTTP connections.

HTTP connection pooling triggers consistent failures in #14620. Let's disable it until there's more time to solve the underlying problem in #15694.

---
- [X] `./mach build -d` does not report any errors
- [X] `./mach test-tidy` does not report any errors
- [X] There are tests for these changes

<!-- Reviewable:start -->
---
This change is [<img src="https://reviewable.io/review_button.svg" height="34" align="absmiddle" alt="Reviewable"/>](https://reviewable.io/reviews/servo/servo/15696)
<!-- Reviewable:end -->
@nox nox self-assigned this Mar 31, 2017
@nox
Copy link
Member

@nox nox commented Mar 31, 2017

Should I enable pooling again now that the hyper bump landed?
@jdm
Copy link
Member Author

@jdm jdm commented Mar 31, 2017

We can certainly see what happens!
bors-servo added a commit that referenced this issue Mar 31, 2017
@bors-servo
Auto merge of #16209 - nox:net, r=<try>
Loading status checks…
9fdf48f 
Enable HTTP pooling again (fixes #15694)
bors-servo added a commit that referenced this issue Mar 31, 2017
@bors-servo
Auto merge of #16209 - nox:net, r=jdm
Loading status checks…
325713a 
Enable HTTP pooling again (fixes #15694)

<!-- Reviewable:start -->
This change is [<img src="https://reviewable.io/review_button.svg" height="34" align="absmiddle" alt="Reviewable"/>](https://reviewable.io/reviews/servo/servo/16209)
<!-- Reviewable:end -->
@jdm jdm reopened this Apr 1, 2017
@jdm
Copy link
Member Author

@jdm jdm commented Apr 1, 2017

After #16209 merged, the no-sniff tests started having intermittent failures again:


  ▶ Unexpected subtest result in /fetch/nosniff/parsing-nosniff.html:
  │ FAIL [expected PASS] URL query: no-x
  └   → assert_unreached: Unexpected error event Reached unreachable code

This is still broken, it turns out.
@jdm jdm mentioned this issue Apr 1, 2017
Merged
3 of 3 tasks complete
@bors-servo bors-servo closed this in 30fad4e Apr 1, 2017
@jdm jdm reopened this Apr 2, 2017
@nox
Copy link
Member

@nox nox commented Apr 3, 2017

From your logs:

 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "DEBUG:hyper::http::h1: request line: Get "/fetch/nosniff/resources/nosniff-no-x.asis" Http11"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "DEBUG:hyper::http::h1: headers=Headers { Accept: */*"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", Accept-Language: en-US, en; q=0.5"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", Referer: http://web-platform.test:8000/fetch/nosniff/parsing-nosniff.html"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", User-Agent: Servo/wptrunner"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", Host: web-platform.test:8000"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", Accept-Encoding: gzip, deflate, br"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) ", }"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::client::response: Response::with_message"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::client::pool: previous_response_expected_no_content false"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::http::h1: previous_response_expected_no_content = false"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.set_raw( "Content-Type", [[120, 47, 120]] )"
 0:04.76 PROCESS_OUTPUT: Thread-TestrunnerManager-1 (pid:38135) "TRACE:hyper::header: Headers.set_raw( "X-Content-Type-Options", [[34, 110, 111, 115, 110, 105, 70, 70, 34]] )"

If that response indeed is what hyper thought it received for nosniff-no-x, there is a serious issue somewhere. That test is supposed to send a Content-Type-Options header and hyper thinks it received a X-Content-Type-Options.
@jdm jdm mentioned this issue Apr 4, 2017
Merged
4 of 4 tasks complete
bors-servo added a commit that referenced this issue Apr 4, 2017
@bors-servo
Auto merge of #16262 - jdm:connection-pool, r=<try>
Loading status checks…
f7dd5d6 
Enable HTTP connection pooling

- [X] `./mach build -d` does not report any errors
- [X] `./mach test-tidy` does not report any errors
- [X] These changes fix #15694
- [X] There are tests for these changes

<!-- Reviewable:start -->
---
This change is [<img src="https://reviewable.io/review_button.svg" height="34" align="absmiddle" alt="Reviewable"/>](https://reviewable.io/reviews/servo/servo/16262)
<!-- Reviewable:end -->
bors-servo added a commit that referenced this issue Apr 5, 2017
@bors-servo
Auto merge of #16262 - jdm:connection-pool, r=nox
Loading status checks…
c2f3cf0 
Enable HTTP connection pooling

- [X] `./mach build -d` does not report any errors
- [X] `./mach test-tidy` does not report any errors
- [X] These changes fix #15694
- [X] There are tests for these changes

<!-- Reviewable:start -->
---
This change is [<img src="https://reviewable.io/review_button.svg" height="34" align="absmiddle" alt="Reviewable"/>](https://reviewable.io/reviews/servo/servo/16262)
<!-- Reviewable:end -->
clementmiao added a commit to clementmiao/servo that referenced this issue Apr 7, 2017
@nox @clementmiao
Enable HTTP pooling again (fixes servo#15694)
ead88f5
clementmiao added a commit to clementmiao/servo that referenced this issue Apr 7, 2017
@jdm @clementmiao
Revert "Enable HTTP pooling again (fixes servo#15694)".
178d209
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@nox nox

Labels
A-network
Projects
None yet
Milestone
No milestone
Linked pull requests

Successfully merging a pull request may close this issue.

Enable HTTP connection pooling
2 participants
@jdm @nox
You can’t perform that action at this time.