Okhttp: HTTP2 POST - java.io.IOException: stream was reset: REFUSED_STREAM
Hi,
we are using okhttp v3.2.0 and, in the attempt to migrate to http2, we compiled nginx v1.9.15 (latest as of today) against libssl 1.0.2g (ALPN support). Any client platform other than okhttp works as expected.
As far as okhttp is concerned, it looks like GET requests are correctly served by nginx, although the app fails with the following error while submitting any POST request:
04-22 15:10:15.934 18768-19313/com.pymmt.pymmt E/HttpImpl: NativeLogger Exception during http request
java.io.IOException: stream was reset: REFUSED_STREAM
at okhttp3.internal.framed.FramedStream.getResponseHeaders(FramedStream.java:145)
at okhttp3.internal.http.Http2xStream.readResponseHeaders(Http2xStream.java:149)
at okhttp3.internal.http.HttpEngine.readNetworkResponse(HttpEngine.java:723)
at okhttp3.internal.http.HttpEngine.access$200(HttpEngine.java:81)
at okhttp3.internal.http.HttpEngine$NetworkInterceptorChain.proceed(HttpEngine.java:708)
at okhttp3.internal.http.HttpEngine.readResponse(HttpEngine.java:563)
at okhttp3.RealCall.getResponse(RealCall.java:241)
at okhttp3.RealCall$ApplicationInterceptorChain.proceed(RealCall.java:198)
at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:160)
at okhttp3.RealCall.access$100(RealCall.java:30)
at okhttp3.RealCall$AsyncCall.execute(RealCall.java:127)
at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
at java.lang.Thread.run(Thread.java:818)
Nginx in debug mode complains about the client prematurely closing the stream:
2016/04/22 15:10:16 [debug] 7894#7894: *369 process http2 frame type:3 f:0 l:4 sid:5
2016/04/22 15:10:16 [debug] 7894#7894: *369 http2 RST_STREAM frame, sid:5 status:8
2016/04/22 15:10:16 [info] 7894#7894: *369 client canceled stream 5, client: 5.168.111.94, server: pymmt.com, request: "POST /generic/api/v1/user/login/uniqueId HTTP/2.0", host: "py.pymmt.com"
2016/04/22 15:10:16 [debug] 7894#7894: *369 http run request: "/generic/api/v1/user/login/uniqueId?"
2016/04/22 15:10:16 [debug] 7894#7894: *369 http2 read client request body handler
2016/04/22 15:10:16 [info] 7894#7894: *369 client prematurely closed stream, client: 5.168.111.94, server: pymmt.com, request: "POST /generic/api/v1/user/login/uniqueId HTTP/2.0", host: "py.pymmt.com"4: *371 SSL buf copy: 27
The full nginx debug log of the request is available here:
http://pastebin.com/LBms9emf
Currently, as suggested in other issues, we got the app to work by forcing it on HTTP1.1.
Thanks in advance
PL
plrunner
All 31 comments
I have just met this issue, too. HTTP2 is the future, I hope this get fixed fast as I'd love to use it in my Android apps.
tazio
on 22 Apr 2016
Thanks for the thorough investigation. I'll take a look.
swankjesse
on 22 Apr 2016
Welcome and thank you for this great lib.
Feel free to ask me to carry out any test you consider useful to solve this issue.
Moreover, if you find it useful I can provide you an apk performing a faulting request against our test environment.
PL
plrunner
on 22 Apr 2016
Could you try with frame logging enabled in OkHttp? That should help to figure out what’s happening on the client side. Pasting this somewhere is the easiest way to do that:
private static final Logger frameLogger = frameLogger();
public static Logger frameLogger() {
Logger frameLogger = Logger.getLogger(Http2.class.getName() + "$FrameLogger");
frameLogger.setLevel(Level.FINE);
ConsoleHandler handler = new ConsoleHandler();
handler.setLevel(Level.FINE);
handler.setFormatter(new SimpleFormatter() {
@Override public String format(LogRecord record) {
return String.format("%s%n", record.getMessage());
}
});
frameLogger.addHandler(handler);
return frameLogger;
}
It needs a static variable because the Java logging API may lose its configuration unless you have that.
swankjesse
on 24 Apr 2016
Thanks for the quick reply.
I'll get back as soon as I have the logs from our developers.
PL
plrunner
on 24 Apr 2016
Here you go:
04-25 19:10:54.361 23709-23768/com.pymmt.pymmt W/System.err: >> CONNECTION 505249202a20485454502f322e300d0a0d0a534d0d0a0d0a
04-25 19:10:54.361 23709-23768/com.pymmt.pymmt W/System.err: >> 0x00000000 6 SETTINGS
04-25 19:10:54.361 23709-23768/com.pymmt.pymmt W/System.err: >> 0x00000000 4 WINDOW_UPDATE
04-25 19:10:54.361 23709-23768/com.pymmt.pymmt W/System.err: >> 0x00000003 301 HEADERS END_HEADERS
04-25 19:10:54.361 23709-23768/com.pymmt.pymmt W/System.err: >> 0x00000003 50 DATA END_STREAM
04-25 19:10:54.441 23709-24477/com.pymmt.pymmt W/System.err: << 0x00000000 18 SETTINGS
04-25 19:10:54.441 23709-24477/com.pymmt.pymmt W/System.err: << 0x00000000 4 WINDOW_UPDATE
04-25 19:10:54.441 23709-23784/com.pymmt.pymmt W/System.err: >> 0x00000000 0 SETTINGS ACK
04-25 19:10:54.501 23709-24477/com.pymmt.pymmt W/System.err: << 0x00000000 0 SETTINGS ACK
04-25 19:10:54.501 23709-24477/com.pymmt.pymmt W/System.err: << 0x00000003 4 RST_STREAM
04-25 19:10:54.501 23709-24477/com.pymmt.pymmt W/System.err: >> 0x00000000 8 GOAWAY
04-25 19:10:54.511 23709-23768/com.pymmt.pymmt E/HttpImpl: NativeLogger Exception during http request
java.io.IOException: stream was reset: REFUSED_STREAM
at okhttp3.internal.framed.FramedStream.getResponseHeaders(FramedStream.java:145)
at okhttp3.internal.http.Http2xStream.readResponseHeaders(Http2xStream.java:149)
at okhttp3.internal.http.HttpEngine.readNetworkResponse(HttpEngine.java:723)
at okhttp3.internal.http.HttpEngine.access$200(HttpEngine.java:81)
at okhttp3.internal.http.HttpEngine$NetworkInterceptorChain.proceed(HttpEngine.java:708)
at okhttp3.internal.http.HttpEngine.readResponse(HttpEngine.java:563)
at okhttp3.RealCall.getResponse(RealCall.java:241)
at okhttp3.RealCall$ApplicationInterceptorChain.proceed(RealCall.java:198)
at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:160)
at okhttp3.RealCall.access$100(RealCall.java:30)
at okhttp3.RealCall$AsyncCall.execute(RealCall.java:127)
at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
at java.lang.Thread.run(Thread.java:818)
PL
plrunner
on 25 Apr 2016
@swankjesse not sure if you've had time to make progress on this. I was able to reproduce by spinning up a VM in GCP using the Ubuntu 16.04 image (it has latest nginx and openssl.) I missed this in the pastebin above, but nginx is logging this message:
2016/04/22 15:10:16 [info] 7894#7894: *371 client sent stream with data before settings were acknowledged while processing HTTP/2 connection, client: 5.168.111.94, server: 0.0.0.0:443
2016/04/22 15:10:16 [debug] 7894#7894: *371 http2 send RST_STREAM frame sid:3, status:7
dave-r12
on 26 Apr 2016
I think I am affected by exactly this issue, using bitfireAT/davdroid
nginx error log:
client sent stream with data before settings were acknowledged while processing HTTP/2 connection
davdroid debug logs show:
2016-04-24 09:05:08 3 [ui.setup.DavResourceFinder] Finding initial carddav service configuration
2016-04-24 09:05:08 3 [ui.setup.DavResourceFinder] Checking user-given URL: https://owncloud.domain.tld/
2016-04-24 09:05:08 3 [HttpClient$1] --> PROPFIND https://owncloud.domain.tld/ http/1.1
2016-04-24 09:05:08 3 [HttpClient$1] Content-Type: application/xml; charset=utf-8
2016-04-24 09:05:08 3 [HttpClient$1] Content-Length: 290
2016-04-24 09:05:08 3 [HttpClient$1] Depth: 0
2016-04-24 09:05:08 3 [HttpClient$1]
2016-04-24 09:05:08 3 [HttpClient$1] <?xml version='1.0' encoding='UTF-8' ?><propfind xmlns="DAV:" xmlns:CAL="urn:ietf:params:xml:ns:caldav" xmlns:CARD="urn:ietf:params:xml:ns:carddav"><prop><resourcetype /><displayname /><CARD:addressbook-description /><CARD:addressbook-home-set /><current-user-principal /></prop></propfind>
2016-04-24 09:05:08 3 [HttpClient$1] --> END PROPFIND (290-byte body)
2016-04-24 09:05:08 3 [ui.setup.DavResourceFinder] PROPFIND/OPTIONS on user-given URL failed
EXCEPTION java.io.IOException: stream was reset: REFUSED_STREAM
at okhttp3.internal.framed.FramedStream.getResponseHeaders(FramedStream.java:145)
at okhttp3.internal.http.Http2xStream.readResponseHeaders(Http2xStream.java:149)
at okhttp3.internal.http.HttpEngine.readNetworkResponse(HttpEngine.java:723)
at okhttp3.internal.http.HttpEngine.access$200(HttpEngine.java:81)
at okhttp3.internal.http.HttpEngine$NetworkInterceptorChain.proceed(HttpEngine.java:708)
at at.bitfire.davdroid.HttpClient$PreemptiveAuthenticationInterceptor.intercept(HttpClient.java:153)
at okhttp3.internal.http.HttpEngine$NetworkInterceptorChain.proceed(HttpEngine.java:681)
at at.bitfire.davdroid.HttpClient$UserAgentInterceptor.intercept(HttpClient.java:139)
at okhttp3.internal.http.HttpEngine$NetworkInterceptorChain.proceed(HttpEngine.java:681)
at okhttp3.internal.http.HttpEngine.readResponse(HttpEngine.java:563)
at okhttp3.RealCall.getResponse(RealCall.java:241)
at okhttp3.RealCall$ApplicationInterceptorChain.proceed(RealCall.java:198)
at okhttp3.logging.HttpLoggingInterceptor.intercept(HttpLoggingInterceptor.java:203)
at okhttp3.RealCall$ApplicationInterceptorChain.proceed(RealCall.java:187)
at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:160)
at okhttp3.RealCall.execute(RealCall.java:57)
at at.bitfire.dav4android.DavResource.propfind(DavResource.java:268)
at at.bitfire.davdroid.ui.setup.DavResourceFinder.checkUserGivenURL(DavResourceFinder.java:156)
at at.bitfire.davdroid.ui.setup.DavResourceFinder.findInitialConfiguration(DavResourceFinder.java:116)
at at.bitfire.davdroid.ui.setup.DavResourceFinder.findInitialConfiguration(DavResourceFinder.java:87)
at at.bitfire.davdroid.ui.setup.DetectConfigurationFragment$ServerConfigurationLoader.loadInBackground(DetectConfigurationFragment.java:143)
at at.bitfire.davdroid.ui.setup.DetectConfigurationFragment$ServerConfigurationLoader.loadInBackground(DetectConfigurationFragment.java:126)
at android.support.v4.content.AsyncTaskLoader.onLoadInBackground(AsyncTaskLoader.java:296)
at android.support.v4.content.AsyncTaskLoader$LoadTask.doInBackground(AsyncTaskLoader.java:54)
at android.support.v4.content.AsyncTaskLoader$LoadTask.doInBackground(AsyncTaskLoader.java:42)
at android.support.v4.content.ModernAsyncTask$2.call(ModernAsyncTask.java:128)
at java.util.concurrent.FutureTask.run(FutureTask.java:237)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)
at java.lang.Thread.run(Thread.java:818)
see https://forums.bitfire.at/topic/1070/issues-with-http-2-0
raoulbhatia
on 26 Apr 2016
I'm wondering if they were thinking we'd retry the request?
The REFUSED_STREAM error code can be included in a RST_STREAM frame to indicate that the stream is being closed prior to any processing having occurred. Any request that was sent on the reset stream can be safely retried.
Requests that have not been processed have not failed; clients MAY automatically retry them, even those with non-idempotent methods.
dave-r12
on 26 Apr 2016
Here's the commit that introduced this, https://github.com/nginx/nginx/commit/536b5510d1051281bd9411723102333e6d1dbdf2
Seems strange, but I think it's within the spec.
dave-r12
on 26 Apr 2016
@dave-r12, in facts with nginx v1.9.14 the behaviour was pretty different, but even more nasty and hard to be exposed: POST requests in my case were served in around 12 seconds or so. I was about to open an issue while experimenting with 1.9.14 but I thought the problem might be in my configuration.
plrunner
on 26 Apr 2016
It’s unfortunate that this will require the client to wait for the server’s settings before it can transmit its first request. It adds head-of-line blocking that HTTP/2 tries so hard to avoid.
Sigh. Section 3.5 says what we’re doing is okay:
To avoid unnecessary latency, clients are permitted to send additional frames to the server immediately after sending the client connection preface, without waiting to receive the server connection preface. It is important to note, however, that the server connection preface SETTINGS frame might include parameters that necessarily alter how a client is expected to communicate with the server. Upon receiving the SETTINGS frame, the client is expected to honor any parameters established.
I think we’re keeping up our side of the bargain, and OkHttp does honor SETTINGS on all streams, including those initiated before the SETTINGS ACK was sent.
Our options:
- Hold to read SETTINGS and write SETTINGS_ACK before initiating any streams. This is simple but slow.
- Hold to read SETTINGS and write SETTINGS_ACK before initiating any streams that have a request body. This is less simple and potentially just as slow.
- Retry the request when a stream is refused. This is awkward to the application layer because we’ll have to throw an exception in the RequestBody writer and then retry it. Some RequestBody writers won’t expect this!
- Petition nginx to relax this constraint.
swankjesse
on 27 Apr 2016
@dave-r12 can you check to see what other clients do? Does curl wait for the SETTINGS frame before sending a POST? I’m not sure if there’s an easy way to delay that from being sent in nginx, but if you added a 5 second sleep or something it’d be pretty easy to see what it does.
swankjesse
on 27 Apr 2016
Got it. Took a peek at golang's client. If I'm reading it right, it looks like they send SETTINGS frame, then WINDOW_UPDATE frame, then block on reading a frame, which they require to be SETTINGS. Finally they ACK the settings and start the reader go routine.
See here https://github.com/golang/go/blob/master/src/net/http/h2_bundle.go#L5060
Agree with your description, I'm still struggling with why they interpreted it this way. I'll see if I can research some other clients in the morning.
dave-r12
on 27 Apr 2016
Yeah. There’s been so much work done to eliminate “connection startup chattiness”. Seems like blasting the initial frames first should be a win to reduce latency.
https://www.mnot.net/blog/2016/04/22/ideal-http
swankjesse
on 27 Apr 2016
I asked the experts: https://lists.w3.org/Archives/Public/ietf-http-wg/2016AprJun/0174.html
swankjesse
on 27 Apr 2016
On guidance from experts I asked nginx for a fix: https://trac.nginx.org/nginx/ticket/959
swankjesse
on 27 Apr 2016
Nice!
dave-r12
on 27 Apr 2016
FYI, same issue with nginx version: nginx/1.10.0 (Ubuntu)
see http://packages.ubuntu.com/search?keywords=nginx -> xenial-updates
raoulbhatia
on 27 Apr 2016
I must admit my limited knowldge of http2 does allow me to comprehend in full details the answer from vbart . Anyway it looks like the RST_STREAM is returned for other reasons, doesn't it?
plrunner
on 29 Apr 2016
It means we may need to recover in OkHttp somehow.
swankjesse
on 29 Apr 2016
@plrunner can you get POST requests to work at all with nginx 1.9.15? I've been debugging it and it's setting the initial window size to 0, but never sends a window update. I'm likely misconfiguring something but wanted to see if you got it working.
Also, nghttp (which I think curl uses for http2) also behaves as OkHttp. It begins sending data immediately, but fails because nginx sends a REFUSED_STREAM.
dave-r12
on 5 May 2016
@dave-r12
at the moment we are using HTTP1.1
plrunner
on 5 May 2016
Thanks. I was able to get a POST working with nginx + HTTP2. It enforces 2 unfortunate constraints.
- We can't send data eagerly (we already knew this.)
- We must send a HEADERS frame, then hold, in order to receive a WINDOWS_UPDATE frame for the stream to send data. This introduces another round trip.
dave-r12
on 5 May 2016
@dave-r12
Great! Did you commit your changes somewhere?
plrunner
on 6 May 2016
Sorry, I got it working independent of OkHttp, I haven't made any code changes. I was trying to understand what they were doing first. It's a strange interpretation of the spec IMO.
dave-r12
on 6 May 2016
Maybe some traction from nginx? They just responded on the ticket:
I agree, while it's not optimal from the latency point of view, such approach significantly simplifies the code. So it's a fair price, that was paid at the current stage of HTTP/2 implementation.
Introducing some kind of preread buffer will be the next step.
dave-r12
on 6 May 2016
I’ve opened a new issue #2543 for OkHttp’s mitigation of this problem. We’ll make OkHttp handle all refused streams and we’ll workaround this problem at the same time.
swankjesse
on 8 May 2016
For anyone interested, I posted this on the other issue:
A quick update: nginx attached a proposed patch on their issue tracker. I tested patch against OkHttp and it worked perfectly.
dave-r12
on 21 May 2016
@dave-r12 that’s great news.
swankjesse
on 21 May 2016
As a further heads-up, this patch is now available in mainline nginx branch 1.11, which as a positive side-effect makes connection-initiating POST requests over HTTP/2 in major browsers (Firefox, MS Edge, Safari 9.x and alternative browsers on iOS, etc.) work again.
DosAmp
on 8 Jun 2016
Related issues
yschimke
·
3Comments
SElab2019
·
3Comments
HyakYegoryaln
·
3Comments
tangjiabing
·
3Comments
albka1986
·
3Comments
Most helpful comment
Here's the commit that introduced this, https://github.com/nginx/nginx/commit/536b5510d1051281bd9411723102333e6d1dbdf2
Seems strange, but I think it's within the spec.