diff --git a/src/Enclave.edl b/src/Enclave.edl index c82c96d9..b3bc278d 100644 --- a/src/Enclave.edl +++ b/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); }; }; diff --git a/src/libos/src/entry.rs b/src/libos/src/entry.rs index 753aba36..2e1038c1 100644 --- a/src/libos/src/entry.rs +++ b/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 } } diff --git a/src/libos/src/process/mod.rs b/src/libos/src/process/mod.rs index 1764e788..0783148b 100644 --- a/src/libos/src/process/mod.rs +++ b/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}; diff --git a/src/libos/src/process/task.rs b/src/libos/src/process/task.rs index 4277aa7a..4d7b408d 100644 --- a/src/libos/src/process/task.rs +++ b/src/libos/src/process/task.rs @@ -137,11 +137,11 @@ thread_local! { Cell::new(0 as *const SgxMutex) }; // for log getting pid without locking process - static _PID: Cell = Cell::new(0); + static _TID: Cell = Cell::new(0); } -pub fn current_pid() -> pid_t { - _PID.with(|p| p.get()) +pub fn get_current_tid() -> pid_t { + _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(); - _PID.with(|p| p.set(pid)); + let tid = process.lock().unwrap().get_tid(); + _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)); // Prevent memory leakage diff --git a/src/libos/src/syscall/mod.rs b/src/libos/src/syscall/mod.rs index 9828823c..603e907d 100644 --- a/src/libos/src/syscall/mod.rs +++ b/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 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 syscall = Syscall::new(num, arg0, arg1, arg2, arg3, arg4, arg5).unwrap(); - info!("{:?}", &syscall); + let ret = Syscall::new(num, arg0, arg1, arg2, arg3, arg4, arg5).and_then(|syscall| { + log::set_round_desc(Some(syscall.num.as_str())); + 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); - - match ret { + let retval = 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 } /* diff --git a/src/libos/src/util/log.rs b/src/libos/src/util/log.rs index a7fd4a63..8f6da021 100644 --- a/src/libos/src/util/log.rs +++ b/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") { - 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 + log::set_max_level(level); +} + +/// Notify the logger that a new round starts. +/// +/// Log messages generated in a thread are organized in _rounds_. Each round +/// 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 = Default::default(); + static ROUND_DESC : Cell> = 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()); - // TODO: add process info - println!( - //"\u{1B}[{}m[{:>5}][{}] {}\u{1B}[0m", - "\u{1B}[{}m[{:>5}] {}\u{1B}[0m", - color as u8, - record.level(), - //crate::process::current_pid(), - record.args() - ); + // Parts of message + let level = record.level(); + let tid = process::get_current_tid(); + let rounds = round_count(); + let desc = round_desc(); + // Message (null-terminated) + let message = if let Some(desc) = desc { + 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 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)] -#[derive(Debug, Clone, Copy, Eq, PartialEq)] -#[repr(u8)] -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, +extern "C" { + fn occlum_ocall_print_log(level: u32, msg: *const u8); + fn occlum_ocall_flush_log(); } diff --git a/src/pal/src/ocalls/log.c b/src/pal/src/ocalls/log.c new file mode 100644 index 00000000..18694f4e --- /dev/null +++ b/src/pal/src/ocalls/log.c @@ -0,0 +1,54 @@ +#include +#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); +}