khive_db/checkpoint.rs
1//! Periodic WAL checkpoint task for the connection pool.
2//!
3//! Issues `PRAGMA wal_checkpoint(PASSIVE)` on every tick — including when the
4//! WAL page count exceeds the high-water mark. Ordinary ticks stay
5//! PASSIVE-only and non-blocking; a rare, separately-gated escalation may
6//! additionally run `PRAGMA wal_checkpoint(TRUNCATE)` under the same writer
7//! guard with a shortened busy timeout — see the ADR-091 Plank 2 doc below
8//! for the escalation's own gating.
9//!
10//! Non-contending design: `checkpoint_once` uses `try_writer_nowait` (zero-wait
11//! `try_lock`) so a tick is skipped immediately when any writer holds the mutex,
12//! rather than blocking for up to `checkout_timeout`. The checkpoint task must
13//! never stall active write traffic — a skipped tick is always preferable.
14//!
15//! Why TRUNCATE is excluded from *every ordinary* tick: TRUNCATE inherits
16//! RESTART semantics — it waits for active readers to release their WAL
17//! snapshots and invokes the busy handler before acquiring the exclusive lock
18//! needed to reset the WAL file. With PoolConfig's 30 s busy_timeout, blindly
19//! running it every tick could sit inside SQLite holding the sole writer
20//! connection for up to 30 s, stalling all normal write traffic. PASSIVE never
21//! waits for readers; it checkpoints as many frames as currently possible and
22//! returns promptly. When WAL pressure is sustained (high_water_pages
23//! exceeded), the task emits a WARNING; once WAL pressure reaches the much
24//! higher `truncate_high_water_pages` mark, the rare Plank 2 escalation below
25//! may additionally attempt a bounded, rate-limited TRUNCATE under a
26//! deliberately shortened busy timeout — replacing what used to be a purely
27//! operator-scheduled manual step.
28//!
29//! Threshold-crossing WARN semantics: both the `warn_pages` and `high_water_pages`
30//! warnings fire at most once per below→above crossing. Skipped ticks (writer
31//! busy) leave the crossing state unchanged so that a skip cannot spuriously
32//! re-arm the rate limit while WAL pressure is still elevated. The ADR-091
33//! Plank 0 open-transaction-registry WARNs (oldest-entry escalation and the
34//! high-water snapshot enumeration) ride the SAME crossing gates — they are
35//! not independently rate-limited, so they never repeat on consecutive ticks
36//! that remain above a threshold. Only the per-tick `debug!` trace of the
37//! oldest open entry fires unconditionally.
38//!
39//! ADR-091 Plank 2: rare TRUNCATE escalation. The periodic tick above stays
40//! PASSIVE-only and non-blocking; on top of it, `checkpoint_once` also
41//! evaluates a much rarer escalation to `PRAGMA wal_checkpoint(TRUNCATE)`
42//! once the WAL has grown past `truncate_high_water_pages` and at least
43//! `truncate_min_interval` has elapsed since the last TRUNCATE *attempt*
44//! (not the last successful reclaim). This is a **single writer checkout per
45//! tick**: PASSIVE and any due TRUNCATE both run under the one guard
46//! `checkpoint_once` already holds — there is never a second concurrent
47//! checkout for TRUNCATE. If the writer mutex is busy, both PASSIVE and any
48//! due TRUNCATE are skipped for that tick, and `last_truncate_attempt` is
49//! left untouched so the next tick where the writer is free is immediately
50//! eligible rather than waiting out the full interval again.
51//! `last_truncate_attempt` only advances on a tick that actually attempted
52//! TRUNCATE (writer held, threshold crossed, interval elapsed) — never on a
53//! skip for any reason (writer busy, below threshold, interval not yet up).
54//! TRUNCATE runs under a temporarily shortened `busy_timeout`
55//! (`truncate_busy_timeout`), restored on the writer connection immediately
56//! after the attempt, win or lose. No transaction is ever killed or aborted
57//! here — the tx_registry is only read for diagnostics (Plank 1 owns
58//! enforcement).
59
60use std::sync::atomic::{AtomicU64, Ordering};
61use std::sync::Arc;
62use std::time::{Duration, Instant};
63
64use crate::pool::{ConnectionPool, WriterGuard};
65
66// ── metrics read-surface (load/perf harness) ─────────────────────────────
67//
68// Process-wide gauges mirroring the fallback-counter pattern in
69// `khive-mcp/src/daemon.rs` (`FALLBACK_*` statics + their `pub(crate)`
70// accessors): the checkpoint task is a single fire-and-forget
71// `tokio::spawn` with no handle retained anywhere the daemon's
72// connection-accept loop can reach, so these are plain module-scoped
73// atomics rather than a struct threaded through every `checkpoint_once`/
74// `maybe_truncate`/`note_truncate_outcome` call site (and, transitively,
75// every existing test call site). Read-only surface: nothing here is ever
76// reset outside `#[cfg(test)]`, and nothing reachable over the daemon wire
77// can reset them either (see `khive_runtime::daemon::DaemonRequestFrame::
78// metrics_only`).
79
80/// Last-observed WAL page count (`query_wal_pages`'s return value on its
81/// most recent call, from either `checkpoint_once` or `maybe_truncate`).
82/// `u64::MAX` is the "never observed" sentinel — no checkpoint tick has run
83/// yet in this process — distinct from a genuine zero-page WAL.
84static LAST_WAL_PAGES: AtomicU64 = AtomicU64::new(u64::MAX);
85
86/// Count of TRUNCATE attempts (`maybe_truncate`'s pragma actually invoked,
87/// win or lose) across this process's lifetime.
88static TRUNCATE_ATTEMPTS: AtomicU64 = AtomicU64::new(0);
89
90/// Current consecutive-failure count, mirrored from the caller-owned
91/// `TruncateState::consecutive_failures` field into a process-readable
92/// gauge every time `note_truncate_outcome` runs.
93static TRUNCATE_CONSECUTIVE_FAILURES: AtomicU64 = AtomicU64::new(0);
94
95/// Count of checkpoint ticks skipped because the writer mutex was already
96/// held (ADR-091 checkpoint-pressure telemetry), across this process's
97/// lifetime. Never reset outside `#[cfg(test)]`.
98static CHECKPOINT_SKIPPED_TICKS: AtomicU64 = AtomicU64::new(0);
99
100/// Current run-length of consecutive skipped ticks. Reset to 0 the next time
101/// a tick is actually observed (writer free), so a sustained skip streak is
102/// visible even between two successful observations.
103static CHECKPOINT_CONSECUTIVE_SKIPS: AtomicU64 = AtomicU64::new(0);
104
105/// WAL page count as of the most recent *observed* tick, snapshotted at the
106/// moment a skip occurs. `u64::MAX` is the "no skip has recorded a snapshot
107/// yet" sentinel, mirroring `LAST_WAL_PAGES`.
108static CHECKPOINT_LAST_SKIP_WAL_PAGES: AtomicU64 = AtomicU64::new(u64::MAX);
109
110/// Last-observed WAL page count, if any checkpoint tick has run yet in this
111/// process. Read surface for the daemon-frame metrics snapshot.
112pub fn last_observed_wal_pages() -> Option<u64> {
113 match LAST_WAL_PAGES.load(Ordering::Relaxed) {
114 u64::MAX => None,
115 pages => Some(pages),
116 }
117}
118
119/// Total WAL TRUNCATE attempts made in this process's lifetime.
120pub fn truncate_attempts() -> u64 {
121 TRUNCATE_ATTEMPTS.load(Ordering::Relaxed)
122}
123
124/// Current consecutive TRUNCATE-attempt failure count.
125pub fn truncate_consecutive_failures() -> u64 {
126 TRUNCATE_CONSECUTIVE_FAILURES.load(Ordering::Relaxed)
127}
128
129/// Total checkpoint ticks skipped (writer busy) in this process's lifetime.
130pub fn checkpoint_skipped_ticks() -> u64 {
131 CHECKPOINT_SKIPPED_TICKS.load(Ordering::Relaxed)
132}
133
134/// Current consecutive-skip run length; 0 once the next tick is observed.
135pub fn checkpoint_consecutive_skips() -> u64 {
136 CHECKPOINT_CONSECUTIVE_SKIPS.load(Ordering::Relaxed)
137}
138
139/// WAL page count last known at the time of the most recent skip, if any
140/// skip has occurred yet in this process.
141pub fn checkpoint_last_skip_wal_pages() -> Option<u64> {
142 match CHECKPOINT_LAST_SKIP_WAL_PAGES.load(Ordering::Relaxed) {
143 u64::MAX => None,
144 pages => Some(pages),
145 }
146}
147
148/// A tick's writer checkout was skipped (mutex busy): bump the lifetime and
149/// consecutive-skip counters and snapshot the last-known WAL pressure so an
150/// operator can see how bad the WAL was heading into the skip streak.
151fn note_checkpoint_skipped() {
152 CHECKPOINT_SKIPPED_TICKS.fetch_add(1, Ordering::Relaxed);
153 CHECKPOINT_CONSECUTIVE_SKIPS.fetch_add(1, Ordering::Relaxed);
154 if let Some(pages) = last_observed_wal_pages() {
155 CHECKPOINT_LAST_SKIP_WAL_PAGES.store(pages, Ordering::Relaxed);
156 }
157}
158
159/// A tick was actually observed (writer free): close out any prior skip
160/// streak. `_wal_pages` is accepted for call-site symmetry with
161/// `note_checkpoint_skipped` and to leave room for a future observed-side
162/// gauge without changing this function's signature again.
163fn note_checkpoint_observed(_wal_pages: u64) {
164 CHECKPOINT_CONSECUTIVE_SKIPS.store(0, Ordering::Relaxed);
165}
166
167/// Reset the checkpoint-pressure atomics between tests. Process-wide gauges
168/// are otherwise shared across every test in this binary; tests that assert
169/// on them must reset first and run under a shared `#[serial(...)]` group.
170#[cfg(test)]
171pub(crate) fn reset_checkpoint_metrics_for_tests() {
172 CHECKPOINT_SKIPPED_TICKS.store(0, Ordering::Relaxed);
173 CHECKPOINT_CONSECUTIVE_SKIPS.store(0, Ordering::Relaxed);
174 CHECKPOINT_LAST_SKIP_WAL_PAGES.store(u64::MAX, Ordering::Relaxed);
175}
176
177/// Outcome of a single checkpoint attempt.
178///
179/// `Skipped` is returned when the writer mutex is already held (the tick is a
180/// no-op). `Observed` carries the WAL page count read during the tick. The
181/// distinction matters for threshold-crossing WARN rate-limiting: a skipped tick
182/// must leave the above/below state unchanged so that a busy tick cannot
183/// spuriously re-arm the rate limit while WAL pressure is still elevated.
184#[derive(Debug, Clone, Copy, PartialEq, Eq)]
185pub enum CheckpointTick {
186 /// The writer mutex was busy; no checkpoint was issued this tick.
187 Skipped,
188 /// A checkpoint was issued; the value is the observed WAL page count.
189 Observed(u64),
190}
191
192/// Default number of consecutive above-`warn_pages` observed ticks required
193/// to escalate from the INFO to the WARN rung of the ADR-091 severity ladder.
194pub const DEFAULT_WARN_SUSTAINED_CYCLES: u8 = 3;
195
196/// Configuration for the WAL checkpoint background task.
197///
198/// All fields default to conservative production values. Override via the
199/// environment variables documented on each field.
200#[derive(Clone, Debug)]
201pub struct CheckpointConfig {
202 /// How often to run a passive checkpoint when there is no active write.
203 ///
204 /// Overridable via `KHIVE_CHECKPOINT_INTERVAL_MS` (milliseconds).
205 /// Default: 500 ms.
206 pub interval: Duration,
207
208 /// WAL page count above which a warning is logged.
209 ///
210 /// Overridable via `KHIVE_WAL_WARN_PAGES`.
211 /// Default: 2000 pages (~8 MB at 4 KiB page size).
212 pub warn_pages: u64,
213
214 /// Number of consecutive observed ticks with `wal_pages >= warn_pages`
215 /// required before the ADR-091 severity ladder escalates from INFO
216 /// (first crossing) to WARN (sustained pressure). Edge-triggered once
217 /// per elevation episode — see [`CheckpointSeverityState`].
218 ///
219 /// Overridable via `KHIVE_WAL_WARN_SUSTAINED_CYCLES`.
220 /// Default: 3 cycles.
221 pub warn_sustained_cycles: u8,
222
223 /// WAL page count above which a high-pressure WARNING is logged.
224 ///
225 /// The periodic task always runs PASSIVE regardless; this threshold signals
226 /// that a long-lived reader may be pinning an old WAL snapshot that PASSIVE
227 /// cannot reclaim. An operator can then schedule a blocking TRUNCATE at a
228 /// safe moment outside normal write traffic.
229 ///
230 /// Overridable via `KHIVE_WAL_HIGH_WATER_PAGES`.
231 /// Default: 6000 pages (~24 MB at 4 KiB page size).
232 pub high_water_pages: u64,
233
234 /// WAL page count above which a TRUNCATE escalation attempt is armed
235 /// (ADR-091 Plank 2).
236 ///
237 /// This is a separate, much higher threshold than `high_water_pages`:
238 /// crossing it does not itself attempt TRUNCATE — it only arms the
239 /// attempt, which additionally requires `truncate_min_interval` to have
240 /// elapsed since the last attempt.
241 ///
242 /// Overridable via `KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES`.
243 /// Default: 20000 pages.
244 pub truncate_high_water_pages: u64,
245
246 /// Minimum spacing between TRUNCATE *attempts* (not successes).
247 ///
248 /// A skipped tick (writer busy, below threshold, or interval not yet
249 /// elapsed) never advances the "last attempt" clock, so the next tick
250 /// where the writer is free and the threshold is still crossed is
251 /// immediately eligible rather than waiting out the full interval again.
252 ///
253 /// Overridable via `KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS`.
254 /// Default: 300 seconds (5 minutes).
255 pub truncate_min_interval: Duration,
256
257 /// Temporary `busy_timeout` used only for the duration of a TRUNCATE
258 /// attempt, restored to the pool's configured busy timeout immediately
259 /// after the attempt completes (win or lose).
260 ///
261 /// Overridable via `KHIVE_WAL_TRUNCATE_BUSY_MS`.
262 /// Default: 2000 ms.
263 pub truncate_busy_timeout: Duration,
264}
265
266impl Default for CheckpointConfig {
267 fn default() -> Self {
268 Self {
269 interval: Duration::from_millis(500),
270 warn_pages: 2000,
271 warn_sustained_cycles: DEFAULT_WARN_SUSTAINED_CYCLES,
272 high_water_pages: 6000,
273 truncate_high_water_pages: 20_000,
274 truncate_min_interval: Duration::from_secs(300),
275 truncate_busy_timeout: Duration::from_millis(2000),
276 }
277 }
278}
279
280impl CheckpointConfig {
281 /// Build a `CheckpointConfig` from the environment.
282 ///
283 /// Unset or unparseable variables fall back to the compiled-in defaults.
284 pub fn from_env() -> Self {
285 let mut cfg = Self::default();
286
287 if let Ok(ms) = std::env::var("KHIVE_CHECKPOINT_INTERVAL_MS") {
288 if let Ok(v) = ms.parse::<u64>() {
289 if v > 0 {
290 cfg.interval = Duration::from_millis(v);
291 }
292 }
293 }
294
295 if let Ok(v) = std::env::var("KHIVE_WAL_WARN_PAGES") {
296 if let Ok(n) = v.parse::<u64>() {
297 if n > 0 {
298 cfg.warn_pages = n;
299 }
300 }
301 }
302
303 if let Ok(v) = std::env::var("KHIVE_WAL_WARN_SUSTAINED_CYCLES") {
304 if let Ok(n) = v.parse::<u8>() {
305 if n > 0 {
306 cfg.warn_sustained_cycles = n;
307 }
308 }
309 }
310
311 if let Ok(v) = std::env::var("KHIVE_WAL_HIGH_WATER_PAGES") {
312 if let Ok(n) = v.parse::<u64>() {
313 if n > 0 {
314 cfg.high_water_pages = n;
315 }
316 }
317 }
318
319 if let Ok(v) = std::env::var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES") {
320 if let Ok(n) = v.parse::<u64>() {
321 if n > 0 {
322 cfg.truncate_high_water_pages = n;
323 }
324 }
325 }
326
327 if let Ok(v) = std::env::var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS") {
328 if let Ok(n) = v.parse::<u64>() {
329 if n > 0 {
330 cfg.truncate_min_interval = Duration::from_secs(n);
331 }
332 }
333 }
334
335 if let Ok(v) = std::env::var("KHIVE_WAL_TRUNCATE_BUSY_MS") {
336 if let Ok(n) = v.parse::<u64>() {
337 if n > 0 {
338 cfg.truncate_busy_timeout = Duration::from_millis(n);
339 }
340 }
341 }
342
343 cfg
344 }
345}
346
347/// Mutable escalation state carried across ticks by the caller (ADR-091 Plank 2).
348///
349/// Kept separate from [`CheckpointConfig`] because it is *state*, not
350/// configuration: `last_attempt` and `consecutive_failures` mutate every tick,
351/// while `CheckpointConfig` is parsed once and held immutable for the life of
352/// the task.
353#[derive(Debug, Default)]
354pub struct TruncateState {
355 /// When the last TRUNCATE *attempt* ran (armed + writer held), regardless
356 /// of whether it succeeded in reclaiming pages. `None` means no attempt
357 /// has ever run, so the first armed tick is immediately eligible.
358 last_attempt: Option<Instant>,
359 /// Count of consecutive TRUNCATE attempts that failed to bring `wal_pages`
360 /// back below `warn_pages`. Resets to 0 the first time an attempt clears
361 /// `warn_pages`; used to fire a one-shot escalated WARN at exactly 3
362 /// consecutive failures (does not repeat every subsequent attempt).
363 consecutive_failures: u32,
364}
365
366/// ADR-091 graduated severity rung for sustained WAL pressure.
367///
368/// `Alarm` is never produced by [`CheckpointSeverityState::observe_wal_pages`]
369/// — it labels the existing TRUNCATE-escalation tier (`maybe_truncate`),
370/// which is gated on its own threshold/interval state, not on this ladder.
371/// It exists here so callers and tests can name all three rungs uniformly.
372#[derive(Debug, Clone, Copy, PartialEq, Eq)]
373pub enum CheckpointSeverityRung {
374 /// First observed tick crossing `warn_pages` after a below-warn tick.
375 Info,
376 /// `warn_sustained_cycles` consecutive observed ticks at/above
377 /// `warn_pages`; edge-triggered once per elevation episode.
378 Warn,
379 /// The TRUNCATE-escalation tier (`checkpoint_high_water_pages` and
380 /// above); never emitted by `observe_wal_pages`.
381 Alarm,
382}
383
384/// ADR-091 severity ladder state, carried across ticks by the caller
385/// alongside [`TruncateState`]. Pure state machine: no I/O, no logging —
386/// callers turn the returned emissions into `tracing` calls.
387#[derive(Debug, Default, Clone)]
388pub struct CheckpointSeverityState {
389 /// Whether the previous observed tick was at/above `warn_pages`. Drives
390 /// the below→above edge that fires INFO.
391 was_above_warn: bool,
392 /// Run-length of consecutive observed ticks at/above `warn_pages` in the
393 /// current elevation episode. Resets to 0 on any below-warn tick.
394 consecutive_above_warn: u8,
395 /// Whether WARN has already fired for the current elevation episode, so
396 /// sustained pressure logs WARN once per episode, not once per tick past
397 /// the threshold.
398 warn_emitted_for_episode: bool,
399}
400
401/// One severity-ladder emission produced by a single
402/// [`CheckpointSeverityState::observe_wal_pages`] call.
403#[derive(Debug, Clone, Copy, PartialEq, Eq)]
404pub struct CheckpointSeverityEmission {
405 /// Which rung this emission represents (`Info` or `Warn`; see
406 /// [`CheckpointSeverityRung::Alarm`] doc for why `Alarm` never appears
407 /// here).
408 pub rung: CheckpointSeverityRung,
409 /// The WAL page count observed on the tick that produced this emission.
410 pub wal_pages: u64,
411 /// The `warn_pages` threshold in effect for this tick.
412 pub threshold_pages: u64,
413 /// Consecutive above-warn cycle count as of this tick (1 on the INFO
414 /// edge, `warn_sustained_cycles` on the WARN edge).
415 pub consecutive_cycles: u8,
416}
417
418impl CheckpointSeverityState {
419 /// Advance the severity ladder by one observed tick and return every
420 /// rung crossed on this tick (zero, one, or two emissions: a fresh
421 /// elevation episode can produce INFO and, if `warn_sustained_cycles`
422 /// is 1, WARN on the very same tick).
423 ///
424 /// A below-warn tick resets both the consecutive-cycle counter and the
425 /// per-episode WARN latch, re-arming INFO/WARN for a later episode.
426 /// Skipped ticks must not be passed here at all — the caller only calls
427 /// this on `CheckpointTick::Observed`, matching the existing
428 /// threshold-crossing WARN's skip-leaves-state-unchanged rule.
429 pub fn observe_wal_pages(
430 &mut self,
431 wal_pages: u64,
432 config: &CheckpointConfig,
433 ) -> Vec<CheckpointSeverityEmission> {
434 let mut emissions = Vec::new();
435 let above_warn = wal_pages >= config.warn_pages;
436
437 if above_warn {
438 self.consecutive_above_warn = self.consecutive_above_warn.saturating_add(1);
439
440 if !self.was_above_warn {
441 emissions.push(CheckpointSeverityEmission {
442 rung: CheckpointSeverityRung::Info,
443 wal_pages,
444 threshold_pages: config.warn_pages,
445 consecutive_cycles: self.consecutive_above_warn,
446 });
447 }
448
449 if !self.warn_emitted_for_episode
450 && self.consecutive_above_warn >= config.warn_sustained_cycles
451 {
452 emissions.push(CheckpointSeverityEmission {
453 rung: CheckpointSeverityRung::Warn,
454 wal_pages,
455 threshold_pages: config.warn_pages,
456 consecutive_cycles: self.consecutive_above_warn,
457 });
458 self.warn_emitted_for_episode = true;
459 }
460 } else {
461 self.consecutive_above_warn = 0;
462 self.warn_emitted_for_episode = false;
463 }
464
465 self.was_above_warn = above_warn;
466 emissions
467 }
468}
469
470/// Run the WAL checkpoint background task.
471///
472/// This is a long-running async task that should be spawned with
473/// `tokio::spawn`. It loops until `shutdown_rx` observes a change (or its
474/// sender is dropped), at which point it exits on its next `select!` wakeup.
475/// Callers should hold the paired `tokio::sync::watch::Sender` for the
476/// daemon's run scope and send on it as part of the shutdown sequence.
477///
478/// An earlier version of this task used `Arc::strong_count(&pool) <= 1` as
479/// its exit condition instead of an explicit signal. That check is
480/// unreachable whenever a sibling owner holds its own clone of `pool` for
481/// the task's lifetime — which the production boot path does: `event_store`
482/// (`Option<Arc<dyn EventStore>>`), when `Some`, is a `SqlEventStore` that
483/// retains its own `Arc::clone` of the same pool, so the task always
484/// observed `strong_count == 2` and never exited via that mechanism
485/// (issue #774). The explicit watch channel does not depend on how many
486/// other owners exist.
487///
488/// The task issues `PRAGMA wal_checkpoint(PASSIVE)` on every tick — ordinary
489/// ticks stay PASSIVE-only and non-blocking; see the module-level doc for the
490/// rare Plank 2 TRUNCATE escalation `checkpoint_once` may additionally run
491/// under the same writer guard when WAL pressure is sustained past
492/// `truncate_high_water_pages`. A WARNING is emitted once on threshold
493/// crossing (wal_pages transitions from below a threshold to at/above) rather
494/// than on every tick, preventing log spam when a long-lived reader pins a
495/// WAL snapshot.
496///
497/// Skipped ticks (writer mutex busy) leave both crossing-state flags unchanged
498/// so that a skip cannot spuriously re-arm the rate limit while WAL pressure is
499/// still elevated.
500///
501/// Uses `try_writer_nowait` (zero-wait try-lock) so a busy writer causes the
502/// current tick to be skipped rather than stalling write traffic.
503///
504/// `event_store` (ADR-094): when `Some`, this task appends a best-effort
505/// `CheckpointOutcomeRecorded` lifecycle event on every tick where WAL
506/// pressure is at/above `warn_pages`, plus exactly one drain row on the tick
507/// that observes pressure fall back below `warn_pages` after an elevated
508/// episode — never on every ordinary below-warn tick. `namespace` is
509/// stamped on those rows. `None` makes event emission a pure no-op, exactly
510/// like an unconfigured audit sink elsewhere in the runtime.
511pub async fn run_checkpoint_task(
512 pool: Arc<ConnectionPool>,
513 config: CheckpointConfig,
514 event_store: Option<Arc<dyn khive_storage::EventStore>>,
515 namespace: String,
516 mut shutdown_rx: tokio::sync::watch::Receiver<()>,
517) {
518 let mut interval = tokio::time::interval(config.interval);
519 interval.set_missed_tick_behavior(tokio::time::MissedTickBehavior::Skip);
520 let mut severity_state = CheckpointSeverityState::default();
521 let mut was_above_high_water = false;
522 let mut truncate_state = TruncateState::default();
523 // Independent of `severity_state` (which owns the WARN-episode ladder
524 // internally): this tracks only the "was the previous observed tick
525 // elevated" edge the ADR-094 event emission needs, so the event path
526 // never has to reach into the severity state machine's private fields.
527 let mut event_was_elevated = false;
528
529 loop {
530 // A closed sender (the daemon returning without an explicit send)
531 // makes `changed()` resolve with `Err` immediately, which `select!`
532 // treats as ready — so shutdown is observed either way, not just on
533 // an explicit send.
534 tokio::select! {
535 _ = interval.tick() => {}
536 _ = shutdown_rx.changed() => break,
537 }
538
539 let tick = checkpoint_once(&pool, &config, &mut truncate_state);
540 // Skipped ticks leave crossing state unchanged — a busy tick must not
541 // re-arm the rate limit while WAL pressure is still elevated.
542 let wal_pages = match tick {
543 CheckpointTick::Skipped => continue,
544 CheckpointTick::Observed(n) => n,
545 };
546
547 let above_warn = wal_pages >= config.warn_pages;
548 let above_high_water = wal_pages >= config.high_water_pages;
549 let above_truncate_high_water = wal_pages >= config.truncate_high_water_pages;
550
551 // Per-tick debug for the oldest open entry always fires (cheap, single
552 // `oldest()` lookup); the two `warn!`-level registry logs below are
553 // gated on the SAME crossing state as the WAL-threshold WARNs above,
554 // so sustained pressure logs once per crossing, not once per tick.
555 log_tx_registry_oldest_debug(wal_pages);
556
557 // ADR-091 severity ladder: INFO on the first below→above crossing,
558 // WARN once `warn_sustained_cycles` consecutive ticks stay elevated.
559 // The oldest-entry registry WARN rides the same INFO edge the old
560 // binary crossing_warn used to gate on.
561 for emission in severity_state.observe_wal_pages(wal_pages, &config) {
562 match emission.rung {
563 CheckpointSeverityRung::Info => {
564 log_tx_registry_oldest_warn(wal_pages);
565 tracing::info!(
566 wal_pages = emission.wal_pages,
567 warn_threshold = emission.threshold_pages,
568 "WAL page count crossed warn threshold"
569 );
570 }
571 CheckpointSeverityRung::Warn => {
572 tracing::warn!(
573 wal_pages = emission.wal_pages,
574 warn_threshold = emission.threshold_pages,
575 consecutive_cycles = emission.consecutive_cycles,
576 "WAL page count failed to drain below warn threshold"
577 );
578 }
579 CheckpointSeverityRung::Alarm => {
580 // Never produced by `observe_wal_pages`; see its doc.
581 }
582 }
583 }
584
585 let high_water_crossed = crossing_warn(above_high_water, &mut was_above_high_water);
586 if high_water_crossed {
587 log_tx_registry_snapshot_warn(wal_pages);
588 tracing::warn!(
589 wal_pages,
590 high_water = config.high_water_pages,
591 "WAL high-water mark exceeded; sustained WAL pressure — \
592 a long-lived reader may be pinning an old snapshot that PASSIVE cannot reclaim"
593 );
594 }
595
596 // ADR-094: emit every elevated tick, plus exactly one drain row on
597 // the tick that observes the episode end — never on every ordinary
598 // below-warn tick.
599 if checkpoint_outcome_should_emit(above_warn, event_was_elevated) {
600 let payload = khive_storage::CheckpointOutcomeRecordedPayload {
601 wal_pages,
602 warn_pages: config.warn_pages,
603 high_water_pages: config.high_water_pages,
604 truncate_high_water_pages: config.truncate_high_water_pages,
605 above_warn,
606 above_high_water,
607 above_truncate_high_water,
608 };
609 append_checkpoint_lifecycle_event(
610 event_store.as_ref(),
611 &namespace,
612 khive_types::EventKind::CheckpointOutcomeRecorded,
613 payload,
614 )
615 .await;
616 }
617 event_was_elevated = above_warn;
618 }
619}
620
621/// Whether a `CheckpointOutcomeRecorded` event should be emitted for this
622/// tick: every elevated (`above_warn`) tick, plus exactly one drain row on
623/// the first tick that observes a return to below-warn after an elevated
624/// episode (`was_elevated`). An ordinary below-warn tick following another
625/// below-warn tick emits nothing.
626fn checkpoint_outcome_should_emit(above_warn: bool, was_elevated: bool) -> bool {
627 above_warn || was_elevated
628}
629
630/// Append one ADR-094 lifecycle event on behalf of the checkpoint task.
631///
632/// Best-effort: `event_store == None` is a no-op, and an append failure is
633/// logged and swallowed. No lifecycle-append error may ever interrupt or
634/// slow down checkpoint/TRUNCATE work — the checkpoint task's correctness
635/// does not depend on this succeeding.
636async fn append_checkpoint_lifecycle_event<P: serde::Serialize>(
637 store: Option<&Arc<dyn khive_storage::EventStore>>,
638 namespace: &str,
639 kind: khive_types::EventKind,
640 payload: P,
641) {
642 let Some(store) = store else {
643 return;
644 };
645 let payload_value = match serde_json::to_value(&payload) {
646 Ok(v) => v,
647 Err(e) => {
648 tracing::warn!(
649 error = %e,
650 event_kind = %kind.name(),
651 "failed to serialize checkpoint lifecycle event payload"
652 );
653 return;
654 }
655 };
656 let event = khive_storage::Event::new(
657 namespace,
658 "checkpoint.lifecycle",
659 kind,
660 khive_types::SubstrateKind::Event,
661 "daemon:checkpoint_task",
662 )
663 .with_payload(payload_value);
664 if let Err(err) = store.append_event(event).await {
665 tracing::warn!(
666 error = %err,
667 event_kind = %kind.name(),
668 "checkpoint lifecycle event append failed"
669 );
670 }
671}
672
673/// ADR-091 Plank 0: log the oldest open transaction registry entry alongside
674/// the WAL frame count at `debug!`, on EVERY tick regardless of threshold
675/// state. This is the low-volume per-tick trace; the WARN-level escalations
676/// live in [`log_tx_registry_oldest_warn`] and
677/// [`log_tx_registry_snapshot_warn`], both of which are gated on threshold
678/// *crossing* by the caller (`run_checkpoint_task`) so they fire once per
679/// crossing rather than once per tick. Observe only: this never enforces or
680/// force-closes anything.
681fn log_tx_registry_oldest_debug(wal_pages: u64) {
682 if let Some((age, label)) = khive_storage::tx_registry::oldest() {
683 tracing::debug!(
684 wal_pages,
685 oldest_tx_age_secs = age.as_secs_f64(),
686 oldest_tx_label = label.as_deref().unwrap_or("<unlabeled>"),
687 "WAL checkpoint tick: oldest open transaction registry entry"
688 );
689 }
690}
691
692/// ADR-091 Plank 0: escalate the oldest open registry entry to `warn!`.
693///
694/// Callers MUST gate this on a below→above `warn_pages` crossing (via
695/// `crossing_warn`) — it is not rate-limited internally, so calling it every
696/// tick would reproduce the log-spam bug this rewrite fixes.
697fn log_tx_registry_oldest_warn(wal_pages: u64) {
698 if let Some((age, label)) = khive_storage::tx_registry::oldest() {
699 tracing::warn!(
700 wal_pages,
701 oldest_tx_age_secs = age.as_secs_f64(),
702 oldest_tx_label = label.as_deref().unwrap_or("<unlabeled>"),
703 "WAL checkpoint tick: oldest open transaction registry entry"
704 );
705 }
706}
707
708/// ADR-091 Plank 0: enumerate every open registry entry at `warn!` — the
709/// "which caller is holding the pin" answer this ADR's static reading could
710/// not produce.
711///
712/// Callers MUST gate this on a below→above `high_water_pages` crossing (via
713/// `crossing_warn`) — it is not rate-limited internally, so calling it every
714/// tick would repeat the full snapshot enumeration every tick under
715/// sustained pressure.
716fn log_tx_registry_snapshot_warn(wal_pages: u64) {
717 for (age, label) in khive_storage::tx_registry::snapshot() {
718 tracing::warn!(
719 wal_pages,
720 tx_age_secs = age.as_secs_f64(),
721 tx_label = label.as_deref().unwrap_or("<unlabeled>"),
722 "WAL high-water: open transaction registry entry"
723 );
724 }
725}
726
727/// Issue one checkpoint cycle against the writer connection.
728///
729/// Returns [`CheckpointTick::Skipped`] when the writer mutex is already held
730/// (the tick is a no-op) and [`CheckpointTick::Observed`] with the WAL page
731/// count otherwise. All checkpoint errors are logged at warn level and treated
732/// as non-fatal; the next tick retries.
733///
734/// Uses `try_writer_nowait` so that a busy active writer causes this tick to
735/// be skipped immediately rather than stalling for up to `checkout_timeout`.
736/// The caller (`run_checkpoint_task`) owns all threshold-crossing WARN logging
737/// so that warnings fire at most once per crossing, not every tick.
738///
739/// ADR-091 Plank 2: after the PASSIVE pass, this is also the single point
740/// that may escalate to TRUNCATE (`maybe_truncate`) — under the SAME writer
741/// guard acquired above, never a second checkout. A busy writer (`Skipped`)
742/// short-circuits before either PASSIVE or TRUNCATE run.
743pub fn checkpoint_once(
744 pool: &ConnectionPool,
745 config: &CheckpointConfig,
746 truncate_state: &mut TruncateState,
747) -> CheckpointTick {
748 let writer = match pool.try_writer_nowait() {
749 Ok(w) => w,
750 Err(_) => {
751 note_checkpoint_skipped();
752 return CheckpointTick::Skipped;
753 }
754 };
755
756 let wal_pages = query_wal_pages(writer.conn());
757
758 if let Err(e) = writer
759 .conn()
760 .execute_batch("PRAGMA wal_checkpoint(PASSIVE)")
761 {
762 tracing::warn!(error = %e, "WAL checkpoint failed");
763 } else {
764 tracing::debug!(wal_pages, "WAL checkpoint issued");
765 }
766
767 maybe_truncate(pool, &writer, config, wal_pages, truncate_state);
768
769 CheckpointTick::Observed(wal_pages)
770}
771
772/// ADR-091 Plank 2: evaluate and, if due, attempt a TRUNCATE escalation.
773///
774/// Runs under the writer guard the caller already holds — never performs its
775/// own checkout. Returns immediately (a no-op) unless BOTH:
776/// - `wal_pages >= config.truncate_high_water_pages`, and
777/// - no prior attempt (`truncate_state.last_attempt.is_none()`) OR at least
778/// `config.truncate_min_interval` has elapsed since the last attempt.
779///
780/// `truncate_state.last_attempt` is stamped ONLY immediately before the
781/// TRUNCATE pragma itself runs (writer held, threshold crossed, interval
782/// elapsed, AND the temporary busy_timeout override successfully applied) —
783/// every earlier return (below threshold, interval not elapsed, or the
784/// busy_timeout override failing to apply) is a skip, not an attempt, and
785/// never touches it, matching the ADR's "skip must not stamp" requirement.
786///
787/// The oldest-pinning-transaction snapshot is logged (reusing Plank 0's
788/// `tx_registry`) before the attempt, so an operator can see what is
789/// (potentially) pinning the WAL even if the attempt goes on to succeed.
790/// `busy_timeout` is temporarily lowered to `config.truncate_busy_timeout` for
791/// the PRAGMA call and restored to the pool's configured value immediately
792/// after, regardless of outcome. No transaction is ever killed here — this is
793/// read-only diagnostics plus the TRUNCATE pragma itself; enforcement is
794/// Plank 1's job, not this one's.
795fn maybe_truncate(
796 pool: &ConnectionPool,
797 writer: &WriterGuard<'_>,
798 config: &CheckpointConfig,
799 wal_pages_before: u64,
800 truncate_state: &mut TruncateState,
801) {
802 if wal_pages_before < config.truncate_high_water_pages {
803 return;
804 }
805
806 if let Some(last) = truncate_state.last_attempt {
807 if last.elapsed() < config.truncate_min_interval {
808 return;
809 }
810 }
811
812 // Which caller (if any) is pinning the WAL — logged before the attempt so
813 // it is available even if the attempt itself succeeds.
814 log_tx_registry_snapshot_warn(wal_pages_before);
815
816 let conn = writer.conn();
817 let original_busy_timeout = pool.config().busy_timeout;
818
819 if let Err(e) = conn.busy_timeout(config.truncate_busy_timeout) {
820 // Setup failed before the TRUNCATE pragma ever ran — this is a skip,
821 // not an attempt. `last_attempt` must NOT advance here (ADR-091
822 // §377-382): stamping now would suppress the next eligible attempt
823 // for the full `truncate_min_interval` on a path that never touched
824 // the WAL at all.
825 tracing::warn!(error = %e, "failed to lower busy_timeout for TRUNCATE attempt; skipping");
826 return;
827 }
828
829 // Only now is this a genuine attempt: the writer is held, the threshold
830 // and interval gates passed, and the busy_timeout override is in effect
831 // immediately before the TRUNCATE pragma itself.
832 truncate_state.last_attempt = Some(Instant::now());
833
834 let start = Instant::now();
835 let outcome = conn.execute_batch("PRAGMA wal_checkpoint(TRUNCATE)");
836 let elapsed = start.elapsed();
837
838 // Restore the pool's configured busy_timeout immediately after the
839 // attempt, win or lose, before any other logging or bookkeeping.
840 if let Err(e) = conn.busy_timeout(original_busy_timeout) {
841 tracing::warn!(error = %e, "failed to restore busy_timeout after TRUNCATE attempt");
842 }
843
844 match outcome {
845 Ok(()) => {
846 let wal_pages_after = query_wal_pages(conn);
847 tracing::info!(
848 wal_pages_before,
849 wal_pages_after,
850 elapsed_ms = elapsed.as_millis() as u64,
851 "WAL TRUNCATE checkpoint attempted"
852 );
853
854 let made_progress = wal_pages_after < wal_pages_before;
855 if !made_progress {
856 tracing::warn!(
857 wal_pages_before,
858 wal_pages_after,
859 "WAL TRUNCATE attempt made no progress; \
860 a long-lived reader may still be pinning the WAL snapshot"
861 );
862 log_tx_registry_snapshot_warn(wal_pages_after);
863 }
864
865 note_truncate_outcome(config, wal_pages_after, truncate_state);
866 }
867 Err(e) => {
868 tracing::warn!(error = %e, wal_pages_before, "WAL TRUNCATE attempt failed");
869 log_tx_registry_snapshot_warn(wal_pages_before);
870 note_truncate_outcome(config, wal_pages_before, truncate_state);
871 }
872 }
873}
874
875/// ADR-091 Plank 2: track consecutive TRUNCATE attempts that fail to bring
876/// `wal_pages` back below `warn_pages`, firing a one-shot escalated WARN at
877/// exactly the third consecutive failure (does not repeat every attempt
878/// thereafter — mirrors the crossing-WARN debounce used elsewhere in this
879/// module). A single attempt that clears `warn_pages` resets the counter.
880fn note_truncate_outcome(
881 config: &CheckpointConfig,
882 wal_pages_after: u64,
883 state: &mut TruncateState,
884) {
885 // Metrics read-surface (load/perf harness): this function runs exactly
886 // once per genuine TRUNCATE attempt (both the `Ok` and `Err` outcome
887 // arms in `maybe_truncate` call it once each), so incrementing here
888 // counts total attempts without a separate call site.
889 TRUNCATE_ATTEMPTS.fetch_add(1, Ordering::Relaxed);
890
891 if wal_pages_after >= config.warn_pages {
892 state.consecutive_failures = state.consecutive_failures.saturating_add(1);
893 if state.consecutive_failures == 3 {
894 tracing::warn!(
895 wal_pages_after,
896 warn_threshold = config.warn_pages,
897 "WAL TRUNCATE has failed to clear WAL pressure for 3 consecutive attempts"
898 );
899 }
900 } else {
901 state.consecutive_failures = 0;
902 }
903
904 TRUNCATE_CONSECUTIVE_FAILURES.store(state.consecutive_failures as u64, Ordering::Relaxed);
905}
906
907/// Evaluate whether a threshold-crossing WARN should fire and advance the
908/// crossing-state flag.
909///
910/// Returns `true` on a false→true transition in `now_above` (first observed
911/// above-threshold tick after a below-threshold tick), `false` on any other
912/// tick. The `was_above` flag is updated in-place to track state across calls.
913/// Used by `run_checkpoint_task` for both the `warn_pages` band and the
914/// `high_water_pages` threshold.
915fn crossing_warn(now_above: bool, was_above: &mut bool) -> bool {
916 let fire = now_above && !*was_above;
917 *was_above = now_above;
918 fire
919}
920
921/// Query the current WAL frame count via `PRAGMA wal_checkpoint`.
922///
923/// The pragma returns a 3-column row `(busy, log, checkpointed)`, where `log`
924/// (column index 1) is the number of frames currently in the WAL file — the
925/// backlog the high-water threshold keys off. (Column 2 is `checkpointed`, the
926/// frames moved *by this call*, which is not the WAL size.) The no-arg pragma
927/// also performs a PASSIVE checkpoint as a side effect; the subsequent explicit
928/// `PRAGMA wal_checkpoint(PASSIVE)` in `checkpoint_once` is a deliberate second
929/// pass that can checkpoint any frames written between the two calls.
930///
931/// Returns 0 on any error (e.g. in-memory DB where WAL is not active, which
932/// reports `log = -1`).
933fn query_wal_pages(conn: &rusqlite::Connection) -> u64 {
934 let pages = conn
935 .query_row("PRAGMA wal_checkpoint", [], |row| row.get::<_, i64>(1))
936 .unwrap_or(0)
937 .max(0) as u64;
938 // Metrics read-surface (load/perf harness): mirror every observation into
939 // the process-wide gauge, regardless of which caller (`checkpoint_once`
940 // or `maybe_truncate`) triggered it.
941 LAST_WAL_PAGES.store(pages, Ordering::Relaxed);
942 note_checkpoint_observed(pages);
943 pages
944}
945
946#[cfg(test)]
947mod tests {
948 use super::*;
949 use crate::pool::PoolConfig;
950 use serial_test::serial;
951 use tracing::field::{Field, Visit};
952
953 #[derive(Clone, Debug, Default)]
954 struct CapturedEvent {
955 message: Option<String>,
956 oldest_tx_label: Option<String>,
957 tx_label: Option<String>,
958 }
959
960 #[derive(Default)]
961 struct CapturedEventVisitor(CapturedEvent);
962
963 impl Visit for CapturedEventVisitor {
964 fn record_str(&mut self, field: &Field, value: &str) {
965 match field.name() {
966 "message" => self.0.message = Some(value.to_string()),
967 "oldest_tx_label" => self.0.oldest_tx_label = Some(value.to_string()),
968 "tx_label" => self.0.tx_label = Some(value.to_string()),
969 _ => {}
970 }
971 }
972
973 fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
974 let formatted = format!("{value:?}");
975 let cleaned = formatted
976 .trim_start_matches('"')
977 .trim_end_matches('"')
978 .to_string();
979 match field.name() {
980 "message" => self.0.message = Some(cleaned),
981 "oldest_tx_label" => self.0.oldest_tx_label = Some(cleaned),
982 "tx_label" => self.0.tx_label = Some(cleaned),
983 _ => {}
984 }
985 }
986 }
987
988 /// Minimal `tracing::Subscriber` that captures events into a thread-local
989 /// vec, installed as the thread-local default for the duration of one
990 /// test closure via `tracing::subscriber::with_default`. Mirrors the
991 /// capture subscriber in `khive-runtime/src/pack.rs`'s gate-dispatch tests.
992 struct CaptureSubscriber {
993 events: std::sync::Arc<std::sync::Mutex<Vec<CapturedEvent>>>,
994 }
995
996 impl tracing::Subscriber for CaptureSubscriber {
997 fn enabled(&self, _: &tracing::Metadata<'_>) -> bool {
998 true
999 }
1000 fn new_span(&self, _: &tracing::span::Attributes<'_>) -> tracing::span::Id {
1001 tracing::span::Id::from_u64(1)
1002 }
1003 fn record(&self, _: &tracing::span::Id, _: &tracing::span::Record<'_>) {}
1004 fn record_follows_from(&self, _: &tracing::span::Id, _: &tracing::span::Id) {}
1005 fn event(&self, event: &tracing::Event<'_>) {
1006 let mut visitor = CapturedEventVisitor::default();
1007 event.record(&mut visitor);
1008 self.events.lock().unwrap().push(visitor.0);
1009 }
1010 fn enter(&self, _: &tracing::span::Id) {}
1011 fn exit(&self, _: &tracing::span::Id) {}
1012 }
1013
1014 /// ADR-091 Plank 0: `log_tx_registry_oldest_debug` emits a debug-level log
1015 /// naming the oldest open registry entry's label, on every call.
1016 ///
1017 /// `#[serial(tx_registry)]`: the registry is a process-wide singleton
1018 /// shared across every test in this binary — see `pool.rs`'s and
1019 /// `sql_bridge.rs`'s registry tests, which share this same serial group
1020 /// (round-1 fix: these three were previously unserialized and could
1021 /// race, corrupting each other's `oldest()`/`snapshot()` reads).
1022 ///
1023 /// This test does NOT hardcode "checkpoint_tick_test" as the expected
1024 /// label: production write paths elsewhere in this same test binary
1025 /// (vectors/graph/text stores) also register short-lived registry
1026 /// entries while their own tests run, and `serial(tx_registry)` only
1027 /// serializes against the OTHER tests in that same group, not against
1028 /// every write path in the crate. Instead it samples `oldest()` itself
1029 /// immediately before invoking the function under test and asserts the
1030 /// logged label matches whatever the registry considers oldest at that
1031 /// instant — deterministic regardless of unrelated concurrent registry
1032 /// churn, while still verifying `log_tx_registry_oldest_debug` correctly
1033 /// surfaces the registry's own `oldest()` answer.
1034 #[test]
1035 #[serial(tx_registry)]
1036 fn log_tx_registry_oldest_debug_reports_oldest_open_entry() {
1037 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
1038 let subscriber = CaptureSubscriber {
1039 events: std::sync::Arc::clone(&buffer),
1040 };
1041
1042 let _handle =
1043 khive_storage::tx_registry::register(Some("checkpoint_tick_test".to_string()));
1044
1045 let expected_label = khive_storage::tx_registry::oldest()
1046 .and_then(|(_, label)| label)
1047 .unwrap_or_else(|| "<unlabeled>".to_string());
1048
1049 tracing::subscriber::with_default(subscriber, || {
1050 log_tx_registry_oldest_debug(100);
1051 });
1052
1053 let events = buffer.lock().unwrap();
1054 assert!(
1055 events.iter().any(|e| {
1056 e.message.as_deref()
1057 == Some("WAL checkpoint tick: oldest open transaction registry entry")
1058 && e.oldest_tx_label.as_deref() == Some(expected_label.as_str())
1059 }),
1060 "expected a log line naming the open registry entry's label, got: {events:?}"
1061 );
1062 }
1063
1064 /// ADR-091 Plank 0 (round-1 fix): the oldest-entry WARN and the
1065 /// high-water snapshot-enumeration WARN are gated by `crossing_warn` at
1066 /// the call site (mirroring the WAL-threshold WARNs), so driving two
1067 /// consecutive above-threshold ticks through that same gate must produce
1068 /// exactly one of each — never a repeat on the second tick.
1069 #[test]
1070 #[serial(tx_registry)]
1071 fn registry_warns_fire_on_crossing_and_do_not_repeat() {
1072 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
1073 let subscriber = CaptureSubscriber {
1074 events: std::sync::Arc::clone(&buffer),
1075 };
1076
1077 let _handle =
1078 khive_storage::tx_registry::register(Some("registry_warn_crossing_test".to_string()));
1079
1080 let mut was_above_warn = false;
1081 let mut was_above_high_water = false;
1082
1083 tracing::subscriber::with_default(subscriber, || {
1084 // Tick 1: below→above crossing for both bands — both WARNs fire.
1085 if crossing_warn(true, &mut was_above_warn) {
1086 log_tx_registry_oldest_warn(6000);
1087 }
1088 if crossing_warn(true, &mut was_above_high_water) {
1089 log_tx_registry_snapshot_warn(6000);
1090 }
1091
1092 // Tick 2: still above both thresholds — neither must repeat.
1093 if crossing_warn(true, &mut was_above_warn) {
1094 log_tx_registry_oldest_warn(6000);
1095 }
1096 if crossing_warn(true, &mut was_above_high_water) {
1097 log_tx_registry_snapshot_warn(6000);
1098 }
1099 });
1100
1101 let events = buffer.lock().unwrap();
1102
1103 // `tracing::subscriber::with_default` scopes capture to THIS thread for
1104 // the duration of the closure, so `events` contains only the two
1105 // `log_tx_registry_oldest_warn` calls made above — no concurrent test's
1106 // log calls land in this buffer. This lets the crossing/no-repeat
1107 // assertion match on message text alone: unlike the "names MY label"
1108 // assertion in the sibling test above, WHICH label `oldest()` reports
1109 // is irrelevant here (a concurrent write path elsewhere in the binary
1110 // may transiently be the registry's genuine oldest entry) — only the
1111 // fire-once-per-crossing COUNT is under test.
1112 let oldest_warn_count = events
1113 .iter()
1114 .filter(|e| {
1115 e.message.as_deref()
1116 == Some("WAL checkpoint tick: oldest open transaction registry entry")
1117 })
1118 .count();
1119 assert_eq!(
1120 oldest_warn_count, 1,
1121 "oldest-entry WARN must fire exactly once across two above-threshold ticks, got: {events:?}"
1122 );
1123
1124 let snapshot_warn_count = events
1125 .iter()
1126 .filter(|e| {
1127 e.message.as_deref() == Some("WAL high-water: open transaction registry entry")
1128 && e.tx_label.as_deref() == Some("registry_warn_crossing_test")
1129 })
1130 .count();
1131 assert_eq!(
1132 snapshot_warn_count, 1,
1133 "high-water snapshot WARN must fire exactly once across two above-threshold ticks, got: {events:?}"
1134 );
1135 }
1136
1137 fn file_pool(path: &std::path::Path) -> Arc<ConnectionPool> {
1138 let cfg = PoolConfig {
1139 path: Some(path.to_path_buf()),
1140 ..PoolConfig::default()
1141 };
1142 Arc::new(ConnectionPool::new(cfg).expect("pool open"))
1143 }
1144
1145 // `checkpoint_once` -> `query_wal_pages` writes the process-wide
1146 // `LAST_WAL_PAGES` gauge and resets `CHECKPOINT_CONSECUTIVE_SKIPS`
1147 // (see the reset-discipline comment on `reset_checkpoint_metrics_for_tests`
1148 // above) — this must join the `checkpoint_skip_metrics` group so it can
1149 // never interleave with a test asserting on those same gauges.
1150 #[test]
1151 #[serial(checkpoint_skip_metrics)]
1152 fn checkpoint_once_succeeds_on_file_backed_pool() {
1153 let dir = tempfile::tempdir().unwrap();
1154 let path = dir.path().join("wal_test.db");
1155 let pool = file_pool(&path);
1156
1157 // Create a table so the DB is not completely empty.
1158 {
1159 let writer = pool.try_writer().unwrap();
1160 writer
1161 .conn()
1162 .execute_batch("CREATE TABLE IF NOT EXISTS t (x INTEGER);")
1163 .unwrap();
1164 writer
1165 .conn()
1166 .execute_batch("INSERT INTO t VALUES (1);")
1167 .unwrap();
1168 }
1169
1170 checkpoint_once(
1171 &pool,
1172 &CheckpointConfig::default(),
1173 &mut TruncateState::default(),
1174 );
1175 }
1176
1177 #[test]
1178 #[serial(checkpoint_skip_metrics)]
1179 fn checkpoint_once_is_noop_on_in_memory_pool() {
1180 // In-memory databases do not use WAL; checkpoint_once must not panic.
1181 let cfg = PoolConfig {
1182 path: None,
1183 ..PoolConfig::default()
1184 };
1185 let pool = Arc::new(ConnectionPool::new(cfg).expect("in-memory pool"));
1186 checkpoint_once(
1187 &pool,
1188 &CheckpointConfig::default(),
1189 &mut TruncateState::default(),
1190 );
1191 }
1192
1193 #[tokio::test]
1194 #[serial(checkpoint_skip_metrics)]
1195 async fn checkpoint_task_exits_on_shutdown_signal() {
1196 let dir = tempfile::tempdir().unwrap();
1197 let path = dir.path().join("wal_task_shutdown.db");
1198 let pool = file_pool(&path);
1199
1200 // Use a very short interval so the task ticks quickly in the test.
1201 let cfg = CheckpointConfig {
1202 interval: Duration::from_millis(10),
1203 ..Default::default()
1204 };
1205
1206 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
1207 let handle = tokio::spawn(run_checkpoint_task(
1208 pool,
1209 cfg,
1210 None,
1211 "local".to_string(),
1212 shutdown_rx,
1213 ));
1214
1215 shutdown_tx.send(()).expect("send shutdown signal");
1216
1217 tokio::time::timeout(Duration::from_secs(1), handle)
1218 .await
1219 .expect("checkpoint task should exit within 1s")
1220 .expect("checkpoint task panicked");
1221 }
1222
1223 /// Regression for issue #774: on the production boot path, the daemon
1224 /// passes `run_checkpoint_task` both `pool` directly and an
1225 /// `event_store` that internally retains its own `Arc::clone` of the
1226 /// same pool (`SqlEventStore::new_scoped`). A strong-count-based exit
1227 /// condition can never fire in that shape, because the task always
1228 /// observes at least two live clones — its own `pool` argument plus the
1229 /// one buried in `event_store`. This test reproduces that exact
1230 /// ownership shape (a real `SqlEventStore` holding a sibling clone) and
1231 /// asserts the task still exits promptly via the watch-channel signal,
1232 /// proving the fix does not depend on `Arc::strong_count` at all.
1233 #[tokio::test]
1234 #[serial(checkpoint_skip_metrics)]
1235 async fn checkpoint_task_exits_via_shutdown_signal_with_live_event_store_pool_clone() {
1236 let dir = tempfile::tempdir().unwrap();
1237 let path = dir.path().join("wal_task_event_store.db");
1238 let pool = file_pool(&path);
1239
1240 let cfg = CheckpointConfig {
1241 interval: Duration::from_millis(10),
1242 ..Default::default()
1243 };
1244
1245 let event_store: Arc<dyn khive_storage::EventStore> =
1246 Arc::new(crate::stores::event::SqlEventStore::new_scoped(
1247 Arc::clone(&pool),
1248 true,
1249 "local".to_string(),
1250 ));
1251 // A second, independent sibling clone of `pool` outlives this test
1252 // function's own binding — mirrors `StorageBackend` retaining
1253 // `self.pool` alongside the `SqlEventStore` it hands to the
1254 // checkpoint task in production.
1255 let sibling_pool_clone = Arc::clone(&pool);
1256
1257 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
1258 let handle = tokio::spawn(run_checkpoint_task(
1259 pool,
1260 cfg,
1261 Some(event_store),
1262 "local".to_string(),
1263 shutdown_rx,
1264 ));
1265
1266 // Confirm strong_count is well above 1 — the old check would spin
1267 // forever here — before proving the new signal-based exit works
1268 // regardless.
1269 assert!(
1270 Arc::strong_count(&sibling_pool_clone) > 1,
1271 "test setup must reproduce the multi-owner shape the bug depends on"
1272 );
1273
1274 shutdown_tx.send(()).expect("send shutdown signal");
1275
1276 tokio::time::timeout(Duration::from_secs(1), handle)
1277 .await
1278 .expect(
1279 "checkpoint task should exit within 1s via the watch signal, \
1280 even with a live sibling Arc<ConnectionPool> clone held by \
1281 the event store",
1282 )
1283 .expect("checkpoint task panicked");
1284 }
1285
1286 #[test]
1287 #[serial]
1288 fn checkpoint_config_env_override() {
1289 std::env::set_var("KHIVE_CHECKPOINT_INTERVAL_MS", "250");
1290 std::env::set_var("KHIVE_WAL_WARN_PAGES", "1500");
1291 std::env::set_var("KHIVE_WAL_HIGH_WATER_PAGES", "8000");
1292 std::env::set_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES", "12000");
1293 std::env::set_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS", "60");
1294 std::env::set_var("KHIVE_WAL_TRUNCATE_BUSY_MS", "500");
1295
1296 let cfg = CheckpointConfig::from_env();
1297
1298 std::env::remove_var("KHIVE_CHECKPOINT_INTERVAL_MS");
1299 std::env::remove_var("KHIVE_WAL_WARN_PAGES");
1300 std::env::remove_var("KHIVE_WAL_HIGH_WATER_PAGES");
1301 std::env::remove_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES");
1302 std::env::remove_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS");
1303 std::env::remove_var("KHIVE_WAL_TRUNCATE_BUSY_MS");
1304
1305 assert_eq!(cfg.interval, Duration::from_millis(250));
1306 assert_eq!(cfg.warn_pages, 1500);
1307 assert_eq!(cfg.high_water_pages, 8000);
1308 assert_eq!(cfg.truncate_high_water_pages, 12000);
1309 assert_eq!(cfg.truncate_min_interval, Duration::from_secs(60));
1310 assert_eq!(cfg.truncate_busy_timeout, Duration::from_millis(500));
1311 }
1312
1313 #[test]
1314 #[serial]
1315 fn checkpoint_config_defaults_on_invalid_env() {
1316 let default = CheckpointConfig::default();
1317
1318 std::env::set_var("KHIVE_CHECKPOINT_INTERVAL_MS", "not_a_number");
1319 std::env::set_var("KHIVE_WAL_WARN_PAGES", "");
1320 std::env::set_var("KHIVE_WAL_HIGH_WATER_PAGES", "0");
1321 std::env::set_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES", "not_a_number");
1322 std::env::set_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS", "");
1323 std::env::set_var("KHIVE_WAL_TRUNCATE_BUSY_MS", "0");
1324
1325 let cfg = CheckpointConfig::from_env();
1326
1327 std::env::remove_var("KHIVE_CHECKPOINT_INTERVAL_MS");
1328 std::env::remove_var("KHIVE_WAL_WARN_PAGES");
1329 std::env::remove_var("KHIVE_WAL_HIGH_WATER_PAGES");
1330 std::env::remove_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES");
1331 std::env::remove_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS");
1332 std::env::remove_var("KHIVE_WAL_TRUNCATE_BUSY_MS");
1333
1334 assert_eq!(cfg.interval, default.interval);
1335 assert_eq!(cfg.warn_pages, default.warn_pages);
1336 assert_eq!(cfg.high_water_pages, default.high_water_pages);
1337 assert_eq!(
1338 cfg.truncate_high_water_pages,
1339 default.truncate_high_water_pages
1340 );
1341 assert_eq!(cfg.truncate_min_interval, default.truncate_min_interval);
1342 assert_eq!(cfg.truncate_busy_timeout, default.truncate_busy_timeout);
1343 }
1344
1345 /// Regression: a high-water tick must NOT block behind an active read transaction.
1346 ///
1347 /// Isomorphism guarantee: this test FAILS if `checkpoint_once` regresses to
1348 /// `PRAGMA wal_checkpoint(TRUNCATE)`. Confirmed by reasoning: TRUNCATE inherits
1349 /// RESTART semantics and will invoke the busy handler (sleeping up to
1350 /// `busy_timeout`) while waiting for the open reader snapshot to release.
1351 /// With `busy_timeout = 2000ms` a TRUNCATE regression causes the call to take
1352 /// ~2000ms, blowing the <500ms assertion. PASSIVE returns in <1ms even with an
1353 /// open reader, because PASSIVE never waits for readers.
1354 ///
1355 /// Why `busy_timeout = 2000ms` and threshold `< 500ms`: the original 200ms
1356 /// busy_timeout / 50ms threshold was too tight for contended CI runners where
1357 /// PASSIVE legitimately takes 50-200ms under parallel-test load. Raising the
1358 /// busy_timeout to 2000ms keeps the PASSIVE path well below 500ms while a
1359 /// TRUNCATE regression blocks for ~2000ms — a 4x safety margin on both sides.
1360 #[test]
1361 #[serial(checkpoint_skip_metrics)]
1362 fn checkpoint_high_water_does_not_block_behind_reader() {
1363 let dir = tempfile::tempdir().unwrap();
1364 let path = dir.path().join("high_water_test.db");
1365
1366 // busy_timeout = 2000ms: a TRUNCATE regression blocks ~2s (clearly caught by
1367 // the <500ms assertion below), but PASSIVE returns well within 500ms even on
1368 // a heavily loaded CI runner. 4x margin on both sides vs. the old 200ms/50ms.
1369 let pool = Arc::new(
1370 ConnectionPool::new(PoolConfig {
1371 path: Some(path.clone()),
1372 busy_timeout: Duration::from_millis(2000),
1373 ..PoolConfig::default()
1374 })
1375 .expect("pool open"),
1376 );
1377
1378 // Write data so the WAL has frames to checkpoint.
1379 {
1380 let writer = pool.try_writer().unwrap();
1381 writer
1382 .conn()
1383 .execute_batch(
1384 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
1385 )
1386 .unwrap();
1387 }
1388
1389 // Open a reader and start a real read transaction so it holds a WAL
1390 // snapshot. An idle connection (no BEGIN) does NOT pin frames and would
1391 // not cause TRUNCATE to wait — the transaction is required for isomorphism.
1392 let reader = pool.reader().expect("reader");
1393 reader
1394 .execute_batch("BEGIN DEFERRED; SELECT * FROM t;")
1395 .expect("begin read tx");
1396
1397 // Write another row AFTER the snapshot is established. These new WAL
1398 // frames are now pinned by the open reader snapshot — TRUNCATE cannot
1399 // reclaim them without waiting; PASSIVE skips them and returns immediately.
1400 {
1401 let writer = pool.try_writer().unwrap();
1402 writer
1403 .conn()
1404 .execute_batch("INSERT INTO t VALUES (2);")
1405 .unwrap();
1406 }
1407
1408 let start = std::time::Instant::now();
1409 checkpoint_once(
1410 &pool,
1411 &CheckpointConfig::default(),
1412 &mut TruncateState::default(),
1413 );
1414 let elapsed = start.elapsed();
1415
1416 // Commit and release the read snapshot only after checkpoint_once returns.
1417 reader.execute_batch("COMMIT;").ok();
1418 drop(reader);
1419
1420 // PASSIVE returns in <1ms even with an open reader snapshot.
1421 // A TRUNCATE regression would block ~busy_timeout (2000ms) and fail here.
1422 // 500ms threshold is generous for CI jitter while staying well below 2000ms.
1423 assert!(
1424 elapsed < std::time::Duration::from_millis(500),
1425 "checkpoint_once with active reader snapshot took {:?}; \
1426 expected <500ms (PASSIVE must not block on readers; \
1427 a TRUNCATE regression would block ~2000ms)",
1428 elapsed
1429 );
1430 }
1431
1432 #[test]
1433 #[serial]
1434 fn checkpoint_config_rejects_zero_for_all_fields() {
1435 let default = CheckpointConfig::default();
1436 std::env::set_var("KHIVE_CHECKPOINT_INTERVAL_MS", "0");
1437 std::env::set_var("KHIVE_WAL_WARN_PAGES", "0");
1438 std::env::set_var("KHIVE_WAL_HIGH_WATER_PAGES", "0");
1439 std::env::set_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES", "0");
1440 std::env::set_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS", "0");
1441 std::env::set_var("KHIVE_WAL_TRUNCATE_BUSY_MS", "0");
1442
1443 let cfg = CheckpointConfig::from_env();
1444
1445 std::env::remove_var("KHIVE_CHECKPOINT_INTERVAL_MS");
1446 std::env::remove_var("KHIVE_WAL_WARN_PAGES");
1447 std::env::remove_var("KHIVE_WAL_HIGH_WATER_PAGES");
1448 std::env::remove_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES");
1449 std::env::remove_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS");
1450 std::env::remove_var("KHIVE_WAL_TRUNCATE_BUSY_MS");
1451
1452 assert_eq!(
1453 cfg.interval, default.interval,
1454 "zero interval must fall back to default"
1455 );
1456 assert_eq!(
1457 cfg.warn_pages, default.warn_pages,
1458 "zero warn_pages must fall back to default"
1459 );
1460 assert_eq!(
1461 cfg.high_water_pages, default.high_water_pages,
1462 "zero high_water_pages must fall back to default"
1463 );
1464 assert_eq!(
1465 cfg.truncate_high_water_pages, default.truncate_high_water_pages,
1466 "zero truncate_high_water_pages must fall back to default"
1467 );
1468 assert_eq!(
1469 cfg.truncate_min_interval, default.truncate_min_interval,
1470 "zero truncate_min_interval must fall back to default"
1471 );
1472 assert_eq!(
1473 cfg.truncate_busy_timeout, default.truncate_busy_timeout,
1474 "zero truncate_busy_timeout must fall back to default"
1475 );
1476 }
1477
1478 /// Regression (Finding 1): a Skipped tick must NOT reset was_above_high_water.
1479 ///
1480 /// Before the fix, `checkpoint_once` returned `0` on both a genuinely-empty
1481 /// WAL and a writer-busy skip. The task treated `0` as an observed page count
1482 /// and reset `was_above_high_water`, re-arming the rate limit on every busy
1483 /// tick. With the fix, `CheckpointTick::Skipped` leaves crossing state
1484 /// unchanged.
1485 ///
1486 /// This test drives `crossing_warn` directly (the pure function that owns the
1487 /// decision) rather than going through the async task, which would require a
1488 /// logging harness.
1489 #[test]
1490 fn skipped_tick_does_not_reset_high_water_crossing_state() {
1491 let mut was_above = false;
1492
1493 // First observed tick: above threshold — fires WARN, sets was_above=true.
1494 assert!(
1495 crossing_warn(true, &mut was_above),
1496 "should fire on first crossing"
1497 );
1498 assert!(was_above);
1499
1500 // Simulate several skipped ticks: crossing state must remain true.
1501 // (In the task, Skipped causes `continue` so crossing_warn is never called.)
1502 // We verify by calling crossing_warn with the SAME above=true value, which
1503 // is what Observed(high_count) would produce — but a Skipped tick skips
1504 // the call entirely, so was_above stays as-is. Test the invariant directly:
1505 // if we leave was_above unchanged (no call at all), was_above remains true.
1506 assert!(was_above, "was_above must stay true across skipped ticks");
1507
1508 // Another observed tick still above threshold — must NOT re-fire.
1509 let fired = crossing_warn(true, &mut was_above);
1510 assert!(!fired, "WARN must not re-fire while still above threshold");
1511
1512 // Observed tick below threshold — resets was_above.
1513 let fired = crossing_warn(false, &mut was_above);
1514 assert!(!fired);
1515 assert!(!was_above);
1516
1517 // Next observed tick above threshold — fires again (legitimate new crossing).
1518 let fired = crossing_warn(true, &mut was_above);
1519 assert!(fired, "WARN must fire again on a new below→above crossing");
1520 }
1521
1522 /// Regression (Finding 2): warn_pages WARN fires once on crossing, not every tick.
1523 ///
1524 /// Before the fix, the WARN was emitted inside `checkpoint_once` on every tick
1525 /// while WAL sat in the warn band — log spam under sustained moderate pressure.
1526 /// With the fix, `crossing_warn` gates the WARN on the first in-band tick only;
1527 /// subsequent ticks while still in the band return false.
1528 #[test]
1529 fn warn_pages_fires_once_on_crossing_not_every_tick() {
1530 let mut was_above_warn = false;
1531
1532 // Simulate three consecutive ticks with WAL in the warn band.
1533 let fired_1 = crossing_warn(true, &mut was_above_warn);
1534 let fired_2 = crossing_warn(true, &mut was_above_warn);
1535 let fired_3 = crossing_warn(true, &mut was_above_warn);
1536
1537 assert!(fired_1, "WARN must fire on the first in-band tick");
1538 assert!(
1539 !fired_2,
1540 "WARN must not fire on the second consecutive in-band tick"
1541 );
1542 assert!(
1543 !fired_3,
1544 "WARN must not fire on the third consecutive in-band tick"
1545 );
1546
1547 // Drop below warn band — resets state.
1548 crossing_warn(false, &mut was_above_warn);
1549 assert!(!was_above_warn);
1550
1551 // Re-enter warn band — fires again.
1552 let fired_reentry = crossing_warn(true, &mut was_above_warn);
1553 assert!(
1554 fired_reentry,
1555 "WARN must fire again on re-entry into warn band"
1556 );
1557 }
1558
1559 // ADR-091 Plank 2: TRUNCATE escalation state machine tests.
1560
1561 /// Trigger threshold: once `wal_pages` (as observed by `checkpoint_once`) is
1562 /// at/above `truncate_high_water_pages` and no prior attempt has run, the
1563 /// escalation fires and stamps `last_attempt`.
1564 #[test]
1565 #[serial(tx_registry, checkpoint_skip_metrics)]
1566 fn truncate_attempts_when_high_water_crossed_with_no_prior_attempt() {
1567 let dir = tempfile::tempdir().unwrap();
1568 let path = dir.path().join("truncate_trigger.db");
1569 let pool = file_pool(&path);
1570
1571 {
1572 let writer = pool.try_writer().unwrap();
1573 writer
1574 .conn()
1575 .execute_batch(
1576 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
1577 )
1578 .unwrap();
1579 }
1580
1581 let config = CheckpointConfig {
1582 // Force the escalation to arm regardless of the tiny WAL this test
1583 // actually produces — isolates the trigger-threshold behavior from
1584 // needing to stuff 20,000 real WAL pages.
1585 truncate_high_water_pages: 0,
1586 truncate_min_interval: Duration::from_secs(300),
1587 ..CheckpointConfig::default()
1588 };
1589 let mut state = TruncateState::default();
1590
1591 assert!(
1592 state.last_attempt.is_none(),
1593 "precondition: no attempt has run yet"
1594 );
1595
1596 let tick = checkpoint_once(&pool, &config, &mut state);
1597 assert!(matches!(tick, CheckpointTick::Observed(_)));
1598 assert!(
1599 state.last_attempt.is_some(),
1600 "an attempt must be stamped once the high-water threshold is crossed"
1601 );
1602 }
1603
1604 /// Below-threshold skip: `wal_pages < truncate_high_water_pages` must never
1605 /// stamp `last_attempt` — only an actual attempt advances it.
1606 #[test]
1607 #[serial(tx_registry, checkpoint_skip_metrics)]
1608 fn truncate_does_not_attempt_below_high_water() {
1609 let dir = tempfile::tempdir().unwrap();
1610 let path = dir.path().join("truncate_below_threshold.db");
1611 let pool = file_pool(&path);
1612
1613 {
1614 let writer = pool.try_writer().unwrap();
1615 writer
1616 .conn()
1617 .execute_batch(
1618 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
1619 )
1620 .unwrap();
1621 }
1622
1623 // Effectively unreachable threshold for this test's tiny WAL.
1624 let config = CheckpointConfig {
1625 truncate_high_water_pages: u64::MAX,
1626 ..CheckpointConfig::default()
1627 };
1628 let mut state = TruncateState::default();
1629
1630 checkpoint_once(&pool, &config, &mut state);
1631
1632 assert!(
1633 state.last_attempt.is_none(),
1634 "a below-threshold tick must never stamp last_attempt"
1635 );
1636 }
1637
1638 /// Min-interval skip: once an attempt has run, a subsequent tick that is
1639 /// still above threshold but within `truncate_min_interval` must skip
1640 /// without re-stamping `last_attempt` (the timestamp must not move).
1641 #[test]
1642 #[serial(tx_registry, checkpoint_skip_metrics)]
1643 fn truncate_min_interval_skip_does_not_restamp_last_attempt() {
1644 let dir = tempfile::tempdir().unwrap();
1645 let path = dir.path().join("truncate_min_interval.db");
1646 let pool = file_pool(&path);
1647
1648 {
1649 let writer = pool.try_writer().unwrap();
1650 writer
1651 .conn()
1652 .execute_batch(
1653 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
1654 )
1655 .unwrap();
1656 }
1657
1658 let config = CheckpointConfig {
1659 truncate_high_water_pages: 0,
1660 truncate_min_interval: Duration::from_secs(300),
1661 ..CheckpointConfig::default()
1662 };
1663 let mut state = TruncateState::default();
1664
1665 checkpoint_once(&pool, &config, &mut state);
1666 let first_attempt = state.last_attempt.expect("first tick must attempt");
1667
1668 // Second tick, immediately after: still above threshold, but the
1669 // min-interval has clearly not elapsed — must skip and leave
1670 // last_attempt exactly as it was.
1671 checkpoint_once(&pool, &config, &mut state);
1672 let second_attempt = state.last_attempt.expect("attempt timestamp must persist");
1673
1674 assert_eq!(
1675 first_attempt, second_attempt,
1676 "a tick within truncate_min_interval must not re-stamp last_attempt"
1677 );
1678 }
1679
1680 /// Busy fallback: when the writer mutex is already held, `checkpoint_once`
1681 /// must return `Skipped` and never touch the TRUNCATE state at all — both
1682 /// PASSIVE and any due TRUNCATE are skipped together (one writer checkout
1683 /// per tick). Also asserts #646 checkpoint-pressure telemetry: a skipped
1684 /// tick must bump the skipped/consecutive-skip counters and snapshot the
1685 /// last-known WAL pressure.
1686 #[test]
1687 #[serial(tx_registry, checkpoint_skip_metrics)]
1688 fn busy_writer_skips_both_passive_and_truncate() {
1689 reset_checkpoint_metrics_for_tests();
1690
1691 let dir = tempfile::tempdir().unwrap();
1692 let path = dir.path().join("truncate_busy_skip.db");
1693 let pool = file_pool(&path);
1694
1695 {
1696 let writer = pool.try_writer().unwrap();
1697 writer
1698 .conn()
1699 .execute_batch(
1700 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
1701 )
1702 .unwrap();
1703 }
1704
1705 // An observed tick first, so the skip below has a last-known WAL
1706 // pressure snapshot to carry forward.
1707 let mut warmup_state = TruncateState::default();
1708 let warmup_tick = checkpoint_once(&pool, &CheckpointConfig::default(), &mut warmup_state);
1709 let observed_pages = match warmup_tick {
1710 CheckpointTick::Observed(n) => n,
1711 CheckpointTick::Skipped => panic!("warmup tick must observe, not skip"),
1712 };
1713 assert_eq!(
1714 checkpoint_consecutive_skips(),
1715 0,
1716 "an observed tick must not itself count as a skip"
1717 );
1718
1719 // Hold the writer mutex for the duration of the checkpoint_once call so
1720 // try_writer_nowait() fails, exactly like a concurrent write in progress.
1721 let _held = pool.try_writer().unwrap();
1722
1723 let config = CheckpointConfig {
1724 truncate_high_water_pages: 0,
1725 ..CheckpointConfig::default()
1726 };
1727 let mut state = TruncateState::default();
1728
1729 let tick = checkpoint_once(&pool, &config, &mut state);
1730
1731 assert_eq!(
1732 tick,
1733 CheckpointTick::Skipped,
1734 "a busy writer must skip the tick entirely"
1735 );
1736 assert!(
1737 state.last_attempt.is_none(),
1738 "a skipped tick (writer busy) must never stamp last_attempt, \
1739 even with a threshold that would otherwise arm immediately"
1740 );
1741
1742 assert_eq!(
1743 checkpoint_skipped_ticks(),
1744 1,
1745 "one skipped tick must bump the lifetime skipped-tick counter"
1746 );
1747 assert_eq!(
1748 checkpoint_consecutive_skips(),
1749 1,
1750 "one skipped tick must bump the consecutive-skip run length"
1751 );
1752 assert_eq!(
1753 checkpoint_last_skip_wal_pages(),
1754 Some(observed_pages),
1755 "the skip must snapshot the last-observed WAL pressure"
1756 );
1757 }
1758
1759 /// Observation branch: a checkpoint tick that is actually observed (writer
1760 /// free) must close out a prior skip streak, resetting the
1761 /// consecutive-skip counter to 0 without touching the lifetime total.
1762 #[test]
1763 #[serial(tx_registry, checkpoint_skip_metrics)]
1764 fn observed_tick_resets_consecutive_skips_but_not_lifetime_total() {
1765 reset_checkpoint_metrics_for_tests();
1766
1767 let dir = tempfile::tempdir().unwrap();
1768 let path = dir.path().join("skip_then_observe.db");
1769 let pool = file_pool(&path);
1770
1771 {
1772 let writer = pool.try_writer().unwrap();
1773 writer
1774 .conn()
1775 .execute_batch(
1776 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
1777 )
1778 .unwrap();
1779 }
1780
1781 // Two consecutive skipped ticks.
1782 {
1783 let _held = pool.try_writer().unwrap();
1784 let mut state = TruncateState::default();
1785 for _ in 0..2 {
1786 let tick = checkpoint_once(&pool, &CheckpointConfig::default(), &mut state);
1787 assert_eq!(tick, CheckpointTick::Skipped);
1788 }
1789 }
1790 assert_eq!(checkpoint_skipped_ticks(), 2);
1791 assert_eq!(checkpoint_consecutive_skips(), 2);
1792
1793 // Now the writer is free: an observed tick must reset the streak.
1794 let mut state = TruncateState::default();
1795 let tick = checkpoint_once(&pool, &CheckpointConfig::default(), &mut state);
1796 assert!(matches!(tick, CheckpointTick::Observed(_)));
1797
1798 assert_eq!(
1799 checkpoint_skipped_ticks(),
1800 2,
1801 "an observed tick must not change the lifetime skipped-tick total"
1802 );
1803 assert_eq!(
1804 checkpoint_consecutive_skips(),
1805 0,
1806 "an observed tick must reset the consecutive-skip run length"
1807 );
1808 }
1809
1810 /// Edge-triggered escalation WARN: `note_truncate_outcome` fires exactly
1811 /// once, on the third consecutive attempt that fails to clear
1812 /// `warn_pages`, and does not repeat on a fourth consecutive failure. A
1813 /// single attempt that clears `warn_pages` resets the counter.
1814 #[test]
1815 fn note_truncate_outcome_warns_once_at_third_consecutive_failure() {
1816 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
1817 let subscriber = CaptureSubscriber {
1818 events: std::sync::Arc::clone(&buffer),
1819 };
1820
1821 let config = CheckpointConfig {
1822 warn_pages: 2000,
1823 ..CheckpointConfig::default()
1824 };
1825 let mut state = TruncateState::default();
1826
1827 tracing::subscriber::with_default(subscriber, || {
1828 // Three consecutive attempts that fail to clear warn_pages.
1829 note_truncate_outcome(&config, 5000, &mut state);
1830 note_truncate_outcome(&config, 5000, &mut state);
1831 note_truncate_outcome(&config, 5000, &mut state);
1832 // A fourth consecutive failure must not re-fire the escalation.
1833 note_truncate_outcome(&config, 5000, &mut state);
1834 });
1835
1836 assert_eq!(state.consecutive_failures, 4);
1837
1838 let events = buffer.lock().unwrap();
1839 let escalation_count = events
1840 .iter()
1841 .filter(|e| {
1842 e.message.as_deref()
1843 == Some(
1844 "WAL TRUNCATE has failed to clear WAL pressure for 3 consecutive attempts",
1845 )
1846 })
1847 .count();
1848 assert_eq!(
1849 escalation_count, 1,
1850 "escalation WARN must fire exactly once at the 3rd consecutive failure, got: {events:?}"
1851 );
1852
1853 // A clearing attempt resets the counter.
1854 note_truncate_outcome(&config, 100, &mut state);
1855 assert_eq!(
1856 state.consecutive_failures, 0,
1857 "an attempt that clears warn_pages must reset the consecutive-failure counter"
1858 );
1859 }
1860
1861 // ADR-091 #617: graduated severity ladder state-machine tests.
1862
1863 fn severity_test_config() -> CheckpointConfig {
1864 CheckpointConfig {
1865 warn_pages: 100,
1866 warn_sustained_cycles: 3,
1867 ..CheckpointConfig::default()
1868 }
1869 }
1870
1871 /// INFO rung: a below→above crossing emits exactly one INFO and no WARN
1872 /// (default `warn_sustained_cycles = 3`, only one above-warn tick here).
1873 #[test]
1874 fn severity_ladder_info_on_first_crossing_no_warn() {
1875 let config = severity_test_config();
1876 let mut state = CheckpointSeverityState::default();
1877
1878 let below = state.observe_wal_pages(10, &config);
1879 assert!(below.is_empty(), "below-warn tick must emit nothing");
1880
1881 let above = state.observe_wal_pages(150, &config);
1882 assert_eq!(
1883 above,
1884 vec![CheckpointSeverityEmission {
1885 rung: CheckpointSeverityRung::Info,
1886 wal_pages: 150,
1887 threshold_pages: 100,
1888 consecutive_cycles: 1,
1889 }],
1890 "first below->above crossing must emit exactly one INFO and no WARN"
1891 );
1892 }
1893
1894 /// WARN rung: `warn_sustained_cycles` (3) consecutive above-warn ticks
1895 /// emit WARN exactly on the third tick, not before and not repeated after.
1896 #[test]
1897 fn severity_ladder_warn_on_third_consecutive_cycle() {
1898 let config = severity_test_config();
1899 let mut state = CheckpointSeverityState::default();
1900
1901 let tick1 = state.observe_wal_pages(150, &config);
1902 assert_eq!(tick1.len(), 1);
1903 assert_eq!(tick1[0].rung, CheckpointSeverityRung::Info);
1904
1905 let tick2 = state.observe_wal_pages(150, &config);
1906 assert!(
1907 tick2.is_empty(),
1908 "second consecutive above-warn tick must emit nothing yet"
1909 );
1910
1911 let tick3 = state.observe_wal_pages(150, &config);
1912 assert_eq!(
1913 tick3,
1914 vec![CheckpointSeverityEmission {
1915 rung: CheckpointSeverityRung::Warn,
1916 wal_pages: 150,
1917 threshold_pages: 100,
1918 consecutive_cycles: 3,
1919 }],
1920 "WARN must fire exactly on the third consecutive above-warn tick"
1921 );
1922
1923 let tick4 = state.observe_wal_pages(150, &config);
1924 assert!(
1925 tick4.is_empty(),
1926 "WARN must not repeat on a fourth consecutive above-warn tick"
1927 );
1928 }
1929
1930 /// Re-arm: after a WARN episode drains below warn_pages, a fresh episode
1931 /// of `warn_sustained_cycles` above-warn ticks must WARN again.
1932 #[test]
1933 fn severity_ladder_rearms_warn_after_drain() {
1934 let config = severity_test_config();
1935 let mut state = CheckpointSeverityState::default();
1936
1937 // First episode reaches WARN.
1938 for _ in 0..3 {
1939 state.observe_wal_pages(150, &config);
1940 }
1941 assert!(state.warn_emitted_for_episode);
1942
1943 // Drain below warn_pages: resets the episode.
1944 let drain = state.observe_wal_pages(10, &config);
1945 assert!(drain.is_empty(), "a draining tick must emit nothing");
1946
1947 // Second episode: INFO on first tick, no WARN until the third again.
1948 let reentry = state.observe_wal_pages(150, &config);
1949 assert_eq!(reentry.len(), 1);
1950 assert_eq!(reentry[0].rung, CheckpointSeverityRung::Info);
1951
1952 let mid = state.observe_wal_pages(150, &config);
1953 assert!(mid.is_empty());
1954
1955 let second_warn = state.observe_wal_pages(150, &config);
1956 assert_eq!(
1957 second_warn,
1958 vec![CheckpointSeverityEmission {
1959 rung: CheckpointSeverityRung::Warn,
1960 wal_pages: 150,
1961 threshold_pages: 100,
1962 consecutive_cycles: 3,
1963 }],
1964 "a fresh elevation episode after a drain must WARN again"
1965 );
1966 }
1967
1968 /// False-positive guard: three isolated single-tick crossings, each
1969 /// followed by a drain, must never reach WARN — only INFO fires each time.
1970 #[test]
1971 fn severity_ladder_isolated_crossings_never_warn() {
1972 let config = severity_test_config();
1973 let mut state = CheckpointSeverityState::default();
1974
1975 for _ in 0..3 {
1976 let crossing = state.observe_wal_pages(150, &config);
1977 assert_eq!(
1978 crossing.len(),
1979 1,
1980 "each isolated crossing must emit exactly one INFO"
1981 );
1982 assert_eq!(crossing[0].rung, CheckpointSeverityRung::Info);
1983
1984 let drain = state.observe_wal_pages(10, &config);
1985 assert!(drain.is_empty(), "the drain tick must emit nothing");
1986 }
1987
1988 assert!(
1989 !state.warn_emitted_for_episode,
1990 "isolated single-tick crossings must never accumulate into a WARN"
1991 );
1992 }
1993
1994 /// ALARM rung: the existing TRUNCATE-attempt gate is the ADR-091 ALARM
1995 /// tier. `observe_wal_pages` never produces it; this test documents and
1996 /// locks in that boundary so a future change can't silently reroute
1997 /// ALARM through the INFO/WARN ladder.
1998 #[test]
1999 fn severity_ladder_never_emits_alarm() {
2000 let config = CheckpointConfig {
2001 warn_pages: 100,
2002 warn_sustained_cycles: 1,
2003 ..CheckpointConfig::default()
2004 };
2005 let mut state = CheckpointSeverityState::default();
2006
2007 for wal_pages in [150, 200, 250, u64::MAX] {
2008 let emissions = state.observe_wal_pages(wal_pages, &config);
2009 assert!(
2010 emissions
2011 .iter()
2012 .all(|e| e.rung != CheckpointSeverityRung::Alarm),
2013 "observe_wal_pages must never emit the ALARM rung, got: {emissions:?}"
2014 );
2015 }
2016 }
2017
2018 /// `KHIVE_WAL_WARN_SUSTAINED_CYCLES` overrides the default and rejects 0.
2019 #[test]
2020 #[serial]
2021 fn checkpoint_config_warn_sustained_cycles_env_override() {
2022 let default = CheckpointConfig::default();
2023 assert_eq!(default.warn_sustained_cycles, DEFAULT_WARN_SUSTAINED_CYCLES);
2024
2025 std::env::set_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES", "5");
2026 let cfg = CheckpointConfig::from_env();
2027 std::env::remove_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES");
2028 assert_eq!(cfg.warn_sustained_cycles, 5);
2029
2030 std::env::set_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES", "0");
2031 let cfg_zero = CheckpointConfig::from_env();
2032 std::env::remove_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES");
2033 assert_eq!(
2034 cfg_zero.warn_sustained_cycles, DEFAULT_WARN_SUSTAINED_CYCLES,
2035 "zero must fall back to the default"
2036 );
2037
2038 std::env::set_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES", "not_a_number");
2039 let cfg_invalid = CheckpointConfig::from_env();
2040 std::env::remove_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES");
2041 assert_eq!(
2042 cfg_invalid.warn_sustained_cycles,
2043 DEFAULT_WARN_SUSTAINED_CYCLES
2044 );
2045 }
2046
2047 // ADR-094: `CheckpointOutcomeRecorded` lifecycle event tests.
2048
2049 #[derive(Default)]
2050 struct FakeEventStore {
2051 events: std::sync::Mutex<Vec<khive_storage::Event>>,
2052 }
2053
2054 #[async_trait::async_trait]
2055 impl khive_storage::EventStore for FakeEventStore {
2056 async fn append_event(
2057 &self,
2058 event: khive_storage::Event,
2059 ) -> khive_storage::StorageResult<()> {
2060 self.events.lock().unwrap().push(event);
2061 Ok(())
2062 }
2063
2064 async fn append_events(
2065 &self,
2066 events: Vec<khive_storage::Event>,
2067 ) -> khive_storage::StorageResult<khive_storage::BatchWriteSummary> {
2068 let count = events.len() as u64;
2069 self.events.lock().unwrap().extend(events);
2070 Ok(khive_storage::BatchWriteSummary {
2071 attempted: count,
2072 affected: count,
2073 failed: 0,
2074 first_error: String::new(),
2075 })
2076 }
2077
2078 async fn get_event(
2079 &self,
2080 id: uuid::Uuid,
2081 ) -> khive_storage::StorageResult<Option<khive_storage::Event>> {
2082 Ok(self
2083 .events
2084 .lock()
2085 .unwrap()
2086 .iter()
2087 .find(|e| e.id == id)
2088 .cloned())
2089 }
2090
2091 async fn query_events(
2092 &self,
2093 _filter: khive_storage::EventFilter,
2094 _page: khive_storage::PageRequest,
2095 ) -> khive_storage::StorageResult<khive_storage::Page<khive_storage::Event>> {
2096 unimplemented!("not exercised by the checkpoint lifecycle-event tests")
2097 }
2098
2099 async fn count_events(
2100 &self,
2101 _filter: khive_storage::EventFilter,
2102 ) -> khive_storage::StorageResult<u64> {
2103 Ok(self.events.lock().unwrap().len() as u64)
2104 }
2105 }
2106
2107 /// Pure decision-table coverage for every input combination
2108 /// `checkpoint_outcome_should_emit` can see: a first elevated tick, a
2109 /// sustained elevated tick, the single drain row, and the ordinary
2110 /// healthy tick that must emit nothing.
2111 #[test]
2112 fn checkpoint_outcome_should_emit_covers_all_transitions() {
2113 assert!(
2114 checkpoint_outcome_should_emit(true, false),
2115 "first elevated tick must emit"
2116 );
2117 assert!(
2118 checkpoint_outcome_should_emit(true, true),
2119 "sustained elevated tick must emit"
2120 );
2121 assert!(
2122 checkpoint_outcome_should_emit(false, true),
2123 "the single drain row (elevated -> healthy) must emit"
2124 );
2125 assert!(
2126 !checkpoint_outcome_should_emit(false, false),
2127 "an ordinary below-warn tick must not emit"
2128 );
2129 }
2130
2131 #[tokio::test]
2132 #[serial(checkpoint_skip_metrics)]
2133 async fn checkpoint_task_emits_outcome_events_while_elevated_and_stops_after_drain() {
2134 let dir = tempfile::tempdir().unwrap();
2135 let path = dir.path().join("outcome_emit.db");
2136 let pool = file_pool(&path);
2137
2138 // warn_pages: 0 means any observed WAL page count (even 0) is
2139 // "elevated" for the duration this config is active.
2140 let cfg = CheckpointConfig {
2141 interval: Duration::from_millis(10),
2142 warn_pages: 0,
2143 ..CheckpointConfig::default()
2144 };
2145 let store = Arc::new(FakeEventStore::default());
2146 let store_dyn: Arc<dyn khive_storage::EventStore> = store.clone();
2147
2148 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
2149 let handle = tokio::spawn(run_checkpoint_task(
2150 pool,
2151 cfg,
2152 Some(store_dyn),
2153 "local".to_string(),
2154 shutdown_rx,
2155 ));
2156
2157 tokio::time::sleep(Duration::from_millis(60)).await;
2158 shutdown_tx.send(()).expect("send shutdown signal");
2159 tokio::time::timeout(Duration::from_secs(1), handle)
2160 .await
2161 .expect("checkpoint task should exit within 1s")
2162 .expect("checkpoint task panicked");
2163
2164 let events = store.events.lock().unwrap();
2165 assert!(
2166 !events.is_empty(),
2167 "an always-elevated config must append at least one CheckpointOutcomeRecorded event"
2168 );
2169 assert!(
2170 events
2171 .iter()
2172 .all(|e| e.kind == khive_types::EventKind::CheckpointOutcomeRecorded),
2173 "every appended event must be CheckpointOutcomeRecorded, got: {events:?}"
2174 );
2175 assert!(
2176 events.iter().all(|e| e.namespace == "local"),
2177 "events must be stamped with the namespace passed to run_checkpoint_task"
2178 );
2179 }
2180
2181 #[tokio::test]
2182 #[serial(checkpoint_skip_metrics)]
2183 async fn checkpoint_task_emits_nothing_while_healthy() {
2184 let dir = tempfile::tempdir().unwrap();
2185 let path = dir.path().join("outcome_no_emit.db");
2186 let pool = file_pool(&path);
2187
2188 // An unreachable warn_pages threshold for this test's tiny WAL: every
2189 // tick stays below warn, so no event should ever be appended.
2190 let cfg = CheckpointConfig {
2191 interval: Duration::from_millis(10),
2192 warn_pages: u64::MAX,
2193 ..CheckpointConfig::default()
2194 };
2195 let store = Arc::new(FakeEventStore::default());
2196 let store_dyn: Arc<dyn khive_storage::EventStore> = store.clone();
2197
2198 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
2199 let handle = tokio::spawn(run_checkpoint_task(
2200 pool,
2201 cfg,
2202 Some(store_dyn),
2203 "local".to_string(),
2204 shutdown_rx,
2205 ));
2206
2207 tokio::time::sleep(Duration::from_millis(60)).await;
2208 shutdown_tx.send(()).expect("send shutdown signal");
2209 tokio::time::timeout(Duration::from_secs(1), handle)
2210 .await
2211 .expect("checkpoint task should exit within 1s")
2212 .expect("checkpoint task panicked");
2213
2214 assert!(
2215 store.events.lock().unwrap().is_empty(),
2216 "a config that never crosses warn_pages must never append a lifecycle event"
2217 );
2218 }
2219
2220 #[tokio::test]
2221 #[serial(checkpoint_skip_metrics)]
2222 async fn checkpoint_task_with_no_event_store_does_not_panic() {
2223 let dir = tempfile::tempdir().unwrap();
2224 let path = dir.path().join("outcome_none_store.db");
2225 let pool = file_pool(&path);
2226
2227 let cfg = CheckpointConfig {
2228 interval: Duration::from_millis(10),
2229 warn_pages: 0,
2230 ..CheckpointConfig::default()
2231 };
2232
2233 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
2234 let handle = tokio::spawn(run_checkpoint_task(
2235 pool,
2236 cfg,
2237 None,
2238 "local".to_string(),
2239 shutdown_rx,
2240 ));
2241
2242 tokio::time::sleep(Duration::from_millis(40)).await;
2243 shutdown_tx.send(()).expect("send shutdown signal");
2244 tokio::time::timeout(Duration::from_secs(1), handle)
2245 .await
2246 .expect("checkpoint task should exit within 1s")
2247 .expect("checkpoint task panicked");
2248 }
2249}