fix(grpc-proxy): emit worker tunnel close reason as metric, log and span - #597
fix(grpc-proxy): emit worker tunnel close reason as metric, log and span#597balajinvda wants to merge 1 commit into
Conversation
📝 WalkthroughWalkthroughWorker tunnel lifecycle telemetry now covers creation, active connections, closure reasons, duration, logging, and tracing. ChangesWorker tunnel observability
Estimated code review effort: 3 (Moderate) | ~20 minutes Sequence Diagram(s)sequenceDiagram
participant Director
participant WorkerConnectionCache
participant PrometheusMetrics
participant OpenTelemetryTracer
Director->>WorkerConnectionCache: Cache worker connection
Director->>PrometheusMetrics: Record opened and active connections
WorkerConnectionCache->>Director: Report eviction reason
Director->>PrometheusMetrics: Record closure and duration
Director->>OpenTelemetryTracer: Emit eviction span
Possibly related PRs
Suggested reviewers: 🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
✨ Finishing Touches📝 Generate docstrings
🧪 Generate unit tests (beta)
Comment |
There was a problem hiding this comment.
Actionable comments posted: 1
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@src/invocation-plane-services/grpc-proxy/proxy/director.go`:
- Around line 159-166: Update the span name passed to Tracer.Start in the worker
connection cache eviction path to the stable name
grpc-proxy.worker_connection_cache_eviction, while preserving the existing
attributes and tracing flow.
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Path: .coderabbit.yaml
Review profile: CHILL
Plan: Enterprise
Run ID: 2cc45584-0f6f-458e-b4ae-d0c47b29f21b
📒 Files selected for processing (5)
src/invocation-plane-services/grpc-proxy/proxy/BUILD.bazelsrc/invocation-plane-services/grpc-proxy/proxy/director.gosrc/invocation-plane-services/grpc-proxy/proxy/director_test.gosrc/invocation-plane-services/grpc-proxy/proxy/metrics/metrics.gosrc/invocation-plane-services/grpc-proxy/proxy/worker/worker.go
The span was named "worker connection cache eviction triggered", a sentence matching the log message. AGENTS.md specifies service.operation for span names, with grpc-proxy.forward given as an example, and asks that names stay stable so dashboards and alerts do not break. Rename to grpc-proxy.worker_connection_cache_eviction. The log message is deliberately left unchanged; log and span naming conventions differ and matching them to each other was the original mistake. Raised in review on #597. Signed-off-by: balajinvda <bganesan@nvidia.com>
|
Good catch, this one was a genuine convention violation rather than a nitpick. AGENTS.md specifies Renamed to The log message text is deliberately unchanged. That one I do want stable, since promoting it from debug to info was the point of the change and any existing log searches should keep working. |
The proxy closes worker tunnel connections for several ordinary reasons:
the connection cache TTL expiring, the connection going inactive,
capacity eviction, and shutdown drain. It already computed which reason
applied on every close, then wrote it only to a debug log and discarded
it.
That made "why did the tunnel drop" unanswerable from production data.
It could only be inferred by reading source, because debug logging is
off in production and no metric or span carried the reason. There was
also no telemetry of any kind on the proxy-to-worker leg, which is where
this class of failure lives.
Add four metrics, following the naming and pre-initialisation
conventions in AGENTS.md:
nvcf_grpc_proxy_service_worker_connections_active
nvcf_grpc_proxy_service_worker_connection_opened_total
nvcf_grpc_proxy_service_worker_connection_closed_total{reason}
nvcf_grpc_proxy_service_worker_connection_duration_seconds
The reason label is bounded to four values and every one is
pre-initialised to zero, so rate() has no gaps and absent() alerts do
not misfire. Duration buckets deliberately straddle the two timers that
can close a tunnel, the worker-side QUIC idle timeout at 8s and this
service's cache TTL at 30s, so a hard cliff at either value is visible
as a timer kill rather than a natural end.
Promote the eviction log from debug to info and add how long the tunnel
was held. The message text is unchanged so existing log searches keep
working. Also emit a span named per the service.operation convention in
AGENTS.md, carrying the request id, reason and duration; the eviction
context is the cache's own rather than the session's, so it has no
parent, but the request id makes a dropped session correlatable in
tracing instead of only by grepping logs.
Open and close counts are incremented where they balance: on successful
insertion into the cache, and in the eviction handler which fires for
every entry that was inserted.
Tests cover the reason strings, since dashboards and alerts key on them,
and assert that the emitted set and the pre-initialised set agree.
No behaviour change.
Signed-off-by: balajinvda <bganesan@nvidia.com>
bf61097 to
d499500
Compare
TL;DR
grpc-proxy already computes why it closes every worker tunnel, then writes it to a debug log and discards it. This emits it as a metric, promotes the log to info, and adds a span, so "why did the tunnel drop" becomes answerable from production data.
Observability only, no behaviour change.
Additional Details
The proxy closes worker tunnels for several ordinary reasons: cache TTL expiry, the connection going inactive, capacity eviction, and shutdown drain.
mapEvictionReasonturns each into a string on every close, and that string only ever reached a debug log line.That left an entire hop unobserved. Existing metrics cover client connections and NATS; nothing covered the proxy-to-worker leg, which is exactly where connection-lifecycle failures occur. During a recent streaming-disconnect investigation the question "is the proxy dropping these connections, and if so why" stayed open for weeks, while the service computed the answer every single time it happened.
Metrics added, following the naming and pre-initialisation conventions in AGENTS.md:
Notes on the choices:
reasonis bounded to four values (ttl_expired,deleted,capacity_reached,unknown) and every one is pre-initialised to zero, sorate()has no gaps andabsent()alerts do not misfire on a reason that has not occurred yet.The log line is promoted from debug to info and gains
held_for. The message text is deliberately unchanged so existing log searches and any downstream consumers keep working.The span is emitted with the request id, reason and duration. Worth knowing: the eviction context is the cache's own, not the session's, so this span has no parent to attach to. The request id attribute is what makes a dropped session correlatable in tracing rather than only by grepping logs.
For the Reviewer
proxy/director.goeviction handler is the substance.proxy/metrics/metrics.gofor the metric definitions and the pre-initialised reason set.For QA
No QA needed; this is observability only and changes no request handling.
Verified locally:
bazel test //... --flaky_test_attempts=3— 9 of 9 targets passgo build ./...,go vet ./proxy/..., gofmt clean on all changed filesbazel run //:gazellefor the BUILD file updatesTests added cover the reason strings, since dashboards and alerts key on them, plus a guard that the set emitted by
mapEvictionReasonand the pre-initialised label set stay in agreement. A reason that is emitted but not pre-initialised would silently reintroduce the gap problem.Issues
Closes #596
Checklist
Summary by CodeRabbit
New Features
Tests