Unexpected retried XHR requests on ERR_CONNECTION_CLOSED
Reported by
james@wheare.org,
Sep 2 2016
|
|||
Issue descriptionUserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36 Example URL: Steps to reproduce the problem: 1. Make a long running XHR request that eventually is closed by the webserver What is the expected behavior? The request fails when the webserver closes he connection What went wrong? The request is instead retried with HTTP_TRANSACTION_RESTART_AFTER_ERROR Did this work before? N/A Chrome version: 52.0.2743.116 Channel: stable OS Version: OS X 10.11.6 Flash Version: Shockwave Flash 22.0 r0 This seems related to the closed issue 447463 I experienced this behaviour while testing an application where I'm deliberately making the request hang forever (to diagnose a separate bug). I have haproxy running on port 443 configured with a 40s timeout on both server and client: timeout server 40s timeout client 40s When making a request to https://mydomain.com/example (url changed for privacy) haproxy forwards it to my application which is setup with an infinite hang. After 40s the connection is closed. I would expect chrome to immediately cancel the request, but instead it retries, taking another 40s before finally failing, and making a spurious request to my application. This might be undesirable if the application is already under load, with multiple clients all making similar requests it would double the load. In the timing tab of the devtools network inspector the first request is shown as "Stalled" and the second as "Waiting (TTFB)" (see screenshot) If the full net-internals-log.json is needed, I can email it in private, but I'd rather not post it publicly, unless there's an easy way for me to filter out all the other unrelated requests that it contains. Here's the output from chrome://net-internals/ for that specific request. 3657464: URL_REQUEST https://mydomain.com/example Start Time: 2016-09-02 14:05:06.391 t= 3779 [st= 0] +REQUEST_ALIVE [dt=80021] t= 3782 [st= 3] +URL_REQUEST_DELEGATE [dt=1] t= 3782 [st= 3] DELEGATE_INFO [dt=1] --> delegate_info = "extension Adblock Plus" t= 3783 [st= 4] DELEGATE_INFO [dt=0] --> delegate_info = "extension Adblock Plus" t= 3783 [st= 4] -URL_REQUEST_DELEGATE t= 3783 [st= 4] +URL_REQUEST_START_JOB [dt=80016] --> load_flags = 33026 (BYPASS_CACHE | MAYBE_USER_GESTURE | VERIFY_EV_CERT) --> method = "GET" --> priority = "MEDIUM" --> url = "https://mydomain.com/example" t= 3783 [st= 4] +URL_REQUEST_DELEGATE [dt=2] t= 3783 [st= 4] DELEGATE_INFO [dt=1] --> delegate_info = "extension Tampermonkey" t= 3784 [st= 5] DELEGATE_INFO [dt=1] --> delegate_info = "extension User-Agent Switcher for Google Chrome" t= 3785 [st= 6] -URL_REQUEST_DELEGATE t= 3785 [st= 6] HTTP_CACHE_GET_BACKEND [dt=0] t= 3785 [st= 6] HTTP_CACHE_DOOM_ENTRY [dt=1] --> net_error = -2 (ERR_FAILED) t= 3786 [st= 7] HTTP_CACHE_CREATE_ENTRY [dt=0] t= 3786 [st= 7] HTTP_CACHE_ADD_TO_ENTRY [dt=0] t= 3786 [st= 7] URL_REQUEST_DELEGATE [dt=0] t= 3786 [st= 7] +HTTP_STREAM_REQUEST [dt=0] t= 3786 [st= 7] HTTP_STREAM_REQUEST_STARTED_JOB --> source_dependency = 3657467 (HTTP_STREAM_JOB) t= 3786 [st= 7] HTTP_STREAM_REQUEST_BOUND_TO_JOB --> source_dependency = 3657467 (HTTP_STREAM_JOB) t= 3786 [st= 7] -HTTP_STREAM_REQUEST t= 3786 [st= 7] AUTH_SERVER [dt=0] t= 3786 [st= 7] +HTTP_TRANSACTION_SEND_REQUEST [dt=1] t= 3786 [st= 7] HTTP_TRANSACTION_SEND_REQUEST_HEADERS --> GET /example HTTP/1.1 Host: mydomain.com Connection: keep-alive Pragma: no-cache Cache-Control: no-cache Authorization: Basic [20 bytes were stripped] Accept: application/json, text/javascript, */*; q=0.01 X-Requested-With: XMLHttpRequest User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36 DNT: 1 Referer: https://mydomain.com/ Accept-Encoding: gzip, deflate, sdch, br Accept-Language: en-US,en;q=0.8 Cookie: [96 bytes were stripped] t= 3787 [st= 8] -HTTP_TRANSACTION_SEND_REQUEST t= 3787 [st= 8] +HTTP_TRANSACTION_READ_HEADERS [dt=40006] t= 3787 [st= 8] HTTP_STREAM_PARSER_READ_HEADERS [dt=40005] --> net_error = -100 (ERR_CONNECTION_CLOSED) t=43792 [st=40013] HTTP_TRANSACTION_RESTART_AFTER_ERROR --> net_error = -100 (ERR_CONNECTION_CLOSED) t=43793 [st=40014] -HTTP_TRANSACTION_READ_HEADERS t=43793 [st=40014] +HTTP_STREAM_REQUEST [dt=5] t=43793 [st=40014] HTTP_STREAM_REQUEST_STARTED_JOB --> source_dependency = 3657674 (HTTP_STREAM_JOB) t=43798 [st=40019] HTTP_STREAM_REQUEST_BOUND_TO_JOB --> source_dependency = 3657674 (HTTP_STREAM_JOB) t=43798 [st=40019] -HTTP_STREAM_REQUEST t=43798 [st=40019] AUTH_SERVER [dt=0] t=43798 [st=40019] +HTTP_TRANSACTION_SEND_REQUEST [dt=0] t=43798 [st=40019] HTTP_TRANSACTION_SEND_REQUEST_HEADERS --> GET /example HTTP/1.1 Host: mydomain.com Connection: keep-alive Pragma: no-cache Cache-Control: no-cache Authorization: Basic [20 bytes were stripped] Accept: application/json, text/javascript, */*; q=0.01 X-Requested-With: XMLHttpRequest User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/52.0.2743.116 Safari/537.36 DNT: 1 Referer: https://mydomain.com/ Accept-Encoding: gzip, deflate, sdch, br Accept-Language: en-US,en;q=0.8 Cookie: [96 bytes were stripped] t=43798 [st=40019] -HTTP_TRANSACTION_SEND_REQUEST t=43798 [st=40019] +HTTP_TRANSACTION_READ_HEADERS [dt=40000] t=43798 [st=40019] HTTP_STREAM_PARSER_READ_HEADERS [dt=40000] t=83798 [st=80019] HTTP_TRANSACTION_READ_RESPONSE_HEADERS --> HTTP/1.0 504 Gateway Time-out Cache-Control: no-cache Connection: close Content-Type: text/html t=83798 [st=80019] -HTTP_TRANSACTION_READ_HEADERS t=83798 [st=80019] HTTP_CACHE_WRITE_INFO [dt=0] t=83798 [st=80019] HTTP_CACHE_WRITE_DATA [dt=0] t=83798 [st=80019] HTTP_CACHE_WRITE_INFO [dt=0] t=83798 [st=80019] +URL_REQUEST_DELEGATE [dt=1] t=83798 [st=80019] DELEGATE_INFO [dt=1] --> delegate_info = "extension Tampermonkey" t=83799 [st=80020] -URL_REQUEST_DELEGATE t=83799 [st=80020] -URL_REQUEST_START_JOB t=83799 [st=80020] URL_REQUEST_DELEGATE [dt=1] t=83800 [st=80021] HTTP_TRANSACTION_READ_BODY [dt=0] t=83800 [st=80021] HTTP_CACHE_WRITE_DATA [dt=0] t=83800 [st=80021] URL_REQUEST_JOB_BYTES_READ --> byte_count = 92 t=83800 [st=80021] HTTP_TRANSACTION_READ_BODY [dt=0] t=83800 [st=80021] HTTP_CACHE_WRITE_DATA [dt=0] t=83800 [st=80021] -REQUEST_ALIVE
,
Sep 2 2016
We'll only do this on stale sockets (Either already used, or preconnected before use). Because of the preconnect case, just using "Connection: Close" wouldn't actually circumvent the issue (And doing that is really a bad idea, for other reasons, obviously).
,
Sep 2 2016
The log I pasted does show a 504 Gateway Time-out getting sent and received the second time. I presume it's also being sent the first time as the requests are the same, but there may be something else going on with reused sockets (either with Chrome or haproxy) that I don't quite understand. I'll have a closer look to see exactly what's happening on the server.
,
Sep 2 2016
Maybe you're closing the sock too soon after sending the message, so we're only getting it inconsistently? Anyhow, if you find evidence that we're getting the initial 504, but still retrying, by using Wireshark or something, I'll be happy to investigate. Assigning to myself and adding the Needs-Feedback label, to indicate the ball is in your court.
,
Sep 2 2016
I checked with Charles proxy, and indeed the 504 response isn't being sent on the first request. I believe this was a bug in HAProxy that's fixed in a newer version: https://www.mail-archive.com/haproxy@formilux.org/msg20505.html I'll see if an upgrade fixes it, but either way you can close out this bug. Thanks for the explanation of the retry logic, makes sense.
,
Sep 2 2016
Upgrading HAProxy fixed it.
,
Sep 2 2016
Thanks for the followup! Closing the issue. |
|||
►
Sign in to add a comment |
|||
Comment 1 by mmenke@chromium.org
, Sep 2 2016