feat(nunciod): per-RPC tracing span with request-id correlation and auth logging #371

2026-07-31T23:37:22Z

KofTwentyTwo commented

2026-07-31 23:37:22 +00:00

(Migrated from github.com)

Implements OBS-2 (#358): per-RPC span + request-id correlation + auth logging. Builds on OBS-1's layered subscriber. No proto change.

What changed

Per-RPC root span via a new tower::Layer (rpc_trace::RpcTraceLayer) mounted on the tonic Server builder ahead of the existing WS-D8 resource limits and WS-C1 shutdown, without disturbing them. The span carries request_id, rpc.method, and peer. It opens with a DEBUG event and closes -- once the response body drains -- with an INFO event carrying the terminal gRPC status code and elapsed ms. Routing, the per-service BearerAuthInterceptor, and the handler all run inside the span, so every event emitted while handling a request (including auth logs) inherits the request_id.
request_id scheme: a lightweight per-process id <process-start-nanos>-<counter> (atomic counter), avoiding a new heavy dependency (uuid is only a transitive dep, not a workspace dep).
Correlation propagation: the SyncDispatcher spawns the real sync on a detached tokio task, which does not inherit the caller span; it now captures Span::current() and .instrument()s the task, so a sync kicked off by Mail.Sync logs under the same request_id.
Auth logging in BearerAuthInterceptor: ACCEPT (DEBUG) and REJECT (WARN, with a fixed reason string) carrying only the peer -- never the token, the authorization header, or anything derived from them. The constant-time compare is unchanged.

Honest correlation gap (follow-up)

A request that coalesces onto an already in-flight sync is correlated to the owner's request_id, not its own (it joins the owner's task).
tonic's built-in timeout layer sits outside the trace layer; a request cut off by that timeout is logged via TracedBody's drop path (status Unknown) rather than a distinct deadline event.

Tests (all offline, deterministic; a shared in-test capturing subscriber, no new dev framework)

RPC produces a grpc.request span carrying request_id + rpc.method, logs the terminal status (NotFound/Ok) at INFO with elapsed, and a handler-emitted event is observed under the span.
Auth accept logs DEBUG; bad-token and missing-header reject log WARN with a reason -- asserting neither the real token nor the presented guess appears in any captured log field.

Gates

cargo fmt --all -- --check, cargo check-all, cargo test-all all green; 0 ignored. Secret-safety grep of the diff confirms no token/header value in any tracing macro.

Refs #358

Implements OBS-2 (#358): per-RPC span + request-id correlation + auth logging. Builds on OBS-1's layered subscriber. No proto change. ## What changed - **Per-RPC root span** via a new `tower::Layer` (`rpc_trace::RpcTraceLayer`) mounted on the tonic `Server` builder ahead of the existing WS-D8 resource limits and WS-C1 shutdown, without disturbing them. The span carries `request_id`, `rpc.method`, and `peer`. It opens with a DEBUG event and closes -- once the response body drains -- with an INFO event carrying the terminal gRPC status code and elapsed ms. Routing, the per-service `BearerAuthInterceptor`, and the handler all run inside the span, so every event emitted while handling a request (including auth logs) inherits the `request_id`. - **request_id scheme:** a lightweight per-process id `<process-start-nanos>-<counter>` (atomic counter), avoiding a new heavy dependency (`uuid` is only a transitive dep, not a workspace dep). - **Correlation propagation:** the `SyncDispatcher` spawns the real sync on a detached tokio task, which does not inherit the caller span; it now captures `Span::current()` and `.instrument()`s the task, so a sync kicked off by `Mail.Sync` logs under the same `request_id`. - **Auth logging** in `BearerAuthInterceptor`: ACCEPT (DEBUG) and REJECT (WARN, with a fixed reason string) carrying only the peer -- never the token, the `authorization` header, or anything derived from them. The constant-time compare is unchanged. ## Honest correlation gap (follow-up) - A request that **coalesces** onto an already in-flight sync is correlated to the *owner's* request_id, not its own (it joins the owner's task). - tonic's built-in timeout layer sits outside the trace layer; a request cut off by that timeout is logged via `TracedBody`'s drop path (status `Unknown`) rather than a distinct deadline event. ## Tests (all offline, deterministic; a shared in-test capturing subscriber, no new dev framework) - RPC produces a `grpc.request` span carrying `request_id` + `rpc.method`, logs the terminal status (`NotFound`/`Ok`) at INFO with elapsed, and a handler-emitted event is observed under the span. - Auth accept logs DEBUG; bad-token and missing-header reject log WARN with a reason -- asserting neither the real token nor the presented guess appears in any captured log field. ## Gates `cargo fmt --all -- --check`, `cargo check-all`, `cargo test-all` all green; 0 ignored. Secret-safety grep of the diff confirms no token/header value in any tracing macro. Refs #358

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: KofTwentyTwo/nuncio#371