New issue
Advanced search Search tips

Issue 756063 link

Starred by 2 users
Status: Unconfirmed
Owner: ----
Cc:
pauljensen@chromium.org
b...@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Windows
Pri: 2
Type: Bug



Sign in to add a comment

Long intermittent connection stalls when using an HTTP2 proxy

Reported by k...@luminance.org, Aug 16 2017 
UserAgent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:56.0) Gecko/20100101 Firefox/56.0

Steps to reproduce the problem:
1. Use rich web applications over a HTTP2 proxy with developer tools' network panel open

What is the expected behavior?
No unexplained stalls in requests

What went wrong?
When I play browser games or access other web applications directly via Chrome I get pretty consistent timings because I have a good connection. If I access the same games/applications through an HTTP2 proxy (with the proxy located near to the applications' servers) the latency is dramatically lower, because the HTTP2 proxy is doing the HTTP handshakes and what have you. Unfortunately, requests through the HTTP2 proxy randomly stall for multiple seconds at a time, and this seems to be occurring in Chrome's network stack, not on the proxy.

Did this work before? N/A 

Chrome version: 60.0.3112.90 (Official Build) (64-bit) (cohort: Stable) Revision	6ee4392c6cef820c64ff50b5fd5eeb8596cd0394-refs/branch-heads/3112@{#702}  Channel: stable
OS Version: 10.0
Flash Version: 

I'm pretty certain this isn't an issue with the proxy, since it's a very simple stock installation of squid (for proxying http requests) and nghttpx (for http2). Everything works great except for when a request stalls.

It's hard to find relevant info, but in chrome://tracing the stalled requests look like weird stuff happened. I managed to capture one and I'll paste it in a comment below.

This seems like it might be a variation on issue 473259, but I'm not sure.

Comment 1 by k...@luminance.org, Aug 16 2017 

Here's a tracing entry from a request that stalled. It's an AJAX request that pulls some data down from the remote server. It typically takes 300-600ms when connected directly, and via the proxy it typically takes 200-400ms. You can see in the tracing entry that it seems like the request completed remotely (on the proxy) very quickly and then things just... stalled, for multiple seconds, for no reason that is obvious to me. The actual content body of the stalled requests is always very small.

While using the proxy I see these stalls on a regular basis, once every minute or two. They occur even if I have no other tabs or websites open.


950: URL_REQUEST
http://game.granbluefantasy.jp/quest/content/supporter/720361/1/0?_=1502902914723&t=1502902924503&uid=10777899
Start Time: 2017-08-16 10:02:04.503

t=12812 [st=   0] +REQUEST_ALIVE  [dt=2383]
                   --> priority = "MEDIUM"
                   --> url = "http://game.granbluefantasy.jp/quest/content/supporter/720361/1/0?_=1502902914723&t=1502902924503&uid=10777899"
t=12813 [st=   1]   +URL_REQUEST_DELEGATE  [dt=0]
t=12813 [st=   1]      DELEGATE_INFO  [dt=0]
                       --> delegate_blocked_by = "extension uBlock Origin"
t=12813 [st=   1]   -URL_REQUEST_DELEGATE
t=12813 [st=   1]   +URL_REQUEST_START_JOB  [dt=375]
                     --> load_flags = 256 (VERIFY_EV_CERT)
                     --> method = "GET"
                     --> url = "http://game.granbluefantasy.jp/quest/content/supporter/720361/1/0?_=1502902914723&t=1502902924503&uid=10777899"
t=12813 [st=   1]      URL_REQUEST_DELEGATE  [dt=0]
t=12813 [st=   1]      HTTP_CACHE_GET_BACKEND  [dt=0]
t=12813 [st=   1]      HTTP_CACHE_OPEN_ENTRY  [dt=0]
                       --> net_error = -2 (ERR_FAILED)
t=12813 [st=   1]      HTTP_CACHE_CREATE_ENTRY  [dt=1]
t=12814 [st=   2]      HTTP_CACHE_ADD_TO_ENTRY  [dt=0]
t=12814 [st=   2]     +HTTP_STREAM_REQUEST  [dt=0]
t=12814 [st=   2]        HTTP_STREAM_JOB_CONTROLLER_BOUND
                         --> source_dependency = 956 (HTTP_STREAM_JOB_CONTROLLER)
t=12814 [st=   2]        HTTP_STREAM_REQUEST_BOUND_TO_JOB
                         --> source_dependency = 957 (HTTP_STREAM_JOB)
t=12814 [st=   2]     -HTTP_STREAM_REQUEST
t=12814 [st=   2]      AUTH_PROXY  [dt=0]
t=12814 [st=   2]     +HTTP_TRANSACTION_SEND_REQUEST  [dt=0]
t=12814 [st=   2]        HTTP_TRANSACTION_HTTP2_SEND_REQUEST_HEADERS
                         --> :authority: game.granbluefantasy.jp
                             :method: GET
                             :path: /quest/content/supporter/720361/1/0?_=1502902914723&t=1502902924503&uid=10777899
                             :scheme: http
                             accept: application/json, text/javascript, */*; q=0.01
                             accept-encoding: gzip, deflate
                             accept-language: en-US,en;q=0.8
                             cookie: [1071 bytes were stripped]
                             proxy-authorization: Basic [20 bytes were stripped]
                             referer: http://game.granbluefantasy.jp/
                             user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.90 Safari/537.36
                             x-requested-with: XMLHttpRequest
                             x-version: 1502858315
t=12814 [st=   2]     -HTTP_TRANSACTION_SEND_REQUEST
t=12814 [st=   2]     +HTTP_TRANSACTION_READ_HEADERS  [dt=373]
t=13187 [st= 375]        HTTP_TRANSACTION_READ_RESPONSE_HEADERS
                         --> HTTP/1.1 200
                             status: 200
                             date: Wed, 16 Aug 2017 17:02:02 GMT
                             set-cookie: [879 bytes were stripped]
                             set-cookie: [71 bytes were stripped]
                             vary: User-Agent,Accept-Encoding
                             content-encoding: gzip
                             content-length: 12885
                             content-type: application/json
                             x-cache: MISS from localhost
                             x-cache-lookup: MISS from localhost:3129
                             server: Apache
                             via: 1.1 localhost (squid/3.5.12), 1.1 nghttpx
t=13187 [st= 375]     -HTTP_TRANSACTION_READ_HEADERS
t=13187 [st= 375]     +HTTP_CACHE_WRITE_INFO  [dt=0]
t=13187 [st= 375]        HTTP2_STREAM_UPDATE_RECV_WINDOW
                         --> delta = -3199
                         --> stream_id = 69
                         --> window_size = 6288257
t=13187 [st= 375]     -HTTP_CACHE_WRITE_INFO
t=13187 [st= 375]      HTTP_CACHE_WRITE_DATA  [dt=0]
t=13188 [st= 376]      HTTP_CACHE_WRITE_INFO  [dt=0]
t=13188 [st= 376]      URL_REQUEST_DELEGATE  [dt=0]
t=13188 [st= 376]      URL_REQUEST_FILTERS_SET
                       --> filters = "GZIP"
t=13188 [st= 376]   -URL_REQUEST_START_JOB
t=13188 [st= 376]    URL_REQUEST_DELEGATE  [dt=0]
t=13188 [st= 376]   +HTTP_TRANSACTION_READ_BODY  [dt=0]
t=13188 [st= 376]      HTTP2_STREAM_UPDATE_RECV_WINDOW
                       --> delta = 3199
                       --> stream_id = 69
                       --> window_size = 6291456
t=13188 [st= 376]   -HTTP_TRANSACTION_READ_BODY
t=13188 [st= 376]    HTTP_CACHE_WRITE_DATA  [dt=0]
t=13188 [st= 376]    URL_REQUEST_JOB_BYTES_READ
                     --> byte_count = 3199
t=13189 [st= 377]    URL_REQUEST_JOB_FILTERED_BYTES_READ
                     --> byte_count = 32768
t=13189 [st= 377]    URL_REQUEST_JOB_FILTERED_BYTES_READ
                     --> byte_count = 32768
t=13189 [st= 377]    HTTP2_STREAM_UPDATE_RECV_WINDOW
                     --> delta = -5829
                     --> stream_id = 69
                     --> window_size = 6285627
t=13189 [st= 377]    URL_REQUEST_JOB_FILTERED_BYTES_READ
                     --> byte_count = 6921
t=13189 [st= 377]   +HTTP_TRANSACTION_READ_BODY  [dt=0]
t=13189 [st= 377]      HTTP2_STREAM_UPDATE_RECV_WINDOW
                       --> delta = 5829
                       --> stream_id = 69
                       --> window_size = 6291456
t=13189 [st= 377]   -HTTP_TRANSACTION_READ_BODY
t=13189 [st= 377]    HTTP_CACHE_WRITE_DATA  [dt=0]
t=13189 [st= 377]    URL_REQUEST_JOB_BYTES_READ
                     --> byte_count = 5829
t=13189 [st= 377]    URL_REQUEST_JOB_FILTERED_BYTES_READ
                     --> byte_count = 32768
t=13190 [st= 378]    URL_REQUEST_JOB_FILTERED_BYTES_READ
                     --> byte_count = 32768
t=13190 [st= 378]    URL_REQUEST_JOB_FILTERED_BYTES_READ
                     --> byte_count = 32768
t=13190 [st= 378]    URL_REQUEST_JOB_FILTERED_BYTES_READ
                     --> byte_count = 20523
t=13190 [st= 378]   +HTTP_TRANSACTION_READ_BODY  [dt=3]
t=13191 [st= 379]      HTTP2_STREAM_UPDATE_RECV_WINDOW
                       --> delta = -1291
                       --> stream_id = 69
                       --> window_size = 6290165
t=13193 [st= 381]      HTTP2_STREAM_UPDATE_RECV_WINDOW
                       --> delta = 1291
                       --> stream_id = 69
                       --> window_size = 6291456
t=13193 [st= 381]   -HTTP_TRANSACTION_READ_BODY
t=13193 [st= 381]    HTTP_CACHE_WRITE_DATA  [dt=0]
t=13193 [st= 381]    URL_REQUEST_JOB_BYTES_READ
                     --> byte_count = 1291
t=13193 [st= 381]    URL_REQUEST_JOB_FILTERED_BYTES_READ
                     --> byte_count = 5303
t=13193 [st= 381]   +HTTP_TRANSACTION_READ_BODY  [dt=102]
t=13293 [st= 481]      HTTP2_STREAM_UPDATE_RECV_WINDOW
                       --> delta = -83
                       --> stream_id = 69
                       --> window_size = 6291373
t=13295 [st= 483]      HTTP2_STREAM_UPDATE_RECV_WINDOW
                       --> delta = 83
                       --> stream_id = 69
                       --> window_size = 6291456
t=13295 [st= 483]   -HTTP_TRANSACTION_READ_BODY
t=13295 [st= 483]    HTTP_CACHE_WRITE_DATA  [dt=0]
t=13295 [st= 483]    URL_REQUEST_JOB_BYTES_READ
                     --> byte_count = 83
t=13295 [st= 483]    URL_REQUEST_JOB_FILTERED_BYTES_READ
                     --> byte_count = 333
t=13295 [st= 483]   +HTTP_TRANSACTION_READ_BODY  [dt=900]
t=14193 [st=1381]      HTTP2_STREAM_UPDATE_RECV_WINDOW
                       --> delta = -1448
                       --> stream_id = 69
                       --> window_size = 6290008
t=14195 [st=1383]      HTTP2_STREAM_UPDATE_RECV_WINDOW
                       --> delta = 1448
                       --> stream_id = 69
                       --> window_size = 6291456
t=14195 [st=1383]   -HTTP_TRANSACTION_READ_BODY
t=14195 [st=1383]    HTTP_CACHE_WRITE_DATA  [dt=0]
t=14195 [st=1383]    URL_REQUEST_JOB_BYTES_READ
                     --> byte_count = 1448
t=14195 [st=1383]    URL_REQUEST_JOB_FILTERED_BYTES_READ
                     --> byte_count = 6900
t=14195 [st=1383]   +HTTP_TRANSACTION_READ_BODY  [dt=999]
t=15194 [st=2382]      HTTP2_STREAM_UPDATE_RECV_WINDOW
                       --> delta = -1035
                       --> stream_id = 69
                       --> window_size = 6290421
t=15194 [st=2382]   -HTTP_TRANSACTION_READ_BODY
t=15194 [st=2382]    HTTP_CACHE_WRITE_DATA  [dt=1]
t=15195 [st=2383]    URL_REQUEST_JOB_BYTES_READ
                     --> byte_count = 1035
t=15195 [st=2383]    URL_REQUEST_JOB_FILTERED_BYTES_READ
                     --> byte_count = 4415
t=15195 [st=2383]    HTTP_TRANSACTION_READ_BODY  [dt=0]
t=15195 [st=2383]    HTTP_CACHE_WRITE_DATA  [dt=0]
t=15195 [st=2383] -REQUEST_ALIVE

Comment 2 by ricea@chromium.org, Aug 17 2017

Components: Internals>Network>HTTP2 Internals>Network>Proxy

Comment 3 by mmenke@chromium.org, Aug 17 2017 

Looks like we're stalled waiting to receive the body from the server.  Seems unlikely to be a general proxy issue, so if it's a Chrome issue, most likely either H2 or H2 proxy related, though seems to me it could well be a proxy issue (Since the proxy is what's doing all the work there).

I'll defer to the owner of the H2 code.

Comment 4 by mmenke@chromium.org, Aug 17 2017 

Oh, and we'll probably need the full log, to see what's happening at the H2 session and possibly socket layers (We don't need all bytes, just need to see all reads and H2 events).

Comment 5 by pauljensen@chromium.org, Aug 17 2017

Cc: b...@chromium.org
Labels: Needs-Feedback
CCing bnc@ as he may be interested in looking at the H2 log, and Needs-Feedback for the full log.

Comment 6 by k...@luminance.org, Aug 17 2017 

How do I retain and save the full log? I couldn't find a way to do it when I dug around.
Project Member

Comment 7 by sheriffbot@chromium.org, Aug 17 2017

Cc: pauljensen@chromium.org
Labels: -Needs-Feedback
Thank you for providing more feedback. Adding requester "pauljensen@chromium.org" to the cc list and removing "Needs-Feedback" label.

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot

Comment 9 by k...@luminance.org, Aug 18 2017 

Here's a network log that I believe contains a stall, along with a screenshot of the request that should have stalled. I didn't have the network internals tab open this time so I wasn't able to check the text there to see if it was similar.

The timing from the log should show that almost all requests through the proxy complete quickly, except for the stall, which takes over 3 seconds.
chrome-net-export-log.json.zip
191 KB Download
Screenshot 2017-08-17 19.47.24.png
54.0 KB View Download
Project Member

Comment 10 by sheriffbot@chromium.org, Aug 18 2017

Labels: -Needs-Feedback
Thank you for providing more feedback. Adding requester "pauljensen@chromium.org" to the cc list and removing "Needs-Feedback" label.

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot

Comment 11 by hdodda@chromium.org, Aug 23 2017

Labels: Needs-Traige-M60 TE-NeedsTriageHelp
Adding TE-NeedsTriageHelp , as the issue is out of TE scope.

Thanks!

Comment 12 by k...@luminance.org, Apr 16 2018 

This is still an issue and I think a recent update to Chrome may have made it worse. I previously was mitigating this with an extension that sends periodic pings to a web server (via the proxy) to 'wake up' stalled requests but that no longer seems to reliably work around the issue. I haven't changed my proxy configuration at all so it seems like something would have had to change in Chrome.

Comment 13 by k...@luminance.org, May 13 2018 

This also occurs using Caddy in http2 forward proxy configuration.
►

Sign in to add a comment