use std::sync::atomic::{AtomicU64, Ordering};
use std::sync::Arc;
use std::time::{Duration, Instant};
use crate::pool::{ConnectionPool, WriterGuard};
static LAST_WAL_PAGES: AtomicU64 = AtomicU64::new(u64::MAX);
static TRUNCATE_ATTEMPTS: AtomicU64 = AtomicU64::new(0);
static TRUNCATE_CONSECUTIVE_FAILURES: AtomicU64 = AtomicU64::new(0);
static CHECKPOINT_SKIPPED_TICKS: AtomicU64 = AtomicU64::new(0);
static CHECKPOINT_CONSECUTIVE_SKIPS: AtomicU64 = AtomicU64::new(0);
static CHECKPOINT_LAST_SKIP_WAL_PAGES: AtomicU64 = AtomicU64::new(u64::MAX);
pub fn last_observed_wal_pages() -> Option<u64> {
match LAST_WAL_PAGES.load(Ordering::Relaxed) {
u64::MAX => None,
pages => Some(pages),
}
}
pub fn truncate_attempts() -> u64 {
TRUNCATE_ATTEMPTS.load(Ordering::Relaxed)
}
pub fn truncate_consecutive_failures() -> u64 {
TRUNCATE_CONSECUTIVE_FAILURES.load(Ordering::Relaxed)
}
pub fn checkpoint_skipped_ticks() -> u64 {
CHECKPOINT_SKIPPED_TICKS.load(Ordering::Relaxed)
}
pub fn checkpoint_consecutive_skips() -> u64 {
CHECKPOINT_CONSECUTIVE_SKIPS.load(Ordering::Relaxed)
}
pub fn checkpoint_last_skip_wal_pages() -> Option<u64> {
match CHECKPOINT_LAST_SKIP_WAL_PAGES.load(Ordering::Relaxed) {
u64::MAX => None,
pages => Some(pages),
}
}
fn note_checkpoint_skipped() {
CHECKPOINT_SKIPPED_TICKS.fetch_add(1, Ordering::Relaxed);
CHECKPOINT_CONSECUTIVE_SKIPS.fetch_add(1, Ordering::Relaxed);
if let Some(pages) = last_observed_wal_pages() {
CHECKPOINT_LAST_SKIP_WAL_PAGES.store(pages, Ordering::Relaxed);
}
}
fn note_checkpoint_observed(_wal_pages: u64) {
CHECKPOINT_CONSECUTIVE_SKIPS.store(0, Ordering::Relaxed);
}
#[cfg(test)]
pub(crate) fn reset_checkpoint_metrics_for_tests() {
CHECKPOINT_SKIPPED_TICKS.store(0, Ordering::Relaxed);
CHECKPOINT_CONSECUTIVE_SKIPS.store(0, Ordering::Relaxed);
CHECKPOINT_LAST_SKIP_WAL_PAGES.store(u64::MAX, Ordering::Relaxed);
}
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
pub enum CheckpointTick {
Skipped,
Observed(u64),
}
pub const DEFAULT_WARN_SUSTAINED_CYCLES: u8 = 3;
#[derive(Clone, Debug)]
pub struct CheckpointConfig {
pub interval: Duration,
pub warn_pages: u64,
pub warn_sustained_cycles: u8,
pub high_water_pages: u64,
pub truncate_high_water_pages: u64,
pub truncate_min_interval: Duration,
pub truncate_busy_timeout: Duration,
pub tx_warn_secs: Duration,
pub tx_max_age_secs: Duration,
}
impl Default for CheckpointConfig {
fn default() -> Self {
Self {
interval: Duration::from_millis(500),
warn_pages: 2000,
warn_sustained_cycles: DEFAULT_WARN_SUSTAINED_CYCLES,
high_water_pages: 6000,
truncate_high_water_pages: 20_000,
truncate_min_interval: Duration::from_secs(300),
truncate_busy_timeout: Duration::from_millis(2000),
tx_warn_secs: Duration::from_secs(30),
tx_max_age_secs: Duration::from_secs(120),
}
}
}
impl CheckpointConfig {
pub fn from_env() -> Self {
let mut cfg = Self::default();
if let Ok(ms) = std::env::var("KHIVE_CHECKPOINT_INTERVAL_MS") {
if let Ok(v) = ms.parse::<u64>() {
if v > 0 {
cfg.interval = Duration::from_millis(v);
}
}
}
if let Ok(v) = std::env::var("KHIVE_WAL_WARN_PAGES") {
if let Ok(n) = v.parse::<u64>() {
if n > 0 {
cfg.warn_pages = n;
}
}
}
if let Ok(v) = std::env::var("KHIVE_WAL_WARN_SUSTAINED_CYCLES") {
if let Ok(n) = v.parse::<u8>() {
if n > 0 {
cfg.warn_sustained_cycles = n;
}
}
}
if let Ok(v) = std::env::var("KHIVE_WAL_HIGH_WATER_PAGES") {
if let Ok(n) = v.parse::<u64>() {
if n > 0 {
cfg.high_water_pages = n;
}
}
}
if let Ok(v) = std::env::var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES") {
if let Ok(n) = v.parse::<u64>() {
if n > 0 {
cfg.truncate_high_water_pages = n;
}
}
}
if let Ok(v) = std::env::var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS") {
if let Ok(n) = v.parse::<u64>() {
if n > 0 {
cfg.truncate_min_interval = Duration::from_secs(n);
}
}
}
if let Ok(v) = std::env::var("KHIVE_WAL_TRUNCATE_BUSY_MS") {
if let Ok(n) = v.parse::<u64>() {
if n > 0 {
cfg.truncate_busy_timeout = Duration::from_millis(n);
}
}
}
if let Ok(v) = std::env::var("KHIVE_TX_WARN_SECS") {
if let Ok(n) = v.parse::<u64>() {
if n > 0 {
cfg.tx_warn_secs = Duration::from_secs(n);
}
}
}
if let Ok(v) = std::env::var("KHIVE_TX_MAX_AGE_SECS") {
if let Ok(n) = v.parse::<u64>() {
if n > 0 {
cfg.tx_max_age_secs = Duration::from_secs(n);
}
}
}
if cfg.tx_warn_secs >= cfg.tx_max_age_secs {
let default = Self::default();
tracing::warn!(
configured_tx_warn_secs = cfg.tx_warn_secs.as_secs_f64(),
configured_tx_max_age_secs = cfg.tx_max_age_secs.as_secs_f64(),
fallback_tx_warn_secs = default.tx_warn_secs.as_secs_f64(),
fallback_tx_max_age_secs = default.tx_max_age_secs.as_secs_f64(),
"KHIVE_TX_WARN_SECS must be strictly less than KHIVE_TX_MAX_AGE_SECS; \
both transaction-age thresholds were rejected and reset to their defaults"
);
cfg.tx_warn_secs = default.tx_warn_secs;
cfg.tx_max_age_secs = default.tx_max_age_secs;
}
cfg
}
}
#[derive(Debug, Default)]
pub struct TruncateState {
last_attempt: Option<Instant>,
consecutive_failures: u32,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
pub enum CheckpointSeverityRung {
Info,
Warn,
Alarm,
}
#[derive(Debug, Default, Clone)]
pub struct CheckpointSeverityState {
was_above_warn: bool,
consecutive_above_warn: u8,
warn_emitted_for_episode: bool,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
pub struct CheckpointSeverityEmission {
pub rung: CheckpointSeverityRung,
pub wal_pages: u64,
pub threshold_pages: u64,
pub consecutive_cycles: u8,
}
impl CheckpointSeverityState {
pub fn observe_wal_pages(
&mut self,
wal_pages: u64,
config: &CheckpointConfig,
) -> Vec<CheckpointSeverityEmission> {
let mut emissions = Vec::new();
let above_warn = wal_pages >= config.warn_pages;
if above_warn {
self.consecutive_above_warn = self.consecutive_above_warn.saturating_add(1);
if !self.was_above_warn {
emissions.push(CheckpointSeverityEmission {
rung: CheckpointSeverityRung::Info,
wal_pages,
threshold_pages: config.warn_pages,
consecutive_cycles: self.consecutive_above_warn,
});
}
if !self.warn_emitted_for_episode
&& self.consecutive_above_warn >= config.warn_sustained_cycles
{
emissions.push(CheckpointSeverityEmission {
rung: CheckpointSeverityRung::Warn,
wal_pages,
threshold_pages: config.warn_pages,
consecutive_cycles: self.consecutive_above_warn,
});
self.warn_emitted_for_episode = true;
}
} else {
self.consecutive_above_warn = 0;
self.warn_emitted_for_episode = false;
}
self.was_above_warn = above_warn;
emissions
}
}
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
pub enum TxAgeRung {
Warn,
Stale,
}
#[derive(Debug, Clone, PartialEq, Eq)]
pub struct TxAgeEmission {
pub rung: TxAgeRung,
pub age: Duration,
pub label: Option<String>,
}
#[derive(Debug, Default, Clone)]
pub struct TxAgeSweepState {
was_above_warn: bool,
was_above_max_age: bool,
tracked_id: Option<khive_storage::tx_registry::TxId>,
}
impl TxAgeSweepState {
pub fn observe(
&mut self,
oldest: Option<(khive_storage::tx_registry::TxId, Duration, Option<String>)>,
config: &CheckpointConfig,
) -> Vec<TxAgeEmission> {
let mut emissions = Vec::new();
let Some((id, age, label)) = oldest else {
self.was_above_warn = false;
self.was_above_max_age = false;
self.tracked_id = None;
return emissions;
};
if self.tracked_id != Some(id) {
self.was_above_warn = false;
self.was_above_max_age = false;
}
self.tracked_id = Some(id);
let above_warn = age >= config.tx_warn_secs;
let above_max_age = age >= config.tx_max_age_secs;
if above_warn && !self.was_above_warn {
emissions.push(TxAgeEmission {
rung: TxAgeRung::Warn,
age,
label: label.clone(),
});
}
if above_max_age && !self.was_above_max_age {
emissions.push(TxAgeEmission {
rung: TxAgeRung::Stale,
age,
label,
});
}
self.was_above_warn = above_warn;
self.was_above_max_age = above_max_age;
emissions
}
}
fn log_tx_age_emission(emission: &TxAgeEmission) {
let label = emission.label.as_deref().unwrap_or("<unlabeled>");
match emission.rung {
TxAgeRung::Warn => {
tracing::warn!(
tx_age_secs = emission.age.as_secs_f64(),
tx_label = label,
"ADR-091 Plank 1: open transaction registry entry exceeded soft-cap age"
);
}
TxAgeRung::Stale => {
tracing::error!(
tx_age_secs = emission.age.as_secs_f64(),
tx_label = label,
"ADR-091 Plank 1: open transaction registry entry exceeded the cooperative \
stale-op cap; no in-process mechanism can force-close it — investigate the \
labeled caller directly"
);
}
}
}
pub async fn run_checkpoint_task(
pool: Arc<ConnectionPool>,
config: CheckpointConfig,
event_store: Option<Arc<dyn khive_storage::EventStore>>,
namespace: String,
mut shutdown_rx: tokio::sync::watch::Receiver<()>,
) {
let mut interval = tokio::time::interval(config.interval);
interval.set_missed_tick_behavior(tokio::time::MissedTickBehavior::Skip);
let mut severity_state = CheckpointSeverityState::default();
let mut tx_age_state = TxAgeSweepState::default();
let mut was_above_high_water = false;
let mut truncate_state = TruncateState::default();
let mut event_was_elevated = false;
loop {
tokio::select! {
_ = interval.tick() => {}
_ = shutdown_rx.changed() => break,
}
let tick = checkpoint_once(&pool, &config, &mut truncate_state);
for emission in tx_age_state.observe(khive_storage::tx_registry::oldest(), &config) {
log_tx_age_emission(&emission);
}
let wal_pages = match tick {
CheckpointTick::Skipped => continue,
CheckpointTick::Observed(n) => n,
};
let above_warn = wal_pages >= config.warn_pages;
let above_high_water = wal_pages >= config.high_water_pages;
let above_truncate_high_water = wal_pages >= config.truncate_high_water_pages;
log_tx_registry_oldest_debug(wal_pages);
for emission in severity_state.observe_wal_pages(wal_pages, &config) {
match emission.rung {
CheckpointSeverityRung::Info => {
log_tx_registry_oldest_warn(wal_pages);
tracing::info!(
wal_pages = emission.wal_pages,
warn_threshold = emission.threshold_pages,
"WAL page count crossed warn threshold"
);
}
CheckpointSeverityRung::Warn => {
tracing::warn!(
wal_pages = emission.wal_pages,
warn_threshold = emission.threshold_pages,
consecutive_cycles = emission.consecutive_cycles,
"WAL page count failed to drain below warn threshold"
);
}
CheckpointSeverityRung::Alarm => {
}
}
}
let high_water_crossed = crossing_warn(above_high_water, &mut was_above_high_water);
if high_water_crossed {
log_tx_registry_snapshot_warn(wal_pages);
tracing::warn!(
wal_pages,
high_water = config.high_water_pages,
"WAL high-water mark exceeded; sustained WAL pressure — \
a long-lived reader may be pinning an old snapshot that PASSIVE cannot reclaim"
);
}
if checkpoint_outcome_should_emit(above_warn, event_was_elevated) {
let payload = khive_storage::CheckpointOutcomeRecordedPayload {
wal_pages,
warn_pages: config.warn_pages,
high_water_pages: config.high_water_pages,
truncate_high_water_pages: config.truncate_high_water_pages,
above_warn,
above_high_water,
above_truncate_high_water,
};
append_checkpoint_lifecycle_event(
event_store.as_ref(),
&namespace,
khive_types::EventKind::CheckpointOutcomeRecorded,
payload,
)
.await;
}
event_was_elevated = above_warn;
}
}
fn checkpoint_outcome_should_emit(above_warn: bool, was_elevated: bool) -> bool {
above_warn || was_elevated
}
async fn append_checkpoint_lifecycle_event<P: serde::Serialize>(
store: Option<&Arc<dyn khive_storage::EventStore>>,
namespace: &str,
kind: khive_types::EventKind,
payload: P,
) {
let Some(store) = store else {
return;
};
let payload_value = match serde_json::to_value(&payload) {
Ok(v) => v,
Err(e) => {
tracing::warn!(
error = %e,
event_kind = %kind.name(),
"failed to serialize checkpoint lifecycle event payload"
);
return;
}
};
let event = khive_storage::Event::new(
namespace,
"checkpoint.lifecycle",
kind,
khive_types::SubstrateKind::Event,
"daemon:checkpoint_task",
)
.with_payload(payload_value);
if let Err(err) = store.append_event(event).await {
tracing::warn!(
error = %err,
event_kind = %kind.name(),
"checkpoint lifecycle event append failed"
);
}
}
fn log_tx_registry_oldest_debug(wal_pages: u64) {
if let Some((_id, age, label)) = khive_storage::tx_registry::oldest() {
tracing::debug!(
wal_pages,
oldest_tx_age_secs = age.as_secs_f64(),
oldest_tx_label = label.as_deref().unwrap_or("<unlabeled>"),
"WAL checkpoint tick: oldest open transaction registry entry"
);
}
}
fn log_tx_registry_oldest_warn(wal_pages: u64) {
if let Some((_id, age, label)) = khive_storage::tx_registry::oldest() {
tracing::warn!(
wal_pages,
oldest_tx_age_secs = age.as_secs_f64(),
oldest_tx_label = label.as_deref().unwrap_or("<unlabeled>"),
"WAL checkpoint tick: oldest open transaction registry entry"
);
}
}
fn log_tx_registry_snapshot_warn(wal_pages: u64) {
for (age, label) in khive_storage::tx_registry::snapshot() {
tracing::warn!(
wal_pages,
tx_age_secs = age.as_secs_f64(),
tx_label = label.as_deref().unwrap_or("<unlabeled>"),
"WAL high-water: open transaction registry entry"
);
}
}
pub fn checkpoint_once(
pool: &ConnectionPool,
config: &CheckpointConfig,
truncate_state: &mut TruncateState,
) -> CheckpointTick {
let writer = match pool.try_writer_nowait() {
Ok(w) => w,
Err(_) => {
note_checkpoint_skipped();
return CheckpointTick::Skipped;
}
};
let wal_pages = query_wal_pages(writer.conn());
if let Err(e) = writer
.conn()
.execute_batch("PRAGMA wal_checkpoint(PASSIVE)")
{
tracing::warn!(error = %e, "WAL checkpoint failed");
} else {
tracing::debug!(wal_pages, "WAL checkpoint issued");
}
maybe_truncate(pool, &writer, config, wal_pages, truncate_state);
CheckpointTick::Observed(wal_pages)
}
fn maybe_truncate(
pool: &ConnectionPool,
writer: &WriterGuard<'_>,
config: &CheckpointConfig,
wal_pages_before: u64,
truncate_state: &mut TruncateState,
) {
if wal_pages_before < config.truncate_high_water_pages {
return;
}
if let Some(last) = truncate_state.last_attempt {
if last.elapsed() < config.truncate_min_interval {
return;
}
}
log_tx_registry_snapshot_warn(wal_pages_before);
let conn = writer.conn();
let original_busy_timeout = pool.config().busy_timeout;
if let Err(e) = conn.busy_timeout(config.truncate_busy_timeout) {
tracing::warn!(error = %e, "failed to lower busy_timeout for TRUNCATE attempt; skipping");
return;
}
truncate_state.last_attempt = Some(Instant::now());
let start = Instant::now();
let outcome = conn.execute_batch("PRAGMA wal_checkpoint(TRUNCATE)");
let elapsed = start.elapsed();
if let Err(e) = conn.busy_timeout(original_busy_timeout) {
tracing::warn!(error = %e, "failed to restore busy_timeout after TRUNCATE attempt");
}
match outcome {
Ok(()) => {
let wal_pages_after = query_wal_pages(conn);
tracing::info!(
wal_pages_before,
wal_pages_after,
elapsed_ms = elapsed.as_millis() as u64,
"WAL TRUNCATE checkpoint attempted"
);
let made_progress = wal_pages_after < wal_pages_before;
if !made_progress {
tracing::warn!(
wal_pages_before,
wal_pages_after,
"WAL TRUNCATE attempt made no progress; \
a long-lived reader may still be pinning the WAL snapshot"
);
log_tx_registry_snapshot_warn(wal_pages_after);
}
note_truncate_outcome(config, wal_pages_after, truncate_state);
}
Err(e) => {
tracing::warn!(error = %e, wal_pages_before, "WAL TRUNCATE attempt failed");
log_tx_registry_snapshot_warn(wal_pages_before);
note_truncate_outcome(config, wal_pages_before, truncate_state);
}
}
}
fn note_truncate_outcome(
config: &CheckpointConfig,
wal_pages_after: u64,
state: &mut TruncateState,
) {
TRUNCATE_ATTEMPTS.fetch_add(1, Ordering::Relaxed);
if wal_pages_after >= config.warn_pages {
state.consecutive_failures = state.consecutive_failures.saturating_add(1);
if state.consecutive_failures == 3 {
tracing::warn!(
wal_pages_after,
warn_threshold = config.warn_pages,
"WAL TRUNCATE has failed to clear WAL pressure for 3 consecutive attempts"
);
}
} else {
state.consecutive_failures = 0;
}
TRUNCATE_CONSECUTIVE_FAILURES.store(state.consecutive_failures as u64, Ordering::Relaxed);
}
fn crossing_warn(now_above: bool, was_above: &mut bool) -> bool {
let fire = now_above && !*was_above;
*was_above = now_above;
fire
}
fn query_wal_pages(conn: &rusqlite::Connection) -> u64 {
let pages = conn
.query_row("PRAGMA wal_checkpoint", [], |row| row.get::<_, i64>(1))
.unwrap_or(0)
.max(0) as u64;
LAST_WAL_PAGES.store(pages, Ordering::Relaxed);
note_checkpoint_observed(pages);
pages
}
#[cfg(test)]
mod tests {
use super::*;
use crate::pool::PoolConfig;
use serial_test::serial;
use tracing::field::{Field, Visit};
#[derive(Clone, Debug, Default)]
struct CapturedEvent {
message: Option<String>,
oldest_tx_label: Option<String>,
tx_label: Option<String>,
}
#[derive(Default)]
struct CapturedEventVisitor(CapturedEvent);
impl Visit for CapturedEventVisitor {
fn record_str(&mut self, field: &Field, value: &str) {
match field.name() {
"message" => self.0.message = Some(value.to_string()),
"oldest_tx_label" => self.0.oldest_tx_label = Some(value.to_string()),
"tx_label" => self.0.tx_label = Some(value.to_string()),
_ => {}
}
}
fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
let formatted = format!("{value:?}");
let cleaned = formatted
.trim_start_matches('"')
.trim_end_matches('"')
.to_string();
match field.name() {
"message" => self.0.message = Some(cleaned),
"oldest_tx_label" => self.0.oldest_tx_label = Some(cleaned),
"tx_label" => self.0.tx_label = Some(cleaned),
_ => {}
}
}
}
struct CaptureSubscriber {
events: std::sync::Arc<std::sync::Mutex<Vec<CapturedEvent>>>,
}
impl tracing::Subscriber for CaptureSubscriber {
fn enabled(&self, _: &tracing::Metadata<'_>) -> bool {
true
}
fn new_span(&self, _: &tracing::span::Attributes<'_>) -> tracing::span::Id {
tracing::span::Id::from_u64(1)
}
fn record(&self, _: &tracing::span::Id, _: &tracing::span::Record<'_>) {}
fn record_follows_from(&self, _: &tracing::span::Id, _: &tracing::span::Id) {}
fn event(&self, event: &tracing::Event<'_>) {
let mut visitor = CapturedEventVisitor::default();
event.record(&mut visitor);
self.events.lock().unwrap().push(visitor.0);
}
fn enter(&self, _: &tracing::span::Id) {}
fn exit(&self, _: &tracing::span::Id) {}
}
#[test]
#[serial(tx_registry)]
fn log_tx_registry_oldest_debug_reports_oldest_open_entry() {
let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
let subscriber = CaptureSubscriber {
events: std::sync::Arc::clone(&buffer),
};
let _handle =
khive_storage::tx_registry::register(Some("checkpoint_tick_test".to_string()));
let expected_label = khive_storage::tx_registry::oldest()
.and_then(|(_, _, label)| label)
.unwrap_or_else(|| "<unlabeled>".to_string());
tracing::subscriber::with_default(subscriber, || {
log_tx_registry_oldest_debug(100);
});
let events = buffer.lock().unwrap();
assert!(
events.iter().any(|e| {
e.message.as_deref()
== Some("WAL checkpoint tick: oldest open transaction registry entry")
&& e.oldest_tx_label.as_deref() == Some(expected_label.as_str())
}),
"expected a log line naming the open registry entry's label, got: {events:?}"
);
}
#[test]
#[serial(tx_registry)]
fn registry_warns_fire_on_crossing_and_do_not_repeat() {
let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
let subscriber = CaptureSubscriber {
events: std::sync::Arc::clone(&buffer),
};
let _handle =
khive_storage::tx_registry::register(Some("registry_warn_crossing_test".to_string()));
let mut was_above_warn = false;
let mut was_above_high_water = false;
tracing::subscriber::with_default(subscriber, || {
if crossing_warn(true, &mut was_above_warn) {
log_tx_registry_oldest_warn(6000);
}
if crossing_warn(true, &mut was_above_high_water) {
log_tx_registry_snapshot_warn(6000);
}
if crossing_warn(true, &mut was_above_warn) {
log_tx_registry_oldest_warn(6000);
}
if crossing_warn(true, &mut was_above_high_water) {
log_tx_registry_snapshot_warn(6000);
}
});
let events = buffer.lock().unwrap();
let oldest_warn_count = events
.iter()
.filter(|e| {
e.message.as_deref()
== Some("WAL checkpoint tick: oldest open transaction registry entry")
})
.count();
assert_eq!(
oldest_warn_count, 1,
"oldest-entry WARN must fire exactly once across two above-threshold ticks, got: {events:?}"
);
let snapshot_warn_count = events
.iter()
.filter(|e| {
e.message.as_deref() == Some("WAL high-water: open transaction registry entry")
&& e.tx_label.as_deref() == Some("registry_warn_crossing_test")
})
.count();
assert_eq!(
snapshot_warn_count, 1,
"high-water snapshot WARN must fire exactly once across two above-threshold ticks, got: {events:?}"
);
}
#[test]
fn log_tx_age_emission_carries_label_for_both_rungs() {
let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
let subscriber = CaptureSubscriber {
events: std::sync::Arc::clone(&buffer),
};
tracing::subscriber::with_default(subscriber, || {
log_tx_age_emission(&TxAgeEmission {
rung: TxAgeRung::Warn,
age: Duration::from_secs(45),
label: Some("plank1_warn_test".to_string()),
});
log_tx_age_emission(&TxAgeEmission {
rung: TxAgeRung::Stale,
age: Duration::from_secs(150),
label: Some("plank1_stale_test".to_string()),
});
});
let events = buffer.lock().unwrap();
assert!(
events.iter().any(|e| {
e.message.as_deref()
== Some(
"ADR-091 Plank 1: open transaction registry entry exceeded soft-cap age",
)
&& e.tx_label.as_deref() == Some("plank1_warn_test")
}),
"expected a Warn-rung log line naming the entry, got: {events:?}"
);
assert!(
events.iter().any(|e| {
e.message.as_deref().is_some_and(|m| {
m.starts_with(
"ADR-091 Plank 1: open transaction registry entry exceeded the cooperative",
)
}) && e.tx_label.as_deref() == Some("plank1_stale_test")
}),
"expected a Stale-rung log line naming the entry, got: {events:?}"
);
}
fn file_pool(path: &std::path::Path) -> Arc<ConnectionPool> {
let cfg = PoolConfig {
path: Some(path.to_path_buf()),
..PoolConfig::default()
};
Arc::new(ConnectionPool::new(cfg).expect("pool open"))
}
#[test]
#[serial(checkpoint_skip_metrics)]
fn checkpoint_once_succeeds_on_file_backed_pool() {
let dir = tempfile::tempdir().unwrap();
let path = dir.path().join("wal_test.db");
let pool = file_pool(&path);
{
let writer = pool.try_writer().unwrap();
writer
.conn()
.execute_batch("CREATE TABLE IF NOT EXISTS t (x INTEGER);")
.unwrap();
writer
.conn()
.execute_batch("INSERT INTO t VALUES (1);")
.unwrap();
}
checkpoint_once(
&pool,
&CheckpointConfig::default(),
&mut TruncateState::default(),
);
}
#[test]
#[serial(checkpoint_skip_metrics)]
fn checkpoint_once_is_noop_on_in_memory_pool() {
let cfg = PoolConfig {
path: None,
..PoolConfig::default()
};
let pool = Arc::new(ConnectionPool::new(cfg).expect("in-memory pool"));
checkpoint_once(
&pool,
&CheckpointConfig::default(),
&mut TruncateState::default(),
);
}
#[tokio::test]
#[serial(checkpoint_skip_metrics)]
async fn checkpoint_task_exits_on_shutdown_signal() {
let dir = tempfile::tempdir().unwrap();
let path = dir.path().join("wal_task_shutdown.db");
let pool = file_pool(&path);
let cfg = CheckpointConfig {
interval: Duration::from_millis(10),
..Default::default()
};
let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
let handle = tokio::spawn(run_checkpoint_task(
pool,
cfg,
None,
"local".to_string(),
shutdown_rx,
));
shutdown_tx.send(()).expect("send shutdown signal");
tokio::time::timeout(Duration::from_secs(1), handle)
.await
.expect("checkpoint task should exit within 1s")
.expect("checkpoint task panicked");
}
#[tokio::test]
#[serial(checkpoint_skip_metrics)]
async fn checkpoint_task_exits_via_shutdown_signal_with_live_event_store_pool_clone() {
let dir = tempfile::tempdir().unwrap();
let path = dir.path().join("wal_task_event_store.db");
let pool = file_pool(&path);
let cfg = CheckpointConfig {
interval: Duration::from_millis(10),
..Default::default()
};
let event_store: Arc<dyn khive_storage::EventStore> =
Arc::new(crate::stores::event::SqlEventStore::new_scoped(
Arc::clone(&pool),
true,
"local".to_string(),
));
let sibling_pool_clone = Arc::clone(&pool);
let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
let handle = tokio::spawn(run_checkpoint_task(
pool,
cfg,
Some(event_store),
"local".to_string(),
shutdown_rx,
));
assert!(
Arc::strong_count(&sibling_pool_clone) > 1,
"test setup must reproduce the multi-owner shape the bug depends on"
);
shutdown_tx.send(()).expect("send shutdown signal");
tokio::time::timeout(Duration::from_secs(1), handle)
.await
.expect(
"checkpoint task should exit within 1s via the watch signal, \
even with a live sibling Arc<ConnectionPool> clone held by \
the event store",
)
.expect("checkpoint task panicked");
}
#[test]
#[serial]
fn checkpoint_config_env_override() {
std::env::set_var("KHIVE_CHECKPOINT_INTERVAL_MS", "250");
std::env::set_var("KHIVE_WAL_WARN_PAGES", "1500");
std::env::set_var("KHIVE_WAL_HIGH_WATER_PAGES", "8000");
std::env::set_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES", "12000");
std::env::set_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS", "60");
std::env::set_var("KHIVE_WAL_TRUNCATE_BUSY_MS", "500");
std::env::set_var("KHIVE_TX_WARN_SECS", "15");
std::env::set_var("KHIVE_TX_MAX_AGE_SECS", "90");
let cfg = CheckpointConfig::from_env();
std::env::remove_var("KHIVE_CHECKPOINT_INTERVAL_MS");
std::env::remove_var("KHIVE_WAL_WARN_PAGES");
std::env::remove_var("KHIVE_WAL_HIGH_WATER_PAGES");
std::env::remove_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES");
std::env::remove_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS");
std::env::remove_var("KHIVE_WAL_TRUNCATE_BUSY_MS");
std::env::remove_var("KHIVE_TX_WARN_SECS");
std::env::remove_var("KHIVE_TX_MAX_AGE_SECS");
assert_eq!(cfg.interval, Duration::from_millis(250));
assert_eq!(cfg.warn_pages, 1500);
assert_eq!(cfg.high_water_pages, 8000);
assert_eq!(cfg.truncate_high_water_pages, 12000);
assert_eq!(cfg.truncate_min_interval, Duration::from_secs(60));
assert_eq!(cfg.truncate_busy_timeout, Duration::from_millis(500));
assert_eq!(cfg.tx_warn_secs, Duration::from_secs(15));
assert_eq!(cfg.tx_max_age_secs, Duration::from_secs(90));
}
#[test]
#[serial]
fn checkpoint_config_defaults_on_invalid_env() {
let default = CheckpointConfig::default();
std::env::set_var("KHIVE_CHECKPOINT_INTERVAL_MS", "not_a_number");
std::env::set_var("KHIVE_WAL_WARN_PAGES", "");
std::env::set_var("KHIVE_WAL_HIGH_WATER_PAGES", "0");
std::env::set_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES", "not_a_number");
std::env::set_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS", "");
std::env::set_var("KHIVE_WAL_TRUNCATE_BUSY_MS", "0");
std::env::set_var("KHIVE_TX_WARN_SECS", "not_a_number");
std::env::set_var("KHIVE_TX_MAX_AGE_SECS", "0");
let cfg = CheckpointConfig::from_env();
std::env::remove_var("KHIVE_CHECKPOINT_INTERVAL_MS");
std::env::remove_var("KHIVE_WAL_WARN_PAGES");
std::env::remove_var("KHIVE_WAL_HIGH_WATER_PAGES");
std::env::remove_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES");
std::env::remove_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS");
std::env::remove_var("KHIVE_WAL_TRUNCATE_BUSY_MS");
std::env::remove_var("KHIVE_TX_WARN_SECS");
std::env::remove_var("KHIVE_TX_MAX_AGE_SECS");
assert_eq!(cfg.interval, default.interval);
assert_eq!(cfg.warn_pages, default.warn_pages);
assert_eq!(cfg.high_water_pages, default.high_water_pages);
assert_eq!(
cfg.truncate_high_water_pages,
default.truncate_high_water_pages
);
assert_eq!(cfg.truncate_min_interval, default.truncate_min_interval);
assert_eq!(cfg.truncate_busy_timeout, default.truncate_busy_timeout);
assert_eq!(cfg.tx_warn_secs, default.tx_warn_secs);
assert_eq!(cfg.tx_max_age_secs, default.tx_max_age_secs);
}
#[test]
#[serial(checkpoint_skip_metrics)]
fn checkpoint_high_water_does_not_block_behind_reader() {
let dir = tempfile::tempdir().unwrap();
let path = dir.path().join("high_water_test.db");
let pool = Arc::new(
ConnectionPool::new(PoolConfig {
path: Some(path.clone()),
busy_timeout: Duration::from_millis(2000),
..PoolConfig::default()
})
.expect("pool open"),
);
{
let writer = pool.try_writer().unwrap();
writer
.conn()
.execute_batch(
"CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
)
.unwrap();
}
let reader = pool.reader().expect("reader");
reader
.execute_batch("BEGIN DEFERRED; SELECT * FROM t;")
.expect("begin read tx");
{
let writer = pool.try_writer().unwrap();
writer
.conn()
.execute_batch("INSERT INTO t VALUES (2);")
.unwrap();
}
let start = std::time::Instant::now();
checkpoint_once(
&pool,
&CheckpointConfig::default(),
&mut TruncateState::default(),
);
let elapsed = start.elapsed();
reader.execute_batch("COMMIT;").ok();
drop(reader);
assert!(
elapsed < std::time::Duration::from_millis(500),
"checkpoint_once with active reader snapshot took {:?}; \
expected <500ms (PASSIVE must not block on readers; \
a TRUNCATE regression would block ~2000ms)",
elapsed
);
}
#[test]
#[serial]
fn checkpoint_config_rejects_zero_for_all_fields() {
let default = CheckpointConfig::default();
std::env::set_var("KHIVE_CHECKPOINT_INTERVAL_MS", "0");
std::env::set_var("KHIVE_WAL_WARN_PAGES", "0");
std::env::set_var("KHIVE_WAL_HIGH_WATER_PAGES", "0");
std::env::set_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES", "0");
std::env::set_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS", "0");
std::env::set_var("KHIVE_WAL_TRUNCATE_BUSY_MS", "0");
std::env::set_var("KHIVE_TX_WARN_SECS", "0");
std::env::set_var("KHIVE_TX_MAX_AGE_SECS", "0");
let cfg = CheckpointConfig::from_env();
std::env::remove_var("KHIVE_CHECKPOINT_INTERVAL_MS");
std::env::remove_var("KHIVE_WAL_WARN_PAGES");
std::env::remove_var("KHIVE_WAL_HIGH_WATER_PAGES");
std::env::remove_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES");
std::env::remove_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS");
std::env::remove_var("KHIVE_WAL_TRUNCATE_BUSY_MS");
std::env::remove_var("KHIVE_TX_WARN_SECS");
std::env::remove_var("KHIVE_TX_MAX_AGE_SECS");
assert_eq!(
cfg.interval, default.interval,
"zero interval must fall back to default"
);
assert_eq!(
cfg.warn_pages, default.warn_pages,
"zero warn_pages must fall back to default"
);
assert_eq!(
cfg.high_water_pages, default.high_water_pages,
"zero high_water_pages must fall back to default"
);
assert_eq!(
cfg.truncate_high_water_pages, default.truncate_high_water_pages,
"zero truncate_high_water_pages must fall back to default"
);
assert_eq!(
cfg.truncate_min_interval, default.truncate_min_interval,
"zero truncate_min_interval must fall back to default"
);
assert_eq!(
cfg.truncate_busy_timeout, default.truncate_busy_timeout,
"zero truncate_busy_timeout must fall back to default"
);
assert_eq!(
cfg.tx_warn_secs, default.tx_warn_secs,
"zero tx_warn_secs must fall back to default"
);
assert_eq!(
cfg.tx_max_age_secs, default.tx_max_age_secs,
"zero tx_max_age_secs must fall back to default"
);
}
#[test]
#[serial]
fn checkpoint_config_rejects_reversed_tx_thresholds() {
let default = CheckpointConfig::default();
std::env::set_var("KHIVE_TX_WARN_SECS", "120");
std::env::set_var("KHIVE_TX_MAX_AGE_SECS", "30");
let cfg = CheckpointConfig::from_env();
std::env::remove_var("KHIVE_TX_WARN_SECS");
std::env::remove_var("KHIVE_TX_MAX_AGE_SECS");
assert_eq!(
cfg.tx_warn_secs, default.tx_warn_secs,
"a reversed pair must fall back tx_warn_secs to its default, got: {:?}",
cfg.tx_warn_secs
);
assert_eq!(
cfg.tx_max_age_secs, default.tx_max_age_secs,
"a reversed pair must fall back tx_max_age_secs to its default, got: {:?}",
cfg.tx_max_age_secs
);
}
#[test]
#[serial]
fn checkpoint_config_rejects_equal_tx_thresholds() {
let default = CheckpointConfig::default();
std::env::set_var("KHIVE_TX_WARN_SECS", "60");
std::env::set_var("KHIVE_TX_MAX_AGE_SECS", "60");
let cfg = CheckpointConfig::from_env();
std::env::remove_var("KHIVE_TX_WARN_SECS");
std::env::remove_var("KHIVE_TX_MAX_AGE_SECS");
assert_eq!(
cfg.tx_warn_secs, default.tx_warn_secs,
"an equal pair must fall back tx_warn_secs to its default, got: {:?}",
cfg.tx_warn_secs
);
assert_eq!(
cfg.tx_max_age_secs, default.tx_max_age_secs,
"an equal pair must fall back tx_max_age_secs to its default, got: {:?}",
cfg.tx_max_age_secs
);
}
#[test]
fn skipped_tick_does_not_reset_high_water_crossing_state() {
let mut was_above = false;
assert!(
crossing_warn(true, &mut was_above),
"should fire on first crossing"
);
assert!(was_above);
assert!(was_above, "was_above must stay true across skipped ticks");
let fired = crossing_warn(true, &mut was_above);
assert!(!fired, "WARN must not re-fire while still above threshold");
let fired = crossing_warn(false, &mut was_above);
assert!(!fired);
assert!(!was_above);
let fired = crossing_warn(true, &mut was_above);
assert!(fired, "WARN must fire again on a new below→above crossing");
}
#[test]
fn warn_pages_fires_once_on_crossing_not_every_tick() {
let mut was_above_warn = false;
let fired_1 = crossing_warn(true, &mut was_above_warn);
let fired_2 = crossing_warn(true, &mut was_above_warn);
let fired_3 = crossing_warn(true, &mut was_above_warn);
assert!(fired_1, "WARN must fire on the first in-band tick");
assert!(
!fired_2,
"WARN must not fire on the second consecutive in-band tick"
);
assert!(
!fired_3,
"WARN must not fire on the third consecutive in-band tick"
);
crossing_warn(false, &mut was_above_warn);
assert!(!was_above_warn);
let fired_reentry = crossing_warn(true, &mut was_above_warn);
assert!(
fired_reentry,
"WARN must fire again on re-entry into warn band"
);
}
#[test]
#[serial(tx_registry, checkpoint_skip_metrics)]
fn truncate_attempts_when_high_water_crossed_with_no_prior_attempt() {
let dir = tempfile::tempdir().unwrap();
let path = dir.path().join("truncate_trigger.db");
let pool = file_pool(&path);
{
let writer = pool.try_writer().unwrap();
writer
.conn()
.execute_batch(
"CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
)
.unwrap();
}
let config = CheckpointConfig {
truncate_high_water_pages: 0,
truncate_min_interval: Duration::from_secs(300),
..CheckpointConfig::default()
};
let mut state = TruncateState::default();
assert!(
state.last_attempt.is_none(),
"precondition: no attempt has run yet"
);
let tick = checkpoint_once(&pool, &config, &mut state);
assert!(matches!(tick, CheckpointTick::Observed(_)));
assert!(
state.last_attempt.is_some(),
"an attempt must be stamped once the high-water threshold is crossed"
);
}
#[test]
#[serial(tx_registry, checkpoint_skip_metrics)]
fn truncate_does_not_attempt_below_high_water() {
let dir = tempfile::tempdir().unwrap();
let path = dir.path().join("truncate_below_threshold.db");
let pool = file_pool(&path);
{
let writer = pool.try_writer().unwrap();
writer
.conn()
.execute_batch(
"CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
)
.unwrap();
}
let config = CheckpointConfig {
truncate_high_water_pages: u64::MAX,
..CheckpointConfig::default()
};
let mut state = TruncateState::default();
checkpoint_once(&pool, &config, &mut state);
assert!(
state.last_attempt.is_none(),
"a below-threshold tick must never stamp last_attempt"
);
}
#[test]
#[serial(tx_registry, checkpoint_skip_metrics)]
fn truncate_min_interval_skip_does_not_restamp_last_attempt() {
let dir = tempfile::tempdir().unwrap();
let path = dir.path().join("truncate_min_interval.db");
let pool = file_pool(&path);
{
let writer = pool.try_writer().unwrap();
writer
.conn()
.execute_batch(
"CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
)
.unwrap();
}
let config = CheckpointConfig {
truncate_high_water_pages: 0,
truncate_min_interval: Duration::from_secs(300),
..CheckpointConfig::default()
};
let mut state = TruncateState::default();
checkpoint_once(&pool, &config, &mut state);
let first_attempt = state.last_attempt.expect("first tick must attempt");
checkpoint_once(&pool, &config, &mut state);
let second_attempt = state.last_attempt.expect("attempt timestamp must persist");
assert_eq!(
first_attempt, second_attempt,
"a tick within truncate_min_interval must not re-stamp last_attempt"
);
}
#[test]
#[serial(tx_registry, checkpoint_skip_metrics)]
fn busy_writer_skips_both_passive_and_truncate() {
reset_checkpoint_metrics_for_tests();
let dir = tempfile::tempdir().unwrap();
let path = dir.path().join("truncate_busy_skip.db");
let pool = file_pool(&path);
{
let writer = pool.try_writer().unwrap();
writer
.conn()
.execute_batch(
"CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
)
.unwrap();
}
let mut warmup_state = TruncateState::default();
let warmup_tick = checkpoint_once(&pool, &CheckpointConfig::default(), &mut warmup_state);
let observed_pages = match warmup_tick {
CheckpointTick::Observed(n) => n,
CheckpointTick::Skipped => panic!("warmup tick must observe, not skip"),
};
assert_eq!(
checkpoint_consecutive_skips(),
0,
"an observed tick must not itself count as a skip"
);
let _held = pool.try_writer().unwrap();
let config = CheckpointConfig {
truncate_high_water_pages: 0,
..CheckpointConfig::default()
};
let mut state = TruncateState::default();
let tick = checkpoint_once(&pool, &config, &mut state);
assert_eq!(
tick,
CheckpointTick::Skipped,
"a busy writer must skip the tick entirely"
);
assert!(
state.last_attempt.is_none(),
"a skipped tick (writer busy) must never stamp last_attempt, \
even with a threshold that would otherwise arm immediately"
);
assert_eq!(
checkpoint_skipped_ticks(),
1,
"one skipped tick must bump the lifetime skipped-tick counter"
);
assert_eq!(
checkpoint_consecutive_skips(),
1,
"one skipped tick must bump the consecutive-skip run length"
);
assert_eq!(
checkpoint_last_skip_wal_pages(),
Some(observed_pages),
"the skip must snapshot the last-observed WAL pressure"
);
}
#[test]
fn all_checkpoint_metrics_callers_are_serial_tagged() {
const SELF_SRC: &str = include_str!("checkpoint.rs");
let lines: Vec<&str> = SELF_SRC.lines().collect();
let attr_starts: Vec<usize> = lines
.iter()
.enumerate()
.filter(|(_, l)| {
let t = l.trim();
t == "#[test]" || t.starts_with("#[tokio::test")
})
.map(|(i, _)| i)
.collect();
let mut offenders = Vec::new();
for (idx, &start) in attr_starts.iter().enumerate() {
let end = attr_starts.get(idx + 1).copied().unwrap_or(lines.len());
let span = &lines[start..end];
let touches_shared_metrics = span
.iter()
.any(|l| l.contains("checkpoint_once(") || l.contains("run_checkpoint_task("));
if !touches_shared_metrics {
continue;
}
let has_group_tag = span
.iter()
.any(|l| l.contains("#[serial") && l.contains("checkpoint_skip_metrics"));
if !has_group_tag {
let name = span
.iter()
.find_map(|l| {
let t = l.trim_start();
let t = t.strip_prefix("pub(crate) ").unwrap_or(t);
let t = t.strip_prefix("pub ").unwrap_or(t);
let t = t.strip_prefix("async ").unwrap_or(t);
t.strip_prefix("fn ")
.map(|rest| rest.split(['(', '<']).next().unwrap_or("").trim())
})
.unwrap_or("<unknown test>");
offenders.push(name.to_string());
}
}
assert!(
offenders.is_empty(),
"these tests call checkpoint_once/run_checkpoint_task (which write the \
process-wide LAST_WAL_PAGES/CHECKPOINT_* atomics via query_wal_pages) but \
are not tagged #[serial(checkpoint_skip_metrics)] (or a group including it); \
an untagged caller running concurrently on cargo's default test thread pool \
can clobber those atomics mid-assertion in another test (the #828/#845 race): \
{offenders:?}"
);
}
#[test]
#[serial(tx_registry, checkpoint_skip_metrics)]
fn observed_tick_resets_consecutive_skips_but_not_lifetime_total() {
reset_checkpoint_metrics_for_tests();
let dir = tempfile::tempdir().unwrap();
let path = dir.path().join("skip_then_observe.db");
let pool = file_pool(&path);
{
let writer = pool.try_writer().unwrap();
writer
.conn()
.execute_batch(
"CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
)
.unwrap();
}
{
let _held = pool.try_writer().unwrap();
let mut state = TruncateState::default();
for _ in 0..2 {
let tick = checkpoint_once(&pool, &CheckpointConfig::default(), &mut state);
assert_eq!(tick, CheckpointTick::Skipped);
}
}
assert_eq!(checkpoint_skipped_ticks(), 2);
assert_eq!(checkpoint_consecutive_skips(), 2);
let mut state = TruncateState::default();
let tick = checkpoint_once(&pool, &CheckpointConfig::default(), &mut state);
assert!(matches!(tick, CheckpointTick::Observed(_)));
assert_eq!(
checkpoint_skipped_ticks(),
2,
"an observed tick must not change the lifetime skipped-tick total"
);
assert_eq!(
checkpoint_consecutive_skips(),
0,
"an observed tick must reset the consecutive-skip run length"
);
}
#[test]
fn note_truncate_outcome_warns_once_at_third_consecutive_failure() {
let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
let subscriber = CaptureSubscriber {
events: std::sync::Arc::clone(&buffer),
};
let config = CheckpointConfig {
warn_pages: 2000,
..CheckpointConfig::default()
};
let mut state = TruncateState::default();
tracing::subscriber::with_default(subscriber, || {
note_truncate_outcome(&config, 5000, &mut state);
note_truncate_outcome(&config, 5000, &mut state);
note_truncate_outcome(&config, 5000, &mut state);
note_truncate_outcome(&config, 5000, &mut state);
});
assert_eq!(state.consecutive_failures, 4);
let events = buffer.lock().unwrap();
let escalation_count = events
.iter()
.filter(|e| {
e.message.as_deref()
== Some(
"WAL TRUNCATE has failed to clear WAL pressure for 3 consecutive attempts",
)
})
.count();
assert_eq!(
escalation_count, 1,
"escalation WARN must fire exactly once at the 3rd consecutive failure, got: {events:?}"
);
note_truncate_outcome(&config, 100, &mut state);
assert_eq!(
state.consecutive_failures, 0,
"an attempt that clears warn_pages must reset the consecutive-failure counter"
);
}
fn severity_test_config() -> CheckpointConfig {
CheckpointConfig {
warn_pages: 100,
warn_sustained_cycles: 3,
..CheckpointConfig::default()
}
}
#[test]
fn severity_ladder_info_on_first_crossing_no_warn() {
let config = severity_test_config();
let mut state = CheckpointSeverityState::default();
let below = state.observe_wal_pages(10, &config);
assert!(below.is_empty(), "below-warn tick must emit nothing");
let above = state.observe_wal_pages(150, &config);
assert_eq!(
above,
vec![CheckpointSeverityEmission {
rung: CheckpointSeverityRung::Info,
wal_pages: 150,
threshold_pages: 100,
consecutive_cycles: 1,
}],
"first below->above crossing must emit exactly one INFO and no WARN"
);
}
#[test]
fn severity_ladder_warn_on_third_consecutive_cycle() {
let config = severity_test_config();
let mut state = CheckpointSeverityState::default();
let tick1 = state.observe_wal_pages(150, &config);
assert_eq!(tick1.len(), 1);
assert_eq!(tick1[0].rung, CheckpointSeverityRung::Info);
let tick2 = state.observe_wal_pages(150, &config);
assert!(
tick2.is_empty(),
"second consecutive above-warn tick must emit nothing yet"
);
let tick3 = state.observe_wal_pages(150, &config);
assert_eq!(
tick3,
vec![CheckpointSeverityEmission {
rung: CheckpointSeverityRung::Warn,
wal_pages: 150,
threshold_pages: 100,
consecutive_cycles: 3,
}],
"WARN must fire exactly on the third consecutive above-warn tick"
);
let tick4 = state.observe_wal_pages(150, &config);
assert!(
tick4.is_empty(),
"WARN must not repeat on a fourth consecutive above-warn tick"
);
}
#[test]
fn severity_ladder_rearms_warn_after_drain() {
let config = severity_test_config();
let mut state = CheckpointSeverityState::default();
for _ in 0..3 {
state.observe_wal_pages(150, &config);
}
assert!(state.warn_emitted_for_episode);
let drain = state.observe_wal_pages(10, &config);
assert!(drain.is_empty(), "a draining tick must emit nothing");
let reentry = state.observe_wal_pages(150, &config);
assert_eq!(reentry.len(), 1);
assert_eq!(reentry[0].rung, CheckpointSeverityRung::Info);
let mid = state.observe_wal_pages(150, &config);
assert!(mid.is_empty());
let second_warn = state.observe_wal_pages(150, &config);
assert_eq!(
second_warn,
vec![CheckpointSeverityEmission {
rung: CheckpointSeverityRung::Warn,
wal_pages: 150,
threshold_pages: 100,
consecutive_cycles: 3,
}],
"a fresh elevation episode after a drain must WARN again"
);
}
#[test]
fn severity_ladder_isolated_crossings_never_warn() {
let config = severity_test_config();
let mut state = CheckpointSeverityState::default();
for _ in 0..3 {
let crossing = state.observe_wal_pages(150, &config);
assert_eq!(
crossing.len(),
1,
"each isolated crossing must emit exactly one INFO"
);
assert_eq!(crossing[0].rung, CheckpointSeverityRung::Info);
let drain = state.observe_wal_pages(10, &config);
assert!(drain.is_empty(), "the drain tick must emit nothing");
}
assert!(
!state.warn_emitted_for_episode,
"isolated single-tick crossings must never accumulate into a WARN"
);
}
#[test]
fn severity_ladder_never_emits_alarm() {
let config = CheckpointConfig {
warn_pages: 100,
warn_sustained_cycles: 1,
..CheckpointConfig::default()
};
let mut state = CheckpointSeverityState::default();
for wal_pages in [150, 200, 250, u64::MAX] {
let emissions = state.observe_wal_pages(wal_pages, &config);
assert!(
emissions
.iter()
.all(|e| e.rung != CheckpointSeverityRung::Alarm),
"observe_wal_pages must never emit the ALARM rung, got: {emissions:?}"
);
}
}
fn tx_age_test_config() -> CheckpointConfig {
CheckpointConfig {
tx_warn_secs: Duration::from_secs(30),
tx_max_age_secs: Duration::from_secs(120),
..CheckpointConfig::default()
}
}
fn tx_id(n: u64) -> khive_storage::tx_registry::TxId {
khive_storage::tx_registry::TxId(n)
}
#[test]
fn tx_age_sweep_empty_registry_emits_nothing() {
let config = tx_age_test_config();
let mut state = TxAgeSweepState::default();
let emissions = state.observe(None, &config);
assert!(emissions.is_empty(), "no open entry must emit nothing");
}
#[test]
fn tx_age_sweep_fresh_entry_emits_nothing() {
let config = tx_age_test_config();
let mut state = TxAgeSweepState::default();
let emissions = state.observe(
Some((
tx_id(1),
Duration::from_secs(5),
Some("fresh_span".to_string()),
)),
&config,
);
assert!(emissions.is_empty(), "a fresh entry must emit nothing");
}
#[test]
fn tx_age_sweep_warn_fires_once_on_crossing() {
let config = tx_age_test_config();
let mut state = TxAgeSweepState::default();
let tick1 = state.observe(
Some((
tx_id(1),
Duration::from_secs(45),
Some("stale_span".to_string()),
)),
&config,
);
assert_eq!(
tick1,
vec![TxAgeEmission {
rung: TxAgeRung::Warn,
age: Duration::from_secs(45),
label: Some("stale_span".to_string()),
}],
"crossing tx_warn_secs must emit exactly one Warn"
);
let tick2 = state.observe(
Some((
tx_id(1),
Duration::from_secs(50),
Some("stale_span".to_string()),
)),
&config,
);
assert!(
tick2.is_empty(),
"Warn must not repeat while the entry stays in the warn band"
);
}
#[test]
fn tx_age_sweep_stale_fires_once_on_crossing() {
let config = tx_age_test_config();
let mut state = TxAgeSweepState::default();
state.observe(
Some((
tx_id(1),
Duration::from_secs(45),
Some("stuck_writer_task_tx".to_string()),
)),
&config,
);
let tick = state.observe(
Some((
tx_id(1),
Duration::from_secs(130),
Some("stuck_writer_task_tx".to_string()),
)),
&config,
);
assert_eq!(
tick,
vec![TxAgeEmission {
rung: TxAgeRung::Stale,
age: Duration::from_secs(130),
label: Some("stuck_writer_task_tx".to_string()),
}],
"crossing tx_max_age_secs must emit exactly one Stale"
);
let tick_repeat = state.observe(
Some((
tx_id(1),
Duration::from_secs(200),
Some("stuck_writer_task_tx".to_string()),
)),
&config,
);
assert!(
tick_repeat.is_empty(),
"Stale must not repeat while the entry stays above tx_max_age_secs"
);
}
#[test]
fn tx_age_sweep_already_stale_entry_emits_both_rungs_same_tick() {
let config = tx_age_test_config();
let mut state = TxAgeSweepState::default();
let tick = state.observe(
Some((
tx_id(1),
Duration::from_secs(300),
Some("ancient_tx".to_string()),
)),
&config,
);
assert_eq!(
tick,
vec![
TxAgeEmission {
rung: TxAgeRung::Warn,
age: Duration::from_secs(300),
label: Some("ancient_tx".to_string()),
},
TxAgeEmission {
rung: TxAgeRung::Stale,
age: Duration::from_secs(300),
label: Some("ancient_tx".to_string()),
},
],
"an already-stale entry must cross both rungs on its first observed tick"
);
}
#[test]
fn tx_age_sweep_rearms_after_entry_clears() {
let config = tx_age_test_config();
let mut state = TxAgeSweepState::default();
state.observe(
Some((
tx_id(1),
Duration::from_secs(150),
Some("first_span".to_string()),
)),
&config,
);
let cleared = state.observe(None, &config);
assert!(cleared.is_empty(), "a clearing tick must emit nothing");
let fresh = state.observe(
Some((
tx_id(2),
Duration::from_secs(2),
Some("second_span".to_string()),
)),
&config,
);
assert!(fresh.is_empty(), "a fresh oldest entry must emit nothing");
let rewarn = state.observe(
Some((
tx_id(2),
Duration::from_secs(35),
Some("second_span".to_string()),
)),
&config,
);
assert_eq!(
rewarn,
vec![TxAgeEmission {
rung: TxAgeRung::Warn,
age: Duration::from_secs(35),
label: Some("second_span".to_string()),
}],
"a fresh stale episode after a clear must Warn again"
);
}
#[test]
fn tx_age_sweep_stale_replacement_without_intervening_clear_still_names_new_entry() {
let config = tx_age_test_config();
let mut state = TxAgeSweepState::default();
let tick_a = state.observe(
Some((
tx_id(1),
Duration::from_secs(300),
Some("stale_entry_a".to_string()),
)),
&config,
);
assert_eq!(
tick_a.len(),
2,
"entry A must cross both rungs on its first observed tick, got: {tick_a:?}"
);
let tick_b = state.observe(
Some((
tx_id(2),
Duration::from_secs(400),
Some("stale_entry_b".to_string()),
)),
&config,
);
assert_eq!(
tick_b,
vec![
TxAgeEmission {
rung: TxAgeRung::Warn,
age: Duration::from_secs(400),
label: Some("stale_entry_b".to_string()),
},
TxAgeEmission {
rung: TxAgeRung::Stale,
age: Duration::from_secs(400),
label: Some("stale_entry_b".to_string()),
},
],
"a same-tick identity change to an already-stale successor must re-emit both \
rungs naming the NEW entry, got: {tick_b:?}"
);
}
#[test]
fn tx_age_sweep_uses_configured_thresholds_not_hardcoded_defaults() {
let config = CheckpointConfig {
tx_warn_secs: Duration::from_millis(1),
tx_max_age_secs: Duration::from_millis(2),
..CheckpointConfig::default()
};
let mut state = TxAgeSweepState::default();
let tick = state.observe(
Some((
tx_id(1),
Duration::from_millis(5),
Some("fast_cap_span".to_string()),
)),
&config,
);
assert_eq!(
tick.len(),
2,
"a millisecond-scale cap must cross both rungs immediately, got: {tick:?}"
);
}
#[test]
#[serial(tx_registry, checkpoint_skip_metrics)]
fn tx_age_sweep_names_long_lived_reader_pinning_wal_past_high_water() {
let dir = tempfile::tempdir().unwrap();
let path = dir.path().join("tx_age_sweep_reader_pin.db");
let pool = file_pool(&path);
{
let writer = pool.try_writer().unwrap();
writer
.conn()
.execute_batch(
"CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
)
.unwrap();
}
let reader = pool.reader().expect("reader");
reader
.execute_batch("BEGIN DEFERRED; SELECT * FROM t;")
.expect("begin read tx");
let _tx_handle =
khive_storage::tx_registry::register(Some("tx_age_sweep_reader_pin_test".to_string()));
let config = CheckpointConfig {
high_water_pages: 1,
tx_warn_secs: Duration::from_millis(1),
tx_max_age_secs: Duration::from_millis(1),
..CheckpointConfig::default()
};
{
let writer = pool.try_writer().unwrap();
for i in 0..50 {
writer
.conn()
.execute_batch(&format!("INSERT INTO t VALUES ({i});"))
.unwrap();
}
}
let tick = checkpoint_once(&pool, &config, &mut TruncateState::default());
let wal_pages = match tick {
CheckpointTick::Observed(n) => n,
CheckpointTick::Skipped => panic!("writer must not be busy in this test"),
};
assert!(
wal_pages >= config.high_water_pages,
"test setup must actually drive wal_pages ({wal_pages}) past high_water_pages \
({}) for this regression to mean anything",
config.high_water_pages
);
std::thread::sleep(Duration::from_millis(5));
let our_entry = khive_storage::tx_registry::snapshot()
.into_iter()
.find(|(_, label)| label.as_deref() == Some("tx_age_sweep_reader_pin_test"))
.expect("this test's own tx_registry entry must still be open");
let mut tx_age_state = TxAgeSweepState::default();
let emissions = tx_age_state.observe(Some((tx_id(1), our_entry.0, our_entry.1)), &config);
assert!(
emissions.iter().any(|e| e.rung == TxAgeRung::Stale
&& e.label.as_deref() == Some("tx_age_sweep_reader_pin_test")),
"expected a Stale emission naming the pinning reader, got: {emissions:?}"
);
reader.execute_batch("COMMIT;").ok();
drop(reader);
drop(_tx_handle);
}
#[test]
#[serial(tx_registry, checkpoint_skip_metrics)]
fn tx_age_sweep_own_entry_survives_concurrent_older_registration() {
let _decoy = khive_storage::tx_registry::register(Some("decoy_unrelated_span".to_string()));
std::thread::sleep(Duration::from_millis(2));
let _own = khive_storage::tx_registry::register(Some("this_test_own_span".to_string()));
std::thread::sleep(Duration::from_millis(5));
let global_oldest = khive_storage::tx_registry::oldest().expect("registry not empty");
assert_ne!(
global_oldest.2.as_deref(),
Some("this_test_own_span"),
"test setup must reproduce the race: an older, unrelated entry must be \
the current global oldest, got: {global_oldest:?}"
);
let our_entry = khive_storage::tx_registry::snapshot()
.into_iter()
.find(|(_, label)| label.as_deref() == Some("this_test_own_span"))
.expect("this test's own tx_registry entry must still be open");
let config = CheckpointConfig {
tx_warn_secs: Duration::from_millis(1),
tx_max_age_secs: Duration::from_millis(1),
..CheckpointConfig::default()
};
let mut state = TxAgeSweepState::default();
let emissions = state.observe(Some((tx_id(2), our_entry.0, our_entry.1)), &config);
assert!(
emissions
.iter()
.any(|e| e.rung == TxAgeRung::Stale
&& e.label.as_deref() == Some("this_test_own_span")),
"expected a Stale emission naming this test's own span despite an older, \
unrelated concurrent registration, got: {emissions:?}"
);
}
#[test]
#[serial]
fn checkpoint_config_warn_sustained_cycles_env_override() {
let default = CheckpointConfig::default();
assert_eq!(default.warn_sustained_cycles, DEFAULT_WARN_SUSTAINED_CYCLES);
std::env::set_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES", "5");
let cfg = CheckpointConfig::from_env();
std::env::remove_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES");
assert_eq!(cfg.warn_sustained_cycles, 5);
std::env::set_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES", "0");
let cfg_zero = CheckpointConfig::from_env();
std::env::remove_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES");
assert_eq!(
cfg_zero.warn_sustained_cycles, DEFAULT_WARN_SUSTAINED_CYCLES,
"zero must fall back to the default"
);
std::env::set_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES", "not_a_number");
let cfg_invalid = CheckpointConfig::from_env();
std::env::remove_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES");
assert_eq!(
cfg_invalid.warn_sustained_cycles,
DEFAULT_WARN_SUSTAINED_CYCLES
);
}
#[derive(Default)]
struct FakeEventStore {
events: std::sync::Mutex<Vec<khive_storage::Event>>,
}
#[async_trait::async_trait]
impl khive_storage::EventStore for FakeEventStore {
async fn append_event(
&self,
event: khive_storage::Event,
) -> khive_storage::StorageResult<()> {
self.events.lock().unwrap().push(event);
Ok(())
}
async fn append_events(
&self,
events: Vec<khive_storage::Event>,
) -> khive_storage::StorageResult<khive_storage::BatchWriteSummary> {
let count = events.len() as u64;
self.events.lock().unwrap().extend(events);
Ok(khive_storage::BatchWriteSummary {
attempted: count,
affected: count,
failed: 0,
first_error: String::new(),
})
}
async fn get_event(
&self,
id: uuid::Uuid,
) -> khive_storage::StorageResult<Option<khive_storage::Event>> {
Ok(self
.events
.lock()
.unwrap()
.iter()
.find(|e| e.id == id)
.cloned())
}
async fn query_events(
&self,
_filter: khive_storage::EventFilter,
_page: khive_storage::PageRequest,
) -> khive_storage::StorageResult<khive_storage::Page<khive_storage::Event>> {
unimplemented!("not exercised by the checkpoint lifecycle-event tests")
}
async fn count_events(
&self,
_filter: khive_storage::EventFilter,
) -> khive_storage::StorageResult<u64> {
Ok(self.events.lock().unwrap().len() as u64)
}
}
#[test]
fn checkpoint_outcome_should_emit_covers_all_transitions() {
assert!(
checkpoint_outcome_should_emit(true, false),
"first elevated tick must emit"
);
assert!(
checkpoint_outcome_should_emit(true, true),
"sustained elevated tick must emit"
);
assert!(
checkpoint_outcome_should_emit(false, true),
"the single drain row (elevated -> healthy) must emit"
);
assert!(
!checkpoint_outcome_should_emit(false, false),
"an ordinary below-warn tick must not emit"
);
}
#[tokio::test]
#[serial(checkpoint_skip_metrics)]
async fn checkpoint_task_emits_outcome_events_while_elevated_and_stops_after_drain() {
let dir = tempfile::tempdir().unwrap();
let path = dir.path().join("outcome_emit.db");
let pool = file_pool(&path);
let cfg = CheckpointConfig {
interval: Duration::from_millis(10),
warn_pages: 0,
..CheckpointConfig::default()
};
let store = Arc::new(FakeEventStore::default());
let store_dyn: Arc<dyn khive_storage::EventStore> = store.clone();
let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
let handle = tokio::spawn(run_checkpoint_task(
pool,
cfg,
Some(store_dyn),
"local".to_string(),
shutdown_rx,
));
tokio::time::sleep(Duration::from_millis(60)).await;
shutdown_tx.send(()).expect("send shutdown signal");
tokio::time::timeout(Duration::from_secs(1), handle)
.await
.expect("checkpoint task should exit within 1s")
.expect("checkpoint task panicked");
let events = store.events.lock().unwrap();
assert!(
!events.is_empty(),
"an always-elevated config must append at least one CheckpointOutcomeRecorded event"
);
assert!(
events
.iter()
.all(|e| e.kind == khive_types::EventKind::CheckpointOutcomeRecorded),
"every appended event must be CheckpointOutcomeRecorded, got: {events:?}"
);
assert!(
events.iter().all(|e| e.namespace == "local"),
"events must be stamped with the namespace passed to run_checkpoint_task"
);
}
#[tokio::test]
#[serial(checkpoint_skip_metrics)]
async fn checkpoint_task_emits_nothing_while_healthy() {
let dir = tempfile::tempdir().unwrap();
let path = dir.path().join("outcome_no_emit.db");
let pool = file_pool(&path);
let cfg = CheckpointConfig {
interval: Duration::from_millis(10),
warn_pages: u64::MAX,
..CheckpointConfig::default()
};
let store = Arc::new(FakeEventStore::default());
let store_dyn: Arc<dyn khive_storage::EventStore> = store.clone();
let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
let handle = tokio::spawn(run_checkpoint_task(
pool,
cfg,
Some(store_dyn),
"local".to_string(),
shutdown_rx,
));
tokio::time::sleep(Duration::from_millis(60)).await;
shutdown_tx.send(()).expect("send shutdown signal");
tokio::time::timeout(Duration::from_secs(1), handle)
.await
.expect("checkpoint task should exit within 1s")
.expect("checkpoint task panicked");
assert!(
store.events.lock().unwrap().is_empty(),
"a config that never crosses warn_pages must never append a lifecycle event"
);
}
#[tokio::test]
#[serial(checkpoint_skip_metrics)]
async fn checkpoint_task_with_no_event_store_does_not_panic() {
let dir = tempfile::tempdir().unwrap();
let path = dir.path().join("outcome_none_store.db");
let pool = file_pool(&path);
let cfg = CheckpointConfig {
interval: Duration::from_millis(10),
warn_pages: 0,
..CheckpointConfig::default()
};
let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
let handle = tokio::spawn(run_checkpoint_task(
pool,
cfg,
None,
"local".to_string(),
shutdown_rx,
));
tokio::time::sleep(Duration::from_millis(40)).await;
shutdown_tx.send(()).expect("send shutdown signal");
tokio::time::timeout(Duration::from_secs(1), handle)
.await
.expect("checkpoint task should exit within 1s")
.expect("checkpoint task panicked");
}
#[tokio::test]
#[serial(tx_registry, checkpoint_skip_metrics)]
async fn checkpoint_task_sweeps_stale_registry_entry_while_wal_is_healthy() {
let dir = tempfile::tempdir().unwrap();
let path = dir.path().join("tx_age_sweep_task_healthy_wal.db");
let pool = file_pool(&path);
let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
let subscriber = CaptureSubscriber {
events: std::sync::Arc::clone(&buffer),
};
let _tracing_guard = tracing::subscriber::set_default(subscriber);
let _tx_handle = khive_storage::tx_registry::register(Some(
"checkpoint_task_healthy_wal_sweep_test".to_string(),
));
let cfg = CheckpointConfig {
interval: Duration::from_millis(10),
warn_pages: u64::MAX,
high_water_pages: u64::MAX,
truncate_high_water_pages: u64::MAX,
tx_warn_secs: Duration::from_millis(1),
tx_max_age_secs: Duration::from_millis(1),
..CheckpointConfig::default()
};
let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
let handle = tokio::spawn(run_checkpoint_task(
pool,
cfg,
None,
"local".to_string(),
shutdown_rx,
));
tokio::time::sleep(Duration::from_millis(60)).await;
shutdown_tx.send(()).expect("send shutdown signal");
tokio::time::timeout(Duration::from_secs(1), handle)
.await
.expect("checkpoint task should exit within 1s")
.expect("checkpoint task panicked");
drop(_tx_handle);
let events = buffer.lock().unwrap();
assert!(
events.iter().any(|e| {
e.tx_label.as_deref() == Some("checkpoint_task_healthy_wal_sweep_test")
&& e.message
.as_deref()
.is_some_and(|m| m.contains("stale-op cap"))
}),
"expected the spawned task to sweep and escalate the stale registry entry \
to Stale on its own, got: {events:?}"
);
}
#[tokio::test]
#[serial(tx_registry, checkpoint_skip_metrics)]
async fn checkpoint_task_emits_no_age_alert_for_an_empty_registry() {
let dir = tempfile::tempdir().unwrap();
let path = dir.path().join("tx_age_sweep_task_empty_registry.db");
let pool = file_pool(&path);
let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
let subscriber = CaptureSubscriber {
events: std::sync::Arc::clone(&buffer),
};
let _tracing_guard = tracing::subscriber::set_default(subscriber);
let cfg = CheckpointConfig {
interval: Duration::from_millis(10),
tx_warn_secs: Duration::from_millis(1),
tx_max_age_secs: Duration::from_millis(1),
..CheckpointConfig::default()
};
let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
let handle = tokio::spawn(run_checkpoint_task(
pool,
cfg,
None,
"local".to_string(),
shutdown_rx,
));
tokio::time::sleep(Duration::from_millis(40)).await;
shutdown_tx.send(()).expect("send shutdown signal");
tokio::time::timeout(Duration::from_secs(1), handle)
.await
.expect("checkpoint task should exit within 1s")
.expect("checkpoint task panicked");
let events = buffer.lock().unwrap();
assert!(
events.iter().all(|e| e
.message
.as_deref()
.is_none_or(|m| !m.contains("ADR-091 Plank 1"))),
"an empty registry must never produce a Plank 1 age emission, got: {events:?}"
);
}
#[tokio::test]
#[serial(tx_registry, checkpoint_skip_metrics)]
async fn checkpoint_task_sweeps_stale_entry_even_when_writer_is_busy_every_tick() {
reset_checkpoint_metrics_for_tests();
let dir = tempfile::tempdir().unwrap();
let path = dir.path().join("tx_age_sweep_task_writer_busy.db");
let pool = file_pool(&path);
{
let writer = pool.try_writer().unwrap();
writer
.conn()
.execute_batch("CREATE TABLE IF NOT EXISTS t (x INTEGER);")
.unwrap();
}
let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
let subscriber = CaptureSubscriber {
events: std::sync::Arc::clone(&buffer),
};
let _tracing_guard = tracing::subscriber::set_default(subscriber);
let _tx_handle = khive_storage::tx_registry::register(Some(
"checkpoint_task_writer_busy_sweep_test".to_string(),
));
let _writer_guard = pool.try_writer().expect("acquire writer for busy hold");
let cfg = CheckpointConfig {
interval: Duration::from_millis(10),
tx_warn_secs: Duration::from_millis(1),
tx_max_age_secs: Duration::from_millis(1),
..CheckpointConfig::default()
};
let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
let handle = tokio::spawn(run_checkpoint_task(
Arc::clone(&pool),
cfg,
None,
"local".to_string(),
shutdown_rx,
));
tokio::time::sleep(Duration::from_millis(60)).await;
assert!(
checkpoint_skipped_ticks() > 0,
"test setup must actually drive at least one Skipped tick for this \
regression to mean anything"
);
shutdown_tx.send(()).expect("send shutdown signal");
tokio::time::timeout(Duration::from_secs(1), handle)
.await
.expect("checkpoint task should exit within 1s")
.expect("checkpoint task panicked");
drop(_writer_guard);
drop(_tx_handle);
let events = buffer.lock().unwrap();
assert!(
events.iter().any(|e| {
e.tx_label.as_deref() == Some("checkpoint_task_writer_busy_sweep_test")
&& e.message
.as_deref()
.is_some_and(|m| m.contains("stale-op cap"))
}),
"expected the age sweep to fire even though every tick's writer checkout \
was skipped, got: {events:?}"
);
}
}