Skip to content

device/telemetry: log RPC endpoint identity, collapse repeated failures into transitions #4129

Description

@elitegreg

Tracked by #4130.

Problem

During the 2026-07-29 ledger RPC outage the telemetry agent emitted roughly 600 near-identical
error lines over 22 hours and still did not explain what was wrong. Meanwhile the three facts that
would have identified the cause were either unlogged or invisible.

The pattern to fix is logging per iteration instead of per state change.

Changes

1. Log which RPC endpoint is actually in use

Nothing anywhere records the resolved remote address. The 2026-07-29 outage was one bad load
balancer IP out of five behind one hostname, and no log line on any host said which one it was
talking to. This is the single fact that would have cut triage from a day to minutes.

Add a DialContext wrapper that logs the resolved address on each new connection:

DialContext: func(ctx context.Context, network, addr string) (net.Conn, error) {
	c, err := dialer.DialContext(ctx, network, addr)
	if err != nil {
		return nil, err
	}
	log.Info("ledger rpc connection established",
		"host", addr, "remote", c.RemoteAddr().String())
	return c, nil
},

Noise: with connection pooling this is a handful of lines per day. It also has the useful property
of going quiet exactly when a client has stopped re-dialing, which is itself the symptom.

2. Collapse the pinger's epoch failure into a state transition

pinger.go:58 logs an Error on every failing tick:

epoch, err := p.getCurrentEpoch(ctx)
if err != nil {
	p.log.Error("failed to get current epoch", "error", err)
	return
}

Replace with first-failure and recovery only:

// on entering the failed state
p.log.Error("epoch fetch failing, probing degraded", "error", err)
// on recovery
p.log.Info("epoch fetch recovered", "downtime", d, "ticksSkipped", n)

Roughly 600 lines become 2, and the recovery line carries the duration and skipped-tick count,
which is the part anyone actually needs. Add an
errors_total{error_type="pinger_epoch_fetch"} counter for the middle; the pinger currently has
no metric at all.

(If #4125 lands first, this becomes a warning about serving a
cached epoch rather than about skipping the tick. Either way the transition-only shape applies.)

3. Log peer count changes

peers.go:210 reports the outcome of every refresh at Debug, so the peer list is invisible in
production:

p.log.Debug("Refreshed peers", "devices", len(devices), "links", len(links), "peers", len(peers), "tunnelsNotFound", tunnelsNotFound)

Keep the Debug line, and add an Info line when the count changes plus a Warn when it reaches zero.
A refresh that succeeds and returns zero peers is currently indistinguishable from a healthy one at
Info level. Add a peers_total gauge alongside the existing
peer_discovery_not_found_tunnels.

Noise: one line per change. In steady state, none.

4. Route the stale-cache warning through the agent logger

internal/serviceability/cache.go:87 calls the package-global slog:

slog.Warn("telemetry: program data fetch failed, returning stale cached data", "age", cachedAge, "error", err)

cmd/telemetry/main.go:129 builds its own handler and never calls slog.SetDefault:

log := slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{
	Level:     logLevel,
	AddSource: true,
}))

So the most diagnostic signal in the agent — "the ledger is unreachable and I am serving stale
data" — is emitted through a different logger, in a different format, with no source= field, and
cannot be leveled with the rest of the agent. That is very likely why it was missed during triage.

Fix: give CachingFetcher an injected *slog.Logger (NewCachingFetcher already takes a config-ish
argument list; add it there), and rate-limit to first occurrence plus recovery. It currently fires
on every refresh, which is every 10s for the whole outage.

The existing metricStaleCacheAge gauge already covers the sustained case and is the right thing
to alert on.

5. Make silent drops loud

Covered in detail by #4126 (buffer-full) and #4127 (account-full). Listing here
so the logging work is not considered done without them.

Not proposed

Per-tick logging of successful probes, submissions, or refreshes. The failure mode being fixed is
too much repetition, not too little detail.

Acceptance

  • A 22-hour total RPC outage produces single-digit log lines per component, not hundreds.
  • The resolved RPC endpoint appears in logs.
  • Peer count reaching zero is visible at Info level.
  • Every path that discards samples has both a log line and a counter.

Metadata

Metadata

Assignees

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions