Unimplemented service causes MessageDeframer exceptions in the log #1795
Description
I'm seeing exceptions running grpc-java 0.14.0 in production (same with 0.13.2). Reproducible on both linux and mac with oracle jdk 1.8.0_66.
mai 05, 2016 10:12:52 AM io.grpc.internal.AbstractServerStream deframeFailed
WARNING: Exception processing message
java.lang.IllegalStateException: MessageDeframer is already closed
at com.google.common.base.Preconditions.checkState(Preconditions.java:174)
at io.grpc.internal.MessageDeframer.checkNotClosed(MessageDeframer.java:222)
at io.grpc.internal.MessageDeframer.deframe(MessageDeframer.java:168)
at io.grpc.internal.AbstractStream.deframe(AbstractStream.java:276)
at io.grpc.internal.AbstractServerStream.inboundDataReceived(AbstractServerStream.java:156)
at io.grpc.netty.NettyServerStream.inboundDataReceived(NettyServerStream.java:83)
at io.grpc.netty.NettyServerHandler.onDataRead(NettyServerHandler.java:214)
at io.grpc.netty.NettyServerHandler.access$200(NettyServerHandler.java:93)
at io.grpc.netty.NettyServerHandler$FrameListener.onDataRead(NettyServerHandler.java:425)
at io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder$FrameReadListener.onDataRead(DefaultHttp2ConnectionDecoder.java:250)
at io.netty.handler.codec.http2.Http2InboundFrameLogger$1.onDataRead(Http2InboundFrameLogger.java:46)
at io.netty.handler.codec.http2.DefaultHttp2FrameReader.readDataFrame(DefaultHttp2FrameReader.java:409)
at io.netty.handler.codec.http2.DefaultHttp2FrameReader.processPayloadState(DefaultHttp2FrameReader.java:240)
at io.netty.handler.codec.http2.DefaultHttp2FrameReader.readFrame(DefaultHttp2FrameReader.java:147)
at io.netty.handler.codec.http2.Http2InboundFrameLogger.readFrame(Http2InboundFrameLogger.java:39)
at io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder.decodeFrame(DefaultHttp2ConnectionDecoder.java:111)
at io.netty.handler.codec.http2.Http2ConnectionHandler$FrameDecoder.decode(Http2ConnectionHandler.java:331)
at io.netty.handler.codec.http2.Http2ConnectionHandler.decode(Http2ConnectionHandler.java:391)
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:387)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:245)
at io.netty.channel.ChannelHandlerInvokerUtil.invokeChannelReadNow(ChannelHandlerInvokerUtil.java:83)
at io.netty.channel.DefaultChannelHandlerInvoker.invokeChannelRead(DefaultChannelHandlerInvoker.java:154)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:354)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:145)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:1078)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:117)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:527)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:484)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:398)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:370)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:742)
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:145)
at java.lang.Thread.run(Thread.java:745)
I've found the following code reproduces the exceptions (the number of rounds required may vary as it doesn't happen for all requests):
Server grpcServer = NettyServerBuilder.forPort(0).build();
grpcServer.start();
ManagedChannel channel = NettyChannelBuilder.forAddress("localhost", grpcServer.getPort()).usePlaintext(true).build();
for (int x= 0; x < 100; ++x) {
try {
HealthGrpc.newBlockingStub(channel).check(HealthCheckRequest.getDefaultInstance());
} catch (StatusRuntimeException e) {
if (e.getStatus().getCode() != Code.UNIMPLEMENTED) {
throw new RuntimeException(e);
}
}
}
System.err.println("done");
If you replace Netty with InProcess, you can get the following exception (the number of rounds must be increased a lot, though):
mai 05, 2016 10:33:46 AM io.grpc.internal.SerializingExecutor$TaskRunner run
SEVERE: Exception while executing runnable io.grpc.internal.ServerImpl$ServerTransportListenerImpl$1@2d83238d
java.lang.NullPointerException
at io.grpc.inprocess.InProcessTransport$InProcessStream$InProcessClientStream.internalCancel(InProcessTransport.java:484)
at io.grpc.inprocess.InProcessTransport$InProcessStream$InProcessClientStream.serverClosed(InProcessTransport.java:435)
at io.grpc.inprocess.InProcessTransport$InProcessStream$InProcessClientStream.access$1000(InProcessTransport.java:381)
at io.grpc.inprocess.InProcessTransport$InProcessStream$InProcessServerStream.close(InProcessTransport.java:335)
at io.grpc.internal.ServerImpl$ServerTransportListenerImpl$1.runInContext(ServerImpl.java:316)
at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:54)
at io.grpc.internal.SerializingExecutor$TaskRunner.run(SerializingExecutor.java:154)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)