diff --git a/apps/system/components/DebugConsole/Cargo.toml b/apps/system/components/DebugConsole/Cargo.toml index 2d96b75..b10369e 100644 --- a/apps/system/components/DebugConsole/Cargo.toml +++ b/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", ] diff --git a/apps/system/components/DebugConsole/DebugConsole.camkes b/apps/system/components/DebugConsole/DebugConsole.camkes index 594efb2..e937e8e 100644 --- a/apps/system/components/DebugConsole/DebugConsole.camkes +++ b/apps/system/components/DebugConsole/DebugConsole.camkes @@ -1,3 +1,4 @@ +import ; import ; component DebugConsole { @@ -6,5 +7,6 @@ component DebugConsole { dataport Buf tx_dataport; dataport Buf rx_dataport; + provides LoggerInterface logger; uses SeL4DebugInterface sel4debug; } diff --git a/apps/system/components/DebugConsole/kata-allocator/Cargo.toml b/apps/system/components/DebugConsole/kata-allocator/Cargo.toml index 43c3790..8860113 100644 --- a/apps/system/components/DebugConsole/kata-allocator/Cargo.toml +++ b/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" diff --git a/apps/system/components/DebugConsole/kata-allocator/src/lib.rs b/apps/system/components/DebugConsole/kata-allocator/src/lib.rs index 0bf36d7..9fefeef 100644 --- a/apps/system/components/DebugConsole/kata-allocator/src/lib.rs +++ b/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); } diff --git a/apps/system/components/DebugConsole/kata-debug-console/Cargo.toml b/apps/system/components/DebugConsole/kata-debug-console/Cargo.toml index 2e8f2c2..167fc4b 100644 --- a/apps/system/components/DebugConsole/kata-debug-console/Cargo.toml +++ b/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" diff --git a/apps/system/components/DebugConsole/kata-debug-console/src/run.rs b/apps/system/components/DebugConsole/kata-debug-console/src/run.rs index b3acb2e..fb7740b 100644 --- a/apps/system/components/DebugConsole/kata-debug-console/src/run.rs +++ b/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); diff --git a/apps/system/components/DebugConsole/kata-logger/Cargo.toml b/apps/system/components/DebugConsole/kata-logger/Cargo.toml new file mode 100644 index 0000000..fb9e70f --- /dev/null +++ b/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" diff --git a/apps/system/components/DebugConsole/kata-logger/src/lib.rs b/apps/system/components/DebugConsole/kata-logger/src/lib.rs new file mode 100644 index 0000000..46a5f49 --- /dev/null +++ b/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: '<''>' :: + 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, + "<{}> {}::\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, 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 - " 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, ""); + } +} diff --git a/apps/system/components/DebugConsole/kata-shell/Cargo.toml b/apps/system/components/DebugConsole/kata-shell/Cargo.toml index ff7cbb4..d84ef95 100644 --- a/apps/system/components/DebugConsole/kata-shell/Cargo.toml +++ b/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" diff --git a/apps/system/components/DebugConsole/kata-shell/src/lib.rs b/apps/system/components/DebugConsole/kata-shell/src/lib.rs index 274dbd7..2ef39bb 100644 --- a/apps/system/components/DebugConsole/kata-shell/src/lib.rs +++ b/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 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> "; diff --git a/apps/system/components/DebugConsole/kata-uart-client/Cargo.toml b/apps/system/components/DebugConsole/kata-uart-client/Cargo.toml index 63d7ca1..10e4e1d 100644 --- a/apps/system/components/DebugConsole/kata-uart-client/Cargo.toml +++ b/apps/system/components/DebugConsole/kata-uart-client/Cargo.toml @@ -5,5 +5,7 @@ authors = ["Matt Harvey "] 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" } diff --git a/apps/system/components/DebugConsole/kata-uart-client/src/lib.rs b/apps/system/components/DebugConsole/kata-uart-client/src/lib.rs index 0e4fd03..a19db0f 100644 --- a/apps/system/components/DebugConsole/kata-uart-client/src/lib.rs +++ b/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 { diff --git a/apps/system/components/ProcessManager/ProcessManager.camkes b/apps/system/components/ProcessManager/ProcessManager.camkes index 3783305..cc27516 100644 --- a/apps/system/components/ProcessManager/ProcessManager.camkes +++ b/apps/system/components/ProcessManager/ProcessManager.camkes @@ -1,5 +1,6 @@ // Kata OS ProcessManager services. +import ; import ; import ; import ; @@ -9,5 +10,6 @@ component ProcessManager { provides ProcessControlInterface proc_ctrl; provides PackageManagementInterface proc_mgmt; + uses LoggerInterface logger; uses SeL4DebugInterface sel4debug; } diff --git a/apps/system/components/ProcessManager/kata-proc-manager/Cargo.toml b/apps/system/components/ProcessManager/kata-proc-manager/Cargo.toml index 746bfe1..dbb7737 100644 --- a/apps/system/components/ProcessManager/kata-proc-manager/Cargo.toml +++ b/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] diff --git a/apps/system/components/ProcessManager/kata-proc-manager/src/run.rs b/apps/system/components/ProcessManager/kata-proc-manager/src/run.rs index db2f7cb..a7241eb 100644 --- a/apps/system/components/ProcessManager/kata-proc-manager/src/run.rs +++ b/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. diff --git a/apps/system/components/SeL4Debug/src/wrappers.c b/apps/system/components/SeL4Debug/src/wrappers.c index 1a9d02c..363d2d6 100644 --- a/apps/system/components/SeL4Debug/src/wrappers.c +++ b/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 } diff --git a/apps/system/interfaces/LoggerInterface.camkes b/apps/system/interfaces/LoggerInterface.camkes new file mode 100644 index 0000000..3de7032 --- /dev/null +++ b/apps/system/interfaces/LoggerInterface.camkes @@ -0,0 +1,3 @@ +procedure LoggerInterface { + void log(in string msg); +}; diff --git a/apps/system/interfaces/ProcessManagerBindings.h b/apps/system/interfaces/ProcessManagerBindings.h index 33ba585..955ec46 100644 --- a/apps/system/interfaces/ProcessManagerBindings.h +++ b/apps/system/interfaces/ProcessManagerBindings.h @@ -1,20 +1,22 @@ -#ifndef __PROCESS_MANAGER_BINDINGS_H__ -#define __PROCESS_MANAGER_BINDINGS_H__ +#ifndef __PROCESS_MANGER_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__ */ diff --git a/apps/system/system.camkes b/apps/system/system.camkes index aeccf0e..8b74ecf 100644 --- a/apps/system/system.camkes +++ b/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,