Calls fail with Nginx, even with Transparent Retries

[danieltahara]

I have a client that invokes a gRPC service through Nginx, and so I have to contend with the abrupt GOAWAYS sent by nginx every keepalive_requests.

My understanding is that transparent retry should handle this case. Originally I was on 1.54.1 and saw I was hitting: #10011 so I upgraded to 1.54.2. I'm still getting errors, however.

What confuses me a bit is that I see the original retry code was added here: a83f67a and that there was a subsequent update for netty: 431fb02

I did some more tracing and now it seems like I'm hitting this path: https://github.com/grpc/grpc-java/blob/master/netty/src/main/java/io/grpc/netty/NettyClientHandler.java#L846

Why are we returning a code REFUSED instead of MISCARRIED? Or at a higher level, why doesn't a REFUSED stream get infinite transparent retries? https://github.com/grpc/grpc-java/blame/master/core/src/main/java/io/grpc/internal/RetriableStream.java#L937

And secondarily, how do we end up in the situation where we're getting GOAWAYs on sent streams? It seems like something to do with http2_max_concurrent_streams > nginx's keepalive_requests

[YifeiZhuang]

Answer partially: MISCARRIED indicates the stream never leave the client, transparent retry happens unlimited until successful.
REFUSED indicates the RPC left the client, transparent retry only happen once.

In the GOAWAY situation, when the stream id is larger than the last stream id, if the RPC was sent on wire then gRPC will report REFUSED for the RPC so it transparent retry once to jump to the next connection, then it depends on the retry configuration from the application to decide whether there are further retries, but if the RPC has never leave the wire it is treated as MISCARRIED and retry indefinitely.

[YifeiZhuang]

abrupt GOAWAYS sent by nginx every keepalive_requests.
It seems like something to do with http2_max_concurrent_streams > nginx's keepalive_requests

What are the server and client keepalive configuration and are they correct? Do you have error messages? If server sends goaway for every keepalive request, it looks keepalive ping too frequent or not allowed by the server.

#10011 does seem related. In particular it can help with the case that is hitting max concurrent stream. When max concurrent stream is hit, the RPC with its stream id larger than the goaway last stream id will get REFUSED, then will transparently retry once so it would be successful on a new connection. But if the retry still fails, then #10011 does not help.

[ejona86]

I have a client that invokes a gRPC service through Nginx, and so I have to contend with the abrupt GOAWAYS sent by nginx every keepalive_requests.

For reference (for grpc devs; OP seems to be aware already), we looked into that abrupt handling in #8310 and I opened https://trac.nginx.org/nginx/ticket/2224 . But yeah, "it's just what nginx does." Nginx cuts the connection abruptly when doing lots of RPCs.

It seems like something to do with http2_max_concurrent_streams > nginx's keepalive_requests

Yeah, I expect so. Since we will only transparently retry once if the RPC was sent on-the-wire, if the next attempt also fails, then you'd see the GOAWAY error. http2_max_concurrent_streams can be figured out by client frame logging and looking for the first received SETTINGS frame. keepalive_requests might be able to be inferred from the Last-Stream-ID of the received GOAWAY.

[danieltahara]

REFUSED indicates the RPC left the client, transparent retry only happen once.

I guess specifically the reason this is not retried infinitely b/c it means it potentially "consumed some server resources" so we want to be conservative?

keepalive_requests might be able to be inferred from the Last-Stream-ID of the received GOAWAY.

So I played around with a local nginx, and ultimately what I found was that:

• Last-Stream-ID = 2 * keepalive_requests + 1, although my logs suggest only keepalive_requests actually succeeded which makes sense.
• When I set keepalive_requests = http2_max_concurrent_streams in nginx (originally, keepalive_requests was in fact less than http2_max_concurrent_streams), most of the issues went away.

What I'm still seeing residually is when increasing keepalive_requests to some much larger number (100 -> 10000) I have some gRPC clients that actually get a substantial increase in GOAWAY on SENT stream errors (many other clients had them reduced, as would be expected). Upgrading grpc-java/netty past #10011 helps by about 50%, but I'm flummoxed as to why a higher keepalive_requests limit would increase the incidence of GOAWAYs.

Is there some way to configure an equivalent to keepalive_requests on the client side (basically, to force it through a more graceful connection termination path than the one nginx is forcing it through)?

[ejona86]

I guess specifically the reason this is not retried infinitely b/c it means it potentially "consumed some server resources" so we want to be conservative?

Yeah. And we don't want a bug to allow infinite retrying without a backoff.

Last-Stream-ID = 2 * keepalive_requests + 1

That sounds roughly as expected. The client only uses odd IDs. Even IDs are reserved for the server. IIRC, the client starts at 1 or 3.

I'm flummoxed as to why a higher keepalive_requests limit would increase the incidence of GOAWAYs.

Yeah, at the very least you'd expect doubling the keepalive_requests would half the error rate, as half the number of connections are used.

Is there some way to configure an equivalent to keepalive_requests on the client side

No, we don't have anything like that, and we wouldn't want it because this should be in the server's control. Adding it to the client prevents the server from managing it; the server can't reduce the value as then clients start seeing errors and increasing the value has no effect as clients close early.

[danieltahara]

Yeah, at the very least you'd expect doubling the keepalive_requests would half the error rate, as half the number of connections are used.

So the specific error that I'm seeing is: "GOAWAY closed buffered stream". Do you know how we would hit that and if that traverses the transparent retry system?

What reduced after #10011 and fixing keepalive_requests = http2_max_concurrent_streams: "Abrupt GOAWAY closed unsent stream"

I also see "Abrupt GOAWAY closed sent stream" in lower numbers. I don't know where/why would cause that, b/c I'd imagine that the nginx GOAWAYS would result in "Abrupt GOAWAY closed unsent stream"

[ejona86]

So the specific error that I'm seeing is: "GOAWAY closed buffered stream".

This message is for RPCs that were buffered waiting on MAX_CONCURRENT_STREAMS when the GOAWAY was received.

Those should have been infinitely retriable, because they were never sent. They are properly categorized as MISCARRIED. This would have been caused by #10011, but with that fix they should have gone away completely.

"Abrupt GOAWAY closed unsent stream"

This message is for new RPCs that used the transport after the GOAWAY was received. This is a normal client-side race, because it takes time for the load balancer to stop assigning RPCs to the now-broken transport.

Those are also MISCARRIED, so the same applies to them.

Abrupt GOAWAY closed sent stream

This message is for RPCs that were sent but not processed by the server. So these are REFUSED. Some of these leaking through is possible, because we only retry them once.

[danieltahara]

Those should have been infinitely retriable, because they were never sent. They are properly categorized as MISCARRIED. This would have been caused by #10011, but with that fix they should have gone away completely.

I don't think this would explain the magnitude of the increase, but could part of the problem be that if we follow a REFUSED with a MISCARRIED, we don't continue infinite retries? I'm thinking this: https://github.com/grpc/grpc-java/blob/master/core/src/main/java/io/grpc/internal/RetriableStream.java#L968 then causing this to fail https://github.com/grpc/grpc-java/blob/master/core/src/main/java/io/grpc/internal/RetriableStream.java#L938. Is that the behavior we actually want?

In that case, we would see unsent/buffered stream errors bubble up.

Beyond that, something still seems fishy. Any other details I can provide that might help get to the bottom of this?

[ejona86]

I agree that this line doesn't seem to be what we want:

grpc-java/core/src/main/java/io/grpc/internal/RetriableStream.java

Line 968 in 0c415e8

noMoreTransparentRetry.set(true);

But instead of removing it, I feel like it would be even better to set the flag to false (although only if hedgingPlan.isHedgeable == true or retryPlan.shouldRetry == true), to re-allow a transparent retry since the retry policy decided it was okay to cause more server load.

I'm not convinced that is what you are seeing, as that requires calls to be failing naturally and for you to have a retry policy in place to be useful.

[danieltahara]

I'm not convinced that is what you are seeing, as that requires calls to be failing naturally and for you to have a retry policy in place to be useful.

How else can we explain otherwise retriable errors bubbling up? It seems to me like I have to get a non-retriable GOAWAY (sent stream), hit that line, and then get a retriable one.