mGBA debug logging allows data race from safe code.

[Anders429]

There seems to be a bit of a soundness issue when logging using the API provided by the mgba module. Since writing to the debug buffer is done in multiple instructions, if an interrupt occurs that also attempts to write to the debug buffer, a data race occurs. Consider the following minimal code example:

#![no_std]
#![no_main]

use core::fmt::Write;
use gba::{
    asm_runtime::RUST_IRQ_HANDLER,
    interrupts::IrqBits,
    mgba::{MgbaBufferedLogger, MgbaMessageLevel},
    mmio::{DISPSTAT, IE, IME},
    video::DisplayStatus,
};

#[panic_handler]
fn panic_handler(_: &core::panic::PanicInfo) -> ! {
    loop {}
}

#[link_section = ".iwram"]
extern "C" fn irq_handler(_: IrqBits) {
    if let Ok(mut logger) = MgbaBufferedLogger::try_new(MgbaMessageLevel::Debug) {
        writeln!(&mut logger, "in irq");
    }
}

#[no_mangle]
pub fn main() {
    RUST_IRQ_HANDLER.write(Some(irq_handler));
    DISPSTAT.write(DisplayStatus::new().with_irq_vblank(true));
    IE.write(IrqBits::VBLANK);
    IME.write(true);

    if let Ok(mut logger) = MgbaBufferedLogger::try_new(MgbaMessageLevel::Info) {
        loop {
            writeln!(&mut logger, "Hello, world!");
        }
    }

    loop {}
}

Here we are writing both in the main execution loop and in the interrupt handler. In the log output, I see unexpected logs such as this (omitting several irrelevant logs, of course):

...
[INFO] GBA Debug:	Hello, world!
[DEBUG] GBA Debug:	in irq wo
[INFO] GBA Debug:	
[INFO] GBA Debug:	Hello, world!
...
[INFO] GBA Debug:	Hello, world!
[DEBUG] GBA Debug:	in irq
[INFO] GBA Debug:	
[INFO] GBA Debug:	Hello, world!
...
[INFO] GBA Debug:	Hello, world!
[DEBUG] GBA Debug:	in irq w
[INFO] GBA Debug:	
[INFO] GBA Debug:	Hello, world!
...

While this is a contrived example, the problem is that both the main code and the interrupt code can access this same memory location through the safe API, causing a data race. Rust should guarantee the absence of data races in safe code (see here). This can result in loss of data that should have been logged, due to the data being overwritten in the shared buffer.

Not sure the best way to prevent this. I was thinking either we could mark the MgbaBufferedLogger::try_new() function as unsafe, requiring the caller to guarantee that it won't be interrupted by another write, or add some mechanism to turn IME off temporarily to ensure it is not interrupted.

[Lokathor]

This is an example of a race condition, but not an actual data race which is a specific subtype of race condition where there's an unsynchronized write mixed with unsynchronized reads. Rust only keeps you free of data races, not from all possible race conditions. For example, if two threads fetch_add the same atomic value, it's a race condition that determines which thread sees N and which thread sees N+1.

The particular way that the buffer is interacted with is via MMIO manipulation, and all of the individual MMIO steps can't be interrupted, so any particular location in memory won't race because the GBA only has one core.

Backing up, MgbaBufferedLogger assumes that it controls the entire debug buffer while it exists and the flushes on drop. If this isn't all true you'll get garbled output. You don't need to use the interrupt system to make it give garbled output though. Any code where you're making and dropping a logger while another logger is still active at an outer scope will display this garbled output. Probably this should be documented better.

[Anders429]

I see your point, and I think I understand my incorrect thinking: I was considering each call to writeln! in my example as a single write, whereas it actually is many individual writes of u8 values. So you're definitely right, it's not a data race, because each write is able to be completed before an interrupt can occur. I assume that this would then hold true for any access to an MMIO address, correct?

So I guess the overall issue would be what you said, that this point you mentioned maybe could be documented more explicitly:

MgbaBufferedLogger assumes that it controls the entire debug buffer while it exists

[Lokathor]

The same logic holds when:

• there's only one CPU core
• the cpu cannot be interrupted mid-instruction.
• the read or write happens in a single instruction

the first two are always the case on the GBA hardware (but might not be on all devices, eg a raspberry pi), and the gba crate takes care to only define MMIO controls that use "native" access widths (1, 2, or 4 bytes, and aligned to the same)