fix(grpc-proxy): emit worker tunnel close reason as metric, log and span - #597
Conversation
|
Note Reviews pausedIt looks like this branch is under active development. To avoid overwhelming you with review comments due to an influx of new commits, CodeRabbit has automatically paused this review. You can configure this behavior by changing the Use the following commands to manage reviews:
Use the checkboxes below for quick actions:
ℹ️ Recent review info⚙️ Run configurationConfiguration used: Path: .coderabbit.yaml Review profile: CHILL Plan: Enterprise Run ID: 📒 Files selected for processing (2)
🚧 Files skipped from review as they are similar to previous changes (1)
📝 WalkthroughWalkthroughThe proxy now records worker and client connection lifecycle metrics, close reasons, durations, token issuance and age, CONNECT outcomes, logs, and OpenTelemetry spans. Tests validate reason mappings, label coverage, and close-origin precedence. ChangesProxy connection observability
Estimated code review effort: 4 (Complex) | ~45 minutes Sequence Diagram(s)sequenceDiagram
participant Client
participant HijackHandler
participant StreamDirector
participant WorkerConnectionCache
participant Metrics
participant OpenTelemetry
Client->>HijackHandler: Send CONNECT request
HijackHandler->>StreamDirector: Validate token and request ID
HijackHandler->>Metrics: Record CONNECT result and token age
StreamDirector->>WorkerConnectionCache: Manage worker connection
WorkerConnectionCache->>StreamDirector: Report eviction reason
StreamDirector->>Metrics: Record close reason and duration
StreamDirector->>OpenTelemetry: Emit eviction span
Suggested reviewers: 🚥 Pre-merge checks | ✅ 4 | ❌ 1❌ Failed checks (1 warning)
✅ Passed checks (4 passed)
✨ Finishing Touches 💡 1⚔️ Resolve merge conflicts 💡
📝 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. |
bf61097 to
d499500
Compare
There was a problem hiding this comment.
Actionable comments posted: 2
🧹 Nitpick comments (1)
src/invocation-plane-services/grpc-proxy/proxy/hijack.go (1)
47-53: 📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick winAdd a
/v1/proxyCONNECT duration histogram.HTTP/1 and HTTP/3 bypass the tracing middleware. Record CONNECT setup duration with a bounded Prometheus histogram using a
_secondssuffix.🤖 Prompt for 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. In `@src/invocation-plane-services/grpc-proxy/proxy/hijack.go` around lines 47 - 53, Add a bounded Prometheus histogram for `/v1/proxy` CONNECT setup duration, named with a `_seconds` suffix, and observe the elapsed setup time on every CONNECT attempt in the hijack flow. Update the existing deferred completion block around `result` and `metrics.WorkerConnectTotal` so duration recording occurs for all terminal paths, including HTTP/1 and HTTP/3.Sources: Coding guidelines, Path instructions
🤖 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/metrics/metrics.go`:
- Around line 221-245: Worker registration failures are currently counted as
accepted CONNECTs. In
src/invocation-plane-services/grpc-proxy/proxy/metrics/metrics.go lines 221-245,
add a bounded registration-failure result constant and include it in
ConnectResults; in src/invocation-plane-services/grpc-proxy/proxy/hijack.go
lines 130-134, update HijackHandler to select that result when RegisterWorker
fails before closing the tunnel, and add coverage for this failure path.
In `@src/invocation-plane-services/grpc-proxy/proxy/worker/connections.go`:
- Around line 135-138: Update Close to lock workerConnectionLock while reading
workerConnections, capture its length in a local snapshot, then unlock and reuse
that snapshot for both ClientConnectionWorkerTunnelsAtClose and the debug log.
Keep InitWorkerConn’s existing lock-protected writes unchanged.
---
Nitpick comments:
In `@src/invocation-plane-services/grpc-proxy/proxy/hijack.go`:
- Around line 47-53: Add a bounded Prometheus histogram for `/v1/proxy` CONNECT
setup duration, named with a `_seconds` suffix, and observe the elapsed setup
time on every CONNECT attempt in the hijack flow. Update the existing deferred
completion block around `result` and `metrics.WorkerConnectTotal` so duration
recording occurs for all terminal paths, including HTTP/1 and HTTP/3.
🪄 Autofix
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: 137b9a68-6073-4ec2-b575-aa6a93801b6b
📒 Files selected for processing (6)
src/invocation-plane-services/grpc-proxy/proxy/director.gosrc/invocation-plane-services/grpc-proxy/proxy/director_test.gosrc/invocation-plane-services/grpc-proxy/proxy/hijack.gosrc/invocation-plane-services/grpc-proxy/proxy/metrics/metrics.gosrc/invocation-plane-services/grpc-proxy/proxy/worker/connections.gosrc/invocation-plane-services/grpc-proxy/proxy/worker/worker.go
🚧 Files skipped from review as they are similar to previous changes (1)
- src/invocation-plane-services/grpc-proxy/proxy/director_test.go
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>
Follow-up to the close-reason work in this PR. Reviewing the deployed output showed the instrumentation could say a tunnel closed but not who closed it, and could not see the CONNECT path at all. Both gaps left the questions being asked during incidents unanswerable. Close origin ------------ EvictionReasonDeleted covered three different situations: the client hanging up, the worker hanging up, and a proxy drain. Which side went first is normally the question, and the metric could not distinguish them. onInactive has two callers, worker/connections.go for a client close and worker/worker.go for a worker close, and DeleteAll on drain produces the same reason again. Record an origin on the connection before teardown and resolve it in the eviction handler, so the reason is now client_closed, worker_closed or shutdown. First writer wins: a client close cascades into a worker close, so without that the original cause would always be overwritten. A delete with no recorded origin still reports as deleted rather than being folded into another bucket, so a missing instrumentation path stays visible. CONNECT outcomes ---------------- Nothing observed /v1/proxy. Every terminal path now records exactly one outcome, including the three cases that all return 403 today and are indistinguishable in the response and in the log: rejected_token_expired issued by this pod, aged out rejected_token_unknown never issued by this pod rejected_requestid_mismatch valid token, bound to another request Telling expired from unknown needs a record that outlives the auth entry, so a diagnostic-only cache of issued tokens is kept alongside it, capacity bounded and never consulted when granting access. Auth still reads workerAuth exclusively. Token age is recorded at accept and at rejection, bucketed densely below 30s because that is where consts.Timeout puts the cliff. This makes the headroom real traffic has against the token lifetime directly visible, rather than something inferred from a 403 count. Client connections ------------------ Only an active gauge existed, so churn and lifetime were invisible. Adds opened count, duration, and how many worker tunnels a client connection was still holding when it closed. Anything above zero there means that close tore down live tunnels. All new labels are bounded and pre-initialised. Tests assert the emitted sets and the pre-initialised sets agree, so a new reason or outcome cannot silently skip pre-initialisation. No behaviour change: no auth decision, timeout or teardown path is altered. Signed-off-by: balajinvda <bganesan@nvidia.com>
Signed-off-by: Bora Oztekin <boztekin@nvidia.com>
6c04d3f to
a96a24e
Compare
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/worker/connections_test.go`:
- Around line 695-706: Make the concurrent close test deterministic by
coordinating the `InitWorkerConn` and `conn.Close()` goroutines instead of
releasing both through the same `start` barrier. Run and capture the `Close()`
error, assert the expected closed-connection result for the selected ordering,
and keep initialization assertions consistent with that ordering; do not discard
close errors. Validate the grpc-proxy test with Bazel using
`--flaky_test_attempts=3`.
🪄 Autofix
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: 83788447-43d5-4bdf-9457-9ac317bfbaaa
📒 Files selected for processing (2)
src/invocation-plane-services/grpc-proxy/proxy/worker/connections.gosrc/invocation-plane-services/grpc-proxy/proxy/worker/connections_test.go
🚧 Files skipped from review as they are similar to previous changes (1)
- src/invocation-plane-services/grpc-proxy/proxy/worker/connections.go
There was a problem hiding this comment.
Caution
Inline review comments failed to post. This is likely due to GitHub's internal server error or limits when posting large numbers of comments. If you are seeing this consistently it is likely a permissions issue. Please check "Moderation" -> "Code review limits" under your organization settings.
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/worker/connections_test.go`:
- Around line 695-706: Make the concurrent close test deterministic by
coordinating the `InitWorkerConn` and `conn.Close()` goroutines instead of
releasing both through the same `start` barrier. Run and capture the `Close()`
error, assert the expected closed-connection result for the selected ordering,
and keep initialization assertions consistent with that ordering; do not discard
close errors. Validate the grpc-proxy test with Bazel using
`--flaky_test_attempts=3`.
🪄 Autofix
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: 83788447-43d5-4bdf-9457-9ac317bfbaaa
📒 Files selected for processing (2)
src/invocation-plane-services/grpc-proxy/proxy/worker/connections.gosrc/invocation-plane-services/grpc-proxy/proxy/worker/connections_test.go
🚧 Files skipped from review as they are similar to previous changes (1)
- src/invocation-plane-services/grpc-proxy/proxy/worker/connections.go
🛑 Comments failed to post (1)
src/invocation-plane-services/grpc-proxy/proxy/worker/connections_test.go (1)
695-706: 🎯 Functional Correctness | 🟠 Major | ⚡ Quick win
Make the concurrent close test deterministic.
close(start)releases 100InitWorkerConncalls and 100conn.Close()calls together. If a close completes before an initializer,InitWorkerConncan return the documented closed-connection error fromconnections.goLines [84-129]. Lines [704-706] report that valid outcome as a failure, so the test depends on goroutine scheduling.Run one close operation, capture its error, and define the expected result for the chosen ordering. Do not discard
Close()errors.As per coding guidelines, validate this grpc-proxy test with Bazel and
--flaky_test_attempts=3.Also applies to: 709-713
🤖 Prompt for 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. In `@src/invocation-plane-services/grpc-proxy/proxy/worker/connections_test.go` around lines 695 - 706, Make the concurrent close test deterministic by coordinating the `InitWorkerConn` and `conn.Close()` goroutines instead of releasing both through the same `start` barrier. Run and capture the `Close()` error, assert the expected closed-connection result for the selected ordering, and keep initialization assertions consistent with that ordering; do not discard close errors. Validate the grpc-proxy test with Bazel using `--flaky_test_attempts=3`.Source: Coding guidelines
|
🎉 This PR is included in version nvcf-grpc-proxy-v1.32.1 🎉 The release is available on GitHub release Your semantic-release bot 📦🚀 |
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