underhill_crash: Trace less during crash reporting (microsoft#261)

One of our core crash diagnostics is that we send a chunk of kmsg output
to the host to log. It is ideal if that output contains the panic
message that caused the crash, but that isn't guaranteed. Since we have
a fixed size buffer, it is possible that output that occurs after the
panic message could push the useful details off the end of the buffer.
This PR reduces the amount of tracing we emit during the crash dump
process to make this less likely.

openhcl/underhill_crash/src/lib.rs

@@ -157,7 +157,7 @@ async fn send_dump(
         cfg.max_dump_size
     };
 
-    tracing::info!("The host accepts crash dump files no larger than {max_dump_size} bytes");
+    tracing::debug!(max_dump_size, "Got host config");
 
     let dump_start_rq = crash::DumpStartRequestV1 {
         header: make_header(None, crash::MessageType::REQUEST_NIX_DUMP_START_V1),
@@ -206,7 +206,7 @@ async fn send_dump(
         } else {
             0
         };
-        tracing::info!("Reported crash, wrote {wrote_bytes_total} bytes at {speed} bytes/sec");
+        tracing::info!(size = wrote_bytes_total, speed, "Reported crash");
 
         Ok::<(), anyhow::Error>(())
     });
@@ -270,13 +270,12 @@ pub fn main() -> ! {
 
     let os_version = OsVersionInfo::new();
 
-    let crate_name = env!("CARGO_PKG_NAME");
     let crate_revision = option_env!("VERGEN_GIT_SHA").unwrap_or("UNKNOWN_REVISION");
-    tracing::info!(?crate_name, ?crate_revision, "Crash reporting process");
 
     let os_version_major = os_version.major();
     let os_version_minor = os_version.minor();
     tracing::error!(
+        ?crate_revision,
         ?options.comm,
         ?options.pid,
         ?options.tid,
@@ -571,20 +570,20 @@ impl<'a> DumpStreamer<'a> {
         // write the actual length of the kmsg log in a predictable location
         self.write((kmsg_len as u32).as_bytes()).await?;
 
-        tracing::info!("wrote kmsg with length: {}", kmsg_len);
+        tracing::debug!(len = kmsg_len, "wrote kmsg");
 
         Ok(())
     }
 
     /// Let the VSP know that is all the data so the host can start reporting
     async fn complete(&mut self, os_version: &OsVersionInfo) -> anyhow::Result<()> {
-        tracing::info!(
+        tracing::debug!(
             "Read {} bytes, wrote {} bytes",
             self.read_bytes_total,
             self.wrote_bytes_total
         );
         if self.read_bytes_total + KMSG_NOTE_BYTES == self.wrote_bytes_total {
-            tracing::info!(
+            tracing::debug!(
                 "Bytes written includes {} bytes for kmsg note",
                 KMSG_NOTE_BYTES,
             );

vm/devices/vmbus/vmbus_user_channel/src/lib.rs

@@ -163,10 +163,10 @@ pub fn open_uio_device(instance_id: &Guid) -> Result<File, Error> {
         .map_err(ErrorInner::Exist)?;
 
     let uio_dev_path = Path::new("/dev").join(uio_path.file_name());
-    tracing::info!(
-        "opening device {} for {}",
-        uio_dev_path.display(),
-        instance_id
+    tracing::debug!(
+        dev_path = %uio_dev_path.display(),
+        %instance_id,
+        "opening device"
     );
 
     let file = fs_err::OpenOptions::new()