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/README.md b/vmbase/README.md
index 552ac31..7f621fb 100644
--- a/vmbase/README.md
+++ b/vmbase/README.md
@@ -51,12 +51,14 @@
entry point. Instead, `vmbase` provides a macro to specify your main function:
```rust
-use vmbase::{main, println};
+use vmbase::{logger, main};
+use log::{info, LevelFilter};
main!(main);
pub fn main(arg0: u64, arg1: u64, arg2: u64, arg3: u64) {
- println!("Hello world");
+ logger::init(LevelFilter::Info).unwrap();
+ info!("Hello world");
}
```
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(())
+ }
+ }
+}
diff --git a/vmbase/src/console.rs b/vmbase/src/console.rs
index fabea91..7c8ddf6 100644
--- a/vmbase/src/console.rs
+++ b/vmbase/src/console.rs
@@ -40,14 +40,14 @@
/// Writes a string to the console.
///
/// Panics if [`init`] was not called first.
-pub fn write_str(s: &str) {
+pub(crate) fn write_str(s: &str) {
CONSOLE.lock().as_mut().unwrap().write_str(s).unwrap();
}
/// Writes a formatted string to the console.
///
/// Panics if [`init`] was not called first.
-pub fn write_args(format_args: Arguments) {
+pub(crate) fn write_args(format_args: Arguments) {
write(CONSOLE.lock().as_mut().unwrap(), format_args).unwrap();
}
@@ -69,20 +69,10 @@
let _ = write(&mut uart, format_args);
}
-/// Prints the given string to the console.
-///
-/// Panics if the console has not yet been initialised. May hang if used in an exception context;
-/// use `eprint!` instead.
-#[macro_export]
-macro_rules! print {
- ($($arg:tt)*) => ($crate::console::write_args(format_args!($($arg)*)));
-}
-
/// Prints the given formatted string to the console, followed by a newline.
///
/// Panics if the console has not yet been initialised. May hang if used in an exception context;
/// use `eprintln!` instead.
-#[macro_export]
macro_rules! println {
() => ($crate::console::write_str("\n"));
($($arg:tt)*) => ({
@@ -91,6 +81,8 @@
);
}
+pub(crate) use println; // Make it available in this crate.
+
/// Prints the given string to the console in an emergency, such as an exception handler.
///
/// Never panics.
diff --git a/vmbase/src/entry.rs b/vmbase/src/entry.rs
index 1510ae2..8cdfe77 100644
--- a/vmbase/src/entry.rs
+++ b/vmbase/src/entry.rs
@@ -36,12 +36,14 @@
/// Example:
///
/// ```rust
-/// use vmbase::main;
+/// use vmbase::{logger, main};
+/// use log::{info, LevelFilter};
///
/// main!(my_main);
///
/// fn my_main() {
-/// println!("Hello world");
+/// logger::init(LevelFilter::Info).unwrap();
+/// info!("Hello world");
/// }
/// ```
#[macro_export]
diff --git a/vmbase/src/logger.rs b/vmbase/src/logger.rs
index 5f0f1c2..94dc880 100644
--- a/vmbase/src/logger.rs
+++ b/vmbase/src/logger.rs
@@ -20,27 +20,71 @@
extern crate log;
-use super::println;
+use crate::console::println;
+use core::sync::atomic::{AtomicBool, Ordering};
use log::{LevelFilter, Log, Metadata, Record, SetLoggerError};
-struct Logger;
-static LOGGER: Logger = Logger;
+struct Logger {
+ is_enabled: AtomicBool,
+}
+static mut LOGGER: Logger = Logger::new();
+
+impl Logger {
+ const fn new() -> Self {
+ Self { is_enabled: AtomicBool::new(true) }
+ }
+
+ fn swap_enabled(&mut self, enabled: bool) -> bool {
+ self.is_enabled.swap(enabled, Ordering::Relaxed)
+ }
+}
impl Log for Logger {
fn enabled(&self, _metadata: &Metadata) -> bool {
- true
+ self.is_enabled.load(Ordering::Relaxed)
}
fn log(&self, record: &Record) {
- println!("[{}] {}", record.level(), record.args());
+ if self.enabled(record.metadata()) {
+ println!("[{}] {}", record.level(), record.args());
+ }
}
fn flush(&self) {}
}
+/// An RAII implementation of a log suppressor. When the instance is dropped, logging is re-enabled.
+pub struct SuppressGuard {
+ old_enabled: bool,
+}
+
+impl SuppressGuard {
+ fn new() -> Self {
+ // Safe because it modifies an atomic.
+ unsafe { Self { old_enabled: LOGGER.swap_enabled(false) } }
+ }
+}
+
+impl Drop for SuppressGuard {
+ fn drop(&mut self) {
+ // Safe because it modifies an atomic.
+ unsafe {
+ LOGGER.swap_enabled(self.old_enabled);
+ }
+ }
+}
+
/// Initialize vmbase logger with a given max logging level.
pub fn init(max_level: LevelFilter) -> Result<(), SetLoggerError> {
- log::set_logger(&LOGGER)?;
+ // Safe because it only sets the global logger.
+ unsafe {
+ log::set_logger(&LOGGER)?;
+ }
log::set_max_level(max_level);
Ok(())
}
+
+/// Suppress logging until the return value goes out of scope.
+pub fn suppress() -> SuppressGuard {
+ SuppressGuard::new()
+}