main: Create a format string parser and printer for log output

Introduces a custom format string parser for use for log entries. For
now only the existing format string entries are covered and the default
format string matches the existing behaviour.

The format string is tokenized once and then that token stream is used
for each log entry.

Assisted-by: Claude:Opus-4.7
Signed-off-by: Rob Bradford <rbradford@meta.com>

cloud-hypervisor/src/logger.rs

@@ -3,11 +3,110 @@
 // SPDX-License-Identifier: Apache-2.0
 //
 
+use std::io::Write;
+use std::str::FromStr;
 use std::sync::Mutex;
+use std::time::Instant;
+
+use thiserror::Error;
+
+#[derive(Debug, Error)]
+pub enum Error {
+    #[error("Unterminated '{{' in format string")]
+    UnterminatedBrace,
+    #[error("Unmatched '}}' in format string")]
+    UnmatchedBrace,
+    #[error("Unknown format token '{{{0}}}'")]
+    UnknownToken(String),
+}
+
+enum Token {
+    Literal(String),
+    BootTime,
+    Thread,
+    Level,
+    Location,
+    Msg,
+}
+
+impl FromStr for Token {
+    type Err = Error;
+
+    fn from_str(s: &str) -> Result<Self, Self::Err> {
+        match s {
+            "boottime" => Ok(Self::BootTime),
+            "thread" => Ok(Self::Thread),
+            "level" => Ok(Self::Level),
+            "location" => Ok(Self::Location),
+            "msg" => Ok(Self::Msg),
+            _ => Err(Error::UnknownToken(s.to_string())),
+        }
+    }
+}
+
+fn parse_format(fmt: &str) -> Result<Vec<Token>, Error> {
+    let mut tokens = Vec::new();
+    let mut literal = String::new();
+    let mut chars = fmt.chars().peekable();
+
+    while let Some(c) = chars.next() {
+        match c {
+            '{' => {
+                if chars.peek() == Some(&'{') {
+                    chars.next();
+                    literal.push('{');
+                    continue;
+                }
+
+                if !literal.is_empty() {
+                    tokens.push(Token::Literal(std::mem::take(&mut literal)));
+                }
+
+                let mut name = String::new();
+                loop {
+                    match chars.next() {
+                        Some('}') => break,
+                        Some(ch) => name.push(ch),
+                        None => return Err(Error::UnterminatedBrace),
+                    }
+                }
+
+                tokens.push(name.parse()?);
+            }
+            '}' => {
+                if chars.peek() == Some(&'}') {
+                    chars.next();
+                    literal.push('}');
+                } else {
+                    return Err(Error::UnmatchedBrace);
+                }
+            }
+            _ => literal.push(c),
+        }
+    }
+    if !literal.is_empty() {
+        tokens.push(Token::Literal(literal));
+    }
+    Ok(tokens)
+}
+
+const DEFAULT_FORMAT: &str =
+    "cloud-hypervisor: {boottime}s: <{thread}> {level}:{location} -- {msg}";
 
 pub struct Logger {
-    pub output: Mutex<Box<dyn std::io::Write + Send>>,
-    pub start: std::time::Instant,
+    output: Mutex<Box<dyn Write + Send>>,
+    start: Instant,
+    tokens: Vec<Token>,
+}
+
+impl Logger {
+    pub fn new(output: Box<dyn Write + Send>) -> Result<Self, Error> {
+        Ok(Self {
+            output: Mutex::new(output),
+            start: Instant::now(),
+            tokens: parse_format(DEFAULT_FORMAT)?,
+        })
+    }
 }
 
 impl log::Log for Logger {
@@ -20,28 +119,28 @@ impl log::Log for Logger {
             return;
         }
 
-        let now = std::time::Instant::now();
-        let duration = now.duration_since(self.start);
-        let duration_s = duration.as_secs_f32();
-
-        let location = if let (Some(file), Some(line)) = (record.file(), record.line()) {
-            format!("{file}:{line}")
-        } else {
-            record.target().to_string()
-        };
-
+        let duration_s = Instant::now().duration_since(self.start).as_secs_f32();
         let mut out = self.output.lock().unwrap();
-        write!(
-            &mut *out,
-            // 10: 6 decimal places + sep => whole seconds in range `0..=999` properly aligned
-            "cloud-hypervisor: {:>10.6?}s: <{}> {}:{} -- {}\r\n",
-            duration_s,
-            std::thread::current().name().unwrap_or("anonymous"),
-            record.level(),
-            location,
-            record.args(),
-        )
-        .ok();
+        for token in &self.tokens {
+            let _ = match token {
+                Token::Literal(s) => out.write_all(s.as_bytes()),
+                // 10: 6 decimal places + sep => whole seconds in range `0..=999` properly aligned
+                Token::BootTime => write!(&mut *out, "{duration_s:>10.6?}"),
+                Token::Thread => write!(
+                    &mut *out,
+                    "{}",
+                    std::thread::current().name().unwrap_or("anonymous")
+                ),
+                Token::Level => write!(&mut *out, "{}", record.level()),
+                Token::Location => match (record.file(), record.line()) {
+                    (Some(file), Some(line)) => write!(&mut *out, "{file}:{line}"),
+                    _ => write!(&mut *out, "{}", record.target()),
+                },
+                Token::Msg => write!(&mut *out, "{}", record.args()),
+            };
+        }
+        let _ = out.write_all(b"\r\n");
     }
+
     fn flush(&self) {}
 }

cloud-hypervisor/src/main.rs

@@ -9,7 +9,6 @@ mod test_util;
 
 use std::fs::File;
 use std::os::unix::io::{AsRawFd, FromRawFd, RawFd};
-use std::sync::Mutex;
 use std::sync::mpsc::channel;
 use std::{env, io};
 
@@ -97,6 +96,8 @@ enum Error {
     BareGdb,
     #[error("Error creating log file")]
     LogFileCreation(#[source] std::io::Error),
+    #[error("Error parsing logger format")]
+    LoggerFormat(#[source] logger::Error),
     #[error("Error setting up logger")]
     LoggerSetup(#[source] log::SetLoggerError),
     #[error("Failed to gracefully shutdown http api")]
@@ -514,12 +515,10 @@ fn start_vmm(
         Box::new(std::io::stderr())
     };
 
-    log::set_boxed_logger(Box::new(Logger {
-        output: Mutex::new(log_file),
-        start: std::time::Instant::now(),
-    }))
-    .map(|()| log::set_max_level(log_level))
-    .map_err(Error::LoggerSetup)?;
+    let logger = Logger::new(log_file).map_err(Error::LoggerFormat)?;
+    log::set_boxed_logger(Box::new(logger))
+        .map(|()| log::set_max_level(log_level))
+        .map_err(Error::LoggerSetup)?;
 
     let (api_request_sender, api_request_receiver) = channel();
     let api_evt = EventFd::new(EFD_NONBLOCK).map_err(Error::CreateApiEventFd)?;