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

Drain response bodies before retrying #2987

Merged

Conversation

armanbilge
Copy link
Contributor

Workaround for http4s/http4s-jdk-http-client#714 (comment). Hopefully :)

@codecov
Copy link

codecov bot commented Feb 24, 2023

Codecov Report

Base: 90.84% // Head: 90.84% // No change to project coverage 👍

Coverage data is based on head (8fc1f26) compared to base (5216d47).
Patch has no changes to coverable lines.

Additional details and impacted files
@@           Coverage Diff           @@
##             main    #2987   +/-   ##
=======================================
  Coverage   90.84%   90.84%           
=======================================
  Files         160      160           
  Lines        3298     3298           
  Branches      314      314           
=======================================
  Hits         2996     2996           
  Misses        302      302           
Impacted Files Coverage Δ
...scalasteward/core/client/ClientConfiguration.scala 100.00% <ø> (ø)

Help us with your feedback. Take ten seconds to tell us how you rate us. Have a feature suggestion? Share it here.

☔ View full report at Codecov.
📢 Do you have feedback about the report comment? Let us know in this issue.

Copy link
Member

@fthomas fthomas left a comment

Choose a reason for hiding this comment

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

Thanks @armanbilge!

@daddykotex It would be nice to know if this fixes the error you reported in the http4s-jdk-http-client issue.

@fthomas fthomas merged commit 4453bae into scala-steward-org:main Feb 25, 2023
@fthomas fthomas added this to the 0.23.0 milestone Feb 25, 2023
@fthomas fthomas added the bug Something isn't working label Feb 25, 2023
@daddykotex
Copy link
Contributor

Last docker tag was build on: a16a482d. This should include this fix, yet our run failed with:

java.io.IOException: HTTP/1.1 header parser received no bytes
	at java.net.http/jdk.internal.net.http.common.Utils.wrapWithExtraDetail(Utils.java:327)
	at java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.onReadError(Http1Response.java:673)
	at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.checkForErrors(Http1AsyncReceiver.java:297)
	at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.flush(Http1AsyncReceiver.java:263)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SynchronizedRestartableTask.run(SequentialScheduler.java:175)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
	at java.net.http/jdk.internal.net.http.HttpClientImpl$DelegatingExecutor.execute(HttpClientImpl.java:153)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:273)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:242)
	at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.onReadError(Http1AsyncReceiver.java:506)
	at java.net.http/jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber.onComplete(Http1AsyncReceiver.java:591)
	at java.net.http/jdk.internal.net.http.common.SSLTube$DelegateWrapper.onComplete(SSLTube.java:268)
	at java.net.http/jdk.internal.net.http.common.SSLTube$SSLSubscriberWrapper.complete(SSLTube.java:432)
	at java.net.http/jdk.internal.net.http.common.SSLTube$SSLSubscriberWrapper.onComplete(SSLTube.java:562)
	at java.net.http/jdk.internal.net.http.common.SubscriberWrapper.checkCompletion(SubscriberWrapper.java:443)
	at java.net.http/jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run1(SubscriberWrapper.java:322)
	at java.net.http/jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run(SubscriberWrapper.java:261)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SynchronizedRestartableTask.run(SequentialScheduler.java:175)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)
	at java.net.http/jdk.internal.net.http.common.SubscriberWrapper.outgoing(SubscriberWrapper.java:234)
	at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader.processData(SSLFlowDelegate.java:468)
	at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader$ReaderDownstreamPusher.run(SSLFlowDelegate.java:264)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SynchronizedRestartableTask.run(SequentialScheduler.java:175)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
	at delay @ org.http4s.jdkhttpclient.JdkHttpClient$.$anonfun$apply$23(JdkHttpClient.scala:243)
	at fromCompletableFuture @ org.http4s.jdkhttpclient.JdkHttpClient$.$anonfun$apply$23(JdkHttpClient.scala:243)
	at apply @ org.http4s.jdkhttpclient.JdkHttpClient$.convertResponse$1(JdkHttpClient.scala:178)
	at tupled @ org.http4s.jdkhttpclient.JdkHttpClient$.convertResponse$1(JdkHttpClient.scala:178)
	at tupled @ org.http4s.jdkhttpclient.JdkHttpClient$.convertResponse$1(JdkHttpClient.scala:178)
	at main$ @ org.scalasteward.core.Main$.main(Main.scala:23)
	at main$ @ org.scalasteward.core.Main$.main(Main.scala:23)
	at main$ @ org.scalasteward.core.Main$.main(Main.scala:23)
	at use @ org.scalasteward.core.Main$.run(Main.scala:26)
	at flatMap @ org.scalasteward.core.util.HttpJsonClient.requestWithHeaders(HttpJsonClient.scala:84)
Caused by: java.io.EOFException: EOF reached while reading
	at java.net.http/jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber.onComplete(Http1AsyncReceiver.java:591)
	at java.net.http/jdk.internal.net.http.common.SSLTube$DelegateWrapper.onComplete(SSLTube.java:268)
	at java.net.http/jdk.internal.net.http.common.SSLTube$SSLSubscriberWrapper.complete(SSLTube.java:432)
	at java.net.http/jdk.internal.net.http.common.SSLTube$SSLSubscriberWrapper.onComplete(SSLTube.java:562)
	at java.net.http/jdk.internal.net.http.common.SubscriberWrapper.checkCompletion(SubscriberWrapper.java:443)
	at java.net.http/jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run1(SubscriberWrapper.java:322)
	at java.net.http/jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run(SubscriberWrapper.java:261)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SynchronizedRestartableTask.run(SequentialScheduler.java:175)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)
	at java.net.http/jdk.internal.net.http.common.SubscriberWrapper.outgoing(SubscriberWrapper.java:234)
	at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader.processData(SSLFlowDelegate.java:468)
	at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader$ReaderDownstreamPusher.run(SSLFlowDelegate.java:264)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SynchronizedRestartableTask.run(SequentialScheduler.java:175)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
	at cats.effect.unsafe.WorkerThread.run(WorkerThread.scala:555)

Looking at the stack, we may be looking at a different problem.

@armanbilge
Copy link
Contributor Author

Thanks for trying that! It may be that we need to drain the body in some other places as well.

Looking at the stack, we may be looking at a different problem.

Well, these kinds of issues are tricky to track down. In my experience usually it's the request before the request that appears to fail that has gone wrong. e.g. one request succeeds but corrupts the connection, the one after it goes wrong.

@fthomas
Copy link
Member

fthomas commented Feb 28, 2023

The stack trace also includes HttpJsonClient.requestWithHeaders but I looks to me that the response body is always read there:
https://github.com/scala-steward-org/scala-steward/blob/v0.22.0/modules/core/src/main/scala/org/scalasteward/core/util/HttpJsonClient.scala#L81-L107

@daddykotex
Copy link
Contributor

Today, the stack was a little bit different:

java.io.IOException: HTTP/1.1 header parser received no bytes
	at java.net.http/jdk.internal.net.http.common.Utils.wrapWithExtraDetail(Utils.java:327)
	at java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.onReadError(Http1Response.java:673)
	at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.checkForErrors(Http1AsyncReceiver.java:297)
	at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.flush(Http1AsyncReceiver.java:263)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SynchronizedRestartableTask.run(SequentialScheduler.java:175)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
	at delay @ org.http4s.jdkhttpclient.JdkHttpClient$.$anonfun$apply$23(JdkHttpClient.scala:243)
	at fromCompletableFuture @ org.http4s.jdkhttpclient.JdkHttpClient$.$anonfun$apply$23(JdkHttpClient.scala:243)
	at apply @ org.http4s.jdkhttpclient.JdkHttpClient$.convertResponse$1(JdkHttpClient.scala:178)
	at tupled @ org.http4s.jdkhttpclient.JdkHttpClient$.convertResponse$1(JdkHttpClient.scala:178)
	at tupled @ org.http4s.jdkhttpclient.JdkHttpClient$.convertResponse$1(JdkHttpClient.scala:178)
	at main$ @ org.scalasteward.core.Main$.main(Main.scala:23)
	at main$ @ org.scalasteward.core.Main$.main(Main.scala:23)
	at main$ @ org.scalasteward.core.Main$.main(Main.scala:23)
	at use @ org.scalasteward.core.Main$.run(Main.scala:26)
	at flatMap @ org.scalasteward.core.util.HttpJsonClient.requestWithHeaders(HttpJsonClient.scala:84)
Caused by: java.io.IOException: Connection reset by peer
	at java.base/sun.nio.ch.FileDispatcherImpl.read0(Native Method)
	at java.base/sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
	at java.base/sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276)
	at java.base/sun.nio.ch.IOUtil.read(IOUtil.java:233)
	at java.base/sun.nio.ch.IOUtil.read(IOUtil.java:223)
	at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:356)
	at java.net.http/jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1153)
	at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:821)
	at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:175)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)
	at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)
	at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.signalReadable(SocketTube.java:763)
	at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:941)
	at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:245)
	at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:957)
	at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:912)
	at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
	at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:912)

Ran on: b8648fcc

@daddykotex
Copy link
Contributor

I'm starting to think that the reason we see this error is due to rate limiting (but I'm not sure because after we see the error, the instance continues to create other PRs in other repos...). When you look at the docs for rate limiting it is specified that we can read:

You should wait and try your request again after a few minutes. If the retry-after response header is present, you should not retry your request until after that many seconds has elapsed. Otherwise, you should not retry your request until the time, in UTC epoch seconds, specified by the x-ratelimit-reset header.

Right after that, there is an example of response when rate limiting occurs:

> HTTP/2 403
> Content-Type: application/json; charset=utf-8
> Connection: close

> {
>   "message": "You have exceeded a secondary rate limit and have been temporarily blocked from content creation. Please retry your request again later.",
>   "documentation_url": "https://docs.github.com/rest/overview/resources-in-the-rest-api#secondary-rate-limits"
> }

We can see two things: http/2 and a connection:close. Maybe the issue is surrounding this use kind of response?

@armanbilge
Copy link
Contributor Author

Not sure about the connection to HTTP/2. The stack traces above are both mentioning HTTP/1 related classes.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants