JSON POST full path requests fail when then there is a GET binding

[rfevang]

In attempting to upgrade to esp-v2, we came across some failing requests. It turns out all the failing calls have service definitions like

rpc GetThing(GetThingRequest) returns (GetThingResponse) {
  option (google.api.http) = {
    get: "/v1/things/{thing_id}"
  };
}

But were still called from the front end by POST calls to /my.package.ThingService/GetThing. All these calls stall for slightly over 4 seconds, before returning a 502. Changing them to GET /v1/things/mything makes the calls work.

In esp-v1 both call forms work. It looks like esp-v2 is attempting to make them work, as the calls are forwarded to the underlying server, but the server isn't able to process the call properly. It throws an error message relatively quickly, complaining about a null gRPC stream. The server is running Java.

According to https://cloud.google.com/endpoints/docs/grpc/transcoding#where_to_configure_transcoding sending POST calls is still supposed to work, even if there are other bindings.

[rfevang]

Server side error messages:

Aug 08, 2022 9:50:40 AM io.grpc.netty.shaded.io.grpc.netty.NettyServerHandler onDataRead
WARNING: Exception in onDataRead()
java.lang.NullPointerException: Cannot invoke "io.grpc.netty.shaded.io.grpc.netty.NettyServerStream$TransportState.tag()" because "stream" is null
	at io.grpc.netty.shaded.io.grpc.netty.NettyServerHandler.onDataRead(NettyServerHandler.java:480)
	at io.grpc.netty.shaded.io.grpc.netty.NettyServerHandler.access$900(NettyServerHandler.java:103)
	at io.grpc.netty.shaded.io.grpc.netty.NettyServerHandler$FrameListener.onDataRead(NettyServerHandler.java:814)
	at io.grpc.netty.shaded.io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder$FrameReadListener.onDataRead(DefaultHttp2ConnectionDecoder.java:292)
	at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2InboundFrameLogger$1.onDataRead(Http2InboundFrameLogger.java:48)
	at io.grpc.netty.shaded.io.netty.handler.codec.http2.DefaultHttp2FrameReader.readDataFrame(DefaultHttp2FrameReader.java:422)
	at io.grpc.netty.shaded.io.netty.handler.codec.http2.DefaultHttp2FrameReader.processPayloadState(DefaultHttp2FrameReader.java:251)
	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.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.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)
	at java.base/java.lang.Thread.run(Thread.java:833)

Aug 08, 2022 9:50:40 AM io.grpc.netty.shaded.io.grpc.netty.NettyServerHandler onStreamError
WARNING: Stream Error
io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2Exception$StreamException: Cannot invoke "io.grpc.netty.shaded.io.grpc.netty.NettyServerStream$TransportState.tag()" because "stream" is null
	at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2Exception.streamError(Http2Exception.java:167)
	at io.grpc.netty.shaded.io.grpc.netty.NettyServerHandler.newStreamException(NettyServerHandler.java:791)
	at io.grpc.netty.shaded.io.grpc.netty.NettyServerHandler.onDataRead(NettyServerHandler.java:489)
	at io.grpc.netty.shaded.io.grpc.netty.NettyServerHandler.access$900(NettyServerHandler.java:103)
	at io.grpc.netty.shaded.io.grpc.netty.NettyServerHandler$FrameListener.onDataRead(NettyServerHandler.java:814)
	at io.grpc.netty.shaded.io.netty.handler.codec.http2.DefaultHttp2ConnectionDecoder$FrameReadListener.onDataRead(DefaultHttp2ConnectionDecoder.java:292)
	at io.grpc.netty.shaded.io.netty.handler.codec.http2.Http2InboundFrameLogger$1.onDataRead(Http2InboundFrameLogger.java:48)
	at io.grpc.netty.shaded.io.netty.handler.codec.http2.DefaultHttp2FrameReader.readDataFrame(DefaultHttp2FrameReader.java:422)
	at io.grpc.netty.shaded.io.netty.handler.codec.http2.DefaultHttp2FrameReader.processPayloadState(DefaultHttp2FrameReader.java:251)
	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.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.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)
	at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: java.lang.NullPointerException: Cannot invoke "io.grpc.netty.shaded.io.grpc.netty.NettyServerStream$TransportState.tag()" because "stream" is null
	at io.grpc.netty.shaded.io.grpc.netty.NettyServerHandler.onDataRead(NettyServerHandler.java:480)
	... 28 more

[TAOXUY]

Hi @rfevang,

• The default HTTP Pattern(POST /my.package.ThingService/GetThing) should work even with other HTTP pattern configured if you use grpc protocol as your backend address prefix(GKE,Cloud Run). Here is the corresponding config code. Could you check that?

• In the meanwhile, maybe you can also try additional_bindings to specify all these HTTP Patterns:

rpc GetThing(GetThingRequest) returns (GetThingResponse) {
  option (google.api.http) = {
    post: "/my.package.ThingService/GetThing"
    body: *
    additional_bindings {
      get: "/v1/things/{thing_id}"
    }
  };
}

• It still doesn't work. If you don't mind, you can also set ESPv2 --enable_debug flag and send the ESPv2 std log to [email protected], so that we can take another look.

[rfevang]

Hi @TAOXUY. Yes we're using grpc://... as backend address. As I said, the call is making it to the correct server, but the server spits out the above error messages.

The documentation has a big red warning box specifically saying NOT to do the additional_bindings thing you mentioned above:

Warning: Using http method POST with the URL path GRPC_SERVICE_FULL_NAME/METHOD_NAME> is supported by default. Do
not add additional mapping for this method in the proto file's google.api.http annotation or in the http.rules section of
the service config yaml file. This will result in a "duplicate http pattern" error.

So if that's what we need to do then the documentation needs to be updated. I don't think it is the problem though, as the request isn't stopping in esp, we do see it appear in the grpc server, just in a way that crashes.

[rfevang]

Sent logs via email

[TAOXUY]

Hi @rfevang,

Have u sent? I didn't see the log email. Maybe you can send to [email protected].

So if that's what we need to do then the documentation needs to be updated.

[rfevang]

Forwarded to your address. I see that I got a reply from the group delivery system rejecting the email, but that reply was marked as spam on my end so I didn't see it until I opened the mail to forward it to you.

If ESPv2 hasn't generated a default binding it should reply 404 shouldn't it? I can try adding the binding manually later.

[TAOXUY]

Just checked your log so the transcoding is failed an the http requests are passed to backend directly, causing the backend failure as expected.

external/envoy/source/extensions/filters/http/grpc_json_transcoder/json_transcoder_filter.cc:443] [32][http2]Failed to transcode request headers: Could not resolve /xxx to a method.
external/envoy/source/extensions/filters/http/grpc_json_transcoder/json_transcoder_filter.cc:448] [32][http2]Request is passed through without transcoding because it cannot be mapped to a gRPC method.

Double checked, https://cloud.google.com/endpoints/docs/grpc/transcoding#where_to_configure_transcoding is actually added for ESPv2, so basically the default HTTP Pattern GRPC_SERVICE_FULL_NAME/METHOD_NAME is honored only when no google.api.http annotations are not set.

As for adding additional_bindings for the default HTTP Pattern mentioned earlier, this can help mitigate this gap but we need to make some change to make that work.

[rfevang]

Tried using additional_bindings, and it results in endpoints crashing on startup, printing

F0812 17:55:01.245070      10 server.go:54] fail to initialize config manager: fail to fetch and apply the startup service config, fail to make a snapshot, makeHttpConnectionManagerRouteConfig got err: fail to sort route match, my.package.ThingService.GetThing has duplicate http pattern `POST /my.package.ThingService/GetThing`

like the big red warning said it would. So at least the documentation is on point :)

I realize it's probably not a good idea to have a GET binding and use the default POST, but we have a fair amount of older services without http annotations, and this bug will make it harder to transition them to GET in a smooth way using ESPv2.

[TAOXUY]

Hi @rfevang, adding additional_bindings for the default HTTP Pattern doesn't work for now as mentioned above. Our team have put this bug in our execution.

[TAOXUY]

It should be solved by https://github.com/GoogleCloudPlatform/esp-v2/pull/725#pullrequestreview-1081039548. Please wait for release 2.39.0.