HTTP/2 and TSProxy not working correctly?

[soulgalore]

Hey Pat, could something in Chrome 54 affect how TSProxy handles HTTP/2 (I've seen https://github.com/WPO-Foundation/webpagetest/issues/747)?

When I test https://en.wikipedia.org/wiki/Barack_Obama through TSProxy in latest Chrome using Browsertime (and parse the event log from Chrome) I get different results almost every time in number of requests, it can go from 40 to 118 or something like that. When I check the browser it seems like sometimes in downloads the images and sometimes it starts to redownload them again. I'm not 100% sure this is 54 only but I think so. I can provide a full TSProxy log tomorrow. When I use Firefox 49 with TSProxy it works as expected and Chrome 54 without the proxy.

It seems that a lot of requests is dropped because they are incomplete.

Best Peter

[soulgalore]

Ok, here's how I do to reproduce:

$ python tsproxy.py --rtt=28 --inkbps=5000 --outkbps=1000 -vvvv
$ /Applications/Google\ Chrome.app/Contents/MacOS/Google\ Chrome --proxy-server="socks://127.0.0.1:1080"

Then after all the startup network traffic is finished, I open the network tab, turn off the cache and open https://en.wikipedia.org/wiki/Barack_Obama

The output from TSProxy: https://gist.github.com/soulgalore/4aeadcc8c27e3aa52489cfa741c7a002

And devtools look like this:

[pmeenan]

Are you running the latest? Just a sanity check because there have been a few bug fixes since the original release (I think August 10th is probably the latest of the critical issues).

[soulgalore]

Yes, when I tested standalone with Chrome I used the latest version (pulled the latest from Github). Just verified and got the same again, so I hope it will be reproducible for others!

[beenanner]

Doesn't appear to be related to Chrome 54. I can reproduce on Chrome 53. Some request seem to make it before the timeout failures.

[beenanner]

I can also reproduce in Firefox. It's almost like the socks proxy just gives up and closes the connection which causes all the request that haven't finished to be marked as failed.

02:25:08.825 - [9] SOCKS <= 410 byte(s) 02:25:25.301 - [10] Server Connection Closed 02:25:25.301 - [10] Browser Connection Closed

[soulgalore]

Yes I was wrong in the original issue. Also we havent seen it fail on other sites but I'll test tonight if I can reproduce on other websites.

[soulgalore]

I tried a couple of other sites and could not reproduce it, I only get the problem with Wikipedia.

[pmeenan]

I'll take a look on Monday but a netlog might help show what Chrome is seeing.

If the proxy closed the connection while bytes were in flight I could see it causing issues but it is supposed to queue up the connection closing event behind the data and flush the data before actually closing.

For Firefox, is it with the same URL?

[soulgalore]

Thanks, that would be great! Here's a netlog: https://gist.githubusercontent.com/soulgalore/e58066e3664d60c57d9dd5ac3cf96416/raw/5568d925726feb68a4bb6cb3fe374cb4f475ef44/net-internals-log.json

Get things like this for the domain:

t= 714 [st=  0] +HTTP_STREAM_JOB  [dt=419]
                 --> alternative_service = "Uninitialized :0"
                 --> original_url = "https://upload.wikimedia.org/"
                 --> priority = "LOWEST"
                 --> source_dependency = 36129 (URL_REQUEST)
                 --> url = "https://upload.wikimedia.org/"
t= 714 [st=  0]   +PROXY_SERVICE  [dt=0]
t= 714 [st=  0]      PROXY_SERVICE_RESOLVED_PROXY_LIST
                     --> pac_string = "SOCKS5 127.0.0.1:1080"
t= 714 [st=  0]   -PROXY_SERVICE
t= 714 [st=  0]   +HOST_RESOLVER_IMPL_REQUEST  [dt=0]
                   --> address_family = 0
                   --> allow_cached_response = true
                   --> host = "upload.wikimedia.org:443"
                   --> is_speculative = false
t= 714 [st=  0]      HOST_RESOLVER_IMPL_IPV6_REACHABILITY_CHECK
                     --> cached = true
                     --> ipv6_available = false
t= 714 [st=  0]   -HOST_RESOLVER_IMPL_REQUEST
                   --> net_error = -804 (ERR_DNS_CACHE_MISS)
t= 714 [st=  0]   +SOCKET_POOL  [dt=419]
t= 714 [st=  0]      SOCKET_POOL_STALLED_MAX_SOCKETS_PER_GROUP
t=1133 [st=419] -HTTP_STREAM_JOB
t=1133 [st=419]  CANCELLED
t=1133 [st=419] -SOCKET_POOL

And then for each request:

t=1155 [st= 401]     +HTTP_TRANSACTION_READ_HEADERS  [dt=889]
t=2044 [st=1290]        HTTP2_STREAM_ERROR
                        --> description = "ABANDONED (stream_id=37): https://upload.wikimedia.org/wikipedia/commons/thumb/a/a8/Office-book.svg/60px-Office-book.svg.png"
                        --> status = -100
                        --> stream_id = 37
t=2044 [st=1290]     -HTTP_TRANSACTION_READ_HEADERS

@beenanner you got the same problem with Firefox for the same URL right?

[beenanner]

Correct I saw the same issue with Firefox.

[pmeenan]

I'm pretty sure it was an interaction with the code that emulated TCP slow start and it not working well. With the code disabled I could not reproduce the issue anymore.

Back to the drawing board on a good way to reproduce slow start (or may just leave it as something that the proxy can't emulate).

Please re-open it if it doesn't look fixed on your end.

[soulgalore]

thanks @pmeenan it works fine now!