kmsg: Log the raw buffer if we fail to parse (microsoft#1704)

We've seen a crash here in the wild, but haven't yet figured out what
exactly is failing to parse. Add some more logging so we can hopefully
get this if it happens again.

Author: smalis-msft

hyperv/tools/hypestv/src/windows/vm.rs

@@ -486,9 +486,8 @@ impl VmInner {
 
                 while let Some(data) = kmsg.next().await {
                     match data {
-                        Ok(data) => {
-                            let message = kmsg::KmsgParsedEntry::new(&data)?;
-                            match &mut target {
+                        Ok(data) => match kmsg::KmsgParsedEntry::new(&data) {
+                            Ok(message) => match &mut target {
                                 IoTarget::Printer => {
                                     writeln!(
                                         self.printer.out(),
@@ -501,8 +500,18 @@ impl VmInner {
                                     let line = format!("{}\r\n", message.display(true));
                                     console.write_all(line.as_bytes()).await?;
                                 }
-                            }
-                        }
+                            },
+                            Err(e) => match &mut target {
+                                IoTarget::Printer => {
+                                    writeln!(self.printer.out(), "[kmsg]: invalid entry: {:?}", e)
+                                        .ok();
+                                }
+                                IoTarget::Console(console) => {
+                                    let line = format!("invalid kmsg entry: {:?}\r\n", e);
+                                    console.write_all(line.as_bytes()).await?;
+                                }
+                            },
+                        },
                         Err(err) if err.kind() == std::io::ErrorKind::ConnectionReset => {
                             break;
                         }

openhcl/ohcldiag-dev/src/main.rs

@@ -629,10 +629,10 @@ pub fn main() -> anyhow::Result<()> {
 
                     while let Some(data) = file_stream.next().await {
                         match data {
-                            Ok(data) => {
-                                let message = kmsg::KmsgParsedEntry::new(&data)?;
-                                println!("{}", message.display(is_terminal));
-                            }
+                            Ok(data) => match kmsg::KmsgParsedEntry::new(&data) {
+                                Ok(message) => println!("{}", message.display(is_terminal)),
+                                Err(e) => println!("Invalid kmsg entry: {e:?}"),
+                            },
                             Err(err) if reconnect && err.kind() == ErrorKind::ConnectionReset => {
                                 if verbose {
                                     eprintln!(

petri/src/tracing.rs

@@ -332,8 +332,9 @@ pub async fn kmsg_log_task(
     while let Some(data) = file_stream.next().await {
         match data {
             Ok(data) => {
-                let message = kmsg::KmsgParsedEntry::new(&data)?;
-                log_file.write_entry(message.display(false));
+                let message = KmsgParsedEntry::new(&data).unwrap();
+                let level = kernel_level_to_tracing_level(message.level);
+                log_file.write_entry_fmt(None, level, format_args!("{}", message.display(false)));
             }
             Err(err) => {
                 tracing::info!("kmsg disconnected: {err:?}");

support/kmsg/src/lib.rs

@@ -69,12 +69,12 @@ impl Display for EncodedMessage<'_> {
 
 /// An error indicating the kmsg entry could not be parsed because it is invalid.
 #[derive(Debug, Error)]
-#[error("invalid kmsg entry")]
-pub struct InvalidKmsgEntry;
+#[error("invalid kmsg entry: {0:?}")]
+pub struct InvalidKmsgEntry<'a>(&'a [u8]);
 
 impl<'a> KmsgParsedEntry<'a> {
-    pub fn new(data: &'a [u8]) -> Result<Self, InvalidKmsgEntry> {
-        Self::new_inner(data).ok_or(InvalidKmsgEntry)
+    pub fn new(data: &'a [u8]) -> Result<Self, InvalidKmsgEntry<'a>> {
+        Self::new_inner(data).ok_or(InvalidKmsgEntry(data))
     }
 
     fn new_inner(data: &'a [u8]) -> Option<Self> {

vmm_tests/vmm_tests/tests/tests/multiarch.rs

@@ -105,7 +105,7 @@ async fn efi_diagnostics_no_boot(config: PetriVmConfigOpenVmm) -> anyhow::Result
     // Search for the message
     while let Some(data) = kmsg.next().await {
         let data = data.context("reading kmsg")?;
-        let msg = kmsg::KmsgParsedEntry::new(&data)?;
+        let msg = kmsg::KmsgParsedEntry::new(&data).unwrap();
         let raw = msg.message.as_raw();
         if raw.contains(NO_BOOT_MSG) {
             return Ok(());

vmm_tests/vmm_tests/tests/tests/x86_64/openhcl_uefi.rs

@@ -149,7 +149,7 @@ async fn no_numa_errors(config: PetriVmConfigOpenVmm) -> Result<(), anyhow::Erro
     // Search kmsg and make sure we didn't see any errors from the kernel
     while let Some(data) = kmsg.next().await {
         let data = data.context("reading kmsg")?;
-        let msg = kmsg::KmsgParsedEntry::new(&data)?;
+        let msg = kmsg::KmsgParsedEntry::new(&data).unwrap();
         let raw = msg.message.as_raw();
         if raw.contains(BAD_PROP) {
             anyhow::bail!("found bad prop in kmsg");