Explain why prometheus-exporter marks an endpoint unavailable - #916
Conversation
🔍 Vulnerabilities of
|
| digest | sha256:4557e65da8ebd5be49503128d9e5d37cbab4c563ffa780a5718620f4d596de75 |
| vulnerabilities |     |
| platform | linux/amd64 |
| size | 124 MB |
| packages | 380 |
📦 Base Image ubuntu:24.04
| also known as |
|
| digest | sha256:1e0a86e57d247923571b75e0aaf48a1449cf8c543d51fb3e07a4a7d7bfa79316 |
| vulnerabilities |   |
There was a problem hiding this comment.
Solid direction and the failure taxonomy is the right shape — the cardinality fix is genuinely correct, and I verified it at runtime with endpoints carrying different query-param label sets. Two things need to change before this goes in.
The first is a crasher: the metric pointers are now assigned by initHealthcheckMetrics, but the poller goroutines are launched before that call. Any endpoint whose first poll fails synchronously inside NewSubstreamsClientConn (missing :port, or --insecure --plaintext together) reaches markFailure while status is still nil. dmetrics.GaugeVec.SetInt derefs immediately and the pollers have no recover, so it takes the whole exporter down, all endpoints. go build -race flags it too. Reproduced both halves.
The second is that the change loses the "why" for the most common failure. waitForConnReady treats TRANSIENT_FAILURE as retryable, so connection-refused and NXDOMAIN both burn the full --connect-timeout and come out as byte-identical connect_timeout lines with the real dial error discarded. Before this, both surfaced as gRPC Unavailable carrying dial tcp ...: connection refused / no such host. Endpoint-down is the case an operator hits most, and it's the one that got harder to diagnose.
Rest is smaller — details inline. Worth calling the --force-protocol-version rejection out in the PR body with a deploy-order note: anything currently pinning 2 or 3 crash-loops on the new image, which silences that fleet's healthcheck metrics at exactly the wrong moment.
Classify every failed poll into a reason (connect, connect_timeout,
invalid_request, request_timeout, stream_error, stale_block, no_data),
exposed on a new substreams_healthcheck_failure_count{reason,grpc_code}
counter and carried in the logs.
Give connection establishment its own --connect-timeout budget, separate
from --timeout: gRPC dials lazily, so DNS, TLS and load-balancer
resolution used to be charged to the request timeout and a slow
connection was reported as an endpoint failure. Report the two phases
separately as connect_duration_ms and stream_duration_ms.
Log every failed poll, not only the transition into unavailable, and log
a block age above half of --max-freshness so an alert on block_age_ms is
no longer silent. Add a consecutive_failures gauge and reset block_age_ms
to NaN when a poll returns no block.
Speak sf.substreams.rpc.v4.Stream/Blocks only, dropping the v3-to-v2
fallback that closed the connection and then kept reading from it.
--force-protocol-version now accepts only v4 and is validated at startup.
Fix a panic on inconsistent label cardinality when endpoints carry
different sets of query-parameter labels.
# Conflicts:
# docs/release-notes/change-log.md
Declare the healthcheck metrics before starting the pollers. Moving them into initHealthcheckMetrics left the seven package-level pointers nil while the poller goroutines were already running, which is a data race and a nil dereference for any endpoint that fails on its first attempt. Fail fast when the gRPC channel reaches TRANSIENT_FAILURE instead of waiting out --connect-timeout. gRPC re-dials on its own backoff, so a refused connection or a DNS failure used to burn the whole budget and then report connect_timeout with the real dial error discarded. The request is now issued anyway, since that is what surfaces the dial error, and the failure is reported as connect_failed. connect_timeout is left to mean a connection that is merely slow. Rename the reason for a client that could not be constructed from connect to invalid_config: it never described the endpoint. Read the request deadline cause. gRPC answers with its own DeadlineExceeded status and drops the cause, so the log never named which budget expired. Report the block age on crossings of half of --max-freshness rather than on every poll, and only once three consecutive polls agree. A chain whose block interval straddles the threshold otherwise reports a healthy endpoint forever. Reject --force-protocol-version before ParseProtocolVersion so that an operator passing 2 or 3 is not first told those versions are supported. Guard the Clock dereference, reported as invalid_response, and drop the write-only pollResult.blockNum and endpointSpecs.url fields. Flag the --force-protocol-version break as an explicit operator step in the changelog, and drop comments that restated their identifier.
--force-protocol-version is not passed by any production deployment, so the flag becoming v4-only needs no operator step. Keep the breaking marker, drop the crash-loop warning.
4df60fd to
06d6569
Compare
There was a problem hiding this comment.
Second pass. Six of the seven are properly resolved and I verified each rather than taking the replies at face value — init ordering exercised under -race with both trigger cases, context.Cause confirmed end-to-end (dgrpc.AsGRPCError unwraps, so the grpc_code label survives the %w), the freshness streak traced through sustained drift / straddling / recovery / nil maxFreshness, and the nil-Clock branch confirmed reachable against a fake server. All nine taxonomy reasons are reachable, none dead. CI green including -race.
The waitForConnReady fix is the problem. Failing fast on the first TRANSIENT_FAILURE fixed the diagnostic but broke recovery: gRPC enters that state on any failed dial and re-dials on its own backoff, so it is not terminal. An endpoint that refuses one dial and accepts the next — a rolling restart, a brief DNS blip, a load balancer moment with no healthy backend — is now reported unavailable on the first refused SYN, and --connect-timeout no longer covers the case it exists for. That is a behaviour change to the availability signal itself, not to its explanation, which makes it worse than the bug it replaced.
I wrote two regression tests rather than just asserting this. Both fail on 06d6569b:
--- FAIL: TestWaitForConnReady_RecoversWithinConnectBudget (0.50s)
endpoint came up after 500ms, well inside the 5s connect budget,
but the poll gave up after 593.833µs
--- FAIL: TestWaitForConnReady_GivesUpAfterConnectBudget (0.00s)
gave up after 529.125µs without spending the 500ms connect budget
Both pass with the fix suggested inline, and the full tools suite stays green under -race. Test file and the one-function change are in the inline comments — take them or replace them, but waitForConnReady should not stay uncovered either way: it is the site of both this fix and the previous one, and neither had a test that could fail.
The rest is small: the changelog claims the DNS failure is carried in the error and it isn't, and a few nits.
One aside — 44c481de's message body ends with the git merge comment template committed verbatim (# Conflicts: / # docs/release-notes/change-log.md). Worth a reword on the next force-push.
| // the connection rather than to the endpoint's own answer. | ||
| func streamFailure(ctx context.Context, connectFailedFast bool, err error) (failureReason, error) { | ||
| err = withDeadlineCause(ctx, err) | ||
| if connectFailedFast { |
There was a problem hiding this comment.
connectFailedFast short-circuits before the error is looked at, so the reason and the code can disagree.
Once it is set at prometheus-exporter.go:519, gRPC keeps re-dialing on its backoff. If the channel reaches READY before the RPC is issued and the stream then fails for an unrelated reason — ResourceExhausted, Unauthenticated, a request deadline — this still returns reasonConnectFailed while grpcCodeOf reports the true code. failure_count{reason="connect_failed",grpc_code="Unauthenticated"} is a series that describes nothing real.
Low probability today (gRPC's base backoff is ~1s against microseconds to issue the RPC), and it shrinks further if you take the wait-through-TRANSIENT_FAILURE version, since the flag would then only be set at budget expiry. Left unpatched for that reason — worth settling waitForConnReady first, then gating this on the error rather than the flag alone.
| return fmt.Errorf("invalid --force-protocol-version %d: the prometheus exporter only speaks %s for now, leave the flag unset or pass 4", protocolVersionFlag, client.ProtocolVersionV4) | ||
| } | ||
|
|
||
| forceProtocolVersion, err := client.ParseProtocolVersion(protocolVersionFlag) |
There was a problem hiding this comment.
subReq.Validate() runs inside the poll loop, after a full dial, on every poll of every endpoint.
A bad module name is a startup config error. Hoisting the validation next to the other startup checks in runPrometheus would fail the command immediately, instead of reporting every endpoint as invalid_request forever, once per interval, each time paying a TCP+TLS connection first.
Left this one to you — it changes when the command fails, which is more than a nit.
TRANSIENT_FAILURE is not terminal: gRPC re-dials on its own backoff, so an endpoint that refuses one dial and accepts the next (rolling restart, DNS blip, load balancer with no healthy backend) is reported unavailable on the first refused SYN, and --connect-timeout is never spent on the case it exists for. Both tests fail at 06d6569. They pass once waitForConnReady waits through TRANSIENT_FAILURE while recording that a dial failed, so connect_failed keeps the real dial error and connect_timeout keeps its meaning. Refs #916
trackBlockAge returned early without clearing the streak, so a poll carrying no block age did not break it. Two polls above half, an outage, then one more above half reported confirmed_over_polls: 3 for a window that was never consecutive. Refs #916
The check above it rejects everything but 0 and 4, and both parse, so the error branch could not be taken. Refs #916
The changelog said connect_failed carries the DNS failure. It does not: the roundrobin balancer replaces the resolver error, so a hostname that does not resolve surfaces as "no children to pick from" and no part of the message names DNS. streamFailure's doc comment broke mid-sentence and documented connect_timeout, which it never returns. Refs #916
|
Pushed four commits rather than leaving the code in comments:
Each is one logical change; What I did not push, on purpose: the I've cleared out the review comments that the pushes resolved, so what's left inline is only what's still open. I also withdrew an earlier nit about the Happy to take the |
The connect budget exists to cover a backend that is restarting, so a refused dial is not the end of the attempt: gRPC re-dials on its own backoff and an endpoint that comes back inside the budget is healthy. Returning on the first TRANSIENT_FAILURE reported those as connect_failed and broke TestWaitForConnReady_RecoversWithinConnectBudget. waitForConnReady goes back to waiting for the deadline, but remembers whether a dial failed along the way. That is what still separates the two timeouts: a channel that failed a dial reports connect_failed and lets the request surface the actual dial error, while one that never left CONNECTING reports connect_timeout. Renamed errConnFailedFast to errConnDialFailed, which is what it now means.
GabrielCartier
left a comment
GabrielCartier
left a comment
There was a problem hiding this comment.
Approving. Verified ebbe7294 locally rather than off the CI summary: both regression tests pass, full tools suite green (35) under -race, build/vet/gofmt clean.
The connect-budget fix is the right shape — dialFailed is remembered while the loop still waits out the budget, so a backend that recovers inside it reports healthy and one that genuinely failed a dial still gets connect_failed with the real error instead of a bare timeout. connect_timeout keeps its meaning for a channel that never left CONNECTING. errConnDialFailed is a better name than the one I suggested; "fast" was the part that was wrong.
I'm leaving the two remaining threads open on purpose — streamFailure short-circuiting on connectFailed without consulting the error, and subReq.Validate() running per-poll after a full dial. Neither is necessary for this to merge. Take them or close them as you like.
3 participants
An alert firing on
substreams_healthcheck_statusgave no way to tell an unreachable endpoint from an unauthenticated, overloaded or merely late one, and a flapping endpoint could produce no logs at all. This adds a failure taxonomy, separates connection setup from the request, and logs every failed poll.Every failure is classified into a
reason(invalid_config,connect_failed,connect_timeout,invalid_request,request_timeout,stream_error,stale_block,invalid_response,no_data), exposed on a newsubstreams_healthcheck_failure_count{reason,grpc_code}counter and carried in the logs. Metrics are declared throughdmetrics.Connection establishment gets its own
--connect-timeout(default 10s), separate from--timeout, which now covers theBlocksrequest alone. gRPC dials lazily, so DNS/TLS/LB resolution was previously charged to the request budget and a slow connection was reported as an endpoint failure — the source of thewaiting for new LB policy update: context deadline exceedederrors. The exporter now waits for the channel to beREADYfirst, and reportssubstreams_healthcheck_connect_duration_msandsubstreams_healthcheck_stream_duration_msseparately;substreams_healthcheck_duration_mskeeps its old meaning of the two combined.A dial that fails outright is reported as
connect_failedwithin milliseconds, carrying the real dial error (connection refused, DNS failure), rather than waiting out the connect budget.connect_timeoutis reserved for a connection that is merely slow to come up, and its error names the budget that expired instead of sayingcontext deadline exceeded.Every failed poll is logged, not just the transition into
unavailable, with reason, gRPC code, both durations and the consecutive failure count; recovery logs the downtime and how many polls failed. A block age crossing half of--max-freshnessis reported too, so an alert onsubstreams_healthcheck_block_age_msis no longer silent — edge-triggered and confirmed over three polls, so a chain whose block interval straddles the threshold stays quiet.New
substreams_healthcheck_consecutive_failuresgauge to alert on instead ofstatuswhen single-poll hiccups should be ignored, andblock_age_msnow resets toNaNwhen a poll returns no block instead of reporting the age of the last block ever seen.The exporter speaks
sf.substreams.rpc.v4.Stream/Blocksonly. The v3-to-v2 fallback is removed — it closed the connection and then kept reading from it — and--force-protocol-versionnow accepts only4(or unset), the flag being kept for the protocol versions to come. Nothing in production passes it today, so there is no deploy-order step.Fixes a panic on inconsistent label cardinality when endpoints are given different sets of query-parameter labels, and guards the block
Clockdereference that would otherwise take the whole exporter down.Verified end-to-end against the live fleet with a real API key: the v4 success path works on
mainnet.ethandmainnet.sol, andconnect_failed(refused port and NXDOMAIN),connect_timeout,stream_error/Unauthenticated,stale_block, the block-age crossing and the version-flag rejection were each exercised.