Add more info to log messages (e.g., timestamp, thread, and round)

src/Enclave.edl

@@ -117,5 +117,8 @@ enclave {
             unsigned int initval,
             int flags
         ) propagate_errno;
+
+        void occlum_ocall_print_log(uint32_t level, [in, string] const char* msg);
+        void occlum_ocall_flush_log(void);
     };
 };

src/libos/src/entry.rs

@@ -21,7 +21,16 @@ pub extern "C" fn occlum_ecall_new_process(
 ) -> i32 {
     INIT_ONCE.call_once(|| {
         // Init the log infrastructure first so that log messages will be printed afterwards
-        util::log::init();
+        use util::log::LevelFilter;
+        let log_level = match option_env!("LIBOS_LOG") {
+            Some("error") => LevelFilter::Error,
+            Some("warn") => LevelFilter::Warn,
+            Some("info") => LevelFilter::Info,
+            Some("debug") => LevelFilter::Debug,
+            Some("trace") => LevelFilter::Trace,
+            _ => LevelFilter::Error, // errors are printed be default
+        };
+        util::log::init(log_level);
         // Init MPX for SFI
         util::mpx_util::mpx_enable();
         // Register exception handlers (support cpuid & rdtsc for now)
@@ -33,7 +42,7 @@ pub extern "C" fn occlum_ecall_new_process(
     let (path, args) = match parse_arguments(path_buf, argv) {
         Ok(path_and_args) => path_and_args,
         Err(e) => {
-            error!("invalid arguments for LibOS: {}", e.backtrace());
+            eprintln!("invalid arguments for LibOS: {}", e.backtrace());
             return EXIT_STATUS_INTERNAL_ERROR;
         }
     };
@@ -42,7 +51,7 @@ pub extern "C" fn occlum_ecall_new_process(
         backtrace::__rust_begin_short_backtrace(|| match do_new_process(&path, &args) {
             Ok(pid_t) => pid_t as i32,
             Err(e) => {
-                error!("failed to boot up LibOS: {}", e.backtrace());
+                eprintln!("failed to boot up LibOS: {}", e.backtrace());
                 EXIT_STATUS_INTERNAL_ERROR
             }
         })
@@ -62,7 +71,7 @@ pub extern "C" fn occlum_ecall_exec_thread(libos_pid: i32, host_tid: i32) -> i32
             match do_exec_thread(libos_pid as pid_t, host_tid as pid_t) {
                 Ok(exit_status) => exit_status,
                 Err(e) => {
-                    error!("failed to execute a process: {}", e.backtrace());
+                    eprintln!("failed to execute a process: {}", e.backtrace());
                     EXIT_STATUS_INTERNAL_ERROR
                 }
             }

src/libos/src/process/mod.rs

@@ -7,7 +7,7 @@ pub use self::process::{Status, IDLE_PROCESS};
 pub use self::process_table::get;
 pub use self::sched::{do_sched_getaffinity, do_sched_setaffinity, do_sched_yield, CpuSet};
 pub use self::spawn::{do_spawn, do_spawn_without_exec, ElfFile, FileAction, ProgramHeaderExt};
-pub use self::task::{current_pid, get_current, run_task, Task};
+pub use self::task::{get_current, get_current_tid, run_task, Task};
 pub use self::thread::{do_clone, do_set_tid_address, CloneFlags, ThreadGroup};
 pub use self::wait::{WaitQueue, Waiter};
 

src/libos/src/process/task.rs

@@ -137,11 +137,11 @@ thread_local! {
         Cell::new(0 as *const SgxMutex<Process>)
     };
     // for log getting pid without locking process
-    static _PID: Cell<pid_t> = Cell::new(0);
+    static _TID: Cell<pid_t> = Cell::new(0);
 }
 
-pub fn current_pid() -> pid_t {
+pub fn get_current_tid() -> pid_t {
-    _PID.with(|p| p.get())
+    _TID.with(|tid_cell| tid_cell.get())
 }
 
 pub fn get_current() -> ProcessRef {
@@ -155,8 +155,8 @@ pub fn get_current() -> ProcessRef {
 }
 
 fn set_current(process: &ProcessRef) {
-    let pid = process.lock().unwrap().get_pid();
+    let tid = process.lock().unwrap().get_tid();
-    _PID.with(|p| p.set(pid));
+    _TID.with(|tid_cell| tid_cell.set(tid));
 
     let process_ref_clone = process.clone();
     let process_ptr = Arc::into_raw(process_ref_clone);
@@ -167,7 +167,7 @@ fn set_current(process: &ProcessRef) {
 }
 
 fn reset_current() {
-    _PID.with(|p| p.set(0));
+    _TID.with(|tid_cell| tid_cell.set(0));
     let mut process_ptr = _CURRENT_PROCESS_PTR.with(|cp| cp.replace(0 as *const SgxMutex<Process>));
 
     // Prevent memory leakage

src/libos/src/syscall/mod.rs

@@ -27,6 +27,7 @@ use std::ffi::{CStr, CString};
 use std::io::{Read, Seek, SeekFrom, Write};
 use std::ptr;
 use time::{clockid_t, timespec_t, timeval_t, GLOBAL_PROFILER};
+use util::log::{self, LevelFilter};
 use util::mem_util::from_user::*;
 use vm::{MMapFlags, VMPerms};
 use {fs, process, std, vm};
@@ -416,6 +417,18 @@ macro_rules! impl_syscall_nums {
             )*
         }
 
+        impl SyscallNum {
+            pub fn as_str(&self) -> &'static str {
+                use SyscallNum::*;
+                match *self {
+                    #![deny(unreachable_patterns)]
+                    $(
+                        $name => stringify!($name),
+                    )*
+                }
+            }
+        }
+
         impl TryFrom<u32> for SyscallNum {
             type Error = error::Error;
 
@@ -429,7 +442,6 @@ macro_rules! impl_syscall_nums {
             }
         }
 
-
         #[derive(Copy, Clone, Debug)]
         pub struct SyscallNumError {
             invalid_num: u32,
@@ -565,7 +577,10 @@ pub extern "C" fn occlum_syscall(
     arg4: isize,
     arg5: isize,
 ) -> isize {
-    let pid = process::do_gettid();
+    // Start a new round of log messages for this system call. But we do not
+    // set the description of this round, yet. We will do so after checking the
+    // given system call number is a valid.
+    log::next_round(None);
 
     #[cfg(feature = "syscall_timing")]
     GLOBAL_PROFILER
@@ -574,12 +589,12 @@ pub extern "C" fn occlum_syscall(
         .syscall_enter(syscall_num)
         .expect("unexpected error from profiler to enter syscall");
 
-    let ret = {
+    let ret = Syscall::new(num, arg0, arg1, arg2, arg3, arg4, arg5).and_then(|syscall| {
-        let syscall = Syscall::new(num, arg0, arg1, arg2, arg3, arg4, arg5).unwrap();
+        log::set_round_desc(Some(syscall.num.as_str()));
-        info!("{:?}", &syscall);
+        trace!("{:?}", &syscall);
 
         dispatch_syscall(syscall)
-    };
+    });
 
     #[cfg(feature = "syscall_timing")]
     GLOBAL_PROFILER
@@ -588,18 +603,38 @@ pub extern "C" fn occlum_syscall(
         .syscall_exit(syscall_num, ret.is_err())
         .expect("unexpected error from profiler to exit syscall");
 
-    info!("tid: {} => {:?} ", pid, ret);
+    let retval = match ret {
-
-    match ret {
         Ok(retval) => retval as isize,
         Err(e) => {
-            warn!("{}", e.backtrace());
+            let should_log_err = |errno| {
+                // If the log level requires every detail, don't ignore any error
+                if log::max_level() == LevelFilter::Trace {
+                    return true;
+                }
+
+                // All other log levels require errors to be outputed. But
+                // some errnos are usually benign and may occur in a very high
+                // frequency. So we want to ignore them to keep noises at a
+                // minimum level in the log.
+                //
+                // TODO: use a smarter, frequency-based strategy to decide whether
+                // to suppress error messages.
+                match errno {
+                    EAGAIN | ETIMEDOUT => false,
+                    _ => true,
+                }
+            };
+            if should_log_err(e.errno()) {
+                error!("Error = {}", e.backtrace());
+            }
 
             let retval = -(e.errno() as isize);
             debug_assert!(retval != 0);
             retval
         }
-    }
+    };
+    trace!("Retval = {:?}", retval);
+    retval
 }
 
 /*

src/libos/src/util/log.rs

@@ -1,18 +1,68 @@
+use super::process;
+/// Log infrastructure.
+///
+/// There are five APIs for producing log messages:
+/// 1. `error!`
+/// 2. `warn!`
+/// 3. `info!`
+/// 4. `debug!`
+/// 5. `trace!`
+/// which corresponds to five different log levels.
+///
+/// Safety. Sensitive, internal info may be leaked though log messages. To prevent
+/// this from happening, the current solution is to turn off the log entirely
+/// when initializing the log infrastructure, if the enclave is in release mode.
+///
+/// Note. Do not use log as a way to display critical info to users as log may be
+/// turned off (even the error messages). For such messages, use `println!` or
+/// `eprintln!` directly.
 use log::*;
+use std::cell::Cell;
 
-pub fn init() {
+pub use log::{max_level, LevelFilter};
+
+/// Initialize the log infrastructure with the given log level.
+pub fn init(level: LevelFilter) {
     static LOGGER: SimpleLogger = SimpleLogger;
     log::set_logger(&LOGGER).expect("logger cannot be set twice");
-    log::set_max_level(match option_env!("LIBOS_LOG") {
+    log::set_max_level(level);
-        Some("error") => LevelFilter::Error,
+}
-        Some("warn") => LevelFilter::Warn,
+
-        Some("info") => LevelFilter::Info,
+/// Notify the logger that a new round starts.
-        Some("debug") => LevelFilter::Debug,
+///
-        Some("trace") => LevelFilter::Trace,
+/// Log messages generated in a thread are organized in _rounds_. Each round
-        _ => LevelFilter::Error, // errors are printed be default
+/// is a group of related log messages. For examples, all log messages generated
+/// during the execution of a single system call may belong to the same round.
+pub fn next_round(desc: Option<&'static str>) {
+    ROUND_COUNT.with(|cell| {
+        cell.set(cell.get() + 1);
+    });
+    ROUND_DESC.with(|cell| {
+        cell.set(desc);
     });
 }
 
+/// Set the description of the current round
+pub fn set_round_desc(desc: Option<&'static str>) {
+    ROUND_DESC.with(|cell| {
+        cell.set(desc);
+    });
+}
+
+fn round_count() -> u64 {
+    ROUND_COUNT.with(|cell| cell.get())
+}
+
+fn round_desc() -> Option<&'static str> {
+    ROUND_DESC.with(|cell| cell.get())
+}
+
+thread_local! {
+    static ROUND_COUNT : Cell<u64> = Default::default();
+    static ROUND_DESC : Cell<Option<&'static str>> = Default::default();
+}
+
+/// A simple logger that adds thread and round info to log messages.
 struct SimpleLogger;
 
 impl Log for SimpleLogger {
@@ -21,51 +71,36 @@ impl Log for SimpleLogger {
     }
     fn log(&self, record: &Record) {
         if self.enabled(record.metadata()) {
-            let color = Color::from(record.level());
+            // Parts of message
-            // TODO: add process info
+            let level = record.level();
-            println!(
+            let tid = process::get_current_tid();
-                //"\u{1B}[{}m[{:>5}][{}] {}\u{1B}[0m",
+            let rounds = round_count();
-                "\u{1B}[{}m[{:>5}] {}\u{1B}[0m",
+            let desc = round_desc();
-                color as u8,
+            // Message (null-terminated)
-                record.level(),
+            let message = if let Some(desc) = desc {
-                //crate::process::current_pid(),
+                format!(
+                    "[{:>5}][T{}][#{}][{:·>8}] {}\0",
+                    level,
+                    tid,
+                    rounds,
+                    desc,
                     record.args()
-            );
+                )
+            } else {
+                format!("[{:>5}][T{}][#{}] {}\0", level, tid, rounds, record.args())
+            };
+            // Print the message
+            unsafe {
+                occlum_ocall_print_log(level as u32, message.as_ptr());
             }
         }
-    fn flush(&self) {}
-}
-
-impl From<Level> for Color {
-    fn from(level: Level) -> Self {
-        match level {
-            Level::Error => Color::Red,
-            Level::Warn => Color::Yellow,
-            Level::Info => Color::Blue,
-            Level::Debug => Color::Green,
-            Level::Trace => Color::BrightBlack,
     }
+    fn flush(&self) {
+        //unsafe { occlum_ocall_flush_log();  }
     }
 }
 
-#[allow(dead_code)]
+extern "C" {
-#[derive(Debug, Clone, Copy, Eq, PartialEq)]
+    fn occlum_ocall_print_log(level: u32, msg: *const u8);
-#[repr(u8)]
+    fn occlum_ocall_flush_log();
-pub enum Color {
-    Black = 30,
-    Red = 31,
-    Green = 32,
-    Yellow = 33,
-    Blue = 34,
-    Magenta = 35,
-    Cyan = 36,
-    White = 37,
-    BrightBlack = 90,
-    BrightRed = 91,
-    BrightGreen = 92,
-    BrightYellow = 93,
-    BrightBlue = 94,
-    BrightMagenta = 95,
-    BrightCyan = 96,
-    BrightWhite = 97,
 }

src/pal/src/ocalls/log.c

@@ -0,0 +1,54 @@
+#include <stdio.h>
+#include "ocalls.h"
+
+typedef enum {
+    LEVEL_OFF   = 0,
+    LEVEL_ERROR = 1,
+    LEVEL_WARN  = 2,
+    LEVEL_INFO  = 3,
+    LEVEL_DEBUG = 4,
+    LEVEL_TRACE = 5
+} level_t;
+
+#define COLOR_NORMAL    "\x1B[0m"
+#define COLOR_RED       "\x1B[31m"
+#define COLOR_YELLOW    "\x1B[33m"
+#define COLOR_GREEN     "\x1B[32m"
+
+static level_t new_level(unsigned int level) {
+    if (level >= 5) level = 5;
+    return (level_t) level;
+}
+
+void occlum_ocall_print_log(unsigned int _level, const char* msg) {
+    level_t level = new_level(_level);
+    if (level == LEVEL_OFF) {
+        return;
+    }
+
+    const char* color;
+    switch(level) {
+        case LEVEL_ERROR:
+            color = COLOR_RED;
+            break;
+        case LEVEL_WARN:
+            color = COLOR_YELLOW;
+            break;
+        case LEVEL_INFO:
+            color = COLOR_GREEN;
+            break;
+        default:
+            color = COLOR_NORMAL;
+    }
+
+    struct timeval now_tv;
+    gettimeofday(&now_tv, NULL);
+    char day_and_sec[20];
+    strftime(day_and_sec, 20, "%Y-%m-%dT%H:%M:%S", gmtime(&now_tv.tv_sec));
+    int ms = now_tv.tv_usec / 1000;
+    fprintf(stderr, "%s[%s.%03dZ]%s%s\n", color, day_and_sec, ms, msg, COLOR_NORMAL);
+}
+
+void occlum_ocall_flush_log() {
+    fflush(stderr);
+}