StatsHandler Order Guarantees

[davinci26]

Hey folk,

I am wondering if there are any guarantees around the order of operations in Handler.HandleRPC

In particular can I assume that HandleRPC will always be called with:

1. stats.Begin as the first one always
2. the rest of the steps depending on the RPC lifecycle
3. stats.End as the last one always

The reason I am asking is that I have case where stats.InHeader seems to be coming before stats.Begin and I wanted to see if this is by-design or a bug.

[davinci26]

Similar question around the order of TagRPC and HandleRPC. Are we guaranteed that HandleRPC is going to be called after TagRPC?

[eshitachandwani]

In particular can I assume that HandleRPC will always be called with:

1. stats.Begin as the first one always
2. the rest of the steps depending on the RPC lifecycle
3. stats.End as the last one always

Hey @davinci26, this assumption holds because even though there is nothing to enforce the order, stats.Begin is triggered as soon as an RPC attempt begins, and logically, there shouldn't be anything before it, as noted here:
https://github.com/grpc/grpc-go/blob/d66fc3a1efa1dfb33dfedf9760528f1ac2b923b6/stats/stats.go#L39C1-L41C20

Similarly, stats.End is called when the RPC concludes, so ideally, there should be nothing after it as noted here :
https://github.com/grpc/grpc-go/blob/d66fc3a1efa1dfb33dfedf9760528f1ac2b923b6/stats/stats.go#L211C1-L212C18

That said, this applies to a single RPC. If there is a stream of concurrent RPCs, it’s possible to see a stats.InHeader from another RPC before the stats.Begin of a different RPC.

If that's not the case, it would likely indicate a bug. If you encounter such a scenario, providing repro steps would be very helpful.

[eshitachandwani]

Similar question around the order of TagRPC and HandleRPC. Are we guaranteed that HandleRPC is going to be called after TagRPC?

TagRPC provides the final context to be used:
https://github.com/grpc/grpc-go/blob/d66fc3a1efa1dfb33dfedf9760528f1ac2b923b6/stats/handlers.go#L45C2-L47C26
and the context passed to HandleRPC is the same final context returned by TagRPC so that it can get access to the tags added y TagRPC. Also, tagRPC is called at the start of the RPC to add tags to the context which is then used for the rest of RPC life cycle.
So, it seems the order of TagRPC and HandleRPC is essentially guaranteed.

[davinci26]

Yeah this code https://gist.github.com/davinci26/ae394645582488c1c44b5dcb96d52f3a it has:

The repro is based on the example in the repro so it should be pretty simple to run with go run main.go

stats.ConnBegin
stats.InHeader
stats.Begin
stats.InPayload
2024/10/30 08:59:03 Received: world
stats.OutHeader
stats.OutPayload
stats.OutTrailer
stats.End
2024/10/30 08:59:03 Greeting: Hello world

In that case stats.InHeader comes before stats.Begin

[aranjans]

@davinci26 Thanks for raising this question! The current server-side implementation for server does indeed call HandleRPC() with stats.InHeader before stats.Begin. This is the expected behavior, though not explicitly documented.

The server-side stats events follow this order:

1. InHeader (when processing incoming headers)
2. Begin (when starting RPC processing)
3. [message events during RPC]
4. End (when RPC completes)

You're right that this ordering should be better documented. Here is what we would like to have:

1. Add explicit documentation about the server-side stats event ordering
2. Add tests to verify this behavior remains consistent

For now, you can rely on InHeader coming before Begin for server-side stats handlers.
Feel free to send us a PR for this, would be happy to review, thAnks.