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 <dueno@redhat.com>

Author: ueno

agent/src/log_writer.rs

@@ -32,15 +32,21 @@ 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,
             instant: Instant::now(),
             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,

agent/tests/coalesce.rs

@@ -120,7 +120,8 @@ fn test_probe_coalesce() {
         .into_iter::<EventGroup>()
         .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);
+    // first group is a metadata group
+    assert_eq!(groups.len(), 3);
+    assert_eq!(groups[1].events().len(), 4);
+    assert_eq!(groups[2].events().len(), 1);
 }

agent/tests/composite.rs

@@ -144,27 +144,28 @@ fn test_probe_composite() {
         .into_iter::<EventGroup>()
         .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 { .. }));
+    // first group is a metadata group
+    assert_eq!(groups.len(), 6);
     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 { .. }));
 }

agent/tests/no_coalesce.rs

@@ -142,10 +142,11 @@ fn test_probe_no_coalesce() {
         .into_iter::<EventGroup>()
         .collect();
     let groups = groups.expect("error deserializing");
-    assert_eq!(groups.len(), 5);
-    assert_eq!(groups[0].events().len(), 1);
+    // first group is a metadata group
+    assert_eq!(groups.len(), 6);
     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);
 }

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<K, V, S>(source: &BTreeMap<K, V>, serializer: S) -> Result<S::Ok, S::Error>
 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

log-parser/src/query.rs

@@ -2,27 +2,56 @@
 // 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<SystemTime> {
+    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<dyn std::error::Error>> {
     let config = config::Config::new()?;
     Pager::new().setup();
 
     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::<EventGroup>() {
+    let mut groups = Deserializer::from_reader(&log_file)
+        .into_iter::<EventGroup>()
+        .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