search

line / armeria

Your go-to microservice framework for any situation, from the creator of Netty et al. You can build any type of microservice leveraging your favorite technologies, including gRPC, Thrift, Kotlin, Retrofit, Reactive Streams, Spring Boot and Dropwizard.
https://armeria.dev
Apache License 2.0
4.8k stars 914 forks source link

'cannot start a new stream with a DATA frame' error under load #1410

Closed trustin closed 4 years ago

trustin commented 5 years ago

.. probably due to an unexpected disconnection.

17:06:32.883 [armeria-common-worker-epoll-2-11] WARN  c.l.armeria.server.HttpServerHandler - [id: 0x39d2ed0f, L:/127.0.0.1:44525 - R:/127.0.0.1:40232][h2c] Unexpected exception:
java.lang.IllegalStateException: cannot start a new stream 177893 with a DATA frame
        at com.linecorp.armeria.internal.Http2ObjectEncoder.doWriteData(Http2ObjectEncoder.java:92)
        at com.linecorp.armeria.internal.HttpObjectEncoder.writeData(HttpObjectEncoder.java:74)
        at com.linecorp.armeria.server.HttpResponseSubscriber.write0(HttpResponseSubscriber.java:295)
        at com.linecorp.armeria.server.HttpResponseSubscriber.lambda$write$1(HttpResponseSubscriber.java:286)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:326)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:844)
ikhoon commented 4 years ago

Another thread dump, It is caused by GoAway frame

"armeria-common-worker-nio-2-1@4812" daemon prio=5 tid=0x17 nid=NA runnable
  java.lang.Thread.State: RUNNABLE
      at com.linecorp.armeria.internal.Http2ObjectEncoder.doWriteData(Http2ObjectEncoder.java:93)
      at com.linecorp.armeria.internal.HttpObjectEncoder.writeData(HttpObjectEncoder.java:85)
      at com.linecorp.armeria.server.HttpResponseSubscriber.write(HttpResponseSubscriber.java:298)
      at com.linecorp.armeria.server.HttpResponseSubscriber.onNext(HttpResponseSubscriber.java:227)
      at com.linecorp.armeria.server.HttpResponseSubscriber.onNext(HttpResponseSubscriber.java:58)
      at com.linecorp.armeria.common.stream.DefaultStreamMessage.notifySubscriberWithElements(DefaultStreamMessage.java:341)
      at com.linecorp.armeria.common.stream.DefaultStreamMessage.notifySubscriber0(DefaultStreamMessage.java:319)
      at com.linecorp.armeria.common.stream.DefaultStreamMessage.doRequest(DefaultStreamMessage.java:188)
      at com.linecorp.armeria.common.stream.DefaultStreamMessage.request(DefaultStreamMessage.java:173)
      at com.linecorp.armeria.common.stream.AbstractStreamMessage$SubscriptionImpl.request(AbstractStreamMessage.java:276)
      at com.linecorp.armeria.server.HttpResponseSubscriber.lambda$write$1(HttpResponseSubscriber.java:333)
      at com.linecorp.armeria.server.HttpResponseSubscriber$$Lambda$348.500172825.operationComplete(Unknown Source:-1)
      at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:577)
      at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:570)
      at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:549)
      at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:490)
      at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:615)
      at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:604)
      at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:104)
      at io.netty.handler.codec.http2.Http2CodecUtil$SimpleChannelPromiseAggregator.tryPromise(Http2CodecUtil.java:383)
      at io.netty.handler.codec.http2.Http2CodecUtil$SimpleChannelPromiseAggregator.trySuccess(Http2CodecUtil.java:349)
      at io.netty.handler.codec.http2.Http2CodecUtil$SimpleChannelPromiseAggregator.trySuccess(Http2CodecUtil.java:261)
      at io.netty.util.internal.PromiseNotificationUtil.trySuccess(PromiseNotificationUtil.java:48)
      at io.netty.channel.ChannelOutboundBuffer.safeSuccess(ChannelOutboundBuffer.java:715)
      at io.netty.channel.ChannelOutboundBuffer.remove(ChannelOutboundBuffer.java:270)
      at io.netty.channel.ChannelOutboundBuffer.removeBytes(ChannelOutboundBuffer.java:350)
      at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:431)
      at io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:931)
      at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0(AbstractNioChannel.java:354)
      at io.netty.channel.AbstractChannel$AbstractUnsafe.flush(AbstractChannel.java:898)
      at io.netty.channel.DefaultChannelPipeline$HeadContext.flush(DefaultChannelPipeline.java:1384)
      at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:749)
      at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:741)
      at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:727)
      at io.netty.handler.flush.FlushConsolidationHandler.flushNow(FlushConsolidationHandler.java:206)
      at io.netty.handler.flush.FlushConsolidationHandler.flush(FlushConsolidationHandler.java:129)
      at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:749)
      at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:741)
      at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:727)
      at com.linecorp.armeria.internal.TrafficLoggingHandler.flush(TrafficLoggingHandler.java:49)
      at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:749)
      at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:741)
      at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:727)
      at io.netty.handler.codec.http2.Http2ConnectionHandler.onError(Http2ConnectionHandler.java:643)
      at io.netty.handler.codec.http2.DefaultHttp2ConnectionEncoder$FlowControlledData.error(DefaultHttp2ConnectionEncoder.java:441)
      at io.netty.handler.codec.http2.DefaultHttp2RemoteFlowController$FlowState.writeError(DefaultHttp2RemoteFlowController.java:534)
      at io.netty.handler.codec.http2.DefaultHttp2RemoteFlowController$FlowState.cancel(DefaultHttp2RemoteFlowController.java:484)
      at io.netty.handler.codec.http2.DefaultHttp2RemoteFlowController$1.onStreamClosed(DefaultHttp2RemoteFlowController.java:105)
      at io.netty.handler.codec.http2.DefaultHttp2Connection.notifyClosed(DefaultHttp2Connection.java:356)
      at io.netty.handler.codec.http2.DefaultHttp2Connection$ActiveStreams.removeFromActiveStreams(DefaultHttp2Connection.java:1000)
      at io.netty.handler.codec.http2.DefaultHttp2Connection$ActiveStreams$2.process(DefaultHttp2Connection.java:961)
      at io.netty.handler.codec.http2.DefaultHttp2Connection$ActiveStreams.decrementPendingIterations(DefaultHttp2Connection.java:1022)
      at io.netty.handler.codec.http2.DefaultHttp2Connection$ActiveStreams.forEachActiveStream(DefaultHttp2Connection.java:977)
      at io.netty.handler.codec.http2.DefaultHttp2Connection.forEachActiveStream(DefaultHttp2Connection.java:208)
      at com.linecorp.armeria.internal.AbstractHttp2ConnectionHandler.close(AbstractHttp2ConnectionHandler.java:121)
      at io.netty.channel.AbstractChannelHandlerContext.invokeClose(AbstractChannelHandlerContext.java:621)
      at io.netty.channel.AbstractChannelHandlerContext.close(AbstractChannelHandlerContext.java:605)
      at io.netty.channel.AbstractChannelHandlerContext.close(AbstractChannelHandlerContext.java:467)
      at io.netty.channel.DefaultChannelPipeline.close(DefaultChannelPipeline.java:969)
      at io.netty.channel.AbstractChannel.close(AbstractChannel.java:231)
      at com.linecorp.armeria.internal.Http2GoAwayHandler.onGoAwayReceived(Http2GoAwayHandler.java:86)
      at com.linecorp.armeria.server.Http2RequestDecoder.onGoAwayReceived(Http2RequestDecoder.java:318)
      at io.netty.handler.codec.http2.DefaultHttp2Connection.goAwayReceived(DefaultHttp2Connection.java:236)
      at io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder.onGoAwayRead0(DefaultHttp2ConnectionDecoder.java:217)
      at io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder$FrameReadListener.onGoAwayRead(DefaultHttp2ConnectionDecoder.java:551)
      at io.netty.handler.codec.http2.DefaultHttp2FrameReader.readGoAwayFrame(DefaultHttp2FrameReader.java:591)
      at io.netty.handler.codec.http2.DefaultHttp2FrameReader.processPayloadState(DefaultHttp2FrameReader.java:272)
      at io.netty.handler.codec.http2.DefaultHttp2FrameReader.readFrame(DefaultHttp2FrameReader.java:160)
      at io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder.decodeFrame(DefaultHttp2ConnectionDecoder.java:174)
      at io.netty.handler.codec.http2.DecoratingHttp2ConnectionDecoder.decodeFrame(DecoratingHttp2ConnectionDecoder.java:63)
      at io.netty.handler.codec.http2.Http2ConnectionHandler$FrameDecoder.decode(Http2ConnectionHandler.java:378)
      at io.netty.handler.codec.http2.Http2ConnectionHandler.decode(Http2ConnectionHandler.java:438)
      at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:503)
      at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:442)
      at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:281)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
      at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
      at io.netty.handler.logging.LoggingHandler.channelRead(LoggingHandler.java:241)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
      at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
      at io.netty.handler.flush.FlushConsolidationHandler.channelRead(FlushConsolidationHandler.java:154)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
      at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
      at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:287)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
      at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
      at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1422)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
      at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
      at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:931)
      at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
      at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:700)
      at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:635)
      at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:552)
      at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:514)
      at io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1050)
      at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
      at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
      at java.lang.Thread.run(Thread.java:835)
ikhoon commented 4 years ago

Based on the previous thread dump, 1) The server receives the GOAWAY frame. 2) Close all active streams before closing connection. https://github.com/line/armeria/blob/b29ea824f72b6c18a47ca55aef7f1902c958b043/core/src/main/java/com/linecorp/armeria/internal/AbstractHttp2ConnectionHandler.java#L120-L122 3) Flush outboundBuffer buffer. https://github.com/netty/netty/blob/0cde4d9cb4d19ddc0ecafc5be7c5f7c781a1f6e9/transport/src/main/java/io/netty/channel/AbstractChannel.java#L930 4) The callback of future.addListener is called after writing nioBuffers to channel. https://github.com/line/armeria/blob/84403ba1424faf85ca883bb6a299705a3198c4bd/core/src/main/java/com/linecorp/armeria/server/HttpResponseSubscriber.java#L307 5) Request the next item in the future.addListener. https://github.com/line/armeria/blob/84403ba1424faf85ca883bb6a299705a3198c4bd/core/src/main/java/com/linecorp/armeria/server/HttpResponseSubscriber.java#L333 6) Try to write the next item to the stream, but it was already closed on 2)