Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Confirm concurrent HTTP/2 requests with empty flow-control window. #4127

Merged
merged 1 commit into from
Jul 13, 2018

Conversation

dave-r12
Copy link
Collaborator

@dave-r12 dave-r12 commented Jul 7, 2018

I'm not fully convinced this is worth merging. I just wanted to attempt to reproduce the steps in #3915.

// flow-control window.
response1.close();

assertEquals("abc", response2.body().string());
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we make the test stronger e.g. assert nothing can be read until after response1.close? Perhaps using inputStream.available()?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not sure if there is a good way of checking that. It looks like available() will always return 0 unless you trigger a read. From my perspective, this test is proving that the second request will proceed as usual given the actions from the first request.

@natez0r
Copy link

natez0r commented Jul 9, 2018

@dave-r12 this looks like it could be the issue I am seeing. My second request always fails when attempting to take the headers.

For completeness' sake, do you have any pointers on where i could throw a breakpoint in the OKHTTP code to confirm this in my test app?

@dave-r12
Copy link
Collaborator Author

dave-r12 commented Jul 9, 2018

@natez0r currently this test passes! So there is likely something different in your environment.

For completeness' sake, do you have any pointers on where i could throw a breakpoint in the OKHTTP code to confirm this in my test app?

A possible first step: could you turn on frame logging and paste in the output?

@natez0r
Copy link

natez0r commented Jul 9, 2018

When I wrote that comment, I had checked out your patch and that test failed for me:

[INFO] -------------------------------------------------------
[INFO] Running okhttp3.internal.http2.HttpOverHttp2Test
[ERROR] Tests run: 90, Failures: 0, Errors: 2, Skipped: 5, Time elapsed: 38.732 s <<< FAILURE! - in okhttp3.internal.http2.HttpOverHttp2Test
[ERROR] concurrentRequestWithEmptyFlowControlWindowh2_prior_knowledge Time elapsed: 10.092 s <<< ERROR!
java.net.SocketTimeoutException: timeout
at okhttp3.internal.http2.HttpOverHttp2Test.concurrentRequestWithEmptyFlowControlWindow(HttpOverHttp2Test.java:388)
[ERROR] concurrentRequestWithEmptyFlowControlWindowh2 Time elapsed: 10.206 s <<< ERROR!
java.net.SocketTimeoutException: timeout
at okhttp3.internal.http2.HttpOverHttp2Test.concurrentRequestWithEmptyFlowControlWindow(HttpOverHttp2Test.java:388)
[INFO]
[INFO] Results:
[INFO]
[ERROR] Errors:
[ERROR] HttpOverHttp2Test.concurrentRequestWithEmptyFlowControlWindow:388 » SocketTimeout
[ERROR] HttpOverHttp2Test.concurrentRequestWithEmptyFlowControlWindow:388 » SocketTimeout
[INFO]
[ERROR] Tests run: 90, Failures: 0, Errors: 2, Skipped: 5
[INFO]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 52.072 s
[INFO] Finished at: 2018-07-09T10:03:16-04:00
[INFO] ------------------------------------------------------------------------
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:2.21.0:test (default-test) on project okhttp-tests: There are test failures.
[ERROR]
[ERROR] Please refer to /Users/nroy/github/okhttp/okhttp-tests/target/surefire-reports for the individual test results.
[ERROR] Please refer to dump files (if any exist) [date]-jvmRun[N].dump, [date].dumpstream and [date]-jvmRun[N].dumpstream.

@natez0r
Copy link

natez0r commented Jul 9, 2018

I ran my test app with frame logging, here are the logs frame_log.txt

Socket timeout was thrown at 5:59:24 in the logs

07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: Exception thrown:
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: com.google.android.exoplayer2.upstream.HttpDataSource$HttpDataSourceException: Unable to connect to https://video.twimg.com/ext_tw_video/974711634357874688/pr/pl/oJogd9M9-jDXIHQz.m3u8
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at com.google.android.exoplayer2.ext.okhttp.OkHttpDataSource.open(OkHttpDataSource.java:171)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at test_app.nroy.twitter.com.exoplayerplayground.DownloadTest$3.load(DownloadTest.java:153)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at com.google.android.exoplayer2.upstream.Loader$LoadTask.run(Loader.java:317)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at java.lang.Thread.run(Thread.java:764)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: Caused by: java.net.SocketTimeoutException: timeout
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http2.Http2Stream$StreamTimeout.newTimeoutException(Http2Stream.java:605)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http2.Http2Stream$StreamTimeout.exitAndThrowIfTimedOut(Http2Stream.java:613)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http2.Http2Stream.takeResponseHeaders(Http2Stream.java:146)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http2.Http2Codec.readResponseHeaders(Http2Codec.java:127)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:88)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at test_app.nroy.twitter.com.exoplayerplayground.MainActivity.lambda$onCreate$0$MainActivity(MainActivity.java:29)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at test_app.nroy.twitter.com.exoplayerplayground.MainActivity$$Lambda$0.intercept(Unknown Source:22)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at com.facebook.stetho.okhttp3.StethoInterceptor.intercept(StethoInterceptor.java:56)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:45)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:93)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:126)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:200)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at okhttp3.RealCall.execute(RealCall.java:77)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: at com.google.android.exoplayer2.ext.okhttp.OkHttpDataSource.open(OkHttpDataSource.java:167)
07-09 17:59:24.591 23623 23857 E ExoPlayerPlayground: ... 5 more

@dave-r12
Copy link
Collaborator Author

dave-r12 commented Jul 9, 2018

When I wrote that comment, I had checked out your patch and that test failed for me:

I thought I had reproduced but realized I made a change to okhttp module for the test to pass (need to flush the HEADERS frame for the second request.) Can you compile/install that module (okhttp) and run again?

@dave-r12
Copy link
Collaborator Author

dave-r12 commented Jul 9, 2018

I ran my test app with frame logging, here are the logs frame_log.txt

That's helpful, thanks. It almost looks like there is a buffer sitting between the client/server and it's trickling DATA frames to the client. In other words, there's a backlog of DATA frames that are waiting to be delivered from the first request and the response to the second request is at the end of that backlog. What happens if you increase the read timeout of the second request?

@natez0r
Copy link

natez0r commented Jul 10, 2018

That's helpful, thanks. It almost looks like there is a buffer sitting between the client/server and it's trickling DATA frames to the client. In other words, there's a backlog of DATA frames that are waiting to be delivered from the first request and the response to the second request is at the end of that backlog. What happens if you increase the read timeout of the second request?

heh, I wonder if this is how genymotion throttles connections to make them 'Edge', which is not a great actual approximation of network speed.

I had previously upped the timeout and still saw issues, but now i upped it to 500 seconds and can't get the socket timeout to happen again.

@natez0r
Copy link

natez0r commented Jul 10, 2018

I thought I had reproduced but realized I made a change to okhttp module for the test to pass (need to flush the HEADERS frame for the second request.) Can you compile/install that module (okhttp) and run again?

after doing a mvn clean install the tests pass for me

connection.writeSynReply(id, outFinished, responseHeaders);

if (outFinished) {
if (outFinished || connectionWindowEmpty) {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Tempted to refactor this so it’s more symmetric with the code in Http2Connection.newStream(). In particular:

  • we could replace the outFinished local with a different boolean, flushHeaders.
  • we could only check if the connection window is empty if flushHeaders is false.

But as-is this definitely makes responses and requests work more similarly and therefore I think it’s a big improvement.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ie.

if (!flushHeaders) {
  synchronized (connection) {
    flushHeaders = connection.bytesLeftInWriteWindow == 0L;
  }
}

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Turns out it isn’t quite that simple, cause we need to keep outFinished to send with the headers. Regardless, I did this fixup.

@swankjesse
Copy link
Collaborator

Nice improvement.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants