INTERNAL: Panic! This is a bug! at io.grpc.stub.ClientCalls.toStatusRuntimeException caused by NullPointerException

[awangugi-sc]

What version of gRPC-Java are you using?

1.37.0

What is your environment?

jdk 1.8, appengine

What did you expect to see?

Expect to see a successful call, I have also added retry on Internal and that does not seem to work for this error. Though I've tested it works with typical INTERNAL errors.

What did you see instead?

Internal Runtime Exception, the request does not make it out from the client.

Steps to reproduce the bug

I am unable to reproduce the bug, it sporadically occurs.

Here is how I setup my stub:

jwt_token = input.readLine();
Metadata header = new Metadata();
Metadata.Key key = Metadata.Key.of("JWT", Metadata.ASCII_STRING_MARSHALLER);
header.put(key, "");
channel = ManagedChannelBuilder.forTarget(target)
  .forAddress(host, port)
  .overrideAuthority(target)
  .defaultServiceConfig(serviceConfig)
  .enableRetry()
  .maxRetryAttempts(MAX_RETRY_ATTEMPTS)
  .maxInboundMessageSize(INBOUND_MESSAGE_MAX_LIMIT)
  .build();
blockingStub = MetadataUtils.attachHeaders(SigningServiceGrpc.newBlockingStub(channel), header);
stub = MetadataUtils.attachHeaders(SigningServiceGrpc.newStub(channel), header);

And here is my retry_config:

{
    "methodConfig":
    [
        {
            "name": [{}],
            "retryPolicy":
            {
                "maxAttempts": 6,
                "initialBackoff": "0.5s",
                "maxBackoff": "30s",
                "backoffMultiplier": 2,
                "retryableStatusCodes":
                [
                    "UNAVAILABLE",
                    "INTERNAL"
                ]
            }
        }
    ]
}

Stack Trace: SigningServiceGrpc is our proto generated code.
INTERNAL: Panic! This is a bug!
    at io.grpc.stub.ClientCalls.toStatusRuntimeException(ClientCalls.java:262)
    at io.grpc.stub.ClientCalls.getUnchecked(ClientCalls.java:243)
    at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:156)
    at com..signingservice.SigningServiceGrpc$SigningServiceBlockingStub.sign(SigningServiceGrpc.java:184)
    at com.registration.release.SigningServiceClient.sign(SigningServiceClient.java:117)
    at com.registration.release.DockerReleaser.copyToDockerRegistry(DockerReleaser.java:773)
    at com.registration.release.DockerReleaser.releaseDockerImagesForServiceMesh(DockerReleaser.java:997)
    at com.registration.release.ServiceMeshReleaser.processPostBuildActionImpl(ServiceMeshReleaser.java:180)
    at com.registration.release.ServiceMeshReleaser.processPostBuildAction(ServiceMeshReleaser.java:109)
    at com.registration.release.Releaser.lambda$null$2(Releaser.java:1044)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:829)
caused by: java.lang.NullPointerException: null
    at io.grpc.Metadata.valueAsBytes(Metadata.java:180)
    at io.grpc.Metadata.serialize(Metadata.java:471)
    at io.grpc.InternalMetadata.serialize(InternalMetadata.java:78)
    at io.grpc.internal.TransportFrameUtil.toHttp2Headers(TransportFrameUtil.java:51)
    at io.grpc.netty.shaded.io.grpc.netty.Utils.convertClientHeaders(Utils.java:222)
    at io.grpc.netty.shaded.io.grpc.netty.NettyClientStream$Sink.writeHeadersInternal(NettyClientStream.java:145)
    at io.grpc.netty.shaded.io.grpc.netty.NettyClientStream$Sink.writeHeaders(NettyClientStream.java:121)
    at io.grpc.internal.AbstractClientStream.start(AbstractClientStream.java:159)
    at io.grpc.internal.ForwardingClientStream.start(ForwardingClientStream.java:92)
    at io.grpc.internal.InternalSubchannel$CallTracingTransport$1.start(InternalSubchannel.java:681)
    at io.grpc.internal.DelayedStream.internalStart(DelayedStream.java:256)
    at io.grpc.internal.DelayedStream.setStream(DelayedStream.java:143)
    at io.grpc.internal.DelayedClientTransport$PendingStream.createRealStream(DelayedClientTransport.java:364)
    at io.grpc.internal.DelayedClientTransport$PendingStream.access$300(DelayedClientTransport.java:346)
    at io.grpc.internal.DelayedClientTransport.reprocess(DelayedClientTransport.java:304)
    at io.grpc.internal.ManagedChannelImpl.updateSubchannelPicker(ManagedChannelImpl.java:886)
    at io.grpc.internal.ManagedChannelImpl.access$5200(ManagedChannelImpl.java:118)
    at io.grpc.internal.ManagedChannelImpl$LbHelperImpl$1UpdateBalancingState.run(ManagedChannelImpl.java:1439)
    at io.grpc.SynchronizationContext.drain(SynchronizationContext.java:95)
    at io.grpc.SynchronizationContext.execute(SynchronizationContext.java:127)
    at io.grpc.internal.InternalSubchannel$TransportListener.transportReady(InternalSubchannel.java:546)
    at io.grpc.netty.shaded.io.grpc.netty.ClientTransportLifecycleManager.notifyReady(ClientTransportLifecycleManager.java:44)
    at io.grpc.netty.shaded.io.grpc.netty.NettyClientHandler$FrameListener.onSettingsRead(NettyClientHandler.java:915)
    at io.grpc.netty.shaded.io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder$FrameReadListener.onSettingsRead(DefaultHttp2ConnectionDecoder.java:479)
    at io.grpc.netty.shaded.io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder$PrefaceFrameListener.onSettingsRead(DefaultHttp2ConnectionDecoder.java:702)
    at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2InboundFrameLogger$1.onSettingsRead(Http2InboundFrameLogger.java:93)
    at io.grpc.netty.shaded.io.netty.handler.codec.http2.DefaultHttp2FrameReader.readSettingsFrame(DefaultHttp2FrameReader.java:542)
    at io.grpc.netty.shaded.io.netty.handler.codec.http2.DefaultHttp2FrameReader.processPayloadState(DefaultHttp2FrameReader.java:263)
    at io.grpc.netty.shaded.io.netty.handler.codec.http2.DefaultHttp2FrameReader.readFrame(DefaultHttp2FrameReader.java:160)
    at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2InboundFrameLogger.readFrame(Http2InboundFrameLogger.java:41)
    at io.grpc.netty.shaded.io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder.decodeFrame(DefaultHttp2ConnectionDecoder.java:174)
    at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2ConnectionHandler$FrameDecoder.decode(Http2ConnectionHandler.java:378)
    at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2ConnectionHandler$PrefaceDecoder.decode(Http2ConnectionHandler.java:242)
    at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2ConnectionHandler.decode(Http2ConnectionHandler.java:438)
    at io.grpc.netty.shaded.io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:501)
    at io.grpc.netty.shaded.io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:440)
    at io.grpc.netty.shaded.io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)
    at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.grpc.netty.shaded.io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1526)
    at io.grpc.netty.shaded.io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1275)
    at io.grpc.netty.shaded.io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1322)
    at io.grpc.netty.shaded.io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:501)
    at io.grpc.netty.shaded.io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:440)
    at io.grpc.netty.shaded.io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)
    at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.grpc.netty.shaded.io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
    at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.grpc.netty.shaded.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.grpc.netty.shaded.io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
    at io.grpc.netty.shaded.io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:795)
    at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:475)
    at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:378)
    at io.grpc.netty.shaded.io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.grpc.netty.shaded.io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.grpc.netty.shaded.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
... 1 common frames elided

[sanjaypujare]

Can you upgrade to the latest version - 1.51.0 and see if it still happens?

[awangugi-sc]

Can you upgrade to the latest version - 1.51.0 and see if it still happens?

Yah I can do that, but I wonder if there is any reason in particular we think that 1.51.0 would do better?

[sanjaypujare]

Without looking at the details of the issue there is a small chance that the bug might have been fixed. Even otherwise 1.37 is 18 months old so we always recommend upgrading to the latest version.

[ejona86]

Looks like the Metadata.Marshaller returned null. That is a bug. We could have some code to detect this case earlier and make it a more clear exception. But the actual fix is almost certainly in the application.

[ejona86]

Actually, I do see some weird case maybe when metadata.remove() is used. Dunno. But this isn't something we've seen before and it isn't worth our time to debug the year-and-a-half-old 1.37.0, which won't even get updates if we find a problem. I still expect this to happen on newer versions and Metadata hasn't changed much, but retries have had plenty of fixes.

[ejona86]

I can reproduce this on master, but only if the Marshaller is returning null. I tried to get remove() to cause trouble, but it didn't. The case I've reproduced here is really just an application/marshaller bug; the most we'd do is throw an exception earlier.

diff --git a/api/src/test/java/io/grpc/MetadataTest.java b/api/src/test/java/io/grpc/MetadataTest.java
index 51aecc638..594e2520b 100644
--- a/api/src/test/java/io/grpc/MetadataTest.java
+++ b/api/src/test/java/io/grpc/MetadataTest.java
@@ -119,6 +119,26 @@ public class MetadataTest {
   private static final Metadata.Key<Fish> KEY_IMMUTABLE =
       Metadata.Key.of("immutable-bin", IMMUTABLE_FISH_MARSHALLER);
 
+  @Test
+  public void foo() {
+    Metadata metadata = new Metadata();
+    Metadata.Key<byte[]> key = Metadata.Key.of("foo-bin", new Metadata.BinaryMarshaller<byte[]>() {
+        @Override
+        public byte[] toBytes(byte[] value) {
+          return null;
+        }
+
+        @Override
+        public byte[] parseBytes(byte[] serialized) {
+          return serialized;
+        }
+      });
+    metadata.put(key, new byte[0] /* value ignored */);
+    // null is not allowed. It throws NPE during put()
+    //metadata.put(key, null);
+    metadata.serialize();
+  }
+
   @Test
   public void noPseudoHeaders() {
     thrown.expect(IllegalArgumentException.class);

[awangugi-sc]

I see, so the application error must occur when the marshaller in attempts to get the bytes returns null? We're using the ascii string marshaller, is it possible there is an error there? Looking at the code, it mentions that it only works with characters listed from a specific class. Do you know what class it is talking about or which comment?

[ejona86]

I don't think that error is possible with an AsciiMarshaller. It was looking like it needed to be a BinaryMarshaller. So either there is another way to trigger it or one of the very BinaryMarshallers is getting something wrong.

[awangugi-sc]

The other idea I had was I saw that Metadata.java is not threadsafe, but I thought grpc clients were usable in concurrent use cases?

[ejona86]

You can do lots of concurrent RPCs, but you shouldn't share Metadata across them. The stubs create a new metadata object for each RPC.

The main thing that prevents concurrent access of Metadata is only using it when in full control of it. The moment you pass Metadata to the next interceptor, for example, the code gives up the right to access the Metadata.

[ejona86]

#9781 is merged which would detect broken Marshallers early. It wouldn't detect an issue if it was due to application multithreading.

[ejona86]

It doesn't seem we can make any more progress on this, as we still suspect something in the application may be causing the issue. The fix for early NPE checking will be available in 1.53, which may help, but that seems to be all we can do at the moment.

If you find out more, either nowish or once upgrading to 1.53, comment and we can reopen. You can also open a new issue if this gets locked before you get to that point.