vmbase: Temporarily disable logging in exception handlers

Add `logger::block` which temporarily disables logging. This should be used
to prevent log messages being sent to UART from exception handlers. It
allows calling external code in exception handlers which may produce log
messages. Also stop exporting `println` macros from vmbase for the same
reason and use log macros instead.

Bug: 245267332
Test: atest vmbase_example.integration_test

Change-Id: I99e5ea1fa15e7371fd680e4086a3685ac489111d
diff --git a/vmbase/example/src/layout.rs b/vmbase/example/src/layout.rs
index 4c3af6d..e660c5f 100644
--- a/vmbase/example/src/layout.rs
+++ b/vmbase/example/src/layout.rs
@@ -17,8 +17,8 @@
 use aarch64_paging::paging::{MemoryRegion, VirtualAddress};
 use core::arch::asm;
 use core::ops::Range;
+use log::info;
 use vmbase::layout;
-use vmbase::println;
 use vmbase::STACK_CHK_GUARD;
 
 /// The first 1 GiB of memory are used for MMIO.
@@ -74,14 +74,14 @@
 
 pub fn print_addresses() {
     let dtb = dtb_range();
-    println!("dtb:        {}..{} ({} bytes)", dtb.start, dtb.end, dtb.end - dtb.start);
+    info!("dtb:        {}..{} ({} bytes)", dtb.start, dtb.end, dtb.end - dtb.start);
     let text = text_range();
-    println!("text:       {}..{} ({} bytes)", text.start, text.end, text.end - text.start);
+    info!("text:       {}..{} ({} bytes)", text.start, text.end, text.end - text.start);
     let rodata = rodata_range();
-    println!("rodata:     {}..{} ({} bytes)", rodata.start, rodata.end, rodata.end - rodata.start);
-    println!("binary end: {}", binary_end());
+    info!("rodata:     {}..{} ({} bytes)", rodata.start, rodata.end, rodata.end - rodata.start);
+    info!("binary end: {}", binary_end());
     let data = data_range();
-    println!(
+    info!(
         "data:       {}..{} ({} bytes, loaded at {})",
         data.start,
         data.end,
@@ -89,9 +89,9 @@
         data_load_address(),
     );
     let bss = bss_range();
-    println!("bss:        {}..{} ({} bytes)", bss.start, bss.end, bss.end - bss.start);
+    info!("bss:        {}..{} ({} bytes)", bss.start, bss.end, bss.end - bss.start);
     let boot_stack = boot_stack_range();
-    println!(
+    info!(
         "boot_stack: {}..{} ({} bytes)",
         boot_stack.start,
         boot_stack.end,
diff --git a/vmbase/example/src/main.rs b/vmbase/example/src/main.rs
index 9ec2dc4..ed0275b 100644
--- a/vmbase/example/src/main.rs
+++ b/vmbase/example/src/main.rs
@@ -34,8 +34,8 @@
 use core::ffi::CStr;
 use fdtpci::PciInfo;
 use libfdt::Fdt;
-use log::{debug, info, trace, LevelFilter};
-use vmbase::{logger, main, println};
+use log::{debug, error, info, trace, warn, LevelFilter};
+use vmbase::{logger, main};
 
 static INITIALISED_DATA: [u32; 4] = [1, 2, 3, 4];
 static mut ZEROED_DATA: [u32; 10] = [0; 10];
@@ -55,7 +55,7 @@
 pub fn main(arg0: u64, arg1: u64, arg2: u64, arg3: u64) {
     logger::init(LevelFilter::Debug).unwrap();
 
-    println!("Hello world");
+    info!("Hello world");
     info!("x0={:#018x}, x1={:#018x}, x2={:#018x}, x3={:#018x}", arg0, arg1, arg2, arg3);
     print_addresses();
     assert_eq!(arg0, dtb_range().start.0 as u64);
@@ -127,6 +127,8 @@
 
     let mut pci_root = unsafe { pci_info.make_pci_root() };
     check_pci(&mut pci_root);
+
+    emit_suppressed_log();
 }
 
 fn check_stack_guard() {
@@ -236,3 +238,21 @@
         ]
     );
 }
+
+macro_rules! log_all_levels {
+    ($msg:literal) => {{
+        error!($msg);
+        warn!($msg);
+        info!($msg);
+        debug!($msg);
+        trace!($msg);
+    }};
+}
+
+fn emit_suppressed_log() {
+    {
+        let _guard = logger::suppress();
+        log_all_levels!("Suppressed message");
+    }
+    log_all_levels!("Unsuppressed message");
+}
diff --git a/vmbase/example/tests/test.rs b/vmbase/example/tests/test.rs
index 8f0eaa5..9088f1a 100644
--- a/vmbase/example/tests/test.rs
+++ b/vmbase/example/tests/test.rs
@@ -24,6 +24,7 @@
 use anyhow::{Context, Error};
 use log::info;
 use std::{
+    collections::{HashSet, VecDeque},
     fs::File,
     io::{self, BufRead, BufReader, Read, Write},
     os::unix::io::FromRawFd,
@@ -89,7 +90,7 @@
         taskProfiles: vec![],
         gdbPort: 0, // no gdb
     });
-    let console = android_log_fd()?;
+    let (handle, console) = android_log_fd()?;
     let (mut log_reader, log_writer) = pipe()?;
     let vm = VmInstance::create(service.as_ref(), &config, Some(console), Some(log_writer), None)
         .context("Failed to create VM")?;
@@ -99,6 +100,7 @@
     // Wait for VM to finish, and check that it shut down cleanly.
     let death_reason = vm.wait_for_death();
     assert_eq!(death_reason, DeathReason::Shutdown);
+    handle.join().unwrap();
 
     // Check that the expected string was written to the log VirtIO console device.
     let expected = "Hello VirtIO console\n";
@@ -109,15 +111,10 @@
     Ok(())
 }
 
-fn android_log_fd() -> io::Result<File> {
+fn android_log_fd() -> Result<(thread::JoinHandle<()>, File), io::Error> {
     let (reader, writer) = pipe()?;
-
-    thread::spawn(|| {
-        for line in BufReader::new(reader).lines() {
-            info!("{}", line.unwrap());
-        }
-    });
-    Ok(writer)
+    let handle = thread::spawn(|| VmLogProcessor::new(reader).run().unwrap());
+    Ok((handle, writer))
 }
 
 fn pipe() -> io::Result<(File, File)> {
@@ -129,3 +126,51 @@
 
     Ok((reader, writer))
 }
+
+struct VmLogProcessor {
+    reader: Option<File>,
+    expected: VecDeque<String>,
+    unexpected: HashSet<String>,
+    had_unexpected: bool,
+}
+
+impl VmLogProcessor {
+    fn messages() -> (VecDeque<String>, HashSet<String>) {
+        let mut expected = VecDeque::new();
+        let mut unexpected = HashSet::new();
+        for log_lvl in ["[ERROR]", "[WARN]", "[INFO]", "[DEBUG]"] {
+            expected.push_back(format!("{log_lvl} Unsuppressed message"));
+            unexpected.insert(format!("{log_lvl} Suppressed message"));
+        }
+        (expected, unexpected)
+    }
+
+    fn new(reader: File) -> Self {
+        let (expected, unexpected) = Self::messages();
+        Self { reader: Some(reader), expected, unexpected, had_unexpected: false }
+    }
+
+    fn verify(&mut self, msg: &str) {
+        if self.expected.front() == Some(&msg.to_owned()) {
+            self.expected.pop_front();
+        }
+        if !self.had_unexpected && self.unexpected.contains(msg) {
+            self.had_unexpected = true;
+        }
+    }
+
+    fn run(mut self) -> Result<(), &'static str> {
+        for line in BufReader::new(self.reader.take().unwrap()).lines() {
+            let msg = line.unwrap();
+            info!("{msg}");
+            self.verify(&msg);
+        }
+        if !self.expected.is_empty() {
+            Err("missing expected log message")
+        } else if self.had_unexpected {
+            Err("unexpected log message")
+        } else {
+            Ok(())
+        }
+    }
+}