Can't decode compressed gRPC message as compression not configured

[Hristo Katsarski]

Hello Everyone,

We got this error on the server-side of a bi-di streaming:

2023-01-23 23:41:54,879 ERROR [GRPC worker, id #1]  io.grpc.netty.shaded.io.grpc.netty.NettyServerStream$TransportState deframeFailed
WARNING: Exception processing message
io.grpc.StatusRuntimeException: INTERNAL: Can't decode compressed gRPC message as compression not configured
        at io.grpc.Status.asRuntimeException(Status.java:526)
        at io.grpc.internal.MessageDeframer.getCompressedBody(MessageDeframer.java:428)
        at io.grpc.internal.MessageDeframer.processBody(MessageDeframer.java:410)
        at io.grpc.internal.MessageDeframer.deliver(MessageDeframer.java:275)
        at io.grpc.internal.MessageDeframer.request(MessageDeframer.java:161)
        at io.grpc.internal.AbstractStream$TransportState$1RequestRunnable.run(AbstractStream.java:236)
        at io.grpc.netty.shaded.io.grpc.netty.NettyServerStream$TransportState$1.run(NettyServerStream.java:202)
        at io.grpc.netty.shaded.io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
        at io.grpc.netty.shaded.io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
        at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384)
        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 java.lang.Thread.run(Thread.java:748)

There were plenty of messages processed for few days, and all of a sudden this exception breaks the connection. What does it mean, and how can be solved?

Is there a way to trap and "swallow" such exception so that the channel does not get closed?

Using grpc netty shaded 1.42.1 with epoll.

Regards,

Chris

[sanjay...@google.com]

> There were plenty of messages processed for few days, and all of a sudden this exception breaks the connection. 

Is it possible some new clients (esp clients using another gRPC language) are now connecting which is why you are seeing this error?

> What does it mean, and how can be solved?

Can you enable debug/trace logging to see the value of the "grpc-encoding"  header for the offending RPC? That will give us some idea whether you need to use a custom decompressor registry.

[Hristo Katsarski]

>  Is it possible some new clients (esp clients using another gRPC language) are now connecting which is why you are seeing this error?

Both the client and the server are backend Java services. Both use same set of gRPC+ProtoBuf libraries. After removing below method on the client-side there are no more errors for few days (the communication is bi-di streaming and is always up, messages get exchanged constantly):

NettyChannelBuilder...enableFullStreamDecompression()

It might not be the reason though (the error was on the server-side), since the API says: 

Enables full-stream decompression of inbound streams. This will cause the channel's outboundheaders to advertise support for GZIP compressed streams, and gRPC servers which support the feature may respond with a GZIP compressed stream.

> Can you enable debug/trace logging to see the value of the "grpc-encoding"  header for the offending RPC? That will give us some idea whether you need to use a custom decompressor registry.

Could you please provide more info of how to do that? 

At present we have such logging config:

<logger name="io.grpc.netty.shaded.io.grpc.netty">
  <level value="debug"/>
  <appender-ref ref="GrpcCoreAppender"/>
</logger>

which produces log like that (no "grpc-encoding"  header in it):

DEBUG netty.NettyServerHandler - [id: 0x9f841cd8, L:/xxx:8443 - R:/yyy:43421] INBOUND PING: ack=false bytes=1234
DEBUG netty.NettyServerHandler - [id: 0x9f841cd8, L:/xxx:8443 - R:/yyy:43421] OUTBOUND PING: ack=true bytes=1234

DEBUG netty.NettyServerHandler - [id: 0x9f841cd8, L:/xxx:8443 - R:/yyy:43421] OUTBOUND DATA: streamId=3 padding=0 endStream=false length=249 bytes=00000000c708820610f8dc9594df30186b22b8010a0732353233363432120d6f706f732d3239373535316333180120033a06455552555344420b313030323432...

DEBUG netty.NettyServerHandler - [id: 0x9f841cd8, L:/xxx:8443 - R:/yyy:43421] INBOUND DATA: streamId=3 padding=0 endStream=false length=48 bytes=000000002b08e00110fbdc9594df301804221d0a0732353233363432120c6f72642d3239373735316333180220012803

[sanjay...@google.com]

On Friday, January 27, 2023 at 2:06:28 AM UTC-8 chris...@gmail.com wrote:

...

It might not be the reason though (the error was on the server-side), since the API says: 

Enables full-stream decompression of inbound streams. This will cause the channel's outboundheaders to advertise support for GZIP compressed streams, and gRPC servers which support the feature may respond with a GZIP compressed stream.

Yes, it looks unrelated so I am going to ignore it.

> Can you enable debug/trace logging to see the value of the "grpc-encoding"  header for the offending RPC? That will give us some idea whether you need to use a custom decompressor registry.

Could you please provide more info of how to do that? 

At present we have such logging config:

<logger name="io.grpc.netty.shaded.io.grpc.netty">
  <level value="debug"/>
  <appender-ref ref="GrpcCoreAppender"/>
</logger>

which produces log like that (no "grpc-encoding"  header in it):

DEBUG netty.NettyServerHandler - [id: 0x9f841cd8, L:/xxx:8443 - R:/yyy:43421] INBOUND PING: ack=false bytes=1234
DEBUG netty.NettyServerHandler - [id: 0x9f841cd8, L:/xxx:8443 - R:/yyy:43421] OUTBOUND PING: ack=true bytes=1234

DEBUG netty.NettyServerHandler - [id: 0x9f841cd8, L:/xxx:8443 - R:/yyy:43421] OUTBOUND DATA: streamId=3 padding=0 endStream=false length=249 bytes=00000000c708820610f8dc9594df30186b22b8010a0732353233363432120d6f706f732d3239373535316333180120033a06455552555344420b313030323432...

DEBUG netty.NettyServerHandler - [id: 0x9f841cd8, L:/xxx:8443 - R:/yyy:43421] INBOUND DATA: streamId=3 padding=0 endStream=false length=48 bytes=000000002b08e00110fbdc9594df301804221d0a0732353233363432120c6f72642d3239373735316333180220012803

The headers appear in a log message like this:

Aug 26, 2022 5:21:53 PM io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2FrameLogger logHeaders

FINE: [id: 0x22c81f9d, L:/xx.xx.x.xx:50052 - R:/yy.yyy.yy.yyy:42068] INBOUND HEADERS: streamId=1 headers=GrpcHttp2RequestHeaders[:path: /grpc.health.v1.Health/Check, :authority: [qqq:qqqq:qqq:qq:qq:qqqq:qqq:qqq]:50052, :method: POST, :scheme: http, te: trailers, goog-outboundacl-exempt: true, grpc-trace-bin: AABri/UCUi7MmAAAAAAAAAAAAVLcREUbqBPsAgD8gAgARv0AAAAA/gAAAAAAAAAA, grpc-tags-bin: AAAKb3JpZ2luYXRvchhjbG91ZC1nZmUtcHJvZC1kZWRpY2F0ZWQ, content-type: application/grpc, user-agent: grpc-c++/1.40.0-dev grpc-c/18.0.0 (linux; chttp2), grpc-accept-encoding: identity,deflate,gzip, accept-encoding: identity,gzip, grpc-timeout: 4510m] padding=0 endStream=false

- looks like you need to enable FINE logging for io.grpc.netty.shaded.io.netty (you have DEBUG for io.grpc.netty.shaded.io.grpc.netty which is not enough)

- there is no grpc-encoding header in my example snippet either but I would like to see what you have in yours when the error happens then I will analyze the code further

[Hristo Katsarski]

We have not experienced this issue for the past several days. We've updated the grpc-java libs on both sides(client/server) to v1.51.1. Here are the HTTP headers:

2023-02-02 02:30:19,985 DEBUG [GRPC worker, id #3] netty.NettyServerHandler - [id: 0x408a80cd, L:/xxx.xxx.xxx.xxx:8443 - R:/yyy.yyy.yyy.yyy:64339] INBOUND HEADERS: streamId=3 headers=GrpcHttp2RequestHeaders[:path: /com.xxx.yyy.grpc.service.v1.XxxService/Connect, :authority: xxx.yyy.com:8443, :method: POST, :scheme: https, te: trailers, content-type: application/grpc, user-agent: grpc-java-netty/1.51.1, traceparent: 00-9a43474eb67253ba175f03f6a4440250-cae6829dd96d83f5-01, grpc-accept-encoding: gzip] streamDependency=0 weight=16 exclusive=false padding=0 endStream=false

2023-02-02 02:30:20,254 DEBUG [GRPC worker, id #3] netty.NettyServerHandler - [id: 0x408a80cd, L:/xxx.xxx.xxx.xxx:8443 - R:/yyy.yyy.yyy.yyy:64339] OUTBOUND HEADERS: streamId=3 headers=GrpcHttp2OutboundHeaders[:status: 200, content-type: application/grpc, grpc-encoding: identity, grpc-accept-encoding: gzip] padding=0 endStream=false

Will post an update if it happens again.

Regards