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

Received a Maximum active streams violated for this endpoint. from client side #3858

Closed
jrhee17 opened this issue Oct 5, 2021 · 11 comments · Fixed by #3908
Closed

Received a Maximum active streams violated for this endpoint. from client side #3858

jrhee17 opened this issue Oct 5, 2021 · 11 comments · Fixed by #3908
Labels
Milestone

Comments

@jrhee17
Copy link
Contributor

jrhee17 commented Oct 5, 2021

armeria version: 1.8.0
verified client-side isn't changing MAX_CONCURRENT_STREAMS

 java.util.concurrent.CompletionException: com.linecorp.armeria.client.UnprocessedRequestException: io.netty.handler.codec.http2.Http2Exception$StreamException: Maximum active streams violated for this endpoint.
	at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331)
	at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346)
	at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:632)
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
	at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088)
	at com.linecorp.armeria.internal.common.HttpObjectAggregator.fail(HttpObjectAggregator.java:145)
	at com.linecorp.armeria.internal.common.HttpObjectAggregator.onError(HttpObjectAggregator.java:61)
	at com.linecorp.armeria.common.stream.DeferredStreamMessage$ForwardingSubscriber.onError(DeferredStreamMessage.java:347)
	at com.linecorp.armeria.common.stream.AbstractStreamMessage$CloseEvent.notifySubscriber(AbstractStreamMessage.java:276)
	at com.linecorp.armeria.common.stream.DefaultStreamMessage.notifySubscriberOfCloseEvent0(DefaultStreamMessage.java:284)
	at com.linecorp.armeria.common.stream.DefaultStreamMessage.notifySubscriberOfCloseEvent(DefaultStreamMessage.java:276)
	at com.linecorp.armeria.common.stream.DefaultStreamMessage.handleCloseEvent(DefaultStreamMessage.java:448)
	at com.linecorp.armeria.common.stream.DefaultStreamMessage.notifySubscriber0(DefaultStreamMessage.java:391)
	at com.linecorp.armeria.common.stream.DefaultStreamMessage.doRequest(DefaultStreamMessage.java:259)
	at com.linecorp.armeria.common.stream.DefaultStreamMessage.request(DefaultStreamMessage.java:242)
	at com.linecorp.armeria.common.stream.AbstractStreamMessage$SubscriptionImpl.request(AbstractStreamMessage.java:218)
	at com.linecorp.armeria.common.stream.DeferredStreamMessage$ForwardingSubscriber.onSubscribe(DeferredStreamMessage.java:335)
	at com.linecorp.armeria.common.stream.DefaultStreamMessage.subscribe(DefaultStreamMessage.java:147)
	at com.linecorp.armeria.common.stream.DefaultStreamMessage.subscribe(DefaultStreamMessage.java:130)
	at com.linecorp.armeria.common.stream.AbstractStreamMessage.subscribe(AbstractStreamMessage.java:67)
	at com.linecorp.armeria.common.stream.DeferredStreamMessage.safeOnSubscribeToUpstream(DeferredStreamMessage.java:282)
	at com.linecorp.armeria.common.stream.DeferredStreamMessage.delegate(DeferredStreamMessage.java:121)
	at com.linecorp.armeria.common.DeferredHttpResponse.delegate(DeferredHttpResponse.java:48)
	at com.linecorp.armeria.common.DeferredHttpResponse.lambda$delegateWhenComplete$0(DeferredHttpResponse.java:59)
	at java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:930)
	at java.base/java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:907)
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
	at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073)
	at com.linecorp.armeria.client.retry.RetryingClient.lambda$handleBackoff$9(RetryingClient.java:398)
	at java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:930)
	at java.base/java.util.concurrent.CompletableFuture.uniHandleStage(CompletableFuture.java:946)
	at java.base/java.util.concurrent.CompletableFuture.handle(CompletableFuture.java:2266)
	at java.base/java.util.concurrent.CompletableFuture.handle(CompletableFuture.java:143)
	at com.linecorp.armeria.client.retry.RetryingClient.lambda$handleResponse$6(RetryingClient.java:352)
	at java.base/java.util.concurrent.CompletableFuture.uniAcceptNow(CompletableFuture.java:753)
	at java.base/java.util.concurrent.CompletableFuture.uniAcceptStage(CompletableFuture.java:731)
	at java.base/java.util.concurrent.CompletableFuture.thenAccept(CompletableFuture.java:2108)
	at com.linecorp.armeria.client.retry.RetryingClient.handleResponse(RetryingClient.java:312)
	at com.linecorp.armeria.client.retry.RetryingClient.doExecute0(RetryingClient.java:297)
	at com.linecorp.armeria.client.retry.RetryingClient.lambda$handleBackoff$8(RetryingClient.java:392)
	at com.linecorp.armeria.common.RequestContext.lambda$makeContextAware$3(RequestContext.java:546)
	at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
	at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: com.linecorp.armeria.client.UnprocessedRequestException: io.netty.handler.codec.http2.Http2Exception$StreamException: Maximum active streams violated for this endpoint.
	at com.linecorp.armeria.client.UnprocessedRequestException.of(UnprocessedRequestException.java:45)
	at com.linecorp.armeria.client.HttpRequestSubscriber.operationComplete(HttpRequestSubscriber.java:134)
	at com.linecorp.armeria.client.HttpRequestSubscriber.operationComplete(HttpRequestSubscriber.java:54)
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578)
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:552)
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491)
	at io.netty.util.concurrent.DefaultPromise.addListener(DefaultPromise.java:184)
	at io.netty.channel.DefaultChannelPromise.addListener(DefaultChannelPromise.java:95)
	at io.netty.channel.DefaultChannelPromise.addListener(DefaultChannelPromise.java:30)
	at com.linecorp.armeria.client.HttpRequestSubscriber.writeFirstHeader(HttpRequestSubscriber.java:205)
	at com.linecorp.armeria.client.HttpRequestSubscriber.onSubscribe(HttpRequestSubscriber.java:181)
	at com.linecorp.armeria.common.stream.DefaultStreamMessageDuplicator$DownstreamSubscription.invokeOnSubscribe0(DefaultStreamMessageDuplicator.java:672)
	at com.linecorp.armeria.common.stream.DefaultStreamMessageDuplicator$DownstreamSubscription.invokeOnSubscribe(DefaultStreamMessageDuplicator.java:663)
	at com.linecorp.armeria.common.stream.DefaultStreamMessageDuplicator$StreamMessageProcessor.doSubscribe(DefaultStreamMessageDuplicator.java:292)
	at com.linecorp.armeria.common.stream.DefaultStreamMessageDuplicator$StreamMessageProcessor.subscribe(DefaultStreamMessageDuplicator.java:272)
	at com.linecorp.armeria.common.stream.DefaultStreamMessageDuplicator$ChildStreamMessage.subscribe0(DefaultStreamMessageDuplicator.java:537)
	at com.linecorp.armeria.common.stream.DefaultStreamMessageDuplicator$ChildStreamMessage.subscribe(DefaultStreamMessageDuplicator.java:525)
	at com.linecorp.armeria.common.stream.DefaultStreamMessageDuplicator$ChildStreamMessage.subscribe(DefaultStreamMessageDuplicator.java:515)
	at com.linecorp.armeria.common.stream.StreamMessageWrapper.subscribe(StreamMessageWrapper.java:80)
	at com.linecorp.armeria.client.HttpSessionHandler.invoke(HttpSessionHandler.java:203)
	at com.linecorp.armeria.client.HttpClientDelegate.doExecute(HttpClientDelegate.java:276)
	at com.linecorp.armeria.client.HttpClientDelegate.acquireConnectionAndExecute(HttpClientDelegate.java:162)
	at com.linecorp.armeria.client.HttpClientDelegate.finishResolve(HttpClientDelegate.java:123)
	at com.linecorp.armeria.client.HttpClientDelegate.execute(HttpClientDelegate.java:106)
	at com.linecorp.armeria.client.HttpClientDelegate.execute(HttpClientDelegate.java:51)
	at com.linecorp.armeria.client.metric.AbstractMetricCollectingClient.execute(AbstractMetricCollectingClient.java:62)
	at com.linecorp.armeria.internal.client.ClientUtil.pushAndExecute(ClientUtil.java:150)
	at com.linecorp.armeria.internal.client.ClientUtil.executeWithFallback(ClientUtil.java:138)
	at com.linecorp.armeria.client.retry.RetryingClient.doExecute0(RetryingClient.java:286)
	... 11 common frames omitted
Caused by: io.netty.handler.codec.http2.Http2Exception$StreamException: Maximum active streams violated for this endpoint.
	at io.netty.handler.codec.http2.Http2Exception.streamError(Http2Exception.java:152)
	at io.netty.handler.codec.http2.DefaultHttp2Connection$DefaultEndpoint.checkNewStreamAllowed(DefaultHttp2Connection.java:896)
	at io.netty.handler.codec.http2.DefaultHttp2Connection$DefaultEndpoint.createStream(DefaultHttp2Connection.java:748)
	at io.netty.handler.codec.http2.DefaultHttp2Connection$DefaultEndpoint.createStream(DefaultHttp2Connection.java:668)
	at io.netty.handler.codec.http2.DefaultHttp2ConnectionEncoder.writeHeaders0(DefaultHttp2ConnectionEncoder.java:201)
	at io.netty.handler.codec.http2.DefaultHttp2ConnectionEncoder.writeHeaders(DefaultHttp2ConnectionEncoder.java:151)
	at io.netty.handler.codec.http2.DecoratingHttp2FrameWriter.writeHeaders(DecoratingHttp2FrameWriter.java:45)
	at com.linecorp.armeria.client.ClientHttp2ObjectEncoder.doWriteHeaders(ClientHttp2ObjectEncoder.java:73)
	at com.linecorp.armeria.client.ClientHttpObjectEncoder.writeHeaders(ClientHttpObjectEncoder.java:41)
	at com.linecorp.armeria.client.HttpRequestSubscriber.writeFirstHeader(HttpRequestSubscriber.java:204)
	... 30 common frames omitted
@jrhee17
Copy link
Contributor Author

jrhee17 commented Oct 5, 2021

Reported by @techno 🙇‍♂️

@jrhee17
Copy link
Contributor Author

jrhee17 commented Oct 16, 2021

Leaving notes on recent findings (I haven't forgotten about this issue 😄 )

  1. I've been looking into the Http2ConnectionHandlerBuilder#encoderEnforceMaxConcurrentStreams option (which adds a StreamBufferingEncoder decorator for queueing http2 requests when the maxConcurrentStreams limit is reached).
    Assuming the underlying issue is a timing issue where maxConcurrentStreams is updated after requests are piggybacked, I think this approach is promising.

    One downside of this approach is users may incur high latency since requests are enqueued until either 1) the maxConcurrentStreams remote setting is changed 2) other streams are done, creating room for a new stream. It might actually be better to let users retry in this case.

  2. I'm also looking into ways where we can notify the user when the maxConcurrentStreams limit has been changed (perhaps we can catch and re-throw with more details, or fix the exception message upstream in netty) to confirm whether server-side is actually changing the maxConcurrentStreams setting.

Unfortunately, I'm still trying to find a way to consistently reproduce this behavior in unit/integration tests at the moment. Will post more updates if I find anything

@jrhee17
Copy link
Contributor Author

jrhee17 commented Oct 17, 2021

I'm also looking into ways where we can notify the user when the maxConcurrentStreams limit has been changed (perhaps we can catch and re-throw with more details, or fix the exception message upstream in netty) to confirm whether server-side is actually changing the maxConcurrentStreams setting.

It seems like this was fixed with netty/netty#11644 and included in 4.1.68.FINAL (included by armeria since 1.12.0). If this version is applied, at least we can verify if the server-side is actually changing the maxConcurrentStreams value.

@jrhee17
Copy link
Contributor Author

jrhee17 commented Oct 17, 2021

Additional note: Rather than trying to fix the issue for users, maybe we can start with providing metrics s.t. users can understand why the exception is occurring.

Possibly we may be able to record metrics on numActiveStreams, maxActiveStreams for each endpoint (note that each connection may be configured differently, so we should think of how to provide such metrics).

Another alternative may be to add a callback s.t. users can be notified whenever HTTP/2 settings are changed. (i.e. something like ConnectionPoolListener)

@ikhoon ikhoon added the defect label Oct 18, 2021
@jrhee17
Copy link
Contributor Author

jrhee17 commented Oct 28, 2021

(Update) We received a reproducible code via a private message.
In particular, I was able to find maxConcurrentStreams related exceptions after WriteTimeoutException logs were printed.

I'm currently guessing that the timing for decrementing current streams isn't synchronized between armeria and netty completely.

e.g.

1. armeria increases activeStreams
2. netty increases activeStreams
3. an exception (e.g. `WriteTimeoutException`) is thrown, and armeria closes the stream (but netty isn't aware yet)
4. armeria tries to send another request through the same connection, and receives an exception related to `maxConcurrentStreams`

Will post more details after analyzing

@ks-yim
Copy link
Contributor

ks-yim commented Nov 9, 2021

Got the same error in a seemingly different scenario.

This happened when a WebClient has a decorator which makes a request to the same host as the client it is decorating.
Diagram to better describe the scenario..:
image

This error is reproducible, so I will share the minimal example soon.

java.util.concurrent.CompletionException: com.linecorp.armeria.client.UnprocessedRequestException: io.netty.handler.codec.http2.Http2Exception$StreamException: Maximum active streams violated for this endpoint: 20
	at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331)
	at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346)
	at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:632)
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
	at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2158)
	at com.linecorp.armeria.internal.shaded.futures.CompletableFutures.lambda$allAsList$0(CompletableFutures.java:89)
	at java.base/java.util.concurrent.CompletableFuture.uniExceptionally(CompletableFuture.java:986)
	at java.base/java.util.concurrent.CompletableFuture$UniExceptionally.tryFire(CompletableFuture.java:970)
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
	at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2158)
	at com.linecorp.armeria.common.util.UnmodifiableFuture.doCompleteExceptionally(UnmodifiableFuture.java:139)
	at com.linecorp.armeria.common.util.UnmodifiableFuture.lambda$wrap$0(UnmodifiableFuture.java:98)
	at java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:930)
	at java.base/java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:907)
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
	at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2158)
	at com.linecorp.armeria.common.stream.DeferredStreamMessage.lambda$delegate$0(DeferredStreamMessage.java:132)
	at java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:930)
	at java.base/java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:907)
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
	at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2158)
	at com.linecorp.armeria.common.stream.StreamMessageCollector.onError(StreamMessageCollector.java:80)
	at com.linecorp.armeria.common.stream.AbstractStreamMessage$CloseEvent.notifySubscriber(AbstractStreamMessage.java:267)
	at com.linecorp.armeria.common.stream.DefaultStreamMessage.notifySubscriberOfCloseEvent0(DefaultStreamMessage.java:288)
	at com.linecorp.armeria.common.stream.DefaultStreamMessage.notifySubscriberOfCloseEvent(DefaultStreamMessage.java:280)
	at com.linecorp.armeria.common.stream.DefaultStreamMessage.handleCloseEvent(DefaultStreamMessage.java:417)
	at com.linecorp.armeria.common.stream.DefaultStreamMessage.notifySubscriber0(DefaultStreamMessage.java:360)
	at com.linecorp.armeria.common.stream.DefaultStreamMessage.doRequest(DefaultStreamMessage.java:263)
	at com.linecorp.armeria.common.stream.DefaultStreamMessage.request(DefaultStreamMessage.java:246)
	at com.linecorp.armeria.common.stream.AbstractStreamMessage$SubscriptionImpl.request(AbstractStreamMessage.java:209)
	at com.linecorp.armeria.common.stream.StreamMessageCollector.onSubscribe(StreamMessageCollector.java:52)
	at com.linecorp.armeria.common.stream.DefaultStreamMessage.subscribe(DefaultStreamMessage.java:148)
	at com.linecorp.armeria.common.stream.DefaultStreamMessage.lambda$subscribe$0(DefaultStreamMessage.java:134)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:831)
Caused by: com.linecorp.armeria.client.UnprocessedRequestException: io.netty.handler.codec.http2.Http2Exception$StreamException: Maximum active streams violated for this endpoint: 20
	at app//com.linecorp.armeria.client.UnprocessedRequestException.of(UnprocessedRequestException.java:45)
	at app//com.linecorp.armeria.client.HttpRequestSubscriber.operationComplete(HttpRequestSubscriber.java:133)
	at app//com.linecorp.armeria.client.HttpRequestSubscriber.operationComplete(HttpRequestSubscriber.java:53)
	at app//io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578)
	at app//io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:552)
	at app//io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491)
	at app//io.netty.util.concurrent.DefaultPromise.addListener(DefaultPromise.java:184)
	at app//io.netty.channel.DefaultChannelPromise.addListener(DefaultChannelPromise.java:95)
	at app//io.netty.channel.DefaultChannelPromise.addListener(DefaultChannelPromise.java:30)
	at app//com.linecorp.armeria.client.HttpRequestSubscriber.writeFirstHeader(HttpRequestSubscriber.java:205)
	at app//com.linecorp.armeria.client.HttpRequestSubscriber.onSubscribe(HttpRequestSubscriber.java:180)
	at app//com.linecorp.armeria.common.stream.FixedStreamMessage.subscribe0(FixedStreamMessage.java:131)
	at app//com.linecorp.armeria.common.stream.FixedStreamMessage.subscribe(FixedStreamMessage.java:119)
	at app//com.linecorp.armeria.common.stream.EmptyFixedStreamMessage.subscribe(EmptyFixedStreamMessage.java:29)
	at app//com.linecorp.armeria.common.HeaderOverridingHttpRequest.subscribe(HeaderOverridingHttpRequest.java:94)
	at app//com.linecorp.armeria.client.HttpSessionHandler.invoke(HttpSessionHandler.java:201)
	at app//com.linecorp.armeria.client.HttpClientDelegate.doExecute(HttpClientDelegate.java:239)
	at app//com.linecorp.armeria.client.HttpClientDelegate.acquireConnectionAndExecute0(HttpClientDelegate.java:172)
	at app//com.linecorp.armeria.client.HttpClientDelegate.acquireConnectionAndExecute(HttpClientDelegate.java:141)
	at app//com.linecorp.armeria.client.HttpClientDelegate.lambda$execute$0(HttpClientDelegate.java:99)
	at app//com.linecorp.armeria.client.HttpClientDelegate.resolveAddress(HttpClientDelegate.java:124)
	at app//com.linecorp.armeria.client.HttpClientDelegate.execute(HttpClientDelegate.java:95)
	at app//com.linecorp.armeria.client.HttpClientDelegate.execute(HttpClientDelegate.java:47)
	at app//com.linecorp.channel.auth.client.AuthenticatingClient.lambda$execute$0(AuthenticatingClient.java:32)
	at java.base@16.0.1/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:642)
	at java.base@16.0.1/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
	at java.base@16.0.1/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2143)
	at app//com.linecorp.channel.auth.client.strategy.AbstractTokenStrategy.lambda$accessToken$1(AbstractTokenStrategy.java:78)
	at java.base@16.0.1/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:930)
	at java.base@16.0.1/java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:907)
	at java.base@16.0.1/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
	at java.base@16.0.1/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2143)
	at app//com.linecorp.armeria.common.util.UnmodifiableFuture.doComplete(UnmodifiableFuture.java:124)
	at app//com.linecorp.armeria.common.util.UnmodifiableFuture.lambda$wrap$0(UnmodifiableFuture.java:100)
	at java.base@16.0.1/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:930)
	at java.base@16.0.1/java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:907)
	at java.base@16.0.1/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
	at java.base@16.0.1/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2143)
	at app//com.linecorp.armeria.common.stream.DeferredStreamMessage.lambda$delegate$0(DeferredStreamMessage.java:130)
	at java.base@16.0.1/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:930)
	at java.base@16.0.1/java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:907)
	at java.base@16.0.1/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
	at java.base@16.0.1/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2143)
	at app//com.linecorp.armeria.common.stream.StreamMessageCollector.onComplete(StreamMessageCollector.java:67)
	at app//com.linecorp.armeria.common.stream.AbstractStreamMessage$CloseEvent.notifySubscriber(AbstractStreamMessage.java:256)
	at app//com.linecorp.armeria.common.stream.DefaultStreamMessage.notifySubscriberOfCloseEvent0(DefaultStreamMessage.java:288)
	at app//com.linecorp.armeria.common.stream.DefaultStreamMessage.notifySubscriberOfCloseEvent(DefaultStreamMessage.java:280)
	at app//com.linecorp.armeria.common.stream.DefaultStreamMessage.handleCloseEvent(DefaultStreamMessage.java:417)
	at app//com.linecorp.armeria.common.stream.DefaultStreamMessage.notifySubscriber0(DefaultStreamMessage.java:360)
	at app//com.linecorp.armeria.common.stream.DefaultStreamMessage.notifySubscriber(DefaultStreamMessage.java:316)
	at app//com.linecorp.armeria.common.stream.DefaultStreamMessage.addObjectOrEvent(DefaultStreamMessage.java:302)
	at app//com.linecorp.armeria.common.stream.DefaultStreamMessage.close(DefaultStreamMessage.java:424)
	at app//com.linecorp.armeria.client.HttpResponseDecoder$HttpResponseWrapper.closeAction(HttpResponseDecoder.java:338)
	at app//com.linecorp.armeria.client.HttpResponseDecoder$HttpResponseWrapper.cancelTimeoutOrLog(HttpResponseDecoder.java:371)
	at app//com.linecorp.armeria.client.HttpResponseDecoder$HttpResponseWrapper.close(HttpResponseDecoder.java:321)
	at app//com.linecorp.armeria.client.HttpResponseDecoder$HttpResponseWrapper.close(HttpResponseDecoder.java:310)
	at app//com.linecorp.armeria.client.Http2ResponseDecoder.onDataRead(Http2ResponseDecoder.java:273)
	at app//io.netty.handler.codec.http2.Http2FrameListenerDecorator.onDataRead(Http2FrameListenerDecorator.java:36)
	at app//io.netty.handler.codec.http2.Http2EmptyDataFrameListener.onDataRead(Http2EmptyDataFrameListener.java:49)
	at app//io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder$FrameReadListener.onDataRead(DefaultHttp2ConnectionDecoder.java:307)
	at app//io.netty.handler.codec.http2.Http2InboundFrameLogger$1.onDataRead(Http2InboundFrameLogger.java:48)
	at app//io.netty.handler.codec.http2.DefaultHttp2FrameReader.readDataFrame(DefaultHttp2FrameReader.java:415)
	at app//io.netty.handler.codec.http2.DefaultHttp2FrameReader.processPayloadState(DefaultHttp2FrameReader.java:250)
	at app//io.netty.handler.codec.http2.DefaultHttp2FrameReader.readFrame(DefaultHttp2FrameReader.java:159)
	at app//io.netty.handler.codec.http2.Http2InboundFrameLogger.readFrame(Http2InboundFrameLogger.java:41)
	at app//io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder.decodeFrame(DefaultHttp2ConnectionDecoder.java:173)
	at app//io.netty.handler.codec.http2.DecoratingHttp2ConnectionDecoder.decodeFrame(DecoratingHttp2ConnectionDecoder.java:63)
	at app//io.netty.handler.codec.http2.Http2ConnectionHandler$FrameDecoder.decode(Http2ConnectionHandler.java:378)
	at app//io.netty.handler.codec.http2.Http2ConnectionHandler.decode(Http2ConnectionHandler.java:438)
	at app//io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:507)
	at app//io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446)
	at app//io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at app//io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at app//io.netty.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:280)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at app//io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at app//io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1372)
	at app//io.netty.handler.ssl.SslHandler.decodeNonJdkCompatible(SslHandler.java:1246)
	at app//io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1286)
	at app//io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:507)
	at app//io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446)
	at app//io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at app//io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at app//io.netty.handler.flush.FlushConsolidationHandler.channelRead(FlushConsolidationHandler.java:152)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at app//io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at app//io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at app//io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at app//io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	at app//io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
	at app//io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)
	at app//io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
	at app//io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
	at app//io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
	... 4 more
Caused by: io.netty.handler.codec.http2.Http2Exception$StreamException: Maximum active streams violated for this endpoint: 20
	at app//io.netty.handler.codec.http2.Http2Exception.streamError(Http2Exception.java:152)
	at app//io.netty.handler.codec.http2.DefaultHttp2Connection$DefaultEndpoint.checkNewStreamAllowed(DefaultHttp2Connection.java:902)
	at app//io.netty.handler.codec.http2.DefaultHttp2Connection$DefaultEndpoint.createStream(DefaultHttp2Connection.java:751)
	at app//io.netty.handler.codec.http2.DefaultHttp2Connection$DefaultEndpoint.createStream(DefaultHttp2Connection.java:671)
	at app//io.netty.handler.codec.http2.DefaultHttp2ConnectionEncoder.writeHeaders0(DefaultHttp2ConnectionEncoder.java:201)
	at app//io.netty.handler.codec.http2.DefaultHttp2ConnectionEncoder.writeHeaders(DefaultHttp2ConnectionEncoder.java:151)
	at app//com.linecorp.armeria.client.ClientHttp2ObjectEncoder.doWriteHeaders(ClientHttp2ObjectEncoder.java:70)
	at app//com.linecorp.armeria.client.ClientHttpObjectEncoder.writeHeaders(ClientHttpObjectEncoder.java:41)
	at app//com.linecorp.armeria.client.HttpRequestSubscriber.writeFirstHeader(HttpRequestSubscriber.java:204)
	... 95 more

@ks-yim
Copy link
Contributor

ks-yim commented Nov 9, 2021

Demonstration..:
https://github.com/ks-yim/max-stream-violated/blob/main/src/test/java/MaxStreamViolatedTest.java

It turns out that I was wrong about the cause in the above comment. It's not related to decorator or 2 different clients with the same host.

The exception occurs when requests are made in a callback of another request like...:

 // exception
client.get("/resource").aggregate().thenRun(() -> concurrentReqToSameHost());

// but exception is not thrown if `concurrentReqToSameHost()` is called in async callback;
client.get("/resource").aggregate().thenRunAsync(() -> concurrentReqToSameHost(), ctx.eventLoop());

More on this in the demo code.

@jrhee17
Copy link
Contributor Author

jrhee17 commented Nov 9, 2021

Thanks for the detailed analysis!

I think I understand why the exception occurs for the first case consistently.

The callback in thenRun() is run from the eventloop where the response is closed. At this point, unfinishedResponses has been decremented, but netty's numActiveStreams hasn't been decremented yet.

So I believe the flow is as follows:

  1. The first request succeeds and unfinishedResponses == 0, but numActiveStreams == 1.
  2. 10 new requests are queued (since MAX_CONCURRENT_STREAMS = 10)
  3. The last request fails, since unfinishedResponses == 9, but numActiveStreams == 10.
  4. All subsequent requests try to use the same connection, but fail due to MAX_CONCURRENT_STREAMS violation.

I've also verified that the test code passes for the branch #3908

@ikhoon ikhoon added this to the 1.14.0 milestone Nov 9, 2021
@ks-yim
Copy link
Contributor

ks-yim commented Nov 9, 2021

I've also verified that the test code passes for the branch

Good to hear that, thanks for the nice work!!

Just 1 more question..:

  • Would it be a reliable workaround to use ...Async callback with ctx.eventLoop() like in the 2nd case? I am asking this since the AuthDecorator that I mentioned in the first place should work with armeria <= 1.14.0.

@jrhee17
Copy link
Contributor Author

jrhee17 commented Nov 10, 2021

If this bug is blocking development, then I think the above workaround is fine (assuming that the additional cost for rescheduling the task via thenRunAsync is acceptable)

I would also like to note though that the Maximum active streams.. exception can't be 100% avoided since there are other edge cases where the exception can be thrown until the fix is merged. (although I also think the bug should occur with a very low probability in practice)

I'm unsure how AuthDecorator works, but I think calling execute() from a decorator shouldn't be very different from calling execute() directly on the WebClient

@ks-yim
Copy link
Contributor

ks-yim commented Nov 11, 2021

Thanks again.
I've consulted with ikhoon and got almost the same answer. (can't be avoided in some edge cases though I use async callback).

I am thinking about giving a different ClientFactory to the WebClient used within the decorator or downgrade its session protocol to H1. The decorator tries to renew its access token(the part that potentially causes this error) every 15min, so I think the cost is trivial.

minwoox pushed a commit that referenced this issue Nov 23, 2021
**Background**

Currently, armeria maintains a state `HttpResponseDecoder#unfinishedResponses` to check how many in-flight requests are being processed for a connection.

Armeria uses this value to check if all connections occupy too many concurrent streams, and creates a new connection if necessary.

On the other hand, netty maintains it's own state to check how many in-flight requests are being processed for a connection. (`DefaultHttp2Connection.DefaultEndpoint#numActiveStreams`)

Netty checks this value before creating a stream, and throws a `Http2Exception$StreamException` if `MAX_CONCURRENT_STREAMS` is unavailable.

**Problem Statement**

Currently, when a `WriteTimeoutException` is triggered, armeria decrements `unfinishedResponses` and removes the response. (A `WriteTimeoutException` is thrown when a request header isn't written within a predefined `writeTimeoutMillis`)
However, netty may not be aware that armeria has failed the response. Consequently, netty's `numActiveStreams` is greater than armeria's `unfinishedResponses`. This may cause a violation of `MAX_CONCURRENT_STREAMS` for additional requests on the connection.

**Motivation**
Netty always calls `Http2ResponseDecoder.onStreamClosed` before decrementing `numActiveStreams`.
If we want `numActiveStreams` to be in sync with `unfinishedResponses`, I propose that we modify the timing of decrementing `unfinishedResponses` to `Http2ResponseDecoder.onStreamClosed`.

In detail, when a `WriteTimeoutException` is scheduled

https://github.com/line/armeria/blob/117a21e17ec9e30b0c3c2d74d16fdde3cab62434/core/src/main/java/com/linecorp/armeria/client/HttpRequestSubscriber.java#L171-L173

the response is closed.

https://github.com/line/armeria/blob/117a21e17ec9e30b0c3c2d74d16fdde3cab62434/core/src/main/java/com/linecorp/armeria/client/HttpRequestSubscriber.java#L318

Consequently, after the stream processes the `close` event, `whenComplete` is triggered.

https://github.com/line/armeria/blob/117a21e17ec9e30b0c3c2d74d16fdde3cab62434/core/src/main/java/com/linecorp/armeria/client/Http2ResponseDecoder.java#L83-L90

And the response is removed (and `unfinishedResponses` is decremented)

https://github.com/line/armeria/blob/117a21e17ec9e30b0c3c2d74d16fdde3cab62434/core/src/main/java/com/linecorp/armeria/client/Http2ResponseDecoder.java#L101

However, as far as netty is concerned, the request may have been written and may still be processing.

**Misc**

Reproduced `maxConcurrentStreams` when `WriteTimeoutException` occurs at 225a684

**Modifications**

- Remove the `removeResponse` call from `Http2ResponseDecoder. onWrapperCompleted`, and rely on `onStreamClosed` to remove the response/decrement `unfinishedResponses`
- When receiving callbacks for `onHeadersRead`, `onDataRead`, `onRstStreamRead`, also check if `resWrapper` had been closed. This preserves behavior since `res` was previously removed on `WriteTimeoutException`, resulting in `res == null`.


*Update*

I realized that if we simply don't process values when headers/data/rst are received, then we might not send a `GoAway` and close the connection when `disconnectWhenFinished = true` due to df43379.

I've verified this behavior from test cases added in 8018da1

I've modified further such that:
- Only remove responses when `onStreamClosed` is called.
- Remove calls to `channel().close();` if `shouldSendGoAway()` is true for `onDataRead`, `onHeadersRead` since `onStreamClosed` will handle this instead.
- Remove `onStreamClosed` to try to close the `ResponseWrapper` only if the underlying `delegate` is open.

d1183d8

There is a slight change of behavior, where a `GoAway` may be triggered from `onRstStream` as well. Let me know if this change shouldn't be made 🙏 

Result:

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

Successfully merging a pull request may close this issue.

3 participants