search

grpc / grpc-java

The Java gRPC implementation. HTTP/2 based RPC
https://grpc.io/docs/languages/java/
Apache License 2.0
11.4k stars 3.83k forks source link

Logspam from Netty if sending when cancelled #6943

Open byblakeorriver opened 4 years ago

byblakeorriver commented 4 years ago

What version of gRPC-Java are you using?

1.27.0

What is your environment?

Docker image: adoptopenjdk/openjdk8:alpine-slim

What did you expect to see?

I expect to see no unnecessary logs.

What did you see instead?

Unnecessary logs.

Steps to reproduce the bug

To reproduce, create a long lived server side streaming rpc, with a Netty server that has .maxConnectionAge() and .maxConnectionAgeGrace() set. Observe that when the age and grace period has passed you receive the following log: https://gist.github.com/byblakeorriver/6b3c80c8086399e2d922e5173bee12df

byblakeorriver commented 4 years ago

@ejona86 Thanks for the clarification about these logs being noise!

ejona86 commented 4 years ago

This issue is related to cancellation, which is caused by maxConnectionAgeGrace(). If a sender has queued data when it receives a cancellation this is triggered, so it should be easy to reproduce (I think some of our existing tests may produce this). However, it is also not an error. When this happens the stream is being thrown away, so it is "okay" that we are throwing away data. It truly is just logspam.

This may be a complex order-of-processing issue, or maybe we need to check if the stream is cancelled during some particular log statement.

Cleaned up exception from gist:

io.netty.handler.codec.http2.Http2Exception$StreamException: Stream closed before write could take place
    at io.netty.handler.codec.http2.Http2Exception.streamError(Http2Exception.java:167)
    at io.netty.handler.codec.http2.DefaultHttp2RemoteFlowController$FlowState.cancel(DefaultHttp2RemoteFlowController.java:481)
    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.deactivate(DefaultHttp2Connection.java:956)
    at io.netty.handler.codec.http2.DefaultHttp2Connection$DefaultStream.close(DefaultHttp2Connection.java:512)
    at io.netty.handler.codec.http2.DefaultHttp2Connection.close(DefaultHttp2Connection.java:152)
    at io.netty.handler.codec.http2.Http2ConnectionHandler$BaseDecoder.channelInactive(Http2ConnectionHandler.java:209)
    at io.netty.handler.codec.http2.Http2ConnectionHandler.channelInactive(Http2ConnectionHandler.java:417)
    at io.grpc.netty.NettyServerHandler.channelInactive(NettyServerHandler.java:592)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:257)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:243)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:236)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1417)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:257)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:243)
    at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:913)
    at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:819)
    at io.grpc.Context$1.run(Context.java:595)
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:510)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:518)
    at io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1044)
    at io.grpc.Context$1.run(Context.java:595)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.grpc.Context$1.run(Context.java:595)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Unknown Source)
byblakeorriver commented 4 years ago

Error gets logged here: https://github.com/grpc/grpc-java/blob/master/netty/src/main/java/io/grpc/netty/NettyServerHandler.java#L523