Logspam from Netty if sending when cancelled

[byblakeorriver]

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]

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

[ejona86]

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]

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