Reading the operator's mind from logs and metrics
Follow one poll cycle through the structured log, read the three gauges that describe a group, and work a real incident where the dashboard said writable for two minutes after the site had already been fenced.
By the end of this topic you can
- Follow one poll cycle through the structured log using the documented
msgstrings - Read
bloodraven_site_state,bloodraven_replication_lag_secondsandbloodraven_state_transitions_totaland say what the group is doing - Tell a lagging replica apart from a lagging reader in the same metric
You can run the table in your head and say whether cooldown will let the operator act. What you
cannot do yet is check that answer against the live group. Two surfaces make it possible, and
neither is a dashboard: the structured log, and /metrics on :8080.
The log is an interface
Bloodraven’s operational log is not debug output you grep in a panic. It is a published contract. The msg strings and the field names beside them are versioned in site/content/docs/8.observability/7.log-schema.md, and the stability table there is explicit: msg strings in the Event reference “will not change without a deprecation note in the release notes”, and fields listed alongside a stable msg may gain siblings but will never be renamed or removed silently. Downstream pipelines filter on those exact strings — msg = "initiating failover" is a Loki alert, not a regex guess. Changing one is a breaking change for every consumer you cannot see.
Two things follow. First, there are two JSON streams on stdout and only one is contractual: the operational slog stream carries time, level, msg, and you split it from the controller-runtime zap stream with $.time && $.msg versus $.ts && $.logger. Bloodraven does not redefine the zap stream’s shape, so do not build on it. Second, keys are camelCase, not snake_case — activeSite, promotionGtid, divergentTransactions. That convention is part of the contract too.
The anchor event for this unit is one line:
INFO state transition, with fields site, from, to, fg. The from and to values are the four site states you already know: unknown, unreachable, read-only, writable.
It is mirrored exactly once by the counter bloodraven_state_transitions_total{site, from, to} — same event, same labels, one increment per line. It is deliberately not turned into a Kubernetes Event; the log schema’s correlation table lists the Event column for this row as “(none — too noisy for events)”. Transitions are cheap and frequent. Events are for humans you want to page.
One poll cycle
DEBUG covers per-poll bookkeeping and is off by default, because the operator’s slog handler is set to INFO. So a healthy poll loop is silent. Silence is the steady state, not a broken log shipper. Here is what a benign disturbance looks like — restart the reader pod while the counter keeps writing:
kubectl -n bloodraven-playground logs -l app.kubernetes.io/name=bloodraven -f | jq -c 'select(.fg=="bloodraven-playground/playground")'{"time":"2026-08-12T12:04:12.114Z","level":"WARN","msg":"failed to check replica status","site":"reader","error":"dial tcp 10.43.62.14:3306: connect: connection refused","fg":"bloodraven-playground/playground"}
{"time":"2026-08-12T12:04:16.118Z","level":"INFO","msg":"state transition","site":"reader","from":"read-only","to":"unreachable","fg":"bloodraven-playground/playground"}# the pod is back and answering. What is the next INFO line?{"time":"2026-08-12T12:05:02.340Z","level":"INFO","msg":"state transition","site":"reader","from":"unreachable","to":"read-only","fg":"bloodraven-playground/playground"}Read the first block carefully. The last successful poll was at 12:04:10; the transition lands at 12:04:16, six seconds later — pollInterval 2 s × failureThreshold 3, exactly the sum you computed earlier. The WARN above it is not in the Event reference: ad-hoc retry warnings are best-effort, and the error field is a Go error string passed through verbatim. Useful for forensics, unsafe for alerts.
The line you predicted takes a single poll. There is no six-second wait on the way back and no recoveryThreshold involved, because recoveryThreshold gates only the transition to writable. read-only is entered on one successful poll.
The seven metrics
| Metric | Type | Labels | What it says |
|---|---|---|---|
bloodraven_site_state | gauge (state-set) | site, state | 1 on the current state, 0 on the other three |
bloodraven_replication_lag_seconds | gauge | site | seconds behind source; -1 when lag is NULL |
bloodraven_state_transitions_total | counter | site, from, to | one increment per state transition line |
bloodraven_failovers_total | counter | target_site | promotions completed, by the site promoted |
bloodraven_poll_latency_seconds | histogram | site | per-site probe duration; its _count is the loop’s heartbeat |
bloodraven_divergent_transactions | gauge | site | transactions a site holds that the new primary never saw; 0 when healthy |
bloodraven_primary_reassert_total | counter | site | times the operator restored writability on a primary its own sidecar had fenced |
bloodraven_site_state is a state-set, so you never read one series — you read four and find the 1:
bloodraven_site_statesite="iad"state="writable"-1 is not a small lag
bloodraven_replication_lag_seconds is set only for replicating sites, and the operator writes -1 when Seconds_Behind_Source is NULL — that is, when the site is not replicating at all. This matters more than any threshold you might pick. A reading of 0 means “caught up as far as MySQL can tell”. A reading of -1 means “there is no replication stream here”. A dashboard that renders both as “low lag, everything green” inverts the most important signal on the page. Sort your queries so -1 is never averaged with real seconds.
One more trap: when a site goes unreachable, the operator neither updates nor deletes its lag gauge — the DeleteLabelValues branch in the poll’s metric-emission loop is reached only for a site whose state is writable. The last value it published stays on the series. A lag gauge is fresh only as long as the poll loop is turning.
A lagging replica versus a lagging reader
bloodraven_replication_lag_seconds carries only site. There is no role label, so telling a lagging replica apart from a lagging reader is a join you perform yourself, against the group spec. In playground that join is trivial and worth doing consciously:
pdx (primary-candidate) | reader (read-only) | |
|---|---|---|
Counted in coreCount? | yes | no — excluded from every tally |
| Can it be promoted? | yes | never |
| Lag judged against | maxLagSeconds (30 on playground, 300 shipped) | readOnlyMaxLagSeconds (10 on playground; nil inherits maxLagSeconds) |
| Consequence of breaching it | the group’s ReplicationLagging Degraded condition | the site drops out of the -replicas reader endpoint — and nothing else, because the condition loop skips read-only sites entirely |
readOnlyMaxLagSeconds has no default. When it is nil it inherits maxLagSeconds; but an explicit 0 is meaningful and demands zero reported lag. Setting it to 0 is not “unset” — it is the strictest possible reader gate, and it is one of five conjuncts the reader endpoint requires (converged source, replicating, non-nil lag, canonical direct source host, and lag within the threshold). The asymmetry goes further than the numbers. The loop that raises ReplicationLagging, ReplicationBroken and ReplicationError skips every role: read-only site before it reads a threshold at all, so a reader cannot contribute to the group’s Degraded condition however far behind it gets. On playground — maxLagSeconds: 30, readOnlyMaxLagSeconds: 10 — a reader at 45 s is past both numbers and still changes nothing except its own reader-endpoint membership. A primary-candidate at 45 s does the opposite: it stays in the endpoint, stays promotable, and does put ReplicationLagging on the group.
Forensics: two minutes of confident nonsense
This is a captured case study, not something to reproduce. Issue #93 needs Calico; on k3d with kube-router it is masked, because kube-router flushes conntrack on policy change.
The artefacts. Under a deny-all NetworkPolicy, the operator reports activeSite=iad, the site condition state=writable, and Ready=True — for two full minutes. Meanwhile the sidecar at iad has already self-fenced. On /metrics: bloodraven_site_state{site="iad",state="writable"} is pinned at 1, bloodraven_state_transitions_total is perfectly flat, and rate(bloodraven_poll_latency_seconds_count[1m]) is 0 for every site, not just iad.
Stop and answer before reading on: what broke?
Not MySQL, and not the network detection logic. Poll() froze. A deny-all policy blackholes an established connection, an in-flight read blocks with no response, and database/sql context cancellation does not reliably abort a read already parked on such a socket. Poll waits on every site’s probe before it does anything else — so one frozen probe freezes the entire loop. Every gauge in the table above is written after that wait returns. Nothing transitioned, nothing was re-evaluated, and the operator went on publishing the last state it knew, forever, with full confidence. That is why the tell is poll_latency_seconds_count flatlining across all sites: it is the only series that reports whether the loop is still completing cycles at all. Confidence is not freshness.
The wrong first diagnosis is its own lesson. The maintainers initially blamed conntrack and reached for SetConnMaxLifetime(10s). It could not help: a connection parked in a blocked read is never returned to the pool, so it is never recycled. A pool-level fix cannot reach a connection the pool no longer holds. The real fix was a hard driver-level I/O deadline on the probe path, so a blackholed read always returns and the site trips failureThreshold normally.
Where this leaves you
You can now watch playground decide in real time — the state transition line, the state-set gauges, the transition counter — and, just as importantly, tell a genuine reading from a frozen one. Everything is in place to stop predicting and start measuring. Unit 3 holds a site down for real and puts a clock on the result.
Flashcards
The state transition log event — which four fields does it carry?
site, from, to, fg. from/to are one of unknown, unreachable, read-only, writable.
Why is changing a msg string in Bloodraven a breaking change?
The msg strings in the Event reference are a published stability contract that downstream log pipelines filter on by exact match; they change only with a deprecation note in the release notes.
You see bloodraven_site_state{site="pdx",state="read-only"} 1. What are the other three pdx series doing?
They are all 0. It is a state-set: every poll writes all four states for every site, exactly one of them 1.
bloodraven_replication_lag_seconds{site="pdx"} -1 — what happened?
Seconds_Behind_Source came back NULL, meaning the site is not replicating at all. It is a sentinel, not a lag value.
spec.replication.readOnlyMaxLagSeconds is nil versus explicitly 0 — what is the difference?
Nil inherits maxLagSeconds (default 300). An explicit 0 is meaningful and demands zero reported lag before the reader may serve.
Which metric increments exactly once per state transition log line, with the same labels?
bloodraven_state_transitions_total{site, from, to}.
Which single series tells you whether the operator's poll loop is still completing cycles?
bloodraven_poll_latency_seconds_count — its rate going to zero means no cycle has finished, so every other gauge is stale.
What does bloodraven_primary_reassert_total{site} count?
Times the operator restored writability on the last failover target after finding it fenced with no writable site remaining.
Which label does bloodraven_failovers_total carry?
target_site — the site that was promoted, not the one that died.
Two JSON streams arrive on the operator's stdout. How do you keep only the contractual one?
Keep records with time and msg (operational slog); drop records with ts and logger (controller-runtime zap, not a stable interface).
Quiz
Show answer
Answer: unreachable — the series set to 1 names the current state
bloodraven_site_state is a state-set: every poll writes all four state labels for every site, with 1 on the current state and 0 on the others. You read the set and find the 1 — here, unreachable. "Three zeros means unknown" inverts the encoding: zeros are how a state-set says "not this one", and unknown has its own series which is also 0. There is no separate current series and none is needed — the encoding is unambiguous by construction. And unreachable is one of the four real per-site states (unknown, unreachable, read-only, writable), not a flag layered on top of another state. (objective 11)
bloodraven_site_state is a state-set: every poll writes all four state labels for every site, with 1 on the current state and 0 on the others. You read the set and find the 1 — here, unreachable. "Three zeros means unknown" inverts the encoding: zeros are how a state-set says "not this one", and unknown has its own series which is also 0. There is no separate current series and none is needed — the encoding is unambiguous by construction. And unreachable is one of the four real per-site states (unknown, unreachable, read-only, writable), not a flag layered on top of another state. (objective 11)
Show answer
Answer: False
The reversal: -1 is the worst reading on this gauge, not the best. The operator sets -1 when Seconds_Behind_Source comes back NULL, which means the site is not replicating at all — no stream, no lag to measure. 0 means an active stream reporting itself caught up. Treating them alike, as a naive dashboard or an avg() over the series will, hides a dead replica behind a green tile. (objective 11)
The reversal: -1 is the worst reading on this gauge, not the best. The operator sets -1 when Seconds_Behind_Source comes back NULL, which means the site is not replicating at all — no stream, no lag to measure. 0 means an active stream reporting itself caught up. Treating them alike, as a naive dashboard or an avg() over the series will, hides a dead replica behind a green tile. (objective 11)
Show answer
Answer: reader is dropped from the -replicas reader endpoint; the group's own health is unchanged
The lag gauge carries only a site label, so you must join it against the site's role yourself. reader is role: read-only, so its lag is judged against readOnlyMaxLagSeconds (30), and breaching it costs the site its reader-endpoint eligibility — nothing more. ReplicationLagging is driven by maxLagSeconds against the group's core sites, and 45 is nowhere near 300, so the group's condition is untouched. "Ineligible for promotion" mistakes cause for effect: a read-only site can never be promoted and is excluded from coreCount entirely, whatever its lag. And "nothing changes" is the failure of the join itself — applying the group threshold to a site that has its own. (objective 12)
The lag gauge carries only a site label, so you must join it against the site's role yourself. reader is role: read-only, so its lag is judged against readOnlyMaxLagSeconds (30), and breaching it costs the site its reader-endpoint eligibility — nothing more. ReplicationLagging is driven by maxLagSeconds against the group's core sites, and 45 is nowhere near 300, so the group's condition is untouched. "Ineligible for promotion" mistakes cause for effect: a read-only site can never be promoted and is excluded from coreCount entirely, whatever its lag. And "nothing changes" is the failure of the join itself — applying the group threshold to a site that has its own. (objective 12)
Show answer
Answer: The poll loop is alive and completing cycles, probes are slow, and no site has changed state
A climbing _count is the loop's heartbeat: cycles are finishing, so the readings are current. Rising latency says the probes are slow — worth investigating — and a flat transition counter says nothing has changed state, which for a healthy group is the normal, boring case. The frozen-loop signature is the opposite of what you were given: in issue #93 the _count stopped advancing entirely, for every site, because the operator writes its gauges only after waiting on all probes. A failover would show up as transitions, not their absence. And the state-set gauges are re-emitted every poll cycle, not only on a transition, so a turning loop keeps them fresh. (objectives 10, 11)
A climbing _count is the loop's heartbeat: cycles are finishing, so the readings are current. Rising latency says the probes are slow — worth investigating — and a flat transition counter says nothing has changed state, which for a healthy group is the normal, boring case. The frozen-loop signature is the opposite of what you were given: in issue #93 the _count stopped advancing entirely, for every site, because the operator writes its gauges only after waiting on all probes. A failover would show up as transitions, not their absence. And the state-set gauges are re-emitted every poll cycle, not only on a transition, so a turning loop keeps them fresh. (objectives 10, 11)
Show answer
Answer:
SetConnMaxLifetime only recycles connections the pool holds. The connection in question was parked in a blocked read on a blackholed socket, so it was never returned to the pool and therefore never became eligible for recycling — the setting could not reach it. The real failure was that Poll() waits on every site's probe before doing anything, and database/sql context cancellation does not reliably abort a read already parked on such a socket, so one hung probe froze the whole loop. Since the state-set gauges, the transition counter and the status conditions are all written after that wait returns, the operator kept republishing its last known state with full confidence. The artefact that names it is bloodraven_poll_latency_seconds_count flatlining across every site — no cycle completed — not the site-state gauges, which look perfectly healthy precisely because they are frozen. The fix has to bound the I/O itself so a blackholed read returns and the site trips failureThreshold.
A full-credit answer shows: A strong answer covers: (1) a connection blocked in a read is never returned to the pool, so a max-lifetime setting never applies to it; (2) Poll waits on all sites, so one hung probe freezes the entire loop; (3) a frozen loop republishes stale state with no error signal, which is why the status looked healthy; (4) the diagnostic tell is the poll-latency histogram's _count going flat across all sites rather than any site-state or lag series. Credit partial answers that get (1) and (2). An answer that blames conntrack, MySQL, or the NetworkPolicy evaluation order without reaching the blocked-read/frozen-loop mechanism has missed it.
The discrimination is between a fix aimed at the pool and a failure that lives below the pool. Pool-level knobs — max lifetime, max idle, health checks on checkout — all operate on connections the pool can see; a connection stuck in a read it will never finish is invisible to all of them. Reading the artefacts the same way generalises: the state gauges and conditions tell you what the operator believes, and only the poll-latency _count tells you when it last checked. (objectives 10, 11)
Sample answer
SetConnMaxLifetime only recycles connections the pool holds. The connection in question was parked in a blocked read on a blackholed socket, so it was never returned to the pool and therefore never became eligible for recycling — the setting could not reach it. The real failure was that Poll() waits on every site's probe before doing anything, and database/sql context cancellation does not reliably abort a read already parked on such a socket, so one hung probe froze the whole loop. Since the state-set gauges, the transition counter and the status conditions are all written after that wait returns, the operator kept republishing its last known state with full confidence. The artefact that names it is bloodraven_poll_latency_seconds_count flatlining across every site — no cycle completed — not the site-state gauges, which look perfectly healthy precisely because they are frozen. The fix has to bound the I/O itself so a blackholed read returns and the site trips failureThreshold.
A full-credit answer shows
A strong answer covers: (1) a connection blocked in a read is never returned to the pool, so a max-lifetime setting never applies to it; (2) Poll waits on all sites, so one hung probe freezes the entire loop; (3) a frozen loop republishes stale state with no error signal, which is why the status looked healthy; (4) the diagnostic tell is the poll-latency histogram's _count going flat across all sites rather than any site-state or lag series. Credit partial answers that get (1) and (2). An answer that blames conntrack, MySQL, or the NetworkPolicy evaluation order without reaching the blocked-read/frozen-loop mechanism has missed it.
The discrimination is between a fix aimed at the pool and a failure that lives below the pool. Pool-level knobs — max lifetime, max idle, health checks on checkout — all operate on connections the pool can see; a connection stuck in a read it will never finish is invisible to all of them. Reading the artefacts the same way generalises: the state gauges and conditions tell you what the operator believes, and only the poll-latency _count tells you when it last checked. (objectives 10, 11)