uefi/helpers: logger logs to debugcon device

This modifies the logger so that it also prints to the debugcon device
in QEMU respectively the debug-console device in cloud-hypervisor [0].
By default, this device is at I/O port 0xe9. This only works on x86.

The major benefit is that one can get log output from the logger set up
by uefi::helpers::init even after boot services has been exited. Now the
memory map can be logged, for example.

When the integration test runs, the output txt file is put into the root
directory of the project.

Also everyone else developing UEFI apps using uefi-rs and running them in
QEMU or cloud-hypervisor (on x86) benefits.

[0]: https://phip1611.de/blog/how-to-use-qemus-debugcon-feature/

Author: phip1611

.gitignore

@@ -3,3 +3,6 @@
 
 # Files generated by mdBook.
 /book/book/
+
+# Integration test output by QEMU.
+integration-test-debugcon.log

uefi-test-runner/src/main.rs

@@ -196,10 +196,23 @@ fn shutdown(mut st: SystemTable<Boot>) -> ! {
     // type of regression this prevents.
     info!("LOGGING_STILL_WORKING_RIGHT_BEFORE_EBS");
 
-    info!("Testing complete, shutting down...");
+    info!("Testing complete, exiting boot services...");
 
     // Exit boot services as a proof that it works :)
-    let (st, _iter) = st.exit_boot_services(MemoryType::LOADER_DATA);
+    let (st, mmap) = st.exit_boot_services(MemoryType::LOADER_DATA);
+
+    info!("Memory Map:");
+    for desc in mmap.entries() {
+        info!(
+            "start=0x{:016x} size=0x{:016x} type={:?}, attr={:?}",
+            desc.phys_start,
+            desc.page_count * 4096,
+            desc.ty,
+            desc.att
+        );
+    }
+
+    info!("Shutting down...");
 
     #[cfg(target_arch = "x86_64")]
     {

uefi/CHANGELOG.md

@@ -3,6 +3,11 @@
 ## Added
 - Added `RuntimeServices::update_capsule`.
 - Added `RuntimeServices::query_capsule_capabilities`.
+- The logger from `uefi::helpers` now also logs to the [debugcon](https://phip1611.de/blog/how-to-use-qemus-debugcon-feature/)
+  device (QEMU) respectively the debug-console (cloud-hypervisor). This only
+  works on x86. It is activated by default (only on x86) and can be deactivated
+  by removing the `log-debugcon` cargo feature. The major benefit is that one
+  can get log messages even after one exited the boot services.
 
 ## Removed
 - Removed the `panic-on-logger-errors` feature of the `uefi` crate. Logger
@@ -13,8 +18,6 @@
 
 ## Added
 - Added `ResetNotification` protocol.
-
-## Added
 - Added `Timestamp` protocol.
 - Added `UnalignedSlice::as_ptr`.
 - Added common derives for `Event` and `Handle`.

uefi/Cargo.toml

@@ -13,6 +13,7 @@ repository.workspace = true
 rust-version.workspace = true
 
 [features]
+default = [ "log-debugcon" ]
 alloc = []
 
 # Generic gate to code that uses unstable features of Rust. You usually need a nightly toolchain.
@@ -22,7 +23,14 @@ unstable = []
 logger = []
 global_allocator = []
 panic_handler = []
-qemu = ["dep:qemu-exit", "panic_handler"] # panic_handler: logical, not technical dependency
+# Some convenience when running inside QEMU.
+# - dependency log-debugcon: logical, not technical
+# - dependency panic_handler: logical, not technical 
+qemu = ["dep:qemu-exit", "panic_handler", "log-debugcon"]
+# Whether the internal logger from the helpers module should also log to
+# the debugcon device (QEMU) and debug-console (cloud-hypervisor). Only works
+# on x86.
+log-debugcon = []
 
 [dependencies]
 bitflags.workspace = true

uefi/src/helpers/logger.rs

@@ -12,9 +12,8 @@
 //! The last part also means that some Unicode characters might not be
 //! supported by the UEFI console. Don't expect emoji output support.
 
-use crate::proto::console::text::Output;
-
 use crate::prelude::{Boot, SystemTable};
+use crate::proto::console::text::Output;
 use core::fmt::{self, Write};
 use core::ptr;
 use core::sync::atomic::{AtomicPtr, Ordering};
@@ -43,6 +42,31 @@ pub fn disable() {
     LOGGER.disable();
 }
 
+/// Writer to the QEMU debugcon device and the debug-console of
+/// cloud-hypervisor.
+///
+/// More info: <https://phip1611.de/blog/how-to-use-qemus-debugcon-feature/>
+#[cfg(any(target_arch = "x86", target_arch = "x86_64"))]
+#[derive(Copy, Clone, Debug)]
+struct DebugconWriter;
+
+#[cfg(any(target_arch = "x86", target_arch = "x86_64"))]
+impl DebugconWriter {
+    const IO_PORT: u16 = 0xe9;
+}
+
+#[cfg(any(target_arch = "x86", target_arch = "x86_64"))]
+impl core::fmt::Write for DebugconWriter {
+    fn write_str(&mut self, s: &str) -> fmt::Result {
+        for &byte in s.as_bytes() {
+            unsafe {
+                core::arch::asm!("outb %al, %dx", in("al") byte, in("dx") DebugconWriter::IO_PORT, options(att_syntax))
+            };
+        }
+        Ok(())
+    }
+}
+
 /// Logging implementation which writes to a UEFI output stream.
 ///
 /// If this logger is used as a global logger, you must disable it using the
@@ -99,15 +123,13 @@ impl Logger {
 
 impl log::Log for Logger {
     fn enabled(&self, _metadata: &log::Metadata) -> bool {
-        !self.output().is_null()
+        // We decide in `log` already if something is printed. We do not
+        // need micro optimizations here.
+        true
     }
 
     fn log(&self, record: &log::Record) {
-        let output = self.output();
-
-        if !output.is_null() {
-            let writer = unsafe { &mut *output };
-
+        if let Some(writer) = unsafe { self.output().as_mut() } {
             // Ignore all errors. Since we're in the logger implementation we
             // can't log the error. We also don't want to panic, since logging
             // is generally not critical functionality.
@@ -119,6 +141,23 @@ impl log::Log for Logger {
                 record.line().unwrap_or(0),
             );
         }
+
+        #[cfg(all(
+            any(target_arch = "x86", target_arch = "x86_64"),
+            feature = "log-debugcon"
+        ))]
+        {
+            // Ignore all errors. Since we're in the logger implementation we
+            // can't log the error. We also don't want to panic, since logging
+            // is generally not critical functionality.
+            let _ = DecoratedLog::write(
+                &mut DebugconWriter,
+                record.level(),
+                record.args(),
+                record.file().unwrap_or("<unknown file>"),
+                record.line().unwrap_or(0),
+            );
+        }
     }
 
     fn flush(&self) {

uefi/src/helpers/mod.rs

@@ -4,7 +4,10 @@
 //!
 //! For now, this includes:
 //! - using [`uefi::allocator::Allocator`] as global allocator (feature `global_allocator`)
-//! - an implementation of  [`log::Log`] (feature `logger`)
+//! - an implementation of  [`log::Log`] (feature `logger`) which logs to
+//!   the stdout text protocol of UEFI (as long as boot services were not
+//!   excited) and to the [debugcon device](https://phip1611.de/blog/how-to-use-qemus-debugcon-feature/)
+//!   (only on x86)  (feature `log-debugcon`).
 //! - [`print!`][print_macro] and [`println!`][println_macro] macros defaulting
 //!   to the uefi boot service stdout stream
 //! - default panic handler (feature `panic_handler`)
@@ -73,7 +76,8 @@ pub fn system_table() -> SystemTable<Boot> {
 /// memory allocation capabilities.
 ///
 /// **PLEASE NOTE** that these helpers are meant for the pre exit boot service
-/// epoch.
+/// epoch. Limited functionality might work after exiting them, such as logging
+/// to the debugcon device.
 pub fn init(st: &mut SystemTable<Boot>) -> Result<()> {
     if system_table_opt().is_some() {
         // Avoid double initialization.

xtask/src/qemu.rs

@@ -484,6 +484,10 @@ pub fn run_qemu(arch: UefiArch, opt: &QemuOpt) -> Result<()> {
 
     cmd.args(["-device", "virtio-rng-pci"]);
 
+    if arch == UefiArch::IA32 || arch == UefiArch::X86_64 {
+        cmd.args(["-debugcon", "file:./integration-test-debugcon.log"]);
+    }
+
     // Set the boot menu timeout to zero. On aarch64 in particular this speeds
     // up the boot a lot. Note that we have to enable the menu here even though
     // we are skipping right past it, otherwise `splash-time` is ignored in