Add logs to stage1

Ref #4652

oak_containers_stage1/src/client.rs

@@ -45,6 +45,7 @@ impl LauncherClient {
             .context("couldn't form streaming connection")?
             .into_inner();
 
+        println!("get_oak_system_image: got stream");
         let mut image_buf: Vec<u8> = Vec::new();
         while let Some(mut load_response) = stream
             .message()
@@ -53,6 +54,10 @@ impl LauncherClient {
         {
             image_buf.append(&mut load_response.image_chunk);
         }
+        println!(
+            "get_oak_system_image: stream terminated, got {} bytes",
+            image_buf.len()
+        );
 
         Ok(image_buf)
     }

oak_containers_stage1/src/dice.rs

@@ -87,20 +87,27 @@ fn read_stage0_dice_data(start: PhysAddr) -> anyhow::Result<Stage0DiceData> {
     let length = std::mem::size_of::<Stage0DiceData>();
     // Linux presents an inclusive end address.
     let end = start + (length as u64 - 1);
+
+    println!("Reading DICE data from physical memory. Start={start:p}, End={end:p}");
+
     // Ensure that the exact memory range is marked as reserved.
     if !read_memory_ranges()?.iter().any(|range| {
         range.start == start && range.end == end && range.type_description == EXPECTED_E820_TYPE
     }) {
         anyhow::bail!("DICE data range is not reserved");
     }
+    println!("DICE data range is reserved");
 
     // Open a file representing the physical memory.
-    let dice_file = OpenOptions::new()
+    let dice_file_descriptor = OpenOptions::new()
         .read(true)
         .write(true)
         .open(PHYS_MEM_PATH)
         .context("couldn't open DICE memory device for reading")?;
 
+    println!("Opened DICE memory device for reading: FD={dice_file_descriptor:?}");
+
+    println!("Mapping DICE data into virtual memory");
     // Safety: we have checked that the exact memory range is marked as reserved so the Linux kernel
     // will not use it for anything else.
     let start_ptr = unsafe {
@@ -109,10 +116,11 @@ fn read_stage0_dice_data(start: PhysAddr) -> anyhow::Result<Stage0DiceData> {
             length.try_into()?,
             ProtFlags::PROT_READ | ProtFlags::PROT_WRITE,
             MapFlags::MAP_SHARED,
-            dice_file.as_raw_fd(),
+            dice_file_descriptor.as_raw_fd(),
             start.as_u64().try_into()?,
         )?
     };
+    println!("Mapped DICE data into virtual memory: Start={start_ptr:p}");
 
     let result = {
         // Safety: we have checked the length, know it is backed by physical memory and is reserved.
@@ -125,13 +133,16 @@ fn read_stage0_dice_data(start: PhysAddr) -> anyhow::Result<Stage0DiceData> {
         source.zeroize();
         result
     };
+    println!("Read DICE data: Magic={}", result.magic);
 
     if result.magic != STAGE0_MAGIC {
         anyhow::bail!("invalid DICE data");
     }
 
     // Safety: we have just mapped this memory, and the slice over it has been dropped.
     unsafe { munmap(start_ptr, length)? };
+    println!("Unmapped DICE data from virtual memory");
+
     Ok(result)
 }
 

oak_containers_stage1/src/image.rs

@@ -35,6 +35,7 @@ pub fn switch(init: &str) -> Result<!> {
     let args: Vec<CString> = std::env::args_os()
         .map(|arg| CString::new(arg.as_bytes()).unwrap())
         .collect();
+    println!("Switching to {init} with args {args:?}");
     execv(CString::new(init).unwrap().as_c_str(), &args[..])?;
     unreachable!()
 }

oak_containers_stage1/src/main.rs

@@ -57,6 +57,8 @@ struct Args {
 #[tokio::main]
 async fn main() -> Result<(), Box<dyn Error>> {
     let args = Args::parse();
+
+    println!("Mounting /dev");
     if !Path::new("/dev").try_exists()? {
         create_dir("/dev").context("error creating /dev")?;
     }
@@ -69,6 +71,7 @@ async fn main() -> Result<(), Box<dyn Error>> {
     )
     .context("error mounting /dev")?;
 
+    println!("Creating /dev/ram0");
     Command::new("/mke2fs")
         .args(["/dev/ram0"])
         .spawn()?
@@ -77,6 +80,8 @@ async fn main() -> Result<(), Box<dyn Error>> {
     if !Path::new("/rootfs").try_exists()? {
         create_dir("/rootfs").context("error creating /rootfs")?;
     }
+
+    println!("Mounting /dev/ram0 to /rootfs");
     mount(
         Some("/dev/ram0"),
         "/rootfs",
@@ -86,6 +91,7 @@ async fn main() -> Result<(), Box<dyn Error>> {
     )
     .context("error mounting ramdrive to /rootfs")?;
 
+    println!("Mounting /sys");
     // Mount /sys so that we can read the memory map.
     if !Path::new("/sys").try_exists()? {
         create_dir("/sys").context("error creating /sys")?;
@@ -102,10 +108,12 @@ async fn main() -> Result<(), Box<dyn Error>> {
     let mut dice_builder = dice::extract_stage0_dice_data(args.dice_addr)?;
 
     // Unmount /sys and /dev as they are no longer needed.
+    println!("Unmounting /sys and /dev");
     umount("/sys").context("failed to unmount /sys")?;
     umount("/dev").context("failed to unmount /dev")?;
 
     // switch_root(8) magic
+    println!("Switching root");
     chdir("/rootfs").context("failed to chdir to /rootfs")?;
     mount(
         Some("/rootfs"),
@@ -118,10 +126,12 @@ async fn main() -> Result<(), Box<dyn Error>> {
     chroot(".").context("failed to chroot to .")?;
     chdir("/").context("failed to chdir to /")?;
 
+    println!("Creating launcher client");
     let mut client = LauncherClient::new(args.launcher_addr.parse()?)
         .await
         .context("error creating the launcher client")?;
 
+    println!("Fetching system image");
     let buf = client
         .get_oak_system_image()
         .await