Logging

This page is the level guide and the convention catalogue. Mechanics (context plumbing, contextutil.GetLogger) live in code_boundaries.md.

The rule

The level answers one question: who must act?

Pick by intent, not by the number of stack frames between the call and the cause, and not by which HTTP status the request ended with. A line whose answer to “who must act?” is nobody is an Info line however alarming its wording, and a line an operator must act on is an Error however routine the code path that produced it.

Three corollaries carry most of the weight, and each has its own section below: alarms read fields, not levels, detection belongs to metrics, and an internal failure is never a caller error.

Debug

Developer trace. Off in production. Use freely for investigative scaffolding that you would otherwise leave around as a // TODO: print this.

logger.Debug("ephemeral runner signaled ready", "runner_id", runnerID)

Info

Normal lifecycle events, one per state transition rather than one per step in a transition — and routine refusals whose rate tells nobody anything. A validation rejection, a denied authz check, a 429, a 409 on a run whose deployment was already cancelled: the system worked exactly as designed, the caller already learned the outcome from the status code, the actor is known and accountable, and nobody is paged. The line exists so an operator can reconstruct one request after the fact.

logger.Info("runner group key rotated", "group_id", groupID)
logger.Info("matched SCM integration", "integration_id", id, "repository_url", url)
logger.Info("rate limit exceeded", "policy", policy.Name, "route", route)
logger.Info("service account token used on a forbidden endpoint", "path", path)

Authentication failures are the exception. A 401 is the one refusal where we do not know who the caller was, and where a rate is a security signal rather than a usage statistic. Those stay at Warn — see the Warn section’s “attention only in aggregate”. A 403 does not: the caller authenticated, we know exactly who they are, and the permission model turning them away is it working.

This is a rule for new lines, not a licence to go re-level existing ones. Moving a line between Info and Warn changes nothing an alarm reads — see below — so it is rarely worth a diff on its own.

Warn

The system did something worse than normal and expects to recover: a remote dependency hiccuped and we retried, fell back, or are about to; a degraded mode engaged; a budget was exceeded and shed load. Warn earns attention only in aggregate, which imposes two obligations:

• One line per event, never one per attempt. Five retries of one operation are one Warn, emitted once — at exhaustion if it never succeeds, or not at all if it does. A rate of Warn must be readable as a rate of events.
• Escalate on exhaustion. A transient that stops being transient is an Error. Where the retry budget is already tracked — scm_events.attempt_count, the runner group’s consecutiveLaunchFailures — key the escalation off it rather than inventing a second counter beside it.

logger.Warn("rate limiter unavailable, failing open", "policy", policy.Name, "error", err)
logger.Warn("read database unreachable; serving degraded", "error", err)
logger.Warn("github API unavailable, event will be retried", "attempt", n, "error", err)

Error

Failures the system could not handle, where the right next step is human attention. If a dashboard alerts on level=error, every line should be one the on-call wants to wake up to.

logger.Error("user_id missing from context before authz middleware") // invariant violated
logger.Error("failed to begin read transaction", "error", err)        // db unavailable

The non-rule: Error does not mean “an error value was returned.” A returned error the handler maps to a 4xx is a refusal and logs at Info; a returned error from a query the system cannot proceed without logs at Error. The error value tells you what broke, never who must act.

Alarms read fields, not levels

An alarm should never be phrased as “page me on level:error”. The level is a severity hint written by whoever typed the line; the fields are facts about what happened, and they are what a query can actually stand on.

Every line already carries, where it applies:

So the questions an operator actually asks are already answerable, and none of them needs a level:

• Is someone attacking us? — the rate of http_responses{status="401"} by route, broken down by jwt_validation_failures{reason} and its PAT / SA / CSRF siblings. middleware.Logging wraps the mux from the outside, so a 401 written by auth middleware is counted like any other response — session failures included, even though AuthService records no counter of its own.
• Was this a person or the system? — presence and value of auth_method.
• Is it our bug? — http_responses{status=~"5.."}, or level:error once it is trustworthy.

The practical consequence: do not change a line’s level to make it visible. It will not become more visible, and every such change spends the meaning of the level it lands on. If something is genuinely not findable, the missing piece is a field or a counter, not a severity.

The one attribution the fields do not yet carry is dependency vs us on lines with no status — a GitHub 503 inside a background job looks the same as our own bug. component narrows it; nothing names it outright. Worth a field if that question ever needs answering at speed.

Detection is a metric; a log line is forensics

Every request is already counted. middleware.Logging records http_responses{method,route,status} and the request-duration histogram on every request; the rate limiter records every decision per policy; login, JWT, PAT, SA and CSRF failures each have their own counter. See internal/otel/setup.go for the full set.

So a dashboard that wants to know “are 403s spiking?” reads the counter. It must never need a log level to find out, and raising a line to Warn to make it visible on a graph is backwards: it buys nothing the metric did not already have, and it costs the on-call the ability to trust Warn.

Before you raise a level to make something visible, check whether a metric already covers it. If one does, leave the line where it is. If none does, add the counter — that is the change, not the level.

An internal failure is never a caller error

When a check cannot complete, the caller did nothing wrong and the answer is unknown. Reporting “unknown” as “denied” produces a line that is wrong on every axis at once: wrong level (Warn, not Error), wrong status (401/403 instead of 500), wrong message (a security event that did not happen), wrong metric (a validation-failure counter that reads like an attack), and a client told not to retry something that was, in fact, retryable.

The shape to avoid — one err covering both “this token is bad” and “we could not reach the database to find out”:

// WRONG: a SQL failure becomes "invalid JWT", 401, and a security metric.
claims, err := svc.ValidateRunnerGroupJWT(ctx, token)
if err != nil {
    tel.RecordJWTValidationFailure(ctx, reason(err))
    respondUnauthorized(ctx, w, "invalid runner group JWT", "error", err)
    return
}

Validation must distinguish the two before the caller sees them: a domain error for a credential that was judged and found wanting, and a distinct internal error for a check that never reached a verdict. The first is a refusal — 401, Info, counted as a validation failure. The second is an outage — 500, Error, not counted as anything about the credential. The client-facing rule is the same one cancellation follows: never let a message assert something the code did not actually determine.

Cancellation is not a failure

context.Canceled almost never deserves Warn or Error. It means either the client hung up (closed tab, aborted fetch, a webhook sender that timed out) or the process is shutting down — nobody did anything wrong and nobody can act on it. Every ctx-aware call below the cancellation point fails at once, so one disconnect can produce several lines from a single request.

Key off the context, not the error value, and log at Debug:

if ctx.Err() != nil {
    logger.Debug(msg, "error", err)
    return
}
logger.Error(msg, "error", err)

ctx.Err() != nil is the honest test: the same context.Canceled returned while the context is still live came from the operation’s own internals and is a real failure. context.DeadlineExceeded is a separate case — a request that blew its deadline is load-shedding worth a Warn, and a background job that blew its own timeout is an Error.

Established guards to copy rather than reinvent: handlers.WriteError (maps status to level, and context.Canceled → 499 + Debug), the middleware respond* helpers in middleware/auth_respond.go, and jobs.logStepFailure.

Anti-patterns

• A level chosen to make something visible. See Detection is a metric. The counter already exists; check before you raise.
• Error for a refusal that worked. A 400 on a malformed body, a 403 from authz, a 429 from the rate limiter: the system did its job, and nobody is woken for it. (Warn is defensible where a rate of the refusal is itself a signal — 401s — but Error never is.)
• Warn for genuine outages. A failed write transaction or a panic in a worker logs at Error. The on-call rule above applies.
• Error for a disconnected client or a shutting-down process. See Cancellation is not a failure.
• A message that asserts more than the code determined. “Invalid JWT” from a check that never ran, “runner group not found” from a SQL error. Both invent a cause. See An internal failure is never a caller error.
• Multiple lines per event. Pick the level once and use the same line. A Warn followed by an Info saying “but we recovered” is one Warn. The common form of this is layered: an inner client logs the failure and returns the error, and the caller logs it again. The layer that decides what happens next owns the line; every layer below it returns the error silently. Retry loops log once, at exhaustion — not per attempt.
• No level at all (logger.Log(ctx, slog.LevelXxx, ...)). Use the named methods so the call site is grep-able.

Attribute conventions

• Keys are snake_case (org_id, user_id, run_id, runner_id, request_id). These become metric labels and dashboard filters; mixing orgID in inline slog.String calls breaks query consistency.
• Identifiers always use the resource name (org_id, not id) so a multi-resource line is unambiguous.
• Errors go under the error key ("error", err) — never err, never wrapped into the message string. Log search is field-scoped: a bare phrase matches the message only, so an error parked under the wrong key is invisible to the query that would have found it.
• High-cardinality fields (per-user emails, full URLs with secrets, raw PAT names) do not belong on log lines. They land in audit channels or stay out entirely.

Audit channels

A handful of events go through auditXxxEvent helpers (see internal/backend/services/audit.go). Those write to dedicated channels SIEM consumers can route on (role-audit:, user-audit:, pat-audit:, session-audit:, org-audit:, membership-audit:). The level rule above is independent of audit emission — an audited event still logs at the appropriate level.