Skip to content

api: publisher check logs client disconnects as warnings — 88% of prod's warning volume #782

Description

@nikw9944

Summary

publisher check failed error="rows: context canceled" is the single largest source of warnings in prod — 413 of 469 WRN lines in a 24h window — and essentially all of it is users navigating away from a page.

399  publisher check failed error="rows: context canceled"
 14  publisher check failed error="total publishers: context canceled"

(Remaining 24h prod warnings, for scale: 12 link metrics, 6 shreds rewards, 6 device status changes, 5 shreds rewards detail, 4 temporal poll, 3 topologies.)

Cause

api/handlers/publisher_check.go:257 logs with a raw slog.Warn:

resp, fromCache, err := a.fetchPublisherCheckCachedOrLive(r.Context(), q, epochsParam, slotsParam, a.FetchPublisherCheckData)
if err != nil {
    slog.Warn("publisher check failed", "error", err)
    http.Error(w, dberror.UserMessage(err), http.StatusInternalServerError)
    return
}

This is a request handler, and the context is r.Context(). So context canceled here means the client went away mid-query — a closed tab, a navigation, a browser-aborted fetch. The two wrapped messages come from publisher_check.go:451 (rows: %w) and :476 (total publishers: %w).

CLAUDE.md already names this case and says these lines should not exist:

api/handlers.logError wraps this and additionally skips client disconnects entirely (on a request path the caller is gone).

and:

Non-actionable conditions that should never log ERROR: … client disconnects

This call site bypasses that helper, so the disconnects are logged unconditionally.

Why it is worth fixing

It buries real signal. 88% of prod's warning volume is one non-event. Anyone scanning prod warnings for something actionable is reading past 400 lines of tab-closing first.

It can never escalate. Because it is an unconditional slog.Warn, a genuine sustained failure of this query — ClickHouse refusing it, a timeout regression, a bad epoch parameter — produces log lines indistinguishable from someone closing a tab. The condition is invisible to alerting in both directions: it cannot page when it should, and it is too noisy to read manually.

Publisher check is also not a cheap query (~82k cpu-s/day; frequency was already cut by #699), so a real regression here is worth knowing about.

Suggested fix

Route the call site through logError so client disconnects are dropped and genuinely transient causes land at WARN via dberror.IsTransient:

if err != nil {
    logError("publisher check failed", "error", err)
    http.Error(w, dberror.UserMessage(err), http.StatusInternalServerError)
    return
}

Worth a quick sweep for sibling sites while in there — the same handler-path pattern may account for some of the smaller counts above (topologies query failed, failed to fetch device status changes, both also context canceled).

Not a performance problem

Flagging this explicitly because it is the natural first guess: this is not primarily wasted ClickHouse CPU. ClickHouse cancels the query when the client disconnects, so the waste is bounded by however far the query got. The cost here is observability, not compute.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

No labels
No labels

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions