zephyr: Logging through Zephyr log

Implement a simplistic mechanism that is able to log through Zephyr's
logging mechanism.

This change does not attempt to demangle the #define nightmare that is
Zephyr's logging, but just formats to a string, and sends that directly
through a C helper function.

As such, this performs at least one allocation/free, possibly with some
reallocs, depending on how accurate the allocation estimate is, and
whether adding a null terminator requires an additional allocation.

Logs are also all recorded under a single registered log, in the rust
main file.

Signed-off-by: David Brown <[email protected]>

Author: d3zd3z

main.c

@@ -10,12 +10,38 @@
 
 extern void rust_main(void);
 
+// Logging, to see how things things are expanded.
+#include <zephyr/logging/log.h>
+LOG_MODULE_REGISTER(rust, 3);
+
 int main(void)
 {
 	rust_main();
 	return 0;
 }
 
+void rust_log_message(uint32_t level, char *msg) {
+	// Ok.  The log macros in Zephyr perform all kinds of macro stitching, etc, on the
+	// arguments.  As such, we can't just pass the level to something, but actually need to
+	// expand things here.  This puts the file and line information of the log in this file,
+	// rather than where we came from.
+	switch (level) {
+	case LOG_LEVEL_ERR:
+		LOG_ERR("%s", msg);
+		break;
+	case LOG_LEVEL_WRN:
+		LOG_WRN("%s", msg);
+		break;
+	case LOG_LEVEL_INF:
+		LOG_INF("%s", msg);
+		break;
+	case LOG_LEVEL_DBG:
+	default:
+		LOG_DBG("%s", msg);
+		break;
+	}
+}
+
 /* On most arches, panic is entirely macros resulting in some kind of inline assembly.  Create this
  * wrapper so the Rust panic handler can call the same kind of panic.
  */

zephyr-sys/build.rs

@@ -71,9 +71,11 @@ fn main() -> Result<()> {
         .allowlist_function("k_.*")
         .allowlist_function("gpio_.*")
         .allowlist_function("sys_.*")
+        .allowlist_function("z_log.*")
         .allowlist_item("E.*")
         .allowlist_item("K_.*")
         .allowlist_item("ZR_.*")
+        .allowlist_item("LOG_LEVEL_.*")
         // Deprecated
         .blocklist_function("sys_clock_timeout_end_calc")
         .parse_callbacks(Box::new(bindgen::CargoCallbacks::new()))

zephyr-sys/wrapper.h

@@ -33,6 +33,7 @@ extern int errno;
 #include <zephyr/kernel.h>
 #include <zephyr/kernel/thread_stack.h>
 #include <zephyr/drivers/gpio.h>
+#include <zephyr/logging/log.h>
 
 /*
  * bindgen will output #defined constant that resolve to simple numbers.  There are some symbols

zephyr/src/logging.rs

@@ -41,7 +41,8 @@ cfg_if::cfg_if! {
     {
         // Otherwise, if we have logging and allocation, and not minimal, we can use the Zephyr
         // logging backend.  Doing this without allocation is currently a TODO:
-        todo!("Zephyr logging not yet supported");
+        mod impl_zlog;
+        pub use impl_zlog::set_logger;
     } else {
         /// No lagging is possible, provide an empty handler that does nothing.
         ///

zephyr/src/logging/impl_zlog.rs

@@ -0,0 +1,66 @@
+//! Logging through Zephyr's log mechanism.
+//!
+//! This module implements a log handler for the [`log`] crate that logs messages through Zephyr's
+//! logging infrastructure.
+//!
+//! Zephyr's logging is heavily built around a lot of C assumptions, and involves a lot of macros.
+//! As such, this initial implemention will try to keep things simple, and format the message to an
+//! allocated string, and send that off to the logging infrastructure, formatted as a "%s" message.
+//! There are a lot of opportunities to improve this.
+
+extern crate alloc;
+
+use alloc::format;
+use core::ffi::c_char;
+
+use log::{Level, Log, Metadata, Record, SetLoggerError};
+
+use crate::raw;
+
+struct ZlogLogger;
+
+impl Log for ZlogLogger {
+    // For now, just always print messages.
+    fn enabled(&self, _metadata: &Metadata<'_>) -> bool {
+        true
+    }
+
+    /// Print out the log message.
+    fn log(&self, record: &Record<'_>) {
+        let level = match record.level() {
+            Level::Error => raw::LOG_LEVEL_ERR,
+            Level::Warn => raw::LOG_LEVEL_WRN,
+            Level::Info => raw::LOG_LEVEL_INF,
+            Level::Debug => raw::LOG_LEVEL_DBG,
+            // Zephyr doesn't have a separate trace, so fold that into debug.
+            Level::Trace => raw::LOG_LEVEL_DBG,
+        };
+        let mut msg = format!("{}: {}",
+                              record.target(),
+                              record.args());
+        // Append a null so this is a valid C string.  This lets us avoid an additional allocation
+        // and copying.
+        msg.push('\x00');
+        unsafe {
+            rust_log_message(level, msg.as_ptr() as *const c_char);
+        }
+    }
+
+    // Flush not needed.
+    fn flush(&self) {
+    }
+}
+
+extern "C" {
+    fn rust_log_message(level: u32, msg: *const c_char);
+}
+
+static ZLOG_LOGGER: ZlogLogger = ZlogLogger;
+
+/// Set the log handler to log messages through Zephyr's logging framework.
+///
+/// This is unsafe due to racy issues in the log framework on targets that do not support atomic
+/// pointers.
+pub unsafe fn set_logger() -> Result<(), SetLoggerError> {
+    super::set_logger_internal(&ZLOG_LOGGER)
+}