diff --git a/server/src/crate_server/readiness.gleam b/server/src/crate_server/readiness.gleam index 9482027..0ba6204 100644 --- a/server/src/crate_server/readiness.gleam +++ b/server/src/crate_server/readiness.gleam @@ -17,6 +17,7 @@ import gleam/otp/actor import gleam/result import gleam/string import pog +import wisp const cache_ttl_seconds = 5 @@ -72,6 +73,7 @@ type State { // a late reply from an abandoned attempt out of the current one. in_flight: Option(#(Int, Int)), next_generation: Int, + reported: Readiness, worker_replies: Subject(Msg), ) } @@ -142,6 +144,7 @@ pub fn cached(probe: fn() -> Readiness, now: fn() -> Int) -> Check { last: None, in_flight: None, next_generation: 0, + reported: Unknown(never_probed), worker_replies:, )) |> actor.selecting(selector) @@ -161,6 +164,39 @@ pub fn status(check: Check) -> Readiness { check.run() } +/// The line for a change of reported state, and nothing at all when the state +/// has not moved: this gate is the one path that can take the whole site +/// offline, so its transitions are logged while its probes are not. +pub fn transition_line(from: Readiness, to: Readiness) -> Option(String) { + case from == to { + True -> None + False -> Some("readiness: " <> describe(from) <> " -> " <> describe(to)) + } +} + +fn describe(current: Readiness) -> String { + case current { + Ready -> "ready" + Unknown(reason) -> "unknown (" <> reason <> ")" + Down(reason) -> "down (" <> reason <> ")" + } +} + +// Every answer funnels through here, so a flapping gate logs its transitions +// rather than one line per probe. +fn note(state: State, current: Readiness) -> State { + case transition_line(state.reported, current) { + None -> state + Some(line) -> { + case current { + Ready -> wisp.log_info(line) + Unknown(_) | Down(_) -> wisp.log_warning(line) + } + State(..state, reported: current) + } + } +} + fn handle( state: State, msg: Msg, @@ -171,7 +207,7 @@ fn handle( Probe(reply) -> { let #(current, next) = respond(state, probe, now) process.send(reply, current) - actor.continue(next) + actor.continue(note(next, current)) } ProbeResult(generation, current) -> actor.continue(accept(state, generation, current, now)) diff --git a/server/test/health_test.gleam b/server/test/health_test.gleam index b1c8261..97bb391 100644 --- a/server/test/health_test.gleam +++ b/server/test/health_test.gleam @@ -10,6 +10,7 @@ import crate_server/router import gleam/erlang/process import gleam/http import gleam/list +import gleam/option.{None, Some} import gleam/otp/actor import gleam/result import gleam/string @@ -91,6 +92,23 @@ pub fn readyz_gates_on_the_wired_check_while_healthz_stays_up_test() { assert ready.status == 503 } +// An operator staring at 502s needs to know which of "missing table", "busy +// pool" and "dead database" they are looking at, and needs it once per change +// rather than once per probe. +pub fn readiness_logs_state_changes_and_only_state_changes_test() { + let down = readiness.Down("known_users is missing") + + assert readiness.transition_line(readiness.Ready, readiness.Ready) == None + assert readiness.transition_line(down, down) == None + assert readiness.transition_line(readiness.Ready, down) + == Some("readiness: ready -> down (known_users is missing)") + assert readiness.transition_line( + readiness.Unknown("connection unavailable"), + readiness.Ready, + ) + == Some("readiness: unknown (connection unavailable) -> ready") +} + fn check_of(current: readiness.Readiness) -> readiness.Check { readiness.Check(fn() { current }) }