Merge "Add LoggerInterface for logging msgs on the console."

GitOrigin-RevId: 256da9ba28b31f1ac3a87cce0098a52ac918de13

apps/system/components/DebugConsole/Cargo.toml

@@ -4,6 +4,7 @@ members = [
     "kata-debug-console",
     "kata-io",
     "kata-line-reader",
+    "kata-logger",
     "kata-shell",
     "kata-uart-client",
 ]

apps/system/components/DebugConsole/DebugConsole.camkes

@@ -1,3 +1,4 @@
+import <LoggerInterface.camkes>;
 import <SeL4DebugInterface.camkes>;
 
 component DebugConsole {
@@ -6,5 +7,6 @@ component DebugConsole {
   dataport Buf tx_dataport;
   dataport Buf rx_dataport;
 
+  provides LoggerInterface logger;
   uses SeL4DebugInterface sel4debug;
 }

apps/system/components/DebugConsole/kata-allocator/Cargo.toml

@@ -6,4 +6,5 @@ edition = "2018"
 
 [dependencies]
 linked_list_allocator = { version = "0.9", default-features = false, features = ["const_mut_refs"] }
+log = "0.4"
 spin = "0.9"

apps/system/components/DebugConsole/kata-allocator/src/lib.rs

@@ -6,6 +6,7 @@
 use core::alloc::{GlobalAlloc, Layout};
 use core::cell::RefCell;
 use core::ptr::{self, NonNull};
+use log::info;
 
 use linked_list_allocator::Heap;
 use spin::Mutex;
@@ -56,6 +57,7 @@ impl KataHeap {
     /// - This function must be called exactly ONCE.
     /// - `size > 0`
     pub unsafe fn init(&self, start_addr: usize, size: usize) {
+        info!("init: start_addr {:#x} size {}", start_addr, size);
         (*self.heap.lock()).borrow_mut().init(start_addr, size);
     }
 

apps/system/components/DebugConsole/kata-debug-console/Cargo.toml

@@ -8,8 +8,10 @@ description = "Kata OS DebugConsole"
 [dependencies]
 panic-halt = "0.2.0"
 kata-allocator = { path = "../kata-allocator" }
+kata-logger = { path = "../kata-logger" }
 kata-shell = { path = "../kata-shell" }
 kata-uart-client = { path = "../kata-uart-client" }
+log = "0.4"
 
 [lib]
 name = "kata_debug_console"

apps/system/components/DebugConsole/kata-debug-console/src/run.rs

@@ -16,8 +16,18 @@
 extern crate panic_halt;
 
 use kata_allocator;
+use kata_logger::KataLogger;
 use kata_shell;
 use kata_uart_client;
+use log::debug;
+
+static KATA_LOGGER: KataLogger = KataLogger;
+
+#[no_mangle]
+pub extern "C" fn pre_init() {
+    log::set_logger(&KATA_LOGGER).unwrap();
+    log::set_max_level(log::LevelFilter::Debug);
+}
 
 #[no_mangle]
 // NB: use post_init insted of pre_init so syslog interface is setup
@@ -32,6 +42,7 @@ pub extern "C" fn post_init() {
 /// Entry point for DebugConsole. Runs the shell with UART IO.
 #[no_mangle]
 pub extern "C" fn run() -> ! {
+    debug!("run");
     let mut tx = kata_uart_client::Tx {};
     let mut rx = kata_uart_client::Rx {};
     kata_shell::repl(&mut tx, &mut rx);

apps/system/components/DebugConsole/kata-logger/Cargo.toml

@@ -0,0 +1,11 @@
+[package]
+name = "kata-logger"
+version = "0.1.0"
+edition = "2018"
+
+[dependencies]
+arrayvec = { version = "0.7", default-features = false }
+# Disable default so we don't pull in CString which requires an allocator
+bare-io = "0.2"
+cstr_core = { version = "0.2.3", default-features = false }
+log = "0.4"

apps/system/components/DebugConsole/kata-logger/src/lib.rs

@@ -0,0 +1,251 @@
+#![cfg_attr(not(test), no_std)]
+
+use cstr_core::CStr;
+use log::{Metadata, Record};
+
+const MAX_MSG_LEN: usize = 256;
+
+pub struct KataLogger;
+
+impl log::Log for KataLogger {
+    fn enabled(&self, _metadata: &Metadata) -> bool {
+        true
+    }
+
+    fn log(&self, record: &Record) {
+        if self.enabled(record.metadata()) {
+            extern "C" {
+                fn logger_log(msg: *const cstr_core::c_char);
+            }
+            use bare_io::{Cursor, Write};
+            let mut buf = [0 as u8; MAX_MSG_LEN];
+            let mut cur = Cursor::new(&mut buf[..]);
+            // Log msgs are of the form: '<'<level>'>' <target>::<fmt'd-msg>
+            write!(
+                &mut cur,
+                "<{}> {}::{}\0",
+                record.level(),
+                record.target(),
+                record.args()
+            )
+            .unwrap_or_else(|_| {
+                // Too big, indicate overflow with a trailing "...".
+                cur.set_position((MAX_MSG_LEN - 4) as u64);
+                cur.write(b"...\0").expect("write!");
+                ()
+            });
+            unsafe {
+                // If an embedded nul is identified, replace the message; there
+                // are likely better solutions but this should not happen.
+                fn embedded_nul_cstr<'a>(
+                    buf: &'a mut [u8; MAX_MSG_LEN],
+                    record: &Record,
+                ) -> &'a cstr_core::CStr {
+                    let mut cur = Cursor::new(&mut buf[..]);
+                    write!(
+                        &mut cur,
+                        "<{}> {}::<embedded nul>\0",
+                        record.level(),
+                        record.target()
+                    )
+                    .expect("nul!");
+                    let pos = cur.position() as usize;
+                    CStr::from_bytes_with_nul(&buf[..pos]).unwrap()
+                }
+                // NB: this releases the ref on buf held by the Cursor
+                let pos = cur.position() as usize;
+                logger_log(
+                    match CStr::from_bytes_with_nul(&buf[..pos]) {
+                        Ok(cstr) => cstr,
+                        Err(_) => embedded_nul_cstr(&mut buf, record),
+                    }
+                    .as_ptr(),
+                );
+            }
+        }
+    }
+
+    fn flush(&self) {}
+}
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+    use arrayvec::ArrayVec;
+    use log::{debug, error, info, trace, warn};
+
+    static KATA_LOGGER: KataLogger = KataLogger;
+    static mut MSGS: ArrayVec<[u8; MAX_MSG_LEN], 8> = ArrayVec::new_const();
+
+    // Resets msg collection; used at the start of each test.
+    fn reset_msgs() {
+        unsafe {
+            MSGS.clear();
+        }
+    }
+
+    #[no_mangle]
+    pub extern "C" fn logger_log(msg: *const cstr_core::c_char) {
+        unsafe {
+            // NB: this depends on msg pointing to the caller's array
+            MSGS.push(*(msg as *const [u8; MAX_MSG_LEN]));
+        }
+    }
+
+    // Formats a log message as done by KataLogger and returns a zero-padded
+    // Vec holding the message.
+    fn log_msg(level: log::Level, msg: &str) -> Result<Vec<u8>, std::io::Error> {
+        let mut v = Vec::new();
+        use std::io::Write;
+        write!(&mut v, "<{}> {}::{}\0", level, "kata_logger::tests", msg)?;
+        v.resize(MAX_MSG_LEN, 0);
+        assert_eq!(v.len(), MAX_MSG_LEN);
+        Ok(v)
+    }
+
+    fn pop_and_expect_none(level: log::Level) {
+        unsafe {
+            let msg = MSGS.pop();
+            assert_eq!(
+                msg, None,
+                "Assertioon failed for level {}: expected None, got {:?}",
+                level, msg
+            );
+        }
+    }
+
+    fn pop_and_check_result(level: log::Level, test_msg: &str) {
+        unsafe {
+            let msg = MSGS.pop();
+            assert!(
+                msg != None,
+                "Assertion failed for level {}: no log msg collected",
+                level
+            );
+            let expected = log_msg(level, test_msg).unwrap();
+            let observed = msg.unwrap().to_vec();
+            assert_eq!(
+                expected,
+                observed,
+                "Assertion failed for level {}: expected {}, got {}",
+                level,
+                String::from_utf8_lossy(expected.as_slice()),
+                String::from_utf8_lossy(observed.as_slice())
+            );
+        }
+    }
+
+    // NB: to run these sequentially use --test-threads=1; otherwise
+    // cargo will use multiple threads and you will get failures from
+    // multiple users of MSGS and the global logger; e.g.
+    //     cargo +nightly test -- --test-threads=1
+
+    #[test]
+    fn test_each_log_level_works() {
+        reset_msgs();
+
+        let _ = log::set_logger(&KATA_LOGGER);
+        log::set_max_level(log::LevelFilter::Trace);
+
+        let debug_msg = "hello debug";
+        debug!("{}", debug_msg);
+        pop_and_check_result(log::Level::Debug, debug_msg);
+
+        let info_msg = "hello info";
+        info!("{}", info_msg);
+        pop_and_check_result(log::Level::Info, info_msg);
+
+        let warn_msg = "hello warn";
+        warn!("{}", warn_msg);
+        pop_and_check_result(log::Level::Warn, warn_msg);
+
+        let error_msg = "hello error";
+        error!("{}", error_msg);
+        pop_and_check_result(log::Level::Error, error_msg);
+
+        let trace_msg = "hello trace";
+        trace!("{}", trace_msg);
+        pop_and_check_result(log::Level::Trace, trace_msg);
+    }
+
+    #[test]
+    fn test_max_log_level() {
+        reset_msgs();
+
+        let _ = log::set_logger(&KATA_LOGGER);
+        // With filtering at Debug level, levels below should come through.
+        log::set_max_level(log::LevelFilter::Debug);
+
+        let debug_msg = "hello debug";
+        debug!("{}", debug_msg);
+        pop_and_check_result(log::Level::Debug, debug_msg);
+
+        let info_msg = "hello info";
+        info!("{}", info_msg);
+        pop_and_check_result(log::Level::Info, info_msg);
+
+        let warn_msg = "hello warn";
+        warn!("{}", warn_msg);
+        pop_and_check_result(log::Level::Warn, warn_msg);
+
+        let error_msg = "hello error";
+        error!("{}", error_msg);
+        pop_and_check_result(log::Level::Error, error_msg);
+
+        let trace_msg = "hello trace";
+        trace!("{}", trace_msg);
+        pop_and_expect_none(log::Level::Trace);
+
+        // Dynamically adjust the log level
+        log::set_max_level(log::LevelFilter::Info);
+
+        info!("{}", info_msg);
+        pop_and_check_result(log::Level::Info, info_msg);
+
+        debug!("{}", debug_msg);
+        pop_and_expect_none(log::Level::Debug);
+    }
+
+    #[test]
+    fn test_formatting() {
+        reset_msgs();
+
+        let _ = log::set_logger(&KATA_LOGGER);
+        log::set_max_level(log::LevelFilter::Debug);
+
+        debug!("a {} b {} c {} d {:#x}", 99, "foo", 3.4, 32);
+        pop_and_check_result(
+            log::Level::Debug,
+            &format!("a {} b {} c {} d {:#x}", 99, "foo", 3.4, 32)[..],
+        );
+    }
+
+    #[test]
+    fn test_too_long() {
+        reset_msgs();
+
+        let _ = log::set_logger(&KATA_LOGGER);
+        log::set_max_level(log::LevelFilter::Debug);
+
+        // Guarantee formatted message is > MAX_MSG_LEN
+        let mut debug_msg = "debug".repeat((MAX_MSG_LEN / 5) + 1);
+        debug!("{}", debug_msg);
+
+        // Blech, must take into account log msg formatting.
+        debug_msg.truncate(MAX_MSG_LEN - 4 - "<DEBUG> kata_logger::tests::".len());
+        debug_msg.push_str("...");
+        pop_and_check_result(log::Level::Debug, &debug_msg[..]);
+    }
+
+    #[test]
+    fn test_embedded_nul() {
+        reset_msgs();
+
+        let _ = log::set_logger(&KATA_LOGGER);
+        log::set_max_level(log::LevelFilter::Debug);
+
+        let debug_msg = "bar\0foo";
+        debug!("{}", debug_msg);
+        pop_and_check_result(log::Level::Debug, "<embedded nul>");
+    }
+}

apps/system/components/DebugConsole/kata-shell/Cargo.toml

@@ -7,3 +7,4 @@ edition = "2018"
 [dependencies]
 kata-io = { path = "../kata-io" }
 kata-line-reader = { path = "../kata-line-reader" }
+log = "0.4"

apps/system/components/DebugConsole/kata-shell/src/lib.rs

@@ -2,6 +2,7 @@
 
 use core::fmt;
 use core::fmt::Write;
+use log::info;
 
 use kata_io as io;
 use kata_line_reader::LineReader;
@@ -43,7 +44,8 @@ impl From<fmt::Error> for CommandError {
 
 /// Read-eval-print loop for the DebugConsole command line interface.
 pub fn repl(output: &mut dyn io::Write, input: &mut dyn io::Read) -> ! {
-    let _ = write!(output, "DebugConsole::repl()\n");
+    //  let _ = write!(output, "DebugConsole::repl()\n");
+    info!("DebugConsole::repl()");
     let mut line_reader = LineReader::new();
     loop {
         const PROMPT: &str = "KATA_PROMPT> ";

apps/system/components/DebugConsole/kata-uart-client/Cargo.toml

@@ -5,5 +5,7 @@ authors = ["Matt Harvey <mattharvey@google.com>"]
 edition = "2018"
 
 [dependencies]
+# Disable default so we don't pull in CString which requires an allocator
+cstr_core = { version = "0.2.3", default-features = false }
 cty = "0.2.1"
 kata-io = { path = "../kata-io" }

apps/system/components/DebugConsole/kata-uart-client/src/lib.rs

@@ -1,5 +1,7 @@
 #![no_std]
 
+use core::fmt::Write;
+use cstr_core::CStr;
 use kata_io as io;
 
 // C interface to external UART driver.
@@ -10,6 +12,16 @@ extern "C" {
     fn uart_tx(n: cty::size_t);
 }
 
+// Console logging interface.
+#[no_mangle]
+pub extern "C" fn logger_log(msg: *const cstr_core::c_char) {
+    // TODO(sleffler): is the uart driver ok w/ multiple writers?
+    let output: &mut dyn io::Write = &mut self::Tx {};
+    unsafe {
+        let _ = writeln!(output, "{}", CStr::from_ptr(msg).to_str().unwrap());
+    }
+}
+
 pub struct Rx {}
 
 impl io::Read for Rx {

apps/system/components/ProcessManager/ProcessManager.camkes

@@ -1,5 +1,6 @@
 // Kata OS ProcessManager services.
 
+import <LoggerInterface.camkes>;
 import <ProcessControlInterface.camkes>;
 import <PackageManagementInterface.camkes>;
 import <SeL4DebugInterface.camkes>;
@@ -9,5 +10,6 @@ component ProcessManager {
   provides ProcessControlInterface proc_ctrl;
   provides PackageManagementInterface proc_mgmt;
 
+  uses LoggerInterface logger;
   uses SeL4DebugInterface sel4debug;
 }

apps/system/components/ProcessManager/kata-proc-manager/Cargo.toml

@@ -7,7 +7,9 @@ edition = "2018"
 [dependencies]
 arrayvec = { version = "0.7", default-features = false }
 kata-allocator = { path = "../../DebugConsole/kata-allocator" }
+kata-logger = { path = "../../DebugConsole/kata-logger" }
 kata-proc-common = { path = "../kata-proc-common" }
+log = "0.4"
 panic-halt = "0.2.0"
 
 [lib]

apps/system/components/ProcessManager/kata-proc-manager/src/run.rs

@@ -10,11 +10,21 @@ extern crate panic_halt;
 
 use arrayvec::ArrayVec;
 use core::marker::Sync;
+use log::debug;
 
 use kata_allocator;
+use kata_logger::KataLogger;
 use kata_proc_common as proc;
 use proc::*;
 
+static KATA_LOGGER: KataLogger = KataLogger;
+
+#[no_mangle]
+pub extern "C" fn pre_init() {
+    log::set_logger(&KATA_LOGGER).unwrap();
+    log::set_max_level(log::LevelFilter::Debug);
+}
+
 #[no_mangle]
 // NB: use post_init insted of pre_init so logger is setup
 pub extern "C" fn post_init() {
@@ -30,6 +40,7 @@ pub extern "C" fn post_init() {
 pub extern "C" fn run() {
     // Setup the userland address spaces, lifecycles, and system introspection
     // for third-party applications.
+    debug!("run");
 }
 
 // Bundle state tracks start/stop operations.

apps/system/components/SeL4Debug/src/wrappers.c

@@ -3,7 +3,9 @@
 
 void sel4debug_put_string(const char* msg) {
 #ifdef CONFIG_PRINTING
-  seL4_DebugPutString((char*) msg);
+  char buf[512];
+  snprintf(buf, sizeof(buf), "%s\n", msg);
+  seL4_DebugPutString(buf);
 #endif
 }
 

apps/system/interfaces/LoggerInterface.camkes

@@ -0,0 +1,3 @@
+procedure LoggerInterface {
+  void log(in string msg);
+};

apps/system/interfaces/ProcessManagerBindings.h

@@ -1,20 +1,22 @@
-#ifndef __PROCESS_MANAGER_BINDINGS_H__
+#ifndef __PROCESS_MANGER_BINDINGS_H__
-#define __PROCESS_MANAGER_BINDINGS_H__
+#define __PROCESS_MANGER_BINDINGS_H__
 
 /* Warning, this file is autogenerated by cbindgen. Don't modify this manually. */
 
 #define MAX_BUNDLES 10
 
+#define MAX_BUNDLE_ID_SIZE 32
+
 typedef struct Bundle {
   uint32_t something;
 } Bundle;
 
 typedef struct BundleId {
-  uint8_t id[32];
+  uint8_t id[MAX_BUNDLE_ID_SIZE];
 } BundleId;
 
 typedef struct BundleIdArray {
   struct BundleId ids[MAX_BUNDLES];
 } BundleIdArray;
 
-#endif /* __PROCESS_MANAGER_BINDINGS_H__ */
+#endif /* __PROCESS_MANGER_BINDINGS_H__ */

apps/system/system.camkes

@@ -39,6 +39,12 @@ assembly {
         //     from uart.interrupt, to drv.interrupt);
         connection seL4RPCCall uart_inf(from debug_console.uart, to drv.uart);
 
+        // Connect the LoggerInterface to each component that needs to log
+        // to the console. (TODO(sleffler): does N:1 work?)
+        // TODO(sleffler): what happens if client sends rpc's before the recvr is ready?
+        connection seL4RPCCall LoggerInterface(from process_manager.logger,
+                                               to debug_console.logger);
+
         // Connect the SeL4Debug interface of each component that needs access.
         connection seL4RPCCall SeL4DebugInterface(from debug_console.sel4debug,
                                                   from process_manager.sel4debug,