Issue
I have a very weird behavioural difference when my Java program is run with Java 8 and Java 11.
I am using the MSGraph API (1.7.0) to make several calls to the Onedrive APIs. To make these calls, I am using 4 parallel threads for sync a lot of files (around 1000) on my hard disk.
When I execute the program with Java 8, I get no exceptions. When I execute it with java 11, I get a Socket Timeout Exception in around the 60% of the calls.
To configure the IGraphServiceClient, I am using the default configuration. As far as I am concerned, the HTTP Provider is OKHttp3 in this case.
Has anybody experienced anything like this?
[UPDATE-1]
These are the environments I have tested:
- Oracle's JDK 1.8.0_192 --> Perfect. Not an error in around 400 calls
- Openjdk 11.0.7 and Oracle's jdk 11.0.3 --> tons of Sokcet Timeout Exceptions
Hereby you have the stacktrace:
com.microsoft.graph.core.ClientException: Error during http request
at com.microsoft.graph.http.CoreHttpProvider.sendRequestInternal(CoreHttpProvider.java:422) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.http.CoreHttpProvider.send(CoreHttpProvider.java:204) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.http.CoreHttpProvider.send(CoreHttpProvider.java:184) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.http.BaseStreamRequest.send(BaseStreamRequest.java:85) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.requests.extensions.DriveItemStreamRequest.get(DriveItemStreamRequest.java:55) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.provider.onedrive.OnedriveServiceClient.download(OnedriveServiceClient.java:236) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.provider.onedrive.OnedriveFile.download(OnedriveFile.java:42) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.model.wrapper.RemoteFile.download(RemoteFile.java:20) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.syncing.task.LocalFileDownloadSyncTask.downloadIntoTemp(LocalFileDownloadSyncTask.java:71) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.syncing.task.LocalFileDownloadSyncTask.execute(LocalFileDownloadSyncTask.java:54) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.syncing.Syncer.lambda$taskRunner$1(Syncer.java:66) ~[easybox-0.1-SNAPSHOT.jar:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: java.net.SocketTimeoutException: timeout
at okhttp3.internal.http2.Http2Stream$StreamTimeout.newTimeoutException(Http2Stream.java:656) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http2.Http2Stream$StreamTimeout.exitAndThrowIfTimedOut(Http2Stream.java:664) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http2.Http2Stream.takeHeaders(Http2Stream.java:153) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http2.Http2Codec.readResponseHeaders(Http2Codec.java:131) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:88) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:45) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:93) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:126) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.httpcore.TelemetryHandler.intercept(TelemetryHandler.java:35) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.httpcore.RedirectHandler.intercept(RedirectHandler.java:123) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.httpcore.RetryHandler.intercept(RetryHandler.java:140) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.httpcore.AuthenticationHandler.intercept(AuthenticationHandler.java:31) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:254) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.RealCall.execute(RealCall.java:92) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.http.CoreHttpProvider.sendRequestInternal(CoreHttpProvider.java:356) ~[easybox-0.1-SNAPSHOT.jar:?]
... 15 more
and a second stacktrace
Caused by: java.net.SocketTimeoutException: timeout
at okhttp3.internal.http2.Http2Stream$StreamTimeout.newTimeoutException(Http2Stream.java:656) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http2.Http2Stream$StreamTimeout.exitAndThrowIfTimedOut(Http2Stream.java:664) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http2.Http2Stream$FramingSource.read(Http2Stream.java:398) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http2.Http2Codec$StreamFinishingSource.read(Http2Codec.java:205) ~[easybox-0.1-SNAPSHOT.jar:?]
at okio.RealBufferedSource$1.read(RealBufferedSource.java:439) ~[easybox-0.1-SNAPSHOT.jar:?]
at java.io.BufferedInputStream.fill(BufferedInputStream.java:252) ~[?:?]
at java.io.BufferedInputStream.read1(BufferedInputStream.java:292) ~[?:?]
at java.io.BufferedInputStream.read(BufferedInputStream.java:351) ~[?:?]
at java.io.FilterInputStream.read(FilterInputStream.java:107) ~[?:?]
at easybox.provider.onedrive.OnedriveServiceClient.download(OnedriveServiceClient.java:239) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.provider.onedrive.OnedriveFile.download(OnedriveFile.java:42) ~[easybox-0.1-SNAPSHOT.jar:?]
... 9 more
[UPDATE-2]
After overriding the okhttp dependency to versions 3.14.9 and 4.7.2 (latest available), everything is still the same, although something has changed. Besides the usual timeout exception:
com.microsoft.graph.core.ClientException: Error during http request
at com.microsoft.graph.http.CoreHttpProvider.sendRequestInternal(CoreHttpProvider.java:422) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.http.CoreHttpProvider.send(CoreHttpProvider.java:204) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.http.CoreHttpProvider.send(CoreHttpProvider.java:184) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.http.BaseStreamRequest.send(BaseStreamRequest.java:85) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.requests.extensions.DriveItemStreamRequest.get(DriveItemStreamRequest.java:55) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.provider.onedrive.OnedriveServiceClient.download(OnedriveServiceClient.java:236) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.provider.onedrive.OnedriveFile.download(OnedriveFile.java:42) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.model.wrapper.RemoteFile.download(RemoteFile.java:20) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.syncing.task.LocalFileDownloadSyncTask.downloadIntoTemp(LocalFileDownloadSyncTask.java:71) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.syncing.task.LocalFileDownloadSyncTask.execute(LocalFileDownloadSyncTask.java:54) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.syncing.Syncer.lambda$taskRunner$1(Syncer.java:66) ~[easybox-0.1-SNAPSHOT.jar:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: java.net.SocketTimeoutException: timeout
at okhttp3.internal.http2.Http2Stream$StreamTimeout.newTimeoutException(Http2Stream.kt:677) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http2.Http2Stream$StreamTimeout.exitAndThrowIfTimedOut(Http2Stream.kt:686) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http2.Http2Stream.takeHeaders(Http2Stream.kt:143) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http2.Http2ExchangeCodec.readResponseHeaders(Http2ExchangeCodec.kt:96) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:106) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:79) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:96) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.httpcore.TelemetryHandler.intercept(TelemetryHandler.java:35) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.httpcore.RedirectHandler.intercept(RedirectHandler.java:123) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.httpcore.RetryHandler.intercept(RetryHandler.java:140) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.httpcore.AuthenticationHandler.intercept(AuthenticationHandler.java:31) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:197) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.connection.RealCall.execute(RealCall.kt:148) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.http.CoreHttpProvider.sendRequestInternal(CoreHttpProvider.java:356) ~[easybox-0.1-SNAPSHOT.jar:?]
... 15 more
a new one appears from time to time:
com.microsoft.graph.core.ClientException: Error during http request
at com.microsoft.graph.http.CoreHttpProvider.sendRequestInternal(CoreHttpProvider.java:422) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.http.CoreHttpProvider.send(CoreHttpProvider.java:204) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.http.CoreHttpProvider.send(CoreHttpProvider.java:184) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.http.BaseStreamRequest.send(BaseStreamRequest.java:85) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.requests.extensions.DriveItemStreamRequest.get(DriveItemStreamRequest.java:55) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.provider.onedrive.OnedriveServiceClient.download(OnedriveServiceClient.java:236) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.provider.onedrive.OnedriveFile.download(OnedriveFile.java:42) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.model.wrapper.RemoteFile.download(RemoteFile.java:20) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.syncing.task.LocalFileDownloadSyncTask.downloadIntoTemp(LocalFileDownloadSyncTask.java:71) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.syncing.task.LocalFileDownloadSyncTask.execute(LocalFileDownloadSyncTask.java:54) ~[easybox-0.1-SNAPSHOT.jar:?]
at easybox.syncing.Syncer.lambda$taskRunner$1(Syncer.java:66) ~[easybox-0.1-SNAPSHOT.jar:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: okhttp3.internal.http2.StreamResetException: stream was reset: CANCEL
at okhttp3.internal.http2.Http2Stream.takeHeaders(Http2Stream.kt:148) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http2.Http2ExchangeCodec.readResponseHeaders(Http2ExchangeCodec.kt:96) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.connection.Exchange.readResponseHeaders(Exchange.kt:106) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.kt:79) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:34) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:96) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.httpcore.TelemetryHandler.intercept(TelemetryHandler.java:35) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.httpcore.RedirectHandler.intercept(RedirectHandler.java:123) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.httpcore.RetryHandler.intercept(RetryHandler.java:140) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.httpcore.AuthenticationHandler.intercept(AuthenticationHandler.java:31) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:100) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:197) ~[easybox-0.1-SNAPSHOT.jar:?]
at okhttp3.internal.connection.RealCall.execute(RealCall.kt:148) ~[easybox-0.1-SNAPSHOT.jar:?]
at com.microsoft.graph.http.CoreHttpProvider.sendRequestInternal(CoreHttpProvider.java:356) ~[easybox-0.1-SNAPSHOT.jar:?]
... 15 more
Solution
OkHttp on JDK9 (or JDK8 252+), will negotiate HTTP/2 by default. There is a high chance it is related to this change.
Try building a client without HTTP/2 and see if you still get this problem.
val client = OkHttpClient.Builder()
.protocols(listOf(Protocol.HTTP_1_1))
.build()
If it fixes things, it's likely either an incompatibility of the server with HTTP/2, or related to connection reuse e.g. too many requests over a single connection.
UPDATE by kekolab 20201030.
Microsoft fixed the issue by restraining the protocol version to 1.1, exactly as suggested by the OP Yuri above. Nice stuff, this thread is referenced in the code: https://github.com/microsoftgraph/msgraph-sdk-java/pull/473/files#
Answered By - Yuri Schimke
Answer Checked By - Candace Johnson (JavaFixing Volunteer)
