1use std::sync::atomic::{AtomicU64, Ordering};
27use std::sync::Arc;
28use std::time::{Duration, Instant};
29
30use crate::pool::{ConnectionPool, WriterGuard};
31
32static LAST_WAL_PAGES: AtomicU64 = AtomicU64::new(u64::MAX);
41
42static TRUNCATE_ATTEMPTS: AtomicU64 = AtomicU64::new(0);
45
46static TRUNCATE_CONSECUTIVE_FAILURES: AtomicU64 = AtomicU64::new(0);
50
51static CHECKPOINT_SKIPPED_TICKS: AtomicU64 = AtomicU64::new(0);
55
56static CHECKPOINT_CONSECUTIVE_SKIPS: AtomicU64 = AtomicU64::new(0);
60
61static CHECKPOINT_LAST_SKIP_WAL_PAGES: AtomicU64 = AtomicU64::new(u64::MAX);
65
66pub fn last_observed_wal_pages() -> Option<u64> {
69 match LAST_WAL_PAGES.load(Ordering::Relaxed) {
70 u64::MAX => None,
71 pages => Some(pages),
72 }
73}
74
75pub fn truncate_attempts() -> u64 {
77 TRUNCATE_ATTEMPTS.load(Ordering::Relaxed)
78}
79
80pub fn truncate_consecutive_failures() -> u64 {
82 TRUNCATE_CONSECUTIVE_FAILURES.load(Ordering::Relaxed)
83}
84
85pub fn checkpoint_skipped_ticks() -> u64 {
87 CHECKPOINT_SKIPPED_TICKS.load(Ordering::Relaxed)
88}
89
90pub fn checkpoint_consecutive_skips() -> u64 {
92 CHECKPOINT_CONSECUTIVE_SKIPS.load(Ordering::Relaxed)
93}
94
95pub fn checkpoint_last_skip_wal_pages() -> Option<u64> {
98 match CHECKPOINT_LAST_SKIP_WAL_PAGES.load(Ordering::Relaxed) {
99 u64::MAX => None,
100 pages => Some(pages),
101 }
102}
103
104fn note_checkpoint_skipped() {
108 CHECKPOINT_SKIPPED_TICKS.fetch_add(1, Ordering::Relaxed);
109 CHECKPOINT_CONSECUTIVE_SKIPS.fetch_add(1, Ordering::Relaxed);
110 if let Some(pages) = last_observed_wal_pages() {
111 CHECKPOINT_LAST_SKIP_WAL_PAGES.store(pages, Ordering::Relaxed);
112 }
113}
114
115fn note_checkpoint_observed(_wal_pages: u64) {
120 CHECKPOINT_CONSECUTIVE_SKIPS.store(0, Ordering::Relaxed);
121}
122
123#[cfg(test)]
127pub(crate) fn reset_checkpoint_metrics_for_tests() {
128 CHECKPOINT_SKIPPED_TICKS.store(0, Ordering::Relaxed);
129 CHECKPOINT_CONSECUTIVE_SKIPS.store(0, Ordering::Relaxed);
130 CHECKPOINT_LAST_SKIP_WAL_PAGES.store(u64::MAX, Ordering::Relaxed);
131}
132
133#[derive(Debug, Clone, Copy, PartialEq, Eq)]
141pub enum CheckpointTick {
142 Skipped,
144 Observed(u64),
146}
147
148pub const DEFAULT_WARN_SUSTAINED_CYCLES: u8 = 3;
151
152#[derive(Clone, Debug)]
157pub struct CheckpointConfig {
158 pub interval: Duration,
163
164 pub warn_pages: u64,
169
170 pub warn_sustained_cycles: u8,
178
179 pub high_water_pages: u64,
189
190 pub truncate_high_water_pages: u64,
201
202 pub truncate_min_interval: Duration,
212
213 pub truncate_busy_timeout: Duration,
220
221 pub tx_warn_secs: Duration,
229
230 pub tx_max_age_secs: Duration,
238}
239
240impl Default for CheckpointConfig {
241 fn default() -> Self {
242 Self {
243 interval: Duration::from_millis(500),
244 warn_pages: 2000,
245 warn_sustained_cycles: DEFAULT_WARN_SUSTAINED_CYCLES,
246 high_water_pages: 6000,
247 truncate_high_water_pages: 20_000,
248 truncate_min_interval: Duration::from_secs(300),
249 truncate_busy_timeout: Duration::from_millis(2000),
250 tx_warn_secs: Duration::from_secs(30),
251 tx_max_age_secs: Duration::from_secs(120),
252 }
253 }
254}
255
256impl CheckpointConfig {
257 pub fn from_env() -> Self {
261 let mut cfg = Self::default();
262
263 if let Ok(ms) = std::env::var("KHIVE_CHECKPOINT_INTERVAL_MS") {
264 if let Ok(v) = ms.parse::<u64>() {
265 if v > 0 {
266 cfg.interval = Duration::from_millis(v);
267 }
268 }
269 }
270
271 if let Ok(v) = std::env::var("KHIVE_WAL_WARN_PAGES") {
272 if let Ok(n) = v.parse::<u64>() {
273 if n > 0 {
274 cfg.warn_pages = n;
275 }
276 }
277 }
278
279 if let Ok(v) = std::env::var("KHIVE_WAL_WARN_SUSTAINED_CYCLES") {
280 if let Ok(n) = v.parse::<u8>() {
281 if n > 0 {
282 cfg.warn_sustained_cycles = n;
283 }
284 }
285 }
286
287 if let Ok(v) = std::env::var("KHIVE_WAL_HIGH_WATER_PAGES") {
288 if let Ok(n) = v.parse::<u64>() {
289 if n > 0 {
290 cfg.high_water_pages = n;
291 }
292 }
293 }
294
295 if let Ok(v) = std::env::var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES") {
296 if let Ok(n) = v.parse::<u64>() {
297 if n > 0 {
298 cfg.truncate_high_water_pages = n;
299 }
300 }
301 }
302
303 if let Ok(v) = std::env::var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS") {
304 if let Ok(n) = v.parse::<u64>() {
305 if n > 0 {
306 cfg.truncate_min_interval = Duration::from_secs(n);
307 }
308 }
309 }
310
311 if let Ok(v) = std::env::var("KHIVE_WAL_TRUNCATE_BUSY_MS") {
312 if let Ok(n) = v.parse::<u64>() {
313 if n > 0 {
314 cfg.truncate_busy_timeout = Duration::from_millis(n);
315 }
316 }
317 }
318
319 if let Ok(v) = std::env::var("KHIVE_TX_WARN_SECS") {
320 if let Ok(n) = v.parse::<u64>() {
321 if n > 0 {
322 cfg.tx_warn_secs = Duration::from_secs(n);
323 }
324 }
325 }
326
327 if let Ok(v) = std::env::var("KHIVE_TX_MAX_AGE_SECS") {
328 if let Ok(n) = v.parse::<u64>() {
329 if n > 0 {
330 cfg.tx_max_age_secs = Duration::from_secs(n);
331 }
332 }
333 }
334
335 if cfg.tx_warn_secs >= cfg.tx_max_age_secs {
345 let default = Self::default();
346 tracing::warn!(
347 configured_tx_warn_secs = cfg.tx_warn_secs.as_secs_f64(),
348 configured_tx_max_age_secs = cfg.tx_max_age_secs.as_secs_f64(),
349 fallback_tx_warn_secs = default.tx_warn_secs.as_secs_f64(),
350 fallback_tx_max_age_secs = default.tx_max_age_secs.as_secs_f64(),
351 "KHIVE_TX_WARN_SECS must be strictly less than KHIVE_TX_MAX_AGE_SECS; \
352 both transaction-age thresholds were rejected and reset to their defaults"
353 );
354 cfg.tx_warn_secs = default.tx_warn_secs;
355 cfg.tx_max_age_secs = default.tx_max_age_secs;
356 }
357
358 cfg
359 }
360}
361
362#[derive(Debug, Default)]
369pub struct TruncateState {
370 last_attempt: Option<Instant>,
374 consecutive_failures: u32,
379}
380
381#[derive(Debug, Clone, Copy, PartialEq, Eq)]
388pub enum CheckpointSeverityRung {
389 Info,
391 Warn,
394 Alarm,
397}
398
399#[derive(Debug, Default, Clone)]
403pub struct CheckpointSeverityState {
404 was_above_warn: bool,
407 consecutive_above_warn: u8,
410 warn_emitted_for_episode: bool,
414}
415
416#[derive(Debug, Clone, Copy, PartialEq, Eq)]
419pub struct CheckpointSeverityEmission {
420 pub rung: CheckpointSeverityRung,
424 pub wal_pages: u64,
426 pub threshold_pages: u64,
428 pub consecutive_cycles: u8,
431}
432
433impl CheckpointSeverityState {
434 pub fn observe_wal_pages(
445 &mut self,
446 wal_pages: u64,
447 config: &CheckpointConfig,
448 ) -> Vec<CheckpointSeverityEmission> {
449 let mut emissions = Vec::new();
450 let above_warn = wal_pages >= config.warn_pages;
451
452 if above_warn {
453 self.consecutive_above_warn = self.consecutive_above_warn.saturating_add(1);
454
455 if !self.was_above_warn {
456 emissions.push(CheckpointSeverityEmission {
457 rung: CheckpointSeverityRung::Info,
458 wal_pages,
459 threshold_pages: config.warn_pages,
460 consecutive_cycles: self.consecutive_above_warn,
461 });
462 }
463
464 if !self.warn_emitted_for_episode
465 && self.consecutive_above_warn >= config.warn_sustained_cycles
466 {
467 emissions.push(CheckpointSeverityEmission {
468 rung: CheckpointSeverityRung::Warn,
469 wal_pages,
470 threshold_pages: config.warn_pages,
471 consecutive_cycles: self.consecutive_above_warn,
472 });
473 self.warn_emitted_for_episode = true;
474 }
475 } else {
476 self.consecutive_above_warn = 0;
477 self.warn_emitted_for_episode = false;
478 }
479
480 self.was_above_warn = above_warn;
481 emissions
482 }
483}
484
485#[derive(Debug, Clone, Copy, PartialEq, Eq)]
489pub enum TxAgeRung {
490 Warn,
492 Stale,
497}
498
499#[derive(Debug, Clone, PartialEq, Eq)]
501pub struct TxAgeEmission {
502 pub rung: TxAgeRung,
503 pub age: Duration,
504 pub label: Option<String>,
505}
506
507#[derive(Debug, Default, Clone)]
518pub struct TxAgeSweepState {
519 was_above_warn: bool,
522 was_above_max_age: bool,
525 tracked_id: Option<khive_storage::tx_registry::TxId>,
530}
531
532impl TxAgeSweepState {
533 pub fn observe(
545 &mut self,
546 oldest: Option<(khive_storage::tx_registry::TxId, Duration, Option<String>)>,
547 config: &CheckpointConfig,
548 ) -> Vec<TxAgeEmission> {
549 let mut emissions = Vec::new();
550
551 let Some((id, age, label)) = oldest else {
552 self.was_above_warn = false;
553 self.was_above_max_age = false;
554 self.tracked_id = None;
555 return emissions;
556 };
557
558 if self.tracked_id != Some(id) {
559 self.was_above_warn = false;
560 self.was_above_max_age = false;
561 }
562 self.tracked_id = Some(id);
563
564 let above_warn = age >= config.tx_warn_secs;
565 let above_max_age = age >= config.tx_max_age_secs;
566
567 if above_warn && !self.was_above_warn {
568 emissions.push(TxAgeEmission {
569 rung: TxAgeRung::Warn,
570 age,
571 label: label.clone(),
572 });
573 }
574 if above_max_age && !self.was_above_max_age {
575 emissions.push(TxAgeEmission {
576 rung: TxAgeRung::Stale,
577 age,
578 label,
579 });
580 }
581
582 self.was_above_warn = above_warn;
583 self.was_above_max_age = above_max_age;
584 emissions
585 }
586}
587
588fn log_tx_age_emission(emission: &TxAgeEmission) {
593 let label = emission.label.as_deref().unwrap_or("<unlabeled>");
594 match emission.rung {
595 TxAgeRung::Warn => {
596 tracing::warn!(
597 tx_age_secs = emission.age.as_secs_f64(),
598 tx_label = label,
599 "ADR-091 Plank 1: open transaction registry entry exceeded soft-cap age"
600 );
601 }
602 TxAgeRung::Stale => {
603 tracing::error!(
604 tx_age_secs = emission.age.as_secs_f64(),
605 tx_label = label,
606 "ADR-091 Plank 1: open transaction registry entry exceeded the cooperative \
607 stale-op cap; no in-process mechanism can force-close it — investigate the \
608 labeled caller directly"
609 );
610 }
611 }
612}
613
614pub async fn run_checkpoint_task(
634 pool: Arc<ConnectionPool>,
635 config: CheckpointConfig,
636 event_store: Option<Arc<dyn khive_storage::EventStore>>,
637 namespace: String,
638 mut shutdown_rx: tokio::sync::watch::Receiver<()>,
639) {
640 let mut interval = tokio::time::interval(config.interval);
641 interval.set_missed_tick_behavior(tokio::time::MissedTickBehavior::Skip);
642 let mut severity_state = CheckpointSeverityState::default();
643 let mut tx_age_state = TxAgeSweepState::default();
644 let mut was_above_high_water = false;
645 let mut truncate_state = TruncateState::default();
646 let mut event_was_elevated = false;
651
652 loop {
653 tokio::select! {
658 _ = interval.tick() => {}
659 _ = shutdown_rx.changed() => break,
660 }
661
662 let tick = checkpoint_once(&pool, &config, &mut truncate_state);
663
664 for emission in tx_age_state.observe(khive_storage::tx_registry::oldest(), &config) {
680 log_tx_age_emission(&emission);
681 }
682
683 let wal_pages = match tick {
686 CheckpointTick::Skipped => continue,
687 CheckpointTick::Observed(n) => n,
688 };
689
690 let above_warn = wal_pages >= config.warn_pages;
691 let above_high_water = wal_pages >= config.high_water_pages;
692 let above_truncate_high_water = wal_pages >= config.truncate_high_water_pages;
693
694 log_tx_registry_oldest_debug(wal_pages);
699
700 for emission in severity_state.observe_wal_pages(wal_pages, &config) {
705 match emission.rung {
706 CheckpointSeverityRung::Info => {
707 log_tx_registry_oldest_warn(wal_pages);
708 tracing::info!(
709 wal_pages = emission.wal_pages,
710 warn_threshold = emission.threshold_pages,
711 "WAL page count crossed warn threshold"
712 );
713 }
714 CheckpointSeverityRung::Warn => {
715 tracing::warn!(
716 wal_pages = emission.wal_pages,
717 warn_threshold = emission.threshold_pages,
718 consecutive_cycles = emission.consecutive_cycles,
719 "WAL page count failed to drain below warn threshold"
720 );
721 }
722 CheckpointSeverityRung::Alarm => {
723 }
725 }
726 }
727
728 let high_water_crossed = crossing_warn(above_high_water, &mut was_above_high_water);
729 if high_water_crossed {
730 log_tx_registry_snapshot_warn(wal_pages);
731 tracing::warn!(
732 wal_pages,
733 high_water = config.high_water_pages,
734 "WAL high-water mark exceeded; sustained WAL pressure — \
735 a long-lived reader may be pinning an old snapshot that PASSIVE cannot reclaim"
736 );
737 }
738
739 if checkpoint_outcome_should_emit(above_warn, event_was_elevated) {
743 let payload = khive_storage::CheckpointOutcomeRecordedPayload {
744 wal_pages,
745 warn_pages: config.warn_pages,
746 high_water_pages: config.high_water_pages,
747 truncate_high_water_pages: config.truncate_high_water_pages,
748 above_warn,
749 above_high_water,
750 above_truncate_high_water,
751 };
752 append_checkpoint_lifecycle_event(
753 event_store.as_ref(),
754 &namespace,
755 khive_types::EventKind::CheckpointOutcomeRecorded,
756 payload,
757 )
758 .await;
759 }
760 event_was_elevated = above_warn;
761 }
762}
763
764fn checkpoint_outcome_should_emit(above_warn: bool, was_elevated: bool) -> bool {
770 above_warn || was_elevated
771}
772
773async fn append_checkpoint_lifecycle_event<P: serde::Serialize>(
780 store: Option<&Arc<dyn khive_storage::EventStore>>,
781 namespace: &str,
782 kind: khive_types::EventKind,
783 payload: P,
784) {
785 let Some(store) = store else {
786 return;
787 };
788 let payload_value = match serde_json::to_value(&payload) {
789 Ok(v) => v,
790 Err(e) => {
791 tracing::warn!(
792 error = %e,
793 event_kind = %kind.name(),
794 "failed to serialize checkpoint lifecycle event payload"
795 );
796 return;
797 }
798 };
799 let event = khive_storage::Event::new(
800 namespace,
801 "checkpoint.lifecycle",
802 kind,
803 khive_types::SubstrateKind::Event,
804 "daemon:checkpoint_task",
805 )
806 .with_payload(payload_value);
807 if let Err(err) = store.append_event(event).await {
808 tracing::warn!(
809 error = %err,
810 event_kind = %kind.name(),
811 "checkpoint lifecycle event append failed"
812 );
813 }
814}
815
816fn log_tx_registry_oldest_debug(wal_pages: u64) {
823 if let Some((_id, age, label)) = khive_storage::tx_registry::oldest() {
824 tracing::debug!(
825 wal_pages,
826 oldest_tx_age_secs = age.as_secs_f64(),
827 oldest_tx_label = label.as_deref().unwrap_or("<unlabeled>"),
828 "WAL checkpoint tick: oldest open transaction registry entry"
829 );
830 }
831}
832
833fn log_tx_registry_oldest_warn(wal_pages: u64) {
837 if let Some((_id, age, label)) = khive_storage::tx_registry::oldest() {
838 tracing::warn!(
839 wal_pages,
840 oldest_tx_age_secs = age.as_secs_f64(),
841 oldest_tx_label = label.as_deref().unwrap_or("<unlabeled>"),
842 "WAL checkpoint tick: oldest open transaction registry entry"
843 );
844 }
845}
846
847fn log_tx_registry_snapshot_warn(wal_pages: u64) {
851 for (age, label) in khive_storage::tx_registry::snapshot() {
852 tracing::warn!(
853 wal_pages,
854 tx_age_secs = age.as_secs_f64(),
855 tx_label = label.as_deref().unwrap_or("<unlabeled>"),
856 "WAL high-water: open transaction registry entry"
857 );
858 }
859}
860
861pub fn checkpoint_once(
878 pool: &ConnectionPool,
879 config: &CheckpointConfig,
880 truncate_state: &mut TruncateState,
881) -> CheckpointTick {
882 let writer = match pool.try_writer_nowait() {
883 Ok(w) => w,
884 Err(_) => {
885 note_checkpoint_skipped();
886 return CheckpointTick::Skipped;
887 }
888 };
889
890 let wal_pages = query_wal_pages(writer.conn());
891
892 if let Err(e) = writer
893 .conn()
894 .execute_batch("PRAGMA wal_checkpoint(PASSIVE)")
895 {
896 tracing::warn!(error = %e, "WAL checkpoint failed");
897 } else {
898 tracing::debug!(wal_pages, "WAL checkpoint issued");
899 }
900
901 maybe_truncate(pool, &writer, config, wal_pages, truncate_state);
902
903 CheckpointTick::Observed(wal_pages)
904}
905
906fn maybe_truncate(
911 pool: &ConnectionPool,
912 writer: &WriterGuard<'_>,
913 config: &CheckpointConfig,
914 wal_pages_before: u64,
915 truncate_state: &mut TruncateState,
916) {
917 if wal_pages_before < config.truncate_high_water_pages {
918 return;
919 }
920
921 if let Some(last) = truncate_state.last_attempt {
922 if last.elapsed() < config.truncate_min_interval {
923 return;
924 }
925 }
926
927 log_tx_registry_snapshot_warn(wal_pages_before);
930
931 let conn = writer.conn();
932 let original_busy_timeout = pool.config().busy_timeout;
933
934 if let Err(e) = conn.busy_timeout(config.truncate_busy_timeout) {
935 tracing::warn!(error = %e, "failed to lower busy_timeout for TRUNCATE attempt; skipping");
941 return;
942 }
943
944 truncate_state.last_attempt = Some(Instant::now());
948
949 let start = Instant::now();
950 let outcome = conn.execute_batch("PRAGMA wal_checkpoint(TRUNCATE)");
951 let elapsed = start.elapsed();
952
953 if let Err(e) = conn.busy_timeout(original_busy_timeout) {
956 tracing::warn!(error = %e, "failed to restore busy_timeout after TRUNCATE attempt");
957 }
958
959 match outcome {
960 Ok(()) => {
961 let wal_pages_after = query_wal_pages(conn);
962 tracing::info!(
963 wal_pages_before,
964 wal_pages_after,
965 elapsed_ms = elapsed.as_millis() as u64,
966 "WAL TRUNCATE checkpoint attempted"
967 );
968
969 let made_progress = wal_pages_after < wal_pages_before;
970 if !made_progress {
971 tracing::warn!(
972 wal_pages_before,
973 wal_pages_after,
974 "WAL TRUNCATE attempt made no progress; \
975 a long-lived reader may still be pinning the WAL snapshot"
976 );
977 log_tx_registry_snapshot_warn(wal_pages_after);
978 }
979
980 note_truncate_outcome(config, wal_pages_after, truncate_state);
981 }
982 Err(e) => {
983 tracing::warn!(error = %e, wal_pages_before, "WAL TRUNCATE attempt failed");
984 log_tx_registry_snapshot_warn(wal_pages_before);
985 note_truncate_outcome(config, wal_pages_before, truncate_state);
986 }
987 }
988}
989
990fn note_truncate_outcome(
996 config: &CheckpointConfig,
997 wal_pages_after: u64,
998 state: &mut TruncateState,
999) {
1000 TRUNCATE_ATTEMPTS.fetch_add(1, Ordering::Relaxed);
1005
1006 if wal_pages_after >= config.warn_pages {
1007 state.consecutive_failures = state.consecutive_failures.saturating_add(1);
1008 if state.consecutive_failures == 3 {
1009 tracing::warn!(
1010 wal_pages_after,
1011 warn_threshold = config.warn_pages,
1012 "WAL TRUNCATE has failed to clear WAL pressure for 3 consecutive attempts"
1013 );
1014 }
1015 } else {
1016 state.consecutive_failures = 0;
1017 }
1018
1019 TRUNCATE_CONSECUTIVE_FAILURES.store(state.consecutive_failures as u64, Ordering::Relaxed);
1020}
1021
1022fn crossing_warn(now_above: bool, was_above: &mut bool) -> bool {
1031 let fire = now_above && !*was_above;
1032 *was_above = now_above;
1033 fire
1034}
1035
1036fn query_wal_pages(conn: &rusqlite::Connection) -> u64 {
1049 let pages = conn
1050 .query_row("PRAGMA wal_checkpoint", [], |row| row.get::<_, i64>(1))
1051 .unwrap_or(0)
1052 .max(0) as u64;
1053 LAST_WAL_PAGES.store(pages, Ordering::Relaxed);
1057 note_checkpoint_observed(pages);
1058 pages
1059}
1060
1061#[cfg(test)]
1062mod tests {
1063 use super::*;
1064 use crate::pool::PoolConfig;
1065 use serial_test::serial;
1066 use tracing::field::{Field, Visit};
1067
1068 #[derive(Clone, Debug, Default)]
1069 struct CapturedEvent {
1070 message: Option<String>,
1071 oldest_tx_label: Option<String>,
1072 tx_label: Option<String>,
1073 }
1074
1075 #[derive(Default)]
1076 struct CapturedEventVisitor(CapturedEvent);
1077
1078 impl Visit for CapturedEventVisitor {
1079 fn record_str(&mut self, field: &Field, value: &str) {
1080 match field.name() {
1081 "message" => self.0.message = Some(value.to_string()),
1082 "oldest_tx_label" => self.0.oldest_tx_label = Some(value.to_string()),
1083 "tx_label" => self.0.tx_label = Some(value.to_string()),
1084 _ => {}
1085 }
1086 }
1087
1088 fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
1089 let formatted = format!("{value:?}");
1090 let cleaned = formatted
1091 .trim_start_matches('"')
1092 .trim_end_matches('"')
1093 .to_string();
1094 match field.name() {
1095 "message" => self.0.message = Some(cleaned),
1096 "oldest_tx_label" => self.0.oldest_tx_label = Some(cleaned),
1097 "tx_label" => self.0.tx_label = Some(cleaned),
1098 _ => {}
1099 }
1100 }
1101 }
1102
1103 struct CaptureSubscriber {
1108 events: std::sync::Arc<std::sync::Mutex<Vec<CapturedEvent>>>,
1109 }
1110
1111 impl tracing::Subscriber for CaptureSubscriber {
1112 fn enabled(&self, _: &tracing::Metadata<'_>) -> bool {
1113 true
1114 }
1115 fn new_span(&self, _: &tracing::span::Attributes<'_>) -> tracing::span::Id {
1116 tracing::span::Id::from_u64(1)
1117 }
1118 fn record(&self, _: &tracing::span::Id, _: &tracing::span::Record<'_>) {}
1119 fn record_follows_from(&self, _: &tracing::span::Id, _: &tracing::span::Id) {}
1120 fn event(&self, event: &tracing::Event<'_>) {
1121 let mut visitor = CapturedEventVisitor::default();
1122 event.record(&mut visitor);
1123 self.events.lock().unwrap().push(visitor.0);
1124 }
1125 fn enter(&self, _: &tracing::span::Id) {}
1126 fn exit(&self, _: &tracing::span::Id) {}
1127 }
1128
1129 #[test]
1132 #[serial(tx_registry)]
1133 fn log_tx_registry_oldest_debug_reports_oldest_open_entry() {
1134 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
1135 let subscriber = CaptureSubscriber {
1136 events: std::sync::Arc::clone(&buffer),
1137 };
1138
1139 let _handle =
1140 khive_storage::tx_registry::register(Some("checkpoint_tick_test".to_string()));
1141
1142 let expected_label = khive_storage::tx_registry::oldest()
1143 .and_then(|(_, _, label)| label)
1144 .unwrap_or_else(|| "<unlabeled>".to_string());
1145
1146 tracing::subscriber::with_default(subscriber, || {
1147 log_tx_registry_oldest_debug(100);
1148 });
1149
1150 let events = buffer.lock().unwrap();
1151 assert!(
1152 events.iter().any(|e| {
1153 e.message.as_deref()
1154 == Some("WAL checkpoint tick: oldest open transaction registry entry")
1155 && e.oldest_tx_label.as_deref() == Some(expected_label.as_str())
1156 }),
1157 "expected a log line naming the open registry entry's label, got: {events:?}"
1158 );
1159 }
1160
1161 #[test]
1167 #[serial(tx_registry)]
1168 fn registry_warns_fire_on_crossing_and_do_not_repeat() {
1169 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
1170 let subscriber = CaptureSubscriber {
1171 events: std::sync::Arc::clone(&buffer),
1172 };
1173
1174 let _handle =
1175 khive_storage::tx_registry::register(Some("registry_warn_crossing_test".to_string()));
1176
1177 let mut was_above_warn = false;
1178 let mut was_above_high_water = false;
1179
1180 tracing::subscriber::with_default(subscriber, || {
1181 if crossing_warn(true, &mut was_above_warn) {
1183 log_tx_registry_oldest_warn(6000);
1184 }
1185 if crossing_warn(true, &mut was_above_high_water) {
1186 log_tx_registry_snapshot_warn(6000);
1187 }
1188
1189 if crossing_warn(true, &mut was_above_warn) {
1191 log_tx_registry_oldest_warn(6000);
1192 }
1193 if crossing_warn(true, &mut was_above_high_water) {
1194 log_tx_registry_snapshot_warn(6000);
1195 }
1196 });
1197
1198 let events = buffer.lock().unwrap();
1199
1200 let oldest_warn_count = events
1210 .iter()
1211 .filter(|e| {
1212 e.message.as_deref()
1213 == Some("WAL checkpoint tick: oldest open transaction registry entry")
1214 })
1215 .count();
1216 assert_eq!(
1217 oldest_warn_count, 1,
1218 "oldest-entry WARN must fire exactly once across two above-threshold ticks, got: {events:?}"
1219 );
1220
1221 let snapshot_warn_count = events
1222 .iter()
1223 .filter(|e| {
1224 e.message.as_deref() == Some("WAL high-water: open transaction registry entry")
1225 && e.tx_label.as_deref() == Some("registry_warn_crossing_test")
1226 })
1227 .count();
1228 assert_eq!(
1229 snapshot_warn_count, 1,
1230 "high-water snapshot WARN must fire exactly once across two above-threshold ticks, got: {events:?}"
1231 );
1232 }
1233
1234 #[test]
1237 fn log_tx_age_emission_carries_label_for_both_rungs() {
1238 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
1239 let subscriber = CaptureSubscriber {
1240 events: std::sync::Arc::clone(&buffer),
1241 };
1242
1243 tracing::subscriber::with_default(subscriber, || {
1244 log_tx_age_emission(&TxAgeEmission {
1245 rung: TxAgeRung::Warn,
1246 age: Duration::from_secs(45),
1247 label: Some("plank1_warn_test".to_string()),
1248 });
1249 log_tx_age_emission(&TxAgeEmission {
1250 rung: TxAgeRung::Stale,
1251 age: Duration::from_secs(150),
1252 label: Some("plank1_stale_test".to_string()),
1253 });
1254 });
1255
1256 let events = buffer.lock().unwrap();
1257 assert!(
1258 events.iter().any(|e| {
1259 e.message.as_deref()
1260 == Some(
1261 "ADR-091 Plank 1: open transaction registry entry exceeded soft-cap age",
1262 )
1263 && e.tx_label.as_deref() == Some("plank1_warn_test")
1264 }),
1265 "expected a Warn-rung log line naming the entry, got: {events:?}"
1266 );
1267 assert!(
1268 events.iter().any(|e| {
1269 e.message.as_deref().is_some_and(|m| {
1270 m.starts_with(
1271 "ADR-091 Plank 1: open transaction registry entry exceeded the cooperative",
1272 )
1273 }) && e.tx_label.as_deref() == Some("plank1_stale_test")
1274 }),
1275 "expected a Stale-rung log line naming the entry, got: {events:?}"
1276 );
1277 }
1278
1279 fn file_pool(path: &std::path::Path) -> Arc<ConnectionPool> {
1280 let cfg = PoolConfig {
1281 path: Some(path.to_path_buf()),
1282 ..PoolConfig::default()
1283 };
1284 Arc::new(ConnectionPool::new(cfg).expect("pool open"))
1285 }
1286
1287 #[test]
1293 #[serial(checkpoint_skip_metrics)]
1294 fn checkpoint_once_succeeds_on_file_backed_pool() {
1295 let dir = tempfile::tempdir().unwrap();
1296 let path = dir.path().join("wal_test.db");
1297 let pool = file_pool(&path);
1298
1299 {
1301 let writer = pool.try_writer().unwrap();
1302 writer
1303 .conn()
1304 .execute_batch("CREATE TABLE IF NOT EXISTS t (x INTEGER);")
1305 .unwrap();
1306 writer
1307 .conn()
1308 .execute_batch("INSERT INTO t VALUES (1);")
1309 .unwrap();
1310 }
1311
1312 checkpoint_once(
1313 &pool,
1314 &CheckpointConfig::default(),
1315 &mut TruncateState::default(),
1316 );
1317 }
1318
1319 #[test]
1320 #[serial(checkpoint_skip_metrics)]
1321 fn checkpoint_once_is_noop_on_in_memory_pool() {
1322 let cfg = PoolConfig {
1324 path: None,
1325 ..PoolConfig::default()
1326 };
1327 let pool = Arc::new(ConnectionPool::new(cfg).expect("in-memory pool"));
1328 checkpoint_once(
1329 &pool,
1330 &CheckpointConfig::default(),
1331 &mut TruncateState::default(),
1332 );
1333 }
1334
1335 #[tokio::test]
1336 #[serial(checkpoint_skip_metrics)]
1337 async fn checkpoint_task_exits_on_shutdown_signal() {
1338 let dir = tempfile::tempdir().unwrap();
1339 let path = dir.path().join("wal_task_shutdown.db");
1340 let pool = file_pool(&path);
1341
1342 let cfg = CheckpointConfig {
1344 interval: Duration::from_millis(10),
1345 ..Default::default()
1346 };
1347
1348 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
1349 let handle = tokio::spawn(run_checkpoint_task(
1350 pool,
1351 cfg,
1352 None,
1353 "local".to_string(),
1354 shutdown_rx,
1355 ));
1356
1357 shutdown_tx.send(()).expect("send shutdown signal");
1358
1359 tokio::time::timeout(Duration::from_secs(1), handle)
1360 .await
1361 .expect("checkpoint task should exit within 1s")
1362 .expect("checkpoint task panicked");
1363 }
1364
1365 #[tokio::test]
1369 #[serial(checkpoint_skip_metrics)]
1370 async fn checkpoint_task_exits_via_shutdown_signal_with_live_event_store_pool_clone() {
1371 let dir = tempfile::tempdir().unwrap();
1372 let path = dir.path().join("wal_task_event_store.db");
1373 let pool = file_pool(&path);
1374
1375 let cfg = CheckpointConfig {
1376 interval: Duration::from_millis(10),
1377 ..Default::default()
1378 };
1379
1380 let event_store: Arc<dyn khive_storage::EventStore> =
1381 Arc::new(crate::stores::event::SqlEventStore::new_scoped(
1382 Arc::clone(&pool),
1383 true,
1384 "local".to_string(),
1385 ));
1386 let sibling_pool_clone = Arc::clone(&pool);
1391
1392 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
1393 let handle = tokio::spawn(run_checkpoint_task(
1394 pool,
1395 cfg,
1396 Some(event_store),
1397 "local".to_string(),
1398 shutdown_rx,
1399 ));
1400
1401 assert!(
1405 Arc::strong_count(&sibling_pool_clone) > 1,
1406 "test setup must reproduce the multi-owner shape the bug depends on"
1407 );
1408
1409 shutdown_tx.send(()).expect("send shutdown signal");
1410
1411 tokio::time::timeout(Duration::from_secs(1), handle)
1412 .await
1413 .expect(
1414 "checkpoint task should exit within 1s via the watch signal, \
1415 even with a live sibling Arc<ConnectionPool> clone held by \
1416 the event store",
1417 )
1418 .expect("checkpoint task panicked");
1419 }
1420
1421 #[test]
1422 #[serial]
1423 fn checkpoint_config_env_override() {
1424 std::env::set_var("KHIVE_CHECKPOINT_INTERVAL_MS", "250");
1425 std::env::set_var("KHIVE_WAL_WARN_PAGES", "1500");
1426 std::env::set_var("KHIVE_WAL_HIGH_WATER_PAGES", "8000");
1427 std::env::set_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES", "12000");
1428 std::env::set_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS", "60");
1429 std::env::set_var("KHIVE_WAL_TRUNCATE_BUSY_MS", "500");
1430 std::env::set_var("KHIVE_TX_WARN_SECS", "15");
1431 std::env::set_var("KHIVE_TX_MAX_AGE_SECS", "90");
1432
1433 let cfg = CheckpointConfig::from_env();
1434
1435 std::env::remove_var("KHIVE_CHECKPOINT_INTERVAL_MS");
1436 std::env::remove_var("KHIVE_WAL_WARN_PAGES");
1437 std::env::remove_var("KHIVE_WAL_HIGH_WATER_PAGES");
1438 std::env::remove_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES");
1439 std::env::remove_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS");
1440 std::env::remove_var("KHIVE_WAL_TRUNCATE_BUSY_MS");
1441 std::env::remove_var("KHIVE_TX_WARN_SECS");
1442 std::env::remove_var("KHIVE_TX_MAX_AGE_SECS");
1443
1444 assert_eq!(cfg.interval, Duration::from_millis(250));
1445 assert_eq!(cfg.warn_pages, 1500);
1446 assert_eq!(cfg.high_water_pages, 8000);
1447 assert_eq!(cfg.truncate_high_water_pages, 12000);
1448 assert_eq!(cfg.truncate_min_interval, Duration::from_secs(60));
1449 assert_eq!(cfg.truncate_busy_timeout, Duration::from_millis(500));
1450 assert_eq!(cfg.tx_warn_secs, Duration::from_secs(15));
1451 assert_eq!(cfg.tx_max_age_secs, Duration::from_secs(90));
1452 }
1453
1454 #[test]
1455 #[serial]
1456 fn checkpoint_config_defaults_on_invalid_env() {
1457 let default = CheckpointConfig::default();
1458
1459 std::env::set_var("KHIVE_CHECKPOINT_INTERVAL_MS", "not_a_number");
1460 std::env::set_var("KHIVE_WAL_WARN_PAGES", "");
1461 std::env::set_var("KHIVE_WAL_HIGH_WATER_PAGES", "0");
1462 std::env::set_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES", "not_a_number");
1463 std::env::set_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS", "");
1464 std::env::set_var("KHIVE_WAL_TRUNCATE_BUSY_MS", "0");
1465 std::env::set_var("KHIVE_TX_WARN_SECS", "not_a_number");
1466 std::env::set_var("KHIVE_TX_MAX_AGE_SECS", "0");
1467
1468 let cfg = CheckpointConfig::from_env();
1469
1470 std::env::remove_var("KHIVE_CHECKPOINT_INTERVAL_MS");
1471 std::env::remove_var("KHIVE_WAL_WARN_PAGES");
1472 std::env::remove_var("KHIVE_WAL_HIGH_WATER_PAGES");
1473 std::env::remove_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES");
1474 std::env::remove_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS");
1475 std::env::remove_var("KHIVE_WAL_TRUNCATE_BUSY_MS");
1476 std::env::remove_var("KHIVE_TX_WARN_SECS");
1477 std::env::remove_var("KHIVE_TX_MAX_AGE_SECS");
1478
1479 assert_eq!(cfg.interval, default.interval);
1480 assert_eq!(cfg.warn_pages, default.warn_pages);
1481 assert_eq!(cfg.high_water_pages, default.high_water_pages);
1482 assert_eq!(
1483 cfg.truncate_high_water_pages,
1484 default.truncate_high_water_pages
1485 );
1486 assert_eq!(cfg.truncate_min_interval, default.truncate_min_interval);
1487 assert_eq!(cfg.truncate_busy_timeout, default.truncate_busy_timeout);
1488 assert_eq!(cfg.tx_warn_secs, default.tx_warn_secs);
1489 assert_eq!(cfg.tx_max_age_secs, default.tx_max_age_secs);
1490 }
1491
1492 #[test]
1497 #[serial(checkpoint_skip_metrics)]
1498 fn checkpoint_high_water_does_not_block_behind_reader() {
1499 let dir = tempfile::tempdir().unwrap();
1500 let path = dir.path().join("high_water_test.db");
1501
1502 let pool = Arc::new(
1506 ConnectionPool::new(PoolConfig {
1507 path: Some(path.clone()),
1508 busy_timeout: Duration::from_millis(2000),
1509 ..PoolConfig::default()
1510 })
1511 .expect("pool open"),
1512 );
1513
1514 {
1516 let writer = pool.try_writer().unwrap();
1517 writer
1518 .conn()
1519 .execute_batch(
1520 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
1521 )
1522 .unwrap();
1523 }
1524
1525 let reader = pool.reader().expect("reader");
1529 reader
1530 .execute_batch("BEGIN DEFERRED; SELECT * FROM t;")
1531 .expect("begin read tx");
1532
1533 {
1537 let writer = pool.try_writer().unwrap();
1538 writer
1539 .conn()
1540 .execute_batch("INSERT INTO t VALUES (2);")
1541 .unwrap();
1542 }
1543
1544 let start = std::time::Instant::now();
1545 checkpoint_once(
1546 &pool,
1547 &CheckpointConfig::default(),
1548 &mut TruncateState::default(),
1549 );
1550 let elapsed = start.elapsed();
1551
1552 reader.execute_batch("COMMIT;").ok();
1554 drop(reader);
1555
1556 assert!(
1560 elapsed < std::time::Duration::from_millis(500),
1561 "checkpoint_once with active reader snapshot took {:?}; \
1562 expected <500ms (PASSIVE must not block on readers; \
1563 a TRUNCATE regression would block ~2000ms)",
1564 elapsed
1565 );
1566 }
1567
1568 #[test]
1569 #[serial]
1570 fn checkpoint_config_rejects_zero_for_all_fields() {
1571 let default = CheckpointConfig::default();
1572 std::env::set_var("KHIVE_CHECKPOINT_INTERVAL_MS", "0");
1573 std::env::set_var("KHIVE_WAL_WARN_PAGES", "0");
1574 std::env::set_var("KHIVE_WAL_HIGH_WATER_PAGES", "0");
1575 std::env::set_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES", "0");
1576 std::env::set_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS", "0");
1577 std::env::set_var("KHIVE_WAL_TRUNCATE_BUSY_MS", "0");
1578 std::env::set_var("KHIVE_TX_WARN_SECS", "0");
1579 std::env::set_var("KHIVE_TX_MAX_AGE_SECS", "0");
1580
1581 let cfg = CheckpointConfig::from_env();
1582
1583 std::env::remove_var("KHIVE_CHECKPOINT_INTERVAL_MS");
1584 std::env::remove_var("KHIVE_WAL_WARN_PAGES");
1585 std::env::remove_var("KHIVE_WAL_HIGH_WATER_PAGES");
1586 std::env::remove_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES");
1587 std::env::remove_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS");
1588 std::env::remove_var("KHIVE_WAL_TRUNCATE_BUSY_MS");
1589 std::env::remove_var("KHIVE_TX_WARN_SECS");
1590 std::env::remove_var("KHIVE_TX_MAX_AGE_SECS");
1591
1592 assert_eq!(
1593 cfg.interval, default.interval,
1594 "zero interval must fall back to default"
1595 );
1596 assert_eq!(
1597 cfg.warn_pages, default.warn_pages,
1598 "zero warn_pages must fall back to default"
1599 );
1600 assert_eq!(
1601 cfg.high_water_pages, default.high_water_pages,
1602 "zero high_water_pages must fall back to default"
1603 );
1604 assert_eq!(
1605 cfg.truncate_high_water_pages, default.truncate_high_water_pages,
1606 "zero truncate_high_water_pages must fall back to default"
1607 );
1608 assert_eq!(
1609 cfg.truncate_min_interval, default.truncate_min_interval,
1610 "zero truncate_min_interval must fall back to default"
1611 );
1612 assert_eq!(
1613 cfg.truncate_busy_timeout, default.truncate_busy_timeout,
1614 "zero truncate_busy_timeout must fall back to default"
1615 );
1616 assert_eq!(
1617 cfg.tx_warn_secs, default.tx_warn_secs,
1618 "zero tx_warn_secs must fall back to default"
1619 );
1620 assert_eq!(
1621 cfg.tx_max_age_secs, default.tx_max_age_secs,
1622 "zero tx_max_age_secs must fall back to default"
1623 );
1624 }
1625
1626 #[test]
1629 #[serial]
1630 fn checkpoint_config_rejects_reversed_tx_thresholds() {
1631 let default = CheckpointConfig::default();
1632 std::env::set_var("KHIVE_TX_WARN_SECS", "120");
1633 std::env::set_var("KHIVE_TX_MAX_AGE_SECS", "30");
1634
1635 let cfg = CheckpointConfig::from_env();
1636
1637 std::env::remove_var("KHIVE_TX_WARN_SECS");
1638 std::env::remove_var("KHIVE_TX_MAX_AGE_SECS");
1639
1640 assert_eq!(
1641 cfg.tx_warn_secs, default.tx_warn_secs,
1642 "a reversed pair must fall back tx_warn_secs to its default, got: {:?}",
1643 cfg.tx_warn_secs
1644 );
1645 assert_eq!(
1646 cfg.tx_max_age_secs, default.tx_max_age_secs,
1647 "a reversed pair must fall back tx_max_age_secs to its default, got: {:?}",
1648 cfg.tx_max_age_secs
1649 );
1650 }
1651
1652 #[test]
1655 #[serial]
1656 fn checkpoint_config_rejects_equal_tx_thresholds() {
1657 let default = CheckpointConfig::default();
1658 std::env::set_var("KHIVE_TX_WARN_SECS", "60");
1659 std::env::set_var("KHIVE_TX_MAX_AGE_SECS", "60");
1660
1661 let cfg = CheckpointConfig::from_env();
1662
1663 std::env::remove_var("KHIVE_TX_WARN_SECS");
1664 std::env::remove_var("KHIVE_TX_MAX_AGE_SECS");
1665
1666 assert_eq!(
1667 cfg.tx_warn_secs, default.tx_warn_secs,
1668 "an equal pair must fall back tx_warn_secs to its default, got: {:?}",
1669 cfg.tx_warn_secs
1670 );
1671 assert_eq!(
1672 cfg.tx_max_age_secs, default.tx_max_age_secs,
1673 "an equal pair must fall back tx_max_age_secs to its default, got: {:?}",
1674 cfg.tx_max_age_secs
1675 );
1676 }
1677
1678 #[test]
1681 fn skipped_tick_does_not_reset_high_water_crossing_state() {
1682 let mut was_above = false;
1683
1684 assert!(
1686 crossing_warn(true, &mut was_above),
1687 "should fire on first crossing"
1688 );
1689 assert!(was_above);
1690
1691 assert!(was_above, "was_above must stay true across skipped ticks");
1698
1699 let fired = crossing_warn(true, &mut was_above);
1701 assert!(!fired, "WARN must not re-fire while still above threshold");
1702
1703 let fired = crossing_warn(false, &mut was_above);
1705 assert!(!fired);
1706 assert!(!was_above);
1707
1708 let fired = crossing_warn(true, &mut was_above);
1710 assert!(fired, "WARN must fire again on a new below→above crossing");
1711 }
1712
1713 #[test]
1720 fn warn_pages_fires_once_on_crossing_not_every_tick() {
1721 let mut was_above_warn = false;
1722
1723 let fired_1 = crossing_warn(true, &mut was_above_warn);
1725 let fired_2 = crossing_warn(true, &mut was_above_warn);
1726 let fired_3 = crossing_warn(true, &mut was_above_warn);
1727
1728 assert!(fired_1, "WARN must fire on the first in-band tick");
1729 assert!(
1730 !fired_2,
1731 "WARN must not fire on the second consecutive in-band tick"
1732 );
1733 assert!(
1734 !fired_3,
1735 "WARN must not fire on the third consecutive in-band tick"
1736 );
1737
1738 crossing_warn(false, &mut was_above_warn);
1740 assert!(!was_above_warn);
1741
1742 let fired_reentry = crossing_warn(true, &mut was_above_warn);
1744 assert!(
1745 fired_reentry,
1746 "WARN must fire again on re-entry into warn band"
1747 );
1748 }
1749
1750 #[test]
1756 #[serial(tx_registry, checkpoint_skip_metrics)]
1757 fn truncate_attempts_when_high_water_crossed_with_no_prior_attempt() {
1758 let dir = tempfile::tempdir().unwrap();
1759 let path = dir.path().join("truncate_trigger.db");
1760 let pool = file_pool(&path);
1761
1762 {
1763 let writer = pool.try_writer().unwrap();
1764 writer
1765 .conn()
1766 .execute_batch(
1767 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
1768 )
1769 .unwrap();
1770 }
1771
1772 let config = CheckpointConfig {
1773 truncate_high_water_pages: 0,
1777 truncate_min_interval: Duration::from_secs(300),
1778 ..CheckpointConfig::default()
1779 };
1780 let mut state = TruncateState::default();
1781
1782 assert!(
1783 state.last_attempt.is_none(),
1784 "precondition: no attempt has run yet"
1785 );
1786
1787 let tick = checkpoint_once(&pool, &config, &mut state);
1788 assert!(matches!(tick, CheckpointTick::Observed(_)));
1789 assert!(
1790 state.last_attempt.is_some(),
1791 "an attempt must be stamped once the high-water threshold is crossed"
1792 );
1793 }
1794
1795 #[test]
1798 #[serial(tx_registry, checkpoint_skip_metrics)]
1799 fn truncate_does_not_attempt_below_high_water() {
1800 let dir = tempfile::tempdir().unwrap();
1801 let path = dir.path().join("truncate_below_threshold.db");
1802 let pool = file_pool(&path);
1803
1804 {
1805 let writer = pool.try_writer().unwrap();
1806 writer
1807 .conn()
1808 .execute_batch(
1809 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
1810 )
1811 .unwrap();
1812 }
1813
1814 let config = CheckpointConfig {
1816 truncate_high_water_pages: u64::MAX,
1817 ..CheckpointConfig::default()
1818 };
1819 let mut state = TruncateState::default();
1820
1821 checkpoint_once(&pool, &config, &mut state);
1822
1823 assert!(
1824 state.last_attempt.is_none(),
1825 "a below-threshold tick must never stamp last_attempt"
1826 );
1827 }
1828
1829 #[test]
1833 #[serial(tx_registry, checkpoint_skip_metrics)]
1834 fn truncate_min_interval_skip_does_not_restamp_last_attempt() {
1835 let dir = tempfile::tempdir().unwrap();
1836 let path = dir.path().join("truncate_min_interval.db");
1837 let pool = file_pool(&path);
1838
1839 {
1840 let writer = pool.try_writer().unwrap();
1841 writer
1842 .conn()
1843 .execute_batch(
1844 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
1845 )
1846 .unwrap();
1847 }
1848
1849 let config = CheckpointConfig {
1850 truncate_high_water_pages: 0,
1851 truncate_min_interval: Duration::from_secs(300),
1852 ..CheckpointConfig::default()
1853 };
1854 let mut state = TruncateState::default();
1855
1856 checkpoint_once(&pool, &config, &mut state);
1857 let first_attempt = state.last_attempt.expect("first tick must attempt");
1858
1859 checkpoint_once(&pool, &config, &mut state);
1863 let second_attempt = state.last_attempt.expect("attempt timestamp must persist");
1864
1865 assert_eq!(
1866 first_attempt, second_attempt,
1867 "a tick within truncate_min_interval must not re-stamp last_attempt"
1868 );
1869 }
1870
1871 #[test]
1878 #[serial(tx_registry, checkpoint_skip_metrics)]
1879 fn busy_writer_skips_both_passive_and_truncate() {
1880 reset_checkpoint_metrics_for_tests();
1881
1882 let dir = tempfile::tempdir().unwrap();
1883 let path = dir.path().join("truncate_busy_skip.db");
1884 let pool = file_pool(&path);
1885
1886 {
1887 let writer = pool.try_writer().unwrap();
1888 writer
1889 .conn()
1890 .execute_batch(
1891 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
1892 )
1893 .unwrap();
1894 }
1895
1896 let mut warmup_state = TruncateState::default();
1899 let warmup_tick = checkpoint_once(&pool, &CheckpointConfig::default(), &mut warmup_state);
1900 let observed_pages = match warmup_tick {
1901 CheckpointTick::Observed(n) => n,
1902 CheckpointTick::Skipped => panic!("warmup tick must observe, not skip"),
1903 };
1904 assert_eq!(
1905 checkpoint_consecutive_skips(),
1906 0,
1907 "an observed tick must not itself count as a skip"
1908 );
1909
1910 let _held = pool.try_writer().unwrap();
1913
1914 let config = CheckpointConfig {
1915 truncate_high_water_pages: 0,
1916 ..CheckpointConfig::default()
1917 };
1918 let mut state = TruncateState::default();
1919
1920 let tick = checkpoint_once(&pool, &config, &mut state);
1921
1922 assert_eq!(
1923 tick,
1924 CheckpointTick::Skipped,
1925 "a busy writer must skip the tick entirely"
1926 );
1927 assert!(
1928 state.last_attempt.is_none(),
1929 "a skipped tick (writer busy) must never stamp last_attempt, \
1930 even with a threshold that would otherwise arm immediately"
1931 );
1932
1933 assert_eq!(
1934 checkpoint_skipped_ticks(),
1935 1,
1936 "one skipped tick must bump the lifetime skipped-tick counter"
1937 );
1938 assert_eq!(
1939 checkpoint_consecutive_skips(),
1940 1,
1941 "one skipped tick must bump the consecutive-skip run length"
1942 );
1943 assert_eq!(
1944 checkpoint_last_skip_wal_pages(),
1945 Some(observed_pages),
1946 "the skip must snapshot the last-observed WAL pressure"
1947 );
1948 }
1949
1950 #[test]
1965 fn all_checkpoint_metrics_callers_are_serial_tagged() {
1966 const SELF_SRC: &str = include_str!("checkpoint.rs");
1967 let lines: Vec<&str> = SELF_SRC.lines().collect();
1968
1969 let attr_starts: Vec<usize> = lines
1970 .iter()
1971 .enumerate()
1972 .filter(|(_, l)| {
1973 let t = l.trim();
1974 t == "#[test]" || t.starts_with("#[tokio::test")
1975 })
1976 .map(|(i, _)| i)
1977 .collect();
1978
1979 let mut offenders = Vec::new();
1980
1981 for (idx, &start) in attr_starts.iter().enumerate() {
1982 let end = attr_starts.get(idx + 1).copied().unwrap_or(lines.len());
1983 let span = &lines[start..end];
1984
1985 let touches_shared_metrics = span
1986 .iter()
1987 .any(|l| l.contains("checkpoint_once(") || l.contains("run_checkpoint_task("));
1988 if !touches_shared_metrics {
1989 continue;
1990 }
1991
1992 let has_group_tag = span
1993 .iter()
1994 .any(|l| l.contains("#[serial") && l.contains("checkpoint_skip_metrics"));
1995
1996 if !has_group_tag {
1997 let name = span
1998 .iter()
1999 .find_map(|l| {
2000 let t = l.trim_start();
2001 let t = t.strip_prefix("pub(crate) ").unwrap_or(t);
2002 let t = t.strip_prefix("pub ").unwrap_or(t);
2003 let t = t.strip_prefix("async ").unwrap_or(t);
2004 t.strip_prefix("fn ")
2005 .map(|rest| rest.split(['(', '<']).next().unwrap_or("").trim())
2006 })
2007 .unwrap_or("<unknown test>");
2008 offenders.push(name.to_string());
2009 }
2010 }
2011
2012 assert!(
2013 offenders.is_empty(),
2014 "these tests call checkpoint_once/run_checkpoint_task (which write the \
2015 process-wide LAST_WAL_PAGES/CHECKPOINT_* atomics via query_wal_pages) but \
2016 are not tagged #[serial(checkpoint_skip_metrics)] (or a group including it); \
2017 an untagged caller running concurrently on cargo's default test thread pool \
2018 can clobber those atomics mid-assertion in another test (the #828/#845 race): \
2019 {offenders:?}"
2020 );
2021 }
2022
2023 #[test]
2027 #[serial(tx_registry, checkpoint_skip_metrics)]
2028 fn observed_tick_resets_consecutive_skips_but_not_lifetime_total() {
2029 reset_checkpoint_metrics_for_tests();
2030
2031 let dir = tempfile::tempdir().unwrap();
2032 let path = dir.path().join("skip_then_observe.db");
2033 let pool = file_pool(&path);
2034
2035 {
2036 let writer = pool.try_writer().unwrap();
2037 writer
2038 .conn()
2039 .execute_batch(
2040 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
2041 )
2042 .unwrap();
2043 }
2044
2045 {
2047 let _held = pool.try_writer().unwrap();
2048 let mut state = TruncateState::default();
2049 for _ in 0..2 {
2050 let tick = checkpoint_once(&pool, &CheckpointConfig::default(), &mut state);
2051 assert_eq!(tick, CheckpointTick::Skipped);
2052 }
2053 }
2054 assert_eq!(checkpoint_skipped_ticks(), 2);
2055 assert_eq!(checkpoint_consecutive_skips(), 2);
2056
2057 let mut state = TruncateState::default();
2059 let tick = checkpoint_once(&pool, &CheckpointConfig::default(), &mut state);
2060 assert!(matches!(tick, CheckpointTick::Observed(_)));
2061
2062 assert_eq!(
2063 checkpoint_skipped_ticks(),
2064 2,
2065 "an observed tick must not change the lifetime skipped-tick total"
2066 );
2067 assert_eq!(
2068 checkpoint_consecutive_skips(),
2069 0,
2070 "an observed tick must reset the consecutive-skip run length"
2071 );
2072 }
2073
2074 #[test]
2079 fn note_truncate_outcome_warns_once_at_third_consecutive_failure() {
2080 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
2081 let subscriber = CaptureSubscriber {
2082 events: std::sync::Arc::clone(&buffer),
2083 };
2084
2085 let config = CheckpointConfig {
2086 warn_pages: 2000,
2087 ..CheckpointConfig::default()
2088 };
2089 let mut state = TruncateState::default();
2090
2091 tracing::subscriber::with_default(subscriber, || {
2092 note_truncate_outcome(&config, 5000, &mut state);
2094 note_truncate_outcome(&config, 5000, &mut state);
2095 note_truncate_outcome(&config, 5000, &mut state);
2096 note_truncate_outcome(&config, 5000, &mut state);
2098 });
2099
2100 assert_eq!(state.consecutive_failures, 4);
2101
2102 let events = buffer.lock().unwrap();
2103 let escalation_count = events
2104 .iter()
2105 .filter(|e| {
2106 e.message.as_deref()
2107 == Some(
2108 "WAL TRUNCATE has failed to clear WAL pressure for 3 consecutive attempts",
2109 )
2110 })
2111 .count();
2112 assert_eq!(
2113 escalation_count, 1,
2114 "escalation WARN must fire exactly once at the 3rd consecutive failure, got: {events:?}"
2115 );
2116
2117 note_truncate_outcome(&config, 100, &mut state);
2119 assert_eq!(
2120 state.consecutive_failures, 0,
2121 "an attempt that clears warn_pages must reset the consecutive-failure counter"
2122 );
2123 }
2124
2125 fn severity_test_config() -> CheckpointConfig {
2128 CheckpointConfig {
2129 warn_pages: 100,
2130 warn_sustained_cycles: 3,
2131 ..CheckpointConfig::default()
2132 }
2133 }
2134
2135 #[test]
2138 fn severity_ladder_info_on_first_crossing_no_warn() {
2139 let config = severity_test_config();
2140 let mut state = CheckpointSeverityState::default();
2141
2142 let below = state.observe_wal_pages(10, &config);
2143 assert!(below.is_empty(), "below-warn tick must emit nothing");
2144
2145 let above = state.observe_wal_pages(150, &config);
2146 assert_eq!(
2147 above,
2148 vec![CheckpointSeverityEmission {
2149 rung: CheckpointSeverityRung::Info,
2150 wal_pages: 150,
2151 threshold_pages: 100,
2152 consecutive_cycles: 1,
2153 }],
2154 "first below->above crossing must emit exactly one INFO and no WARN"
2155 );
2156 }
2157
2158 #[test]
2161 fn severity_ladder_warn_on_third_consecutive_cycle() {
2162 let config = severity_test_config();
2163 let mut state = CheckpointSeverityState::default();
2164
2165 let tick1 = state.observe_wal_pages(150, &config);
2166 assert_eq!(tick1.len(), 1);
2167 assert_eq!(tick1[0].rung, CheckpointSeverityRung::Info);
2168
2169 let tick2 = state.observe_wal_pages(150, &config);
2170 assert!(
2171 tick2.is_empty(),
2172 "second consecutive above-warn tick must emit nothing yet"
2173 );
2174
2175 let tick3 = state.observe_wal_pages(150, &config);
2176 assert_eq!(
2177 tick3,
2178 vec![CheckpointSeverityEmission {
2179 rung: CheckpointSeverityRung::Warn,
2180 wal_pages: 150,
2181 threshold_pages: 100,
2182 consecutive_cycles: 3,
2183 }],
2184 "WARN must fire exactly on the third consecutive above-warn tick"
2185 );
2186
2187 let tick4 = state.observe_wal_pages(150, &config);
2188 assert!(
2189 tick4.is_empty(),
2190 "WARN must not repeat on a fourth consecutive above-warn tick"
2191 );
2192 }
2193
2194 #[test]
2197 fn severity_ladder_rearms_warn_after_drain() {
2198 let config = severity_test_config();
2199 let mut state = CheckpointSeverityState::default();
2200
2201 for _ in 0..3 {
2203 state.observe_wal_pages(150, &config);
2204 }
2205 assert!(state.warn_emitted_for_episode);
2206
2207 let drain = state.observe_wal_pages(10, &config);
2209 assert!(drain.is_empty(), "a draining tick must emit nothing");
2210
2211 let reentry = state.observe_wal_pages(150, &config);
2213 assert_eq!(reentry.len(), 1);
2214 assert_eq!(reentry[0].rung, CheckpointSeverityRung::Info);
2215
2216 let mid = state.observe_wal_pages(150, &config);
2217 assert!(mid.is_empty());
2218
2219 let second_warn = state.observe_wal_pages(150, &config);
2220 assert_eq!(
2221 second_warn,
2222 vec![CheckpointSeverityEmission {
2223 rung: CheckpointSeverityRung::Warn,
2224 wal_pages: 150,
2225 threshold_pages: 100,
2226 consecutive_cycles: 3,
2227 }],
2228 "a fresh elevation episode after a drain must WARN again"
2229 );
2230 }
2231
2232 #[test]
2235 fn severity_ladder_isolated_crossings_never_warn() {
2236 let config = severity_test_config();
2237 let mut state = CheckpointSeverityState::default();
2238
2239 for _ in 0..3 {
2240 let crossing = state.observe_wal_pages(150, &config);
2241 assert_eq!(
2242 crossing.len(),
2243 1,
2244 "each isolated crossing must emit exactly one INFO"
2245 );
2246 assert_eq!(crossing[0].rung, CheckpointSeverityRung::Info);
2247
2248 let drain = state.observe_wal_pages(10, &config);
2249 assert!(drain.is_empty(), "the drain tick must emit nothing");
2250 }
2251
2252 assert!(
2253 !state.warn_emitted_for_episode,
2254 "isolated single-tick crossings must never accumulate into a WARN"
2255 );
2256 }
2257
2258 #[test]
2263 fn severity_ladder_never_emits_alarm() {
2264 let config = CheckpointConfig {
2265 warn_pages: 100,
2266 warn_sustained_cycles: 1,
2267 ..CheckpointConfig::default()
2268 };
2269 let mut state = CheckpointSeverityState::default();
2270
2271 for wal_pages in [150, 200, 250, u64::MAX] {
2272 let emissions = state.observe_wal_pages(wal_pages, &config);
2273 assert!(
2274 emissions
2275 .iter()
2276 .all(|e| e.rung != CheckpointSeverityRung::Alarm),
2277 "observe_wal_pages must never emit the ALARM rung, got: {emissions:?}"
2278 );
2279 }
2280 }
2281
2282 fn tx_age_test_config() -> CheckpointConfig {
2286 CheckpointConfig {
2287 tx_warn_secs: Duration::from_secs(30),
2288 tx_max_age_secs: Duration::from_secs(120),
2289 ..CheckpointConfig::default()
2290 }
2291 }
2292
2293 fn tx_id(n: u64) -> khive_storage::tx_registry::TxId {
2298 khive_storage::tx_registry::TxId(n)
2299 }
2300
2301 #[test]
2303 fn tx_age_sweep_empty_registry_emits_nothing() {
2304 let config = tx_age_test_config();
2305 let mut state = TxAgeSweepState::default();
2306
2307 let emissions = state.observe(None, &config);
2308 assert!(emissions.is_empty(), "no open entry must emit nothing");
2309 }
2310
2311 #[test]
2313 fn tx_age_sweep_fresh_entry_emits_nothing() {
2314 let config = tx_age_test_config();
2315 let mut state = TxAgeSweepState::default();
2316
2317 let emissions = state.observe(
2318 Some((
2319 tx_id(1),
2320 Duration::from_secs(5),
2321 Some("fresh_span".to_string()),
2322 )),
2323 &config,
2324 );
2325 assert!(emissions.is_empty(), "a fresh entry must emit nothing");
2326 }
2327
2328 #[test]
2332 fn tx_age_sweep_warn_fires_once_on_crossing() {
2333 let config = tx_age_test_config();
2334 let mut state = TxAgeSweepState::default();
2335
2336 let tick1 = state.observe(
2337 Some((
2338 tx_id(1),
2339 Duration::from_secs(45),
2340 Some("stale_span".to_string()),
2341 )),
2342 &config,
2343 );
2344 assert_eq!(
2345 tick1,
2346 vec![TxAgeEmission {
2347 rung: TxAgeRung::Warn,
2348 age: Duration::from_secs(45),
2349 label: Some("stale_span".to_string()),
2350 }],
2351 "crossing tx_warn_secs must emit exactly one Warn"
2352 );
2353
2354 let tick2 = state.observe(
2355 Some((
2356 tx_id(1),
2357 Duration::from_secs(50),
2358 Some("stale_span".to_string()),
2359 )),
2360 &config,
2361 );
2362 assert!(
2363 tick2.is_empty(),
2364 "Warn must not repeat while the entry stays in the warn band"
2365 );
2366 }
2367
2368 #[test]
2371 fn tx_age_sweep_stale_fires_once_on_crossing() {
2372 let config = tx_age_test_config();
2373 let mut state = TxAgeSweepState::default();
2374
2375 state.observe(
2378 Some((
2379 tx_id(1),
2380 Duration::from_secs(45),
2381 Some("stuck_writer_task_tx".to_string()),
2382 )),
2383 &config,
2384 );
2385
2386 let tick = state.observe(
2387 Some((
2388 tx_id(1),
2389 Duration::from_secs(130),
2390 Some("stuck_writer_task_tx".to_string()),
2391 )),
2392 &config,
2393 );
2394 assert_eq!(
2395 tick,
2396 vec![TxAgeEmission {
2397 rung: TxAgeRung::Stale,
2398 age: Duration::from_secs(130),
2399 label: Some("stuck_writer_task_tx".to_string()),
2400 }],
2401 "crossing tx_max_age_secs must emit exactly one Stale"
2402 );
2403
2404 let tick_repeat = state.observe(
2405 Some((
2406 tx_id(1),
2407 Duration::from_secs(200),
2408 Some("stuck_writer_task_tx".to_string()),
2409 )),
2410 &config,
2411 );
2412 assert!(
2413 tick_repeat.is_empty(),
2414 "Stale must not repeat while the entry stays above tx_max_age_secs"
2415 );
2416 }
2417
2418 #[test]
2422 fn tx_age_sweep_already_stale_entry_emits_both_rungs_same_tick() {
2423 let config = tx_age_test_config();
2424 let mut state = TxAgeSweepState::default();
2425
2426 let tick = state.observe(
2427 Some((
2428 tx_id(1),
2429 Duration::from_secs(300),
2430 Some("ancient_tx".to_string()),
2431 )),
2432 &config,
2433 );
2434 assert_eq!(
2435 tick,
2436 vec![
2437 TxAgeEmission {
2438 rung: TxAgeRung::Warn,
2439 age: Duration::from_secs(300),
2440 label: Some("ancient_tx".to_string()),
2441 },
2442 TxAgeEmission {
2443 rung: TxAgeRung::Stale,
2444 age: Duration::from_secs(300),
2445 label: Some("ancient_tx".to_string()),
2446 },
2447 ],
2448 "an already-stale entry must cross both rungs on its first observed tick"
2449 );
2450 }
2451
2452 #[test]
2455 fn tx_age_sweep_rearms_after_entry_clears() {
2456 let config = tx_age_test_config();
2457 let mut state = TxAgeSweepState::default();
2458
2459 state.observe(
2460 Some((
2461 tx_id(1),
2462 Duration::from_secs(150),
2463 Some("first_span".to_string()),
2464 )),
2465 &config,
2466 );
2467
2468 let cleared = state.observe(None, &config);
2470 assert!(cleared.is_empty(), "a clearing tick must emit nothing");
2471
2472 let fresh = state.observe(
2474 Some((
2475 tx_id(2),
2476 Duration::from_secs(2),
2477 Some("second_span".to_string()),
2478 )),
2479 &config,
2480 );
2481 assert!(fresh.is_empty(), "a fresh oldest entry must emit nothing");
2482
2483 let rewarn = state.observe(
2485 Some((
2486 tx_id(2),
2487 Duration::from_secs(35),
2488 Some("second_span".to_string()),
2489 )),
2490 &config,
2491 );
2492 assert_eq!(
2493 rewarn,
2494 vec![TxAgeEmission {
2495 rung: TxAgeRung::Warn,
2496 age: Duration::from_secs(35),
2497 label: Some("second_span".to_string()),
2498 }],
2499 "a fresh stale episode after a clear must Warn again"
2500 );
2501 }
2502
2503 #[test]
2507 fn tx_age_sweep_stale_replacement_without_intervening_clear_still_names_new_entry() {
2508 let config = tx_age_test_config();
2509 let mut state = TxAgeSweepState::default();
2510
2511 let tick_a = state.observe(
2512 Some((
2513 tx_id(1),
2514 Duration::from_secs(300),
2515 Some("stale_entry_a".to_string()),
2516 )),
2517 &config,
2518 );
2519 assert_eq!(
2520 tick_a.len(),
2521 2,
2522 "entry A must cross both rungs on its first observed tick, got: {tick_a:?}"
2523 );
2524
2525 let tick_b = state.observe(
2528 Some((
2529 tx_id(2),
2530 Duration::from_secs(400),
2531 Some("stale_entry_b".to_string()),
2532 )),
2533 &config,
2534 );
2535 assert_eq!(
2536 tick_b,
2537 vec![
2538 TxAgeEmission {
2539 rung: TxAgeRung::Warn,
2540 age: Duration::from_secs(400),
2541 label: Some("stale_entry_b".to_string()),
2542 },
2543 TxAgeEmission {
2544 rung: TxAgeRung::Stale,
2545 age: Duration::from_secs(400),
2546 label: Some("stale_entry_b".to_string()),
2547 },
2548 ],
2549 "a same-tick identity change to an already-stale successor must re-emit both \
2550 rungs naming the NEW entry, got: {tick_b:?}"
2551 );
2552 }
2553
2554 #[test]
2557 fn tx_age_sweep_uses_configured_thresholds_not_hardcoded_defaults() {
2558 let config = CheckpointConfig {
2559 tx_warn_secs: Duration::from_millis(1),
2560 tx_max_age_secs: Duration::from_millis(2),
2561 ..CheckpointConfig::default()
2562 };
2563 let mut state = TxAgeSweepState::default();
2564
2565 let tick = state.observe(
2566 Some((
2567 tx_id(1),
2568 Duration::from_millis(5),
2569 Some("fast_cap_span".to_string()),
2570 )),
2571 &config,
2572 );
2573 assert_eq!(
2574 tick.len(),
2575 2,
2576 "a millisecond-scale cap must cross both rungs immediately, got: {tick:?}"
2577 );
2578 }
2579
2580 #[test]
2583 #[serial(tx_registry, checkpoint_skip_metrics)]
2584 fn tx_age_sweep_names_long_lived_reader_pinning_wal_past_high_water() {
2585 let dir = tempfile::tempdir().unwrap();
2586 let path = dir.path().join("tx_age_sweep_reader_pin.db");
2587 let pool = file_pool(&path);
2588
2589 {
2590 let writer = pool.try_writer().unwrap();
2591 writer
2592 .conn()
2593 .execute_batch(
2594 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
2595 )
2596 .unwrap();
2597 }
2598
2599 let reader = pool.reader().expect("reader");
2604 reader
2605 .execute_batch("BEGIN DEFERRED; SELECT * FROM t;")
2606 .expect("begin read tx");
2607 let _tx_handle =
2608 khive_storage::tx_registry::register(Some("tx_age_sweep_reader_pin_test".to_string()));
2609
2610 let config = CheckpointConfig {
2613 high_water_pages: 1,
2614 tx_warn_secs: Duration::from_millis(1),
2615 tx_max_age_secs: Duration::from_millis(1),
2616 ..CheckpointConfig::default()
2617 };
2618 {
2619 let writer = pool.try_writer().unwrap();
2620 for i in 0..50 {
2621 writer
2622 .conn()
2623 .execute_batch(&format!("INSERT INTO t VALUES ({i});"))
2624 .unwrap();
2625 }
2626 }
2627
2628 let tick = checkpoint_once(&pool, &config, &mut TruncateState::default());
2629 let wal_pages = match tick {
2630 CheckpointTick::Observed(n) => n,
2631 CheckpointTick::Skipped => panic!("writer must not be busy in this test"),
2632 };
2633 assert!(
2634 wal_pages >= config.high_water_pages,
2635 "test setup must actually drive wal_pages ({wal_pages}) past high_water_pages \
2636 ({}) for this regression to mean anything",
2637 config.high_water_pages
2638 );
2639
2640 std::thread::sleep(Duration::from_millis(5));
2647 let our_entry = khive_storage::tx_registry::snapshot()
2658 .into_iter()
2659 .find(|(_, label)| label.as_deref() == Some("tx_age_sweep_reader_pin_test"))
2660 .expect("this test's own tx_registry entry must still be open");
2661 let mut tx_age_state = TxAgeSweepState::default();
2662 let emissions = tx_age_state.observe(Some((tx_id(1), our_entry.0, our_entry.1)), &config);
2663 assert!(
2664 emissions.iter().any(|e| e.rung == TxAgeRung::Stale
2665 && e.label.as_deref() == Some("tx_age_sweep_reader_pin_test")),
2666 "expected a Stale emission naming the pinning reader, got: {emissions:?}"
2667 );
2668
2669 reader.execute_batch("COMMIT;").ok();
2670 drop(reader);
2671 drop(_tx_handle);
2672 }
2673
2674 #[test]
2677 #[serial(tx_registry, checkpoint_skip_metrics)]
2678 fn tx_age_sweep_own_entry_survives_concurrent_older_registration() {
2679 let _decoy = khive_storage::tx_registry::register(Some("decoy_unrelated_span".to_string()));
2680 std::thread::sleep(Duration::from_millis(2));
2681 let _own = khive_storage::tx_registry::register(Some("this_test_own_span".to_string()));
2682 std::thread::sleep(Duration::from_millis(5));
2683
2684 let global_oldest = khive_storage::tx_registry::oldest().expect("registry not empty");
2690 assert_ne!(
2691 global_oldest.2.as_deref(),
2692 Some("this_test_own_span"),
2693 "test setup must reproduce the race: an older, unrelated entry must be \
2694 the current global oldest, got: {global_oldest:?}"
2695 );
2696
2697 let our_entry = khive_storage::tx_registry::snapshot()
2698 .into_iter()
2699 .find(|(_, label)| label.as_deref() == Some("this_test_own_span"))
2700 .expect("this test's own tx_registry entry must still be open");
2701
2702 let config = CheckpointConfig {
2703 tx_warn_secs: Duration::from_millis(1),
2704 tx_max_age_secs: Duration::from_millis(1),
2705 ..CheckpointConfig::default()
2706 };
2707 let mut state = TxAgeSweepState::default();
2708 let emissions = state.observe(Some((tx_id(2), our_entry.0, our_entry.1)), &config);
2709 assert!(
2710 emissions
2711 .iter()
2712 .any(|e| e.rung == TxAgeRung::Stale
2713 && e.label.as_deref() == Some("this_test_own_span")),
2714 "expected a Stale emission naming this test's own span despite an older, \
2715 unrelated concurrent registration, got: {emissions:?}"
2716 );
2717 }
2718
2719 #[test]
2721 #[serial]
2722 fn checkpoint_config_warn_sustained_cycles_env_override() {
2723 let default = CheckpointConfig::default();
2724 assert_eq!(default.warn_sustained_cycles, DEFAULT_WARN_SUSTAINED_CYCLES);
2725
2726 std::env::set_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES", "5");
2727 let cfg = CheckpointConfig::from_env();
2728 std::env::remove_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES");
2729 assert_eq!(cfg.warn_sustained_cycles, 5);
2730
2731 std::env::set_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES", "0");
2732 let cfg_zero = CheckpointConfig::from_env();
2733 std::env::remove_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES");
2734 assert_eq!(
2735 cfg_zero.warn_sustained_cycles, DEFAULT_WARN_SUSTAINED_CYCLES,
2736 "zero must fall back to the default"
2737 );
2738
2739 std::env::set_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES", "not_a_number");
2740 let cfg_invalid = CheckpointConfig::from_env();
2741 std::env::remove_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES");
2742 assert_eq!(
2743 cfg_invalid.warn_sustained_cycles,
2744 DEFAULT_WARN_SUSTAINED_CYCLES
2745 );
2746 }
2747
2748 #[derive(Default)]
2751 struct FakeEventStore {
2752 events: std::sync::Mutex<Vec<khive_storage::Event>>,
2753 }
2754
2755 #[async_trait::async_trait]
2756 impl khive_storage::EventStore for FakeEventStore {
2757 async fn append_event(
2758 &self,
2759 event: khive_storage::Event,
2760 ) -> khive_storage::StorageResult<()> {
2761 self.events.lock().unwrap().push(event);
2762 Ok(())
2763 }
2764
2765 async fn append_events(
2766 &self,
2767 events: Vec<khive_storage::Event>,
2768 ) -> khive_storage::StorageResult<khive_storage::BatchWriteSummary> {
2769 let count = events.len() as u64;
2770 self.events.lock().unwrap().extend(events);
2771 Ok(khive_storage::BatchWriteSummary {
2772 attempted: count,
2773 affected: count,
2774 failed: 0,
2775 first_error: String::new(),
2776 })
2777 }
2778
2779 async fn get_event(
2780 &self,
2781 id: uuid::Uuid,
2782 ) -> khive_storage::StorageResult<Option<khive_storage::Event>> {
2783 Ok(self
2784 .events
2785 .lock()
2786 .unwrap()
2787 .iter()
2788 .find(|e| e.id == id)
2789 .cloned())
2790 }
2791
2792 async fn query_events(
2793 &self,
2794 _filter: khive_storage::EventFilter,
2795 _page: khive_storage::PageRequest,
2796 ) -> khive_storage::StorageResult<khive_storage::Page<khive_storage::Event>> {
2797 unimplemented!("not exercised by the checkpoint lifecycle-event tests")
2798 }
2799
2800 async fn count_events(
2801 &self,
2802 _filter: khive_storage::EventFilter,
2803 ) -> khive_storage::StorageResult<u64> {
2804 Ok(self.events.lock().unwrap().len() as u64)
2805 }
2806 }
2807
2808 #[test]
2813 fn checkpoint_outcome_should_emit_covers_all_transitions() {
2814 assert!(
2815 checkpoint_outcome_should_emit(true, false),
2816 "first elevated tick must emit"
2817 );
2818 assert!(
2819 checkpoint_outcome_should_emit(true, true),
2820 "sustained elevated tick must emit"
2821 );
2822 assert!(
2823 checkpoint_outcome_should_emit(false, true),
2824 "the single drain row (elevated -> healthy) must emit"
2825 );
2826 assert!(
2827 !checkpoint_outcome_should_emit(false, false),
2828 "an ordinary below-warn tick must not emit"
2829 );
2830 }
2831
2832 #[tokio::test]
2833 #[serial(checkpoint_skip_metrics)]
2834 async fn checkpoint_task_emits_outcome_events_while_elevated_and_stops_after_drain() {
2835 let dir = tempfile::tempdir().unwrap();
2836 let path = dir.path().join("outcome_emit.db");
2837 let pool = file_pool(&path);
2838
2839 let cfg = CheckpointConfig {
2842 interval: Duration::from_millis(10),
2843 warn_pages: 0,
2844 ..CheckpointConfig::default()
2845 };
2846 let store = Arc::new(FakeEventStore::default());
2847 let store_dyn: Arc<dyn khive_storage::EventStore> = store.clone();
2848
2849 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
2850 let handle = tokio::spawn(run_checkpoint_task(
2851 pool,
2852 cfg,
2853 Some(store_dyn),
2854 "local".to_string(),
2855 shutdown_rx,
2856 ));
2857
2858 tokio::time::sleep(Duration::from_millis(60)).await;
2859 shutdown_tx.send(()).expect("send shutdown signal");
2860 tokio::time::timeout(Duration::from_secs(1), handle)
2861 .await
2862 .expect("checkpoint task should exit within 1s")
2863 .expect("checkpoint task panicked");
2864
2865 let events = store.events.lock().unwrap();
2866 assert!(
2867 !events.is_empty(),
2868 "an always-elevated config must append at least one CheckpointOutcomeRecorded event"
2869 );
2870 assert!(
2871 events
2872 .iter()
2873 .all(|e| e.kind == khive_types::EventKind::CheckpointOutcomeRecorded),
2874 "every appended event must be CheckpointOutcomeRecorded, got: {events:?}"
2875 );
2876 assert!(
2877 events.iter().all(|e| e.namespace == "local"),
2878 "events must be stamped with the namespace passed to run_checkpoint_task"
2879 );
2880 }
2881
2882 #[tokio::test]
2883 #[serial(checkpoint_skip_metrics)]
2884 async fn checkpoint_task_emits_nothing_while_healthy() {
2885 let dir = tempfile::tempdir().unwrap();
2886 let path = dir.path().join("outcome_no_emit.db");
2887 let pool = file_pool(&path);
2888
2889 let cfg = CheckpointConfig {
2892 interval: Duration::from_millis(10),
2893 warn_pages: u64::MAX,
2894 ..CheckpointConfig::default()
2895 };
2896 let store = Arc::new(FakeEventStore::default());
2897 let store_dyn: Arc<dyn khive_storage::EventStore> = store.clone();
2898
2899 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
2900 let handle = tokio::spawn(run_checkpoint_task(
2901 pool,
2902 cfg,
2903 Some(store_dyn),
2904 "local".to_string(),
2905 shutdown_rx,
2906 ));
2907
2908 tokio::time::sleep(Duration::from_millis(60)).await;
2909 shutdown_tx.send(()).expect("send shutdown signal");
2910 tokio::time::timeout(Duration::from_secs(1), handle)
2911 .await
2912 .expect("checkpoint task should exit within 1s")
2913 .expect("checkpoint task panicked");
2914
2915 assert!(
2916 store.events.lock().unwrap().is_empty(),
2917 "a config that never crosses warn_pages must never append a lifecycle event"
2918 );
2919 }
2920
2921 #[tokio::test]
2922 #[serial(checkpoint_skip_metrics)]
2923 async fn checkpoint_task_with_no_event_store_does_not_panic() {
2924 let dir = tempfile::tempdir().unwrap();
2925 let path = dir.path().join("outcome_none_store.db");
2926 let pool = file_pool(&path);
2927
2928 let cfg = CheckpointConfig {
2929 interval: Duration::from_millis(10),
2930 warn_pages: 0,
2931 ..CheckpointConfig::default()
2932 };
2933
2934 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
2935 let handle = tokio::spawn(run_checkpoint_task(
2936 pool,
2937 cfg,
2938 None,
2939 "local".to_string(),
2940 shutdown_rx,
2941 ));
2942
2943 tokio::time::sleep(Duration::from_millis(40)).await;
2944 shutdown_tx.send(()).expect("send shutdown signal");
2945 tokio::time::timeout(Duration::from_secs(1), handle)
2946 .await
2947 .expect("checkpoint task should exit within 1s")
2948 .expect("checkpoint task panicked");
2949 }
2950
2951 #[tokio::test]
2968 #[serial(tx_registry, checkpoint_skip_metrics)]
2969 async fn checkpoint_task_sweeps_stale_registry_entry_while_wal_is_healthy() {
2970 let dir = tempfile::tempdir().unwrap();
2971 let path = dir.path().join("tx_age_sweep_task_healthy_wal.db");
2972 let pool = file_pool(&path);
2973
2974 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
2975 let subscriber = CaptureSubscriber {
2976 events: std::sync::Arc::clone(&buffer),
2977 };
2978 let _tracing_guard = tracing::subscriber::set_default(subscriber);
2979
2980 let _tx_handle = khive_storage::tx_registry::register(Some(
2981 "checkpoint_task_healthy_wal_sweep_test".to_string(),
2982 ));
2983
2984 let cfg = CheckpointConfig {
2985 interval: Duration::from_millis(10),
2986 warn_pages: u64::MAX,
2987 high_water_pages: u64::MAX,
2988 truncate_high_water_pages: u64::MAX,
2989 tx_warn_secs: Duration::from_millis(1),
2990 tx_max_age_secs: Duration::from_millis(1),
2991 ..CheckpointConfig::default()
2992 };
2993
2994 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
2995 let handle = tokio::spawn(run_checkpoint_task(
2996 pool,
2997 cfg,
2998 None,
2999 "local".to_string(),
3000 shutdown_rx,
3001 ));
3002
3003 tokio::time::sleep(Duration::from_millis(60)).await;
3004 shutdown_tx.send(()).expect("send shutdown signal");
3005 tokio::time::timeout(Duration::from_secs(1), handle)
3006 .await
3007 .expect("checkpoint task should exit within 1s")
3008 .expect("checkpoint task panicked");
3009
3010 drop(_tx_handle);
3011
3012 let events = buffer.lock().unwrap();
3013 assert!(
3014 events.iter().any(|e| {
3015 e.tx_label.as_deref() == Some("checkpoint_task_healthy_wal_sweep_test")
3016 && e.message
3017 .as_deref()
3018 .is_some_and(|m| m.contains("stale-op cap"))
3019 }),
3020 "expected the spawned task to sweep and escalate the stale registry entry \
3021 to Stale on its own, got: {events:?}"
3022 );
3023 }
3024
3025 #[tokio::test]
3029 #[serial(tx_registry, checkpoint_skip_metrics)]
3030 async fn checkpoint_task_emits_no_age_alert_for_an_empty_registry() {
3031 let dir = tempfile::tempdir().unwrap();
3032 let path = dir.path().join("tx_age_sweep_task_empty_registry.db");
3033 let pool = file_pool(&path);
3034
3035 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
3036 let subscriber = CaptureSubscriber {
3037 events: std::sync::Arc::clone(&buffer),
3038 };
3039 let _tracing_guard = tracing::subscriber::set_default(subscriber);
3040
3041 let cfg = CheckpointConfig {
3042 interval: Duration::from_millis(10),
3043 tx_warn_secs: Duration::from_millis(1),
3044 tx_max_age_secs: Duration::from_millis(1),
3045 ..CheckpointConfig::default()
3046 };
3047
3048 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
3049 let handle = tokio::spawn(run_checkpoint_task(
3050 pool,
3051 cfg,
3052 None,
3053 "local".to_string(),
3054 shutdown_rx,
3055 ));
3056
3057 tokio::time::sleep(Duration::from_millis(40)).await;
3058 shutdown_tx.send(()).expect("send shutdown signal");
3059 tokio::time::timeout(Duration::from_secs(1), handle)
3060 .await
3061 .expect("checkpoint task should exit within 1s")
3062 .expect("checkpoint task panicked");
3063
3064 let events = buffer.lock().unwrap();
3065 assert!(
3066 events.iter().all(|e| e
3067 .message
3068 .as_deref()
3069 .is_none_or(|m| !m.contains("ADR-091 Plank 1"))),
3070 "an empty registry must never produce a Plank 1 age emission, got: {events:?}"
3071 );
3072 }
3073
3074 #[tokio::test]
3082 #[serial(tx_registry, checkpoint_skip_metrics)]
3083 async fn checkpoint_task_sweeps_stale_entry_even_when_writer_is_busy_every_tick() {
3084 reset_checkpoint_metrics_for_tests();
3085
3086 let dir = tempfile::tempdir().unwrap();
3087 let path = dir.path().join("tx_age_sweep_task_writer_busy.db");
3088 let pool = file_pool(&path);
3089 {
3090 let writer = pool.try_writer().unwrap();
3091 writer
3092 .conn()
3093 .execute_batch("CREATE TABLE IF NOT EXISTS t (x INTEGER);")
3094 .unwrap();
3095 }
3096
3097 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
3098 let subscriber = CaptureSubscriber {
3099 events: std::sync::Arc::clone(&buffer),
3100 };
3101 let _tracing_guard = tracing::subscriber::set_default(subscriber);
3102
3103 let _tx_handle = khive_storage::tx_registry::register(Some(
3104 "checkpoint_task_writer_busy_sweep_test".to_string(),
3105 ));
3106
3107 let _writer_guard = pool.try_writer().expect("acquire writer for busy hold");
3111
3112 let cfg = CheckpointConfig {
3113 interval: Duration::from_millis(10),
3114 tx_warn_secs: Duration::from_millis(1),
3115 tx_max_age_secs: Duration::from_millis(1),
3116 ..CheckpointConfig::default()
3117 };
3118
3119 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
3120 let handle = tokio::spawn(run_checkpoint_task(
3121 Arc::clone(&pool),
3122 cfg,
3123 None,
3124 "local".to_string(),
3125 shutdown_rx,
3126 ));
3127
3128 tokio::time::sleep(Duration::from_millis(60)).await;
3130
3131 assert!(
3132 checkpoint_skipped_ticks() > 0,
3133 "test setup must actually drive at least one Skipped tick for this \
3134 regression to mean anything"
3135 );
3136
3137 shutdown_tx.send(()).expect("send shutdown signal");
3138 tokio::time::timeout(Duration::from_secs(1), handle)
3139 .await
3140 .expect("checkpoint task should exit within 1s")
3141 .expect("checkpoint task panicked");
3142
3143 drop(_writer_guard);
3144 drop(_tx_handle);
3145
3146 let events = buffer.lock().unwrap();
3147 assert!(
3148 events.iter().any(|e| {
3149 e.tx_label.as_deref() == Some("checkpoint_task_writer_busy_sweep_test")
3150 && e.message
3151 .as_deref()
3152 .is_some_and(|m| m.contains("stale-op cap"))
3153 }),
3154 "expected the age sweep to fire even though every tick's writer checkout \
3155 was skipped, got: {events:?}"
3156 );
3157 }
3158}