1use std::path::{Path, PathBuf};
27use std::sync::atomic::{AtomicU64, Ordering};
28use std::sync::Arc;
29use std::time::{Duration, Instant};
30
31use crate::pool::{ConnectionPool, WriterGuard};
32
33static LAST_WAL_PAGES: AtomicU64 = AtomicU64::new(u64::MAX);
42
43static TRUNCATE_ATTEMPTS: AtomicU64 = AtomicU64::new(0);
46
47static TRUNCATE_CONSECUTIVE_FAILURES: AtomicU64 = AtomicU64::new(0);
51
52static CHECKPOINT_SKIPPED_TICKS: AtomicU64 = AtomicU64::new(0);
56
57static CHECKPOINT_CONSECUTIVE_SKIPS: AtomicU64 = AtomicU64::new(0);
61
62static CHECKPOINT_LAST_SKIP_WAL_PAGES: AtomicU64 = AtomicU64::new(u64::MAX);
66
67pub fn last_observed_wal_pages() -> Option<u64> {
70 match LAST_WAL_PAGES.load(Ordering::Relaxed) {
71 u64::MAX => None,
72 pages => Some(pages),
73 }
74}
75
76pub fn truncate_attempts() -> u64 {
78 TRUNCATE_ATTEMPTS.load(Ordering::Relaxed)
79}
80
81pub fn truncate_consecutive_failures() -> u64 {
83 TRUNCATE_CONSECUTIVE_FAILURES.load(Ordering::Relaxed)
84}
85
86pub fn checkpoint_skipped_ticks() -> u64 {
88 CHECKPOINT_SKIPPED_TICKS.load(Ordering::Relaxed)
89}
90
91pub fn checkpoint_consecutive_skips() -> u64 {
93 CHECKPOINT_CONSECUTIVE_SKIPS.load(Ordering::Relaxed)
94}
95
96pub fn checkpoint_last_skip_wal_pages() -> Option<u64> {
99 match CHECKPOINT_LAST_SKIP_WAL_PAGES.load(Ordering::Relaxed) {
100 u64::MAX => None,
101 pages => Some(pages),
102 }
103}
104
105fn note_checkpoint_skipped() {
109 CHECKPOINT_SKIPPED_TICKS.fetch_add(1, Ordering::Relaxed);
110 CHECKPOINT_CONSECUTIVE_SKIPS.fetch_add(1, Ordering::Relaxed);
111 if let Some(pages) = last_observed_wal_pages() {
112 CHECKPOINT_LAST_SKIP_WAL_PAGES.store(pages, Ordering::Relaxed);
113 }
114}
115
116fn note_checkpoint_observed(_wal_pages: u64) {
121 CHECKPOINT_CONSECUTIVE_SKIPS.store(0, Ordering::Relaxed);
122}
123
124#[cfg(test)]
128pub(crate) fn reset_checkpoint_metrics_for_tests() {
129 CHECKPOINT_SKIPPED_TICKS.store(0, Ordering::Relaxed);
130 CHECKPOINT_CONSECUTIVE_SKIPS.store(0, Ordering::Relaxed);
131 CHECKPOINT_LAST_SKIP_WAL_PAGES.store(u64::MAX, Ordering::Relaxed);
132}
133
134#[derive(Debug, Clone, Copy, PartialEq, Eq)]
142pub enum CheckpointTick {
143 Skipped,
145 Observed(u64),
147}
148
149pub const DEFAULT_WARN_SUSTAINED_CYCLES: u8 = 3;
152
153#[derive(Clone, Debug)]
158pub struct CheckpointConfig {
159 pub interval: Duration,
164
165 pub warn_pages: u64,
170
171 pub warn_sustained_cycles: u8,
179
180 pub high_water_pages: u64,
190
191 pub truncate_high_water_pages: u64,
202
203 pub truncate_min_interval: Duration,
213
214 pub truncate_busy_timeout: Duration,
221
222 pub tx_warn_secs: Duration,
230
231 pub tx_max_age_secs: Duration,
239}
240
241impl Default for CheckpointConfig {
242 fn default() -> Self {
243 Self {
244 interval: Duration::from_millis(500),
245 warn_pages: 2000,
246 warn_sustained_cycles: DEFAULT_WARN_SUSTAINED_CYCLES,
247 high_water_pages: 6000,
248 truncate_high_water_pages: 20_000,
249 truncate_min_interval: Duration::from_secs(300),
250 truncate_busy_timeout: Duration::from_millis(2000),
251 tx_warn_secs: Duration::from_secs(30),
252 tx_max_age_secs: Duration::from_secs(120),
253 }
254 }
255}
256
257impl CheckpointConfig {
258 pub fn from_env() -> Self {
262 let mut cfg = Self::default();
263
264 if let Ok(ms) = std::env::var("KHIVE_CHECKPOINT_INTERVAL_MS") {
265 if let Ok(v) = ms.parse::<u64>() {
266 if v > 0 {
267 cfg.interval = Duration::from_millis(v);
268 }
269 }
270 }
271
272 if let Ok(v) = std::env::var("KHIVE_WAL_WARN_PAGES") {
273 if let Ok(n) = v.parse::<u64>() {
274 if n > 0 {
275 cfg.warn_pages = n;
276 }
277 }
278 }
279
280 if let Ok(v) = std::env::var("KHIVE_WAL_WARN_SUSTAINED_CYCLES") {
281 if let Ok(n) = v.parse::<u8>() {
282 if n > 0 {
283 cfg.warn_sustained_cycles = n;
284 }
285 }
286 }
287
288 if let Ok(v) = std::env::var("KHIVE_WAL_HIGH_WATER_PAGES") {
289 if let Ok(n) = v.parse::<u64>() {
290 if n > 0 {
291 cfg.high_water_pages = n;
292 }
293 }
294 }
295
296 if let Ok(v) = std::env::var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES") {
297 if let Ok(n) = v.parse::<u64>() {
298 if n > 0 {
299 cfg.truncate_high_water_pages = n;
300 }
301 }
302 }
303
304 if let Ok(v) = std::env::var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS") {
305 if let Ok(n) = v.parse::<u64>() {
306 if n > 0 {
307 cfg.truncate_min_interval = Duration::from_secs(n);
308 }
309 }
310 }
311
312 if let Ok(v) = std::env::var("KHIVE_WAL_TRUNCATE_BUSY_MS") {
313 if let Ok(n) = v.parse::<u64>() {
314 if n > 0 {
315 cfg.truncate_busy_timeout = Duration::from_millis(n);
316 }
317 }
318 }
319
320 (cfg.tx_warn_secs, cfg.tx_max_age_secs) =
321 tx_age_thresholds_from_env(cfg.tx_warn_secs, cfg.tx_max_age_secs);
322
323 cfg
324 }
325}
326
327fn tx_age_thresholds_from_env(
341 default_warn: Duration,
342 default_max: Duration,
343) -> (Duration, Duration) {
344 let mut warn_secs = default_warn;
345 let mut max_age_secs = default_max;
346
347 if let Ok(v) = std::env::var("KHIVE_TX_WARN_SECS") {
348 if let Ok(n) = v.parse::<u64>() {
349 if n > 0 {
350 warn_secs = Duration::from_secs(n);
351 }
352 }
353 }
354
355 if let Ok(v) = std::env::var("KHIVE_TX_MAX_AGE_SECS") {
356 if let Ok(n) = v.parse::<u64>() {
357 if n > 0 {
358 max_age_secs = Duration::from_secs(n);
359 }
360 }
361 }
362
363 if warn_secs >= max_age_secs {
364 tracing::warn!(
365 configured_tx_warn_secs = warn_secs.as_secs_f64(),
366 configured_tx_max_age_secs = max_age_secs.as_secs_f64(),
367 fallback_tx_warn_secs = default_warn.as_secs_f64(),
368 fallback_tx_max_age_secs = default_max.as_secs_f64(),
369 "KHIVE_TX_WARN_SECS must be strictly less than KHIVE_TX_MAX_AGE_SECS; \
370 both transaction-age thresholds were rejected and reset to their defaults"
371 );
372 return (default_warn, default_max);
373 }
374
375 (warn_secs, max_age_secs)
376}
377
378#[derive(Debug, Default)]
385pub struct TruncateState {
386 last_attempt: Option<Instant>,
390 consecutive_failures: u32,
395}
396
397#[derive(Debug, Clone, Copy, PartialEq, Eq)]
404pub enum CheckpointSeverityRung {
405 Info,
407 Warn,
410 Alarm,
413}
414
415#[derive(Debug, Default, Clone)]
419pub struct CheckpointSeverityState {
420 was_above_warn: bool,
423 consecutive_above_warn: u8,
426 warn_emitted_for_episode: bool,
430}
431
432#[derive(Debug, Clone, Copy, PartialEq, Eq)]
435pub struct CheckpointSeverityEmission {
436 pub rung: CheckpointSeverityRung,
440 pub wal_pages: u64,
442 pub threshold_pages: u64,
444 pub consecutive_cycles: u8,
447}
448
449impl CheckpointSeverityState {
450 pub fn observe_wal_pages(
461 &mut self,
462 wal_pages: u64,
463 config: &CheckpointConfig,
464 ) -> Vec<CheckpointSeverityEmission> {
465 let mut emissions = Vec::new();
466 let above_warn = wal_pages >= config.warn_pages;
467
468 if above_warn {
469 self.consecutive_above_warn = self.consecutive_above_warn.saturating_add(1);
470
471 if !self.was_above_warn {
472 emissions.push(CheckpointSeverityEmission {
473 rung: CheckpointSeverityRung::Info,
474 wal_pages,
475 threshold_pages: config.warn_pages,
476 consecutive_cycles: self.consecutive_above_warn,
477 });
478 }
479
480 if !self.warn_emitted_for_episode
481 && self.consecutive_above_warn >= config.warn_sustained_cycles
482 {
483 emissions.push(CheckpointSeverityEmission {
484 rung: CheckpointSeverityRung::Warn,
485 wal_pages,
486 threshold_pages: config.warn_pages,
487 consecutive_cycles: self.consecutive_above_warn,
488 });
489 self.warn_emitted_for_episode = true;
490 }
491 } else {
492 self.consecutive_above_warn = 0;
493 self.warn_emitted_for_episode = false;
494 }
495
496 self.was_above_warn = above_warn;
497 emissions
498 }
499}
500
501#[derive(Debug, Clone, Copy, PartialEq, Eq)]
505pub enum TxAgeRung {
506 Warn,
508 Stale,
513}
514
515#[derive(Debug, Clone, PartialEq, Eq)]
517pub struct TxAgeEmission {
518 pub rung: TxAgeRung,
519 pub age: Duration,
520 pub label: Option<String>,
521}
522
523#[derive(Debug, Default, Clone)]
534pub struct TxAgeSweepState {
535 was_above_warn: bool,
538 was_above_max_age: bool,
541 tracked_id: Option<khive_storage::tx_registry::TxId>,
546}
547
548impl TxAgeSweepState {
549 pub fn observe(
561 &mut self,
562 oldest: Option<(khive_storage::tx_registry::TxId, Duration, Option<String>)>,
563 tx_warn_secs: Duration,
564 tx_max_age_secs: Duration,
565 ) -> Vec<TxAgeEmission> {
566 let mut emissions = Vec::new();
567
568 let Some((id, age, label)) = oldest else {
569 self.was_above_warn = false;
570 self.was_above_max_age = false;
571 self.tracked_id = None;
572 return emissions;
573 };
574
575 if self.tracked_id != Some(id) {
576 self.was_above_warn = false;
577 self.was_above_max_age = false;
578 }
579 self.tracked_id = Some(id);
580
581 let above_warn = age >= tx_warn_secs;
582 let above_max_age = age >= tx_max_age_secs;
583
584 if above_warn && !self.was_above_warn {
585 emissions.push(TxAgeEmission {
586 rung: TxAgeRung::Warn,
587 age,
588 label: label.clone(),
589 });
590 }
591 if above_max_age && !self.was_above_max_age {
592 emissions.push(TxAgeEmission {
593 rung: TxAgeRung::Stale,
594 age,
595 label,
596 });
597 }
598
599 self.was_above_warn = above_warn;
600 self.was_above_max_age = above_max_age;
601 emissions
602 }
603}
604
605fn log_tx_age_emission(emission: &TxAgeEmission) {
610 let label = emission.label.as_deref().unwrap_or("<unlabeled>");
611 match emission.rung {
612 TxAgeRung::Warn => {
613 tracing::warn!(
614 tx_age_secs = emission.age.as_secs_f64(),
615 tx_label = label,
616 "ADR-091 Plank 1: open transaction registry entry exceeded soft-cap age"
617 );
618 }
619 TxAgeRung::Stale => {
620 tracing::error!(
621 tx_age_secs = emission.age.as_secs_f64(),
622 tx_label = label,
623 "ADR-091 Plank 1: open transaction registry entry exceeded the cooperative \
624 stale-op cap; no in-process mechanism can force-close it — investigate the \
625 labeled caller directly"
626 );
627 }
628 }
629}
630
631struct WalpinSidecarState {
638 dir: PathBuf,
639 pid: u32,
640 role: &'static str,
641 started_at: i64,
642 sweep_interval_ms: u64,
647 wrote: bool,
648 beacon_registered: bool,
654 last_heartbeat: Option<LastHeartbeatState>,
661}
662
663struct LastHeartbeatState {
669 span_id: khive_storage::tx_registry::TxId,
670 label: Option<String>,
671 attribution_basis: &'static str,
672 sweep_interval_ms: u64,
673 oldest_tx_started_at: i64,
674}
675
676impl LastHeartbeatState {
677 fn content_matches(
683 &self,
684 span_id: khive_storage::tx_registry::TxId,
685 label: &Option<String>,
686 attribution_basis: &str,
687 sweep_interval_ms: u64,
688 ) -> bool {
689 self.span_id == span_id
690 && self.label == *label
691 && self.attribution_basis == attribution_basis
692 && self.sweep_interval_ms == sweep_interval_ms
693 }
694}
695
696impl WalpinSidecarState {
697 fn new(
700 db_path: Option<&Path>,
701 is_file_backed: bool,
702 role: &'static str,
703 interval: Duration,
704 ) -> Option<Self> {
705 let path = db_path?;
706 if !crate::walpin::sidecar_enabled(is_file_backed) {
707 return None;
708 }
709 let pid = std::process::id();
710 Some(Self {
711 dir: crate::walpin::sidecar_dir_for(path),
712 pid,
713 role,
714 started_at: crate::walpin::process_start_time_secs(pid).unwrap_or(0),
715 sweep_interval_ms: interval.as_millis().min(u64::MAX as u128) as u64,
716 wrote: false,
717 last_heartbeat: None,
718 beacon_registered: false,
719 })
720 }
721
722 async fn register_beacon(&mut self) {
731 let dir = self.dir.clone();
732 let beacon = crate::walpin::WalpinBeacon {
733 pid: self.pid,
734 process_role: self.role.to_string(),
735 started_at: self.started_at,
736 sweep_interval_ms: self.sweep_interval_ms,
737 };
738 let result =
739 tokio::task::spawn_blocking(move || crate::walpin::write_beacon(&dir, &beacon)).await;
740 match result {
741 Ok(Ok(())) => {
742 self.beacon_registered = true;
743 }
744 Ok(Err(e)) => {
745 tracing::warn!(
746 error = %e,
747 "ADR-091 Amendment 2: failed to write walpin registration beacon; \
748 this process's sidecar health will read as unknown, not registered-silent"
749 );
750 }
751 Err(join_err) => {
752 tracing::warn!(
753 error = %join_err,
754 "ADR-091 Amendment 2: walpin beacon write task panicked"
755 );
756 }
757 }
758 }
759
760 async fn refresh_beacon(&mut self) {
770 if !self.beacon_registered {
771 self.register_beacon().await;
772 return;
773 }
774 let dir = self.dir.clone();
775 let pid = self.pid;
776 let result =
777 tokio::task::spawn_blocking(move || crate::walpin::touch_beacon(&dir, pid)).await;
778 match result {
779 Ok(Ok(())) => {}
780 Ok(Err(e)) => {
781 self.beacon_registered = false;
782 tracing::warn!(
783 error = %e,
784 "ADR-091 Amendment 2: failed to refresh walpin registration beacon; \
785 this process's sidecar health will read as unknown, not registered-silent"
786 );
787 }
788 Err(join_err) => {
789 self.beacon_registered = false;
790 tracing::warn!(
791 error = %join_err,
792 "ADR-091 Amendment 2: walpin beacon refresh task panicked"
793 );
794 }
795 }
796 }
797
798 async fn drop_beacon_fail_closed(&mut self) {
809 let dir = self.dir.clone();
810 let pid = self.pid;
811 self.beacon_registered = false;
812 let result =
813 tokio::task::spawn_blocking(move || crate::walpin::remove_beacon(&dir, pid)).await;
814 match result {
815 Ok(Ok(())) => {}
816 Ok(Err(e)) => {
817 tracing::warn!(
818 error = %e,
819 "ADR-091 Amendment 2: failed to remove walpin beacon after a failed \
820 heartbeat write; beacon will age out of the freshness window instead"
821 );
822 }
823 Err(join_err) => {
824 tracing::warn!(
825 error = %join_err,
826 "ADR-091 Amendment 2: walpin beacon removal task panicked"
827 );
828 }
829 }
830 }
831
832 async fn observe(
836 &mut self,
837 oldest: Option<khive_storage::tx_registry::OldestSpan>,
838 tx_warn_secs: Duration,
839 ) {
840 match oldest {
841 Some(span) if span.age >= tx_warn_secs => {
842 let attribution_basis = match span.origin {
849 khive_storage::tx_registry::TxOrigin::Database(_) => "origin",
850 khive_storage::tx_registry::TxOrigin::Unscoped
851 | khive_storage::tx_registry::TxOrigin::Memory => "fallback",
852 };
853
854 let content_unchanged = self.wrote
860 && self.last_heartbeat.as_ref().is_some_and(|last| {
861 last.content_matches(
862 span.id,
863 &span.label,
864 attribution_basis,
865 self.sweep_interval_ms,
866 )
867 });
868
869 if content_unchanged {
870 let dir = self.dir.clone();
871 let pid = self.pid;
872 let touch_result = tokio::task::spawn_blocking(move || {
873 crate::walpin::touch_heartbeat(&dir, pid)
874 })
875 .await;
876 match touch_result {
877 Ok(Ok(())) => {
878 self.refresh_beacon().await;
879 return;
880 }
881 Ok(Err(e)) => {
882 tracing::warn!(
883 error = %e,
884 "ADR-091 Amendment 3 Plank F1: walpin heartbeat touch failed; \
885 recreating with a full body write"
886 );
887 }
888 Err(join_err) => {
889 tracing::warn!(
890 error = %join_err,
891 "ADR-091 Amendment 3 Plank F1: walpin heartbeat touch task \
892 panicked; recreating with a full body write"
893 );
894 }
895 }
896 }
901
902 let oldest_tx_started_at = self
909 .last_heartbeat
910 .as_ref()
911 .filter(|last| last.span_id == span.id)
912 .map(|last| last.oldest_tx_started_at)
913 .unwrap_or_else(|| now_epoch_secs().saturating_sub(span.age.as_secs() as i64));
914
915 let heartbeat = crate::walpin::WalpinHeartbeat {
916 pid: self.pid,
917 process_role: self.role.to_string(),
918 started_at: self.started_at,
919 oldest_tx_age_secs: span.age.as_secs_f64(),
920 oldest_tx_label: span.label.clone(),
921 oldest_tx_started_at: Some(oldest_tx_started_at),
922 updated_at: now_epoch_secs(),
923 sweep_interval_ms: self.sweep_interval_ms,
924 attribution_basis: Some(attribution_basis.to_string()),
925 };
926 let dir = self.dir.clone();
927 let result = tokio::task::spawn_blocking(move || {
928 crate::walpin::write_heartbeat(&dir, &heartbeat)
929 })
930 .await;
931 match result {
941 Ok(Ok(())) => {
942 self.wrote = true;
943 self.last_heartbeat = Some(LastHeartbeatState {
944 span_id: span.id,
945 label: span.label,
946 attribution_basis,
947 sweep_interval_ms: self.sweep_interval_ms,
948 oldest_tx_started_at,
949 });
950 self.refresh_beacon().await;
951 }
952 Ok(Err(e)) => {
953 tracing::warn!(
954 error = %e,
955 "ADR-091 Amendment 2 Plank B: failed to write walpin heartbeat; \
956 removing beacon so this process cannot read as \
957 registered-silent while over threshold"
958 );
959 self.last_heartbeat = None;
963 self.drop_beacon_fail_closed().await;
964 }
965 Err(join_err) => {
966 tracing::warn!(
967 error = %join_err,
968 "ADR-091 Amendment 2 Plank B: walpin heartbeat write task panicked"
969 );
970 self.last_heartbeat = None;
971 self.drop_beacon_fail_closed().await;
972 }
973 }
974 }
975 _ => {
976 self.refresh_beacon().await;
977 if self.wrote {
978 let dir = self.dir.clone();
979 let pid = self.pid;
980 let result = tokio::task::spawn_blocking(move || {
981 crate::walpin::remove_heartbeat(&dir, pid)
982 })
983 .await;
984 match result {
985 Ok(Ok(())) => {}
986 Ok(Err(e)) => tracing::warn!(
987 error = %e,
988 "ADR-091 Amendment 2 Plank B: failed to remove walpin heartbeat"
989 ),
990 Err(join_err) => tracing::warn!(
991 error = %join_err,
992 "ADR-091 Amendment 2 Plank B: walpin heartbeat removal task panicked"
993 ),
994 }
995 self.wrote = false;
996 self.last_heartbeat = None;
997 }
998 }
999 }
1000 }
1001
1002 async fn shutdown(&mut self) {
1003 if self.wrote {
1004 let dir = self.dir.clone();
1005 let pid = self.pid;
1006 let _ = tokio::task::spawn_blocking(move || crate::walpin::remove_heartbeat(&dir, pid))
1007 .await;
1008 self.wrote = false;
1009 }
1010 }
1011}
1012
1013fn now_epoch_secs() -> i64 {
1014 std::time::SystemTime::now()
1015 .duration_since(std::time::UNIX_EPOCH)
1016 .map(|d| d.as_secs() as i64)
1017 .unwrap_or(0)
1018}
1019
1020#[derive(Clone, Debug)]
1025pub struct SessionSweepConfig {
1026 pub interval: Duration,
1031 pub tx_warn_secs: Duration,
1033 pub tx_max_age_secs: Duration,
1035}
1036
1037impl Default for SessionSweepConfig {
1038 fn default() -> Self {
1039 Self {
1040 interval: Duration::from_secs(5),
1041 tx_warn_secs: Duration::from_secs(30),
1042 tx_max_age_secs: Duration::from_secs(120),
1043 }
1044 }
1045}
1046
1047impl SessionSweepConfig {
1048 pub fn from_env() -> Self {
1052 let mut cfg = Self::default();
1053
1054 if let Ok(ms) = std::env::var("KHIVE_SESSION_SWEEP_INTERVAL_MS") {
1055 if let Ok(v) = ms.parse::<u64>() {
1056 if v > 0 {
1057 cfg.interval = Duration::from_millis(v);
1058 }
1059 }
1060 }
1061 (cfg.tx_warn_secs, cfg.tx_max_age_secs) =
1066 tx_age_thresholds_from_env(cfg.tx_warn_secs, cfg.tx_max_age_secs);
1067
1068 cfg
1069 }
1070}
1071
1072pub struct SweepBackend {
1082 pub pool: Arc<ConnectionPool>,
1083 pub is_main: bool,
1084}
1085
1086struct BackendSweep {
1092 filter: khive_storage::tx_registry::TxOriginFilter,
1093 tx_age_state: TxAgeSweepState,
1094 sidecar: Option<WalpinSidecarState>,
1095}
1096
1097pub async fn run_session_sweep_task(
1111 backends: Vec<SweepBackend>,
1112 config: SessionSweepConfig,
1113 mut shutdown_rx: tokio::sync::watch::Receiver<()>,
1114) {
1115 let mut interval = tokio::time::interval(config.interval);
1116 interval.set_missed_tick_behavior(tokio::time::MissedTickBehavior::Skip);
1117
1118 let mut sweeps: Vec<BackendSweep> = Vec::with_capacity(backends.len());
1119 for backend in backends {
1120 let identity = match backend.pool.origin() {
1121 khive_storage::tx_registry::TxOrigin::Database(id) => id,
1122 khive_storage::tx_registry::TxOrigin::Memory
1125 | khive_storage::tx_registry::TxOrigin::Unscoped => continue,
1126 };
1127 let filter = if backend.is_main {
1128 khive_storage::tx_registry::TxOriginFilter::Main(identity)
1129 } else {
1130 khive_storage::tx_registry::TxOriginFilter::Secondary(identity)
1131 };
1132 let sidecar = WalpinSidecarState::new(
1133 backend.pool.canonical_path(),
1134 true,
1135 "session",
1136 config.interval,
1137 );
1138 sweeps.push(BackendSweep {
1139 filter,
1140 tx_age_state: TxAgeSweepState::default(),
1141 sidecar,
1142 });
1143 }
1144 for sweep in sweeps.iter_mut() {
1145 if let Some(sidecar) = sweep.sidecar.as_mut() {
1146 sidecar.register_beacon().await;
1147 }
1148 }
1149
1150 loop {
1151 tokio::select! {
1152 _ = interval.tick() => {}
1153 _ = shutdown_rx.changed() => break,
1154 }
1155
1156 for sweep in sweeps.iter_mut() {
1157 let oldest = khive_storage::tx_registry::oldest_for(&sweep.filter);
1158 for emission in sweep.tx_age_state.observe(
1159 oldest.as_ref().map(|s| (s.id, s.age, s.label.clone())),
1160 config.tx_warn_secs,
1161 config.tx_max_age_secs,
1162 ) {
1163 log_tx_age_emission(&emission);
1164 }
1165 if let Some(sidecar) = sweep.sidecar.as_mut() {
1166 sidecar.observe(oldest, config.tx_warn_secs).await;
1167 }
1168 }
1169 }
1170
1171 for sweep in sweeps.iter_mut() {
1172 if let Some(sidecar) = sweep.sidecar.as_mut() {
1173 sidecar.shutdown().await;
1174 }
1175 }
1176}
1177
1178pub async fn run_checkpoint_task(
1205 pool: Arc<ConnectionPool>,
1206 config: CheckpointConfig,
1207 event_store: Option<Arc<dyn khive_storage::EventStore>>,
1208 namespace: String,
1209 mut shutdown_rx: tokio::sync::watch::Receiver<()>,
1210 is_main: bool,
1211) {
1212 let mut interval = tokio::time::interval(config.interval);
1213 interval.set_missed_tick_behavior(tokio::time::MissedTickBehavior::Skip);
1214 let mut severity_state = CheckpointSeverityState::default();
1215 let mut tx_age_state = TxAgeSweepState::default();
1216 let mut was_above_high_water = false;
1217 let mut truncate_state = TruncateState::default();
1218 let mut event_was_elevated = false;
1223 let tx_filter = match pool.origin() {
1236 khive_storage::tx_registry::TxOrigin::Database(id) => Some(if is_main {
1237 khive_storage::tx_registry::TxOriginFilter::Main(id)
1238 } else {
1239 khive_storage::tx_registry::TxOriginFilter::Secondary(id)
1240 }),
1241 khive_storage::tx_registry::TxOrigin::Memory
1242 | khive_storage::tx_registry::TxOrigin::Unscoped => None,
1243 };
1244 #[cfg(unix)]
1250 let mut walpin_state =
1251 WalpinSidecarState::new(pool.canonical_path(), true, "daemon", config.interval);
1252 #[cfg(unix)]
1253 if let Some(sidecar) = walpin_state.as_mut() {
1254 sidecar.register_beacon().await;
1255 }
1256
1257 loop {
1258 tokio::select! {
1263 _ = interval.tick() => {}
1264 _ = shutdown_rx.changed() => break,
1265 }
1266
1267 let tick = checkpoint_once(&pool, &config, &mut truncate_state);
1268
1269 let oldest_tx = tx_filter
1285 .as_ref()
1286 .and_then(khive_storage::tx_registry::oldest_for);
1287 for emission in tx_age_state.observe(
1288 oldest_tx.as_ref().map(|s| (s.id, s.age, s.label.clone())),
1289 config.tx_warn_secs,
1290 config.tx_max_age_secs,
1291 ) {
1292 log_tx_age_emission(&emission);
1293 }
1294 #[cfg(unix)]
1298 if let Some(sidecar) = walpin_state.as_mut() {
1299 sidecar
1300 .observe(oldest_tx.clone(), config.tx_warn_secs)
1301 .await;
1302 }
1303
1304 let wal_pages = match tick {
1307 CheckpointTick::Skipped => continue,
1308 CheckpointTick::Observed(n) => n,
1309 };
1310
1311 let above_warn = wal_pages >= config.warn_pages;
1312 let above_high_water = wal_pages >= config.high_water_pages;
1313 let above_truncate_high_water = wal_pages >= config.truncate_high_water_pages;
1314
1315 log_tx_registry_oldest_debug(wal_pages, oldest_tx.as_ref());
1321
1322 for emission in severity_state.observe_wal_pages(wal_pages, &config) {
1327 match emission.rung {
1328 CheckpointSeverityRung::Info => {
1329 log_tx_registry_oldest_warn(wal_pages, oldest_tx.as_ref());
1330 tracing::info!(
1331 wal_pages = emission.wal_pages,
1332 warn_threshold = emission.threshold_pages,
1333 "WAL page count crossed warn threshold"
1334 );
1335 }
1336 CheckpointSeverityRung::Warn => {
1337 tracing::warn!(
1338 wal_pages = emission.wal_pages,
1339 warn_threshold = emission.threshold_pages,
1340 consecutive_cycles = emission.consecutive_cycles,
1341 "WAL page count failed to drain below warn threshold"
1342 );
1343 }
1344 CheckpointSeverityRung::Alarm => {
1345 }
1347 }
1348 }
1349
1350 let high_water_crossed = crossing_warn(above_high_water, &mut was_above_high_water);
1351 if high_water_crossed {
1352 log_tx_registry_snapshot_warn(wal_pages);
1353 tracing::warn!(
1354 wal_pages,
1355 high_water = config.high_water_pages,
1356 "WAL high-water mark exceeded; sustained WAL pressure — \
1357 a long-lived reader may be pinning an old snapshot that PASSIVE cannot reclaim"
1358 );
1359 }
1360
1361 if checkpoint_outcome_should_emit(above_warn, event_was_elevated) {
1365 let payload = khive_storage::CheckpointOutcomeRecordedPayload {
1366 wal_pages,
1367 warn_pages: config.warn_pages,
1368 high_water_pages: config.high_water_pages,
1369 truncate_high_water_pages: config.truncate_high_water_pages,
1370 above_warn,
1371 above_high_water,
1372 above_truncate_high_water,
1373 };
1374 append_checkpoint_lifecycle_event(
1375 event_store.as_ref(),
1376 &namespace,
1377 khive_types::EventKind::CheckpointOutcomeRecorded,
1378 payload,
1379 )
1380 .await;
1381 }
1382 event_was_elevated = above_warn;
1383 }
1384
1385 #[cfg(unix)]
1386 if let Some(sidecar) = walpin_state.as_mut() {
1387 sidecar.shutdown().await;
1388 }
1389}
1390
1391fn checkpoint_outcome_should_emit(above_warn: bool, was_elevated: bool) -> bool {
1397 above_warn || was_elevated
1398}
1399
1400async fn append_checkpoint_lifecycle_event<P: serde::Serialize>(
1407 store: Option<&Arc<dyn khive_storage::EventStore>>,
1408 namespace: &str,
1409 kind: khive_types::EventKind,
1410 payload: P,
1411) {
1412 let Some(store) = store else {
1413 return;
1414 };
1415 let payload_value = match serde_json::to_value(&payload) {
1416 Ok(v) => v,
1417 Err(e) => {
1418 tracing::warn!(
1419 error = %e,
1420 event_kind = %kind.name(),
1421 "failed to serialize checkpoint lifecycle event payload"
1422 );
1423 return;
1424 }
1425 };
1426 let event = khive_storage::Event::new(
1427 namespace,
1428 "checkpoint.lifecycle",
1429 kind,
1430 khive_types::SubstrateKind::Event,
1431 "daemon:checkpoint_task",
1432 )
1433 .with_payload(payload_value);
1434 if let Err(err) = store.append_event(event).await {
1435 tracing::warn!(
1436 error = %err,
1437 event_kind = %kind.name(),
1438 "checkpoint lifecycle event append failed"
1439 );
1440 }
1441}
1442
1443fn log_tx_registry_oldest_debug(
1452 wal_pages: u64,
1453 oldest: Option<&khive_storage::tx_registry::OldestSpan>,
1454) {
1455 if let Some(span) = oldest {
1456 tracing::debug!(
1457 wal_pages,
1458 oldest_tx_age_secs = span.age.as_secs_f64(),
1459 oldest_tx_label = span.label.as_deref().unwrap_or("<unlabeled>"),
1460 "WAL checkpoint tick: oldest open transaction registry entry"
1461 );
1462 }
1463}
1464
1465fn log_tx_registry_oldest_warn(
1469 wal_pages: u64,
1470 oldest: Option<&khive_storage::tx_registry::OldestSpan>,
1471) {
1472 if let Some(span) = oldest {
1473 tracing::warn!(
1474 wal_pages,
1475 oldest_tx_age_secs = span.age.as_secs_f64(),
1476 oldest_tx_label = span.label.as_deref().unwrap_or("<unlabeled>"),
1477 "WAL checkpoint tick: oldest open transaction registry entry"
1478 );
1479 }
1480}
1481
1482fn log_tx_registry_snapshot_warn(wal_pages: u64) {
1486 for (age, label) in khive_storage::tx_registry::snapshot() {
1487 tracing::warn!(
1488 wal_pages,
1489 tx_age_secs = age.as_secs_f64(),
1490 tx_label = label.as_deref().unwrap_or("<unlabeled>"),
1491 "WAL high-water: open transaction registry entry"
1492 );
1493 }
1494}
1495
1496pub fn checkpoint_once(
1513 pool: &ConnectionPool,
1514 config: &CheckpointConfig,
1515 truncate_state: &mut TruncateState,
1516) -> CheckpointTick {
1517 let writer = match pool.try_writer_nowait() {
1518 Ok(w) => w,
1519 Err(_) => {
1520 note_checkpoint_skipped();
1521 return CheckpointTick::Skipped;
1522 }
1523 };
1524
1525 let wal_pages = query_wal_pages(writer.conn());
1526
1527 if let Err(e) = writer
1528 .conn()
1529 .execute_batch("PRAGMA wal_checkpoint(PASSIVE)")
1530 {
1531 tracing::warn!(error = %e, "WAL checkpoint failed");
1532 } else {
1533 tracing::debug!(wal_pages, "WAL checkpoint issued");
1534 }
1535
1536 maybe_truncate(pool, &writer, config, wal_pages, truncate_state);
1537
1538 CheckpointTick::Observed(wal_pages)
1539}
1540
1541fn maybe_truncate(
1546 pool: &ConnectionPool,
1547 writer: &WriterGuard<'_>,
1548 config: &CheckpointConfig,
1549 wal_pages_before: u64,
1550 truncate_state: &mut TruncateState,
1551) {
1552 if wal_pages_before < config.truncate_high_water_pages {
1553 return;
1554 }
1555
1556 if let Some(last) = truncate_state.last_attempt {
1557 if last.elapsed() < config.truncate_min_interval {
1558 return;
1559 }
1560 }
1561
1562 log_tx_registry_snapshot_warn(wal_pages_before);
1565
1566 let conn = writer.conn();
1567 let original_busy_timeout = pool.config().busy_timeout;
1568
1569 if let Err(e) = conn.busy_timeout(config.truncate_busy_timeout) {
1570 tracing::warn!(error = %e, "failed to lower busy_timeout for TRUNCATE attempt; skipping");
1576 return;
1577 }
1578
1579 truncate_state.last_attempt = Some(Instant::now());
1583
1584 let start = Instant::now();
1585 let outcome = conn.execute_batch("PRAGMA wal_checkpoint(TRUNCATE)");
1586 let elapsed = start.elapsed();
1587
1588 if let Err(e) = conn.busy_timeout(original_busy_timeout) {
1591 tracing::warn!(error = %e, "failed to restore busy_timeout after TRUNCATE attempt");
1592 }
1593
1594 match outcome {
1595 Ok(()) => {
1596 let wal_pages_after = query_wal_pages(conn);
1597 tracing::info!(
1598 wal_pages_before,
1599 wal_pages_after,
1600 elapsed_ms = elapsed.as_millis() as u64,
1601 "WAL TRUNCATE checkpoint attempted"
1602 );
1603
1604 let made_progress = wal_pages_after < wal_pages_before;
1605 if !made_progress {
1606 tracing::warn!(
1607 wal_pages_before,
1608 wal_pages_after,
1609 "WAL TRUNCATE attempt made no progress; \
1610 a long-lived reader may still be pinning the WAL snapshot"
1611 );
1612 log_tx_registry_snapshot_warn(wal_pages_after);
1613 #[cfg(unix)]
1614 log_walpin_sidecar_report(pool);
1615 log_wal_pin_depth(conn);
1616 }
1617
1618 note_truncate_outcome(config, wal_pages_after, truncate_state);
1619 }
1620 Err(e) => {
1621 tracing::warn!(error = %e, wal_pages_before, "WAL TRUNCATE attempt failed");
1622 log_tx_registry_snapshot_warn(wal_pages_before);
1623 note_truncate_outcome(config, wal_pages_before, truncate_state);
1624 }
1625 }
1626}
1627
1628fn note_truncate_outcome(
1634 config: &CheckpointConfig,
1635 wal_pages_after: u64,
1636 state: &mut TruncateState,
1637) {
1638 TRUNCATE_ATTEMPTS.fetch_add(1, Ordering::Relaxed);
1643
1644 if wal_pages_after >= config.warn_pages {
1645 state.consecutive_failures = state.consecutive_failures.saturating_add(1);
1646 if state.consecutive_failures == 3 {
1647 tracing::warn!(
1648 wal_pages_after,
1649 warn_threshold = config.warn_pages,
1650 "WAL TRUNCATE has failed to clear WAL pressure for 3 consecutive attempts"
1651 );
1652 }
1653 } else {
1654 state.consecutive_failures = 0;
1655 }
1656
1657 TRUNCATE_CONSECUTIVE_FAILURES.store(state.consecutive_failures as u64, Ordering::Relaxed);
1658}
1659
1660#[cfg(unix)]
1675fn log_walpin_sidecar_report(pool: &ConnectionPool) {
1676 let Some(path) = pool.canonical_path() else {
1677 return;
1678 };
1679 if !crate::walpin::sidecar_enabled(true) {
1680 return;
1681 }
1682 let dir = crate::walpin::sidecar_dir_for(path);
1683 let sweep_interval = SessionSweepConfig::from_env().interval;
1688 let report = match crate::walpin::enumerate_live(&dir, sweep_interval) {
1689 Ok(report) => report,
1690 Err(e) => {
1691 tracing::warn!(
1692 error = %e,
1693 "ADR-091 Amendment 2 Plank B: sidecar directory failed the trust-boundary \
1694 check; cross-process WAL-pin attribution is unestablished for this tick"
1695 );
1696 return;
1697 }
1698 };
1699 let now = now_epoch_secs();
1700 for hb in report.reporting() {
1701 tracing::warn!(
1707 walpin_pid = hb.pid,
1708 walpin_role = %hb.process_role,
1709 walpin_oldest_tx_age_secs = hb.current_oldest_tx_age_secs(now),
1710 walpin_oldest_tx_label = hb.oldest_tx_label.as_deref().unwrap_or("<unlabeled>"),
1711 walpin_attribution_basis = hb.attribution_basis.as_deref().unwrap_or("<unspecified>"),
1712 walpin_attribution_evidence_backed = hb.attribution_is_evidence_backed(),
1713 walpin_health = "reporting",
1714 "ADR-091 Amendment 2 Plank B: live cross-process WAL-pin attribution report"
1715 );
1716 }
1717 for pid in report.registered_silent_pids() {
1718 tracing::debug!(
1719 walpin_pid = pid,
1720 walpin_health = "registered_silent",
1721 "ADR-091 Amendment 2 Plank B: process affirmatively reports no over-threshold span"
1722 );
1723 }
1724 let mut unknown_pids: Vec<u32> = report.unknown_pids().collect();
1725
1726 match crate::walpin::census_holders(path) {
1735 Ok(census) => {
1736 let sidecar_known: std::collections::HashSet<u32> = report
1737 .reporting()
1738 .map(|hb| hb.pid)
1739 .chain(report.registered_silent_pids())
1740 .chain(unknown_pids.iter().copied())
1741 .collect();
1742 let mut census_only: Vec<u32> =
1743 census.holders.difference(&sidecar_known).copied().collect();
1744 if !census_only.is_empty() {
1745 census_only.sort_unstable();
1746 tracing::warn!(
1747 ?census_only,
1748 "ADR-091 Amendment 2: these PIDs hold the database file open \
1749 at the OS level but have no sidecar data at all (pre-feature binary, \
1750 sidecar disabled, or wedged before its first write)"
1751 );
1752 unknown_pids.extend(census_only);
1753 }
1754 if !census.is_complete() {
1755 let mut uninspectable = census.uninspectable_pids.clone();
1756 uninspectable.sort_unstable();
1757 tracing::warn!(
1758 ?uninspectable,
1759 truncated = census.truncated,
1760 "ADR-091 Amendment 2: the OS-derived holder census is \
1761 INCOMPLETE — either specific PIDs' open file descriptors could not be \
1762 inspected (permission denied, or a listing race), or the enumeration walk \
1763 itself has positive evidence it did not see the full live-process universe \
1764 (namespace/visibility check, directory-iterator error, self-canary, or a \
1765 libproc buffer that stayed at capacity after bounded retries) — cannot \
1766 rule out an unregistered holder"
1767 );
1768 if uninspectable.is_empty() {
1769 unknown_pids.push(0);
1776 } else {
1777 unknown_pids.extend(uninspectable);
1778 }
1779 }
1780 }
1781 Err(e) => {
1782 tracing::warn!(
1783 error = %e,
1784 "ADR-091 Amendment 2: OS-derived holder census failed; \
1785 attribution cannot rule out an unregistered database holder this tick"
1786 );
1787 unknown_pids.push(0);
1791 }
1792 }
1793
1794 if !unknown_pids.is_empty() {
1795 tracing::warn!(
1796 ?unknown_pids,
1797 "ADR-091 Amendment 2 Plank B: sidecar health unestablished for these PIDs; \
1798 attribution is inconclusive and the native/unregistered-mechanism conclusion \
1799 is NOT licensed this tick"
1800 );
1801 } else if report.reporting().next().is_none() {
1802 tracing::info!(
1803 "ADR-091 Amendment 2 Plank B: every live PID is reporting or registered-silent \
1804 with none pinning; the WAL pin is not attributable to any in-process registry \
1805 span this sidecar covers"
1806 );
1807 }
1808}
1809
1810fn log_wal_pin_depth(conn: &rusqlite::Connection) {
1816 match query_wal_pin_depth(conn) {
1817 Ok((log, checkpointed)) => {
1818 tracing::warn!(
1819 wal_log_frames = log,
1820 wal_checkpointed_frames = checkpointed,
1821 wal_pin_depth = (log - checkpointed).max(0),
1822 "ADR-091 Amendment 2 Plank C: WAL pin depth after TRUNCATE no-progress"
1823 );
1824 }
1825 Err(e) => {
1826 tracing::warn!(
1827 error = %e,
1828 "ADR-091 Amendment 2 Plank C: failed to query WAL pin depth"
1829 );
1830 }
1831 }
1832}
1833
1834fn query_wal_pin_depth(conn: &rusqlite::Connection) -> rusqlite::Result<(i64, i64)> {
1841 conn.query_row("PRAGMA wal_checkpoint(PASSIVE)", [], |row| {
1842 Ok((row.get::<_, i64>(1)?, row.get::<_, i64>(2)?))
1843 })
1844}
1845
1846fn crossing_warn(now_above: bool, was_above: &mut bool) -> bool {
1855 let fire = now_above && !*was_above;
1856 *was_above = now_above;
1857 fire
1858}
1859
1860fn query_wal_pages(conn: &rusqlite::Connection) -> u64 {
1873 let pages = conn
1874 .query_row("PRAGMA wal_checkpoint", [], |row| row.get::<_, i64>(1))
1875 .unwrap_or(0)
1876 .max(0) as u64;
1877 LAST_WAL_PAGES.store(pages, Ordering::Relaxed);
1881 note_checkpoint_observed(pages);
1882 pages
1883}
1884
1885#[cfg(test)]
1886mod tests {
1887 use super::*;
1888 use crate::pool::PoolConfig;
1889 use serial_test::serial;
1890 use tracing::field::{Field, Visit};
1891
1892 #[derive(Clone, Debug, Default)]
1893 struct CapturedEvent {
1894 message: Option<String>,
1895 oldest_tx_label: Option<String>,
1896 tx_label: Option<String>,
1897 }
1898
1899 #[derive(Default)]
1900 struct CapturedEventVisitor(CapturedEvent);
1901
1902 impl Visit for CapturedEventVisitor {
1903 fn record_str(&mut self, field: &Field, value: &str) {
1904 match field.name() {
1905 "message" => self.0.message = Some(value.to_string()),
1906 "oldest_tx_label" => self.0.oldest_tx_label = Some(value.to_string()),
1907 "tx_label" => self.0.tx_label = Some(value.to_string()),
1908 _ => {}
1909 }
1910 }
1911
1912 fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
1913 let formatted = format!("{value:?}");
1914 let cleaned = formatted
1915 .trim_start_matches('"')
1916 .trim_end_matches('"')
1917 .to_string();
1918 match field.name() {
1919 "message" => self.0.message = Some(cleaned),
1920 "oldest_tx_label" => self.0.oldest_tx_label = Some(cleaned),
1921 "tx_label" => self.0.tx_label = Some(cleaned),
1922 _ => {}
1923 }
1924 }
1925 }
1926
1927 struct CaptureSubscriber {
1932 events: std::sync::Arc<std::sync::Mutex<Vec<CapturedEvent>>>,
1933 }
1934
1935 impl tracing::Subscriber for CaptureSubscriber {
1936 fn enabled(&self, _: &tracing::Metadata<'_>) -> bool {
1937 true
1938 }
1939 fn new_span(&self, _: &tracing::span::Attributes<'_>) -> tracing::span::Id {
1940 tracing::span::Id::from_u64(1)
1941 }
1942 fn record(&self, _: &tracing::span::Id, _: &tracing::span::Record<'_>) {}
1943 fn record_follows_from(&self, _: &tracing::span::Id, _: &tracing::span::Id) {}
1944 fn event(&self, event: &tracing::Event<'_>) {
1945 let mut visitor = CapturedEventVisitor::default();
1946 event.record(&mut visitor);
1947 self.events.lock().unwrap().push(visitor.0);
1948 }
1949 fn enter(&self, _: &tracing::span::Id) {}
1950 fn exit(&self, _: &tracing::span::Id) {}
1951 }
1952
1953 #[test]
1956 #[serial(tx_registry)]
1957 fn log_tx_registry_oldest_debug_reports_oldest_open_entry() {
1958 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
1959 let subscriber = CaptureSubscriber {
1960 events: std::sync::Arc::clone(&buffer),
1961 };
1962
1963 let _handle =
1964 khive_storage::tx_registry::register(Some("checkpoint_tick_test".to_string()));
1965
1966 let oldest = khive_storage::tx_registry::oldest().map(|(id, age, label)| {
1967 khive_storage::tx_registry::OldestSpan {
1968 id,
1969 age,
1970 label,
1971 origin: khive_storage::tx_registry::TxOrigin::Unscoped,
1972 }
1973 });
1974 let expected_label = oldest
1975 .as_ref()
1976 .and_then(|s| s.label.clone())
1977 .unwrap_or_else(|| "<unlabeled>".to_string());
1978
1979 tracing::subscriber::with_default(subscriber, || {
1980 log_tx_registry_oldest_debug(100, oldest.as_ref());
1981 });
1982
1983 let events = buffer.lock().unwrap();
1984 assert!(
1985 events.iter().any(|e| {
1986 e.message.as_deref()
1987 == Some("WAL checkpoint tick: oldest open transaction registry entry")
1988 && e.oldest_tx_label.as_deref() == Some(expected_label.as_str())
1989 }),
1990 "expected a log line naming the open registry entry's label, got: {events:?}"
1991 );
1992 }
1993
1994 #[test]
2000 #[serial(tx_registry)]
2001 fn registry_warns_fire_on_crossing_and_do_not_repeat() {
2002 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
2003 let subscriber = CaptureSubscriber {
2004 events: std::sync::Arc::clone(&buffer),
2005 };
2006
2007 let _handle =
2008 khive_storage::tx_registry::register(Some("registry_warn_crossing_test".to_string()));
2009 let oldest = khive_storage::tx_registry::oldest().map(|(id, age, label)| {
2010 khive_storage::tx_registry::OldestSpan {
2011 id,
2012 age,
2013 label,
2014 origin: khive_storage::tx_registry::TxOrigin::Unscoped,
2015 }
2016 });
2017
2018 let mut was_above_warn = false;
2019 let mut was_above_high_water = false;
2020
2021 tracing::subscriber::with_default(subscriber, || {
2022 if crossing_warn(true, &mut was_above_warn) {
2024 log_tx_registry_oldest_warn(6000, oldest.as_ref());
2025 }
2026 if crossing_warn(true, &mut was_above_high_water) {
2027 log_tx_registry_snapshot_warn(6000);
2028 }
2029
2030 if crossing_warn(true, &mut was_above_warn) {
2032 log_tx_registry_oldest_warn(6000, oldest.as_ref());
2033 }
2034 if crossing_warn(true, &mut was_above_high_water) {
2035 log_tx_registry_snapshot_warn(6000);
2036 }
2037 });
2038
2039 let events = buffer.lock().unwrap();
2040
2041 let oldest_warn_count = events
2051 .iter()
2052 .filter(|e| {
2053 e.message.as_deref()
2054 == Some("WAL checkpoint tick: oldest open transaction registry entry")
2055 })
2056 .count();
2057 assert_eq!(
2058 oldest_warn_count, 1,
2059 "oldest-entry WARN must fire exactly once across two above-threshold ticks, got: {events:?}"
2060 );
2061
2062 let snapshot_warn_count = events
2063 .iter()
2064 .filter(|e| {
2065 e.message.as_deref() == Some("WAL high-water: open transaction registry entry")
2066 && e.tx_label.as_deref() == Some("registry_warn_crossing_test")
2067 })
2068 .count();
2069 assert_eq!(
2070 snapshot_warn_count, 1,
2071 "high-water snapshot WARN must fire exactly once across two above-threshold ticks, got: {events:?}"
2072 );
2073 }
2074
2075 #[test]
2078 fn log_tx_age_emission_carries_label_for_both_rungs() {
2079 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
2080 let subscriber = CaptureSubscriber {
2081 events: std::sync::Arc::clone(&buffer),
2082 };
2083
2084 tracing::subscriber::with_default(subscriber, || {
2085 log_tx_age_emission(&TxAgeEmission {
2086 rung: TxAgeRung::Warn,
2087 age: Duration::from_secs(45),
2088 label: Some("plank1_warn_test".to_string()),
2089 });
2090 log_tx_age_emission(&TxAgeEmission {
2091 rung: TxAgeRung::Stale,
2092 age: Duration::from_secs(150),
2093 label: Some("plank1_stale_test".to_string()),
2094 });
2095 });
2096
2097 let events = buffer.lock().unwrap();
2098 assert!(
2099 events.iter().any(|e| {
2100 e.message.as_deref()
2101 == Some(
2102 "ADR-091 Plank 1: open transaction registry entry exceeded soft-cap age",
2103 )
2104 && e.tx_label.as_deref() == Some("plank1_warn_test")
2105 }),
2106 "expected a Warn-rung log line naming the entry, got: {events:?}"
2107 );
2108 assert!(
2109 events.iter().any(|e| {
2110 e.message.as_deref().is_some_and(|m| {
2111 m.starts_with(
2112 "ADR-091 Plank 1: open transaction registry entry exceeded the cooperative",
2113 )
2114 }) && e.tx_label.as_deref() == Some("plank1_stale_test")
2115 }),
2116 "expected a Stale-rung log line naming the entry, got: {events:?}"
2117 );
2118 }
2119
2120 fn file_pool(path: &std::path::Path) -> Arc<ConnectionPool> {
2121 let cfg = PoolConfig {
2122 path: Some(path.to_path_buf()),
2123 ..PoolConfig::default()
2124 };
2125 Arc::new(ConnectionPool::new(cfg).expect("pool open"))
2126 }
2127
2128 #[test]
2134 #[serial(checkpoint_skip_metrics)]
2135 fn checkpoint_once_succeeds_on_file_backed_pool() {
2136 let dir = tempfile::tempdir().unwrap();
2137 let path = dir.path().join("wal_test.db");
2138 let pool = file_pool(&path);
2139
2140 {
2142 let writer = pool.try_writer().unwrap();
2143 writer
2144 .conn()
2145 .execute_batch("CREATE TABLE IF NOT EXISTS t (x INTEGER);")
2146 .unwrap();
2147 writer
2148 .conn()
2149 .execute_batch("INSERT INTO t VALUES (1);")
2150 .unwrap();
2151 }
2152
2153 checkpoint_once(
2154 &pool,
2155 &CheckpointConfig::default(),
2156 &mut TruncateState::default(),
2157 );
2158 }
2159
2160 #[test]
2161 #[serial(checkpoint_skip_metrics)]
2162 fn checkpoint_once_is_noop_on_in_memory_pool() {
2163 let cfg = PoolConfig {
2165 path: None,
2166 ..PoolConfig::default()
2167 };
2168 let pool = Arc::new(ConnectionPool::new(cfg).expect("in-memory pool"));
2169 checkpoint_once(
2170 &pool,
2171 &CheckpointConfig::default(),
2172 &mut TruncateState::default(),
2173 );
2174 }
2175
2176 #[tokio::test]
2177 #[serial(checkpoint_skip_metrics)]
2178 async fn checkpoint_task_exits_on_shutdown_signal() {
2179 let dir = tempfile::tempdir().unwrap();
2180 let path = dir.path().join("wal_task_shutdown.db");
2181 let pool = file_pool(&path);
2182
2183 let cfg = CheckpointConfig {
2185 interval: Duration::from_millis(10),
2186 ..Default::default()
2187 };
2188
2189 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
2190 let handle = tokio::spawn(run_checkpoint_task(
2191 pool,
2192 cfg,
2193 None,
2194 "local".to_string(),
2195 shutdown_rx,
2196 true,
2197 ));
2198
2199 shutdown_tx.send(()).expect("send shutdown signal");
2200
2201 tokio::time::timeout(Duration::from_secs(1), handle)
2202 .await
2203 .expect("checkpoint task should exit within 1s")
2204 .expect("checkpoint task panicked");
2205 }
2206
2207 #[tokio::test]
2211 #[serial(checkpoint_skip_metrics)]
2212 async fn checkpoint_task_exits_via_shutdown_signal_with_live_event_store_pool_clone() {
2213 let dir = tempfile::tempdir().unwrap();
2214 let path = dir.path().join("wal_task_event_store.db");
2215 let pool = file_pool(&path);
2216
2217 let cfg = CheckpointConfig {
2218 interval: Duration::from_millis(10),
2219 ..Default::default()
2220 };
2221
2222 let event_store: Arc<dyn khive_storage::EventStore> =
2223 Arc::new(crate::stores::event::SqlEventStore::new_scoped(
2224 Arc::clone(&pool),
2225 true,
2226 "local".to_string(),
2227 ));
2228 let sibling_pool_clone = Arc::clone(&pool);
2233
2234 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
2235 let handle = tokio::spawn(run_checkpoint_task(
2236 pool,
2237 cfg,
2238 Some(event_store),
2239 "local".to_string(),
2240 shutdown_rx,
2241 true,
2242 ));
2243
2244 assert!(
2248 Arc::strong_count(&sibling_pool_clone) > 1,
2249 "test setup must reproduce the multi-owner shape the bug depends on"
2250 );
2251
2252 shutdown_tx.send(()).expect("send shutdown signal");
2253
2254 tokio::time::timeout(Duration::from_secs(1), handle)
2255 .await
2256 .expect(
2257 "checkpoint task should exit within 1s via the watch signal, \
2258 even with a live sibling Arc<ConnectionPool> clone held by \
2259 the event store",
2260 )
2261 .expect("checkpoint task panicked");
2262 }
2263
2264 #[test]
2265 #[serial]
2266 fn checkpoint_config_env_override() {
2267 std::env::set_var("KHIVE_CHECKPOINT_INTERVAL_MS", "250");
2268 std::env::set_var("KHIVE_WAL_WARN_PAGES", "1500");
2269 std::env::set_var("KHIVE_WAL_HIGH_WATER_PAGES", "8000");
2270 std::env::set_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES", "12000");
2271 std::env::set_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS", "60");
2272 std::env::set_var("KHIVE_WAL_TRUNCATE_BUSY_MS", "500");
2273 std::env::set_var("KHIVE_TX_WARN_SECS", "15");
2274 std::env::set_var("KHIVE_TX_MAX_AGE_SECS", "90");
2275
2276 let cfg = CheckpointConfig::from_env();
2277
2278 std::env::remove_var("KHIVE_CHECKPOINT_INTERVAL_MS");
2279 std::env::remove_var("KHIVE_WAL_WARN_PAGES");
2280 std::env::remove_var("KHIVE_WAL_HIGH_WATER_PAGES");
2281 std::env::remove_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES");
2282 std::env::remove_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS");
2283 std::env::remove_var("KHIVE_WAL_TRUNCATE_BUSY_MS");
2284 std::env::remove_var("KHIVE_TX_WARN_SECS");
2285 std::env::remove_var("KHIVE_TX_MAX_AGE_SECS");
2286
2287 assert_eq!(cfg.interval, Duration::from_millis(250));
2288 assert_eq!(cfg.warn_pages, 1500);
2289 assert_eq!(cfg.high_water_pages, 8000);
2290 assert_eq!(cfg.truncate_high_water_pages, 12000);
2291 assert_eq!(cfg.truncate_min_interval, Duration::from_secs(60));
2292 assert_eq!(cfg.truncate_busy_timeout, Duration::from_millis(500));
2293 assert_eq!(cfg.tx_warn_secs, Duration::from_secs(15));
2294 assert_eq!(cfg.tx_max_age_secs, Duration::from_secs(90));
2295 }
2296
2297 #[test]
2298 #[serial]
2299 fn checkpoint_config_defaults_on_invalid_env() {
2300 let default = CheckpointConfig::default();
2301
2302 std::env::set_var("KHIVE_CHECKPOINT_INTERVAL_MS", "not_a_number");
2303 std::env::set_var("KHIVE_WAL_WARN_PAGES", "");
2304 std::env::set_var("KHIVE_WAL_HIGH_WATER_PAGES", "0");
2305 std::env::set_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES", "not_a_number");
2306 std::env::set_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS", "");
2307 std::env::set_var("KHIVE_WAL_TRUNCATE_BUSY_MS", "0");
2308 std::env::set_var("KHIVE_TX_WARN_SECS", "not_a_number");
2309 std::env::set_var("KHIVE_TX_MAX_AGE_SECS", "0");
2310
2311 let cfg = CheckpointConfig::from_env();
2312
2313 std::env::remove_var("KHIVE_CHECKPOINT_INTERVAL_MS");
2314 std::env::remove_var("KHIVE_WAL_WARN_PAGES");
2315 std::env::remove_var("KHIVE_WAL_HIGH_WATER_PAGES");
2316 std::env::remove_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES");
2317 std::env::remove_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS");
2318 std::env::remove_var("KHIVE_WAL_TRUNCATE_BUSY_MS");
2319 std::env::remove_var("KHIVE_TX_WARN_SECS");
2320 std::env::remove_var("KHIVE_TX_MAX_AGE_SECS");
2321
2322 assert_eq!(cfg.interval, default.interval);
2323 assert_eq!(cfg.warn_pages, default.warn_pages);
2324 assert_eq!(cfg.high_water_pages, default.high_water_pages);
2325 assert_eq!(
2326 cfg.truncate_high_water_pages,
2327 default.truncate_high_water_pages
2328 );
2329 assert_eq!(cfg.truncate_min_interval, default.truncate_min_interval);
2330 assert_eq!(cfg.truncate_busy_timeout, default.truncate_busy_timeout);
2331 assert_eq!(cfg.tx_warn_secs, default.tx_warn_secs);
2332 assert_eq!(cfg.tx_max_age_secs, default.tx_max_age_secs);
2333 }
2334
2335 #[test]
2340 #[serial(checkpoint_skip_metrics)]
2341 fn checkpoint_high_water_does_not_block_behind_reader() {
2342 let dir = tempfile::tempdir().unwrap();
2343 let path = dir.path().join("high_water_test.db");
2344
2345 let pool = Arc::new(
2349 ConnectionPool::new(PoolConfig {
2350 path: Some(path.clone()),
2351 busy_timeout: Duration::from_millis(2000),
2352 ..PoolConfig::default()
2353 })
2354 .expect("pool open"),
2355 );
2356
2357 {
2359 let writer = pool.try_writer().unwrap();
2360 writer
2361 .conn()
2362 .execute_batch(
2363 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
2364 )
2365 .unwrap();
2366 }
2367
2368 let reader = pool.reader().expect("reader");
2372 reader
2373 .execute_batch("BEGIN DEFERRED; SELECT * FROM t;")
2374 .expect("begin read tx");
2375
2376 {
2380 let writer = pool.try_writer().unwrap();
2381 writer
2382 .conn()
2383 .execute_batch("INSERT INTO t VALUES (2);")
2384 .unwrap();
2385 }
2386
2387 let start = std::time::Instant::now();
2388 checkpoint_once(
2389 &pool,
2390 &CheckpointConfig::default(),
2391 &mut TruncateState::default(),
2392 );
2393 let elapsed = start.elapsed();
2394
2395 reader.execute_batch("COMMIT;").ok();
2397 drop(reader);
2398
2399 assert!(
2403 elapsed < std::time::Duration::from_millis(500),
2404 "checkpoint_once with active reader snapshot took {:?}; \
2405 expected <500ms (PASSIVE must not block on readers; \
2406 a TRUNCATE regression would block ~2000ms)",
2407 elapsed
2408 );
2409 }
2410
2411 #[test]
2412 #[serial]
2413 fn checkpoint_config_rejects_zero_for_all_fields() {
2414 let default = CheckpointConfig::default();
2415 std::env::set_var("KHIVE_CHECKPOINT_INTERVAL_MS", "0");
2416 std::env::set_var("KHIVE_WAL_WARN_PAGES", "0");
2417 std::env::set_var("KHIVE_WAL_HIGH_WATER_PAGES", "0");
2418 std::env::set_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES", "0");
2419 std::env::set_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS", "0");
2420 std::env::set_var("KHIVE_WAL_TRUNCATE_BUSY_MS", "0");
2421 std::env::set_var("KHIVE_TX_WARN_SECS", "0");
2422 std::env::set_var("KHIVE_TX_MAX_AGE_SECS", "0");
2423
2424 let cfg = CheckpointConfig::from_env();
2425
2426 std::env::remove_var("KHIVE_CHECKPOINT_INTERVAL_MS");
2427 std::env::remove_var("KHIVE_WAL_WARN_PAGES");
2428 std::env::remove_var("KHIVE_WAL_HIGH_WATER_PAGES");
2429 std::env::remove_var("KHIVE_WAL_TRUNCATE_HIGH_WATER_PAGES");
2430 std::env::remove_var("KHIVE_WAL_TRUNCATE_MIN_INTERVAL_SECS");
2431 std::env::remove_var("KHIVE_WAL_TRUNCATE_BUSY_MS");
2432 std::env::remove_var("KHIVE_TX_WARN_SECS");
2433 std::env::remove_var("KHIVE_TX_MAX_AGE_SECS");
2434
2435 assert_eq!(
2436 cfg.interval, default.interval,
2437 "zero interval must fall back to default"
2438 );
2439 assert_eq!(
2440 cfg.warn_pages, default.warn_pages,
2441 "zero warn_pages must fall back to default"
2442 );
2443 assert_eq!(
2444 cfg.high_water_pages, default.high_water_pages,
2445 "zero high_water_pages must fall back to default"
2446 );
2447 assert_eq!(
2448 cfg.truncate_high_water_pages, default.truncate_high_water_pages,
2449 "zero truncate_high_water_pages must fall back to default"
2450 );
2451 assert_eq!(
2452 cfg.truncate_min_interval, default.truncate_min_interval,
2453 "zero truncate_min_interval must fall back to default"
2454 );
2455 assert_eq!(
2456 cfg.truncate_busy_timeout, default.truncate_busy_timeout,
2457 "zero truncate_busy_timeout must fall back to default"
2458 );
2459 assert_eq!(
2460 cfg.tx_warn_secs, default.tx_warn_secs,
2461 "zero tx_warn_secs must fall back to default"
2462 );
2463 assert_eq!(
2464 cfg.tx_max_age_secs, default.tx_max_age_secs,
2465 "zero tx_max_age_secs must fall back to default"
2466 );
2467 }
2468
2469 #[test]
2472 #[serial]
2473 fn checkpoint_config_rejects_reversed_tx_thresholds() {
2474 let default = CheckpointConfig::default();
2475 std::env::set_var("KHIVE_TX_WARN_SECS", "120");
2476 std::env::set_var("KHIVE_TX_MAX_AGE_SECS", "30");
2477
2478 let cfg = CheckpointConfig::from_env();
2479
2480 std::env::remove_var("KHIVE_TX_WARN_SECS");
2481 std::env::remove_var("KHIVE_TX_MAX_AGE_SECS");
2482
2483 assert_eq!(
2484 cfg.tx_warn_secs, default.tx_warn_secs,
2485 "a reversed pair must fall back tx_warn_secs to its default, got: {:?}",
2486 cfg.tx_warn_secs
2487 );
2488 assert_eq!(
2489 cfg.tx_max_age_secs, default.tx_max_age_secs,
2490 "a reversed pair must fall back tx_max_age_secs to its default, got: {:?}",
2491 cfg.tx_max_age_secs
2492 );
2493 }
2494
2495 #[test]
2498 #[serial]
2499 fn checkpoint_config_rejects_equal_tx_thresholds() {
2500 let default = CheckpointConfig::default();
2501 std::env::set_var("KHIVE_TX_WARN_SECS", "60");
2502 std::env::set_var("KHIVE_TX_MAX_AGE_SECS", "60");
2503
2504 let cfg = CheckpointConfig::from_env();
2505
2506 std::env::remove_var("KHIVE_TX_WARN_SECS");
2507 std::env::remove_var("KHIVE_TX_MAX_AGE_SECS");
2508
2509 assert_eq!(
2510 cfg.tx_warn_secs, default.tx_warn_secs,
2511 "an equal pair must fall back tx_warn_secs to its default, got: {:?}",
2512 cfg.tx_warn_secs
2513 );
2514 assert_eq!(
2515 cfg.tx_max_age_secs, default.tx_max_age_secs,
2516 "an equal pair must fall back tx_max_age_secs to its default, got: {:?}",
2517 cfg.tx_max_age_secs
2518 );
2519 }
2520
2521 #[test]
2524 fn skipped_tick_does_not_reset_high_water_crossing_state() {
2525 let mut was_above = false;
2526
2527 assert!(
2529 crossing_warn(true, &mut was_above),
2530 "should fire on first crossing"
2531 );
2532 assert!(was_above);
2533
2534 assert!(was_above, "was_above must stay true across skipped ticks");
2541
2542 let fired = crossing_warn(true, &mut was_above);
2544 assert!(!fired, "WARN must not re-fire while still above threshold");
2545
2546 let fired = crossing_warn(false, &mut was_above);
2548 assert!(!fired);
2549 assert!(!was_above);
2550
2551 let fired = crossing_warn(true, &mut was_above);
2553 assert!(fired, "WARN must fire again on a new below→above crossing");
2554 }
2555
2556 #[test]
2563 fn warn_pages_fires_once_on_crossing_not_every_tick() {
2564 let mut was_above_warn = false;
2565
2566 let fired_1 = crossing_warn(true, &mut was_above_warn);
2568 let fired_2 = crossing_warn(true, &mut was_above_warn);
2569 let fired_3 = crossing_warn(true, &mut was_above_warn);
2570
2571 assert!(fired_1, "WARN must fire on the first in-band tick");
2572 assert!(
2573 !fired_2,
2574 "WARN must not fire on the second consecutive in-band tick"
2575 );
2576 assert!(
2577 !fired_3,
2578 "WARN must not fire on the third consecutive in-band tick"
2579 );
2580
2581 crossing_warn(false, &mut was_above_warn);
2583 assert!(!was_above_warn);
2584
2585 let fired_reentry = crossing_warn(true, &mut was_above_warn);
2587 assert!(
2588 fired_reentry,
2589 "WARN must fire again on re-entry into warn band"
2590 );
2591 }
2592
2593 #[test]
2599 #[serial(tx_registry, checkpoint_skip_metrics)]
2600 fn truncate_attempts_when_high_water_crossed_with_no_prior_attempt() {
2601 let dir = tempfile::tempdir().unwrap();
2602 let path = dir.path().join("truncate_trigger.db");
2603 let pool = file_pool(&path);
2604
2605 {
2606 let writer = pool.try_writer().unwrap();
2607 writer
2608 .conn()
2609 .execute_batch(
2610 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
2611 )
2612 .unwrap();
2613 }
2614
2615 let config = CheckpointConfig {
2616 truncate_high_water_pages: 0,
2620 truncate_min_interval: Duration::from_secs(300),
2621 ..CheckpointConfig::default()
2622 };
2623 let mut state = TruncateState::default();
2624
2625 assert!(
2626 state.last_attempt.is_none(),
2627 "precondition: no attempt has run yet"
2628 );
2629
2630 let tick = checkpoint_once(&pool, &config, &mut state);
2631 assert!(matches!(tick, CheckpointTick::Observed(_)));
2632 assert!(
2633 state.last_attempt.is_some(),
2634 "an attempt must be stamped once the high-water threshold is crossed"
2635 );
2636 }
2637
2638 #[test]
2641 #[serial(tx_registry, checkpoint_skip_metrics)]
2642 fn truncate_does_not_attempt_below_high_water() {
2643 let dir = tempfile::tempdir().unwrap();
2644 let path = dir.path().join("truncate_below_threshold.db");
2645 let pool = file_pool(&path);
2646
2647 {
2648 let writer = pool.try_writer().unwrap();
2649 writer
2650 .conn()
2651 .execute_batch(
2652 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
2653 )
2654 .unwrap();
2655 }
2656
2657 let config = CheckpointConfig {
2659 truncate_high_water_pages: u64::MAX,
2660 ..CheckpointConfig::default()
2661 };
2662 let mut state = TruncateState::default();
2663
2664 checkpoint_once(&pool, &config, &mut state);
2665
2666 assert!(
2667 state.last_attempt.is_none(),
2668 "a below-threshold tick must never stamp last_attempt"
2669 );
2670 }
2671
2672 #[test]
2676 #[serial(tx_registry, checkpoint_skip_metrics)]
2677 fn truncate_min_interval_skip_does_not_restamp_last_attempt() {
2678 let dir = tempfile::tempdir().unwrap();
2679 let path = dir.path().join("truncate_min_interval.db");
2680 let pool = file_pool(&path);
2681
2682 {
2683 let writer = pool.try_writer().unwrap();
2684 writer
2685 .conn()
2686 .execute_batch(
2687 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
2688 )
2689 .unwrap();
2690 }
2691
2692 let config = CheckpointConfig {
2693 truncate_high_water_pages: 0,
2694 truncate_min_interval: Duration::from_secs(300),
2695 ..CheckpointConfig::default()
2696 };
2697 let mut state = TruncateState::default();
2698
2699 checkpoint_once(&pool, &config, &mut state);
2700 let first_attempt = state.last_attempt.expect("first tick must attempt");
2701
2702 checkpoint_once(&pool, &config, &mut state);
2706 let second_attempt = state.last_attempt.expect("attempt timestamp must persist");
2707
2708 assert_eq!(
2709 first_attempt, second_attempt,
2710 "a tick within truncate_min_interval must not re-stamp last_attempt"
2711 );
2712 }
2713
2714 #[test]
2721 #[serial(tx_registry, checkpoint_skip_metrics)]
2722 fn busy_writer_skips_both_passive_and_truncate() {
2723 reset_checkpoint_metrics_for_tests();
2724
2725 let dir = tempfile::tempdir().unwrap();
2726 let path = dir.path().join("truncate_busy_skip.db");
2727 let pool = file_pool(&path);
2728
2729 {
2730 let writer = pool.try_writer().unwrap();
2731 writer
2732 .conn()
2733 .execute_batch(
2734 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
2735 )
2736 .unwrap();
2737 }
2738
2739 let mut warmup_state = TruncateState::default();
2742 let warmup_tick = checkpoint_once(&pool, &CheckpointConfig::default(), &mut warmup_state);
2743 let observed_pages = match warmup_tick {
2744 CheckpointTick::Observed(n) => n,
2745 CheckpointTick::Skipped => panic!("warmup tick must observe, not skip"),
2746 };
2747 assert_eq!(
2748 checkpoint_consecutive_skips(),
2749 0,
2750 "an observed tick must not itself count as a skip"
2751 );
2752
2753 let _held = pool.try_writer().unwrap();
2756
2757 let config = CheckpointConfig {
2758 truncate_high_water_pages: 0,
2759 ..CheckpointConfig::default()
2760 };
2761 let mut state = TruncateState::default();
2762
2763 let tick = checkpoint_once(&pool, &config, &mut state);
2764
2765 assert_eq!(
2766 tick,
2767 CheckpointTick::Skipped,
2768 "a busy writer must skip the tick entirely"
2769 );
2770 assert!(
2771 state.last_attempt.is_none(),
2772 "a skipped tick (writer busy) must never stamp last_attempt, \
2773 even with a threshold that would otherwise arm immediately"
2774 );
2775
2776 assert_eq!(
2777 checkpoint_skipped_ticks(),
2778 1,
2779 "one skipped tick must bump the lifetime skipped-tick counter"
2780 );
2781 assert_eq!(
2782 checkpoint_consecutive_skips(),
2783 1,
2784 "one skipped tick must bump the consecutive-skip run length"
2785 );
2786 assert_eq!(
2787 checkpoint_last_skip_wal_pages(),
2788 Some(observed_pages),
2789 "the skip must snapshot the last-observed WAL pressure"
2790 );
2791 }
2792
2793 #[test]
2808 fn all_checkpoint_metrics_callers_are_serial_tagged() {
2809 const SELF_SRC: &str = include_str!("checkpoint.rs");
2810 let lines: Vec<&str> = SELF_SRC.lines().collect();
2811
2812 let attr_starts: Vec<usize> = lines
2813 .iter()
2814 .enumerate()
2815 .filter(|(_, l)| {
2816 let t = l.trim();
2817 t == "#[test]" || t.starts_with("#[tokio::test")
2818 })
2819 .map(|(i, _)| i)
2820 .collect();
2821
2822 let mut offenders = Vec::new();
2823
2824 for (idx, &start) in attr_starts.iter().enumerate() {
2825 let end = attr_starts.get(idx + 1).copied().unwrap_or(lines.len());
2826 let span = &lines[start..end];
2827
2828 let touches_shared_metrics = span
2829 .iter()
2830 .any(|l| l.contains("checkpoint_once(") || l.contains("run_checkpoint_task("));
2831 if !touches_shared_metrics {
2832 continue;
2833 }
2834
2835 let has_group_tag = span
2836 .iter()
2837 .any(|l| l.contains("#[serial") && l.contains("checkpoint_skip_metrics"));
2838
2839 if !has_group_tag {
2840 let name = span
2841 .iter()
2842 .find_map(|l| {
2843 let t = l.trim_start();
2844 let t = t.strip_prefix("pub(crate) ").unwrap_or(t);
2845 let t = t.strip_prefix("pub ").unwrap_or(t);
2846 let t = t.strip_prefix("async ").unwrap_or(t);
2847 t.strip_prefix("fn ")
2848 .map(|rest| rest.split(['(', '<']).next().unwrap_or("").trim())
2849 })
2850 .unwrap_or("<unknown test>");
2851 offenders.push(name.to_string());
2852 }
2853 }
2854
2855 assert!(
2856 offenders.is_empty(),
2857 "these tests call checkpoint_once/run_checkpoint_task (which write the \
2858 process-wide LAST_WAL_PAGES/CHECKPOINT_* atomics via query_wal_pages) but \
2859 are not tagged #[serial(checkpoint_skip_metrics)] (or a group including it); \
2860 an untagged caller running concurrently on cargo's default test thread pool \
2861 can clobber those atomics mid-assertion in another test (the #828/#845 race): \
2862 {offenders:?}"
2863 );
2864 }
2865
2866 #[test]
2870 #[serial(tx_registry, checkpoint_skip_metrics)]
2871 fn observed_tick_resets_consecutive_skips_but_not_lifetime_total() {
2872 reset_checkpoint_metrics_for_tests();
2873
2874 let dir = tempfile::tempdir().unwrap();
2875 let path = dir.path().join("skip_then_observe.db");
2876 let pool = file_pool(&path);
2877
2878 {
2879 let writer = pool.try_writer().unwrap();
2880 writer
2881 .conn()
2882 .execute_batch(
2883 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
2884 )
2885 .unwrap();
2886 }
2887
2888 {
2890 let _held = pool.try_writer().unwrap();
2891 let mut state = TruncateState::default();
2892 for _ in 0..2 {
2893 let tick = checkpoint_once(&pool, &CheckpointConfig::default(), &mut state);
2894 assert_eq!(tick, CheckpointTick::Skipped);
2895 }
2896 }
2897 assert_eq!(checkpoint_skipped_ticks(), 2);
2898 assert_eq!(checkpoint_consecutive_skips(), 2);
2899
2900 let mut state = TruncateState::default();
2902 let tick = checkpoint_once(&pool, &CheckpointConfig::default(), &mut state);
2903 assert!(matches!(tick, CheckpointTick::Observed(_)));
2904
2905 assert_eq!(
2906 checkpoint_skipped_ticks(),
2907 2,
2908 "an observed tick must not change the lifetime skipped-tick total"
2909 );
2910 assert_eq!(
2911 checkpoint_consecutive_skips(),
2912 0,
2913 "an observed tick must reset the consecutive-skip run length"
2914 );
2915 }
2916
2917 #[test]
2922 fn note_truncate_outcome_warns_once_at_third_consecutive_failure() {
2923 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
2924 let subscriber = CaptureSubscriber {
2925 events: std::sync::Arc::clone(&buffer),
2926 };
2927
2928 let config = CheckpointConfig {
2929 warn_pages: 2000,
2930 ..CheckpointConfig::default()
2931 };
2932 let mut state = TruncateState::default();
2933
2934 tracing::subscriber::with_default(subscriber, || {
2935 note_truncate_outcome(&config, 5000, &mut state);
2937 note_truncate_outcome(&config, 5000, &mut state);
2938 note_truncate_outcome(&config, 5000, &mut state);
2939 note_truncate_outcome(&config, 5000, &mut state);
2941 });
2942
2943 assert_eq!(state.consecutive_failures, 4);
2944
2945 let events = buffer.lock().unwrap();
2946 let escalation_count = events
2947 .iter()
2948 .filter(|e| {
2949 e.message.as_deref()
2950 == Some(
2951 "WAL TRUNCATE has failed to clear WAL pressure for 3 consecutive attempts",
2952 )
2953 })
2954 .count();
2955 assert_eq!(
2956 escalation_count, 1,
2957 "escalation WARN must fire exactly once at the 3rd consecutive failure, got: {events:?}"
2958 );
2959
2960 note_truncate_outcome(&config, 100, &mut state);
2962 assert_eq!(
2963 state.consecutive_failures, 0,
2964 "an attempt that clears warn_pages must reset the consecutive-failure counter"
2965 );
2966 }
2967
2968 fn severity_test_config() -> CheckpointConfig {
2971 CheckpointConfig {
2972 warn_pages: 100,
2973 warn_sustained_cycles: 3,
2974 ..CheckpointConfig::default()
2975 }
2976 }
2977
2978 #[test]
2981 fn severity_ladder_info_on_first_crossing_no_warn() {
2982 let config = severity_test_config();
2983 let mut state = CheckpointSeverityState::default();
2984
2985 let below = state.observe_wal_pages(10, &config);
2986 assert!(below.is_empty(), "below-warn tick must emit nothing");
2987
2988 let above = state.observe_wal_pages(150, &config);
2989 assert_eq!(
2990 above,
2991 vec![CheckpointSeverityEmission {
2992 rung: CheckpointSeverityRung::Info,
2993 wal_pages: 150,
2994 threshold_pages: 100,
2995 consecutive_cycles: 1,
2996 }],
2997 "first below->above crossing must emit exactly one INFO and no WARN"
2998 );
2999 }
3000
3001 #[test]
3004 fn severity_ladder_warn_on_third_consecutive_cycle() {
3005 let config = severity_test_config();
3006 let mut state = CheckpointSeverityState::default();
3007
3008 let tick1 = state.observe_wal_pages(150, &config);
3009 assert_eq!(tick1.len(), 1);
3010 assert_eq!(tick1[0].rung, CheckpointSeverityRung::Info);
3011
3012 let tick2 = state.observe_wal_pages(150, &config);
3013 assert!(
3014 tick2.is_empty(),
3015 "second consecutive above-warn tick must emit nothing yet"
3016 );
3017
3018 let tick3 = state.observe_wal_pages(150, &config);
3019 assert_eq!(
3020 tick3,
3021 vec![CheckpointSeverityEmission {
3022 rung: CheckpointSeverityRung::Warn,
3023 wal_pages: 150,
3024 threshold_pages: 100,
3025 consecutive_cycles: 3,
3026 }],
3027 "WARN must fire exactly on the third consecutive above-warn tick"
3028 );
3029
3030 let tick4 = state.observe_wal_pages(150, &config);
3031 assert!(
3032 tick4.is_empty(),
3033 "WARN must not repeat on a fourth consecutive above-warn tick"
3034 );
3035 }
3036
3037 #[test]
3040 fn severity_ladder_rearms_warn_after_drain() {
3041 let config = severity_test_config();
3042 let mut state = CheckpointSeverityState::default();
3043
3044 for _ in 0..3 {
3046 state.observe_wal_pages(150, &config);
3047 }
3048 assert!(state.warn_emitted_for_episode);
3049
3050 let drain = state.observe_wal_pages(10, &config);
3052 assert!(drain.is_empty(), "a draining tick must emit nothing");
3053
3054 let reentry = state.observe_wal_pages(150, &config);
3056 assert_eq!(reentry.len(), 1);
3057 assert_eq!(reentry[0].rung, CheckpointSeverityRung::Info);
3058
3059 let mid = state.observe_wal_pages(150, &config);
3060 assert!(mid.is_empty());
3061
3062 let second_warn = state.observe_wal_pages(150, &config);
3063 assert_eq!(
3064 second_warn,
3065 vec![CheckpointSeverityEmission {
3066 rung: CheckpointSeverityRung::Warn,
3067 wal_pages: 150,
3068 threshold_pages: 100,
3069 consecutive_cycles: 3,
3070 }],
3071 "a fresh elevation episode after a drain must WARN again"
3072 );
3073 }
3074
3075 #[test]
3078 fn severity_ladder_isolated_crossings_never_warn() {
3079 let config = severity_test_config();
3080 let mut state = CheckpointSeverityState::default();
3081
3082 for _ in 0..3 {
3083 let crossing = state.observe_wal_pages(150, &config);
3084 assert_eq!(
3085 crossing.len(),
3086 1,
3087 "each isolated crossing must emit exactly one INFO"
3088 );
3089 assert_eq!(crossing[0].rung, CheckpointSeverityRung::Info);
3090
3091 let drain = state.observe_wal_pages(10, &config);
3092 assert!(drain.is_empty(), "the drain tick must emit nothing");
3093 }
3094
3095 assert!(
3096 !state.warn_emitted_for_episode,
3097 "isolated single-tick crossings must never accumulate into a WARN"
3098 );
3099 }
3100
3101 #[test]
3106 fn severity_ladder_never_emits_alarm() {
3107 let config = CheckpointConfig {
3108 warn_pages: 100,
3109 warn_sustained_cycles: 1,
3110 ..CheckpointConfig::default()
3111 };
3112 let mut state = CheckpointSeverityState::default();
3113
3114 for wal_pages in [150, 200, 250, u64::MAX] {
3115 let emissions = state.observe_wal_pages(wal_pages, &config);
3116 assert!(
3117 emissions
3118 .iter()
3119 .all(|e| e.rung != CheckpointSeverityRung::Alarm),
3120 "observe_wal_pages must never emit the ALARM rung, got: {emissions:?}"
3121 );
3122 }
3123 }
3124
3125 fn tx_age_test_config() -> CheckpointConfig {
3129 CheckpointConfig {
3130 tx_warn_secs: Duration::from_secs(30),
3131 tx_max_age_secs: Duration::from_secs(120),
3132 ..CheckpointConfig::default()
3133 }
3134 }
3135
3136 fn tx_id(n: u64) -> khive_storage::tx_registry::TxId {
3141 khive_storage::tx_registry::TxId(n)
3142 }
3143
3144 #[test]
3146 fn tx_age_sweep_empty_registry_emits_nothing() {
3147 let config = tx_age_test_config();
3148 let mut state = TxAgeSweepState::default();
3149
3150 let emissions = state.observe(None, config.tx_warn_secs, config.tx_max_age_secs);
3151 assert!(emissions.is_empty(), "no open entry must emit nothing");
3152 }
3153
3154 #[test]
3156 fn tx_age_sweep_fresh_entry_emits_nothing() {
3157 let config = tx_age_test_config();
3158 let mut state = TxAgeSweepState::default();
3159
3160 let emissions = state.observe(
3161 Some((
3162 tx_id(1),
3163 Duration::from_secs(5),
3164 Some("fresh_span".to_string()),
3165 )),
3166 config.tx_warn_secs,
3167 config.tx_max_age_secs,
3168 );
3169 assert!(emissions.is_empty(), "a fresh entry must emit nothing");
3170 }
3171
3172 #[test]
3176 fn tx_age_sweep_warn_fires_once_on_crossing() {
3177 let config = tx_age_test_config();
3178 let mut state = TxAgeSweepState::default();
3179
3180 let tick1 = state.observe(
3181 Some((
3182 tx_id(1),
3183 Duration::from_secs(45),
3184 Some("stale_span".to_string()),
3185 )),
3186 config.tx_warn_secs,
3187 config.tx_max_age_secs,
3188 );
3189 assert_eq!(
3190 tick1,
3191 vec![TxAgeEmission {
3192 rung: TxAgeRung::Warn,
3193 age: Duration::from_secs(45),
3194 label: Some("stale_span".to_string()),
3195 }],
3196 "crossing tx_warn_secs must emit exactly one Warn"
3197 );
3198
3199 let tick2 = state.observe(
3200 Some((
3201 tx_id(1),
3202 Duration::from_secs(50),
3203 Some("stale_span".to_string()),
3204 )),
3205 config.tx_warn_secs,
3206 config.tx_max_age_secs,
3207 );
3208 assert!(
3209 tick2.is_empty(),
3210 "Warn must not repeat while the entry stays in the warn band"
3211 );
3212 }
3213
3214 #[test]
3217 fn tx_age_sweep_stale_fires_once_on_crossing() {
3218 let config = tx_age_test_config();
3219 let mut state = TxAgeSweepState::default();
3220
3221 state.observe(
3224 Some((
3225 tx_id(1),
3226 Duration::from_secs(45),
3227 Some("stuck_writer_task_tx".to_string()),
3228 )),
3229 config.tx_warn_secs,
3230 config.tx_max_age_secs,
3231 );
3232
3233 let tick = state.observe(
3234 Some((
3235 tx_id(1),
3236 Duration::from_secs(130),
3237 Some("stuck_writer_task_tx".to_string()),
3238 )),
3239 config.tx_warn_secs,
3240 config.tx_max_age_secs,
3241 );
3242 assert_eq!(
3243 tick,
3244 vec![TxAgeEmission {
3245 rung: TxAgeRung::Stale,
3246 age: Duration::from_secs(130),
3247 label: Some("stuck_writer_task_tx".to_string()),
3248 }],
3249 "crossing tx_max_age_secs must emit exactly one Stale"
3250 );
3251
3252 let tick_repeat = state.observe(
3253 Some((
3254 tx_id(1),
3255 Duration::from_secs(200),
3256 Some("stuck_writer_task_tx".to_string()),
3257 )),
3258 config.tx_warn_secs,
3259 config.tx_max_age_secs,
3260 );
3261 assert!(
3262 tick_repeat.is_empty(),
3263 "Stale must not repeat while the entry stays above tx_max_age_secs"
3264 );
3265 }
3266
3267 #[test]
3271 fn tx_age_sweep_already_stale_entry_emits_both_rungs_same_tick() {
3272 let config = tx_age_test_config();
3273 let mut state = TxAgeSweepState::default();
3274
3275 let tick = state.observe(
3276 Some((
3277 tx_id(1),
3278 Duration::from_secs(300),
3279 Some("ancient_tx".to_string()),
3280 )),
3281 config.tx_warn_secs,
3282 config.tx_max_age_secs,
3283 );
3284 assert_eq!(
3285 tick,
3286 vec![
3287 TxAgeEmission {
3288 rung: TxAgeRung::Warn,
3289 age: Duration::from_secs(300),
3290 label: Some("ancient_tx".to_string()),
3291 },
3292 TxAgeEmission {
3293 rung: TxAgeRung::Stale,
3294 age: Duration::from_secs(300),
3295 label: Some("ancient_tx".to_string()),
3296 },
3297 ],
3298 "an already-stale entry must cross both rungs on its first observed tick"
3299 );
3300 }
3301
3302 #[test]
3305 fn tx_age_sweep_rearms_after_entry_clears() {
3306 let config = tx_age_test_config();
3307 let mut state = TxAgeSweepState::default();
3308
3309 state.observe(
3310 Some((
3311 tx_id(1),
3312 Duration::from_secs(150),
3313 Some("first_span".to_string()),
3314 )),
3315 config.tx_warn_secs,
3316 config.tx_max_age_secs,
3317 );
3318
3319 let cleared = state.observe(None, config.tx_warn_secs, config.tx_max_age_secs);
3321 assert!(cleared.is_empty(), "a clearing tick must emit nothing");
3322
3323 let fresh = state.observe(
3325 Some((
3326 tx_id(2),
3327 Duration::from_secs(2),
3328 Some("second_span".to_string()),
3329 )),
3330 config.tx_warn_secs,
3331 config.tx_max_age_secs,
3332 );
3333 assert!(fresh.is_empty(), "a fresh oldest entry must emit nothing");
3334
3335 let rewarn = state.observe(
3337 Some((
3338 tx_id(2),
3339 Duration::from_secs(35),
3340 Some("second_span".to_string()),
3341 )),
3342 config.tx_warn_secs,
3343 config.tx_max_age_secs,
3344 );
3345 assert_eq!(
3346 rewarn,
3347 vec![TxAgeEmission {
3348 rung: TxAgeRung::Warn,
3349 age: Duration::from_secs(35),
3350 label: Some("second_span".to_string()),
3351 }],
3352 "a fresh stale episode after a clear must Warn again"
3353 );
3354 }
3355
3356 #[test]
3360 fn tx_age_sweep_stale_replacement_without_intervening_clear_still_names_new_entry() {
3361 let config = tx_age_test_config();
3362 let mut state = TxAgeSweepState::default();
3363
3364 let tick_a = state.observe(
3365 Some((
3366 tx_id(1),
3367 Duration::from_secs(300),
3368 Some("stale_entry_a".to_string()),
3369 )),
3370 config.tx_warn_secs,
3371 config.tx_max_age_secs,
3372 );
3373 assert_eq!(
3374 tick_a.len(),
3375 2,
3376 "entry A must cross both rungs on its first observed tick, got: {tick_a:?}"
3377 );
3378
3379 let tick_b = state.observe(
3382 Some((
3383 tx_id(2),
3384 Duration::from_secs(400),
3385 Some("stale_entry_b".to_string()),
3386 )),
3387 config.tx_warn_secs,
3388 config.tx_max_age_secs,
3389 );
3390 assert_eq!(
3391 tick_b,
3392 vec![
3393 TxAgeEmission {
3394 rung: TxAgeRung::Warn,
3395 age: Duration::from_secs(400),
3396 label: Some("stale_entry_b".to_string()),
3397 },
3398 TxAgeEmission {
3399 rung: TxAgeRung::Stale,
3400 age: Duration::from_secs(400),
3401 label: Some("stale_entry_b".to_string()),
3402 },
3403 ],
3404 "a same-tick identity change to an already-stale successor must re-emit both \
3405 rungs naming the NEW entry, got: {tick_b:?}"
3406 );
3407 }
3408
3409 #[test]
3412 fn tx_age_sweep_uses_configured_thresholds_not_hardcoded_defaults() {
3413 let config = CheckpointConfig {
3414 tx_warn_secs: Duration::from_millis(1),
3415 tx_max_age_secs: Duration::from_millis(2),
3416 ..CheckpointConfig::default()
3417 };
3418 let mut state = TxAgeSweepState::default();
3419
3420 let tick = state.observe(
3421 Some((
3422 tx_id(1),
3423 Duration::from_millis(5),
3424 Some("fast_cap_span".to_string()),
3425 )),
3426 config.tx_warn_secs,
3427 config.tx_max_age_secs,
3428 );
3429 assert_eq!(
3430 tick.len(),
3431 2,
3432 "a millisecond-scale cap must cross both rungs immediately, got: {tick:?}"
3433 );
3434 }
3435
3436 #[test]
3439 #[serial(tx_registry, checkpoint_skip_metrics)]
3440 fn tx_age_sweep_names_long_lived_reader_pinning_wal_past_high_water() {
3441 let dir = tempfile::tempdir().unwrap();
3442 let path = dir.path().join("tx_age_sweep_reader_pin.db");
3443 let pool = file_pool(&path);
3444
3445 {
3446 let writer = pool.try_writer().unwrap();
3447 writer
3448 .conn()
3449 .execute_batch(
3450 "CREATE TABLE IF NOT EXISTS t (x INTEGER); INSERT INTO t VALUES (1);",
3451 )
3452 .unwrap();
3453 }
3454
3455 let reader = pool.reader().expect("reader");
3460 reader
3461 .execute_batch("BEGIN DEFERRED; SELECT * FROM t;")
3462 .expect("begin read tx");
3463 let _tx_handle =
3464 khive_storage::tx_registry::register(Some("tx_age_sweep_reader_pin_test".to_string()));
3465
3466 let config = CheckpointConfig {
3469 high_water_pages: 1,
3470 tx_warn_secs: Duration::from_millis(1),
3471 tx_max_age_secs: Duration::from_millis(1),
3472 ..CheckpointConfig::default()
3473 };
3474 {
3475 let writer = pool.try_writer().unwrap();
3476 for i in 0..50 {
3477 writer
3478 .conn()
3479 .execute_batch(&format!("INSERT INTO t VALUES ({i});"))
3480 .unwrap();
3481 }
3482 }
3483
3484 let tick = checkpoint_once(&pool, &config, &mut TruncateState::default());
3485 let wal_pages = match tick {
3486 CheckpointTick::Observed(n) => n,
3487 CheckpointTick::Skipped => panic!("writer must not be busy in this test"),
3488 };
3489 assert!(
3490 wal_pages >= config.high_water_pages,
3491 "test setup must actually drive wal_pages ({wal_pages}) past high_water_pages \
3492 ({}) for this regression to mean anything",
3493 config.high_water_pages
3494 );
3495
3496 std::thread::sleep(Duration::from_millis(5));
3503 let our_entry = khive_storage::tx_registry::snapshot()
3514 .into_iter()
3515 .find(|(_, label)| label.as_deref() == Some("tx_age_sweep_reader_pin_test"))
3516 .expect("this test's own tx_registry entry must still be open");
3517 let mut tx_age_state = TxAgeSweepState::default();
3518 let emissions = tx_age_state.observe(
3519 Some((tx_id(1), our_entry.0, our_entry.1)),
3520 config.tx_warn_secs,
3521 config.tx_max_age_secs,
3522 );
3523 assert!(
3524 emissions.iter().any(|e| e.rung == TxAgeRung::Stale
3525 && e.label.as_deref() == Some("tx_age_sweep_reader_pin_test")),
3526 "expected a Stale emission naming the pinning reader, got: {emissions:?}"
3527 );
3528
3529 reader.execute_batch("COMMIT;").ok();
3530 drop(reader);
3531 drop(_tx_handle);
3532 }
3533
3534 #[test]
3537 #[serial(tx_registry, checkpoint_skip_metrics)]
3538 fn tx_age_sweep_own_entry_survives_concurrent_older_registration() {
3539 let _decoy = khive_storage::tx_registry::register(Some("decoy_unrelated_span".to_string()));
3540 std::thread::sleep(Duration::from_millis(2));
3541 let _own = khive_storage::tx_registry::register(Some("this_test_own_span".to_string()));
3542 std::thread::sleep(Duration::from_millis(5));
3543
3544 let global_oldest = khive_storage::tx_registry::oldest().expect("registry not empty");
3550 assert_ne!(
3551 global_oldest.2.as_deref(),
3552 Some("this_test_own_span"),
3553 "test setup must reproduce the race: an older, unrelated entry must be \
3554 the current global oldest, got: {global_oldest:?}"
3555 );
3556
3557 let our_entry = khive_storage::tx_registry::snapshot()
3558 .into_iter()
3559 .find(|(_, label)| label.as_deref() == Some("this_test_own_span"))
3560 .expect("this test's own tx_registry entry must still be open");
3561
3562 let config = CheckpointConfig {
3563 tx_warn_secs: Duration::from_millis(1),
3564 tx_max_age_secs: Duration::from_millis(1),
3565 ..CheckpointConfig::default()
3566 };
3567 let mut state = TxAgeSweepState::default();
3568 let emissions = state.observe(
3569 Some((tx_id(2), our_entry.0, our_entry.1)),
3570 config.tx_warn_secs,
3571 config.tx_max_age_secs,
3572 );
3573 assert!(
3574 emissions
3575 .iter()
3576 .any(|e| e.rung == TxAgeRung::Stale
3577 && e.label.as_deref() == Some("this_test_own_span")),
3578 "expected a Stale emission naming this test's own span despite an older, \
3579 unrelated concurrent registration, got: {emissions:?}"
3580 );
3581 }
3582
3583 #[test]
3585 #[serial]
3586 fn checkpoint_config_warn_sustained_cycles_env_override() {
3587 let default = CheckpointConfig::default();
3588 assert_eq!(default.warn_sustained_cycles, DEFAULT_WARN_SUSTAINED_CYCLES);
3589
3590 std::env::set_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES", "5");
3591 let cfg = CheckpointConfig::from_env();
3592 std::env::remove_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES");
3593 assert_eq!(cfg.warn_sustained_cycles, 5);
3594
3595 std::env::set_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES", "0");
3596 let cfg_zero = CheckpointConfig::from_env();
3597 std::env::remove_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES");
3598 assert_eq!(
3599 cfg_zero.warn_sustained_cycles, DEFAULT_WARN_SUSTAINED_CYCLES,
3600 "zero must fall back to the default"
3601 );
3602
3603 std::env::set_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES", "not_a_number");
3604 let cfg_invalid = CheckpointConfig::from_env();
3605 std::env::remove_var("KHIVE_WAL_WARN_SUSTAINED_CYCLES");
3606 assert_eq!(
3607 cfg_invalid.warn_sustained_cycles,
3608 DEFAULT_WARN_SUSTAINED_CYCLES
3609 );
3610 }
3611
3612 #[derive(Default)]
3615 struct FakeEventStore {
3616 events: std::sync::Mutex<Vec<khive_storage::Event>>,
3617 }
3618
3619 #[async_trait::async_trait]
3620 impl khive_storage::EventStore for FakeEventStore {
3621 async fn append_event(
3622 &self,
3623 event: khive_storage::Event,
3624 ) -> khive_storage::StorageResult<()> {
3625 self.events.lock().unwrap().push(event);
3626 Ok(())
3627 }
3628
3629 async fn append_events(
3630 &self,
3631 events: Vec<khive_storage::Event>,
3632 ) -> khive_storage::StorageResult<khive_storage::BatchWriteSummary> {
3633 let count = events.len() as u64;
3634 self.events.lock().unwrap().extend(events);
3635 Ok(khive_storage::BatchWriteSummary {
3636 attempted: count,
3637 affected: count,
3638 failed: 0,
3639 first_error: String::new(),
3640 })
3641 }
3642
3643 async fn get_event(
3644 &self,
3645 id: uuid::Uuid,
3646 ) -> khive_storage::StorageResult<Option<khive_storage::Event>> {
3647 Ok(self
3648 .events
3649 .lock()
3650 .unwrap()
3651 .iter()
3652 .find(|e| e.id == id)
3653 .cloned())
3654 }
3655
3656 async fn query_events(
3657 &self,
3658 _filter: khive_storage::EventFilter,
3659 _page: khive_storage::PageRequest,
3660 ) -> khive_storage::StorageResult<khive_storage::Page<khive_storage::Event>> {
3661 unimplemented!("not exercised by the checkpoint lifecycle-event tests")
3662 }
3663
3664 async fn count_events(
3665 &self,
3666 _filter: khive_storage::EventFilter,
3667 ) -> khive_storage::StorageResult<u64> {
3668 Ok(self.events.lock().unwrap().len() as u64)
3669 }
3670 }
3671
3672 #[test]
3677 fn checkpoint_outcome_should_emit_covers_all_transitions() {
3678 assert!(
3679 checkpoint_outcome_should_emit(true, false),
3680 "first elevated tick must emit"
3681 );
3682 assert!(
3683 checkpoint_outcome_should_emit(true, true),
3684 "sustained elevated tick must emit"
3685 );
3686 assert!(
3687 checkpoint_outcome_should_emit(false, true),
3688 "the single drain row (elevated -> healthy) must emit"
3689 );
3690 assert!(
3691 !checkpoint_outcome_should_emit(false, false),
3692 "an ordinary below-warn tick must not emit"
3693 );
3694 }
3695
3696 #[tokio::test]
3697 #[serial(checkpoint_skip_metrics)]
3698 async fn checkpoint_task_emits_outcome_events_while_elevated_and_stops_after_drain() {
3699 let dir = tempfile::tempdir().unwrap();
3700 let path = dir.path().join("outcome_emit.db");
3701 let pool = file_pool(&path);
3702
3703 let cfg = CheckpointConfig {
3706 interval: Duration::from_millis(10),
3707 warn_pages: 0,
3708 ..CheckpointConfig::default()
3709 };
3710 let store = Arc::new(FakeEventStore::default());
3711 let store_dyn: Arc<dyn khive_storage::EventStore> = store.clone();
3712
3713 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
3714 let handle = tokio::spawn(run_checkpoint_task(
3715 pool,
3716 cfg,
3717 Some(store_dyn),
3718 "local".to_string(),
3719 shutdown_rx,
3720 true,
3721 ));
3722
3723 tokio::time::sleep(Duration::from_millis(60)).await;
3724 shutdown_tx.send(()).expect("send shutdown signal");
3725 tokio::time::timeout(Duration::from_secs(1), handle)
3726 .await
3727 .expect("checkpoint task should exit within 1s")
3728 .expect("checkpoint task panicked");
3729
3730 let events = store.events.lock().unwrap();
3731 assert!(
3732 !events.is_empty(),
3733 "an always-elevated config must append at least one CheckpointOutcomeRecorded event"
3734 );
3735 assert!(
3736 events
3737 .iter()
3738 .all(|e| e.kind == khive_types::EventKind::CheckpointOutcomeRecorded),
3739 "every appended event must be CheckpointOutcomeRecorded, got: {events:?}"
3740 );
3741 assert!(
3742 events.iter().all(|e| e.namespace == "local"),
3743 "events must be stamped with the namespace passed to run_checkpoint_task"
3744 );
3745 }
3746
3747 #[tokio::test]
3748 #[serial(checkpoint_skip_metrics)]
3749 async fn checkpoint_task_emits_nothing_while_healthy() {
3750 let dir = tempfile::tempdir().unwrap();
3751 let path = dir.path().join("outcome_no_emit.db");
3752 let pool = file_pool(&path);
3753
3754 let cfg = CheckpointConfig {
3757 interval: Duration::from_millis(10),
3758 warn_pages: u64::MAX,
3759 ..CheckpointConfig::default()
3760 };
3761 let store = Arc::new(FakeEventStore::default());
3762 let store_dyn: Arc<dyn khive_storage::EventStore> = store.clone();
3763
3764 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
3765 let handle = tokio::spawn(run_checkpoint_task(
3766 pool,
3767 cfg,
3768 Some(store_dyn),
3769 "local".to_string(),
3770 shutdown_rx,
3771 true,
3772 ));
3773
3774 tokio::time::sleep(Duration::from_millis(60)).await;
3775 shutdown_tx.send(()).expect("send shutdown signal");
3776 tokio::time::timeout(Duration::from_secs(1), handle)
3777 .await
3778 .expect("checkpoint task should exit within 1s")
3779 .expect("checkpoint task panicked");
3780
3781 assert!(
3782 store.events.lock().unwrap().is_empty(),
3783 "a config that never crosses warn_pages must never append a lifecycle event"
3784 );
3785 }
3786
3787 #[tokio::test]
3788 #[serial(checkpoint_skip_metrics)]
3789 async fn checkpoint_task_with_no_event_store_does_not_panic() {
3790 let dir = tempfile::tempdir().unwrap();
3791 let path = dir.path().join("outcome_none_store.db");
3792 let pool = file_pool(&path);
3793
3794 let cfg = CheckpointConfig {
3795 interval: Duration::from_millis(10),
3796 warn_pages: 0,
3797 ..CheckpointConfig::default()
3798 };
3799
3800 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
3801 let handle = tokio::spawn(run_checkpoint_task(
3802 pool,
3803 cfg,
3804 None,
3805 "local".to_string(),
3806 shutdown_rx,
3807 true,
3808 ));
3809
3810 tokio::time::sleep(Duration::from_millis(40)).await;
3811 shutdown_tx.send(()).expect("send shutdown signal");
3812 tokio::time::timeout(Duration::from_secs(1), handle)
3813 .await
3814 .expect("checkpoint task should exit within 1s")
3815 .expect("checkpoint task panicked");
3816 }
3817
3818 #[tokio::test]
3835 #[serial(tx_registry, checkpoint_skip_metrics)]
3836 async fn checkpoint_task_sweeps_stale_registry_entry_while_wal_is_healthy() {
3837 let dir = tempfile::tempdir().unwrap();
3838 let path = dir.path().join("tx_age_sweep_task_healthy_wal.db");
3839 let pool = file_pool(&path);
3840
3841 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
3842 let subscriber = CaptureSubscriber {
3843 events: std::sync::Arc::clone(&buffer),
3844 };
3845 let _tracing_guard = tracing::subscriber::set_default(subscriber);
3846
3847 let _tx_handle = khive_storage::tx_registry::register(Some(
3848 "checkpoint_task_healthy_wal_sweep_test".to_string(),
3849 ));
3850
3851 let cfg = CheckpointConfig {
3852 interval: Duration::from_millis(10),
3853 warn_pages: u64::MAX,
3854 high_water_pages: u64::MAX,
3855 truncate_high_water_pages: u64::MAX,
3856 tx_warn_secs: Duration::from_millis(1),
3857 tx_max_age_secs: Duration::from_millis(1),
3858 ..CheckpointConfig::default()
3859 };
3860
3861 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
3862 let handle = tokio::spawn(run_checkpoint_task(
3863 pool,
3864 cfg,
3865 None,
3866 "local".to_string(),
3867 shutdown_rx,
3868 true,
3869 ));
3870
3871 tokio::time::sleep(Duration::from_millis(60)).await;
3872 shutdown_tx.send(()).expect("send shutdown signal");
3873 tokio::time::timeout(Duration::from_secs(1), handle)
3874 .await
3875 .expect("checkpoint task should exit within 1s")
3876 .expect("checkpoint task panicked");
3877
3878 drop(_tx_handle);
3879
3880 let events = buffer.lock().unwrap();
3881 assert!(
3882 events.iter().any(|e| {
3883 e.tx_label.as_deref() == Some("checkpoint_task_healthy_wal_sweep_test")
3884 && e.message
3885 .as_deref()
3886 .is_some_and(|m| m.contains("stale-op cap"))
3887 }),
3888 "expected the spawned task to sweep and escalate the stale registry entry \
3889 to Stale on its own, got: {events:?}"
3890 );
3891 }
3892
3893 #[tokio::test]
3897 #[serial(tx_registry, checkpoint_skip_metrics)]
3898 async fn checkpoint_task_emits_no_age_alert_for_an_empty_registry() {
3899 let dir = tempfile::tempdir().unwrap();
3900 let path = dir.path().join("tx_age_sweep_task_empty_registry.db");
3901 let pool = file_pool(&path);
3902
3903 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
3904 let subscriber = CaptureSubscriber {
3905 events: std::sync::Arc::clone(&buffer),
3906 };
3907 let _tracing_guard = tracing::subscriber::set_default(subscriber);
3908
3909 let cfg = CheckpointConfig {
3910 interval: Duration::from_millis(10),
3911 tx_warn_secs: Duration::from_millis(1),
3912 tx_max_age_secs: Duration::from_millis(1),
3913 ..CheckpointConfig::default()
3914 };
3915
3916 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
3917 let handle = tokio::spawn(run_checkpoint_task(
3918 pool,
3919 cfg,
3920 None,
3921 "local".to_string(),
3922 shutdown_rx,
3923 true,
3924 ));
3925
3926 tokio::time::sleep(Duration::from_millis(40)).await;
3927 shutdown_tx.send(()).expect("send shutdown signal");
3928 tokio::time::timeout(Duration::from_secs(1), handle)
3929 .await
3930 .expect("checkpoint task should exit within 1s")
3931 .expect("checkpoint task panicked");
3932
3933 let events = buffer.lock().unwrap();
3934 assert!(
3935 events.iter().all(|e| e
3936 .message
3937 .as_deref()
3938 .is_none_or(|m| !m.contains("ADR-091 Plank 1"))),
3939 "an empty registry must never produce a Plank 1 age emission, got: {events:?}"
3940 );
3941 }
3942
3943 #[tokio::test]
3951 #[serial(tx_registry, checkpoint_skip_metrics)]
3952 async fn checkpoint_task_sweeps_stale_entry_even_when_writer_is_busy_every_tick() {
3953 reset_checkpoint_metrics_for_tests();
3954
3955 let dir = tempfile::tempdir().unwrap();
3956 let path = dir.path().join("tx_age_sweep_task_writer_busy.db");
3957 let pool = file_pool(&path);
3958 {
3959 let writer = pool.try_writer().unwrap();
3960 writer
3961 .conn()
3962 .execute_batch("CREATE TABLE IF NOT EXISTS t (x INTEGER);")
3963 .unwrap();
3964 }
3965
3966 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
3967 let subscriber = CaptureSubscriber {
3968 events: std::sync::Arc::clone(&buffer),
3969 };
3970 let _tracing_guard = tracing::subscriber::set_default(subscriber);
3971
3972 let _tx_handle = khive_storage::tx_registry::register(Some(
3973 "checkpoint_task_writer_busy_sweep_test".to_string(),
3974 ));
3975
3976 let _writer_guard = pool.try_writer().expect("acquire writer for busy hold");
3980
3981 let cfg = CheckpointConfig {
3982 interval: Duration::from_millis(10),
3983 tx_warn_secs: Duration::from_millis(1),
3984 tx_max_age_secs: Duration::from_millis(1),
3985 ..CheckpointConfig::default()
3986 };
3987
3988 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
3989 let handle = tokio::spawn(run_checkpoint_task(
3990 Arc::clone(&pool),
3991 cfg,
3992 None,
3993 "local".to_string(),
3994 shutdown_rx,
3995 true,
3996 ));
3997
3998 tokio::time::sleep(Duration::from_millis(60)).await;
4000
4001 assert!(
4002 checkpoint_skipped_ticks() > 0,
4003 "test setup must actually drive at least one Skipped tick for this \
4004 regression to mean anything"
4005 );
4006
4007 shutdown_tx.send(()).expect("send shutdown signal");
4008 tokio::time::timeout(Duration::from_secs(1), handle)
4009 .await
4010 .expect("checkpoint task should exit within 1s")
4011 .expect("checkpoint task panicked");
4012
4013 drop(_writer_guard);
4014 drop(_tx_handle);
4015
4016 let events = buffer.lock().unwrap();
4017 assert!(
4018 events.iter().any(|e| {
4019 e.tx_label.as_deref() == Some("checkpoint_task_writer_busy_sweep_test")
4020 && e.message
4021 .as_deref()
4022 .is_some_and(|m| m.contains("stale-op cap"))
4023 }),
4024 "expected the age sweep to fire even though every tick's writer checkout \
4025 was skipped, got: {events:?}"
4026 );
4027 }
4028
4029 #[tokio::test]
4033 async fn session_sweep_task_exits_on_shutdown_signal() {
4034 let cfg = SessionSweepConfig {
4035 interval: Duration::from_millis(10),
4036 ..SessionSweepConfig::default()
4037 };
4038 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
4039 let handle = tokio::spawn(run_session_sweep_task(Vec::new(), cfg, shutdown_rx));
4040
4041 shutdown_tx.send(()).expect("send shutdown signal");
4042
4043 tokio::time::timeout(Duration::from_secs(1), handle)
4044 .await
4045 .expect("session sweep task should exit within 1s")
4046 .expect("session sweep task panicked");
4047 }
4048
4049 async fn wait_for(deadline: Duration, mut cond: impl FnMut() -> bool) -> bool {
4053 let start = std::time::Instant::now();
4054 while start.elapsed() < deadline {
4055 if cond() {
4056 return true;
4057 }
4058 tokio::time::sleep(Duration::from_millis(5)).await;
4059 }
4060 cond()
4061 }
4062
4063 #[tokio::test]
4064 #[serial(khive_walpin_sidecar_env)]
4065 async fn walpin_observe_drops_beacon_when_heartbeat_write_fails() {
4066 let dir = tempfile::tempdir().unwrap();
4067 let db_path = dir.path().join("observe_gate.db");
4068 let sidecar_dir = crate::walpin::sidecar_dir_for(&db_path);
4069 let _env_guard = crate::walpin::EnvVarGuard::capture("KHIVE_WALPIN_SIDECAR");
4070 std::env::set_var("KHIVE_WALPIN_SIDECAR", "1");
4071
4072 let mut state = WalpinSidecarState::new(
4073 Some(db_path.as_path()),
4074 true,
4075 "session",
4076 Duration::from_millis(500),
4077 )
4078 .expect("sidecar enabled for a file-backed path");
4079 state.register_beacon().await;
4080 let pid = std::process::id();
4081 let beacon_path = sidecar_dir.join(format!("{pid}.beacon"));
4082 let before = std::fs::metadata(&beacon_path)
4083 .expect("beacon registered")
4084 .modified()
4085 .unwrap();
4086
4087 let obstruction = sidecar_dir.join(format!(".{pid}.json.tmp"));
4092 std::fs::create_dir(&obstruction).unwrap();
4093
4094 tokio::time::sleep(Duration::from_millis(20)).await;
4095 let over_threshold = Some(khive_storage::tx_registry::OldestSpan {
4096 id: khive_storage::tx_registry::TxId(1),
4097 age: Duration::from_secs(60),
4098 label: None,
4099 origin: khive_storage::tx_registry::TxOrigin::Unscoped,
4100 });
4101 state
4102 .observe(over_threshold.clone(), Duration::from_secs(30))
4103 .await;
4104
4105 assert!(
4106 !sidecar_dir.join(format!("{pid}.json")).exists(),
4107 "heartbeat write must have failed"
4108 );
4109 assert!(
4112 !beacon_path.exists(),
4113 "a failed heartbeat write must remove the beacon — a still-fresh \
4114 beacon with no heartbeat would classify registered-silent \
4115 (before-mtime {before:?})"
4116 );
4117
4118 std::fs::remove_dir(&obstruction).unwrap();
4121 state.observe(over_threshold, Duration::from_secs(30)).await;
4122 assert!(
4123 sidecar_dir.join(format!("{pid}.json")).exists(),
4124 "heartbeat must land once the write path recovers"
4125 );
4126 assert!(
4127 beacon_path.exists(),
4128 "beacon must re-register on the first healthy tick after removal"
4129 );
4130 }
4131
4132 #[tokio::test]
4133 #[serial(khive_walpin_sidecar_env)]
4134 async fn walpin_observe_touches_mtime_without_rewriting_body_when_content_unchanged() {
4135 let dir = tempfile::tempdir().unwrap();
4136 let db_path = dir.path().join("observe_touch.db");
4137 let sidecar_dir = crate::walpin::sidecar_dir_for(&db_path);
4138 let _env_guard = crate::walpin::EnvVarGuard::capture("KHIVE_WALPIN_SIDECAR");
4139 std::env::set_var("KHIVE_WALPIN_SIDECAR", "1");
4140
4141 let mut state = WalpinSidecarState::new(
4142 Some(db_path.as_path()),
4143 true,
4144 "session",
4145 Duration::from_millis(500),
4146 )
4147 .expect("sidecar enabled for a file-backed path");
4148 let pid = std::process::id();
4149 let heartbeat_path = sidecar_dir.join(format!("{pid}.json"));
4150 let span = khive_storage::tx_registry::OldestSpan {
4151 id: khive_storage::tx_registry::TxId(1),
4152 age: Duration::from_secs(60),
4153 label: None,
4154 origin: khive_storage::tx_registry::TxOrigin::Unscoped,
4155 };
4156
4157 state
4158 .observe(Some(span.clone()), Duration::from_secs(30))
4159 .await;
4160 let body_after_create = std::fs::read(&heartbeat_path).expect("heartbeat written");
4161
4162 let backdated = std::time::SystemTime::now() - Duration::from_secs(120);
4168 std::fs::File::open(&heartbeat_path)
4169 .unwrap()
4170 .set_modified(backdated)
4171 .unwrap();
4172
4173 state.observe(Some(span), Duration::from_secs(30)).await;
4174
4175 let body_after_second_observe =
4176 std::fs::read(&heartbeat_path).expect("heartbeat still present");
4177 assert_eq!(
4178 body_after_create, body_after_second_observe,
4179 "unchanged oldest-span identity/label/attribution/cadence must touch mtime, \
4180 not rewrite the body"
4181 );
4182 let mtime_after = std::fs::metadata(&heartbeat_path)
4183 .unwrap()
4184 .modified()
4185 .unwrap();
4186 assert!(
4187 mtime_after > backdated,
4188 "the touch must advance mtime past the backdated value"
4189 );
4190 }
4191
4192 #[tokio::test]
4193 #[serial(khive_walpin_sidecar_env)]
4194 async fn walpin_observe_recreates_heartbeat_after_it_is_deleted_while_span_still_live() {
4195 let dir = tempfile::tempdir().unwrap();
4196 let db_path = dir.path().join("observe_recreate.db");
4197 let sidecar_dir = crate::walpin::sidecar_dir_for(&db_path);
4198 let _env_guard = crate::walpin::EnvVarGuard::capture("KHIVE_WALPIN_SIDECAR");
4199 std::env::set_var("KHIVE_WALPIN_SIDECAR", "1");
4200
4201 let mut state = WalpinSidecarState::new(
4202 Some(db_path.as_path()),
4203 true,
4204 "session",
4205 Duration::from_millis(500),
4206 )
4207 .expect("sidecar enabled for a file-backed path");
4208 let pid = std::process::id();
4209 let heartbeat_path = sidecar_dir.join(format!("{pid}.json"));
4210 let span = khive_storage::tx_registry::OldestSpan {
4211 id: khive_storage::tx_registry::TxId(1),
4212 age: Duration::from_secs(60),
4213 label: None,
4214 origin: khive_storage::tx_registry::TxOrigin::Unscoped,
4215 };
4216
4217 state
4218 .observe(Some(span.clone()), Duration::from_secs(30))
4219 .await;
4220 assert!(heartbeat_path.exists(), "heartbeat written on first tick");
4221
4222 std::fs::remove_file(&heartbeat_path).unwrap();
4228 assert!(!heartbeat_path.exists());
4229
4230 state.observe(Some(span), Duration::from_secs(30)).await;
4231
4232 assert!(
4233 heartbeat_path.exists(),
4234 "a touch failure against a deleted heartbeat must recreate it via a full write"
4235 );
4236 let recreated: crate::walpin::WalpinHeartbeat =
4237 serde_json::from_slice(&std::fs::read(&heartbeat_path).unwrap()).unwrap();
4238 assert_eq!(recreated.pid, pid);
4239 assert_eq!(recreated.oldest_tx_age_secs, 60.0);
4240 }
4241
4242 #[tokio::test]
4243 #[serial(tx_registry, khive_walpin_sidecar_env)]
4244 async fn session_sweep_task_writes_and_clears_walpin_heartbeat() {
4245 let dir = tempfile::tempdir().unwrap();
4246 let db_path = dir.path().join("session_sweep.db");
4247 let pool = file_pool(&db_path);
4248 let sidecar_dir =
4249 crate::walpin::sidecar_dir_for(pool.canonical_path().expect("file-backed pool"));
4250 let _env_guard = crate::walpin::EnvVarGuard::capture("KHIVE_WALPIN_SIDECAR");
4251 std::env::set_var("KHIVE_WALPIN_SIDECAR", "1");
4252
4253 let cfg = SessionSweepConfig {
4254 interval: Duration::from_millis(10),
4255 tx_warn_secs: Duration::from_millis(20),
4256 tx_max_age_secs: Duration::from_millis(500),
4257 };
4258 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
4259 let handle = tokio::spawn(run_session_sweep_task(
4260 vec![SweepBackend {
4261 pool: Arc::clone(&pool),
4262 is_main: true,
4263 }],
4264 cfg,
4265 shutdown_rx,
4266 ));
4267
4268 let pid = std::process::id();
4275 let beacon = crate::walpin::beacon_path(&sidecar_dir, pid);
4276 assert!(
4277 wait_for(Duration::from_secs(2), || beacon.exists()).await,
4278 "a quiet process must still register its one-time beacon"
4279 );
4280 assert!(
4281 !sidecar_dir.join(format!("{pid}.json")).exists(),
4282 "a quiet process must not write a walpin heartbeat"
4283 );
4284
4285 let tx_handle =
4286 khive_storage::tx_registry::register(Some("session_sweep_walpin_test".to_string()));
4287 let heartbeat_path = sidecar_dir.join(format!("{pid}.json"));
4288 assert!(
4289 wait_for(Duration::from_secs(2), || heartbeat_path.exists()).await,
4290 "expected a walpin heartbeat once the span crossed tx_warn_secs"
4291 );
4292 let body = std::fs::read_to_string(&heartbeat_path).unwrap();
4293 let hb: crate::walpin::WalpinHeartbeat = serde_json::from_str(&body).unwrap();
4294 assert_eq!(hb.pid, pid);
4295 assert_eq!(hb.process_role, "session");
4296 assert_eq!(
4297 hb.oldest_tx_label.as_deref(),
4298 Some("session_sweep_walpin_test")
4299 );
4300 assert_eq!(
4301 hb.attribution_basis.as_deref(),
4302 Some("fallback"),
4303 "an Unscoped span observed only through the main view's fallback \
4304 must carry attribution_basis=\"fallback\", never \"origin\""
4305 );
4306
4307 drop(tx_handle);
4308 assert!(
4309 wait_for(Duration::from_secs(2), || !heartbeat_path.exists()).await,
4310 "heartbeat must be removed once the stale span clears"
4311 );
4312
4313 shutdown_tx.send(()).expect("send shutdown signal");
4314 tokio::time::timeout(Duration::from_secs(1), handle)
4315 .await
4316 .expect("session sweep task should exit within 1s")
4317 .expect("session sweep task panicked");
4318 }
4319
4320 #[tokio::test]
4331 #[serial(tx_registry, khive_walpin_sidecar_env)]
4332 async fn session_sweep_fan_out_scopes_secondary_span_to_secondary_sidecar_only() {
4333 let main_dir = tempfile::tempdir().unwrap();
4334 let secondary_dir = tempfile::tempdir().unwrap();
4335 let main_pool = file_pool(&main_dir.path().join("main.db"));
4336 let secondary_pool = file_pool(&secondary_dir.path().join("secondary.db"));
4337 let main_sidecar =
4338 crate::walpin::sidecar_dir_for(main_pool.canonical_path().expect("file-backed"));
4339 let secondary_sidecar =
4340 crate::walpin::sidecar_dir_for(secondary_pool.canonical_path().expect("file-backed"));
4341 let _env_guard = crate::walpin::EnvVarGuard::capture("KHIVE_WALPIN_SIDECAR");
4342 std::env::set_var("KHIVE_WALPIN_SIDECAR", "1");
4343
4344 let cfg = SessionSweepConfig {
4345 interval: Duration::from_millis(10),
4346 tx_warn_secs: Duration::from_millis(20),
4347 tx_max_age_secs: Duration::from_millis(500),
4348 };
4349 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
4350 let handle = tokio::spawn(run_session_sweep_task(
4351 vec![
4352 SweepBackend {
4353 pool: Arc::clone(&main_pool),
4354 is_main: true,
4355 },
4356 SweepBackend {
4357 pool: Arc::clone(&secondary_pool),
4358 is_main: false,
4359 },
4360 ],
4361 cfg,
4362 shutdown_rx,
4363 ));
4364
4365 let pid = std::process::id();
4366 let secondary_heartbeat = secondary_sidecar.join(format!("{pid}.json"));
4367 let main_heartbeat = main_sidecar.join(format!("{pid}.json"));
4368
4369 let tx_handle = khive_storage::tx_registry::register_scoped(
4370 Some("graph_traverse_read".to_string()),
4371 secondary_pool.origin(),
4372 );
4373 assert!(
4374 wait_for(Duration::from_secs(2), || secondary_heartbeat.exists()).await,
4375 "expected a walpin heartbeat in the secondary backend's own sidecar"
4376 );
4377 assert!(
4378 !main_heartbeat.exists(),
4379 "a span scoped to the secondary backend's origin must never produce \
4380 a heartbeat in the main backend's sidecar"
4381 );
4382
4383 let body = std::fs::read_to_string(&secondary_heartbeat).unwrap();
4384 let hb: crate::walpin::WalpinHeartbeat = serde_json::from_str(&body).unwrap();
4385 assert_eq!(hb.oldest_tx_label.as_deref(), Some("graph_traverse_read"));
4386 assert_eq!(
4387 hb.attribution_basis.as_deref(),
4388 Some("origin"),
4389 "a Secondary-view winner is always Database-origin-backed — never fallback"
4390 );
4391
4392 drop(tx_handle);
4393 assert!(
4394 wait_for(Duration::from_secs(2), || !secondary_heartbeat.exists()).await,
4395 "secondary heartbeat must be removed once its span clears"
4396 );
4397 assert!(
4398 !main_heartbeat.exists(),
4399 "the main sidecar must have stayed untouched for the whole tick sequence"
4400 );
4401
4402 shutdown_tx.send(()).expect("send shutdown signal");
4403 tokio::time::timeout(Duration::from_secs(1), handle)
4404 .await
4405 .expect("session sweep task should exit within 1s")
4406 .expect("session sweep task panicked");
4407 }
4408
4409 #[tokio::test]
4418 #[serial(tx_registry, checkpoint_skip_metrics, khive_walpin_sidecar_env)]
4419 async fn checkpoint_task_ignores_span_registered_against_other_backend_origin_and_unscoped() {
4420 let dir_a = tempfile::tempdir().unwrap();
4421 let dir_b = tempfile::tempdir().unwrap();
4422 let pool_a = file_pool(&dir_a.path().join("backend_a.db"));
4423 let pool_b = file_pool(&dir_b.path().join("backend_b.db"));
4426 let sidecar_a =
4427 crate::walpin::sidecar_dir_for(pool_a.canonical_path().expect("file-backed"));
4428 let _env_guard = crate::walpin::EnvVarGuard::capture("KHIVE_WALPIN_SIDECAR");
4429 std::env::set_var("KHIVE_WALPIN_SIDECAR", "1");
4430
4431 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
4432 let subscriber = CaptureSubscriber {
4433 events: std::sync::Arc::clone(&buffer),
4434 };
4435 let _tracing_guard = tracing::subscriber::set_default(subscriber);
4436
4437 let _b_origin_handle = khive_storage::tx_registry::register_scoped(
4438 Some("b_origin_span_ignored_by_a".to_string()),
4439 pool_b.origin(),
4440 );
4441 let _unscoped_handle = khive_storage::tx_registry::register(Some(
4442 "unscoped_span_ignored_by_secondary".to_string(),
4443 ));
4444
4445 let cfg = CheckpointConfig {
4446 interval: Duration::from_millis(10),
4447 tx_warn_secs: Duration::from_millis(1),
4448 tx_max_age_secs: Duration::from_millis(1),
4449 ..CheckpointConfig::default()
4450 };
4451 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
4452 let handle = tokio::spawn(run_checkpoint_task(
4453 pool_a,
4454 cfg,
4455 None,
4456 "local".to_string(),
4457 shutdown_rx,
4458 false, ));
4460
4461 tokio::time::sleep(Duration::from_millis(60)).await;
4466 shutdown_tx.send(()).expect("send shutdown signal");
4467 tokio::time::timeout(Duration::from_secs(1), handle)
4468 .await
4469 .expect("checkpoint task should exit within 1s")
4470 .expect("checkpoint task panicked");
4471
4472 let events = buffer.lock().unwrap();
4473 assert!(
4474 events.iter().all(|e| {
4475 e.tx_label.as_deref() != Some("b_origin_span_ignored_by_a")
4476 && e.tx_label.as_deref() != Some("unscoped_span_ignored_by_secondary")
4477 }),
4478 "backend A's Secondary filter must never emit an age alert naming a span \
4479 registered against a different backend's origin or an Unscoped span, got: \
4480 {events:?}"
4481 );
4482 assert!(
4483 !sidecar_a
4484 .join(format!("{}.json", std::process::id()))
4485 .exists(),
4486 "backend A's own sidecar must never gain a heartbeat from a span it does not own"
4487 );
4488 }
4489
4490 #[tokio::test]
4497 #[serial(tx_registry, checkpoint_skip_metrics, khive_walpin_sidecar_env)]
4498 async fn checkpoint_task_detects_and_enumerates_secondary_backend_stall() {
4499 let dir = tempfile::tempdir().unwrap();
4500 let pool = file_pool(&dir.path().join("secondary_stall.db"));
4501 let sidecar_dir =
4502 crate::walpin::sidecar_dir_for(pool.canonical_path().expect("file-backed"));
4503 let _env_guard = crate::walpin::EnvVarGuard::capture("KHIVE_WALPIN_SIDECAR");
4504 std::env::set_var("KHIVE_WALPIN_SIDECAR", "1");
4505
4506 let buffer = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
4507 let subscriber = CaptureSubscriber {
4508 events: std::sync::Arc::clone(&buffer),
4509 };
4510 let _tracing_guard = tracing::subscriber::set_default(subscriber);
4511
4512 let tx_handle = khive_storage::tx_registry::register_scoped(
4513 Some("secondary_stall_test".to_string()),
4514 pool.origin(),
4515 );
4516
4517 let cfg = CheckpointConfig {
4518 interval: Duration::from_millis(10),
4519 tx_warn_secs: Duration::from_millis(5),
4520 tx_max_age_secs: Duration::from_millis(500),
4521 ..CheckpointConfig::default()
4522 };
4523 let (shutdown_tx, shutdown_rx) = tokio::sync::watch::channel(());
4524 let pid = std::process::id();
4525 let heartbeat_path = sidecar_dir.join(format!("{pid}.json"));
4526 let handle = tokio::spawn(run_checkpoint_task(
4527 pool,
4528 cfg,
4529 None,
4530 "local".to_string(),
4531 shutdown_rx,
4532 false, ));
4534
4535 assert!(
4536 wait_for(Duration::from_secs(2), || heartbeat_path.exists()).await,
4537 "expected a walpin heartbeat once the secondary backend's own span crossed \
4538 tx_warn_secs"
4539 );
4540 let body = std::fs::read_to_string(&heartbeat_path).unwrap();
4541 let hb: crate::walpin::WalpinHeartbeat = serde_json::from_str(&body).unwrap();
4542 assert_eq!(hb.oldest_tx_label.as_deref(), Some("secondary_stall_test"));
4543 assert_eq!(
4544 hb.attribution_basis.as_deref(),
4545 Some("origin"),
4546 "a Secondary-view winner is always Database-origin-backed — never fallback"
4547 );
4548 assert!(
4549 hb.oldest_tx_age_secs > 0.0,
4550 "the heartbeat must reflect a nonzero stale age for the secondary backend's own \
4551 span, got {hb:?}"
4552 );
4553
4554 shutdown_tx.send(()).expect("send shutdown signal");
4555 tokio::time::timeout(Duration::from_secs(1), handle)
4556 .await
4557 .expect("checkpoint task should exit within 1s")
4558 .expect("checkpoint task panicked");
4559
4560 drop(tx_handle);
4561
4562 let events = buffer.lock().unwrap();
4563 assert!(
4564 events.iter().any(|e| {
4565 e.tx_label.as_deref() == Some("secondary_stall_test")
4566 && e.message
4567 .as_deref()
4568 .is_some_and(|m| m.contains("ADR-091 Plank 1"))
4569 }),
4570 "expected the secondary backend's own checkpoint task to emit a Plank 1 age alert \
4571 for its own stalled span, got: {events:?}"
4572 );
4573 }
4574
4575 #[test]
4576 fn wal_pin_depth_arithmetic_against_real_connection() {
4577 let dir = tempfile::tempdir().unwrap();
4578 let path = dir.path().join("pin_depth.db");
4579 let pool = file_pool(&path);
4580 let writer = pool.try_writer().expect("acquire writer");
4581 let conn = writer.conn();
4582
4583 conn.execute_batch("CREATE TABLE t (v INTEGER)").unwrap();
4584 conn.execute_batch("INSERT INTO t (v) VALUES (1)").unwrap();
4585
4586 let (log, checkpointed) =
4587 query_wal_pin_depth(conn).expect("PRAGMA wal_checkpoint(PASSIVE) must succeed");
4588 assert!(
4592 log >= checkpointed,
4593 "checkpointed frames cannot exceed log frames"
4594 );
4595 assert_eq!(
4596 log - checkpointed,
4597 0,
4598 "an unpinned WAL must fully checkpoint under PASSIVE"
4599 );
4600 }
4601
4602 #[test]
4603 fn wal_pin_depth_arithmetic_on_in_memory_pool_errors_cleanly() {
4604 let cfg = PoolConfig {
4608 path: None,
4609 ..PoolConfig::default()
4610 };
4611 let pool = ConnectionPool::new(cfg).expect("in-memory pool");
4612 let writer = pool.try_writer().expect("acquire writer");
4613 let _ = query_wal_pin_depth(writer.conn());
4616 }
4617}