Observability

A broker instance publishes what it is doing through exactly three surfaces: structured logs on stdout, GET /metrics (a small JSON object), and GET /metrics/prometheus (exposition text). They do not overlap by accident: the logs carry rates, latencies and cache sizes that Prometheus does not, and Prometheus carries database-backed cluster totals that the logs do not.

Log verbosity and format

The tracing subscriber is installed as the first statement of main, before configuration is loaded, so even a fatal boot error is a timestamped structured line.

Verbosity resolves in one fixed order: RUST_LOG, then LOG_LEVEL, then info. An empty or whitespace-only value is treated as unset. Both variables accept full EnvFilter syntax, so per-subsystem control works without raising the global level:

LOG_LEVEL=info,queen::pop=debug

An unparseable filter directive does not fail the boot. It silently falls back to info.

QUEEN_LOG_JSON=1 replaces the text formatter with one JSON object per line, with the event’s fields flattened to the top level. That is the mode to use with a log shipper. In text mode ANSI colour is off unconditionally, because these logs are almost always read through a container or journal driver where escape codes are noise.

Every line has the same shape:

<RFC3339 UTC>  <LEVEL>  <target>  <message>  key=value …

The timestamp is generated by the broker, not by the log driver, and the target names the subsystem. These are the targets in the binary:

The effective configuration is logged at boot

After the JWT configuration is validated, the broker emits one boot line per subsystem (config: server, postgres, auth, sync, engine, flow, jobs, file_buffer, security, logging), carrying the value it actually resolved for each knob, with secrets masked. Numeric environment variables are parsed leniently (an unparseable number silently becomes the default), so this block is the only reliable way to confirm what the process understood. Read it before believing a deployment manifest.

The rates block

One task emits one rates line with scope="global" every QUEEN_LOG_RATES_MS (default 10000 ms, floored at 1000). Every value is derived from process state that was already collected, so the block costs nothing per request. Rates are deltas over the elapsed window, not lifetime averages.

Immediately after the global line, up to QUEEN_LOG_TOPN_QUEUES (default 10) queue rates lines follow, one per busiest queue, ranked by push + pop + ack activity and carrying tenant, queue, push_s, pop_s, ack_s, a window-weighted lag_ms and a hot=shown/total counter. A queue with no activity in the window is omitted entirely, so the absence of a queue here means idle, not missing.

The sizes block

The same task emits one sizes line per interval. This is the memory surface: the numbers that tell you whether the broker’s caches are living inside their budgets.

A rising dedup_suppressed is a sizing signal, not a correctness one: deduplication stays exact because the SQL probe is authoritative, but pushes on a suppressed partition pay a full-window database probe instead of a cache hit. The fix is a larger QUEEN_DEDUP_CACHE_MB or fewer hot partitions.

rss_gb and the queen_process_resident_memory_bytes gauge both read /proc/self/statm, so on a non-Linux host they report 0.

Two lines that fire on transition, not on schedule

The reporter also watches two conditions between intervals:

• Entering or leaving spooled mode. When the database goes away, WARN spool announces "entering buffered mode (degraded durability)" and carries the pending count; when it comes back, INFO spool "DB recovered" marks the other edge. These are the most important durability lines the broker emits, and they appear once per transition rather than once per interval.
• Pool saturation. When connections are queueing, WARN pool "connection pool saturated" reports waiting, size and max, at most once per 10 s.

Anti-flood sampling

No line is emitted per message or per request. Every hot-path and background-loop diagnostic goes through one sampling primitive: a wall-clock window gate that admits at most one emit per interval process-wide, chosen by a compare-and-swap so exactly one thread wins. The line it prints carries suppressed=N, the number of occurrences swallowed since the previous emit.

The windows in use are 10 s for hot-path and drain diagnostics (encryption failures, spool open and drain failures, fusion and ack-fusion errors, pool acquisition failures, the periodic fusion and dedup summaries), 30 s for the retention and stats cycle errors, and 60 s for the metrics-collector insert errors and JWKS refresh failures.

Two consequences worth internalising. First, suppressed=0 on a warning means it happened once; a large suppressed means a storm, and the count is the signal. Second, a sustained outage produces roughly one line per window per subsystem, not one per failure. Do not size an alert on log volume.

The panic hook is the counterpart on the other side. Release builds are compiled with panic = "abort", so a panic in any background loop terminates the whole process rather than quietly killing one subsystem. The hook emits ERROR panic with the source location and thread name before the abort, so a crash-looping container always leaves a reason behind.

GET /metrics is JSON, not Prometheus

GET /metrics returns a small JSON object, and scraping it with Prometheus will fail to parse. Its shape is inherited from an older server, and several members are structural placeholders that are always zero: requests.rate, messages.rate, database.waitingRequests, every memory field except rss, and both cpu fields. What is real is uptime, requests.total (push + pop + ack request counts for this process), messages.total, database.poolSize and database.idleConnections, and memory.rss.

Use it for a quick check by hand. Do not build a dashboard on it: pool_waiting is the number you actually want and this endpoint reports it as zero.

GET /metrics/prometheus

The exposition is assembled in one pass: in-process counters and gauges first, then the adaptive concurrency limits, the pool gauges, the maintenance flag and the disk-spool gauges, then one database call whose JSON becomes the queen_cluster_* families, the per-queue minute rates and the dead-letter depths.

Two properties decide how you alert on it:

• The database block is best-effort. If the pool has no connection or the read fails, those families are absent from that scrape and it still returns 200. An alert on the absence of queen_cluster_* detects a database problem; an alert on a non-200 response does not.
• queen_process_* is per-instance and resets on restart. queen_cluster_* is a lifetime total read out of PostgreSQL, identical on every instance. Aggregate it with max, never sum.

Per-queue series are not live counters. Each instance flushes per-queue deltas into minute buckets every METRICS_FLUSH_MS (60 s by default) and the aggregator reads the most recent bucket within a five-minute window, so a value can be one flush interval stale and a queue that goes quiet drops out of the exposition after about five minutes instead of reporting zero. queen_queue_metrics_age_seconds is how you tell “no traffic” from “stale bucket”.

The full family list, label sets and the three families that never carry data live in the Prometheus reference under Reference.

What to alert on

Durability first. These come from gauges that are always present, because they are in-process:

• queen_file_buffer_db_healthy == 0: the broker is spooling pushes to disk. Page on it.
• queen_file_buffer_pending not returning to 0 after the database recovers: the drain is stuck. Check the spool target for permanent drain failures.
• queen_file_buffer_failed > 0: a spool write failed, which means those pushes were reported to the client as failed and are gone. This is the only counter here that represents accepted-then-lost work, and it should be zero forever.
• queen_maintenance_mode_enabled == 1 when nobody enabled it: a peer flipped it, or it survived a restart in queen.system_state.

Then saturation and errors:

• rate(queen_cluster_db_errors_total) above zero. Statement errors, statement timeouts and pool acquisition failures on the data paths all land here, and spooled pushes are counted before being relabelled buffered, so the spool cannot hide them.
• queen_db_pool_idle pinned at 0, corroborated by the pool WARN in the log.
• queen_event_loop_lag_avg_milliseconds, a 100 ms ticker measuring its own overshoot. Sustained growth means the runtime or the host is starved.
• queen_queue_pop_lag_milliseconds{stat="max"} per queue, together with queen_queue_metrics_age_seconds so a stale bucket is not read as recovery.
• rate(queen_cluster_dlq_total) for dead-letter transitions, and queen_dlq_depth (with its per-queue queen_dlq_depth_by_queue) for the standing row count in queen.log_dlq. The depth only falls when someone deletes dead letters, so it is the hygiene signal, and the rate is the incident signal.

Finally, a few log conditions have no metric at all and are worth a log-based rule: target=panic at any level, target=encryption reporting encryption DISABLED (a malformed key means flagged queues store plaintext with only a warning), target=retention "cycle error", and target=shutdown "spool has undrained events at shutdown".

Do not alert on /health returning 503 as a proxy for “the broker is broken” without reading Probes and restarts first. That endpoint does a real database round trip, and treating it as a liveness signal destroys the spool it exists to complement.

Related pages