grpcclient: a rollout of a dependency served by grpcserver opens the breaker of a Client with five streams open to the pod

[Zaba505]

What happens

A grpcclient Client with five or more server streams open to one pod of a dependency opens its circuit breaker when that pod shuts down, even while the dependency's other pods are healthy. Every call the Client makes, unary or stream, is then rejected for Breaker.OpenFor, 10s by default.

• grpcserver's Shutdown ends every stream with Unavailable and server is shutting down, so that its client reconnects to another pod, as Streams at shutdown describes.
• grpcclient counts a stream that opened once, when it ends, with the Breaker of Classify's answer. The default Classify counts Unavailable as a Failure.
• So each stream that the pod's shutdown ends is a failure. Five in a row trip the default policy.

A rollout of the dependency does this to every client with five streams open to a pod it replaces, once for each pod.

MaxConnectionAgeGrace does the same. When it closes a connection that still has streams open, each one ends with Unavailable, closing transport due to: ... received prior goaway: code: NO_ERROR, debug data: "max_age", and counts as a failure.

Both sides run on humus's defaults. Nothing failed: the server ended the streams on purpose, as the docs say it should.

Why

• Shutdown ends a stream with errShuttingDown, Unavailable (streams.go#L17-L20).
• A stream's ticket is settled when RecvMsg returns an error, with Classify's answer for that error (breaker.go#L226-L252). Only a caller's cancellation is released without counting.
• The default Classify answers Unavailable with circuit.Failure (classify.go#L70-L71), whatever the method and however long the stream was open.
• The default policy trips after 5 failures in a row (settings.go#L180-L185).

How it was found

While prototyping the gRPC walkthrough, against main at d4eadda, under go test -race, inside synctest, on one humustest Host.

• A front App relayed a backend's server stream through a grpcclient Client on DefaultSettings(), and served it on to the test. Each backend stream sent a message a second until its context ended.
• The backend was two grpcserver Apps, ledger-a and ledger-b. The front's Host dialed the Client's Addr to whichever of them was "in the endpoints", as a ClusterIP Service does.
• The test opened N streams through the front, all of them on ledger-a. It then took ledger-a out of the endpoints and sent it SIGTERM, and called a unary method 1s after ledger-a exited.

Streams open	Classify	The breaker	The unary call
1	the default	stayed closed. The stream opened again on ledger-b	OK
6	the default	opened when ledger-a's Shutdown ended the streams. 4 of the 6 couldn't open again: circuit: call rejected: open for another 10s	Unavailable, rejected
6	the default, but Ignored for the end of a stream with Unavailable and server is shutting down	stayed closed. All 6 opened again on ledger-b	OK

With a single backend whose options set MaxConnectionAge: time.Minute and MaxConnectionAgeGrace: 10 * time.Second, and six streams open, the breaker opened when the grace closed the connection, about 76s in.

grpcclient's own tests open one stream at a time, and grpcserver's tests have no client with a breaker, so neither reaches this.

The docs

• Calling gRPC services' Streams says that a stream that opens is counted once, when it ends, and the default's table counts Unavailable as a Failure. Neither says that a server's shutdown, or its connection age, ends streams that way.
• gRPC services' Streams at shutdown tells the client to reconnect on Unavailable. A grpcclient Client can do that only once its breaker lets it.

Expected

On humus's defaults, a dependency's rollout or its connection age doesn't open its clients' breakers. A stream that a server ends on purpose says nothing about whether the dependency answers calls. Some ways to get there:

• The end of a stream that has received a message, with Unavailable, is Ignored, as the end of a stream its caller cancelled is. A stream that fails to open still counts. So does the next attempt to open one, which is what tells a dependency that is down.
• grpcserver ends streams at shutdown with a status the default Classify knows, such as one with a detail of humus's, and the default ignores it. That covers Shutdown, but not MaxConnectionAgeGrace, whose close is grpc-go's.
• The default stays, and the docs show a Classify that ignores a stream ended this way.

Whichever is chosen:

• a test runs five streams across a backend's Shutdown, and across its MaxConnectionAgeGrace;
• both pages' sections on streams say what the end of a stream counts.

References

• Proposal: gRPC services, and its revision, which chose to end streams with Unavailable
• Proposal: outbound gRPC clients, and its revision 1
• Proposal: gRPC walkthrough, whose case that rolls out the ledger with watches open waits for the fix

[Zaba505]

Triage

Verdict: A reproducible bug in grpcclient, not a misuse and not a feature request. With both sides on humus's defaults, a rollout of a dependency served by grpcserver, or the dependency's MaxConnectionAgeGrace, opens the breaker of a Client with 5 streams open to the pod. It is worse than reported. 3 streams are enough when the rollout replaces, in turn, two pods the Client lands on. Bidirectional streams do it too. And while subscriptions open again, the Client's unary calls stayed rejected for 20s to 60s, not OpenFor's 10s. #1180 is filed to fix it.

Is this a misuse of humus?

No. The behaviour is humus's on both sides. grpcserver picks the status a stream ends with at Shutdown (streams.go#L17-L20). grpcclient counts a stream's end in its breaker (breaker.go#L226-L252). The default Classify decides what Unavailable counts (classify.go#L70-L71).

The end user's part is what the docs tell them to do. Their subscription subscribes again on Unavailable, as Streams at shutdown shows. Their dependency sets MaxConnectionAgeGrace, which Spreading clients across pods tells a server with long streams to set. Nothing else is configured: the dependency runs on grpcserver.Defaults, and the Client on DefaultSettings().

The strongest case for misuse: Classify exists so the end user can say what a dependency's codes mean. The default's table counts Unavailable as a Failure, and the bullet under it says Unavailable is "what grpcserver ends streams with at shutdown" (doc.go#L234-L236). An end user who read both could have written a Classify that ignores it. That doesn't hold:

• The dependency is a humus service on humus's defaults, and the docs promise that its rollout moves the Client (below). Nothing tells the end user that the default needs help for that.
• Classify can tell a stream that Shutdown ended only by its message, server is shutting down. A stream that MaxConnectionAgeGrace ended has grpc-go's status, and only grpc-go's message text marks it: received prior goaway: code: NO_ERROR, debug data: "max_age". I saw both messages in the runs. That no API names the second is reasoned from code.

Is it a feature request?

No. The behaviour contradicts what the docs promise:

• grpcclient's doc, doc.go#L104-L106: "Two things move a Client to another pod. grpcserver's Shutdown sends every client a GOAWAY, so a rollout of the dependency moves them." With 5 streams open, the rollout doesn't move the Client. It stops it.
• gRPC services' Spreading clients across pods: "Its clients dial again, and reach whichever pod the Service picks, so a grpcclient Client sees no error. MaxConnectionAgeGrace bounds how long the RPCs on an old connection may take before it is closed under them, which a server with long streams sets." Calling gRPC services' Spreading the load with MaxConnectionAge says the same.
• gRPC services' Streams at shutdown: "Unavailable is gRPC's code for a condition the client corrects by retrying, so the end user's client reconnects on it", and in its sample, "Reconnect: the new stream lands on another pod." The breaker rejects the reconnect.
• Classification.Breaker, classify.go#L35-L37: "circuit.Ignored for a result that says nothing about the dependency." A stream the server ended on purpose says nothing about whether the dependency answers. In every run, the next pod answered every call that reached it.

What does describe the behaviour is the default's table and the bullet under it, quoted above. TestClient_breaker_counts_a_streams_end also counts a stream that ends with Unavailable after a message as one failure, though its backend returns that status itself. #763 names grpcserver's shutdown status as a reason to retry Unavailable. Neither it nor its revision 1 says what the breaker does when a rollout ends a Client's streams. These are the docs and the test that describe the bug.

Restoring what the docs promise, and correcting the table, the bullet and the test that describe the bug, isn't an API change.

Is it reproducible?

Yes. The tests are in grpcclient's package, extending dependencies_test.go, at 443a9ae. They ran with Go 1.27.0, grpc-go v1.84.0 and bedrock's circuit v0.25.0, under go test -race, inside synctest, on one humustest Host, with grpc-go's logging at info. No container is involved.

Each pod of the dependency is a grpcserver App on grpcserver.Defaults, with its 5s drain and 15s grace period. The end user's App has a Client of ledger:9090 on DefaultSettings(), and a job whose subscriptions each receive a message a second and subscribe again when their stream ends with Unavailable. The Host dials ledger:9090 to whichever pod is in the endpoints, as a ClusterIP Service does. Each test asserts what the docs promise, and ran 4 times:

Scenario	Runs that failed	What happened
A rollout, 5 server streams on the pod it replaces	4 of 4	the breaker opened at the fifth end. 1 to 4 subscriptions couldn't open again, and a unary call 1s after the pod exited was rejected
A rollout, 5 bidirectional streams	4 of 4	the same. 2 or 3 subscriptions couldn't open again
A rollout, 3 server streams, on two pods it replaces in turn	4 of 4	the breaker opened at the fifth end, the second on the second pod. 2 or 3 subscriptions couldn't open again
A rollout, 4 server streams	0 of 4	the breaker stayed closed: 4 failures don't trip the default policy
MaxConnectionAge: time.Minute, MaxConnectionAgeGrace: 10 * time.Second, 5 server streams	4 of 4	the breaker opened when the grace closed the connection, 69s to 77s in. 2 to 5 subscriptions couldn't open again
A rollout, 5 server streams whose subscriptions try again a second after a failed open, and a unary call every second	4 of 4	unary calls were rejected for 20s, 40s, 40s and 60s

A rollout with 5 server streams: the breaker opens. ledger-a and ledger-b serve, and the 5 subscriptions are on ledger-a. At +0.1s, ledger-a leaves the endpoints and gets SIGTERM. In run 1:

1. ledger-a serves through its 5s drain. At +5.1s its Shutdown ends every stream: subscription 0, on ledger-a, ended: rpc error: code = Unavailable desc = server is shutting down, and the same for the other 4.
2. Each end settles its stream's ticket with the default's Failure. The fifth trips the default policy: +005.100s breaker record "circuit breaker open": previous_state=closed consecutive_failures=5 failures=5 successes=0.
3. The subscriptions subscribe again. One did before the fifth end, and landed on ledger-b: subscription 0 heard from ledger-b. The other 4 were rejected: subscription 1 failed to open: circuit: call rejected: open for another 10s.
4. ledger-a exits 0. 1s later, EmptyCall: circuit: call rejected: open for another 9s.

MaxConnectionAgeGrace: the same, from grpc-go. One pod, with MaxConnectionAge: time.Minute and MaxConnectionAgeGrace: 10 * time.Second. In run 1:

1. About 65s in, the server's GOAWAY idles the Client's subchannel: [Channel #3 SubChannel #4] Subchannel Connectivity change to IDLE. The 5 streams stay open on the old connection.
2. 10s later, grpc-go logs [server-transport ...] Closing server transport due to maximum connection age, then [client-transport ...] Closing: connection error: desc = "error reading from server: EOF".
3. Each stream ends with code = Unavailable desc = closing transport due to: connection error: desc = "error reading from server: EOF", received prior goaway: code: NO_ERROR, debug data: "max_age". The fifth opens the breaker at +76.6s, consecutive_failures=5. 4 of the 5 subscriptions couldn't open again, and EmptyCall 1s later was rejected.

Unary calls stay rejected past OpenFor. As the first scenario, but each subscription tries again a second after a failed open, and the end user's App makes a unary call every second. In run 1:

1. The breaker opens at +5.1s, and turns half-open at +15.1s: breaker record "circuit breaker half-open". Breaker.Probes is 1.
2. At +15.1s, a subscription's retry takes the one probe slot, and its stream opens on ledger-b: subscription 2 heard from ledger-b. Its ticket settles only when the stream ends, so it keeps the slot. Every other call is rejected: EmptyCall: circuit: call rejected: half-open, and every probe slot is taken.
3. At +25.1s, circuit times the probe out, and the next subscription's retry takes the slot. That repeats every 10s until no subscription is left to open: at +25.1s and +35.1s.
4. Then a unary call gets the slot, at +45.6s, and 3 successful probes close the breaker: +047.600s breaker record "circuit breaker closed". Unary calls were rejected from +5.6s to +44.6s. In run 4, all 5 subscriptions had failed to open, and the calls were rejected for the whole minute the test made them.

This corrects three things in the report:

• "Every call the Client makes, unary or stream, is then rejected for Breaker.OpenFor, 10s by default." It is rejected for longer while subscriptions open again: 20s to 60s here.
• "five or more server streams open to one pod". Fewer trip it across a rollout. 3 streams did, on two pods the rollout replaced in turn.
• "Neither says that a server's shutdown, or its connection age, ends streams that way." The bullet under the default's table names grpcserver's shutdown. It says nothing of the connection age.

Why

1. Shutdown cancels every stream handler's context. When the handler then returns nil or context.Canceled, the interceptor ends the stream with errShuttingDown, Unavailable (streams.go#L17-L20, #L61-L66). Reproduced.
2. MaxConnectionAgeGrace's close is grpc-go's. Its client transport ends every stream still on the connection with Unavailable. Reproduced, with the message above.
3. A stream that opened holds its attempt's ticket. settle settles it once, when RecvMsg returns an error, with the Breaker of Classify's answer for that error. Only a caller's cancellation, and the call's own deadline, are decided without Classify (breaker.go#L226-L252). Reproduced.
4. The default Classify answers Unavailable with circuit.Failure (classify.go#L70-L71), whatever ended the stream, and however long it was open. Reproduced.
5. The default policy trips after 5 failures in a row (settings.go#L180-L185). A pod's streams end together. A stream that opened again on the next pod counts nothing until it ends, so nothing comes between the ends on one pod and the next. Reproduced.
6. Half-open, circuit admits Breaker.Probes calls at once, 1 by default, and rejects the rest (breaker.go#L311-L340). A probe keeps its slot until it is settled, or until ProbeTimeout passes. circuit then counts it timed out (breaker.go#L402-L409), and the default Probe policy keeps probing (settings.go#L187-L199). A subscription's stream doesn't end, so each one that takes the slot keeps every other call out for 10s. grpcclient's doc says this of an abandoned stream (doc.go#L415-L421). A live one does the same. Reproduced.

Two more ways in, which I reasoned from code and didn't reproduce:

• A readiness monitor that calls the dependency's grpc.health.v1 through the Client, as doc.go#L692-L705 shows, fails while the breaker rejects. So a rollout of the dependency would turn every pod of the end user's service unready, as an outage would.
• A stream still open when the dependency's grace period runs out, such as one whose handler is blocked in Recv, ends when Stop closes its connection. grpc-go ends it with Unavailable, which counts the same.

#1180 is filed to fix it:

• a rollout of a dependency served by grpcserver, on humus's defaults, leaves closed the breaker of a Client with streams open to the pods it replaces, of every kind, and across several pods in turn. The subscriptions open again on the next pod, and unary calls are answered throughout;
• the same for a dependency's MaxConnectionAgeGrace;
• a dependency whose calls fail still opens the breaker;
• the reproductions above, as tests in dependencies_test.go;
• docs in both packages and on both pages that say what the end of such a stream counts.

[Zaba505]

Fixed by #1187, merged as 3d2e52c.

An open stream that ends with Unavailable is now the Client's to decide, without asking Classify, and its circuit breaker ignores it. That covers both causes: grpcserver's Shutdown at a rollout, and grpc-go's close at MaxConnectionAgeGrace. It holds for any number of streams, for server and bidirectional streams, and with or without a message first. A failed open still counts, so a dependency that is down still opens the breaker.

The triage's reproductions are in grpc/grpcclient/dependencies_test.go, and they pass. These docs now say what such an end counts: grpcclient's and grpcserver's package docs, and the Calling gRPC services and gRPC services pages.