okhttp: Frequent cancelling the HTTP/2 requests will cause client never sends WINDOW_UPDATE frame
Description: When downloading a lot of medium-sized files from Nginx HTTP/2 server, if requests are frequently canceled (RST_STREAM), eventually the connection will timeout and not be able to send/receive any data from the server.
On the server side configure the Nginx server to support HTTP/2 with a self-signed certificate. And host about 100 files with size about 500k each. On the client side, I built an Android test, using a single thread to download the file from file no.1 to file no.100 consequently. During each download, the request is canceled and then proceed to download next file. Eventually, the request will timeout. Depending on the setup the timeout may happen on different download. But once the testing environment is set, it always failed on the same file.
Server info: nginx/1.13.10 Client info: Android 6.0 with OKHttp 3.10.0
This issue is reproducible on multiple servers. For example, Go HTTP/2 server and AWS CloudFront.
A filtered (sid:75) server log shows that the header frame has been sent on 14:39:32 and then timed out after 60 seconds. Note, it is not always the header frame though. Sometimes it is the data frame not being sent out.
2018/03/05 14:39:32 [debug] 92282#0: *4 http2 frame type:1 f:5 l:14 sid:75
2018/03/05 14:39:32 [debug] 92282#0: *4 http2 HEADERS frame sid:75 depends on 0 excl:0 weight:16
2018/03/05 14:39:32 [debug] 92282#0: *4 http2 frame out: 00007FD4B082ABA0 sid:75 bl:1 len:122
2018/03/05 14:39:32 [debug] 92282#0: *4 http2 frame sent: 00007FD4B082ABA0 sid:75 bl:1 len:122
2018/03/05 14:40:32 [debug] 92282#0: *4 http2 send RST_STREAM frame sid:75, status:1
In the meantime, the client log shows the header is not received until 14:40:32
03-05 14:39:32.229 5979-5995/? V/VB_Network: Sending request https://10.0.0.186/files/37 on Connection{10.0.0.186:443, proxy=DIRECT hostAddress=/10.0.0.186:443 cipherSuite=TLS_RSA_WITH_AES_128_CBC_SHA protocol=h2}
User-Agent:
Host: 10.0.0.186
Connection: Keep-Alive
Accept-Encoding: gzip
03-05 14:40:32.397 5979-5995/? V/VB_Network: Received response for https://10.0.0.186/files/37 (h2) in 60167.4ms
server: nginx/1.13.10
date: Mon, 05 Mar 2018 22:39:32 GMT
content-type: application/octet-stream
content-length: 562176
last-modified: Sun, 04 Mar 2018 00:23:13 GMT
etag: "5a9b3c71-89400"
accept-ranges: bytes
03-05 14:40:32.400 5979-5995/? E/VB_Test: stream was reset: PROTOCOL_ERROR https://10.0.0.186/files/37
At first, I thought it is a server issue, so I filed a bug to the Nginx team. They replied that this is because the client never sends the WINDOW_UPDATE frame except after the initial connection.
Server Full Log Client Full Log
The test project is under git@github.com:jifang/nginx_bug_repo1.git
About this issue
- Original URL
- State: closed
- Created 6 years ago
- Comments: 40 (2 by maintainers)
Commits related to this issue
- Fixed issue 3915 when client did not update receive window in case stream is canceled https://github.com/square/okhttp/issues/3915 — committed to wowex/okhttp by markotosic 6 years ago
- Issue 3915 fixed cases when: 1. Client cancels stream and does not update window 2. Client receives RstStream and does not update window https://github.com/square/okhttp/issues/3915 — committed to wowex/okhttp by markotosic 6 years ago
- Issue 3915 fixed most common cases fixed cases when: 1. Client cancels stream and does not update window for unread data 2. Client receives RstStream and does not update window for unread data 3. Cli... — committed to wowex/okhttp by markotosic 6 years ago
- Issue 3915 Added test cases when: 1. Client cancels stream and should update window for unread data 2. Client receives Data for closed (unknown) stream and should calculate that data into window h... — committed to wowex/okhttp by markotosic 6 years ago
- Issue 3915 fixed cases when: 1. Client cancels stream and does not update window for unread data 2. Client receives RstStream and does not update window for unread data 3. Client receives Data for clo... — committed to wowex/okhttp by markotosic 6 years ago
- Issue 3915 fixed cases when: 1. Client cancels stream and does not update window for unread data 2. Client receives RstStream and does not update window for unread data 3. Client receives Data for clo... — committed to wowex/okhttp by markotosic 6 years ago
- Issue 3915 fixed cases when: 1. Client cancels stream and does not update window for unread data 2. Client receives RstStream and does not update window for unread data 3. Client receives Data for clo... — committed to wowex/okhttp by markotosic 6 years ago
- Issue 3915 fixed case when: 1. Client closes stream and does not update window for unread data https://github.com/square/okhttp/issues/3915 Test code: Call call = client.newCall(request); try (... — committed to wowex/okhttp by markotosic 6 years ago
- Defer StreamResetException until response body buffer is fully read. We rely on the application layer to read the response body buffer before sending WINDOW_UPDATE's. Previously we'd immediately thro... — committed to square/okhttp by dave-r12 6 years ago
- Defer StreamResetException until response body buffer is fully read. We rely on the application layer to read the response body buffer before sending WINDOW_UPDATE's. Previously we'd immediately thro... — committed to square/okhttp by dave-r12 6 years ago
- Ensure discarded HTTP/2 data frames free flow-control space. https://github.com/square/okhttp/issues/3915 — committed to square/okhttp by dave-r12 6 years ago
- Ensure discarded HTTP/2 data frames free flow-control space. (#4033) https://github.com/square/okhttp/issues/3915 — committed to square/okhttp by dave-r12 6 years ago
- Ensure discarded HTTP/2 data frames free flow-control space. (#4033) https://github.com/square/okhttp/issues/3915 — committed to square/okhttp by dave-r12 6 years ago
@natez0r I tried to write a test case to match what you found: https://github.com/square/okhttp/pull/4127. What do you think?
Hey Dave, I’ll try to come up with a test case when I get back from vacation late next week. Thanks for your help on this!
On Fri, Jun 29, 2018, 8:52 AM Dave Roberge notifications@github.com wrote:
Awesome, thanks for the fix @dave-r12! much appreciated. If you’d like, I can run my test project on it once it is in a snapshot.