use std::path::{Path, PathBuf};
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);
}
}
}
(cfg.tx_warn_secs, cfg.tx_max_age_secs) =
tx_age_thresholds_from_env(cfg.tx_warn_secs, cfg.tx_max_age_secs);
cfg
}
}
fn tx_age_thresholds_from_env(
default_warn: Duration,
default_max: Duration,
) -> (Duration, Duration) {
let mut warn_secs = default_warn;
let mut max_age_secs = default_max;
if let Ok(v) = std::env::var("KHIVE_TX_WARN_SECS") {
if let Ok(n) = v.parse::<u64>() {
if n > 0 {
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 {
max_age_secs = Duration::from_secs(n);
}
}
}
if warn_secs >= max_age_secs {
tracing::warn!(
configured_tx_warn_secs = warn_secs.as_secs_f64(),
configured_tx_max_age_secs = max_age_secs.as_secs_f64(),
fallback_tx_warn_secs = default_warn.as_secs_f64(),
fallback_tx_max_age_secs = default_max.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"
);
return (default_warn, default_max);
}
(warn_secs, max_age_secs)
}
#[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>)>,
tx_warn_secs: Duration,
tx_max_age_secs: Duration,
) -> 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 >= tx_warn_secs;
let above_max_age = age >= 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"
);
}
}
}
struct WalpinSidecarState {
dir: PathBuf,
pid: u32,
role: &'static str,
started_at: i64,
sweep_interval_ms: u64,
wrote: bool,
beacon_registered: bool,
last_heartbeat: Option<LastHeartbeatState>,
}
struct LastHeartbeatState {
span_id: khive_storage::tx_registry::TxId,
label: Option<String>,
attribution_basis: &'static str,
sweep_interval_ms: u64,
oldest_tx_started_at: i64,
}
impl LastHeartbeatState {
fn content_matches(
&self,
span_id: khive_storage::tx_registry::TxId,
label: &Option<String>,
attribution_basis: &str,
sweep_interval_ms: u64,
) -> bool {
self.span_id == span_id
&& self.label == *label
&& self.attribution_basis == attribution_basis
&& self.sweep_interval_ms == sweep_interval_ms
}
}
impl WalpinSidecarState {
fn new(
db_path: Option<&Path>,
is_file_backed: bool,
role: &'static str,
interval: Duration,
) -> Option<Self> {
let path = db_path?;
if !crate::walpin::sidecar_enabled(is_file_backed) {
return None;
}
let pid = std::process::id();
Some(Self {
dir: crate::walpin::sidecar_dir_for(path),
pid,
role,
started_at: crate::walpin::process_start_time_secs(pid).unwrap_or(0),
sweep_interval_ms: interval.as_millis().min(u64::MAX as u128) as u64,
wrote: false,
last_heartbeat: None,
beacon_registered: false,
})
}
async fn register_beacon(&mut self) {
let dir = self.dir.clone();
let beacon = crate::walpin::WalpinBeacon {
pid: self.pid,
process_role: self.role.to_string(),
started_at: self.started_at,
sweep_interval_ms: self.sweep_interval_ms,
};
let result =
tokio::task::spawn_blocking(move || crate::walpin::write_beacon(&dir, &beacon)).await;
match result {
Ok(Ok(())) => {
self.beacon_registered = true;
}
Ok(Err(e)) => {
tracing::warn!(
error = %e,
"ADR-091 Amendment 2: failed to write walpin registration beacon; \
this process's sidecar health will read as unknown, not registered-silent"
);
}
Err(join_err) => {
tracing::warn!(
error = %join_err,
"ADR-091 Amendment 2: walpin beacon write task panicked"
);
}
}
}
async fn refresh_beacon(&mut self) {
if !self.beacon_registered {
self.register_beacon().await;
return;
}
let dir = self.dir.clone();
let pid = self.pid;
let result =
tokio::task::spawn_blocking(move || crate::walpin::touch_beacon(&dir, pid)).await;
match result {
Ok(Ok(())) => {}
Ok(Err(e)) => {
self.beacon_registered = false;
tracing::warn!(
error = %e,
"ADR-091 Amendment 2: failed to refresh walpin registration beacon; \
this process's sidecar health will read as unknown, not registered-silent"
);
}
Err(join_err) => {
self.beacon_registered = false;
tracing::warn!(
error = %join_err,
"ADR-091 Amendment 2: walpin beacon refresh task panicked"
);
}
}
}
async fn drop_beacon_fail_closed(&mut self) {
let dir = self.dir.clone();
let pid = self.pid;
self.beacon_registered = false;
let result =
tokio::task::spawn_blocking(move || crate::walpin::remove_beacon(&dir, pid)).await;
match result {
Ok(Ok(())) => {}
Ok(Err(e)) => {
tracing::warn!(
error = %e,
"ADR-091 Amendment 2: failed to remove walpin beacon after a failed \
heartbeat write; beacon will age out of the freshness window instead"
);
}
Err(join_err) => {
tracing::warn!(
error = %join_err,
"ADR-091 Amendment 2: walpin beacon removal task panicked"
);
}
}
}
async fn observe(
&mut self,
oldest: Option<khive_storage::tx_registry::OldestSpan>,
tx_warn_secs: Duration,
) {
match oldest {
Some(span) if span.age >= tx_warn_secs => {
let attribution_basis = match span.origin {
khive_storage::tx_registry::TxOrigin::Database(_) => "origin",
khive_storage::tx_registry::TxOrigin::Unscoped
| khive_storage::tx_registry::TxOrigin::Memory => "fallback",
};
let content_unchanged = self.wrote
&& self.last_heartbeat.as_ref().is_some_and(|last| {
last.content_matches(
span.id,
&span.label,
attribution_basis,
self.sweep_interval_ms,
)
});
if content_unchanged {
let dir = self.dir.clone();
let pid = self.pid;
let touch_result = tokio::task::spawn_blocking(move || {
crate::walpin::touch_heartbeat(&dir, pid)
})
.await;
match touch_result {
Ok(Ok(())) => {
self.refresh_beacon().await;
return;
}
Ok(Err(e)) => {
tracing::warn!(
error = %e,
"ADR-091 Amendment 3 Plank F1: walpin heartbeat touch failed; \
recreating with a full body write"
);
}
Err(join_err) => {
tracing::warn!(
error = %join_err,
"ADR-091 Amendment 3 Plank F1: walpin heartbeat touch task \
panicked; recreating with a full body write"
);
}
}
}
let oldest_tx_started_at = self
.last_heartbeat
.as_ref()
.filter(|last| last.span_id == span.id)
.map(|last| last.oldest_tx_started_at)
.unwrap_or_else(|| now_epoch_secs().saturating_sub(span.age.as_secs() as i64));
let heartbeat = crate::walpin::WalpinHeartbeat {
pid: self.pid,
process_role: self.role.to_string(),
started_at: self.started_at,
oldest_tx_age_secs: span.age.as_secs_f64(),
oldest_tx_label: span.label.clone(),
oldest_tx_started_at: Some(oldest_tx_started_at),
updated_at: now_epoch_secs(),
sweep_interval_ms: self.sweep_interval_ms,
attribution_basis: Some(attribution_basis.to_string()),
};
let dir = self.dir.clone();
let result = tokio::task::spawn_blocking(move || {
crate::walpin::write_heartbeat(&dir, &heartbeat)
})
.await;
match result {
Ok(Ok(())) => {
self.wrote = true;
self.last_heartbeat = Some(LastHeartbeatState {
span_id: span.id,
label: span.label,
attribution_basis,
sweep_interval_ms: self.sweep_interval_ms,
oldest_tx_started_at,
});
self.refresh_beacon().await;
}
Ok(Err(e)) => {
tracing::warn!(
error = %e,
"ADR-091 Amendment 2 Plank B: failed to write walpin heartbeat; \
removing beacon so this process cannot read as \
registered-silent while over threshold"
);
self.last_heartbeat = None;
self.drop_beacon_fail_closed().await;
}
Err(join_err) => {
tracing::warn!(
error = %join_err,
"ADR-091 Amendment 2 Plank B: walpin heartbeat write task panicked"
);
self.last_heartbeat = None;
self.drop_beacon_fail_closed().await;
}
}
}
_ => {
self.refresh_beacon().await;
if self.wrote {
let dir = self.dir.clone();
let pid = self.pid;
let result = tokio::task::spawn_blocking(move || {
crate::walpin::remove_heartbeat(&dir, pid)
})
.await;
match result {
Ok(Ok(())) => {}
Ok(Err(e)) => tracing::warn!(
error = %e,
"ADR-091 Amendment 2 Plank B: failed to remove walpin heartbeat"
),
Err(join_err) => tracing::warn!(
error = %join_err,
"ADR-091 Amendment 2 Plank B: walpin heartbeat removal task panicked"
),
}
self.wrote = false;
self.last_heartbeat = None;
}
}
}
}
async fn shutdown(&mut self) {
if self.wrote {
let dir = self.dir.clone();
let pid = self.pid;
let _ = tokio::task::spawn_blocking(move || crate::walpin::remove_heartbeat(&dir, pid))
.await;
self.wrote = false;
}
}
}
fn now_epoch_secs() -> i64 {
std::time::SystemTime::now()
.duration_since(std::time::UNIX_EPOCH)
.map(|d| d.as_secs() as i64)
.unwrap_or(0)
}
#[derive(Clone, Debug)]
pub struct SessionSweepConfig {
pub interval: Duration,
pub tx_warn_secs: Duration,
pub tx_max_age_secs: Duration,
}
impl Default for SessionSweepConfig {
fn default() -> Self {
Self {
interval: Duration::from_secs(5),
tx_warn_secs: Duration::from_secs(30),
tx_max_age_secs: Duration::from_secs(120),
}
}
}
impl SessionSweepConfig {
pub fn from_env() -> Self {
let mut cfg = Self::default();
if let Ok(ms) = std::env::var("KHIVE_SESSION_SWEEP_INTERVAL_MS") {
if let Ok(v) = ms.parse::<u64>() {
if v > 0 {
cfg.interval = Duration::from_millis(v);
}
}
}
(cfg.tx_warn_secs, cfg.tx_max_age_secs) =
tx_age_thresholds_from_env(cfg.tx_warn_secs, cfg.tx_max_age_secs);
cfg
}
}
pub struct SweepBackend {
pub pool: Arc<ConnectionPool>,
pub is_main: bool,
}
struct BackendSweep {
filter: khive_storage::tx_registry::TxOriginFilter,
tx_age_state: TxAgeSweepState,
sidecar: Option<WalpinSidecarState>,
}
pub async fn run_session_sweep_task(
backends: Vec<SweepBackend>,
config: SessionSweepConfig,
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 sweeps: Vec<BackendSweep> = Vec::with_capacity(backends.len());
for backend in backends {
let identity = match backend.pool.origin() {
khive_storage::tx_registry::TxOrigin::Database(id) => id,
khive_storage::tx_registry::TxOrigin::Memory
| khive_storage::tx_registry::TxOrigin::Unscoped => continue,
};
let filter = if backend.is_main {
khive_storage::tx_registry::TxOriginFilter::Main(identity)
} else {
khive_storage::tx_registry::TxOriginFilter::Secondary(identity)
};
let sidecar = WalpinSidecarState::new(
backend.pool.canonical_path(),
true,
"session",
config.interval,
);
sweeps.push(BackendSweep {
filter,
tx_age_state: TxAgeSweepState::default(),
sidecar,
});
}
for sweep in sweeps.iter_mut() {
if let Some(sidecar) = sweep.sidecar.as_mut() {
sidecar.register_beacon().await;
}
}
loop {
tokio::select! {
_ = interval.tick() => {}
_ = shutdown_rx.changed() => break,
}
for sweep in sweeps.iter_mut() {
let oldest = khive_storage::tx_registry::oldest_for(&sweep.filter);
for emission in sweep.tx_age_state.observe(
oldest.as_ref().map(|s| (s.id, s.age, s.label.clone())),
config.tx_warn_secs,
config.tx_max_age_secs,
) {
log_tx_age_emission(&emission);
}
if let Some(sidecar) = sweep.sidecar.as_mut() {
sidecar.observe(oldest, config.tx_warn_secs).await;
}
}
}
for sweep in sweeps.iter_mut() {
if let Some(sidecar) = sweep.sidecar.as_mut() {
sidecar.shutdown().await;
}
}
}
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<()>,
is_main: bool,
) {
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;
let tx_filter = match pool.origin() {
khive_storage::tx_registry::TxOrigin::Database(id) => Some(if is_main {
khive_storage::tx_registry::TxOriginFilter::Main(id)
} else {
khive_storage::tx_registry::TxOriginFilter::Secondary(id)
}),
khive_storage::tx_registry::TxOrigin::Memory
| khive_storage::tx_registry::TxOrigin::Unscoped => None,
};
#[cfg(unix)]
let mut walpin_state =
WalpinSidecarState::new(pool.canonical_path(), true, "daemon", config.interval);
#[cfg(unix)]
if let Some(sidecar) = walpin_state.as_mut() {
sidecar.register_beacon().await;
}
loop {
tokio::select! {
_ = interval.tick() => {}
_ = shutdown_rx.changed() => break,
}
let tick = checkpoint_once(&pool, &config, &mut truncate_state);
let oldest_tx = tx_filter
.as_ref()
.and_then(khive_storage::tx_registry::oldest_for);
for emission in tx_age_state.observe(
oldest_tx.as_ref().map(|s| (s.id, s.age, s.label.clone())),
config.tx_warn_secs,
config.tx_max_age_secs,
) {
log_tx_age_emission(&emission);
}
#[cfg(unix)]
if let Some(sidecar) = walpin_state.as_mut() {
sidecar
.observe(oldest_tx.clone(), config.tx_warn_secs)
.await;
}
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, oldest_tx.as_ref());
for emission in severity_state.observe_wal_pages(wal_pages, &config) {
match emission.rung {
CheckpointSeverityRung::Info => {
log_tx_registry_oldest_warn(wal_pages, oldest_tx.as_ref());
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;
}
#[cfg(unix)]
if let Some(sidecar) = walpin_state.as_mut() {
sidecar.shutdown().await;
}
}
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,
oldest: Option<&khive_storage::tx_registry::OldestSpan>,
) {
if let Some(span) = oldest {
tracing::debug!(
wal_pages,
oldest_tx_age_secs = span.age.as_secs_f64(),
oldest_tx_label = span.label.as_deref().unwrap_or("<unlabeled>"),
"WAL checkpoint tick: oldest open transaction registry entry"
);
}
}
fn log_tx_registry_oldest_warn(
wal_pages: u64,
oldest: Option<&khive_storage::tx_registry::OldestSpan>,
) {
if let Some(span) = oldest {
tracing::warn!(
wal_pages,
oldest_tx_age_secs = span.age.as_secs_f64(),
oldest_tx_label = span.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);
#[cfg(unix)]
log_walpin_sidecar_report(pool);
log_wal_pin_depth(conn);
}
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);
}
#[cfg(unix)]
fn log_walpin_sidecar_report(pool: &ConnectionPool) {
let Some(path) = pool.canonical_path() else {
return;
};
if !crate::walpin::sidecar_enabled(true) {
return;
}
let dir = crate::walpin::sidecar_dir_for(path);
let sweep_interval = SessionSweepConfig::from_env().interval;
let report = match crate::walpin::enumerate_live(&dir, sweep_interval) {
Ok(report) => report,
Err(e) => {
tracing::warn!(
error = %e,
"ADR-091 Amendment 2 Plank B: sidecar directory failed the trust-boundary \
check; cross-process WAL-pin attribution is unestablished for this tick"
);
return;
}
};
let now = now_epoch_secs();
for hb in report.reporting() {
tracing::warn!(
walpin_pid = hb.pid,
walpin_role = %hb.process_role,
walpin_oldest_tx_age_secs = hb.current_oldest_tx_age_secs(now),
walpin_oldest_tx_label = hb.oldest_tx_label.as_deref().unwrap_or("<unlabeled>"),
walpin_attribution_basis = hb.attribution_basis.as_deref().unwrap_or("<unspecified>"),
walpin_attribution_evidence_backed = hb.attribution_is_evidence_backed(),
walpin_health = "reporting",
"ADR-091 Amendment 2 Plank B: live cross-process WAL-pin attribution report"
);
}
for pid in report.registered_silent_pids() {
tracing::debug!(
walpin_pid = pid,
walpin_health = "registered_silent",
"ADR-091 Amendment 2 Plank B: process affirmatively reports no over-threshold span"
);
}
let mut unknown_pids: Vec<u32> = report.unknown_pids().collect();
match crate::walpin::census_holders(path) {
Ok(census) => {
let sidecar_known: std::collections::HashSet<u32> = report
.reporting()
.map(|hb| hb.pid)
.chain(report.registered_silent_pids())
.chain(unknown_pids.iter().copied())
.collect();
let mut census_only: Vec<u32> =
census.holders.difference(&sidecar_known).copied().collect();
if !census_only.is_empty() {
census_only.sort_unstable();
tracing::warn!(
?census_only,
"ADR-091 Amendment 2: these PIDs hold the database file open \
at the OS level but have no sidecar data at all (pre-feature binary, \
sidecar disabled, or wedged before its first write)"
);
unknown_pids.extend(census_only);
}
if !census.is_complete() {
let mut uninspectable = census.uninspectable_pids.clone();
uninspectable.sort_unstable();
tracing::warn!(
?uninspectable,
truncated = census.truncated,
"ADR-091 Amendment 2: the OS-derived holder census is \
INCOMPLETE — either specific PIDs' open file descriptors could not be \
inspected (permission denied, or a listing race), or the enumeration walk \
itself has positive evidence it did not see the full live-process universe \
(namespace/visibility check, directory-iterator error, self-canary, or a \
libproc buffer that stayed at capacity after bounded retries) — cannot \
rule out an unregistered holder"
);
if uninspectable.is_empty() {
unknown_pids.push(0);
} else {
unknown_pids.extend(uninspectable);
}
}
}
Err(e) => {
tracing::warn!(
error = %e,
"ADR-091 Amendment 2: OS-derived holder census failed; \
attribution cannot rule out an unregistered database holder this tick"
);
unknown_pids.push(0);
}
}
if !unknown_pids.is_empty() {
tracing::warn!(
?unknown_pids,
"ADR-091 Amendment 2 Plank B: sidecar health unestablished for these PIDs; \
attribution is inconclusive and the native/unregistered-mechanism conclusion \
is NOT licensed this tick"
);
} else if report.reporting().next().is_none() {
tracing::info!(
"ADR-091 Amendment 2 Plank B: every live PID is reporting or registered-silent \
with none pinning; the WAL pin is not attributable to any in-process registry \
span this sidecar covers"
);
}
}
fn log_wal_pin_depth(conn: &rusqlite::Connection) {
match query_wal_pin_depth(conn) {
Ok((log, checkpointed)) => {
tracing::warn!(
wal_log_frames = log,
wal_checkpointed_frames = checkpointed,
wal_pin_depth = (log - checkpointed).max(0),
"ADR-091 Amendment 2 Plank C: WAL pin depth after TRUNCATE no-progress"
);
}
Err(e) => {
tracing::warn!(
error = %e,
"ADR-091 Amendment 2 Plank C: failed to query WAL pin depth"
);
}
}
}
fn query_wal_pin_depth(conn: &rusqlite::Connection) -> rusqlite::Result<(i64, i64)> {
conn.query_row("PRAGMA wal_checkpoint(PASSIVE)", [], |row| {
Ok((row.get::<_, i64>(1)?, row.get::<_, i64>(2)?))
})
}
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 oldest = khive_storage::tx_registry::oldest().map(|(id, age, label)| {
khive_storage::tx_registry::OldestSpan {
id,
age,
label,
origin: khive_storage::tx_registry::TxOrigin::Unscoped,
}
});
let expected_label = oldest
.as_ref()
.and_then(|s| s.label.clone())
.unwrap_or_else(|| "<unlabeled>".to_string());
tracing::subscriber::with_default(subscriber, || {
log_tx_registry_oldest_debug(100, oldest.as_ref());
});
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 oldest = khive_storage::tx_registry::oldest().map(|(id, age, label)| {
khive_storage::tx_registry::OldestSpan {
id,
age,
label,
origin: khive_storage::tx_registry::TxOrigin::Unscoped,
}
});
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, oldest.as_ref());
}
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, oldest.as_ref());
}
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,
true,
));
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,
true,
));
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.tx_warn_secs, config.tx_max_age_secs);
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.tx_warn_secs,
config.tx_max_age_secs,
);
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.tx_warn_secs,
config.tx_max_age_secs,
);
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.tx_warn_secs,
config.tx_max_age_secs,
);
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.tx_warn_secs,
config.tx_max_age_secs,
);
let tick = state.observe(
Some((
tx_id(1),
Duration::from_secs(130),
Some("stuck_writer_task_tx".to_string()),
)),
config.tx_warn_secs,
config.tx_max_age_secs,
);
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.tx_warn_secs,
config.tx_max_age_secs,
);
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.tx_warn_secs,
config.tx_max_age_secs,
);
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.tx_warn_secs,
config.tx_max_age_secs,
);
let cleared = state.observe(None, config.tx_warn_secs, config.tx_max_age_secs);
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.tx_warn_secs,
config.tx_max_age_secs,
);
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.tx_warn_secs,
config.tx_max_age_secs,
);
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.tx_warn_secs,
config.tx_max_age_secs,
);
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.tx_warn_secs,
config.tx_max_age_secs,
);
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.tx_warn_secs,
config.tx_max_age_secs,
);
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.tx_warn_secs,
config.tx_max_age_secs,
);
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.tx_warn_secs,
config.tx_max_age_secs,
);
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,
true,
));
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,
true,
));
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,
true,
));
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,
true,
));
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,
true,
));
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,
true,
));
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:?}"
);
}
#[tokio::test]
async fn session_sweep_task_exits_on_shutdown_signal() {
let cfg = SessionSweepConfig {
interval: Duration::from_millis(10),
..SessionSweepConfig::default()
};
let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
let handle = tokio::spawn(run_session_sweep_task(Vec::new(), cfg, shutdown_rx));
shutdown_tx.send(()).expect("send shutdown signal");
tokio::time::timeout(Duration::from_secs(1), handle)
.await
.expect("session sweep task should exit within 1s")
.expect("session sweep task panicked");
}
async fn wait_for(deadline: Duration, mut cond: impl FnMut() -> bool) -> bool {
let start = std::time::Instant::now();
while start.elapsed() < deadline {
if cond() {
return true;
}
tokio::time::sleep(Duration::from_millis(5)).await;
}
cond()
}
#[tokio::test]
#[serial(khive_walpin_sidecar_env)]
async fn walpin_observe_drops_beacon_when_heartbeat_write_fails() {
let dir = tempfile::tempdir().unwrap();
let db_path = dir.path().join("observe_gate.db");
let sidecar_dir = crate::walpin::sidecar_dir_for(&db_path);
let _env_guard = crate::walpin::EnvVarGuard::capture("KHIVE_WALPIN_SIDECAR");
std::env::set_var("KHIVE_WALPIN_SIDECAR", "1");
let mut state = WalpinSidecarState::new(
Some(db_path.as_path()),
true,
"session",
Duration::from_millis(500),
)
.expect("sidecar enabled for a file-backed path");
state.register_beacon().await;
let pid = std::process::id();
let beacon_path = sidecar_dir.join(format!("{pid}.beacon"));
let before = std::fs::metadata(&beacon_path)
.expect("beacon registered")
.modified()
.unwrap();
let obstruction = sidecar_dir.join(format!(".{pid}.json.tmp"));
std::fs::create_dir(&obstruction).unwrap();
tokio::time::sleep(Duration::from_millis(20)).await;
let over_threshold = Some(khive_storage::tx_registry::OldestSpan {
id: khive_storage::tx_registry::TxId(1),
age: Duration::from_secs(60),
label: None,
origin: khive_storage::tx_registry::TxOrigin::Unscoped,
});
state
.observe(over_threshold.clone(), Duration::from_secs(30))
.await;
assert!(
!sidecar_dir.join(format!("{pid}.json")).exists(),
"heartbeat write must have failed"
);
assert!(
!beacon_path.exists(),
"a failed heartbeat write must remove the beacon — a still-fresh \
beacon with no heartbeat would classify registered-silent \
(before-mtime {before:?})"
);
std::fs::remove_dir(&obstruction).unwrap();
state.observe(over_threshold, Duration::from_secs(30)).await;
assert!(
sidecar_dir.join(format!("{pid}.json")).exists(),
"heartbeat must land once the write path recovers"
);
assert!(
beacon_path.exists(),
"beacon must re-register on the first healthy tick after removal"
);
}
#[tokio::test]
#[serial(khive_walpin_sidecar_env)]
async fn walpin_observe_touches_mtime_without_rewriting_body_when_content_unchanged() {
let dir = tempfile::tempdir().unwrap();
let db_path = dir.path().join("observe_touch.db");
let sidecar_dir = crate::walpin::sidecar_dir_for(&db_path);
let _env_guard = crate::walpin::EnvVarGuard::capture("KHIVE_WALPIN_SIDECAR");
std::env::set_var("KHIVE_WALPIN_SIDECAR", "1");
let mut state = WalpinSidecarState::new(
Some(db_path.as_path()),
true,
"session",
Duration::from_millis(500),
)
.expect("sidecar enabled for a file-backed path");
let pid = std::process::id();
let heartbeat_path = sidecar_dir.join(format!("{pid}.json"));
let span = khive_storage::tx_registry::OldestSpan {
id: khive_storage::tx_registry::TxId(1),
age: Duration::from_secs(60),
label: None,
origin: khive_storage::tx_registry::TxOrigin::Unscoped,
};
state
.observe(Some(span.clone()), Duration::from_secs(30))
.await;
let body_after_create = std::fs::read(&heartbeat_path).expect("heartbeat written");
let backdated = std::time::SystemTime::now() - Duration::from_secs(120);
std::fs::File::open(&heartbeat_path)
.unwrap()
.set_modified(backdated)
.unwrap();
state.observe(Some(span), Duration::from_secs(30)).await;
let body_after_second_observe =
std::fs::read(&heartbeat_path).expect("heartbeat still present");
assert_eq!(
body_after_create, body_after_second_observe,
"unchanged oldest-span identity/label/attribution/cadence must touch mtime, \
not rewrite the body"
);
let mtime_after = std::fs::metadata(&heartbeat_path)
.unwrap()
.modified()
.unwrap();
assert!(
mtime_after > backdated,
"the touch must advance mtime past the backdated value"
);
}
#[tokio::test]
#[serial(khive_walpin_sidecar_env)]
async fn walpin_observe_recreates_heartbeat_after_it_is_deleted_while_span_still_live() {
let dir = tempfile::tempdir().unwrap();
let db_path = dir.path().join("observe_recreate.db");
let sidecar_dir = crate::walpin::sidecar_dir_for(&db_path);
let _env_guard = crate::walpin::EnvVarGuard::capture("KHIVE_WALPIN_SIDECAR");
std::env::set_var("KHIVE_WALPIN_SIDECAR", "1");
let mut state = WalpinSidecarState::new(
Some(db_path.as_path()),
true,
"session",
Duration::from_millis(500),
)
.expect("sidecar enabled for a file-backed path");
let pid = std::process::id();
let heartbeat_path = sidecar_dir.join(format!("{pid}.json"));
let span = khive_storage::tx_registry::OldestSpan {
id: khive_storage::tx_registry::TxId(1),
age: Duration::from_secs(60),
label: None,
origin: khive_storage::tx_registry::TxOrigin::Unscoped,
};
state
.observe(Some(span.clone()), Duration::from_secs(30))
.await;
assert!(heartbeat_path.exists(), "heartbeat written on first tick");
std::fs::remove_file(&heartbeat_path).unwrap();
assert!(!heartbeat_path.exists());
state.observe(Some(span), Duration::from_secs(30)).await;
assert!(
heartbeat_path.exists(),
"a touch failure against a deleted heartbeat must recreate it via a full write"
);
let recreated: crate::walpin::WalpinHeartbeat =
serde_json::from_slice(&std::fs::read(&heartbeat_path).unwrap()).unwrap();
assert_eq!(recreated.pid, pid);
assert_eq!(recreated.oldest_tx_age_secs, 60.0);
}
#[tokio::test]
#[serial(tx_registry, khive_walpin_sidecar_env)]
async fn session_sweep_task_writes_and_clears_walpin_heartbeat() {
let dir = tempfile::tempdir().unwrap();
let db_path = dir.path().join("session_sweep.db");
let pool = file_pool(&db_path);
let sidecar_dir =
crate::walpin::sidecar_dir_for(pool.canonical_path().expect("file-backed pool"));
let _env_guard = crate::walpin::EnvVarGuard::capture("KHIVE_WALPIN_SIDECAR");
std::env::set_var("KHIVE_WALPIN_SIDECAR", "1");
let cfg = SessionSweepConfig {
interval: Duration::from_millis(10),
tx_warn_secs: Duration::from_millis(20),
tx_max_age_secs: Duration::from_millis(500),
};
let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
let handle = tokio::spawn(run_session_sweep_task(
vec![SweepBackend {
pool: Arc::clone(&pool),
is_main: true,
}],
cfg,
shutdown_rx,
));
let pid = std::process::id();
let beacon = crate::walpin::beacon_path(&sidecar_dir, pid);
assert!(
wait_for(Duration::from_secs(2), || beacon.exists()).await,
"a quiet process must still register its one-time beacon"
);
assert!(
!sidecar_dir.join(format!("{pid}.json")).exists(),
"a quiet process must not write a walpin heartbeat"
);
let tx_handle =
khive_storage::tx_registry::register(Some("session_sweep_walpin_test".to_string()));
let heartbeat_path = sidecar_dir.join(format!("{pid}.json"));
assert!(
wait_for(Duration::from_secs(2), || heartbeat_path.exists()).await,
"expected a walpin heartbeat once the span crossed tx_warn_secs"
);
let body = std::fs::read_to_string(&heartbeat_path).unwrap();
let hb: crate::walpin::WalpinHeartbeat = serde_json::from_str(&body).unwrap();
assert_eq!(hb.pid, pid);
assert_eq!(hb.process_role, "session");
assert_eq!(
hb.oldest_tx_label.as_deref(),
Some("session_sweep_walpin_test")
);
assert_eq!(
hb.attribution_basis.as_deref(),
Some("fallback"),
"an Unscoped span observed only through the main view's fallback \
must carry attribution_basis=\"fallback\", never \"origin\""
);
drop(tx_handle);
assert!(
wait_for(Duration::from_secs(2), || !heartbeat_path.exists()).await,
"heartbeat must be removed once the stale span clears"
);
shutdown_tx.send(()).expect("send shutdown signal");
tokio::time::timeout(Duration::from_secs(1), handle)
.await
.expect("session sweep task should exit within 1s")
.expect("session sweep task panicked");
}
#[tokio::test]
#[serial(tx_registry, khive_walpin_sidecar_env)]
async fn session_sweep_fan_out_scopes_secondary_span_to_secondary_sidecar_only() {
let main_dir = tempfile::tempdir().unwrap();
let secondary_dir = tempfile::tempdir().unwrap();
let main_pool = file_pool(&main_dir.path().join("main.db"));
let secondary_pool = file_pool(&secondary_dir.path().join("secondary.db"));
let main_sidecar =
crate::walpin::sidecar_dir_for(main_pool.canonical_path().expect("file-backed"));
let secondary_sidecar =
crate::walpin::sidecar_dir_for(secondary_pool.canonical_path().expect("file-backed"));
let _env_guard = crate::walpin::EnvVarGuard::capture("KHIVE_WALPIN_SIDECAR");
std::env::set_var("KHIVE_WALPIN_SIDECAR", "1");
let cfg = SessionSweepConfig {
interval: Duration::from_millis(10),
tx_warn_secs: Duration::from_millis(20),
tx_max_age_secs: Duration::from_millis(500),
};
let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
let handle = tokio::spawn(run_session_sweep_task(
vec![
SweepBackend {
pool: Arc::clone(&main_pool),
is_main: true,
},
SweepBackend {
pool: Arc::clone(&secondary_pool),
is_main: false,
},
],
cfg,
shutdown_rx,
));
let pid = std::process::id();
let secondary_heartbeat = secondary_sidecar.join(format!("{pid}.json"));
let main_heartbeat = main_sidecar.join(format!("{pid}.json"));
let tx_handle = khive_storage::tx_registry::register_scoped(
Some("graph_traverse_read".to_string()),
secondary_pool.origin(),
);
assert!(
wait_for(Duration::from_secs(2), || secondary_heartbeat.exists()).await,
"expected a walpin heartbeat in the secondary backend's own sidecar"
);
assert!(
!main_heartbeat.exists(),
"a span scoped to the secondary backend's origin must never produce \
a heartbeat in the main backend's sidecar"
);
let body = std::fs::read_to_string(&secondary_heartbeat).unwrap();
let hb: crate::walpin::WalpinHeartbeat = serde_json::from_str(&body).unwrap();
assert_eq!(hb.oldest_tx_label.as_deref(), Some("graph_traverse_read"));
assert_eq!(
hb.attribution_basis.as_deref(),
Some("origin"),
"a Secondary-view winner is always Database-origin-backed — never fallback"
);
drop(tx_handle);
assert!(
wait_for(Duration::from_secs(2), || !secondary_heartbeat.exists()).await,
"secondary heartbeat must be removed once its span clears"
);
assert!(
!main_heartbeat.exists(),
"the main sidecar must have stayed untouched for the whole tick sequence"
);
shutdown_tx.send(()).expect("send shutdown signal");
tokio::time::timeout(Duration::from_secs(1), handle)
.await
.expect("session sweep task should exit within 1s")
.expect("session sweep task panicked");
}
#[tokio::test]
#[serial(tx_registry, checkpoint_skip_metrics, khive_walpin_sidecar_env)]
async fn checkpoint_task_ignores_span_registered_against_other_backend_origin_and_unscoped() {
let dir_a = tempfile::tempdir().unwrap();
let dir_b = tempfile::tempdir().unwrap();
let pool_a = file_pool(&dir_a.path().join("backend_a.db"));
let pool_b = file_pool(&dir_b.path().join("backend_b.db"));
let sidecar_a =
crate::walpin::sidecar_dir_for(pool_a.canonical_path().expect("file-backed"));
let _env_guard = crate::walpin::EnvVarGuard::capture("KHIVE_WALPIN_SIDECAR");
std::env::set_var("KHIVE_WALPIN_SIDECAR", "1");
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 _b_origin_handle = khive_storage::tx_registry::register_scoped(
Some("b_origin_span_ignored_by_a".to_string()),
pool_b.origin(),
);
let _unscoped_handle = khive_storage::tx_registry::register(Some(
"unscoped_span_ignored_by_secondary".to_string(),
));
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_a,
cfg,
None,
"local".to_string(),
shutdown_rx,
false, ));
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 = buffer.lock().unwrap();
assert!(
events.iter().all(|e| {
e.tx_label.as_deref() != Some("b_origin_span_ignored_by_a")
&& e.tx_label.as_deref() != Some("unscoped_span_ignored_by_secondary")
}),
"backend A's Secondary filter must never emit an age alert naming a span \
registered against a different backend's origin or an Unscoped span, got: \
{events:?}"
);
assert!(
!sidecar_a
.join(format!("{}.json", std::process::id()))
.exists(),
"backend A's own sidecar must never gain a heartbeat from a span it does not own"
);
}
#[tokio::test]
#[serial(tx_registry, checkpoint_skip_metrics, khive_walpin_sidecar_env)]
async fn checkpoint_task_detects_and_enumerates_secondary_backend_stall() {
let dir = tempfile::tempdir().unwrap();
let pool = file_pool(&dir.path().join("secondary_stall.db"));
let sidecar_dir =
crate::walpin::sidecar_dir_for(pool.canonical_path().expect("file-backed"));
let _env_guard = crate::walpin::EnvVarGuard::capture("KHIVE_WALPIN_SIDECAR");
std::env::set_var("KHIVE_WALPIN_SIDECAR", "1");
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_scoped(
Some("secondary_stall_test".to_string()),
pool.origin(),
);
let cfg = CheckpointConfig {
interval: Duration::from_millis(10),
tx_warn_secs: Duration::from_millis(5),
tx_max_age_secs: Duration::from_millis(500),
..CheckpointConfig::default()
};
let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
let pid = std::process::id();
let heartbeat_path = sidecar_dir.join(format!("{pid}.json"));
let handle = tokio::spawn(run_checkpoint_task(
pool,
cfg,
None,
"local".to_string(),
shutdown_rx,
false, ));
assert!(
wait_for(Duration::from_secs(2), || heartbeat_path.exists()).await,
"expected a walpin heartbeat once the secondary backend's own span crossed \
tx_warn_secs"
);
let body = std::fs::read_to_string(&heartbeat_path).unwrap();
let hb: crate::walpin::WalpinHeartbeat = serde_json::from_str(&body).unwrap();
assert_eq!(hb.oldest_tx_label.as_deref(), Some("secondary_stall_test"));
assert_eq!(
hb.attribution_basis.as_deref(),
Some("origin"),
"a Secondary-view winner is always Database-origin-backed — never fallback"
);
assert!(
hb.oldest_tx_age_secs > 0.0,
"the heartbeat must reflect a nonzero stale age for the secondary backend's own \
span, got {hb:?}"
);
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("secondary_stall_test")
&& e.message
.as_deref()
.is_some_and(|m| m.contains("ADR-091 Plank 1"))
}),
"expected the secondary backend's own checkpoint task to emit a Plank 1 age alert \
for its own stalled span, got: {events:?}"
);
}
#[test]
fn wal_pin_depth_arithmetic_against_real_connection() {
let dir = tempfile::tempdir().unwrap();
let path = dir.path().join("pin_depth.db");
let pool = file_pool(&path);
let writer = pool.try_writer().expect("acquire writer");
let conn = writer.conn();
conn.execute_batch("CREATE TABLE t (v INTEGER)").unwrap();
conn.execute_batch("INSERT INTO t (v) VALUES (1)").unwrap();
let (log, checkpointed) =
query_wal_pin_depth(conn).expect("PRAGMA wal_checkpoint(PASSIVE) must succeed");
assert!(
log >= checkpointed,
"checkpointed frames cannot exceed log frames"
);
assert_eq!(
log - checkpointed,
0,
"an unpinned WAL must fully checkpoint under PASSIVE"
);
}
#[test]
fn wal_pin_depth_arithmetic_on_in_memory_pool_errors_cleanly() {
let cfg = PoolConfig {
path: None,
..PoolConfig::default()
};
let pool = ConnectionPool::new(cfg).expect("in-memory pool");
let writer = pool.try_writer().expect("acquire writer");
let _ = query_wal_pin_depth(writer.conn());
}
}