Merge pull request #306 from roblabla/feature-better-logging

Better logging - more colors, less duplication

clock/Cargo.toml

@@ -7,3 +7,4 @@ edition = "2018"
 
 [dependencies]
 sunrise-libuser = { path = "../libuser" }
+log = "0.4.6"

clock/src/main.rs

@@ -19,7 +19,7 @@
 #[macro_use]
 extern crate sunrise_libuser;
 #[macro_use]
-extern crate alloc;
+extern crate log;
 
 use sunrise_libuser::terminal::{Terminal, WindowSize};
 use sunrise_libuser::io::{self, Io};
@@ -154,7 +154,7 @@ fn main() {
                 year = (year & 0x0F) + ((year / 16) * 10);
             }
 
-            let _ = syscalls::output_debug_string(&format!("{:02}:{:02}:{:02} {} {:02} {} {}", hours, minutes, seconds, get_day_of_week(dayofweek), day, get_month(month), year));
+            info!("{:02}:{:02}:{:02} {} {:02} {} {}", hours, minutes, seconds, get_day_of_week(dayofweek), day, get_month(month), year);
             let _ = write!(&mut logger, "\n{:02}:{:02}:{:02} {} {:02} {} {}", hours, minutes, seconds, get_day_of_week(dayofweek), day, get_month(month), year);
         }
     }

kernel/src/interrupts/syscalls.rs

@@ -212,8 +212,16 @@ fn wait_synchronization(handles_ptr: UserSpacePtr<[u32]>, timeout_ns: usize) ->
 }
 
 /// Print the passed string to the serial port.
-fn output_debug_string(s: UserSpacePtr<[u8]>) -> Result<(), UserspaceError> {
-    info!("{}", String::from_utf8_lossy(&*s));
+fn output_debug_string(msg: UserSpacePtr<[u8]>, level: usize, target: UserSpacePtr<[u8]>) -> Result<(), UserspaceError> {
+    let level = match level {
+        00..20    => log::Level::Error,
+        20..40    => log::Level::Warn,
+        40..60    => log::Level::Info,
+        60..80    => log::Level::Debug,
+        _         => log::Level::Trace,
+    };
+
+    log!(target: &*String::from_utf8_lossy(&*target), level, "{}", String::from_utf8_lossy(&*msg));
     Ok(())
 }
 
@@ -681,7 +689,7 @@ pub extern fn syscall_handler_inner(registers: &mut Registers) {
         (true, nr::WaitSynchronization) => registers.apply1(wait_synchronization(UserSpacePtr::from_raw_parts(x0 as _, x1), x2)),
         (true, nr::ConnectToNamedPort) => registers.apply1(connect_to_named_port(UserSpacePtr(x0 as _))),
         (true, nr::SendSyncRequestWithUserBuffer) => registers.apply0(send_sync_request_with_user_buffer(UserSpacePtrMut::from_raw_parts_mut(x0 as _, x1), x2 as _)),
-        (true, nr::OutputDebugString) => registers.apply0(output_debug_string(UserSpacePtr::from_raw_parts(x0 as _, x1))),
+        (true, nr::OutputDebugString) => registers.apply0(output_debug_string(UserSpacePtr::from_raw_parts(x0 as _, x1), x2, UserSpacePtr::from_raw_parts(x3 as _, x4))),
         (true, nr::CreateSession) => registers.apply2(create_session(x0 != 0, x1 as _)),
         (true, nr::AcceptSession) => registers.apply1(accept_session(x0 as _)),
         (true, nr::ReplyAndReceiveWithUserBuffer) => registers.apply1(reply_and_receive_with_user_buffer(UserSpacePtrMut::from_raw_parts_mut(x0 as _, x1), UserSpacePtr::from_raw_parts(x2 as _, x3), x4 as _, x5)),

kernel/src/log_impl/mod.rs

@@ -20,11 +20,19 @@ impl Log for Logger {
     }
 
     fn log(&self, record: &Record<'_>) {
+        use crate::devices::rs232::{SerialAttributes, SerialColor};
+        let color = SerialAttributes::fg(match record.level() {
+            log::Level::Error => SerialColor::Red,
+            log::Level::Warn  => SerialColor::Yellow,
+            log::Level::Info  => SerialColor::Green,
+            log::Level::Debug => SerialColor::Cyan,
+            log::Level::Trace => SerialColor::White,
+        });
         if self.filter.read().matches(record) {
             if let Some(thread) = scheduler::try_get_current_thread() {
-                writeln!(SerialLogger, "[{}] - {} - {} - {}", record.level(), record.target(), thread.process.name, record.args());
+                writeln!(SerialLogger, "[{}{}{}] - {} - {} - {}", color, record.level(), SerialAttributes::default(), record.target(), thread.process.name, record.args());
             } else {
-                writeln!(SerialLogger, "[{}] - {} - {}", record.level(), record.target(), record.args());
+                writeln!(SerialLogger, "[{}{}{}] - {} - {}", color, record.level(), SerialAttributes::default(), record.target(), record.args());
             }
         }
     }

kernel/src/main.rs

@@ -6,7 +6,7 @@
 //! Currently doesn't do much, besides booting and printing Hello World on the
 //! screen. But hey, that's a start.
 
-#![feature(lang_items, start, asm, global_asm, compiler_builtins_lib, naked_functions, core_intrinsics, const_fn, abi_x86_interrupt, allocator_api, box_syntax, no_more_cas, const_vec_new, step_trait, thread_local, nll, underscore_const_names, doc_cfg)]
+#![feature(lang_items, start, asm, global_asm, compiler_builtins_lib, naked_functions, core_intrinsics, const_fn, abi_x86_interrupt, allocator_api, box_syntax, no_more_cas, const_vec_new, step_trait, thread_local, nll, underscore_const_names, doc_cfg, exclusive_range_pattern)]
 #![no_std]
 #![cfg_attr(target_os = "none", no_main)]
 #![recursion_limit = "1024"]

libuser/src/ipc/macros.rs

@@ -206,7 +206,7 @@ macro_rules! object {
         match $cmdid {
             $($fcmdid => $fcmd,)*
             cmd => {
-                let _ = $crate::syscalls::output_debug_string(&format!("Unknown cmdid: {}", cmd));
+                let _ = $crate::__log::warn!("Unknown cmdid: {}", cmd);
                 Err($crate::error::KernelError::PortRemoteDead.into())
             }
         }

libuser/src/ipc/server.rs

@@ -102,7 +102,7 @@ impl WaitableManager {
                 Ok(false) => (),
                 Ok(true) => { waitables.remove(idx); },
                 Err(err) => {
-                    let _ = syscalls::output_debug_string(&format!("Error: {}", err));
+                    error!("Error: {}", err);
                     waitables.remove(idx);
                 }
             }

libuser/src/lib.rs

@@ -31,11 +31,10 @@ extern crate sunrise_libutils;
 #[macro_use]
 extern crate failure;
 
-
-#[macro_use]
-extern crate log;
+// Marked public for use in the object macro.
 #[macro_use]
-extern crate lazy_static;
+#[doc(hidden)]
+pub extern crate log as __log;
 
 use swipc_gen::gen_ipc;
 
@@ -87,7 +86,7 @@ static ALLOCATOR: allocator::Allocator = allocator::Allocator::new();
 #[cfg(any(all(target_os = "none", not(test)), rustdoc))]
 #[panic_handler] #[no_mangle]
 pub extern fn panic_fmt(p: &core::panic::PanicInfo<'_>) -> ! {
-    let _ = syscalls::output_debug_string(&format!("{}", p));
+    let _ = syscalls::output_debug_string(&format!("{}", p), 10, "sunrise_libuser::panic_fmt");
     syscalls::exit_process();
 }
 

libuser/src/log_impl.rs

@@ -3,19 +3,8 @@
 //! Redirects all logs to the kernel logger (output_debug_string syscall). No
 //! filtering is done, so everything will be sent.
 
-use spin::Mutex;
-use arrayvec::ArrayString;
 use log::{self, Log, LevelFilter, Metadata, Record};
 use crate::syscalls::output_debug_string;
-use core::fmt::{self, Write};
-
-lazy_static! {
-    /// Buffer where pending writes are stored. The buffer is only flushed when
-    /// a \n is written, or when it's full.
-    ///
-    /// In practice, every log will cause a single line (at least) to be written.
-    static ref SVC_LOG_BUFFER: Mutex<ArrayString<[u8; 256]>> = Mutex::new(ArrayString::new());
-}
 
 /// Log implementation structure.
 ///
@@ -28,32 +17,19 @@ impl Log for Logger {
     }
 
     fn log(&self, record: &Record<'_>) {
-        let _ = writeln!(Logger, "[{}] - {} - {}", record.level(), record.target(), record.args());
+        let level = match record.level() {
+            log::Level::Error => 10,
+            log::Level::Warn => 30,
+            log::Level::Info => 50,
+            log::Level::Debug => 70,
+            log::Level::Trace => 90,
+        };
+        let _ = output_debug_string(&*format!("{}", record.args()), level, record.target());
     }
 
     fn flush(&self) {}
 }
 
-impl fmt::Write for Logger {
-    fn write_str(&mut self, data: &str) -> fmt::Result {
-        let mut svc_log_buffer = SVC_LOG_BUFFER.lock();
-        if let Ok(()) = svc_log_buffer.try_push_str(data) {
-            if let Some(pos) = svc_log_buffer.rfind('\n') {
-                let _ = output_debug_string(&svc_log_buffer.as_str()[..pos]);
-                *svc_log_buffer = ArrayString::from(&svc_log_buffer[pos + 1..]).unwrap();
-            }
-        } else {
-            // Worse-case. Just print it all out and start fresh.
-            if !svc_log_buffer.is_empty() {
-                let _ = output_debug_string(svc_log_buffer.as_str());
-            }
-            let _ = output_debug_string(data);
-            svc_log_buffer.clear();
-        }
-        Ok(())
-    }
-}
-
 /// Initializes the global logger with the svc logger.
 ///
 /// This should be called early in the execution of a Rust program. Any log

libuser/src/syscalls.rs

@@ -137,7 +137,7 @@ pub fn exit_process() -> ! {
     unsafe {
         match syscall(nr::ExitProcess, 0, 0, 0, 0, 0, 0) {
             Ok(_) => (),
-            Err(err) => { let _ = output_debug_string(&format!("Failed to exit: {}", err)); },
+            Err(err) => { let _ = output_debug_string(&format!("Failed to exit: {}", err), 10, "sunrise_libuser::syscalls::exit_process"); },
         }
         #[allow(clippy::empty_loop)]
         loop {} // unreachable, but we can't panic, as panic! calls exit_process
@@ -303,9 +303,9 @@ pub fn send_sync_request_with_user_buffer(buf: &mut [u8], handle: &ClientSession
 /// Print the given string to the kernel's debug output.
 ///
 /// Currently, this prints the string to the serial port.
-pub fn output_debug_string(s: &str) -> Result<(), KernelError> {
+pub fn output_debug_string(s: &str, level: usize, target: &str) -> Result<(), KernelError> {
     unsafe {
-        syscall(nr::OutputDebugString, s.as_ptr() as _, s.len(), 0, 0, 0, 0)?;
+        syscall(nr::OutputDebugString, s.as_ptr() as _, s.len(), level, target.as_ptr() as _, target.len(), 0)?;
         Ok(())
     }
 }

sm/src/main.rs

@@ -37,7 +37,6 @@
 
 #[macro_use]
 extern crate sunrise_libuser as libuser;
-#[macro_use]
 extern crate alloc;
 
 

vi/src/main.rs

@@ -22,7 +22,6 @@
 #[macro_use]
 extern crate sunrise_libuser as libuser;
 
-#[macro_use]
 extern crate alloc;