From 94c2576d90e13dfcf991f9b9eec20a9351476c5b Mon Sep 17 00:00:00 2001 From: Daiki Ueno Date: Mon, 6 Apr 2026 20:52:59 +0900 Subject: [PATCH] Include system boot time in the primary log as metadata Timestamps in event entries are relative to the system boot time, meaning that it is only valid within the same boot session. This patch introduces way of recording the system boot time in the log file, in a special "metadata" section. Signed-off-by: Daiki Ueno --- agent/src/log_writer.rs | 26 ++++++++++++++------- agent/tests/coalesce.rs | 7 +++--- agent/tests/composite.rs | 21 +++++++++-------- agent/tests/no_coalesce.rs | 5 ++-- crypto-auditing/src/types.rs | 38 ++++++++++++++++++++++++++++++ docs/logging-format.md | 10 ++++++++ log-parser/src/query.rs | 45 +++++++++++++++++++++++++++++------- 7 files changed, 121 insertions(+), 31 deletions(-) diff --git a/agent/src/log_writer.rs b/agent/src/log_writer.rs index 90c95d3..0f67784 100644 --- a/agent/src/log_writer.rs +++ b/agent/src/log_writer.rs @@ -32,7 +32,8 @@ impl LogWriter { let file = File::create(&config.log_file) .await .with_context(|| format!("unable to create file `{}`", config.log_file.display()))?; - Ok(Self { + + let mut log_writer = Self { config: config.clone(), file: Some(file), offset: 0u64, @@ -40,7 +41,12 @@ impl LogWriter { groups: Vec::default(), written_events: 0usize, pending_events: 0usize, - }) + }; + + let metadata = EventGroup::metadata(); + log_writer.write_event_group(&metadata).await?; + + Ok(log_writer) } pub fn timeout(&self) -> Duration { @@ -164,18 +170,22 @@ impl LogWriter { Ok(()) } + async fn write_event_group(&mut self, group: &EventGroup) -> Result<()> { + let v = match self.config.format { + config::Format::Normal => serde_cbor::ser::to_vec(group)?, + config::Format::Packed => serde_cbor::ser::to_vec_packed(group)?, + config::Format::Minimal => to_vec_minimal(group)?, + }; + self.write_all(v).await + } + pub async fn flush(&mut self) -> Result<()> { self.pending_events = 0; for group in self.groups.clone() { if self.should_rotate_after(self.written_events) { self.rotate().await?; } - let v = match self.config.format { - config::Format::Normal => serde_cbor::ser::to_vec(&group)?, - config::Format::Packed => serde_cbor::ser::to_vec_packed(&group)?, - config::Format::Minimal => to_vec_minimal(&group)?, - }; - self.write_all(v).await?; + self.write_event_group(&group).await?; probe!( crypto_auditing_internal_agent, event_group, diff --git a/agent/tests/coalesce.rs b/agent/tests/coalesce.rs index 4719931..b39f617 100644 --- a/agent/tests/coalesce.rs +++ b/agent/tests/coalesce.rs @@ -120,7 +120,8 @@ fn test_probe_coalesce() { .into_iter::() .collect(); let groups = groups.expect("error deserializing"); - assert_eq!(groups.len(), 2); - assert_eq!(groups[0].events().len(), 4); - assert_eq!(groups[1].events().len(), 1); + assert_eq!(groups.len(), 3); + assert!(groups[0].is_metadata()); + assert_eq!(groups[1].events().len(), 4); + assert_eq!(groups[2].events().len(), 1); } diff --git a/agent/tests/composite.rs b/agent/tests/composite.rs index c65994d..01c6a5f 100644 --- a/agent/tests/composite.rs +++ b/agent/tests/composite.rs @@ -144,27 +144,28 @@ fn test_probe_composite() { .into_iter::() .collect(); let groups = groups.expect("error deserializing"); - assert_eq!(groups.len(), 5); - assert_eq!(groups[0].events().len(), 1); - assert!(matches!(groups[0].events()[0], Event::NewContext { .. })); + assert_eq!(groups.len(), 6); + assert!(groups[0].is_metadata()); assert_eq!(groups[1].events().len(), 1); - if let Event::Data { key, .. } = &groups[1].events()[0] { + assert!(matches!(groups[1].events()[0], Event::NewContext { .. })); + assert_eq!(groups[2].events().len(), 1); + if let Event::Data { key, .. } = &groups[2].events()[0] { assert_eq!(key, "foo"); } else { unreachable!(); } - assert_eq!(groups[2].events().len(), 1); - if let Event::Data { key, .. } = &groups[2].events()[0] { + assert_eq!(groups[3].events().len(), 1); + if let Event::Data { key, .. } = &groups[3].events()[0] { assert_eq!(key, "bar"); } else { unreachable!(); } - assert_eq!(groups[3].events().len(), 1); - if let Event::Data { key, .. } = &groups[3].events()[0] { + assert_eq!(groups[4].events().len(), 1); + if let Event::Data { key, .. } = &groups[4].events()[0] { assert_eq!(key, "baz"); } else { unreachable!(); } - assert_eq!(groups[4].events().len(), 1); - assert!(matches!(groups[4].events()[0], Event::NewContext { .. })); + assert_eq!(groups[5].events().len(), 1); + assert!(matches!(groups[5].events()[0], Event::NewContext { .. })); } diff --git a/agent/tests/no_coalesce.rs b/agent/tests/no_coalesce.rs index 54fdf79..b524853 100644 --- a/agent/tests/no_coalesce.rs +++ b/agent/tests/no_coalesce.rs @@ -142,10 +142,11 @@ fn test_probe_no_coalesce() { .into_iter::() .collect(); let groups = groups.expect("error deserializing"); - assert_eq!(groups.len(), 5); - assert_eq!(groups[0].events().len(), 1); + assert_eq!(groups.len(), 6); + assert!(groups[0].is_metadata()); assert_eq!(groups[1].events().len(), 1); assert_eq!(groups[2].events().len(), 1); assert_eq!(groups[3].events().len(), 1); assert_eq!(groups[4].events().len(), 1); + assert_eq!(groups[5].events().len(), 1); } diff --git a/crypto-auditing/src/types.rs b/crypto-auditing/src/types.rs index f9cccf2..13e3625 100644 --- a/crypto-auditing/src/types.rs +++ b/crypto-auditing/src/types.rs @@ -17,6 +17,9 @@ include!(concat!(env!("OUT_DIR"), "/bindings.rs")); pub type ContextId = [u8; 16]; +/// Context ID associated with `EventGroup` representing metadata +pub const METADATA_CONTEXT_ID: ContextId = [0; 16]; + fn only_values(source: &BTreeMap, serializer: S) -> Result where S: Serializer, @@ -177,6 +180,15 @@ pub enum Event { }, } +impl Event { + pub fn data(&self, needle: &str) -> Option<&EventData> { + match self { + Self::Data { key, value } if key == needle => Some(value), + _ => None, + } + } +} + #[serde_as] #[derive(Serialize, Deserialize, Clone, Debug)] pub struct EventGroup { @@ -197,6 +209,32 @@ fn format_context_id(pid_tgid: u64, context: i64) -> ContextId { } impl EventGroup { + /// Returns a new `EventGroup` with metadata events + pub fn metadata() -> Self { + let events = vec![ + Event::Data { + key: "version".to_string(), + value: EventData::Word(1), + }, + Event::Data { + key: "boot_time".to_string(), + value: EventData::Word(System::boot_time() as i64), + }, + ]; + + Self { + context: METADATA_CONTEXT_ID, + start: Default::default(), + end: Default::default(), + events, + } + } + + /// Returns true if this is a metadata group + pub fn is_metadata(&self) -> bool { + self.context == METADATA_CONTEXT_ID + } + /// Returns the context ID associated with the event group pub fn context(&self) -> &ContextId { &self.context diff --git a/docs/logging-format.md b/docs/logging-format.md index 278136d..51b08df 100644 --- a/docs/logging-format.md +++ b/docs/logging-format.md @@ -363,6 +363,16 @@ events in given time window from `start` to `end`. Timestamps are represented as a monotonic duration from the kernel boot time. `ContextId` is an encrypted 16-byte context. +The first `EventGroup` may be a virtual metadata group, whose +`ContextId` is all-zero. This is used for including environmental +information as event entries. The following events are currently +defined: + +| key | value type | description | +|-------------|------------|---------------------------------------------| +| `version` | word | the file format version (should be 1) | +| `boot_time` | word | kernel boot time in seconds from Unix epoch | + ### Drawbacks and alternatives ### Questions diff --git a/log-parser/src/query.rs b/log-parser/src/query.rs index 8839b91..7446fe6 100644 --- a/log-parser/src/query.rs +++ b/log-parser/src/query.rs @@ -2,14 +2,28 @@ // Copyright (C) 2022-2023 The crypto-auditing developers. use anyhow::{Context as _, Result}; -use crypto_auditing::types::{ContextTracker, EventGroup}; +use crypto_auditing::types::{ContextTracker, EventData, EventGroup}; use pager::Pager; use serde_cbor::de::Deserializer; use std::io::{self, Write}; -use std::time::{Duration, UNIX_EPOCH}; +use std::time::{Duration, SystemTime, UNIX_EPOCH}; mod config; +fn get_boot_time_from_metadata(group: &EventGroup) -> Option { + for event in group.events() { + if let Some(data) = event.data("boot_time") { + match data { + EventData::Word(secs) => { + return Some(UNIX_EPOCH + Duration::from_secs(*secs as u64)); + } + _ => (), + } + } + } + None +} + fn main() -> Result<(), Box> { let config = config::Config::new()?; Pager::new().setup(); @@ -17,12 +31,27 @@ fn main() -> Result<(), Box> { let log_file = std::fs::File::open(&config.log_file) .with_context(|| format!("unable to read file `{}`", config.log_file.display()))?; - let mut tracker = ContextTracker::new( - config - .boot_time - .map(|secs| UNIX_EPOCH + Duration::from_secs(secs)), - ); - for group in Deserializer::from_reader(&log_file).into_iter::() { + let mut groups = Deserializer::from_reader(&log_file) + .into_iter::() + .peekable(); + + // Figure out the system boot time, first from the config, and + // then from the metadata group in the log + let boot_time = if let Some(secs) = config.boot_time { + Some(UNIX_EPOCH + Duration::from_secs(secs)) + } else if let Some(Ok(group)) = groups.peek() + && group.is_metadata() + { + let boot_time = get_boot_time_from_metadata(&group); + // Skip the metadata group + groups.next(); + boot_time + } else { + None + }; + + let mut tracker = ContextTracker::new(boot_time); + for group in groups { tracker.handle_event_group(&group?); } let root_contexts: Vec<_> = tracker