Merge pull request #6 from Anders429/0.2.0

0.2.0

.gitmodules

@@ -1,3 +1,3 @@
 [submodule "tests/mgba_logs/mgba"]
-	path = tests/mgba_logs/mgba
+	path = tests/mgba_log_reporter/mgba
 	url = https://github.com/mgba-emu/mgba.git

CHANGELOG.md

@@ -1,5 +1,13 @@
 # Changelog
 
+## Unreleased
+
+## 0.2.0 - 2023-06-10
+### Changed
+- Removed `voladdress` as a dependency.
+### Fixed
+- Synchronization issues when logging from interrupt handler while already logging in main execution.
+
 ## 0.1.0 - 2023-06-06
 ### Added
 - `init()` function to initialize logging.

Cargo.toml

@@ -1,6 +1,6 @@
 [package]
 name = "mgba_log"
-version = "0.1.0"
+version = "0.2.0"
 authors = ["Anders Evensen"]
 edition = "2021"
 license = "MIT OR Apache-2.0"
@@ -12,9 +12,8 @@ keywords = ["log", "logging", "logger", "gba", "mgba"]
 
 [dependencies]
 log = "0.4.18"
-voladdress = "1.3.0"
 
 [dev-dependencies]
 cargo_metadata = "0.15.4"
-mgba_logs = {path = "tests/mgba_logs"}
+mgba_log_reporter = {path = "tests/mgba_log_reporter"}
 serde_json = "1.0.96"

src/lib.rs

@@ -38,19 +38,22 @@ use core::{
     fmt::{write, Display, Write},
 };
 use log::{LevelFilter, Log, Metadata, Record, SetLoggerError};
-use voladdress::{Safe, VolAddress, VolBlock};
 
 /// Buffer for log messages to be written to.
-const MGBA_LOG_BUFFER: VolBlock<u8, Safe, Safe, 256> = unsafe { VolBlock::new(0x04FF_F600) };
+const MGBA_LOG_BUFFER: *mut u8 = 0x04FF_F600 as *mut u8;
 /// Send register.
 ///
 /// Writing a level to this address drains the log buffer, logging it at the given log level.
-const MGBA_LOG_SEND: VolAddress<Level, Safe, Safe> = unsafe { VolAddress::new(0x04FF_F700) };
+const MGBA_LOG_SEND: *mut Level = 0x04FF_F700 as *mut Level;
 /// Register for enabling logging.
 ///
 /// Writing a value of `0xC0DE` to this address will initialize logging. If logging was initialized
 /// properly in mGBA, reading this address will return the value `0x1DEA`.
-const MGBA_LOG_ENABLE: VolAddress<u16, Safe, Safe> = unsafe { VolAddress::new(0x04FF_F780) };
+const MGBA_LOG_ENABLE: *mut u16 = 0x04FF_F780 as *mut u16;
+/// Interrupt Master Enable.
+///
+/// This register allows enabling and disabling interrupts.
+const IME: *mut bool = 0x0400_0208 as *mut bool;
 
 /// A log level within mGBA.
 ///
@@ -105,6 +108,37 @@ impl Writer {
     fn new(level: Level) -> Self {
         Self { level, index: 0 }
     }
+
+    fn write_byte(&mut self, byte: u8) {
+        // Write the new byte.
+        // SAFETY: This is guaranteed to be valid and in-bounds.
+        unsafe {
+            MGBA_LOG_BUFFER
+                .add(self.index as usize)
+                .write_volatile(byte);
+        }
+
+        let (index, overflowed) = self.index.overflowing_add(1);
+        self.index = index;
+        if overflowed {
+            // SAFETY: This is guaranteed to be a write to a valid address.
+            unsafe {
+                MGBA_LOG_SEND.write_volatile(self.level);
+            }
+        }
+    }
+
+    fn send(&mut self) {
+        // Write a null byte, indicating that this is the end of the message.
+        self.write_byte(b'\x00');
+        if self.index != 0 {
+            // SAFETY: This is guaranteed to be a write to a valid address.
+            unsafe {
+                MGBA_LOG_SEND.write_volatile(self.level);
+            }
+            self.index = 0;
+        }
+    }
 }
 
 impl Write for Writer {
@@ -116,29 +150,17 @@ impl Write for Writer {
             match byte {
                 b'\n' => {
                     // For readability purposes, just start a new log line.
-                    self.index = 0;
-                    MGBA_LOG_SEND.write(self.level);
-                    continue;
+                    self.send();
                 }
                 b'\x00' => {
                     // mGBA interprets null as the end of a line, so we replace null characters
                     // with substitute characters when they are intentionally logged.
-
-                    // SAFETY: This is guaranteed to be in-bounds.
-                    unsafe { MGBA_LOG_BUFFER.get(self.index as usize).unwrap_unchecked() }
-                        .write(b'\x1a');
+                    self.write_byte(b'\x1a');
                 }
                 _ => {
-                    // SAFETY: This is guaranteed to be in-bounds.
-                    unsafe { MGBA_LOG_BUFFER.get(self.index as usize).unwrap_unchecked() }
-                        .write(byte);
+                    self.write_byte(byte);
                 }
             }
-            let (index, overflowed) = self.index.overflowing_add(1);
-            self.index = index;
-            if overflowed {
-                MGBA_LOG_SEND.write(self.level);
-            }
         }
         Ok(())
     }
@@ -147,7 +169,7 @@ impl Write for Writer {
 impl Drop for Writer {
     /// Flushes the buffer, ensuring that the remaining bytes are sent.
     fn drop(&mut self) {
-        MGBA_LOG_SEND.write(self.level);
+        self.send();
     }
 }
 
@@ -174,9 +196,23 @@ impl Log for Logger {
     /// Buffer flushing is handled automatically during logging.
     fn log(&self, record: &Record) {
         if let Ok(level) = Level::try_from(record.level()) {
-            let mut writer = Writer::new(level);
-            write(&mut writer, *record.args())
+            // Disable interrupts, storing the previous value.
+            //
+            // This prevents synchronization issues when messages are logged in interrupt handling.
+            // Interrupts triggered during this time will be handled when interrupts are reenabled.
+            let previous_ime = unsafe { IME.read_volatile() };
+            unsafe { IME.write_volatile(false) };
+
+            // Write log record.
+            //
+            // Note that the writer is dropped after this, causing the buffer to be flushed.
+            write(&mut &mut Writer::new(level), *record.args())
                 .unwrap_or_else(|error| panic!("write to mGBA log buffer failed: {}", error));
+
+            // Restore previous interrupt enable value.
+            unsafe {
+                IME.write_volatile(previous_ime);
+            }
         }
     }
 
@@ -206,7 +242,8 @@ macro_rules! fatal {
 #[doc(hidden)]
 pub fn __fatal(args: fmt::Arguments) {
     // Ensure mGBA is listening.
-    if MGBA_LOG_ENABLE.read() == 0x1DEA {
+    // SAFETY: This is guaranteed to be a valid read.
+    if unsafe { MGBA_LOG_ENABLE.read_volatile() } == 0x1DEA {
         // Fatal logging is often used in panic handlers, so panicking on write failures would lead
         // to recursive panicking. Instead, this fails silently.
         #[allow(unused_must_use)]
@@ -261,8 +298,12 @@ static LOGGER: Logger = Logger;
 /// reason, it instead returns an [`Error`]. See the documentation for [`Error`] for what errors
 /// can occur.
 pub fn init() -> Result<(), Error> {
-    MGBA_LOG_ENABLE.write(0xC0DE);
-    if MGBA_LOG_ENABLE.read() != 0x1DEA {
+    // SAFETY: This is guaranteed to be a valid write.
+    unsafe {
+        MGBA_LOG_ENABLE.write(0xC0DE);
+    }
+    // SAFETY: This is guaranteed to be a valid read.
+    if unsafe { MGBA_LOG_ENABLE.read_volatile() } != 0x1DEA {
         return Err(Error::NotAcknowledgedByMgba);
     }
     log::set_logger(&LOGGER)

tests/log.rs

@@ -4,7 +4,7 @@
 //! versions.
 
 use cargo_metadata::Message;
-use mgba_logs::{Level, Record};
+use mgba_log_reporter::{Level, Record};
 use std::{
     convert::AsRef,
     io::BufReader,
@@ -45,7 +45,7 @@ fn execute_rom(rom: &str) -> Vec<Record> {
     let mut command = Command::new("cargo")
         .args(["run", rom])
         .stdout(Stdio::piped())
-        .current_dir("tests/mgba_logs")
+        .current_dir("tests/mgba_log_reporter")
         .spawn()
         .expect("failed to run rom");
 
@@ -165,3 +165,26 @@ fn overflow() {
         message: "wxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyz".to_owned(),
     }));
 }
+
+#[test]
+fn sync() {
+    let rom = build_rom("tests/sync");
+
+    let records = execute_rom(&rom);
+
+    assert!(records.contains(&Record {
+        level: Level::Info,
+        message: "Hello, world!".to_owned(),
+    }));
+    assert!(records.contains(&Record {
+        level: Level::Debug,
+        message: "in irq".to_owned(),
+    }));
+    // Synchronization issues will cause empty messages to be included in the output. This happens
+    // because the buffer is flushed before writing has finished, and mGBA then interprets the null
+    // character at the start of the buffer as the end of the message.
+    assert!(!records.contains(&Record {
+        level: Level::Info,
+        message: "".to_owned(),
+    }))
+}

tests/mgba_logs/Cargo.toml → tests/mgba_log_reporter/Cargo.toml

@@ -1,10 +1,8 @@
 [package]
-name = "mgba_logs"
+name = "mgba_log_reporter"
 version = "0.1.0"
 edition = "2021"
 
-# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html
-
 [dependencies]
 serde = {version = "1.0.163", features = ["derive"]}
 serde_json = "1.0.96"

tests/mgba_log_reporter/c/runner.h

@@ -0,0 +1,32 @@
+// These are bindings to mGBA's core itself.
+//
+// Defined here are all of the structs and functions necessary for the binary to set up and
+// interact directly with an mGBA instance.
+
+#include <stdbool.h>
+#include <stdint.h>
+
+struct MGBA;
+
+// Creates a new instance of mGBA, loaded with the provided ROM.
+struct MGBA* load(char* rom);
+
+struct callback {
+    void* data;
+    void (*callback)(void*, char[], uint8_t);
+    void (*destroy)(void*);
+};
+
+// Sets a function to be called when logs are received.
+void set_log_callback(struct MGBA* mgba, struct callback callback);
+
+// Reports whether the ROM processing has finished.
+//
+// This is reported by the ROM itself by writing the value `3` to `0x0203FFFF`.
+bool is_finished(struct MGBA* mgba);
+
+// Advance emulation by a single step.
+void step(struct MGBA* mgba);
+
+// Free the mGBA instance.
+void drop(struct MGBA* mgba);

tests/mgba_logs/src/lib.rs → tests/mgba_log_reporter/src/lib.rs

@@ -1,5 +1,11 @@
+//! A publicly exposed library for interoperating with the output of the binary.
+//!
+//! These types can be used to deserialize the JSON output from the binary. This allows reading the
+//! reported log messages.
+
 use serde::{Deserialize, Serialize};
 
+/// The level of a log message.
 #[derive(Debug, Deserialize, Eq, PartialEq, Serialize)]
 pub enum Level {
     Fatal,
@@ -12,6 +18,9 @@ pub enum Level {
 impl TryFrom<u8> for Level {
     type Error = ();
 
+    /// This is the conversion from the actual level value used internally by mGBA. Other values
+    /// are possible as well (there are some log levels that are not possible when logging from a
+    /// ROM itself); these values simply return an error.
     fn try_from(level: u8) -> Result<Self, ()> {
         match level {
             0x01 => Ok(Self::Fatal),
@@ -24,8 +33,11 @@ impl TryFrom<u8> for Level {
     }
 }
 
+/// A single logged message.
 #[derive(Debug, Deserialize, Eq, PartialEq, Serialize)]
 pub struct Record {
+    /// The message's level.
     pub level: Level,
+    /// The log message itself.
     pub message: String,
 }

tests/mgba_logs/src/main.rs → tests/mgba_log_reporter/src/main.rs

@@ -1,13 +1,20 @@
+//! This binary allows running a GBA ROM in an instance of mGBA and capturing the logs emitted by
+//! that ROM.
+//!
+//! Logs that are captured are output as serialized JSON. They can be deserialized into the types
+//! exposed in this crate's library interface.
+
 mod mgba_bindings;
 
-use mgba_logs::{Level, Record};
+use mgba_log_reporter::Record;
 use std::{
     env,
     ffi::{c_char, c_uchar, c_void, CStr, CString},
     io::stdout,
     path::Path,
 };
 
+/// Run the provided ROM file, returning the captured logs.
 fn run(rom: &str) -> Vec<Record> {
     // Create new mGBA core for ROM.
     let rom_c_string = CString::new(rom).expect("failed to convert rom name to CString");
@@ -46,6 +53,9 @@ fn run(rom: &str) -> Vec<Record> {
     results
 }
 
+/// Create a callback from a function that can be passed to the mGBA bindings.
+///
+/// This can be used to create a function for capturing mGBA logs.
 unsafe fn generate_c_callback<F>(f: F) -> mgba_bindings::callback
 where
     F: FnMut(*mut c_char, c_uchar),
@@ -59,6 +69,7 @@ where
     }
 }
 
+/// Wrapper for a function to interface directly with the callback call.
 extern "C" fn call_closure<F>(data: *mut c_void, message: *mut c_char, level: c_uchar)
 where
     F: FnMut(*mut c_char, c_uchar),
@@ -68,9 +79,10 @@ where
     callback(message, level);
 }
 
+/// Wrapper for a function to allow it to be dropped.
 extern "C" fn drop_box<T>(data: *mut c_void) {
     unsafe {
-        Box::from_raw(data as *mut T);
+        drop(Box::from_raw(data as *mut T));
     }
 }
 

tests/mgba_log_reporter/src/mgba_bindings.rs

@@ -0,0 +1,11 @@
+//! Exposes the bindings used for operating with mGBA directly.
+
+#![allow(
+    dead_code,
+    non_camel_case_types,
+    non_snake_case,
+    non_upper_case_globals
+)]
+
+// Bindings are generated by build.rs.
+include!(concat!(env!("OUT_DIR"), "/bindings.rs"));