1#[cfg(test)]
15pub(crate) const LOADED_WAIT: std::time::Duration = std::time::Duration::from_secs(60);
16
17pub mod harness_adapt;
18pub mod harness_metrics;
19pub mod observability;
20pub mod tool_receipts;
21
22pub use observability::{
23 evaluate_alerts, summarize, summarize_log, Alert, AlertKind, AlertThresholds, MetricsSummary,
24};
25
26use car_secrets::{
27 atomic_replace_private_file, create_private_file, open_private_append, revalidate_private_file,
28 revalidate_private_path,
29};
30use chrono::{DateTime, Utc};
31use serde::{Deserialize, Serialize};
32use serde_json::Value;
33use std::collections::{HashMap, HashSet, VecDeque};
34use std::fs;
35use std::future::Future;
36use std::io::{BufRead, BufReader, BufWriter, Read, Seek, SeekFrom, Write};
37use std::path::{Path, PathBuf};
38use std::pin::Pin;
39use std::sync::{mpsc, Arc, Condvar, Mutex, Weak};
40use std::task::{Context, Poll, Waker};
41use std::thread;
42use std::time::{Duration, Instant};
43use uuid::Uuid;
44
45#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize)]
46#[serde(rename_all = "camelCase")]
47pub struct EventLogStats {
48 pub events: usize,
49 pub spans: usize,
50 pub approx_event_bytes: usize,
51 pub approx_span_bytes: usize,
52}
53
54#[derive(Debug, Clone, PartialEq, Eq, Hash, Serialize, Deserialize, schemars::JsonSchema)]
56#[serde(rename_all = "snake_case")]
57pub enum EventKind {
58 RunStarted,
60 RunCancellationRequested,
62 RunCancellationResult,
64 ProposalReceived,
65 ProposalCompleted,
68 ActionValidated,
69 ActionRejected,
70 ActionExecuting,
71 ActionSucceeded,
72 ActionFailed,
73 ActionSkipped,
74 ActionRetrying,
75 ActionDeduplicated,
76 PolicyViolation,
77 StateChanged,
78 StateSnapshot,
79 StateCommitted,
83 StateRollback,
84 SkillDistilled,
86 SkillEvolved,
87 SkillDeprecated,
88 EvolutionTriggered,
89 CandidatePromoted,
93 CandidateRejected,
96 Consolidated,
98 ProactiveMemoryMaintained,
103 ProactiveMemoryIntervention,
104 ReplanAttempted,
106 ReplanProposalReceived,
107 ReplanRejected,
108 ReplanExhausted,
109 VoiceFastTurnStarted,
113 VoiceFastTurnEnded,
114 VoiceSidecarResolved,
115 VoiceSidecarFailed,
116 VoiceSidecarTimedOut,
117 VoiceTurnCancelled,
118 VoiceBridgePlayed,
119 GateAccepted,
125 GateRejected,
126 ModelFallback,
153 SessionScope,
160 PermissionDecision,
177 ApprovalRecorded,
183 BranchDecision,
190 AlternativeRejected,
196 InferenceMetered,
201 ModelCallRefused,
209 TransactionConflict,
216 AdmissionGateDecision,
226 ToolReceiptHallucination,
232 GoalEvaluated,
239 TurnCompleted,
247 RunCompleted,
250 WorkerStarted,
257 WorkerStartsOmitted,
261}
262
263#[derive(Debug, Clone, Serialize, Deserialize, PartialEq)]
265#[serde(rename_all = "snake_case")]
266pub enum SpanStatus {
267 Ok,
268 Error,
269 Unset,
270}
271
272#[derive(Debug, Clone, Serialize, Deserialize)]
274pub struct Span {
275 pub trace_id: String,
276 pub span_id: String,
277 pub parent_span_id: Option<String>,
278 pub name: String,
279 pub start_time: DateTime<Utc>,
280 pub end_time: Option<DateTime<Utc>>,
281 pub status: SpanStatus,
282 pub attributes: HashMap<String, Value>,
283}
284
285pub mod metric_keys {
290 pub const DURATION_MS: &str = "duration_ms";
292 pub const TOKENS_IN: &str = "tokens_in";
294 pub const TOKENS_OUT: &str = "tokens_out";
296 pub const COST_USD: &str = "cost_usd";
298}
299
300#[derive(Debug, Clone, Copy, Default, PartialEq, Serialize, Deserialize)]
306pub struct Metrics {
307 #[serde(default, skip_serializing_if = "Option::is_none")]
308 pub duration_ms: Option<f64>,
309 #[serde(default, skip_serializing_if = "Option::is_none")]
310 pub tokens_in: Option<u64>,
311 #[serde(default, skip_serializing_if = "Option::is_none")]
312 pub tokens_out: Option<u64>,
313 #[serde(default, skip_serializing_if = "Option::is_none")]
314 pub cost_usd: Option<f64>,
315}
316
317impl Metrics {
318 pub fn latency(duration_ms: f64) -> Self {
320 Self {
321 duration_ms: Some(duration_ms),
322 ..Default::default()
323 }
324 }
325
326 pub fn inference(tokens_in: u64, tokens_out: u64, cost_usd: Option<f64>) -> Self {
328 Self {
329 duration_ms: None,
330 tokens_in: Some(tokens_in),
331 tokens_out: Some(tokens_out),
332 cost_usd,
333 }
334 }
335
336 pub fn with_duration(mut self, duration_ms: f64) -> Self {
337 self.duration_ms = Some(duration_ms);
338 self
339 }
340
341 fn merge_into(&self, data: &mut HashMap<String, Value>) {
343 if let Some(d) = self.duration_ms {
344 data.insert(metric_keys::DURATION_MS.into(), Value::from(d));
345 }
346 if let Some(t) = self.tokens_in {
347 data.insert(metric_keys::TOKENS_IN.into(), Value::from(t));
348 }
349 if let Some(t) = self.tokens_out {
350 data.insert(metric_keys::TOKENS_OUT.into(), Value::from(t));
351 }
352 if let Some(c) = self.cost_usd {
353 data.insert(metric_keys::COST_USD.into(), Value::from(c));
354 }
355 }
356}
357
358#[derive(Debug, Clone, PartialEq, Serialize, Deserialize, schemars::JsonSchema)]
360pub struct Event {
361 pub kind: EventKind,
362 #[serde(default, skip_serializing_if = "Option::is_none")]
365 pub run_id: Option<String>,
366 #[serde(default, skip_serializing_if = "Option::is_none")]
369 pub client_id: Option<String>,
370 #[serde(default, skip_serializing_if = "Option::is_none")]
374 pub policy_session_id: Option<String>,
375 #[serde(default, skip_serializing_if = "Option::is_none")]
376 pub action_id: Option<String>,
377 #[serde(default, skip_serializing_if = "Option::is_none")]
378 pub proposal_id: Option<String>,
379 #[serde(default)]
380 pub data: HashMap<String, Value>,
381 #[serde(default = "Utc::now")]
382 pub timestamp: DateTime<Utc>,
383 #[serde(default, skip_serializing_if = "Option::is_none")]
388 pub prev_hash: Option<String>,
389 #[serde(default, skip_serializing_if = "Option::is_none")]
392 pub hash: Option<String>,
393}
394
395impl Event {
396 pub fn duration_ms(&self) -> Option<f64> {
398 self.data
399 .get(metric_keys::DURATION_MS)
400 .and_then(Value::as_f64)
401 }
402
403 pub fn tokens_in(&self) -> Option<u64> {
405 self.data
406 .get(metric_keys::TOKENS_IN)
407 .and_then(Value::as_u64)
408 }
409
410 pub fn tokens_out(&self) -> Option<u64> {
412 self.data
413 .get(metric_keys::TOKENS_OUT)
414 .and_then(Value::as_u64)
415 }
416
417 pub fn cost_usd(&self) -> Option<f64> {
419 self.data.get(metric_keys::COST_USD).and_then(Value::as_f64)
420 }
421
422 pub fn metrics(&self) -> Metrics {
424 Metrics {
425 duration_ms: self.duration_ms(),
426 tokens_in: self.tokens_in(),
427 tokens_out: self.tokens_out(),
428 cost_usd: self.cost_usd(),
429 }
430 }
431}
432
433#[derive(Debug, Clone, Copy, Default, PartialEq, Serialize, Deserialize)]
437pub struct MetricsTotals {
438 pub duration_ms: f64,
439 pub tokens_in: u64,
440 pub tokens_out: u64,
441 pub tokens: u64,
442 pub cost_usd: f64,
443 pub metered_events: usize,
445}
446
447pub fn metrics_totals_of(events: &[Event]) -> MetricsTotals {
456 let mut totals = MetricsTotals::default();
457 for ev in events {
458 if ev.data.contains_key(SUMMARY_OF) {
459 continue;
460 }
461 let m = ev.metrics();
462 let mut metered = false;
463 if let Some(d) = m.duration_ms {
464 totals.duration_ms += d;
465 metered = true;
466 }
467 if let Some(t) = m.tokens_in {
468 totals.tokens_in = totals.tokens_in.saturating_add(t);
469 metered = true;
470 }
471 if let Some(t) = m.tokens_out {
472 totals.tokens_out = totals.tokens_out.saturating_add(t);
473 metered = true;
474 }
475 if let Some(c) = m.cost_usd {
476 totals.cost_usd += c;
477 metered = true;
478 }
479 if metered {
480 totals.metered_events += 1;
481 }
482 }
483 totals.tokens = totals.tokens_in.saturating_add(totals.tokens_out);
484 totals
485}
486
487#[derive(Debug, Clone, Default, PartialEq, Serialize, Deserialize)]
490pub struct AgentCost {
491 pub agent: String,
492 pub calls: u64,
494 pub tokens_in: u64,
495 pub tokens_out: u64,
496 pub cost_usd: f64,
500 #[serde(default)]
503 pub priced_calls: u64,
504 #[serde(default)]
506 pub subscription_calls: u64,
507 #[serde(default)]
510 pub unpriced_calls: u64,
511 #[serde(default)]
516 pub ambiguous_reports: u64,
517 #[serde(default)]
520 pub ambiguous_reported_cost_usd: f64,
521}
522
523pub const UNATTRIBUTED_AGENT: &str = "unattributed";
527
528pub const SUMMARY_OF: &str = "summary_of";
543
544pub const SUMMARY_AMBIGUOUS: &str = "ambiguous";
552
553pub fn cost_by_agent_of(events: &[Event]) -> Vec<AgentCost> {
564 use std::collections::BTreeMap;
565 let mut map: BTreeMap<String, AgentCost> = BTreeMap::new();
566 for e in events {
567 if e.kind != EventKind::InferenceMetered {
568 continue;
569 }
570 let summary = e.data.get(SUMMARY_OF);
571 let ambiguous = summary.and_then(Value::as_str) == Some(SUMMARY_AMBIGUOUS);
572 if summary.is_some() && !ambiguous {
573 continue;
574 }
575 let agent = e
576 .data
577 .get("agent")
578 .and_then(|v| v.as_str())
579 .unwrap_or(UNATTRIBUTED_AGENT)
580 .to_string();
581 let entry = map.entry(agent.clone()).or_insert_with(|| AgentCost {
582 agent,
583 ..Default::default()
584 });
585 if ambiguous {
586 entry.ambiguous_reports += 1;
587 entry.ambiguous_reported_cost_usd += e.cost_usd().unwrap_or(0.0);
588 continue;
589 }
590 entry.calls += 1;
591 entry.tokens_in = entry.tokens_in.saturating_add(e.tokens_in().unwrap_or(0));
592 entry.tokens_out = entry.tokens_out.saturating_add(e.tokens_out().unwrap_or(0));
593 match (
596 e.data.get("cost_source").and_then(|v| v.as_str()),
597 e.cost_usd(),
598 ) {
599 (Some("subscription"), _) => entry.subscription_calls += 1,
600 (Some("unknown"), _) | (None, None) => entry.unpriced_calls += 1,
601 (_, cost) => {
602 entry.priced_calls += 1;
603 entry.cost_usd += cost.unwrap_or(0.0);
604 }
605 }
606 }
607 map.into_values().collect()
608}
609
610enum JournalMessage {
629 Async(String),
630 Critical {
631 line: String,
632 known_existing: bool,
633 ack: JournalAcknowledgement,
634 },
635 #[cfg(test)]
636 Shutdown,
637}
638
639pub const MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT: Duration = Duration::from_secs(30);
643
644const DEFAULT_CRITICAL_ACKNOWLEDGEMENT_CAPACITY: usize = 64;
645
646#[derive(Debug, Clone, Copy, PartialEq, Eq)]
650pub enum JournalFailurePoint {
651 AsyncWrite,
652 Write,
653 Flush,
654 Fsync,
655 HoldAcknowledgement,
659}
660
661#[derive(Debug, Clone, Default)]
662pub struct JournalFailureInjector {
663 failures: Arc<Mutex<VecDeque<JournalFailurePoint>>>,
664 held_acknowledgements: Arc<Mutex<Vec<JournalAcknowledgement>>>,
665 critical_passes: Arc<Mutex<usize>>,
666}
667
668impl JournalFailureInjector {
669 pub fn fail_next(&self, point: JournalFailurePoint) {
670 self.failures
671 .lock()
672 .expect("journal failure injector mutex poisoned")
673 .push_back(point);
674 }
675
676 #[doc(hidden)]
680 pub fn pass_next_critical(&self, count: usize) {
681 *self
682 .critical_passes
683 .lock()
684 .expect("journal critical-pass mutex poisoned") += count;
685 }
686
687 fn take_critical_pass(&self) -> bool {
688 let mut passes = self
689 .critical_passes
690 .lock()
691 .expect("journal critical-pass mutex poisoned");
692 if *passes == 0 {
693 return false;
694 }
695 *passes -= 1;
696 true
697 }
698
699 fn take(&self, point: JournalFailurePoint) -> bool {
700 let mut failures = self
701 .failures
702 .lock()
703 .expect("journal failure injector mutex poisoned");
704 if failures.front() == Some(&point) {
705 failures.pop_front();
706 true
707 } else {
708 false
709 }
710 }
711
712 fn hold_acknowledgement(&self, ack: JournalAcknowledgement) {
713 self.held_acknowledgements
714 .lock()
715 .expect("journal held-acknowledgement mutex poisoned")
716 .push(ack);
717 }
718
719 #[doc(hidden)]
722 pub fn held_acknowledgement_count(&self) -> usize {
723 self.held_acknowledgements
724 .lock()
725 .expect("journal held-acknowledgement mutex poisoned")
726 .len()
727 }
728
729 #[doc(hidden)]
732 pub fn release_held_acknowledgements(&self) {
733 let acknowledgements: Vec<_> = self
734 .held_acknowledgements
735 .lock()
736 .expect("journal held-acknowledgement mutex poisoned")
737 .drain(..)
738 .collect();
739 for acknowledgement in acknowledgements {
740 acknowledgement.send(Ok(()));
741 }
742 }
743}
744
745#[derive(Debug)]
746enum CriticalPreAcceptanceError {
747 WriterUnavailable,
748 WriterStopped,
749 CoordinatorUnavailable(String),
750 CapacityExhausted { capacity: usize },
751 InvalidAcknowledgementTimeout { requested: Duration },
752}
753
754impl std::fmt::Display for CriticalPreAcceptanceError {
755 fn fmt(&self, formatter: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
756 match self {
757 Self::WriterUnavailable => write!(formatter, "journal writer thread is unavailable"),
758 Self::WriterStopped => {
759 write!(
760 formatter,
761 "journal writer stopped before accepting critical append"
762 )
763 }
764 Self::CoordinatorUnavailable(reason) => write!(
765 formatter,
766 "critical acknowledgement coordinator is unavailable: {reason}"
767 ),
768 Self::CapacityExhausted { capacity } => write!(
769 formatter,
770 "critical acknowledgement capacity is exhausted ({capacity} in flight)"
771 ),
772 Self::InvalidAcknowledgementTimeout { requested } => write!(
773 formatter,
774 "critical acknowledgement timeout must be between 1ns and {}ms, got {}ms",
775 MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT.as_millis(),
776 requested.as_millis()
777 ),
778 }
779 }
780}
781
782#[derive(Debug)]
783enum CriticalPostAcceptanceError {
784 DurabilityFailure(String),
785 AcknowledgementTimedOut { timeout: Duration },
786 CoordinatorStopped,
787}
788
789impl std::fmt::Display for CriticalPostAcceptanceError {
790 fn fmt(&self, formatter: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
791 match self {
792 Self::DurabilityFailure(reason) => write!(formatter, "{reason}"),
793 Self::AcknowledgementTimedOut { timeout } => write!(
794 formatter,
795 "journal writer did not acknowledge within {}ms",
796 timeout.as_millis()
797 ),
798 Self::CoordinatorStopped => {
799 write!(
800 formatter,
801 "acknowledgement coordinator stopped after enqueue"
802 )
803 }
804 }
805 }
806}
807
808struct AsyncAcknowledgementState {
809 terminal: bool,
810 result: Option<Result<(), CriticalPostAcceptanceError>>,
811 waker: Option<Waker>,
812}
813
814struct AsyncAcknowledgementEntry {
815 id: u64,
816 deadline: Instant,
817 timeout: Duration,
818 manager: Weak<AsyncAcknowledgementManagerInner>,
819 state: Mutex<AsyncAcknowledgementState>,
820}
821
822impl AsyncAcknowledgementEntry {
823 fn complete(&self, result: Result<(), CriticalPostAcceptanceError>) {
824 self.complete_deciding(|| result);
825 }
826
827 fn complete_writer(&self, result: std::io::Result<()>) {
828 self.complete_deciding(|| {
829 if Instant::now() >= self.deadline {
830 Err(CriticalPostAcceptanceError::AcknowledgementTimedOut {
831 timeout: self.timeout,
832 })
833 } else {
834 result.map_err(|error| {
835 CriticalPostAcceptanceError::DurabilityFailure(error.to_string())
836 })
837 }
838 });
839 }
840
841 fn complete_deciding(&self, decide: impl FnOnce() -> Result<(), CriticalPostAcceptanceError>) {
842 let waker = {
843 let mut state = self
844 .state
845 .lock()
846 .expect("journal async-acknowledgement mutex poisoned");
847 if state.terminal {
848 return;
849 }
850 state.terminal = true;
851 state.result = Some(decide());
852 state.waker.take()
853 };
854 if let Some(manager) = self.manager.upgrade() {
855 manager.remove(self.id);
856 }
857 if let Some(waker) = waker {
858 waker.wake();
859 }
860 }
861
862 fn cancel_preacceptance(&self) {
863 {
864 let mut state = self
865 .state
866 .lock()
867 .expect("journal async-acknowledgement mutex poisoned");
868 if state.terminal {
869 return;
870 }
871 state.terminal = true;
872 }
873 if let Some(manager) = self.manager.upgrade() {
874 manager.remove(self.id);
875 }
876 }
877}
878
879struct AsyncAcknowledgement {
880 entry: Arc<AsyncAcknowledgementEntry>,
881}
882
883impl Future for AsyncAcknowledgement {
884 type Output = Result<(), CriticalPostAcceptanceError>;
885
886 fn poll(self: Pin<&mut Self>, context: &mut Context<'_>) -> Poll<Self::Output> {
887 let mut state = self
888 .entry
889 .state
890 .lock()
891 .expect("journal async-acknowledgement mutex poisoned");
892 match state.result.take() {
893 Some(result) => Poll::Ready(result),
894 None => {
895 state.waker = Some(context.waker().clone());
896 Poll::Pending
897 }
898 }
899 }
900}
901
902struct AsyncAcknowledgementManagerState {
903 entries: HashMap<u64, Arc<AsyncAcknowledgementEntry>>,
904 next_id: u64,
905 shutting_down: bool,
906}
907
908struct AsyncAcknowledgementManagerInner {
909 capacity: usize,
910 state: Mutex<AsyncAcknowledgementManagerState>,
911 changed: Condvar,
912 #[cfg(test)]
913 expiry_barrier: Mutex<Option<AsyncAcknowledgementExpiryBarrier>>,
914}
915
916#[cfg(test)]
917#[derive(Clone)]
918struct AsyncAcknowledgementExpiryBarrier {
919 removed: Arc<std::sync::Barrier>,
920 release: Arc<std::sync::Barrier>,
921}
922
923#[cfg(test)]
924impl AsyncAcknowledgementExpiryBarrier {
925 fn new() -> Self {
926 Self {
927 removed: Arc::new(std::sync::Barrier::new(2)),
928 release: Arc::new(std::sync::Barrier::new(2)),
929 }
930 }
931
932 fn pause_after_removal(&self) {
933 self.removed.wait();
934 self.release.wait();
935 }
936
937 fn wait_until_removed(&self) {
938 self.removed.wait();
939 }
940
941 fn allow_timeout_completion(&self) {
942 self.release.wait();
943 }
944}
945
946impl AsyncAcknowledgementManagerInner {
947 fn remove(&self, id: u64) {
948 let removed = self
949 .state
950 .lock()
951 .expect("journal acknowledgement-manager mutex poisoned")
952 .entries
953 .remove(&id)
954 .is_some();
955 if removed {
956 self.changed.notify_all();
957 }
958 }
959}
960
961struct AsyncAcknowledgementManager {
962 inner: Arc<AsyncAcknowledgementManagerInner>,
963 worker: Mutex<Option<thread::JoinHandle<()>>>,
964}
965
966impl AsyncAcknowledgementManager {
967 fn new(capacity: usize) -> Self {
968 Self {
969 inner: Arc::new(AsyncAcknowledgementManagerInner {
970 capacity,
971 state: Mutex::new(AsyncAcknowledgementManagerState {
972 entries: HashMap::new(),
973 next_id: 0,
974 shutting_down: false,
975 }),
976 changed: Condvar::new(),
977 #[cfg(test)]
978 expiry_barrier: Mutex::new(None),
979 }),
980 worker: Mutex::new(None),
981 }
982 }
983
984 #[cfg(test)]
985 fn pause_next_expiry_after_removal(&self, barrier: AsyncAcknowledgementExpiryBarrier) {
986 *self
987 .inner
988 .expiry_barrier
989 .lock()
990 .expect("journal acknowledgement expiry-barrier mutex poisoned") = Some(barrier);
991 }
992
993 fn ensure_worker(&self) -> Result<(), CriticalPreAcceptanceError> {
994 let mut worker = self
995 .worker
996 .lock()
997 .expect("journal acknowledgement-worker mutex poisoned");
998 if worker.is_some() {
999 return Ok(());
1000 }
1001 let inner = self.inner.clone();
1002 let handle = thread::Builder::new()
1003 .name("car-eventlog-critical-ack".into())
1004 .spawn(move || async_acknowledgement_timer_loop(inner))
1005 .map_err(|error| {
1006 CriticalPreAcceptanceError::CoordinatorUnavailable(error.to_string())
1007 })?;
1008 *worker = Some(handle);
1009 Ok(())
1010 }
1011
1012 fn reserve(
1013 &self,
1014 timeout: Duration,
1015 ) -> Result<AsyncAcknowledgementReservation, CriticalPreAcceptanceError> {
1016 if timeout.is_zero() || timeout > MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT {
1017 return Err(CriticalPreAcceptanceError::InvalidAcknowledgementTimeout {
1018 requested: timeout,
1019 });
1020 }
1021 self.ensure_worker()?;
1022 let mut state = self
1023 .inner
1024 .state
1025 .lock()
1026 .expect("journal acknowledgement-manager mutex poisoned");
1027 if state.shutting_down {
1028 return Err(CriticalPreAcceptanceError::CoordinatorUnavailable(
1029 "coordinator is shutting down".to_string(),
1030 ));
1031 }
1032 if state.entries.len() >= self.inner.capacity {
1033 return Err(CriticalPreAcceptanceError::CapacityExhausted {
1034 capacity: self.inner.capacity,
1035 });
1036 }
1037 let id = loop {
1038 let candidate = state.next_id;
1039 state.next_id = state.next_id.wrapping_add(1);
1040 if !state.entries.contains_key(&candidate) {
1041 break candidate;
1042 }
1043 };
1044 let entry = Arc::new(AsyncAcknowledgementEntry {
1045 id,
1046 deadline: Instant::now() + timeout,
1047 timeout,
1048 manager: Arc::downgrade(&self.inner),
1049 state: Mutex::new(AsyncAcknowledgementState {
1050 terminal: false,
1051 result: None,
1052 waker: None,
1053 }),
1054 });
1055 state.entries.insert(id, entry.clone());
1056 drop(state);
1057 self.inner.changed.notify_all();
1058 Ok(AsyncAcknowledgementReservation {
1059 entry,
1060 preaccepted: true,
1061 })
1062 }
1063
1064 fn shutdown(&self) {
1065 let entries = {
1066 let mut state = self
1067 .inner
1068 .state
1069 .lock()
1070 .expect("journal acknowledgement-manager mutex poisoned");
1071 state.shutting_down = true;
1072 let entries = state
1073 .entries
1074 .drain()
1075 .map(|(_, entry)| entry)
1076 .collect::<Vec<_>>();
1077 self.inner.changed.notify_all();
1078 entries
1079 };
1080 for entry in entries {
1081 entry.complete(Err(CriticalPostAcceptanceError::CoordinatorStopped));
1082 }
1083 if let Some(worker) = self
1084 .worker
1085 .lock()
1086 .expect("journal acknowledgement-worker mutex poisoned")
1087 .take()
1088 {
1089 let _ = worker.join();
1090 }
1091 }
1092}
1093
1094fn async_acknowledgement_timer_loop(inner: Arc<AsyncAcknowledgementManagerInner>) {
1095 loop {
1096 let expired = {
1097 let mut state = inner
1098 .state
1099 .lock()
1100 .expect("journal acknowledgement-manager mutex poisoned");
1101 loop {
1102 if state.shutting_down {
1103 return;
1104 }
1105 let now = Instant::now();
1106 let expired_ids: Vec<_> = state
1107 .entries
1108 .iter()
1109 .filter_map(|(id, entry)| (entry.deadline <= now).then_some(*id))
1110 .collect();
1111 if !expired_ids.is_empty() {
1112 break expired_ids
1113 .into_iter()
1114 .filter_map(|id| state.entries.remove(&id))
1115 .collect::<Vec<_>>();
1116 }
1117 if let Some(deadline) = state.entries.values().map(|entry| entry.deadline).min() {
1118 let wait = deadline.saturating_duration_since(now);
1119 let (next, _) = inner
1120 .changed
1121 .wait_timeout(state, wait)
1122 .expect("journal acknowledgement-manager mutex poisoned");
1123 state = next;
1124 } else {
1125 state = inner
1126 .changed
1127 .wait(state)
1128 .expect("journal acknowledgement-manager mutex poisoned");
1129 }
1130 }
1131 };
1132 #[cfg(test)]
1133 if !expired.is_empty() {
1134 if let Some(barrier) = inner
1135 .expiry_barrier
1136 .lock()
1137 .expect("journal acknowledgement expiry-barrier mutex poisoned")
1138 .take()
1139 {
1140 barrier.pause_after_removal();
1141 }
1142 }
1143 for entry in expired {
1144 entry.complete(Err(CriticalPostAcceptanceError::AcknowledgementTimedOut {
1145 timeout: entry.timeout,
1146 }));
1147 }
1148 }
1149}
1150
1151struct AsyncAcknowledgementReservation {
1152 entry: Arc<AsyncAcknowledgementEntry>,
1153 preaccepted: bool,
1154}
1155
1156impl AsyncAcknowledgementReservation {
1157 fn sender(&self) -> AsyncAcknowledgementSender {
1158 AsyncAcknowledgementSender {
1159 entry: self.entry.clone(),
1160 }
1161 }
1162
1163 fn into_future(mut self) -> AsyncAcknowledgement {
1164 self.preaccepted = false;
1165 AsyncAcknowledgement {
1166 entry: self.entry.clone(),
1167 }
1168 }
1169}
1170
1171impl Drop for AsyncAcknowledgementReservation {
1172 fn drop(&mut self) {
1173 if self.preaccepted {
1174 self.entry.cancel_preacceptance();
1175 }
1176 }
1177}
1178
1179struct AsyncAcknowledgementSender {
1180 entry: Arc<AsyncAcknowledgementEntry>,
1181}
1182
1183impl AsyncAcknowledgementSender {
1184 fn send(&self, result: std::io::Result<()>) {
1185 self.entry.complete_writer(result);
1186 }
1187}
1188
1189enum JournalAcknowledgement {
1190 Sync(mpsc::SyncSender<std::io::Result<()>>),
1191 Async(AsyncAcknowledgementSender),
1192}
1193
1194impl JournalAcknowledgement {
1195 fn send(&self, result: std::io::Result<()>) {
1196 match self {
1197 Self::Sync(sender) => {
1198 let _ = sender.send(result);
1199 }
1200 Self::Async(sender) => sender.send(result),
1201 }
1202 }
1203}
1204
1205impl std::fmt::Debug for JournalAcknowledgement {
1206 fn fmt(&self, formatter: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
1207 match self {
1208 Self::Sync(_) => formatter.write_str("JournalAcknowledgement::Sync"),
1209 Self::Async(_) => formatter.write_str("JournalAcknowledgement::Async"),
1210 }
1211 }
1212}
1213
1214#[derive(Debug, Clone, PartialEq, Eq)]
1218pub enum CriticalAppendError {
1219 Rejected { reason: String },
1221 DurabilityUnknown { reason: String },
1224}
1225
1226impl CriticalAppendError {
1227 pub fn is_retry_safe(&self) -> bool {
1228 matches!(self, Self::DurabilityUnknown { .. })
1229 }
1230}
1231
1232impl std::fmt::Display for CriticalAppendError {
1233 fn fmt(&self, formatter: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
1234 match self {
1235 Self::Rejected { reason } => {
1236 write!(formatter, "critical journal append rejected: {reason}")
1237 }
1238 Self::DurabilityUnknown { reason } => write!(
1239 formatter,
1240 "critical journal durability is unknown; retry the exact event safely: {reason}"
1241 ),
1242 }
1243 }
1244}
1245
1246impl std::error::Error for CriticalAppendError {}
1247
1248struct JournalWriter {
1249 tx: Option<mpsc::Sender<JournalMessage>>,
1252 handle: Option<thread::JoinHandle<()>>,
1253 acknowledgements: AsyncAcknowledgementManager,
1254}
1255
1256impl JournalWriter {
1257 fn spawn(path: PathBuf) -> Self {
1258 Self::spawn_with_injectors(path, JournalFailureInjector::default(), None)
1259 }
1260
1261 fn spawn_with_injector(path: PathBuf, failures: JournalFailureInjector) -> Self {
1262 Self::spawn_with_injectors(path, failures, None)
1263 }
1264
1265 fn spawn_with_private_path_injector(
1266 path: PathBuf,
1267 failures: car_secrets::PrivatePathDurabilityFailureInjector,
1268 ) -> Self {
1269 Self::spawn_with_injectors(path, JournalFailureInjector::default(), Some(failures))
1270 }
1271
1272 fn spawn_with_injectors(
1273 path: PathBuf,
1274 failures: JournalFailureInjector,
1275 private_path_failures: Option<car_secrets::PrivatePathDurabilityFailureInjector>,
1276 ) -> Self {
1277 Self::spawn_with_injectors_and_ack_capacity(
1278 path,
1279 failures,
1280 private_path_failures,
1281 DEFAULT_CRITICAL_ACKNOWLEDGEMENT_CAPACITY,
1282 )
1283 }
1284
1285 fn spawn_with_injectors_and_ack_capacity(
1286 path: PathBuf,
1287 failures: JournalFailureInjector,
1288 private_path_failures: Option<car_secrets::PrivatePathDurabilityFailureInjector>,
1289 acknowledgement_capacity: usize,
1290 ) -> Self {
1291 let (tx, rx) = mpsc::channel::<JournalMessage>();
1292 let acknowledgements = AsyncAcknowledgementManager::new(acknowledgement_capacity);
1293 match thread::Builder::new()
1294 .name("car-eventlog-journal".into())
1295 .spawn(move || journal_loop(path, rx, failures, private_path_failures))
1296 {
1297 Ok(handle) => Self {
1298 tx: Some(tx),
1299 handle: Some(handle),
1300 acknowledgements,
1301 },
1302 Err(e) => {
1304 tracing::warn!(error = %e, "car-eventlog: failed to spawn journal writer thread — journaling disabled for this log");
1305 Self {
1306 tx: None,
1307 handle: None,
1308 acknowledgements,
1309 }
1310 }
1311 }
1312 }
1313
1314 fn send(&self, line: String) {
1315 if let Some(tx) = &self.tx {
1316 let _ = tx.send(JournalMessage::Async(line));
1318 }
1319 }
1320
1321 fn enqueue_critical_sync(
1322 &self,
1323 line: String,
1324 known_existing: bool,
1325 ) -> Result<mpsc::Receiver<std::io::Result<()>>, CriticalPreAcceptanceError> {
1326 let tx = self
1327 .tx
1328 .as_ref()
1329 .ok_or(CriticalPreAcceptanceError::WriterUnavailable)?;
1330 let (ack_tx, ack_rx) = mpsc::sync_channel(0);
1331 tx.send(JournalMessage::Critical {
1332 line,
1333 known_existing,
1334 ack: JournalAcknowledgement::Sync(ack_tx),
1335 })
1336 .map_err(|_| CriticalPreAcceptanceError::WriterStopped)?;
1337 Ok(ack_rx)
1338 }
1339
1340 fn reserve_async_acknowledgement(
1341 &self,
1342 acknowledgement_timeout: Duration,
1343 ) -> Result<AsyncAcknowledgementReservation, CriticalPreAcceptanceError> {
1344 if self.tx.is_none() {
1345 return Err(CriticalPreAcceptanceError::WriterUnavailable);
1346 }
1347 self.acknowledgements.reserve(acknowledgement_timeout)
1348 }
1349
1350 fn enqueue_critical_async(
1351 &self,
1352 line: String,
1353 known_existing: bool,
1354 reservation: AsyncAcknowledgementReservation,
1355 ) -> Result<AsyncAcknowledgement, CriticalPreAcceptanceError> {
1356 let tx = self
1357 .tx
1358 .as_ref()
1359 .ok_or(CriticalPreAcceptanceError::WriterUnavailable)?;
1360 tx.send(JournalMessage::Critical {
1361 line,
1362 known_existing,
1363 ack: JournalAcknowledgement::Async(reservation.sender()),
1364 })
1365 .map_err(|_| CriticalPreAcceptanceError::WriterStopped)?;
1366 Ok(reservation.into_future())
1367 }
1368
1369 #[cfg(test)]
1370 fn remove_sender_for_test(&mut self) {
1371 self.tx.take();
1372 if let Some(handle) = self.handle.take() {
1373 let _ = handle.join();
1374 }
1375 }
1376
1377 #[cfg(test)]
1378 fn stop_receiver_for_test(&mut self) {
1379 if let Some(tx) = &self.tx {
1380 let _ = tx.send(JournalMessage::Shutdown);
1381 }
1382 if let Some(handle) = self.handle.take() {
1383 let _ = handle.join();
1384 }
1385 }
1386}
1387
1388impl Drop for JournalWriter {
1389 fn drop(&mut self) {
1390 self.acknowledgements.shutdown();
1391 self.tx.take();
1394 if let Some(handle) = self.handle.take() {
1395 let _ = handle.join();
1396 }
1397 }
1398}
1399
1400fn journal_loop(
1411 path: PathBuf,
1412 rx: mpsc::Receiver<JournalMessage>,
1413 failures: JournalFailureInjector,
1414 private_path_failures: Option<car_secrets::PrivatePathDurabilityFailureInjector>,
1415) {
1416 let mut writer: Option<std::fs::File> = None;
1417 let mut written_critical_lines = HashSet::new();
1418 let mut blocked_critical: Option<String> = None;
1419 let mut failed_async = VecDeque::new();
1424 let mut after_blocked_critical = VecDeque::new();
1425 while let Ok(message) = rx.recv() {
1426 let existed_before_open = path.exists();
1427 let open = || match private_path_failures.as_ref() {
1428 Some(failures) => {
1429 car_secrets::open_private_append_with_failure_injector(&path, failures)
1430 }
1431 None => open_private_append(&path),
1432 };
1433 match message {
1434 #[cfg(test)]
1435 JournalMessage::Shutdown => break,
1436 JournalMessage::Async(line) => {
1437 if blocked_critical.is_some() {
1438 after_blocked_critical.push_back(line);
1439 continue;
1440 }
1441 if !failed_async.is_empty() {
1442 failed_async.push_back(line);
1443 continue;
1444 }
1445 if writer.is_none() {
1446 writer = open().ok();
1447 }
1448 let result = match writer.as_mut() {
1449 Some(file) => append_journal_line(
1450 &path,
1451 file,
1452 &line,
1453 false,
1454 false,
1455 existed_before_open,
1456 &failures,
1457 &mut written_critical_lines,
1458 ),
1459 None => Err(std::io::Error::other("cannot open journal file")),
1460 };
1461 if let Err(error) = result {
1462 failed_async.push_back(line);
1463 tracing::warn!(path = %path.display(), %error, "car-eventlog: asynchronous journal append failed and is awaiting ordered retry");
1464 }
1465 continue;
1466 }
1467 JournalMessage::Critical {
1468 line,
1469 known_existing,
1470 ack,
1471 } => {
1472 if blocked_critical
1473 .as_deref()
1474 .is_some_and(|pending| pending != line)
1475 {
1476 ack.send(Err(std::io::Error::new(
1477 std::io::ErrorKind::WouldBlock,
1478 "another critical journal row is awaiting durability",
1479 )));
1480 continue;
1481 }
1482 if writer.is_none() {
1483 writer = open().ok();
1484 }
1485
1486 while let Some(pending) = failed_async.front() {
1491 let replay = match writer.as_mut() {
1492 Some(file) => append_journal_line(
1493 &path,
1494 file,
1495 pending,
1496 false,
1497 false,
1498 existed_before_open,
1499 &failures,
1500 &mut written_critical_lines,
1501 ),
1502 None => Err(std::io::Error::other("cannot open journal file")),
1503 };
1504 match replay {
1505 Ok(()) => {
1506 failed_async.pop_front();
1507 }
1508 Err(error) => {
1509 blocked_critical = Some(line.clone());
1510 ack.send(Err(std::io::Error::new(
1511 error.kind(),
1512 format!("prior asynchronous journal row is not durable: {error}"),
1513 )));
1514 break;
1515 }
1516 }
1517 }
1518 if !failed_async.is_empty() {
1519 continue;
1520 }
1521 let line_failures = if failures.take_critical_pass() {
1522 JournalFailureInjector::default()
1523 } else {
1524 failures.clone()
1525 };
1526 let result = match writer.as_mut() {
1527 Some(file) => append_journal_line(
1528 &path,
1529 file,
1530 &line,
1531 true,
1532 known_existing,
1533 existed_before_open,
1534 &line_failures,
1535 &mut written_critical_lines,
1536 ),
1537 None => Err(std::io::Error::other("cannot open journal file")),
1538 };
1539 match result {
1540 Ok(()) => {
1541 blocked_critical = None;
1542 while let Some(queued) = after_blocked_critical.pop_front() {
1543 if let Some(file) = writer.as_mut() {
1544 if let Err(error) = append_journal_line(
1545 &path,
1546 file,
1547 &queued,
1548 false,
1549 false,
1550 true,
1551 &failures,
1552 &mut written_critical_lines,
1553 ) {
1554 failed_async.push_back(queued);
1555 failed_async.append(&mut after_blocked_critical);
1556 tracing::warn!(path = %path.display(), %error, "car-eventlog: queued asynchronous append failed after critical recovery and is awaiting ordered retry");
1557 break;
1558 }
1559 }
1560 }
1561 if line_failures.take(JournalFailurePoint::HoldAcknowledgement) {
1562 failures.hold_acknowledgement(ack);
1563 } else {
1564 ack.send(Ok(()));
1565 }
1566 }
1567 Err(error) => {
1568 blocked_critical = Some(line);
1569 ack.send(Err(error));
1570 }
1571 }
1572 continue;
1573 }
1574 };
1575 }
1576 if let Some(mut writer) = writer {
1577 let _ = writer.flush();
1578 }
1579}
1580
1581fn append_journal_line(
1582 path: &Path,
1583 file: &mut std::fs::File,
1584 line: &str,
1585 critical: bool,
1586 known_existing: bool,
1587 existed_before_open: bool,
1588 failures: &JournalFailureInjector,
1589 written_critical_lines: &mut HashSet<String>,
1590) -> std::io::Result<()> {
1591 revalidate_private_path(path, file)?;
1592 let already_written = known_existing || written_critical_lines.contains(line);
1593 if !already_written {
1594 if (!critical && failures.take(JournalFailurePoint::AsyncWrite))
1595 || (critical && failures.take(JournalFailurePoint::Write))
1596 {
1597 return Err(std::io::Error::from_raw_os_error(28)); }
1599 let mut bytes = Vec::with_capacity(line.len() + 2);
1600 let len = file.seek(SeekFrom::End(0))?;
1601 if len > 0 {
1602 file.seek(SeekFrom::End(-1))?;
1603 let mut tail = [0u8; 1];
1604 file.read_exact(&mut tail)?;
1605 if tail[0] != b'\n' {
1606 bytes.push(b'\n');
1607 }
1608 }
1609 bytes.extend_from_slice(line.as_bytes());
1610 bytes.push(b'\n');
1611 if let Err(error) = file.write_all(&bytes) {
1612 let _ = file.set_len(len);
1616 let _ = file.seek(SeekFrom::End(0));
1617 return Err(error);
1618 }
1619 if critical {
1620 written_critical_lines.insert(line.to_string());
1621 }
1622 }
1623 if critical && failures.take(JournalFailurePoint::Flush) {
1624 return Err(std::io::Error::other("injected journal flush failure"));
1625 }
1626 file.flush()?;
1627 if critical {
1628 if failures.take(JournalFailurePoint::Fsync) {
1629 return Err(std::io::Error::other("injected journal fsync failure"));
1630 }
1631 file.sync_all()?;
1632 if !existed_before_open {
1633 sync_journal_parent(path)?;
1634 }
1635 }
1636 revalidate_private_path(path, file)
1637}
1638
1639#[cfg(not(target_os = "windows"))]
1640fn sync_journal_parent(path: &Path) -> std::io::Result<()> {
1641 if let Some(parent) = path.parent() {
1642 std::fs::File::open(parent)?.sync_all()?;
1643 }
1644 Ok(())
1645}
1646
1647#[cfg(target_os = "windows")]
1648fn sync_journal_parent(_path: &Path) -> std::io::Result<()> {
1649 Ok(())
1654}
1655
1656pub struct EventLog {
1658 events: Vec<Event>,
1659 spans: Vec<Span>,
1660 journal: Option<JournalWriter>,
1661 hash_chaining: bool,
1666 last_hash: Option<String>,
1669 retention: Option<RetentionPolicy>,
1674 journal_path: Option<PathBuf>,
1677 journal_lines: usize,
1682 trimmed_events: u64,
1688 cumulative_cost_usd: f64,
1694 active_binding: Option<EventBinding>,
1698 critical_pending: HashSet<String>,
1702}
1703
1704#[derive(Debug, Clone, PartialEq, Eq)]
1705struct EventBinding {
1706 run_id: String,
1707 client_id: String,
1708 policy_session_id: Option<String>,
1709}
1710
1711struct PreparedCriticalAppend {
1712 existing_index: Option<usize>,
1713 event: Option<Event>,
1714 line: String,
1715 known_existing: bool,
1716}
1717
1718const JOURNAL_COMPACT_MIN_EXCESS: usize = 1024;
1724
1725fn event_digest(
1737 prev_hash: &str,
1738 kind: &EventKind,
1739 run_id: Option<&str>,
1740 client_id: Option<&str>,
1741 policy_session_id: Option<&str>,
1742 action_id: Option<&str>,
1743 proposal_id: Option<&str>,
1744 data: &HashMap<String, Value>,
1745 timestamp: &DateTime<Utc>,
1746) -> String {
1747 use sha2::{Digest, Sha256};
1748 let mut sorted: Vec<(&String, &Value)> = data.iter().collect();
1749 sorted.sort_by(|a, b| a.0.cmp(b.0));
1750 let data_canon: String = sorted
1751 .iter()
1752 .map(|(k, v)| format!("{k}={}", v))
1753 .collect::<Vec<_>>()
1754 .join("\u{1f}");
1755 let kind_str = serde_json::to_string(kind).unwrap_or_default();
1756 let mut hasher = Sha256::new();
1757 hasher.update(prev_hash.as_bytes());
1758 hasher.update(b"\x1e");
1759 hasher.update(kind_str.as_bytes());
1760 if run_id.is_some() || client_id.is_some() || policy_session_id.is_some() {
1763 hasher.update(b"\x1d");
1764 hasher.update(run_id.unwrap_or("").as_bytes());
1765 hasher.update(b"\x1f");
1766 hasher.update(client_id.unwrap_or("").as_bytes());
1767 hasher.update(b"\x1f");
1768 hasher.update(policy_session_id.unwrap_or("").as_bytes());
1769 }
1770 hasher.update(b"\x1e");
1771 hasher.update(action_id.unwrap_or("").as_bytes());
1772 hasher.update(b"\x1e");
1773 hasher.update(proposal_id.unwrap_or("").as_bytes());
1774 hasher.update(b"\x1e");
1775 hasher.update(data_canon.as_bytes());
1776 hasher.update(b"\x1e");
1777 hasher.update(timestamp.to_rfc3339().as_bytes());
1778 let digest = hasher.finalize();
1779 digest.iter().map(|b| format!("{b:02x}")).collect()
1780}
1781
1782#[derive(Debug, Clone, Default, PartialEq, Serialize, Deserialize)]
1792pub struct RetentionPolicy {
1793 #[serde(default, alias = "maxEvents")]
1795 pub max_events: Option<usize>,
1796 #[serde(default, alias = "maxAgeSecs")]
1798 pub max_age_secs: Option<i64>,
1799}
1800
1801#[derive(Debug, Clone, Default, Serialize, Deserialize)]
1811pub struct EventQuery {
1812 #[serde(default)]
1814 pub kinds: Vec<EventKind>,
1815 #[serde(default, alias = "actionId")]
1817 pub action_id: Option<String>,
1818 #[serde(default, alias = "proposalId")]
1820 pub proposal_id: Option<String>,
1821 #[serde(default)]
1823 pub since: Option<DateTime<Utc>>,
1824 #[serde(default)]
1826 pub until: Option<DateTime<Utc>>,
1827 #[serde(default, alias = "dataMatches")]
1831 pub data_matches: std::collections::HashMap<String, String>,
1832 #[serde(default)]
1834 pub limit: Option<usize>,
1835}
1836
1837fn data_value_matches(v: &Value, want: &str) -> bool {
1840 match v {
1841 Value::String(s) => s == want,
1842 Value::Null => false,
1843 other => *other == want,
1844 }
1845}
1846
1847impl EventQuery {
1848 pub fn matches(&self, e: &Event) -> bool {
1850 if !self.kinds.is_empty() && !self.kinds.contains(&e.kind) {
1851 return false;
1852 }
1853 if let Some(aid) = &self.action_id {
1854 if e.action_id.as_deref() != Some(aid.as_str()) {
1855 return false;
1856 }
1857 }
1858 if let Some(pid) = &self.proposal_id {
1859 if e.proposal_id.as_deref() != Some(pid.as_str()) {
1860 return false;
1861 }
1862 }
1863 if let Some(since) = self.since {
1864 if e.timestamp < since {
1865 return false;
1866 }
1867 }
1868 if let Some(until) = self.until {
1869 if e.timestamp >= until {
1870 return false;
1871 }
1872 }
1873 for (k, want) in &self.data_matches {
1874 match e.data.get(k) {
1875 Some(v) if data_value_matches(v, want) => {}
1876 _ => return false,
1877 }
1878 }
1879 true
1880 }
1881}
1882
1883impl EventLog {
1884 pub fn new() -> Self {
1885 Self {
1886 events: Vec::new(),
1887 spans: Vec::new(),
1888 journal: None,
1889 hash_chaining: false,
1890 last_hash: None,
1891 retention: None,
1892 journal_path: None,
1893 journal_lines: 0,
1894 trimmed_events: 0,
1895 cumulative_cost_usd: 0.0,
1896 active_binding: None,
1897 critical_pending: HashSet::new(),
1898 }
1899 }
1900
1901 pub fn with_journal(path: PathBuf) -> Self {
1902 let mut log = Self::with_lazy_journal(path.clone());
1903 log.journal = Some(JournalWriter::spawn(path));
1904 log
1905 }
1906
1907 pub fn with_lazy_journal(path: PathBuf) -> Self {
1912 Self {
1913 events: Vec::new(),
1914 spans: Vec::new(),
1915 journal: None,
1916 hash_chaining: false,
1917 last_hash: None,
1918 retention: None,
1919 journal_path: Some(path),
1920 journal_lines: 0,
1921 trimmed_events: 0,
1922 cumulative_cost_usd: 0.0,
1923 active_binding: None,
1924 critical_pending: HashSet::new(),
1925 }
1926 }
1927
1928 pub fn with_journal_failure_injector(path: PathBuf, failures: JournalFailureInjector) -> Self {
1930 let mut log = Self::with_journal(path.clone());
1931 log.journal = Some(JournalWriter::spawn_with_injector(path, failures));
1932 log
1933 }
1934
1935 #[cfg(test)]
1936 fn with_journal_failure_injector_and_ack_capacity(
1937 path: PathBuf,
1938 failures: JournalFailureInjector,
1939 acknowledgement_capacity: usize,
1940 ) -> Self {
1941 let mut log = Self::with_journal(path.clone());
1942 log.journal = Some(JournalWriter::spawn_with_injectors_and_ack_capacity(
1943 path,
1944 failures,
1945 None,
1946 acknowledgement_capacity,
1947 ));
1948 log
1949 }
1950
1951 pub fn with_private_path_failure_injector(
1953 path: PathBuf,
1954 failures: car_secrets::PrivatePathDurabilityFailureInjector,
1955 ) -> Self {
1956 let mut log = Self::with_journal(path.clone());
1957 log.journal = Some(JournalWriter::spawn_with_private_path_injector(
1958 path, failures,
1959 ));
1960 log
1961 }
1962
1963 pub fn bind_run(&mut self, run_id: &str, client_id: &str) -> Result<(), String> {
1967 if run_id.is_empty() || client_id.is_empty() {
1968 return Err("active journal binding requires non-empty run_id and client_id".into());
1969 }
1970 match &self.active_binding {
1971 Some(binding) if binding.run_id == run_id && binding.client_id == client_id => Ok(()),
1972 Some(binding) => Err(format!(
1973 "journal is already bound to run_id `{}` and client_id `{}`",
1974 binding.run_id, binding.client_id
1975 )),
1976 None => {
1977 self.active_binding = Some(EventBinding {
1978 run_id: run_id.to_string(),
1979 client_id: client_id.to_string(),
1980 policy_session_id: None,
1981 });
1982 Ok(())
1983 }
1984 }
1985 }
1986
1987 pub fn bind_policy_session(&mut self, policy_session_id: &str) -> Result<(), String> {
1989 if policy_session_id.is_empty() {
1990 return Err("policy_session_id must be non-empty".into());
1991 }
1992 let binding = self
1993 .active_binding
1994 .as_mut()
1995 .ok_or_else(|| "cannot bind a policy session without an active run".to_string())?;
1996 match binding.policy_session_id.as_deref() {
1997 Some(existing) if existing != policy_session_id => Err(format!(
1998 "journal proposal is already bound to policy_session_id `{existing}`"
1999 )),
2000 _ => {
2001 binding.policy_session_id = Some(policy_session_id.to_string());
2002 Ok(())
2003 }
2004 }
2005 }
2006
2007 pub fn clear_policy_session(&mut self, policy_session_id: &str) -> Result<(), String> {
2008 let binding = self
2009 .active_binding
2010 .as_mut()
2011 .ok_or_else(|| "cannot clear a policy session without an active run".to_string())?;
2012 if binding.policy_session_id.as_deref() != Some(policy_session_id) {
2013 return Err("policy_session_id does not match the active journal binding".into());
2014 }
2015 binding.policy_session_id = None;
2016 Ok(())
2017 }
2018
2019 pub fn clear_run_binding(&mut self, run_id: &str, client_id: &str) -> Result<(), String> {
2020 let binding = self
2021 .active_binding
2022 .as_ref()
2023 .ok_or_else(|| "journal has no active run binding".to_string())?;
2024 if binding.run_id != run_id || binding.client_id != client_id {
2025 return Err("run_id/client_id does not match the active journal binding".into());
2026 }
2027 if binding.policy_session_id.is_some() {
2028 return Err(
2029 "cannot clear an active run while a proposal policy session is bound".into(),
2030 );
2031 }
2032 self.active_binding = None;
2033 Ok(())
2034 }
2035
2036 pub fn active_run_binding(&self) -> Option<(&str, &str, Option<&str>)> {
2037 self.active_binding.as_ref().map(|binding| {
2038 (
2039 binding.run_id.as_str(),
2040 binding.client_id.as_str(),
2041 binding.policy_session_id.as_deref(),
2042 )
2043 })
2044 }
2045
2046 pub fn with_hash_chaining(mut self) -> Self {
2051 self.enable_hash_chaining();
2052 self
2053 }
2054
2055 pub fn enable_hash_chaining(&mut self) {
2057 self.hash_chaining = true;
2058 if self.last_hash.is_none() {
2060 self.last_hash = self.events.last().and_then(|e| e.hash.clone());
2061 }
2062 }
2063
2064 pub fn hash_chaining_enabled(&self) -> bool {
2066 self.hash_chaining
2067 }
2068
2069 pub fn append(
2070 &mut self,
2071 kind: EventKind,
2072 action_id: Option<&str>,
2073 proposal_id: Option<&str>,
2074 data: HashMap<String, Value>,
2075 ) -> &Event {
2076 let timestamp = Utc::now();
2077 let (prev_hash, hash) = if self.hash_chaining {
2078 let prev = self.last_hash.clone().unwrap_or_default();
2079 let binding = self.active_binding.as_ref();
2080 let h = event_digest(
2081 &prev,
2082 &kind,
2083 binding.map(|b| b.run_id.as_str()),
2084 binding.map(|b| b.client_id.as_str()),
2085 binding.and_then(|b| b.policy_session_id.as_deref()),
2086 action_id,
2087 proposal_id,
2088 &data,
2089 ×tamp,
2090 );
2091 self.last_hash = Some(h.clone());
2092 (Some(prev), Some(h))
2093 } else {
2094 (None, None)
2095 };
2096 let event = Event {
2097 kind,
2098 run_id: self.active_binding.as_ref().map(|b| b.run_id.clone()),
2099 client_id: self.active_binding.as_ref().map(|b| b.client_id.clone()),
2100 policy_session_id: self
2101 .active_binding
2102 .as_ref()
2103 .and_then(|b| b.policy_session_id.clone()),
2104 action_id: action_id.map(|s| s.to_string()),
2105 proposal_id: proposal_id.map(|s| s.to_string()),
2106 data,
2107 timestamp,
2108 prev_hash,
2109 hash,
2110 };
2111
2112 if let Some(journal) = &self.journal {
2115 if let Ok(json) = serde_json::to_string(&event) {
2116 journal.send(json);
2117 self.journal_lines += 1;
2118 }
2119 }
2120
2121 if let Some(c) = event.cost_usd() {
2124 self.cumulative_cost_usd += c;
2125 }
2126
2127 self.events.push(event);
2128 if let Some(max) = self.retention.as_ref().and_then(|p| p.max_events) {
2133 if self.events.len() > max {
2134 let removed = truncate_vec_keep_last(&mut self.events, max);
2135 self.trimmed_events += removed as u64;
2136 self.maybe_compact_journal();
2139 }
2140 }
2141 self.events.last().unwrap()
2142 }
2143
2144 fn prepare_critical_append(
2145 &mut self,
2146 kind: EventKind,
2147 action_id: Option<&str>,
2148 proposal_id: Option<&str>,
2149 data: HashMap<String, Value>,
2150 ) -> Result<PreparedCriticalAppend, String> {
2151 let binding = self.active_binding.as_ref().ok_or_else(|| {
2152 "critical lifecycle event requires an authenticated run binding".to_string()
2153 })?;
2154 let existing = self.events.iter().position(|event| {
2155 event.kind == kind
2156 && event.run_id.as_deref() == Some(binding.run_id.as_str())
2157 && event.client_id.as_deref() == Some(binding.client_id.as_str())
2158 && event.policy_session_id.as_deref() == binding.policy_session_id.as_deref()
2159 && event.action_id.as_deref() == action_id
2160 && event.proposal_id.as_deref() == proposal_id
2161 && event.data == data
2162 });
2163 if existing.is_none() && !self.critical_pending.is_empty() {
2164 return Err(
2165 "another critical lifecycle event is awaiting an exact durability retry".into(),
2166 );
2167 }
2168
2169 if let Some(index) = existing {
2170 let line = serde_json::to_string(&self.events[index]).map_err(|e| e.to_string())?;
2171 return Ok(PreparedCriticalAppend {
2172 existing_index: Some(index),
2173 event: None,
2174 known_existing: !self.critical_pending.contains(&line),
2175 line,
2176 });
2177 }
2178
2179 let timestamp = Utc::now();
2180 let (prev_hash, hash) = if self.hash_chaining {
2181 let prev = self.last_hash.clone().unwrap_or_default();
2182 let hash = event_digest(
2183 &prev,
2184 &kind,
2185 Some(binding.run_id.as_str()),
2186 Some(binding.client_id.as_str()),
2187 binding.policy_session_id.as_deref(),
2188 action_id,
2189 proposal_id,
2190 &data,
2191 ×tamp,
2192 );
2193 (Some(prev), Some(hash))
2194 } else {
2195 (None, None)
2196 };
2197 let event = Event {
2198 kind,
2199 run_id: Some(binding.run_id.clone()),
2200 client_id: Some(binding.client_id.clone()),
2201 policy_session_id: binding.policy_session_id.clone(),
2202 action_id: action_id.map(str::to_string),
2203 proposal_id: proposal_id.map(str::to_string),
2204 data,
2205 timestamp,
2206 prev_hash,
2207 hash,
2208 };
2209 let line = serde_json::to_string(&event).map_err(|error| error.to_string())?;
2210 Ok(PreparedCriticalAppend {
2211 existing_index: None,
2212 event: Some(event),
2213 line,
2214 known_existing: false,
2215 })
2216 }
2217
2218 fn commit_prepared_critical(&mut self, prepared: PreparedCriticalAppend) -> (usize, String) {
2219 let index = match prepared.existing_index {
2220 Some(index) => index,
2221 None => {
2222 let event = prepared
2223 .event
2224 .expect("new critical append must carry its prepared event");
2225 if self.hash_chaining {
2226 self.last_hash = event.hash.clone();
2227 }
2228 self.events.push(event);
2229 self.journal_lines += 1;
2230 self.events.len() - 1
2231 }
2232 };
2233 (index, prepared.line)
2234 }
2235
2236 pub fn append_critical(
2247 &mut self,
2248 kind: EventKind,
2249 action_id: Option<&str>,
2250 proposal_id: Option<&str>,
2251 data: HashMap<String, Value>,
2252 ) -> Result<&Event, String> {
2253 if self.journal.is_none() {
2254 return Err("critical lifecycle event requires an enabled journal".to_string());
2255 }
2256 let prepared = self.prepare_critical_append(kind, action_id, proposal_id, data)?;
2257 let acknowledgement = self
2258 .journal
2259 .as_ref()
2260 .expect("journal presence checked above")
2261 .enqueue_critical_sync(prepared.line.clone(), prepared.known_existing)
2262 .map_err(|error| error.to_string())?;
2263 let (index, line) = self.commit_prepared_critical(prepared);
2264 self.critical_pending.insert(line.clone());
2265 let result = acknowledgement
2266 .recv()
2267 .map_err(|_| {
2268 std::io::Error::new(
2269 std::io::ErrorKind::BrokenPipe,
2270 "journal writer stopped before critical acknowledgement",
2271 )
2272 })
2273 .and_then(|result| result);
2274 match result {
2275 Ok(()) => {
2276 self.critical_pending.remove(&line);
2277 Ok(&self.events[index])
2278 }
2279 Err(error) => {
2280 self.critical_pending.insert(line);
2281 Err(format!("critical journal append was not durable: {error}"))
2282 }
2283 }
2284 }
2285
2286 pub fn append_critical_bounded(
2294 &mut self,
2295 kind: EventKind,
2296 action_id: Option<&str>,
2297 proposal_id: Option<&str>,
2298 data: HashMap<String, Value>,
2299 acknowledgement_timeout: Duration,
2300 ) -> Result<&Event, CriticalAppendError> {
2301 if acknowledgement_timeout.is_zero()
2302 || acknowledgement_timeout > MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT
2303 {
2304 return Err(CriticalAppendError::Rejected {
2305 reason: CriticalPreAcceptanceError::InvalidAcknowledgementTimeout {
2306 requested: acknowledgement_timeout,
2307 }
2308 .to_string(),
2309 });
2310 }
2311 let prepared = self
2312 .prepare_critical_append(kind, action_id, proposal_id, data)
2313 .map_err(|reason| CriticalAppendError::Rejected { reason })?;
2314 if prepared.known_existing && self.journal.is_none() && self.journal_path.is_some() {
2315 let (index, _) = self.commit_prepared_critical(prepared);
2316 return Ok(&self.events[index]);
2317 }
2318 if self.journal.is_none() {
2319 let path = self
2320 .journal_path
2321 .clone()
2322 .ok_or_else(|| CriticalAppendError::Rejected {
2323 reason: "critical lifecycle event requires an enabled journal".to_string(),
2324 })?;
2325 self.journal = Some(JournalWriter::spawn(path));
2326 }
2327 let acknowledgement = self
2328 .journal
2329 .as_ref()
2330 .expect("lazy journal writer installed above")
2331 .enqueue_critical_sync(prepared.line.clone(), prepared.known_existing)
2332 .map_err(|error| CriticalAppendError::Rejected {
2333 reason: error.to_string(),
2334 })?;
2335 let (index, line) = self.commit_prepared_critical(prepared);
2336 self.critical_pending.insert(line.clone());
2337 let result = match acknowledgement.recv_timeout(acknowledgement_timeout) {
2338 Ok(result) => result.map_err(|error| error.to_string()),
2339 Err(mpsc::RecvTimeoutError::Timeout) => Err(format!(
2340 "journal writer did not acknowledge within {}ms",
2341 acknowledgement_timeout.as_millis()
2342 )),
2343 Err(mpsc::RecvTimeoutError::Disconnected) => {
2344 Err("journal writer stopped before critical acknowledgement".to_string())
2345 }
2346 };
2347 match result {
2348 Ok(()) => {
2349 self.critical_pending.remove(&line);
2350 Ok(&self.events[index])
2351 }
2352 Err(reason) => Err(CriticalAppendError::DurabilityUnknown { reason }),
2353 }
2354 }
2355
2356 pub async fn append_critical_async(
2368 &mut self,
2369 kind: EventKind,
2370 action_id: Option<&str>,
2371 proposal_id: Option<&str>,
2372 data: HashMap<String, Value>,
2373 acknowledgement_timeout: Duration,
2374 ) -> Result<&Event, CriticalAppendError> {
2375 let reservation = self
2376 .journal
2377 .as_ref()
2378 .ok_or_else(|| CriticalAppendError::Rejected {
2379 reason: "critical lifecycle event requires an enabled journal".to_string(),
2380 })?
2381 .reserve_async_acknowledgement(acknowledgement_timeout)
2382 .map_err(|error| CriticalAppendError::Rejected {
2383 reason: error.to_string(),
2384 })?;
2385 let prepared = self
2386 .prepare_critical_append(kind, action_id, proposal_id, data)
2387 .map_err(|reason| CriticalAppendError::Rejected { reason })?;
2388 let acknowledgement = self
2389 .journal
2390 .as_ref()
2391 .expect("journal presence checked before reservation")
2392 .enqueue_critical_async(prepared.line.clone(), prepared.known_existing, reservation)
2393 .map_err(|error| CriticalAppendError::Rejected {
2394 reason: error.to_string(),
2395 })?;
2396 let (index, line) = self.commit_prepared_critical(prepared);
2397
2398 self.critical_pending.insert(line.clone());
2401 match acknowledgement.await {
2402 Ok(()) => {
2403 self.critical_pending.remove(&line);
2404 Ok(&self.events[index])
2405 }
2406 Err(error) => Err(CriticalAppendError::DurabilityUnknown {
2407 reason: error.to_string(),
2408 }),
2409 }
2410 }
2411
2412 pub fn verify_chain(&self) -> Result<usize, usize> {
2433 let mut prev = String::new();
2434 let mut verified = 0usize;
2435 let mut chain_started = false;
2436 for (i, ev) in self.events.iter().enumerate() {
2437 let Some(stored) = &ev.hash else {
2438 if chain_started {
2440 return Err(i);
2441 }
2442 continue;
2443 };
2444 let recorded_prev = ev.prev_hash.clone().unwrap_or_default();
2446 if chain_started && recorded_prev != prev {
2447 return Err(i);
2448 }
2449 let recomputed = event_digest(
2450 &recorded_prev,
2451 &ev.kind,
2452 ev.run_id.as_deref(),
2453 ev.client_id.as_deref(),
2454 ev.policy_session_id.as_deref(),
2455 ev.action_id.as_deref(),
2456 ev.proposal_id.as_deref(),
2457 &ev.data,
2458 &ev.timestamp,
2459 );
2460 if &recomputed != stored {
2461 return Err(i);
2462 }
2463 prev = stored.clone();
2464 chain_started = true;
2465 verified += 1;
2466 }
2467 Ok(verified)
2468 }
2469
2470 pub fn append_metered(
2477 &mut self,
2478 kind: EventKind,
2479 action_id: Option<&str>,
2480 proposal_id: Option<&str>,
2481 mut data: HashMap<String, Value>,
2482 metrics: Metrics,
2483 ) -> &Event {
2484 metrics.merge_into(&mut data);
2485 self.append(kind, action_id, proposal_id, data)
2486 }
2487
2488 pub fn metrics_totals(&self) -> MetricsTotals {
2500 metrics_totals_of(&self.events)
2501 }
2502
2503 pub fn cost_by_agent(&self) -> Vec<AgentCost> {
2505 cost_by_agent_of(&self.events)
2506 }
2507
2508 pub fn events(&self) -> &[Event] {
2509 &self.events
2510 }
2511
2512 pub fn len(&self) -> usize {
2513 self.events.len()
2514 }
2515
2516 pub fn span_len(&self) -> usize {
2517 self.spans.len()
2518 }
2519
2520 pub fn is_empty(&self) -> bool {
2521 self.events.is_empty()
2522 }
2523
2524 pub fn stats(&self) -> EventLogStats {
2525 EventLogStats {
2526 events: self.events.len(),
2527 spans: self.spans.len(),
2528 approx_event_bytes: approx_json_bytes(&self.events),
2529 approx_span_bytes: approx_json_bytes(&self.spans),
2530 }
2531 }
2532
2533 pub fn truncate_events_keep_last(&mut self, keep_last: usize) -> usize {
2534 let removed = truncate_vec_keep_last(&mut self.events, keep_last);
2535 self.trimmed_events += removed as u64;
2536 if removed > 0 {
2537 self.maybe_compact_journal();
2538 }
2539 removed
2540 }
2541
2542 pub fn truncate_spans_keep_last(&mut self, keep_last: usize) -> usize {
2543 truncate_vec_keep_last(&mut self.spans, keep_last)
2544 }
2545
2546 pub fn clear(&mut self) -> EventLogStats {
2551 let removed = self.stats();
2552 self.trimmed_events += removed.events as u64;
2553 self.events.clear();
2554 self.events.shrink_to_fit();
2555 self.spans.clear();
2556 self.spans.shrink_to_fit();
2557 removed
2558 }
2559
2560 pub fn trimmed_events(&self) -> u64 {
2566 self.trimmed_events
2567 }
2568
2569 pub fn cumulative_cost_usd(&self) -> f64 {
2576 self.cumulative_cost_usd
2577 }
2578
2579 pub fn journal_size_bytes(&self) -> Option<u64> {
2583 let path = self.journal_path.as_ref()?;
2584 fs::metadata(path).ok().map(|m| m.len())
2585 }
2586
2587 fn maybe_compact_journal(&mut self) {
2593 if self.journal_path.is_none() {
2594 return;
2595 }
2596 let excess = self.journal_lines.saturating_sub(self.events.len());
2597 if excess >= JOURNAL_COMPACT_MIN_EXCESS && excess.saturating_mul(4) >= self.journal_lines {
2598 self.compact_journal();
2599 }
2600 }
2601
2602 pub fn compact_journal(&mut self) -> bool {
2620 let Some(path) = self.journal_path.clone() else {
2621 return false;
2622 };
2623 let compacted_lines: HashSet<String> = self
2624 .events
2625 .iter()
2626 .filter_map(|event| serde_json::to_string(event).ok())
2627 .collect();
2628 self.journal = None;
2630 let file_name = path
2631 .file_name()
2632 .and_then(|name| name.to_str())
2633 .unwrap_or("journal");
2634 let tmp = path.with_file_name(format!(".{file_name}.compact-{}.tmp", Uuid::new_v4()));
2635 let rewrite = (|| -> std::io::Result<()> {
2636 let file = create_private_file(&tmp)?;
2637 let mut writer = BufWriter::new(file);
2638 for ev in &self.events {
2639 let line = serde_json::to_string(ev).map_err(std::io::Error::other)?;
2640 writeln!(writer, "{line}")?;
2641 }
2642 writer.flush()?;
2643 let file = writer.into_inner().map_err(|error| error.into_error())?;
2644 file.sync_all()?;
2645 revalidate_private_file(&file)?;
2646 drop(file);
2647 atomic_replace_private_file(&tmp, &path)
2648 })();
2649 let ok = match rewrite {
2650 Ok(()) => {
2651 self.journal_lines = self.events.len();
2652 self.critical_pending
2658 .retain(|line| !compacted_lines.contains(line));
2659 true
2660 }
2661 Err(e) => {
2662 let _ = fs::remove_file(&tmp);
2663 tracing::warn!(
2664 path = %path.display(), error = %e,
2665 "car-eventlog: journal compaction failed — journal keeps growing until the next successful compaction"
2666 );
2667 false
2668 }
2669 };
2670 self.journal = Some(JournalWriter::spawn(path));
2671 ok
2672 }
2673
2674 pub fn query(&self, query: &EventQuery) -> Vec<&Event> {
2677 let mut out: Vec<&Event> = self.events.iter().filter(|e| query.matches(e)).collect();
2678 out.reverse(); if let Some(limit) = query.limit.filter(|l| *l > 0) {
2680 out.truncate(limit);
2681 }
2682 out
2683 }
2684
2685 pub fn set_retention(&mut self, policy: Option<RetentionPolicy>) {
2689 self.retention = policy;
2690 }
2691
2692 pub fn retention(&self) -> Option<&RetentionPolicy> {
2694 self.retention.as_ref()
2695 }
2696
2697 pub fn enforce_retention(&mut self, policy: &RetentionPolicy, now: DateTime<Utc>) -> usize {
2705 let before = self.events.len();
2706 if let Some(age) = policy.max_age_secs {
2707 let cutoff = now - chrono::Duration::seconds(age);
2708 self.events.retain(|e| e.timestamp >= cutoff);
2709 }
2710 if let Some(max) = policy.max_events {
2711 truncate_vec_keep_last(&mut self.events, max);
2712 }
2713 let removed = before.saturating_sub(self.events.len());
2714 self.trimmed_events += removed as u64;
2715 if removed > 0 {
2716 self.maybe_compact_journal();
2717 }
2718 removed
2719 }
2720
2721 pub fn filter(&self, kind: Option<&EventKind>, action_id: Option<&str>) -> Vec<&Event> {
2722 self.events
2723 .iter()
2724 .filter(|e| {
2725 if let Some(k) = kind {
2726 if &e.kind != k {
2727 return false;
2728 }
2729 }
2730 if let Some(aid) = action_id {
2731 if e.action_id.as_deref() != Some(aid) {
2732 return false;
2733 }
2734 }
2735 true
2736 })
2737 .collect()
2738 }
2739
2740 pub fn begin_span(
2742 &mut self,
2743 name: &str,
2744 trace_id: &str,
2745 parent_span_id: Option<&str>,
2746 attributes: HashMap<String, Value>,
2747 ) -> String {
2748 let span_id = Uuid::new_v4().to_string();
2749 let span = Span {
2750 trace_id: trace_id.to_string(),
2751 span_id: span_id.clone(),
2752 parent_span_id: parent_span_id.map(|s| s.to_string()),
2753 name: name.to_string(),
2754 start_time: Utc::now(),
2755 end_time: None,
2756 status: SpanStatus::Unset,
2757 attributes,
2758 };
2759 self.spans.push(span);
2760 span_id
2761 }
2762
2763 pub fn end_span(&mut self, span_id: &str, status: SpanStatus) {
2765 if let Some(span) = self.spans.iter_mut().find(|s| s.span_id == span_id) {
2766 span.end_time = Some(Utc::now());
2767 span.status = status;
2768 }
2769 }
2770
2771 pub fn spans(&self) -> Vec<Span> {
2773 self.spans.clone()
2774 }
2775
2776 pub fn export_traces(&self) -> String {
2778 let mut traces: HashMap<&str, Vec<&Span>> = HashMap::new();
2780 for span in &self.spans {
2781 traces.entry(span.trace_id.as_str()).or_default().push(span);
2782 }
2783
2784 let resource_spans: Vec<Value> = traces.into_values().map(|spans| {
2785 let scope_spans = spans
2786 .iter()
2787 .map(|s| {
2788 let mut span_obj = serde_json::json!({
2789 "traceId": s.trace_id,
2790 "spanId": s.span_id,
2791 "name": s.name,
2792 "startTimeUnixNano": s.start_time.timestamp_nanos_opt().unwrap_or(0).to_string(),
2793 "status": {
2794 "code": match s.status {
2795 SpanStatus::Ok => 1,
2796 SpanStatus::Error => 2,
2797 SpanStatus::Unset => 0,
2798 }
2799 },
2800 "attributes": s.attributes.iter().map(|(k, v)| {
2801 serde_json::json!({
2802 "key": k,
2803 "value": { "stringValue": v.to_string() }
2804 })
2805 }).collect::<Vec<_>>(),
2806 });
2807
2808 if let Some(ref parent) = s.parent_span_id {
2809 span_obj.as_object_mut().unwrap().insert(
2810 "parentSpanId".to_string(),
2811 Value::from(parent.as_str()),
2812 );
2813 }
2814 if let Some(end) = s.end_time {
2815 span_obj.as_object_mut().unwrap().insert(
2816 "endTimeUnixNano".to_string(),
2817 Value::from(end.timestamp_nanos_opt().unwrap_or(0).to_string()),
2818 );
2819 }
2820
2821 span_obj
2822 })
2823 .collect::<Vec<_>>();
2824
2825 serde_json::json!({
2826 "resource": {
2827 "attributes": [
2828 { "key": "service.name", "value": { "stringValue": "car-runtime" } }
2829 ]
2830 },
2831 "scopeSpans": [{
2832 "scope": { "name": "car-eventlog" },
2833 "spans": scope_spans
2834 }]
2835 })
2836 })
2837 .collect();
2838
2839 serde_json::to_string(&serde_json::json!({
2840 "resourceSpans": resource_spans
2841 }))
2842 .unwrap_or_else(|_| "{}".to_string())
2843 }
2844
2845 pub fn load(path: &Path) -> std::io::Result<Self> {
2847 Self::load_with_writer(path, JournalWriter::spawn(path.to_path_buf()))
2848 }
2849
2850 pub fn load_for_reconciliation(path: &Path) -> std::io::Result<Self> {
2856 Self::load_from_journal(path, None, true)
2857 }
2858
2859 pub fn load_read_only(path: &Path) -> std::io::Result<Self> {
2864 Self::load_from_journal(path, None, false)
2865 }
2866
2867 #[doc(hidden)]
2870 pub fn load_with_journal_failure_injector(
2871 path: &Path,
2872 failures: JournalFailureInjector,
2873 ) -> std::io::Result<Self> {
2874 Self::load_with_writer(
2875 path,
2876 JournalWriter::spawn_with_injector(path.to_path_buf(), failures),
2877 )
2878 }
2879
2880 fn load_with_writer(path: &Path, writer: JournalWriter) -> std::io::Result<Self> {
2881 Self::load_from_journal(path, Some(writer), true)
2882 }
2883
2884 fn load_from_journal(
2885 path: &Path,
2886 writer: Option<JournalWriter>,
2887 repair_torn_tail: bool,
2888 ) -> std::io::Result<Self> {
2889 let file = fs::File::open(path)?;
2890 let mut reader = BufReader::new(file);
2891 let mut events = Vec::new();
2892 let mut event_lines = Vec::new();
2893 let mut line_bytes = Vec::new();
2894 let mut line_number = 0usize;
2895 let mut torn_tail_line = None;
2896
2897 loop {
2898 line_bytes.clear();
2899 let bytes_read = reader.read_until(b'\n', &mut line_bytes)?;
2900 if bytes_read == 0 {
2901 break;
2902 }
2903 line_number += 1;
2904 let terminated = line_bytes.ends_with(b"\n");
2905 if line_bytes.iter().all(|byte| byte.is_ascii_whitespace()) {
2906 if !terminated {
2907 torn_tail_line = Some(line_number);
2908 }
2909 continue;
2910 }
2911 match serde_json::from_slice::<Event>(&line_bytes) {
2912 Ok(event) => {
2913 events.push(event);
2914 event_lines.push(line_number);
2915 if !terminated {
2916 torn_tail_line = Some(line_number);
2917 }
2918 }
2919 Err(_) if !terminated => {
2920 torn_tail_line = Some(line_number);
2925 }
2926 Err(error) => {
2927 return Err(invalid_journal_data(path, line_number, error));
2928 }
2929 }
2930 if !terminated {
2931 break;
2932 }
2933 }
2934 drop(reader);
2935
2936 let last_hash = events.last().and_then(|e| e.hash.clone());
2942 let hash_chaining = last_hash.is_some();
2943 let cumulative_cost_usd = events.iter().filter_map(Event::cost_usd).sum();
2948 let journal_lines = events.len();
2949 let loaded = Self {
2950 events,
2951 spans: Vec::new(),
2952 journal: writer,
2955 hash_chaining,
2956 last_hash,
2957 retention: None,
2958 journal_path: repair_torn_tail.then(|| path.to_path_buf()),
2959 journal_lines,
2960 trimmed_events: 0,
2961 cumulative_cost_usd,
2962 active_binding: None,
2963 critical_pending: HashSet::new(),
2964 };
2965 if let Err(index) = loaded.verify_chain() {
2966 let source_line = event_lines.get(index).copied().unwrap_or(index + 1);
2967 return Err(invalid_journal_data(
2968 path,
2969 source_line,
2970 "hash chain integrity check failed",
2971 ));
2972 }
2973 if let Some(line_number) = torn_tail_line {
2974 if !repair_torn_tail {
2975 return Err(torn_journal_tail(path, line_number));
2976 }
2977 rewrite_loaded_journal(path, &loaded.events)?;
2978 }
2979 Ok(loaded)
2980 }
2981}
2982
2983fn torn_journal_tail(path: &Path, line_number: usize) -> std::io::Error {
2984 std::io::Error::new(
2985 std::io::ErrorKind::UnexpectedEof,
2986 format!(
2987 "event journal torn tail: path={} line={} reason=unterminated final record",
2988 path.display(),
2989 line_number
2990 ),
2991 )
2992}
2993
2994fn invalid_journal_data(
2995 path: &Path,
2996 line_number: usize,
2997 reason: impl std::fmt::Display,
2998) -> std::io::Error {
2999 std::io::Error::new(
3000 std::io::ErrorKind::InvalidData,
3001 format!(
3002 "event journal corruption: path={} line={} reason={reason}",
3003 path.display(),
3004 line_number
3005 ),
3006 )
3007}
3008
3009fn rewrite_loaded_journal(path: &Path, events: &[Event]) -> std::io::Result<()> {
3010 let file_name = path
3011 .file_name()
3012 .and_then(|name| name.to_str())
3013 .unwrap_or("journal");
3014 let temp = path.with_file_name(format!(".{file_name}.recover-{}.tmp", Uuid::new_v4()));
3015 let result = (|| {
3016 let file = create_private_file(&temp)?;
3017 let mut output = BufWriter::new(file);
3018 for event in events {
3019 let line = serde_json::to_string(event).map_err(std::io::Error::other)?;
3020 writeln!(output, "{line}")?;
3021 }
3022 output.flush()?;
3023 let file = output.into_inner().map_err(|error| error.into_error())?;
3024 file.sync_all()?;
3025 revalidate_private_file(&file)?;
3026 drop(file);
3027 atomic_replace_private_file(&temp, path)
3028 })();
3029 if result.is_err() {
3030 let _ = fs::remove_file(&temp);
3031 }
3032 result
3033}
3034
3035fn approx_json_bytes<T: Serialize>(value: &T) -> usize {
3036 serde_json::to_vec(value)
3037 .map(|bytes| bytes.len())
3038 .unwrap_or(0)
3039}
3040
3041fn truncate_vec_keep_last<T>(items: &mut Vec<T>, keep_last: usize) -> usize {
3042 let len = items.len();
3043 if len <= keep_last {
3044 return 0;
3045 }
3046 let removed = len - keep_last;
3047 items.drain(..removed);
3048 items.shrink_to_fit();
3049 removed
3050}
3051
3052impl Default for EventLog {
3053 fn default() -> Self {
3054 Self::new()
3055 }
3056}
3057
3058#[cfg(test)]
3059mod tests {
3060 use super::*;
3061
3062 struct ThreadWake(std::thread::Thread);
3063
3064 impl std::task::Wake for ThreadWake {
3065 fn wake(self: Arc<Self>) {
3066 self.0.unpark();
3067 }
3068
3069 fn wake_by_ref(self: &Arc<Self>) {
3070 self.0.unpark();
3071 }
3072 }
3073
3074 fn test_waker() -> std::task::Waker {
3075 std::task::Waker::from(Arc::new(ThreadWake(std::thread::current())))
3076 }
3077
3078 fn block_on_test_future<F: std::future::Future>(future: F) -> F::Output {
3079 let waker = test_waker();
3080 let mut context = std::task::Context::from_waker(&waker);
3081 let mut future = Box::pin(future);
3082 loop {
3083 match future.as_mut().poll(&mut context) {
3084 std::task::Poll::Ready(output) => return output,
3085 std::task::Poll::Pending => std::thread::park(),
3086 }
3087 }
3088 }
3089
3090 #[test]
3091 fn append_and_read() {
3092 let mut log = EventLog::new();
3093 log.append(
3094 EventKind::ProposalReceived,
3095 None,
3096 Some("p1"),
3097 [("source".to_string(), Value::from("test"))].into(),
3098 );
3099 assert_eq!(log.len(), 1);
3100 assert_eq!(log.events()[0].kind, EventKind::ProposalReceived);
3101 }
3102
3103 #[test]
3104 fn query_filters_by_kind_data_and_time() {
3105 let mut log = EventLog::new();
3106 log.append(
3107 EventKind::PermissionDecision,
3108 Some("a1"),
3109 None,
3110 [
3111 ("caller".to_string(), Value::from("alice")),
3112 ("tool".to_string(), Value::from("shell")),
3113 ]
3114 .into(),
3115 );
3116 log.append(
3117 EventKind::PermissionDecision,
3118 Some("a2"),
3119 None,
3120 [
3121 ("caller".to_string(), Value::from("bob")),
3122 ("tool".to_string(), Value::from("shell")),
3123 ]
3124 .into(),
3125 );
3126 log.append(
3127 EventKind::StateChanged,
3128 Some("a3"),
3129 None,
3130 Default::default(),
3131 );
3132
3133 let q = EventQuery {
3135 kinds: vec![EventKind::PermissionDecision],
3136 ..Default::default()
3137 };
3138 assert_eq!(log.query(&q).len(), 2);
3139
3140 let q = EventQuery {
3142 data_matches: [("caller".to_string(), "alice".to_string())].into(),
3143 ..Default::default()
3144 };
3145 let hits = log.query(&q);
3146 assert_eq!(hits.len(), 1);
3147 assert_eq!(hits[0].action_id.as_deref(), Some("a1"));
3148
3149 let q = EventQuery {
3151 kinds: vec![EventKind::PermissionDecision],
3152 data_matches: [("tool".to_string(), "shell".to_string())].into(),
3153 limit: Some(1),
3154 ..Default::default()
3155 };
3156 let hits = log.query(&q);
3158 assert_eq!(hits.len(), 1);
3159 assert_eq!(hits[0].action_id.as_deref(), Some("a2"));
3160 }
3161
3162 #[test]
3163 fn cost_by_agent_keeps_unknown_costs_unknown_and_unattributed_apart() {
3164 let mut log = EventLog::new();
3165 let row =
3166 |log: &mut EventLog, agent: Option<&str>, source: Option<&str>, cost: Option<f64>| {
3167 let mut data: HashMap<String, Value> = HashMap::new();
3168 if let Some(agent) = agent {
3169 data.insert("agent".into(), Value::from(agent));
3170 }
3171 if let Some(source) = source {
3172 data.insert("cost_source".into(), Value::from(source));
3173 }
3174 log.append_metered(
3175 EventKind::InferenceMetered,
3176 None,
3177 None,
3178 data,
3179 Metrics {
3180 cost_usd: cost,
3181 ..Default::default()
3182 },
3183 );
3184 };
3185 row(&mut log, Some("agent:a"), Some("list_price"), Some(0.25));
3186 row(&mut log, Some("agent:a"), Some("subscription"), Some(0.0));
3187 row(&mut log, Some("agent:a"), Some("unknown"), None);
3188 row(&mut log, Some("agent:a"), None, None);
3189 row(&mut log, Some("agent:a"), None, Some(0.5));
3190 row(&mut log, None, Some("provider"), Some(1.0));
3191 let report = log.cost_by_agent();
3192 let a = report.iter().find(|r| r.agent == "agent:a").unwrap();
3193 assert_eq!(a.calls, 5);
3194 assert_eq!(a.priced_calls, 2);
3195 assert_eq!(a.subscription_calls, 1);
3196 assert_eq!(a.unpriced_calls, 2, "an unknown cost is not a $0 one");
3197 assert!((a.cost_usd - 0.75).abs() < 1e-9);
3198 let unattributed = report
3199 .iter()
3200 .find(|r| r.agent == UNATTRIBUTED_AGENT)
3201 .expect("its own line");
3202 assert_eq!(unattributed.calls, 1);
3203 assert!((unattributed.cost_usd - 1.0).abs() < 1e-9);
3204 }
3205
3206 #[test]
3207 fn cost_by_agent_folds_metered_events() {
3208 let mut log = EventLog::new();
3209 log.append_metered(
3210 EventKind::InferenceMetered,
3211 None,
3212 None,
3213 [("agent".to_string(), Value::from("researcher"))].into(),
3214 Metrics {
3215 tokens_in: Some(100),
3216 tokens_out: Some(50),
3217 cost_usd: Some(2.0),
3218 ..Default::default()
3219 },
3220 );
3221 log.append_metered(
3222 EventKind::InferenceMetered,
3223 None,
3224 None,
3225 [("agent".to_string(), Value::from("researcher"))].into(),
3226 Metrics {
3227 tokens_in: Some(10),
3228 tokens_out: Some(5),
3229 cost_usd: Some(0.2),
3230 ..Default::default()
3231 },
3232 );
3233 log.append_metered(
3234 EventKind::InferenceMetered,
3235 None,
3236 None,
3237 [("agent".to_string(), Value::from("coordinator"))].into(),
3238 Metrics {
3239 cost_usd: Some(0.5),
3240 ..Default::default()
3241 },
3242 );
3243 let report = log.cost_by_agent();
3244 assert_eq!(report.len(), 2);
3245 assert_eq!(report[0].agent, "coordinator");
3247 assert_eq!(report[0].cost_usd, 0.5);
3248 assert_eq!(report[1].agent, "researcher");
3249 assert_eq!(report[1].calls, 2);
3250 assert_eq!(report[1].tokens_in, 110);
3251 assert_eq!(report[1].tokens_out, 55);
3252 assert!((report[1].cost_usd - 2.2).abs() < 1e-9);
3253 }
3254
3255 #[test]
3261 fn cost_by_agent_skips_summary_rows() {
3262 let mut log = EventLog::new();
3263 log.append_metered(
3265 EventKind::InferenceMetered,
3266 None,
3267 None,
3268 [
3269 ("agent".to_string(), Value::from("agent:bot")),
3270 ("call_id".to_string(), Value::from("call-1")),
3271 ]
3272 .into(),
3273 Metrics::inference(100, 50, Some(2.0)),
3274 );
3275 log.append_metered(
3277 EventKind::InferenceMetered,
3278 None,
3279 None,
3280 [
3281 ("agent".to_string(), Value::from("agent:bot")),
3282 ("sub_agent".to_string(), Value::from("Researcher")),
3283 (SUMMARY_OF.to_string(), Value::from("infer")),
3284 ("reported_cost_usd".to_string(), Value::from(2.0)),
3285 ]
3286 .into(),
3287 Metrics::inference(100, 50, Some(2.0)).with_duration(10.0),
3288 );
3289 log.append_metered(
3291 EventKind::InferenceMetered,
3292 None,
3293 None,
3294 [
3295 ("agent".to_string(), Value::from("agent:bot")),
3296 ("sub_agent".to_string(), Value::from("Verifier")),
3297 ("reported_cost_usd".to_string(), Value::from(0.5)),
3298 ]
3299 .into(),
3300 Metrics::inference(10, 5, Some(0.5)),
3301 );
3302 let report = log.cost_by_agent();
3303 assert_eq!(report.len(), 1, "{report:?}");
3304 let bot = &report[0];
3305 assert_eq!(bot.agent, "agent:bot");
3306 assert_eq!((bot.calls, bot.tokens_in, bot.tokens_out), (2, 110, 55));
3307 assert!((bot.cost_usd - 2.5).abs() < 1e-9, "{bot:?}");
3308 }
3309
3310 #[test]
3317 fn cost_by_agent_lists_ambiguous_reports_apart_from_measured_calls() {
3318 let mut log = EventLog::new();
3319 for (call, run) in [("call-1", "Researcher"), ("call-2", "Verifier")] {
3320 log.append_metered(
3321 EventKind::InferenceMetered,
3322 None,
3323 None,
3324 [
3325 ("agent".to_string(), Value::from("agent:bot")),
3326 ("call_id".to_string(), Value::from(call)),
3327 ]
3328 .into(),
3329 Metrics::inference(100, 50, Some(1.0)),
3330 );
3331 log.append_metered(
3332 EventKind::InferenceMetered,
3333 None,
3334 None,
3335 [
3336 ("agent".to_string(), Value::from("agent:bot")),
3337 ("sub_agent".to_string(), Value::from(run)),
3338 (SUMMARY_OF.to_string(), Value::from(SUMMARY_AMBIGUOUS)),
3339 ("reported_cost_usd".to_string(), Value::from(1.0)),
3340 ]
3341 .into(),
3342 Metrics::inference(100, 50, Some(1.0)),
3343 );
3344 }
3345 let report = log.cost_by_agent();
3346 assert_eq!(report.len(), 1, "{report:?}");
3347 let bot = &report[0];
3348 assert_eq!((bot.calls, bot.priced_calls), (2, 2), "{bot:?}");
3349 assert_eq!((bot.tokens_in, bot.tokens_out), (200, 100), "{bot:?}");
3350 assert!((bot.cost_usd - 2.0).abs() < 1e-9, "{bot:?}");
3351 assert_eq!(bot.ambiguous_reports, 2, "{bot:?}");
3352 assert!(
3353 (bot.ambiguous_reported_cost_usd - 2.0).abs() < 1e-9,
3354 "{bot:?}"
3355 );
3356 let totals = log.metrics_totals();
3357 assert!((totals.cost_usd - 2.0).abs() < 1e-9, "{totals:?}");
3358 assert_eq!(totals.tokens, 300);
3359 }
3360
3361 #[test]
3367 fn metrics_totals_skip_summary_rows() {
3368 let mut log = EventLog::new();
3369 log.append_metered(
3370 EventKind::InferenceMetered,
3371 None,
3372 None,
3373 [("call_id".to_string(), Value::from("call-1"))].into(),
3374 Metrics::inference(100, 50, Some(2.0)).with_duration(30.0),
3375 );
3376 log.append_metered(
3377 EventKind::InferenceMetered,
3378 None,
3379 None,
3380 [(SUMMARY_OF.to_string(), Value::from("infer"))].into(),
3381 Metrics::inference(100, 50, Some(2.0)).with_duration(45.0),
3382 );
3383 let t = log.metrics_totals();
3384 assert_eq!((t.tokens_in, t.tokens_out, t.tokens), (100, 50, 150));
3385 assert_eq!(t.cost_usd, 2.0);
3386 assert_eq!(t.duration_ms, 30.0);
3387 assert_eq!(t.metered_events, 1);
3388 assert_eq!(log.events()[1].tokens_in(), Some(100));
3390 assert_eq!(log.events()[1].cost_usd(), Some(2.0));
3391 }
3392
3393 #[test]
3394 fn auto_retention_caps_event_count() {
3395 let mut log = EventLog::new();
3396 log.set_retention(Some(RetentionPolicy {
3397 max_events: Some(3),
3398 max_age_secs: None,
3399 }));
3400 for i in 0..10 {
3401 log.append(
3402 EventKind::StateChanged,
3403 Some(&format!("a{i}")),
3404 None,
3405 Default::default(),
3406 );
3407 }
3408 assert_eq!(log.len(), 3);
3410 assert_eq!(log.events()[0].action_id.as_deref(), Some("a7"));
3411 assert_eq!(log.events()[2].action_id.as_deref(), Some("a9"));
3412 }
3413
3414 #[test]
3415 fn enforce_retention_drops_old_by_age() {
3416 let mut log = EventLog::new();
3417 log.append(
3419 EventKind::StateChanged,
3420 Some("old"),
3421 None,
3422 Default::default(),
3423 );
3424 log.events[0].timestamp = Utc::now() - chrono::Duration::seconds(3600);
3425 log.append(
3426 EventKind::StateChanged,
3427 Some("fresh"),
3428 None,
3429 Default::default(),
3430 );
3431
3432 let removed = log.enforce_retention(
3433 &RetentionPolicy {
3434 max_events: None,
3435 max_age_secs: Some(60),
3436 },
3437 Utc::now(),
3438 );
3439 assert_eq!(removed, 1);
3440 assert_eq!(log.len(), 1);
3441 assert_eq!(log.events()[0].action_id.as_deref(), Some("fresh"));
3442 }
3443
3444 #[test]
3445 fn retention_trims_are_counted() {
3446 let mut log = EventLog::new();
3447 log.set_retention(Some(RetentionPolicy {
3448 max_events: Some(2),
3449 max_age_secs: None,
3450 }));
3451 for i in 0..5 {
3452 log.append(
3453 EventKind::StateChanged,
3454 Some(&format!("a{i}")),
3455 None,
3456 Default::default(),
3457 );
3458 }
3459 assert_eq!(log.trimmed_events(), 3);
3460 assert_eq!(log.truncate_events_keep_last(1), 1);
3461 assert_eq!(log.trimmed_events(), 4);
3462 log.clear();
3463 assert_eq!(log.trimmed_events(), 5);
3464 }
3465
3466 #[test]
3467 fn cumulative_cost_is_monotonic_across_trims_and_reload() {
3468 let dir = tempfile::tempdir().unwrap();
3469 let journal = dir.path().join("cost.jsonl");
3470 {
3471 let mut log = EventLog::with_journal(journal.clone());
3472 log.set_retention(Some(RetentionPolicy {
3473 max_events: Some(1),
3474 max_age_secs: None,
3475 }));
3476 for _ in 0..4 {
3477 log.append_metered(
3478 EventKind::InferenceMetered,
3479 None,
3480 None,
3481 Default::default(),
3482 Metrics {
3483 cost_usd: Some(2.5),
3484 ..Default::default()
3485 },
3486 );
3487 }
3488 assert_eq!(log.len(), 1);
3490 assert!((log.cumulative_cost_usd() - 10.0).abs() < 1e-9);
3491 }
3492 let reloaded = EventLog::load(&journal).unwrap();
3495 assert!((reloaded.cumulative_cost_usd() - 10.0).abs() < 1e-9);
3496 }
3497
3498 #[test]
3499 fn journal_compaction_rewrites_to_retained_set() {
3500 let dir = tempfile::tempdir().unwrap();
3505 let journal = dir.path().join("compact.jsonl");
3506 let keep = 16usize;
3507 let total = keep + JOURNAL_COMPACT_MIN_EXCESS + 8;
3508 {
3509 let mut log = EventLog::with_journal(journal.clone());
3510 log.set_retention(Some(RetentionPolicy {
3511 max_events: Some(keep),
3512 max_age_secs: None,
3513 }));
3514 for i in 0..total {
3515 log.append(
3516 EventKind::ActionSucceeded,
3517 Some(&format!("a{i}")),
3518 None,
3519 HashMap::new(),
3520 );
3521 }
3522 assert_eq!(log.len(), keep);
3523 assert!(log.journal_size_bytes().unwrap_or(0) > 0);
3524 } let reloaded = EventLog::load(&journal).unwrap();
3528 assert!(
3529 reloaded.len() < total,
3530 "journal must have been compacted (got {} lines)",
3531 reloaded.len()
3532 );
3533 assert_eq!(
3535 reloaded.events().last().unwrap().action_id.as_deref(),
3536 Some(format!("a{}", total - 1).as_str())
3537 );
3538 }
3539
3540 #[test]
3541 fn compact_journal_preserves_hash_chain_of_retained_tail() {
3542 let dir = tempfile::tempdir().unwrap();
3546 let journal = dir.path().join("chained.jsonl");
3547 {
3548 let mut log = EventLog::with_journal(journal.clone()).with_hash_chaining();
3549 for i in 0..20 {
3550 log.append(
3551 EventKind::ActionSucceeded,
3552 Some(&format!("a{i}")),
3553 None,
3554 HashMap::new(),
3555 );
3556 }
3557 log.truncate_events_keep_last(5);
3559 assert!(log.compact_journal(), "compaction must succeed");
3560 log.append(
3563 EventKind::ActionSucceeded,
3564 Some("post"),
3565 None,
3566 HashMap::new(),
3567 );
3568 }
3569 let reloaded = EventLog::load(&journal).unwrap();
3570 assert_eq!(reloaded.len(), 6);
3571 assert_eq!(reloaded.verify_chain(), Ok(6), "retained tail must verify");
3572 assert_eq!(reloaded.events()[0].action_id.as_deref(), Some("a15"));
3573 assert_eq!(reloaded.events()[5].action_id.as_deref(), Some("post"));
3574 }
3575
3576 #[test]
3577 fn compact_journal_without_journal_is_noop() {
3578 let mut log = EventLog::new();
3579 log.append(EventKind::StateChanged, Some("a"), None, Default::default());
3580 assert!(!log.compact_journal());
3581 assert_eq!(log.journal_size_bytes(), None);
3582 }
3583
3584 #[test]
3585 fn chaining_off_by_default_no_hashes() {
3586 let mut log = EventLog::new();
3587 log.append(
3588 EventKind::ActionSucceeded,
3589 Some("a1"),
3590 Some("p1"),
3591 HashMap::new(),
3592 );
3593 assert!(!log.hash_chaining_enabled());
3594 assert!(log.events()[0].hash.is_none());
3595 assert!(log.events()[0].prev_hash.is_none());
3596 assert_eq!(log.verify_chain(), Ok(0));
3598 }
3599
3600 #[test]
3601 fn hash_chain_verifies_clean_log() {
3602 let mut log = EventLog::new().with_hash_chaining();
3603 for i in 0..5 {
3604 log.append(
3605 EventKind::ActionSucceeded,
3606 Some(&format!("a{i}")),
3607 Some("p"),
3608 [("i".to_string(), Value::from(i))].into(),
3609 );
3610 }
3611 assert!(log.events().iter().all(|e| e.hash.is_some()));
3613 assert_eq!(log.verify_chain(), Ok(5));
3614 assert_eq!(log.events()[0].prev_hash.as_deref(), Some(""));
3616 for w in log.events().windows(2) {
3618 assert_eq!(w[1].prev_hash, w[0].hash);
3619 }
3620 }
3621
3622 #[test]
3623 fn tampering_with_data_breaks_chain() {
3624 let mut log = EventLog::new().with_hash_chaining();
3625 for i in 0..4 {
3626 log.append(
3627 EventKind::ActionSucceeded,
3628 Some(&format!("a{i}")),
3629 Some("p"),
3630 [("v".to_string(), Value::from(i))].into(),
3631 );
3632 }
3633 assert_eq!(log.verify_chain(), Ok(4));
3634 log.events[2].data.insert("v".to_string(), Value::from(999));
3636 assert_eq!(log.verify_chain(), Err(2));
3638 }
3639
3640 #[test]
3641 fn deleting_an_event_breaks_chain() {
3642 let mut log = EventLog::new().with_hash_chaining();
3643 for i in 0..4 {
3644 log.append(
3645 EventKind::ActionSucceeded,
3646 Some(&format!("a{i}")),
3647 Some("p"),
3648 HashMap::new(),
3649 );
3650 }
3651 log.events.remove(1);
3654 assert_eq!(log.verify_chain(), Err(1));
3655 }
3656
3657 #[test]
3658 fn chain_survives_serialize_roundtrip() {
3659 let mut log = EventLog::new().with_hash_chaining();
3660 for i in 0..3 {
3661 log.append(
3662 EventKind::PermissionDecision,
3663 Some(&format!("a{i}")),
3664 Some("p"),
3665 [
3666 ("decision".to_string(), Value::from("allow")),
3667 ("nested".to_string(), serde_json::json!({"z": 1, "a": 2})),
3668 ]
3669 .into(),
3670 );
3671 }
3672 let lines: Vec<String> = log
3675 .events()
3676 .iter()
3677 .map(|e| serde_json::to_string(e).unwrap())
3678 .collect();
3679 let mut rebuilt = EventLog::new();
3680 for line in &lines {
3681 rebuilt.events.push(serde_json::from_str(line).unwrap());
3682 }
3683 assert_eq!(rebuilt.verify_chain(), Ok(3));
3684 }
3685
3686 #[test]
3687 fn chain_survives_journal_load_and_append() {
3688 let dir = tempfile::tempdir().unwrap();
3693 let journal = dir.path().join("chain.jsonl");
3694 {
3695 let mut log = EventLog::with_journal(journal.clone());
3696 log.enable_hash_chaining();
3697 log.append(EventKind::ActionSucceeded, Some("a1"), None, HashMap::new());
3698 log.append(EventKind::ActionSucceeded, Some("a2"), None, HashMap::new());
3699 } {
3702 let mut log = EventLog::load(&journal).unwrap();
3703 assert!(
3704 log.hash_chaining_enabled(),
3705 "loading a chained tail re-enables chaining"
3706 );
3707 log.append(EventKind::ActionSucceeded, Some("a3"), None, HashMap::new());
3708 assert_eq!(log.verify_chain(), Ok(3), "post-load append stays chained");
3709 }
3710
3711 let reloaded = EventLog::load(&journal).unwrap();
3713 assert_eq!(reloaded.len(), 3);
3714 assert_eq!(reloaded.verify_chain(), Ok(3));
3715
3716 let plain = dir.path().join("plain.jsonl");
3718 {
3719 let mut log = EventLog::with_journal(plain.clone());
3720 log.append(EventKind::ActionSucceeded, Some("a1"), None, HashMap::new());
3721 }
3722 let loaded = EventLog::load(&plain).unwrap();
3723 assert!(!loaded.hash_chaining_enabled(), "unchained tail stays off");
3724 }
3725
3726 #[test]
3727 fn metered_event_carries_metrics_in_data() {
3728 let mut log = EventLog::new();
3729 log.append_metered(
3730 EventKind::ActionSucceeded,
3731 Some("a1"),
3732 Some("p1"),
3733 [("tool".to_string(), Value::from("search"))].into(),
3734 Metrics::inference(120, 45, Some(0.0012)).with_duration(83.0),
3735 );
3736 let ev = &log.events()[0];
3737 assert_eq!(ev.data.get("tool").unwrap(), "search");
3739 assert_eq!(ev.duration_ms(), Some(83.0));
3740 assert_eq!(ev.tokens_in(), Some(120));
3741 assert_eq!(ev.tokens_out(), Some(45));
3742 assert_eq!(ev.cost_usd(), Some(0.0012));
3743 }
3744
3745 #[test]
3746 fn metrics_totals_sum_across_events() {
3747 let mut log = EventLog::new();
3748 log.append_metered(
3749 EventKind::ActionSucceeded,
3750 Some("a1"),
3751 None,
3752 HashMap::new(),
3753 Metrics::latency(50.0),
3754 );
3755 log.append_metered(
3756 EventKind::ActionSucceeded,
3757 Some("a2"),
3758 None,
3759 HashMap::new(),
3760 Metrics::inference(100, 20, Some(0.5)).with_duration(70.0),
3761 );
3762 log.append(EventKind::ProposalReceived, None, None, HashMap::new());
3764
3765 let t = log.metrics_totals();
3766 assert_eq!(t.duration_ms, 120.0);
3767 assert_eq!(t.tokens_in, 100);
3768 assert_eq!(t.tokens_out, 20);
3769 assert_eq!(t.tokens, 120);
3770 assert_eq!(t.cost_usd, 0.5);
3771 assert_eq!(t.metered_events, 2);
3772 }
3773
3774 #[test]
3775 fn metrics_totals_counts_raw_appended_duration_key() {
3776 let mut log = EventLog::new();
3781 log.append(
3782 EventKind::ActionSucceeded,
3783 Some("a1"),
3784 None,
3785 [(metric_keys::DURATION_MS.to_string(), Value::from(42.0))].into(),
3786 );
3787 let t = log.metrics_totals();
3788 assert_eq!(t.duration_ms, 42.0);
3789 assert_eq!(t.metered_events, 1);
3790 }
3791
3792 #[test]
3793 fn new_telemetry_event_kinds_serialize_snake_case() {
3794 let json = serde_json::to_string(&EventKind::BranchDecision).unwrap();
3796 assert_eq!(json, "\"branch_decision\"");
3797 let json = serde_json::to_string(&EventKind::AlternativeRejected).unwrap();
3798 assert_eq!(json, "\"alternative_rejected\"");
3799 let json = serde_json::to_string(&EventKind::InferenceMetered).unwrap();
3800 assert_eq!(json, "\"inference_metered\"");
3801 }
3802
3803 #[test]
3804 fn filter_by_kind() {
3805 let mut log = EventLog::new();
3806 log.append(
3807 EventKind::ProposalReceived,
3808 None,
3809 Some("p1"),
3810 HashMap::new(),
3811 );
3812 log.append(
3813 EventKind::ActionValidated,
3814 Some("a1"),
3815 Some("p1"),
3816 HashMap::new(),
3817 );
3818 log.append(
3819 EventKind::ActionSucceeded,
3820 Some("a1"),
3821 Some("p1"),
3822 HashMap::new(),
3823 );
3824
3825 let validated = log.filter(Some(&EventKind::ActionValidated), None);
3826 assert_eq!(validated.len(), 1);
3827 }
3828
3829 #[test]
3830 fn filter_by_action_id() {
3831 let mut log = EventLog::new();
3832 log.append(EventKind::ActionValidated, Some("a1"), None, HashMap::new());
3833 log.append(EventKind::ActionValidated, Some("a2"), None, HashMap::new());
3834
3835 let a1_events = log.filter(None, Some("a1"));
3836 assert_eq!(a1_events.len(), 1);
3837 }
3838
3839 #[test]
3840 fn journal_write_and_reload() {
3841 let dir = tempfile::tempdir().unwrap();
3842 let journal = dir.path().join("events.jsonl");
3843
3844 {
3845 let mut log = EventLog::with_journal(journal.clone());
3846 log.append(
3847 EventKind::ProposalReceived,
3848 None,
3849 Some("p1"),
3850 HashMap::new(),
3851 );
3852 log.append(
3853 EventKind::ActionSucceeded,
3854 Some("a1"),
3855 Some("p1"),
3856 HashMap::new(),
3857 );
3858 }
3859
3860 assert!(journal.exists());
3861
3862 let reloaded = EventLog::load(&journal).unwrap();
3863 assert_eq!(reloaded.len(), 2);
3864 assert_eq!(reloaded.events()[0].kind, EventKind::ProposalReceived);
3865 assert_eq!(reloaded.events()[1].kind, EventKind::ActionSucceeded);
3866 }
3867
3868 #[test]
3869 fn load_rejects_newline_terminated_corrupt_middle_before_later_terminal() {
3870 let dir = tempfile::tempdir().unwrap();
3871 let journal = dir.path().join("corrupt-middle.jsonl");
3872 let started = serde_json::json!({
3873 "kind": "run_started",
3874 "run_id": "run-corrupt",
3875 "client_id": "client-1",
3876 "data": {"agent_id": "daily-continuity-newsroom"},
3877 "timestamp": "2026-08-30T09:30:00Z"
3878 });
3879 let completed = serde_json::json!({
3880 "kind": "run_completed",
3881 "run_id": "run-corrupt",
3882 "client_id": "client-1",
3883 "data": {
3884 "completion_digest": "must-not-be-trusted",
3885 "termination": {"kind": "outcome", "status": "success", "outcome": {}}
3886 },
3887 "timestamp": "2026-08-30T10:00:00Z"
3888 });
3889 fs::write(
3890 &journal,
3891 format!("{started}\n{{this-is-not-json}}\n{completed}\n"),
3892 )
3893 .unwrap();
3894
3895 let error = match EventLog::load(&journal) {
3896 Ok(_) => panic!("newline-terminated middle corruption must fail closed"),
3897 Err(error) => error,
3898 };
3899 assert_eq!(error.kind(), std::io::ErrorKind::InvalidData);
3900 assert!(error.to_string().contains("line=2"), "{error}");
3901 }
3902
3903 #[test]
3904 fn load_repairs_crash_torn_final_record_before_append() {
3905 let dir = tempfile::tempdir().unwrap();
3906 let journal = dir.path().join("torn-tail.jsonl");
3907 let started = serde_json::json!({
3908 "kind": "run_started",
3909 "run_id": "run-torn",
3910 "client_id": "client-1",
3911 "data": {"agent_id": "daily-continuity-newsroom"},
3912 "timestamp": "2026-08-30T09:30:00Z"
3913 });
3914 let mut journal_file = create_private_file(&journal).unwrap();
3915 write!(journal_file, "{started}\n{{\"kind\":\"run_completed\"").unwrap();
3916 drop(journal_file);
3917
3918 {
3919 let mut loaded = EventLog::load(&journal).expect("torn final row is recoverable");
3920 assert_eq!(loaded.len(), 1);
3921 loaded.append(
3922 EventKind::ProposalReceived,
3923 None,
3924 Some("proposal-after-recovery"),
3925 HashMap::new(),
3926 );
3927 }
3928
3929 let bytes = fs::read_to_string(&journal).unwrap();
3930 assert!(!bytes.contains("{\"kind\":\"run_completed\""), "{bytes}");
3931 assert!(bytes.ends_with('\n'));
3932 let reloaded = EventLog::load(&journal).unwrap();
3933 assert_eq!(reloaded.len(), 2);
3934 assert_eq!(reloaded.events()[0].kind, EventKind::RunStarted);
3935 assert_eq!(reloaded.events()[1].kind, EventKind::ProposalReceived);
3936 }
3937
3938 #[test]
3939 fn load_read_only_rejects_a_torn_tail_without_modifying_the_journal() {
3940 let dir = tempfile::tempdir().unwrap();
3941 let journal = dir.path().join("read-only-torn-tail.jsonl");
3942 let started = serde_json::json!({
3943 "kind": "run_started",
3944 "run_id": "run-torn",
3945 "client_id": "client-1",
3946 "data": {"agent_id": "daily-continuity-newsroom"},
3947 "timestamp": "2026-08-30T09:30:00Z"
3948 });
3949 fs::write(&journal, format!("{started}\n{{\"kind\":\"run_completed\"")).unwrap();
3950 let before = fs::read(&journal).unwrap();
3951
3952 let error = match EventLog::load_read_only(&journal) {
3953 Ok(_) => panic!("read-only loading must expose a torn final row"),
3954 Err(error) => error,
3955 };
3956
3957 assert_eq!(error.kind(), std::io::ErrorKind::UnexpectedEof);
3958 assert!(error.to_string().contains("event journal torn tail"));
3959 assert!(error.to_string().contains("line=2"));
3960 assert_eq!(fs::read(&journal).unwrap(), before);
3961 }
3962
3963 #[test]
3964 fn load_rejects_existing_hash_chain_tampering() {
3965 let dir = tempfile::tempdir().unwrap();
3966 let journal = dir.path().join("tampered-chain.jsonl");
3967 {
3968 let mut log = EventLog::with_journal(journal.clone()).with_hash_chaining();
3969 log.append(
3970 EventKind::RunStarted,
3971 None,
3972 None,
3973 [(
3974 "agent_id".to_string(),
3975 Value::from("daily-continuity-newsroom"),
3976 )]
3977 .into(),
3978 );
3979 log.append(EventKind::RunCompleted, None, None, HashMap::new());
3980 }
3981 let mut rows: Vec<Value> = fs::read_to_string(&journal)
3982 .unwrap()
3983 .lines()
3984 .map(|line| serde_json::from_str(line).unwrap())
3985 .collect();
3986 rows[0]["data"]["agent_id"] = Value::from("tampered-agent");
3987 fs::write(
3988 &journal,
3989 rows.iter()
3990 .map(Value::to_string)
3991 .collect::<Vec<_>>()
3992 .join("\n")
3993 + "\n",
3994 )
3995 .unwrap();
3996
3997 let error = match EventLog::load(&journal) {
3998 Ok(_) => panic!("hash-chain tampering must fail closed during load"),
3999 Err(error) => error,
4000 };
4001 assert_eq!(error.kind(), std::io::ErrorKind::InvalidData);
4002 assert!(error.to_string().contains("hash chain"), "{error}");
4003 assert!(error.to_string().contains("line=1"), "{error}");
4004 }
4005
4006 #[cfg(unix)]
4007 fn unix_mode(path: &Path) -> u32 {
4008 use std::os::unix::fs::PermissionsExt;
4009 fs::symlink_metadata(path).unwrap().permissions().mode() & 0o777
4010 }
4011
4012 #[cfg(unix)]
4013 #[test]
4014 fn car_owned_journal_and_created_parents_are_private() {
4015 let root = tempfile::tempdir().unwrap();
4016 let parent = root.path().join("eventlogs").join("session");
4017 let journal = parent.join("events.jsonl");
4018 {
4019 let mut log = EventLog::with_journal(journal.clone());
4020 log.append(EventKind::StateChanged, Some("a1"), None, HashMap::new());
4021 }
4022
4023 assert_eq!(unix_mode(&root.path().join("eventlogs")), 0o700);
4024 assert_eq!(unix_mode(&parent), 0o700);
4025 assert_eq!(unix_mode(&journal), 0o600);
4026 }
4027
4028 #[cfg(unix)]
4029 #[test]
4030 fn append_hardens_preexisting_owned_permissive_journal() {
4031 use std::os::unix::fs::PermissionsExt;
4032
4033 let dir = tempfile::tempdir().unwrap();
4034 let journal = dir.path().join("events.jsonl");
4035 fs::write(&journal, b"").unwrap();
4036 fs::set_permissions(&journal, fs::Permissions::from_mode(0o644)).unwrap();
4037 {
4038 let mut log = EventLog::with_journal(journal.clone());
4039 log.append(EventKind::StateChanged, Some("a1"), None, HashMap::new());
4040 }
4041 assert_eq!(unix_mode(&journal), 0o600);
4042 }
4043
4044 #[cfg(unix)]
4045 #[test]
4046 fn journal_refuses_symlink_and_hardlink_destinations() {
4047 use std::os::unix::fs::symlink;
4048
4049 let dir = tempfile::tempdir().unwrap();
4050 let victim = dir.path().join("victim");
4051 fs::write(&victim, b"unchanged").unwrap();
4052
4053 for journal in [dir.path().join("symlink"), dir.path().join("hardlink")] {
4054 if journal.ends_with("symlink") {
4055 symlink(&victim, &journal).unwrap();
4056 } else {
4057 fs::hard_link(&victim, &journal).unwrap();
4058 }
4059 {
4060 let mut log = EventLog::with_journal(journal);
4061 log.append(EventKind::StateChanged, Some("a1"), None, HashMap::new());
4062 }
4063 assert_eq!(fs::read(&victim).unwrap(), b"unchanged");
4064 }
4065 }
4066
4067 #[cfg(unix)]
4068 #[test]
4069 fn journal_stops_if_the_opened_path_is_substituted() {
4070 let dir = tempfile::tempdir().unwrap();
4071 let journal = dir.path().join("events.jsonl");
4072 let moved = dir.path().join("moved.jsonl");
4073 let mut log = EventLog::with_journal(journal.clone());
4074 log.append(EventKind::StateChanged, Some("first"), None, HashMap::new());
4075
4076 let deadline = std::time::Instant::now() + crate::LOADED_WAIT;
4077 while fs::metadata(&journal).map_or(true, |metadata| metadata.len() == 0) {
4078 assert!(
4079 std::time::Instant::now() < deadline,
4080 "first event was not persisted"
4081 );
4082 std::thread::yield_now();
4083 }
4084 fs::rename(&journal, &moved).unwrap();
4085 let _substitute = create_private_file(&journal).unwrap();
4086 log.append(
4087 EventKind::StateChanged,
4088 Some("second"),
4089 None,
4090 HashMap::new(),
4091 );
4092 drop(log);
4093
4094 assert_eq!(EventLog::load(&moved).unwrap().len(), 1);
4095 assert_eq!(fs::metadata(&journal).unwrap().len(), 0);
4096 }
4097
4098 #[cfg(unix)]
4099 #[test]
4100 fn compaction_preserves_private_mode_and_leaves_no_temp_name() {
4101 let dir = tempfile::tempdir().unwrap();
4102 let journal = dir.path().join("events.jsonl");
4103 let mut log = EventLog::with_journal(journal.clone());
4104 for index in 0..4 {
4105 log.append(
4106 EventKind::StateChanged,
4107 Some(&format!("a{index}")),
4108 None,
4109 HashMap::new(),
4110 );
4111 }
4112 log.truncate_events_keep_last(2);
4113 assert!(log.compact_journal());
4114 drop(log);
4115
4116 assert_eq!(unix_mode(&journal), 0o600);
4117 let names: Vec<_> = fs::read_dir(dir.path())
4118 .unwrap()
4119 .map(|entry| entry.unwrap().file_name())
4120 .collect();
4121 assert_eq!(names, vec![journal.file_name().unwrap()]);
4122 }
4123
4124 #[cfg(unix)]
4125 #[test]
4126 fn historical_world_readable_journal_can_be_loaded_without_mutation() {
4127 use std::os::unix::fs::PermissionsExt;
4128
4129 let dir = tempfile::tempdir().unwrap();
4130 let journal = dir.path().join("historical.jsonl");
4131 let event = Event {
4132 kind: EventKind::StateChanged,
4133 run_id: None,
4134 client_id: None,
4135 policy_session_id: None,
4136 action_id: Some("historical".into()),
4137 proposal_id: None,
4138 data: HashMap::new(),
4139 timestamp: Utc::now(),
4140 prev_hash: None,
4141 hash: None,
4142 };
4143 fs::write(
4144 &journal,
4145 format!("{}\n", serde_json::to_string(&event).unwrap()),
4146 )
4147 .unwrap();
4148 fs::set_permissions(&journal, fs::Permissions::from_mode(0o644)).unwrap();
4149
4150 let loaded = EventLog::load(&journal).unwrap();
4151 assert_eq!(loaded.len(), 1);
4152 drop(loaded);
4153 assert_eq!(unix_mode(&journal), 0o644);
4154 }
4155
4156 #[test]
4157 fn journal_not_created_without_appends() {
4158 let dir = tempfile::tempdir().unwrap();
4162 let journal = dir.path().join("no-events.jsonl");
4163 {
4164 let _log = EventLog::with_journal(journal.clone());
4165 }
4168 assert!(
4169 !journal.exists(),
4170 "journal file must not be created when nothing is appended"
4171 );
4172 }
4173
4174 #[test]
4175 fn journal_preserves_order_and_count_under_burst() {
4176 let dir = tempfile::tempdir().unwrap();
4180 let journal = dir.path().join("burst.jsonl");
4181 {
4182 let mut log = EventLog::with_journal(journal.clone());
4183 for i in 0..500 {
4184 log.append(
4185 EventKind::ActionSucceeded,
4186 Some(&format!("a{i}")),
4187 None,
4188 HashMap::new(),
4189 );
4190 }
4191 } let reloaded = EventLog::load(&journal).unwrap();
4194 assert_eq!(reloaded.len(), 500, "no events lost");
4195 for (i, event) in reloaded.events().iter().enumerate() {
4196 assert_eq!(
4197 event.action_id.as_deref(),
4198 Some(format!("a{i}").as_str()),
4199 "order preserved at {i}"
4200 );
4201 }
4202 }
4203
4204 #[test]
4205 fn unopenable_journal_is_best_effort_not_fatal() {
4206 let dir = tempfile::tempdir().unwrap();
4210 let journal = dir.path().join("a-directory");
4211 fs::create_dir(&journal).unwrap(); let mut log = EventLog::with_journal(journal);
4214 log.append(
4215 EventKind::ProposalReceived,
4216 None,
4217 Some("p1"),
4218 HashMap::new(),
4219 );
4220 log.append(EventKind::ActionSucceeded, Some("a1"), None, HashMap::new());
4221 assert_eq!(
4222 log.len(),
4223 2,
4224 "in-memory log unaffected by an unwritable journal"
4225 );
4226 }
4228
4229 #[test]
4230 fn load_then_append_preserves_existing_and_adds() {
4231 let dir = tempfile::tempdir().unwrap();
4232 let journal = dir.path().join("resume.jsonl");
4233 {
4234 let mut log = EventLog::with_journal(journal.clone());
4235 log.append(
4236 EventKind::ProposalReceived,
4237 None,
4238 Some("p1"),
4239 HashMap::new(),
4240 );
4241 }
4242 {
4244 let mut log = EventLog::load(&journal).unwrap();
4245 assert_eq!(log.len(), 1);
4246 log.append(EventKind::ActionSucceeded, Some("a1"), None, HashMap::new());
4247 }
4248 let reloaded = EventLog::load(&journal).unwrap();
4249 assert_eq!(reloaded.len(), 2, "append-mode preserved the loaded line");
4250 assert_eq!(reloaded.events()[0].kind, EventKind::ProposalReceived);
4251 assert_eq!(reloaded.events()[1].kind, EventKind::ActionSucceeded);
4252 }
4253
4254 #[test]
4255 fn event_kind_serializes_snake_case() {
4256 assert_eq!(
4257 serde_json::to_string(&EventKind::ProposalReceived).unwrap(),
4258 "\"proposal_received\""
4259 );
4260 assert_eq!(
4261 serde_json::to_string(&EventKind::StateSnapshot).unwrap(),
4262 "\"state_snapshot\""
4263 );
4264 }
4265
4266 #[test]
4267 fn stats_truncate_and_clear_release_retained_entries() {
4268 let mut log = EventLog::new();
4269 for idx in 0..5 {
4270 log.append(
4271 EventKind::ActionSucceeded,
4272 Some(&format!("a{idx}")),
4273 Some("p1"),
4274 [("payload".to_string(), Value::from("x".repeat(16)))].into(),
4275 );
4276 log.begin_span("action.tool_call", "trace", None, HashMap::new());
4277 }
4278
4279 let stats = log.stats();
4280 assert_eq!(stats.events, 5);
4281 assert_eq!(stats.spans, 5);
4282 assert!(stats.approx_event_bytes > 0);
4283 assert!(stats.approx_span_bytes > 0);
4284
4285 assert_eq!(log.truncate_events_keep_last(2), 3);
4286 assert_eq!(log.truncate_spans_keep_last(1), 4);
4287 assert_eq!(log.len(), 2);
4288 assert_eq!(log.span_len(), 1);
4289 assert_eq!(log.events()[0].action_id.as_deref(), Some("a3"));
4290
4291 let removed = log.clear();
4292 assert_eq!(removed.events, 2);
4293 assert_eq!(removed.spans, 1);
4294 assert_eq!(log.len(), 0);
4295 assert_eq!(log.span_len(), 0);
4296 }
4297
4298 #[test]
4299 fn span_begin_end_lifecycle() {
4300 let mut log = EventLog::new();
4301 let trace_id = "trace-1".to_string();
4302
4303 let span_id = log.begin_span(
4304 "test.operation",
4305 &trace_id,
4306 None,
4307 [("key".to_string(), Value::from("value"))].into(),
4308 );
4309
4310 let spans = log.spans();
4311 assert_eq!(spans.len(), 1);
4312 assert_eq!(spans[0].name, "test.operation");
4313 assert_eq!(spans[0].trace_id, "trace-1");
4314 assert!(spans[0].parent_span_id.is_none());
4315 assert!(spans[0].end_time.is_none());
4316 assert_eq!(spans[0].status, SpanStatus::Unset);
4317
4318 log.end_span(&span_id, SpanStatus::Ok);
4319
4320 let spans = log.spans();
4321 assert!(spans[0].end_time.is_some());
4322 assert_eq!(spans[0].status, SpanStatus::Ok);
4323 }
4324
4325 #[test]
4326 fn span_parent_child_relationship() {
4327 let mut log = EventLog::new();
4328 let trace_id = "trace-2".to_string();
4329
4330 let parent_id = log.begin_span("parent.op", &trace_id, None, HashMap::new());
4331 let child_id = log.begin_span("child.op", &trace_id, Some(&parent_id), HashMap::new());
4332
4333 let spans = log.spans();
4334 assert_eq!(spans.len(), 2);
4335
4336 let child = spans.iter().find(|s| s.span_id == child_id).unwrap();
4337 assert_eq!(child.parent_span_id.as_deref(), Some(parent_id.as_str()));
4338 assert_eq!(child.trace_id, trace_id);
4339
4340 let parent = spans.iter().find(|s| s.span_id == parent_id).unwrap();
4341 assert!(parent.parent_span_id.is_none());
4342 }
4343
4344 #[test]
4345 fn export_traces_produces_valid_json() {
4346 let mut log = EventLog::new();
4347 let trace_id = "trace-3".to_string();
4348
4349 let root = log.begin_span(
4350 "proposal.execute",
4351 &trace_id,
4352 None,
4353 [("proposal_id".to_string(), Value::from("p1"))].into(),
4354 );
4355 let child = log.begin_span(
4356 "action.tool_call",
4357 &trace_id,
4358 Some(&root),
4359 [("tool".to_string(), Value::from("read_file"))].into(),
4360 );
4361 log.end_span(&child, SpanStatus::Ok);
4362 log.end_span(&root, SpanStatus::Ok);
4363
4364 let json_str = log.export_traces();
4365 let parsed: Value =
4366 serde_json::from_str(&json_str).expect("export_traces must produce valid JSON");
4367
4368 let resource_spans = parsed["resourceSpans"].as_array().unwrap();
4369 assert_eq!(resource_spans.len(), 1);
4370
4371 let scope_spans = &resource_spans[0]["scopeSpans"][0]["spans"];
4372 let spans_arr = scope_spans.as_array().unwrap();
4373 assert_eq!(spans_arr.len(), 2);
4374
4375 for span in spans_arr {
4377 assert!(span.get("traceId").is_some());
4378 assert!(span.get("spanId").is_some());
4379 assert!(span.get("name").is_some());
4380 assert!(span.get("startTimeUnixNano").is_some());
4381 assert!(span.get("endTimeUnixNano").is_some());
4382 assert!(span.get("status").is_some());
4383 }
4384
4385 let child_span = spans_arr
4387 .iter()
4388 .find(|s| s["name"] == "action.tool_call")
4389 .unwrap();
4390 assert!(child_span.get("parentSpanId").is_some());
4391 }
4392
4393 #[test]
4394 fn span_status_set_on_error() {
4395 let mut log = EventLog::new();
4396 let trace_id = "trace-4".to_string();
4397
4398 let span_id = log.begin_span("failing.op", &trace_id, None, HashMap::new());
4399 log.end_span(&span_id, SpanStatus::Error);
4400
4401 let spans = log.spans();
4402 assert_eq!(spans[0].status, SpanStatus::Error);
4403 assert!(spans[0].end_time.is_some());
4404 }
4405
4406 #[test]
4407 fn active_run_binding_stamps_every_new_event_and_rejects_conflicts() {
4408 let mut log = EventLog::new();
4409 log.bind_run("run-a", "client-a")
4410 .expect("first active run binds");
4411 log.bind_policy_session("policy-session-a")
4412 .expect("CAR-minted policy session binds inside the run");
4413
4414 log.append(
4415 EventKind::ProposalReceived,
4416 None,
4417 Some("same-proposal"),
4418 HashMap::new(),
4419 );
4420 log.append(
4421 EventKind::ActionSucceeded,
4422 Some("action-a"),
4423 Some("same-proposal"),
4424 HashMap::new(),
4425 );
4426
4427 for event in log.events() {
4428 assert_eq!(event.run_id.as_deref(), Some("run-a"));
4429 assert_eq!(event.client_id.as_deref(), Some("client-a"));
4430 assert_eq!(event.policy_session_id.as_deref(), Some("policy-session-a"));
4431 }
4432 assert!(log.bind_run("run-b", "client-a").is_err());
4433 assert!(log.bind_run("run-a", "client-b").is_err());
4434 assert!(log.clear_run_binding("run-b", "client-a").is_err());
4435 assert_eq!(
4436 log.active_run_binding(),
4437 Some(("run-a", "client-a", Some("policy-session-a")))
4438 );
4439
4440 log.clear_policy_session("policy-session-a")
4441 .expect("exact policy session clears");
4442 log.clear_run_binding("run-a", "client-a")
4443 .expect("exact active run clears");
4444 log.append(
4445 EventKind::ProposalReceived,
4446 None,
4447 Some("unbound-legacy"),
4448 HashMap::new(),
4449 );
4450 let legacy = log.events().last().unwrap();
4451 assert!(legacy.run_id.is_none());
4452 assert!(legacy.client_id.is_none());
4453 assert!(legacy.policy_session_id.is_none());
4454 }
4455
4456 #[test]
4457 fn historical_event_without_binding_fields_still_deserializes() {
4458 let historical = r#"{"kind":"proposal_received","proposal_id":"p-old","data":{},"timestamp":"2026-01-02T03:04:05Z"}"#;
4459 let event: Event = serde_json::from_str(historical).expect("historical event replays");
4460 assert!(event.run_id.is_none());
4461 assert!(event.client_id.is_none());
4462 assert!(event.policy_session_id.is_none());
4463 }
4464
4465 #[test]
4466 fn async_acknowledgement_timeout_wins_after_expiry_removal() {
4467 let manager = AsyncAcknowledgementManager::new(1);
4468 let barrier = AsyncAcknowledgementExpiryBarrier::new();
4469 manager.pause_next_expiry_after_removal(barrier.clone());
4470 let reservation = manager.reserve(Duration::from_millis(10)).unwrap();
4471 let sender = reservation.sender();
4472 let acknowledgement = reservation.into_future();
4473
4474 barrier.wait_until_removed();
4475 sender.send(Ok(()));
4476 let result = block_on_test_future(acknowledgement);
4477 barrier.allow_timeout_completion();
4478 manager.shutdown();
4479
4480 assert!(matches!(
4481 result,
4482 Err(CriticalPostAcceptanceError::AcknowledgementTimedOut { .. })
4483 ));
4484 }
4485
4486 #[test]
4487 fn async_acknowledgement_capacity_is_atomic_under_concurrent_reservation() {
4488 let manager = Arc::new(AsyncAcknowledgementManager::new(1));
4489 let barrier = Arc::new(std::sync::Barrier::new(3));
4490 let handles: Vec<_> = (0..2)
4491 .map(|_| {
4492 let manager = manager.clone();
4493 let barrier = barrier.clone();
4494 std::thread::spawn(move || {
4495 let reservation = manager.reserve(MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT);
4496 barrier.wait();
4497 reservation
4498 })
4499 })
4500 .collect();
4501
4502 barrier.wait();
4503 let results: Vec<_> = handles
4504 .into_iter()
4505 .map(|handle| handle.join().unwrap())
4506 .collect();
4507 assert_eq!(results.iter().filter(|result| result.is_ok()).count(), 1);
4508 assert_eq!(
4509 results
4510 .iter()
4511 .filter(|result| {
4512 matches!(
4513 result,
4514 Err(CriticalPreAcceptanceError::CapacityExhausted { capacity: 1 })
4515 )
4516 })
4517 .count(),
4518 1
4519 );
4520 drop(results);
4521 manager.shutdown();
4522 }
4523
4524 #[test]
4525 fn async_acknowledgement_completed_before_future_construction_is_observed() {
4526 let manager = AsyncAcknowledgementManager::new(1);
4527 let reservation = manager
4529 .reserve(MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT)
4530 .unwrap();
4531 reservation.sender().send(Ok(()));
4532 let acknowledgement = reservation.into_future();
4533
4534 assert!(block_on_test_future(acknowledgement).is_ok());
4535 manager.shutdown();
4536 }
4537
4538 #[test]
4539 fn journal_writer_drop_completes_pending_async_acknowledgement() {
4540 let dir = tempfile::tempdir().unwrap();
4541 let failures = JournalFailureInjector::default();
4542 failures.fail_next(JournalFailurePoint::HoldAcknowledgement);
4543 let writer = JournalWriter::spawn_with_injector(
4544 dir.path().join("pending-ack-shutdown.jsonl"),
4545 failures.clone(),
4546 );
4547 let reservation = writer
4548 .reserve_async_acknowledgement(MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT)
4549 .unwrap();
4550 let acknowledgement = writer
4551 .enqueue_critical_async("{}".to_string(), false, reservation)
4552 .unwrap();
4553 let deadline = Instant::now() + crate::LOADED_WAIT;
4554 while failures.held_acknowledgement_count() == 0 {
4555 assert!(
4556 Instant::now() < deadline,
4557 "writer never retained the pending acknowledgement"
4558 );
4559 std::thread::yield_now();
4560 }
4561
4562 drop(writer);
4563 let result = block_on_test_future(acknowledgement);
4564 assert!(matches!(
4565 result,
4566 Err(CriticalPostAcceptanceError::CoordinatorStopped)
4567 ));
4568 failures.release_held_acknowledgements();
4569 }
4570
4571 #[test]
4572 fn startup_reconciliation_opens_a_writer_only_for_a_missing_row() {
4573 let dir = tempfile::tempdir().unwrap();
4574 let path = dir.path().join("startup-lazy.jsonl");
4575 let data = HashMap::from([("completion_digest".to_string(), Value::from("durable"))]);
4576 let mut original = EventLog::with_journal(path.clone());
4577 original.bind_run("run", "client").unwrap();
4578 original
4579 .append_critical_bounded(
4580 EventKind::RunCompleted,
4581 None,
4582 None,
4583 data.clone(),
4584 MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT,
4585 )
4586 .unwrap();
4587 drop(original);
4588
4589 let mut resumed = EventLog::load_for_reconciliation(&path).unwrap();
4590 resumed.bind_run("run", "client").unwrap();
4591 resumed
4592 .append_critical_bounded(
4593 EventKind::RunCompleted,
4594 None,
4595 None,
4596 data,
4597 MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT,
4598 )
4599 .unwrap();
4600 assert!(
4601 resumed.journal.is_none(),
4602 "a row that survived restart needs no append writer"
4603 );
4604
4605 resumed
4606 .append_critical_bounded(
4607 EventKind::ProposalCompleted,
4608 None,
4609 Some("missing"),
4610 HashMap::new(),
4611 MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT,
4612 )
4613 .unwrap();
4614 assert!(
4615 resumed.journal.is_some(),
4616 "a missing row must attach a writer before acknowledging durability"
4617 );
4618 }
4619
4620 #[test]
4621 fn prepare_failure_releases_async_acknowledgement_capacity() {
4622 let dir = tempfile::tempdir().unwrap();
4623 let mut log = EventLog::with_journal_failure_injector_and_ack_capacity(
4624 dir.path().join("prepare-failure-capacity.jsonl"),
4625 JournalFailureInjector::default(),
4626 1,
4627 );
4628 let data = HashMap::from([("completion_digest".to_string(), Value::from("7".repeat(64)))]);
4629
4630 let error = block_on_test_future(log.append_critical_async(
4631 EventKind::RunCompleted,
4632 None,
4633 None,
4634 data.clone(),
4635 Duration::from_secs(1),
4636 ))
4637 .expect_err("an unbound critical event must fail during preparation");
4638 assert!(matches!(error, CriticalAppendError::Rejected { .. }));
4639
4640 log.bind_run("run-after-prepare-failure", "client-after-prepare-failure")
4641 .unwrap();
4642 block_on_test_future(log.append_critical_async(
4643 EventKind::RunCompleted,
4644 None,
4645 None,
4646 data,
4647 MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT,
4648 ))
4649 .expect("the failed preparation must release the only acknowledgement slot");
4650 }
4651
4652 #[test]
4653 fn async_critical_preacceptance_failures_reject_without_fabricating_events() {
4654 let data = HashMap::from([("completion_digest".to_string(), Value::from("f".repeat(64)))]);
4655
4656 let mut no_journal = EventLog::new();
4657 no_journal
4658 .bind_run("run-no-writer", "client-no-writer")
4659 .unwrap();
4660 let error = block_on_test_future(no_journal.append_critical_async(
4661 EventKind::RunCompleted,
4662 None,
4663 None,
4664 data.clone(),
4665 Duration::from_millis(100),
4666 ))
4667 .expect_err("a missing writer must reject before acceptance");
4668 assert!(matches!(error, CriticalAppendError::Rejected { .. }));
4669 assert!(!error.is_retry_safe());
4670 assert!(no_journal.events().is_empty());
4671 assert!(no_journal.critical_pending.is_empty());
4672
4673 let dir = tempfile::tempdir().unwrap();
4674 let unavailable_path = dir.path().join("sender-missing.jsonl");
4675 let mut unavailable = EventLog::with_journal(unavailable_path.clone());
4676 unavailable
4677 .bind_run("run-sender-missing", "client-sender-missing")
4678 .unwrap();
4679 unavailable
4680 .journal
4681 .as_mut()
4682 .unwrap()
4683 .remove_sender_for_test();
4684 let error = block_on_test_future(unavailable.append_critical_async(
4685 EventKind::RunCompleted,
4686 None,
4687 None,
4688 data.clone(),
4689 Duration::from_millis(100),
4690 ))
4691 .expect_err("a missing writer sender must reject before event construction");
4692 assert!(matches!(error, CriticalAppendError::Rejected { .. }));
4693 assert!(unavailable.events().is_empty());
4694 assert!(unavailable.critical_pending.is_empty());
4695 assert!(!unavailable_path.exists());
4696
4697 let stopped_path = dir.path().join("receiver-stopped.jsonl");
4698 let mut stopped = EventLog::with_journal(stopped_path.clone());
4699 stopped
4700 .bind_run("run-receiver-stopped", "client-receiver-stopped")
4701 .unwrap();
4702 stopped.journal.as_mut().unwrap().stop_receiver_for_test();
4703 let error = block_on_test_future(stopped.append_critical_async(
4704 EventKind::RunCompleted,
4705 None,
4706 None,
4707 data,
4708 Duration::from_millis(100),
4709 ))
4710 .expect_err("a stopped writer receiver must reject a failed enqueue");
4711 assert!(matches!(error, CriticalAppendError::Rejected { .. }));
4712 assert!(stopped.events().is_empty());
4713 assert!(stopped.critical_pending.is_empty());
4714 assert!(!stopped_path.exists());
4715 }
4716
4717 #[test]
4718 fn async_critical_rejects_excessive_acknowledgement_duration_before_enqueue() {
4719 let dir = tempfile::tempdir().unwrap();
4720 let path = dir.path().join("excessive-ack-duration.jsonl");
4721 let mut log = EventLog::with_journal(path.clone());
4722 log.bind_run("run-excessive-ack", "client-excessive-ack")
4723 .unwrap();
4724
4725 let error = block_on_test_future(log.append_critical_async(
4726 EventKind::RunCompleted,
4727 None,
4728 None,
4729 HashMap::new(),
4730 MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT + Duration::from_millis(1),
4732 ))
4733 .expect_err("an excessive acknowledgement duration must reject");
4734
4735 assert!(matches!(error, CriticalAppendError::Rejected { .. }));
4736 assert!(log.events().is_empty());
4737 assert!(log.critical_pending.is_empty());
4738 assert!(!path.exists());
4739 }
4740
4741 #[test]
4742 fn async_critical_capacity_exhaustion_rejects_before_enqueue_and_exact_retry_unblocks() {
4743 let dir = tempfile::tempdir().unwrap();
4744 let path = dir.path().join("critical-ack-capacity.jsonl");
4745 let failures = JournalFailureInjector::default();
4746 failures.fail_next(JournalFailurePoint::HoldAcknowledgement);
4747 let mut log = EventLog::with_journal_failure_injector_and_ack_capacity(
4748 path.clone(),
4749 failures.clone(),
4750 1,
4751 );
4752 log.bind_run("run-capacity", "client-capacity").unwrap();
4753 let first_data =
4754 HashMap::from([("completion_digest".to_string(), Value::from("1".repeat(64)))]);
4755 let second_data =
4756 HashMap::from([("completion_digest".to_string(), Value::from("2".repeat(64)))]);
4757
4758 let mut first = Box::pin(log.append_critical_async(
4759 EventKind::RunCompleted,
4760 None,
4761 None,
4762 first_data.clone(),
4763 MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT,
4764 ));
4765 let waker = test_waker();
4766 let mut context = std::task::Context::from_waker(&waker);
4767 assert!(matches!(
4768 first.as_mut().poll(&mut context),
4769 std::task::Poll::Pending
4770 ));
4771 drop(first);
4772 assert_eq!(log.events().len(), 1);
4773 assert_eq!(log.critical_pending.len(), 1);
4774
4775 for attempt in 0..100 {
4776 let error = block_on_test_future(log.append_critical_async(
4777 EventKind::ProposalCompleted,
4778 None,
4779 Some("capacity-rejected"),
4780 second_data.clone(),
4781 Duration::from_millis(100),
4782 ))
4783 .expect_err("exhausted acknowledgement capacity must reject");
4784 let CriticalAppendError::Rejected { reason } = error else {
4785 panic!("attempt {attempt} was not a pre-enqueue rejection");
4786 };
4787 assert!(
4788 reason.contains("acknowledgement capacity is exhausted"),
4789 "attempt {attempt} bypassed capacity admission: {reason}"
4790 );
4791 assert_eq!(log.events().len(), 1);
4792 assert_eq!(log.critical_pending.len(), 1);
4793 }
4794
4795 let hold_deadline = std::time::Instant::now() + crate::LOADED_WAIT;
4796 while failures.held_acknowledgement_count() == 0 {
4797 assert!(
4798 std::time::Instant::now() < hold_deadline,
4799 "writer never reached the held acknowledgement"
4800 );
4801 std::thread::yield_now();
4802 }
4803 let pending_line = serde_json::to_string(&log.events()[0]).unwrap();
4804 assert_eq!(
4805 fs::read_to_string(&path).unwrap(),
4806 format!("{pending_line}\n")
4807 );
4808 failures.release_held_acknowledgements();
4809
4810 let original_timestamp = log.events()[0].timestamp;
4811 let retried = block_on_test_future(log.append_critical_async(
4812 EventKind::RunCompleted,
4813 None,
4814 None,
4815 first_data,
4816 MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT,
4817 ))
4818 .expect("the exact cancelled row must reconcile pending state");
4819 assert_eq!(retried.timestamp, original_timestamp);
4820 assert!(log.critical_pending.is_empty());
4821
4822 block_on_test_future(log.append_critical_async(
4823 EventKind::ProposalCompleted,
4824 None,
4825 Some("capacity-rejected"),
4826 second_data,
4827 MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT,
4828 ))
4829 .expect("a distinct row is allowed after exact reconciliation");
4830 drop(log);
4831
4832 let loaded = EventLog::load(&path).unwrap();
4833 assert_eq!(loaded.events().len(), 2);
4834 assert_eq!(loaded.events()[0].kind, EventKind::RunCompleted);
4835 assert_eq!(loaded.events()[1].kind, EventKind::ProposalCompleted);
4836 }
4837
4838 #[test]
4839 fn async_critical_never_acknowledged_row_remains_exactly_retryable() {
4840 let dir = tempfile::tempdir().unwrap();
4841 let path = dir.path().join("critical-never-acknowledged.jsonl");
4842 let failures = JournalFailureInjector::default();
4843 failures.fail_next(JournalFailurePoint::HoldAcknowledgement);
4844 let mut log = EventLog::with_journal_failure_injector(path.clone(), failures.clone());
4845 log.bind_run("run-never-ack", "client-never-ack").unwrap();
4846 let data = HashMap::from([("completion_digest".to_string(), Value::from("9".repeat(64)))]);
4847
4848 let error = block_on_test_future(log.append_critical_async(
4849 EventKind::RunCompleted,
4850 None,
4851 None,
4852 data.clone(),
4853 Duration::from_millis(20),
4855 ))
4856 .expect_err("the first acknowledgement is retained forever");
4857 assert!(matches!(
4858 error,
4859 CriticalAppendError::DurabilityUnknown { .. }
4860 ));
4861 let original = serde_json::to_string(&log.events()[0]).unwrap();
4862 assert!(log.critical_pending.contains(&original));
4863
4864 let retried = block_on_test_future(log.append_critical_async(
4865 EventKind::RunCompleted,
4866 None,
4867 None,
4868 data,
4869 MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT,
4870 ))
4871 .expect("the exact row must reconcile without the first acknowledgement");
4872 assert_eq!(serde_json::to_string(retried).unwrap(), original);
4873 assert!(log.critical_pending.is_empty());
4874 assert_eq!(
4875 failures.held_acknowledgement_count(),
4876 1,
4877 "the original acknowledgement must remain unsent"
4878 );
4879 drop(log);
4880
4881 assert_eq!(fs::read_to_string(&path).unwrap(), format!("{original}\n"));
4882 assert_eq!(EventLog::load(&path).unwrap().events().len(), 1);
4883 }
4884
4885 #[test]
4886 fn bounded_sync_critical_timeout_is_exactly_retryable() {
4887 let dir = tempfile::tempdir().unwrap();
4888 let path = dir.path().join("critical-bounded-sync-timeout.jsonl");
4889 let failures = JournalFailureInjector::default();
4890 failures.fail_next(JournalFailurePoint::HoldAcknowledgement);
4891 let mut log = EventLog::with_journal_failure_injector(path.clone(), failures.clone());
4892 log.bind_run("run-bounded-sync", "client-bounded-sync")
4893 .unwrap();
4894 let data = HashMap::from([("completion_digest".to_string(), Value::from("7".repeat(64)))]);
4895
4896 let error = log
4897 .append_critical_bounded(
4898 EventKind::RunCompleted,
4899 None,
4900 None,
4901 data.clone(),
4902 Duration::from_millis(20),
4904 )
4905 .expect_err("the retained acknowledgement must hit the exact sync bound");
4906 assert_eq!(
4907 error,
4908 CriticalAppendError::DurabilityUnknown {
4909 reason: "journal writer did not acknowledge within 20ms".to_string()
4910 }
4911 );
4912 assert!(error.is_retry_safe());
4913 let pending = log
4914 .critical_pending
4915 .iter()
4916 .next()
4917 .expect("the exact timed-out row remains pending")
4918 .clone();
4919 assert_eq!(pending, serde_json::to_string(&log.events()[0]).unwrap());
4920
4921 let retried = log
4922 .append_critical_bounded(
4923 EventKind::RunCompleted,
4924 None,
4925 None,
4926 data,
4927 MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT,
4928 )
4929 .expect("an exact retry must reconcile without the held acknowledgement");
4930 assert_eq!(serde_json::to_string(retried).unwrap(), pending);
4931 assert!(log.critical_pending.is_empty());
4932 assert_eq!(failures.held_acknowledgement_count(), 1);
4933 drop(log);
4934 assert_eq!(fs::read_to_string(&path).unwrap(), format!("{pending}\n"));
4935 }
4936
4937 #[test]
4938 fn async_critical_append_bounds_unknown_ack_and_preserves_exact_retry() {
4939 let dir = tempfile::tempdir().unwrap();
4940 let path = dir.path().join("critical-unknown-ack.jsonl");
4941 let failures = JournalFailureInjector::default();
4942 failures.fail_next(JournalFailurePoint::HoldAcknowledgement);
4943 let mut log = EventLog::with_journal_failure_injector(path.clone(), failures.clone());
4944 log.bind_run("run-unknown-ack", "client-unknown-ack")
4945 .unwrap();
4946 let data = HashMap::from([("completion_digest".to_string(), Value::from("e".repeat(64)))]);
4947
4948 let started = std::time::Instant::now();
4949 let error = block_on_test_future(log.append_critical_async(
4950 EventKind::RunCompleted,
4951 None,
4952 None,
4953 data.clone(),
4954 std::time::Duration::from_millis(40),
4956 ))
4957 .expect_err("a retained acknowledgement must become durability-unknown");
4958 assert!(
4959 started.elapsed() < std::time::Duration::from_secs(10),
4961 "the async acknowledgement wait exceeded its bounded allowance"
4962 );
4963 assert!(matches!(
4964 error,
4965 CriticalAppendError::DurabilityUnknown { .. }
4966 ));
4967 assert!(error.is_retry_safe());
4968 assert!(error
4969 .to_string()
4970 .contains("did not acknowledge within 40ms"));
4971
4972 let pending = log
4973 .critical_pending
4974 .iter()
4975 .next()
4976 .expect("the exact unacknowledged row remains pending")
4977 .clone();
4978 assert_eq!(log.critical_pending.len(), 1);
4979 assert_eq!(pending, serde_json::to_string(&log.events()[0]).unwrap());
4980 let disk_row = format!("{pending}\n");
4981 let writer_deadline = std::time::Instant::now() + crate::LOADED_WAIT;
4982 while fs::read_to_string(&path).unwrap_or_default() != disk_row {
4983 assert!(
4984 std::time::Instant::now() < writer_deadline,
4985 "the writer never durably accepted the held-acknowledgement row"
4986 );
4987 std::thread::yield_now();
4988 }
4989 while failures.held_acknowledgement_count() == 0 {
4990 assert!(
4991 std::time::Instant::now() < writer_deadline,
4992 "the writer never retained the late acknowledgement"
4993 );
4994 std::thread::yield_now();
4995 }
4996 assert_eq!(failures.held_acknowledgement_count(), 1);
4997 failures.release_held_acknowledgements();
4998 let original_timestamp = log.events()[0].timestamp;
4999
5000 let distinct_error = block_on_test_future(log.append_critical_async(
5001 EventKind::ProposalCompleted,
5002 None,
5003 Some("different-terminal"),
5004 HashMap::new(),
5005 Duration::from_millis(100),
5006 ))
5007 .expect_err("a different critical row must not bypass exact retry");
5008 assert!(matches!(
5009 distinct_error,
5010 CriticalAppendError::Rejected { .. }
5011 ));
5012 assert_eq!(log.events().len(), 1);
5013
5014 let retried = block_on_test_future(log.append_critical_async(
5015 EventKind::RunCompleted,
5016 None,
5017 None,
5018 data,
5019 MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT,
5020 ))
5021 .expect("an identical retry must finish the retained row");
5022 assert_eq!(retried.timestamp, original_timestamp);
5023 assert!(log.critical_pending.is_empty());
5024
5025 block_on_test_future(log.append_critical_async(
5026 EventKind::ProposalCompleted,
5027 None,
5028 Some("different-terminal"),
5029 HashMap::new(),
5030 MAX_CRITICAL_ACKNOWLEDGEMENT_TIMEOUT,
5031 ))
5032 .expect("a different row is allowed after exact retry reconciliation");
5033 drop(log);
5034
5035 let loaded = EventLog::load(&path).unwrap();
5036 assert_eq!(loaded.events().len(), 2);
5037 assert_eq!(serde_json::to_string(&loaded.events()[0]).unwrap(), pending);
5038 }
5039
5040 #[test]
5041 fn critical_append_failures_retry_same_row_and_fsync_prior_async_events() {
5042 for point in [
5043 JournalFailurePoint::Write,
5044 JournalFailurePoint::Flush,
5045 JournalFailurePoint::Fsync,
5046 ] {
5047 let dir = tempfile::tempdir().unwrap();
5048 let path = dir.path().join(format!("critical-{point:?}.jsonl"));
5049 let failures = JournalFailureInjector::default();
5050 failures.fail_next(point);
5051 let mut log = EventLog::with_journal_failure_injector(path.clone(), failures);
5052 log.bind_run("run-critical", "client-critical").unwrap();
5053 log.append(
5054 EventKind::ProposalReceived,
5055 None,
5056 Some("proposal-critical"),
5057 HashMap::new(),
5058 );
5059 let data =
5060 HashMap::from([("completion_digest".to_string(), Value::from("a".repeat(64)))]);
5061 assert!(
5062 log.append_critical(EventKind::RunCompleted, None, None, data.clone())
5063 .is_err(),
5064 "{point:?} failure must not acknowledge"
5065 );
5066 log.append(
5067 EventKind::ActionSucceeded,
5068 Some("after-pending-terminal"),
5069 Some("proposal-critical"),
5070 HashMap::new(),
5071 );
5072 log.append_critical(EventKind::RunCompleted, None, None, data)
5073 .expect("retry finishes the exact critical row");
5074 drop(log);
5075
5076 let loaded = EventLog::load(&path).unwrap();
5077 let events = loaded.events();
5078 assert_eq!(events[0].kind, EventKind::ProposalReceived);
5079 assert_eq!(events[1].kind, EventKind::RunCompleted);
5080 assert_eq!(events[2].kind, EventKind::ActionSucceeded);
5081 assert_eq!(
5082 events
5083 .iter()
5084 .filter(|event| event.kind == EventKind::RunCompleted)
5085 .count(),
5086 1,
5087 "{point:?} retry must not duplicate a terminal"
5088 );
5089 }
5090 }
5091
5092 #[test]
5093 fn a_critical_pass_moves_a_queued_failure_to_the_next_row() {
5094 let dir = tempfile::tempdir().unwrap();
5095 let path = dir.path().join("critical-pass.jsonl");
5096 let failures = JournalFailureInjector::default();
5097 failures.pass_next_critical(1);
5098 failures.fail_next(JournalFailurePoint::Write);
5099 let mut log = EventLog::with_journal_failure_injector(path.clone(), failures);
5100 log.bind_run("run-critical-pass", "client-critical-pass")
5101 .unwrap();
5102
5103 log.append_critical(
5104 EventKind::RunCancellationRequested,
5105 None,
5106 None,
5107 HashMap::new(),
5108 )
5109 .expect("the passed row must be written despite the queued failure");
5110 assert!(
5111 log.append_critical(EventKind::RunCancellationResult, None, None, HashMap::new())
5112 .is_err(),
5113 "the queued failure must apply to the row after the pass"
5114 );
5115 drop(log);
5116
5117 let kinds: Vec<_> = EventLog::load(&path)
5118 .unwrap()
5119 .events()
5120 .iter()
5121 .map(|event| event.kind.clone())
5122 .collect();
5123 assert_eq!(kinds, vec![EventKind::RunCancellationRequested]);
5124 }
5125
5126 #[test]
5127 fn compacting_a_failed_critical_row_makes_its_retry_idempotent() {
5128 let dir = tempfile::tempdir().unwrap();
5129 let path = dir.path().join("critical-compact-retry.jsonl");
5130 let failures = JournalFailureInjector::default();
5131 failures.fail_next(JournalFailurePoint::Fsync);
5132 let mut log =
5133 EventLog::with_journal_failure_injector(path.clone(), failures).with_hash_chaining();
5134 log.bind_run("run-critical-compact", "client-critical-compact")
5135 .unwrap();
5136 log.append(
5137 EventKind::ProposalReceived,
5138 None,
5139 Some("proposal-critical-compact"),
5140 HashMap::new(),
5141 );
5142 let data = HashMap::from([("completion_digest".to_string(), Value::from("c".repeat(64)))]);
5143
5144 assert!(
5145 log.append_critical(EventKind::RunCompleted, None, None, data.clone())
5146 .is_err(),
5147 "the injected fsync failure must leave the exact terminal pending"
5148 );
5149 assert!(
5150 log.compact_journal(),
5151 "compaction persists the in-memory pending terminal"
5152 );
5153 log.append_critical(EventKind::RunCompleted, None, None, data)
5154 .expect("identical retry recognizes the compacted terminal as durable");
5155 drop(log);
5156
5157 let loaded = EventLog::load(&path).unwrap();
5158 assert_eq!(
5159 loaded
5160 .events()
5161 .iter()
5162 .filter(|event| event.kind == EventKind::RunCompleted)
5163 .count(),
5164 1,
5165 "writer respawn must not duplicate the compacted terminal"
5166 );
5167 assert_eq!(loaded.events()[0].kind, EventKind::ProposalReceived);
5168 assert_eq!(loaded.events()[1].kind, EventKind::RunCompleted);
5169 assert_eq!(loaded.verify_chain(), Ok(2));
5170 }
5171
5172 #[test]
5173 fn critical_append_cannot_ack_until_failed_prior_async_row_is_replayed() {
5174 let dir = tempfile::tempdir().unwrap();
5175 let path = dir.path().join("prior-async-failure.jsonl");
5176 let failures = JournalFailureInjector::default();
5177 failures.fail_next(JournalFailurePoint::AsyncWrite);
5180 failures.fail_next(JournalFailurePoint::AsyncWrite);
5181 let mut log = EventLog::with_journal_failure_injector(path.clone(), failures);
5182 log.bind_run("run-ordered", "client-ordered").unwrap();
5183 log.append(
5184 EventKind::ActionSucceeded,
5185 Some("action-ordered"),
5186 Some("proposal-ordered"),
5187 HashMap::new(),
5188 );
5189 let data = HashMap::from([("completion_digest".to_string(), Value::from("b".repeat(64)))]);
5190
5191 assert!(
5192 log.append_critical(
5193 EventKind::ProposalCompleted,
5194 None,
5195 Some("proposal-ordered"),
5196 data.clone()
5197 )
5198 .is_err(),
5199 "a terminal must not acknowledge while an earlier row is still missing"
5200 );
5201 log.append_critical(
5202 EventKind::ProposalCompleted,
5203 None,
5204 Some("proposal-ordered"),
5205 data,
5206 )
5207 .expect("retry repairs the prior row before acknowledging the terminal");
5208 drop(log);
5209
5210 let loaded = EventLog::load(&path).unwrap();
5211 assert_eq!(loaded.events().len(), 2);
5212 assert_eq!(loaded.events()[0].kind, EventKind::ActionSucceeded);
5213 assert_eq!(loaded.events()[1].kind, EventKind::ProposalCompleted);
5214 }
5215
5216 #[test]
5217 fn first_use_parent_sync_failure_blocks_terminal_until_prior_async_replays() {
5218 let dir = tempfile::tempdir().unwrap();
5219 let path = dir.path().join("nested").join("first-use.jsonl");
5220 let failures = car_secrets::PrivatePathDurabilityFailureInjector::default();
5221 failures.fail_next(car_secrets::PrivatePathDurabilityFailurePoint::ParentDirectorySync);
5222 failures.fail_next(car_secrets::PrivatePathDurabilityFailurePoint::ParentDirectorySync);
5223 let mut log = EventLog::with_private_path_failure_injector(path.clone(), failures);
5224 log.bind_run("run-first-use", "client-first-use").unwrap();
5225 log.append(
5226 EventKind::ActionSucceeded,
5227 Some("action-first-use"),
5228 Some("proposal-first-use"),
5229 HashMap::new(),
5230 );
5231 let data = HashMap::from([("completion_digest".to_string(), Value::from("d".repeat(64)))]);
5232
5233 assert!(log
5234 .append_critical(
5235 EventKind::ProposalCompleted,
5236 None,
5237 Some("proposal-first-use"),
5238 data.clone(),
5239 )
5240 .is_err());
5241 log.append_critical(
5242 EventKind::ProposalCompleted,
5243 None,
5244 Some("proposal-first-use"),
5245 data,
5246 )
5247 .expect("retry durably replays async row then exact terminal");
5248 drop(log);
5249
5250 let loaded = EventLog::load(&path).unwrap();
5251 assert_eq!(loaded.events().len(), 2);
5252 assert_eq!(loaded.events()[0].kind, EventKind::ActionSucceeded);
5253 assert_eq!(loaded.events()[1].kind, EventKind::ProposalCompleted);
5254 }
5255}