From 5933499f9b22a999c5536b7f7497d7c6c007782f Mon Sep 17 00:00:00 2001 From: "Tate, Hongliang Tian" Date: Tue, 24 Mar 2020 15:00:32 +0000 Subject: [PATCH] Refactor LibOS to conform with logging strategy This commit introduces a unified logging strategy, summarized as below: 1. Use `error!` to mark errors or unexpected conditions, e.g., a `Result::Err` returned from a system call. 2. Use `warn!` to warn about potentially problematic issues, e.g., executing a workaround or fake implementation. 3. Use `info!` to show important events (from users' perspective) in normal execution, e.g., creating/exiting a process/thread. 4. Use `debug!` to track major events in normal execution, e.g., the high-level arguments of a system call. 5. Use `trace!` to record the most detailed info, e.g., when a system call enters and exits the LibOS. --- src/libos/src/fs/file_ops/access.rs | 4 ++-- src/libos/src/fs/file_ops/chdir.rs | 2 +- src/libos/src/fs/file_ops/close.rs | 2 +- src/libos/src/fs/file_ops/dirent.rs | 2 +- src/libos/src/fs/file_ops/fcntl.rs | 2 +- src/libos/src/fs/file_ops/fsync.rs | 4 ++-- src/libos/src/fs/file_ops/ioctl/mod.rs | 2 +- src/libos/src/fs/file_ops/link.rs | 2 +- src/libos/src/fs/file_ops/mkdir.rs | 2 +- src/libos/src/fs/file_ops/open.rs | 2 +- src/libos/src/fs/file_ops/read.rs | 6 ++--- src/libos/src/fs/file_ops/rename.rs | 2 +- src/libos/src/fs/file_ops/rmdir.rs | 2 +- src/libos/src/fs/file_ops/sendfile.rs | 2 +- src/libos/src/fs/file_ops/stat.rs | 6 ++--- src/libos/src/fs/file_ops/symlink.rs | 2 +- src/libos/src/fs/file_ops/truncate.rs | 4 ++-- src/libos/src/fs/file_ops/unlink.rs | 2 +- src/libos/src/fs/file_ops/write.rs | 6 ++--- src/libos/src/fs/fs_ops/sync.rs | 2 +- src/libos/src/fs/pipe.rs | 8 ++++--- src/libos/src/fs/syscalls.rs | 1 - src/libos/src/net/io_multiplexing.rs | 10 ++++---- src/libos/src/net/syscalls.rs | 11 ++++----- src/libos/src/prelude.rs | 2 +- src/libos/src/process/arch_prctl.rs | 2 +- src/libos/src/process/spawn/init_vm.rs | 2 +- src/libos/src/process/spawn/mod.rs | 1 + src/libos/src/process/task.rs | 2 ++ src/libos/src/process/thread.rs | 5 ++-- src/libos/src/syscall/mod.rs | 32 +++++++++++++------------- src/libos/src/time/profiler.rs | 2 -- src/libos/src/util/log.rs | 23 +++++++++++++++++- src/libos/src/vm/mod.rs | 8 +++---- 34 files changed, 94 insertions(+), 73 deletions(-) diff --git a/src/libos/src/fs/file_ops/access.rs b/src/libos/src/fs/file_ops/access.rs index 90de53af..19f38c0f 100644 --- a/src/libos/src/fs/file_ops/access.rs +++ b/src/libos/src/fs/file_ops/access.rs @@ -33,7 +33,7 @@ pub fn do_faccessat( mode: AccessibilityCheckMode, flags: AccessibilityCheckFlags, ) -> Result<()> { - info!( + debug!( "faccessat: dirfd: {:?}, path: {:?}, mode: {:?}, flags: {:?}", dirfd, path, mode, flags ); @@ -45,7 +45,7 @@ pub fn do_faccessat( } pub fn do_access(path: &str, mode: AccessibilityCheckMode) -> Result<()> { - info!("access: path: {:?}, mode: {:?}", path, mode); + debug!("access: path: {:?}, mode: {:?}", path, mode); let current_ref = process::get_current(); let mut current = current_ref.lock().unwrap(); let inode = current.lookup_inode(path)?; diff --git a/src/libos/src/fs/file_ops/chdir.rs b/src/libos/src/fs/file_ops/chdir.rs index 1ec25d1d..f0ef7d89 100644 --- a/src/libos/src/fs/file_ops/chdir.rs +++ b/src/libos/src/fs/file_ops/chdir.rs @@ -3,7 +3,7 @@ use super::*; pub fn do_chdir(path: &str) -> Result<()> { let current_ref = process::get_current(); let mut current_process = current_ref.lock().unwrap(); - info!("chdir: path: {:?}", path); + debug!("chdir: path: {:?}", path); let inode = current_process.lookup_inode(path)?; let info = inode.metadata()?; diff --git a/src/libos/src/fs/file_ops/close.rs b/src/libos/src/fs/file_ops/close.rs index efcf1ea0..682a548e 100644 --- a/src/libos/src/fs/file_ops/close.rs +++ b/src/libos/src/fs/file_ops/close.rs @@ -1,7 +1,7 @@ use super::*; pub fn do_close(fd: FileDesc) -> Result<()> { - info!("close: fd: {}", fd); + debug!("close: fd: {}", fd); let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); let file_table_ref = current_process.get_files(); diff --git a/src/libos/src/fs/file_ops/dirent.rs b/src/libos/src/fs/file_ops/dirent.rs index 2b8d687f..c4d6bd90 100644 --- a/src/libos/src/fs/file_ops/dirent.rs +++ b/src/libos/src/fs/file_ops/dirent.rs @@ -61,7 +61,7 @@ unsafe fn write_cstr(ptr: *mut u8, s: &str) { } pub fn do_getdents64(fd: FileDesc, buf: &mut [u8]) -> Result { - info!( + debug!( "getdents64: fd: {}, buf: {:?}, buf_size: {}", fd, buf.as_ptr(), diff --git a/src/libos/src/fs/file_ops/fcntl.rs b/src/libos/src/fs/file_ops/fcntl.rs index dc619d15..bdacfe4c 100644 --- a/src/libos/src/fs/file_ops/fcntl.rs +++ b/src/libos/src/fs/file_ops/fcntl.rs @@ -52,7 +52,7 @@ impl<'a> FcntlCmd<'a> { } pub fn do_fcntl(fd: FileDesc, cmd: &mut FcntlCmd) -> Result { - info!("fcntl: fd: {:?}, cmd: {:?}", &fd, cmd); + debug!("fcntl: fd: {:?}, cmd: {:?}", &fd, cmd); let current_ref = process::get_current(); let mut current = current_ref.lock().unwrap(); let file_table_ref = current.get_files(); diff --git a/src/libos/src/fs/file_ops/fsync.rs b/src/libos/src/fs/file_ops/fsync.rs index 5e126271..b6fa58f4 100644 --- a/src/libos/src/fs/file_ops/fsync.rs +++ b/src/libos/src/fs/file_ops/fsync.rs @@ -1,7 +1,7 @@ use super::*; pub fn do_fsync(fd: FileDesc) -> Result<()> { - info!("fsync: fd: {}", fd); + debug!("fsync: fd: {}", fd); let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); let file_ref = current_process.get_files().lock().unwrap().get(fd)?; @@ -10,7 +10,7 @@ pub fn do_fsync(fd: FileDesc) -> Result<()> { } pub fn do_fdatasync(fd: FileDesc) -> Result<()> { - info!("fdatasync: fd: {}", fd); + debug!("fdatasync: fd: {}", fd); let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); let file_ref = current_process.get_files().lock().unwrap().get(fd)?; diff --git a/src/libos/src/fs/file_ops/ioctl/mod.rs b/src/libos/src/fs/file_ops/ioctl/mod.rs index 1257674c..98e4a39f 100644 --- a/src/libos/src/fs/file_ops/ioctl/mod.rs +++ b/src/libos/src/fs/file_ops/ioctl/mod.rs @@ -65,7 +65,7 @@ impl<'a> IoctlCmd<'a> { } pub fn do_ioctl(fd: FileDesc, cmd: &mut IoctlCmd) -> Result<()> { - info!("ioctl: fd: {}, cmd: {:?}", fd, cmd); + debug!("ioctl: fd: {}, cmd: {:?}", fd, cmd); let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); let file_ref = current_process.get_files().lock().unwrap().get(fd)?; diff --git a/src/libos/src/fs/file_ops/link.rs b/src/libos/src/fs/file_ops/link.rs index 32c6e3e3..3b6c8a5e 100644 --- a/src/libos/src/fs/file_ops/link.rs +++ b/src/libos/src/fs/file_ops/link.rs @@ -3,7 +3,7 @@ use super::*; pub fn do_link(oldpath: &str, newpath: &str) -> Result<()> { let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); - info!("link: oldpath: {:?}, newpath: {:?}", oldpath, newpath); + debug!("link: oldpath: {:?}, newpath: {:?}", oldpath, newpath); let (new_dir_path, new_file_name) = split_path(&newpath); let inode = current_process.lookup_inode(&oldpath)?; diff --git a/src/libos/src/fs/file_ops/mkdir.rs b/src/libos/src/fs/file_ops/mkdir.rs index 96b8f0d9..12ba8076 100644 --- a/src/libos/src/fs/file_ops/mkdir.rs +++ b/src/libos/src/fs/file_ops/mkdir.rs @@ -4,7 +4,7 @@ pub fn do_mkdir(path: &str, mode: usize) -> Result<()> { let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); // TODO: check pathname - info!("mkdir: path: {:?}, mode: {:#o}", path, mode); + debug!("mkdir: path: {:?}, mode: {:#o}", path, mode); let (dir_path, file_name) = split_path(&path); let inode = current_process.lookup_inode(dir_path)?; diff --git a/src/libos/src/fs/file_ops/open.rs b/src/libos/src/fs/file_ops/open.rs index 46cd741d..5c70de43 100644 --- a/src/libos/src/fs/file_ops/open.rs +++ b/src/libos/src/fs/file_ops/open.rs @@ -18,7 +18,7 @@ fn do_open(path: &str, flags: u32, mode: u32) -> Result { } pub fn do_openat(dirfd: DirFd, path: &str, flags: u32, mode: u32) -> Result { - info!( + debug!( "openat: dirfd: {:?}, path: {:?}, flags: {:#o}, mode: {:#o}", dirfd, path, flags, mode ); diff --git a/src/libos/src/fs/file_ops/read.rs b/src/libos/src/fs/file_ops/read.rs index 84a0a4bb..b93a7401 100644 --- a/src/libos/src/fs/file_ops/read.rs +++ b/src/libos/src/fs/file_ops/read.rs @@ -1,7 +1,7 @@ use super::*; pub fn do_read(fd: FileDesc, buf: &mut [u8]) -> Result { - info!("read: fd: {}", fd); + debug!("read: fd: {}", fd); let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); let file_ref = current_process.get_files().lock().unwrap().get(fd)?; @@ -9,7 +9,7 @@ pub fn do_read(fd: FileDesc, buf: &mut [u8]) -> Result { } pub fn do_readv(fd: FileDesc, bufs: &mut [&mut [u8]]) -> Result { - info!("readv: fd: {}", fd); + debug!("readv: fd: {}", fd); let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); let file_ref = current_process.get_files().lock().unwrap().get(fd)?; @@ -17,7 +17,7 @@ pub fn do_readv(fd: FileDesc, bufs: &mut [&mut [u8]]) -> Result { } pub fn do_pread(fd: FileDesc, buf: &mut [u8], offset: usize) -> Result { - info!("pread: fd: {}, offset: {}", fd, offset); + debug!("pread: fd: {}, offset: {}", fd, offset); let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); let file_ref = current_process.get_files().lock().unwrap().get(fd)?; diff --git a/src/libos/src/fs/file_ops/rename.rs b/src/libos/src/fs/file_ops/rename.rs index 41b6cead..c412a23d 100644 --- a/src/libos/src/fs/file_ops/rename.rs +++ b/src/libos/src/fs/file_ops/rename.rs @@ -3,7 +3,7 @@ use super::*; pub fn do_rename(oldpath: &str, newpath: &str) -> Result<()> { let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); - info!("rename: oldpath: {:?}, newpath: {:?}", oldpath, newpath); + debug!("rename: oldpath: {:?}, newpath: {:?}", oldpath, newpath); let (old_dir_path, old_file_name) = split_path(&oldpath); let (new_dir_path, new_file_name) = split_path(&newpath); diff --git a/src/libos/src/fs/file_ops/rmdir.rs b/src/libos/src/fs/file_ops/rmdir.rs index b4801154..6f35fb37 100644 --- a/src/libos/src/fs/file_ops/rmdir.rs +++ b/src/libos/src/fs/file_ops/rmdir.rs @@ -3,7 +3,7 @@ use super::*; pub fn do_rmdir(path: &str) -> Result<()> { let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); - info!("rmdir: path: {:?}", path); + debug!("rmdir: path: {:?}", path); let (dir_path, file_name) = split_path(&path); let dir_inode = current_process.lookup_inode(dir_path)?; diff --git a/src/libos/src/fs/file_ops/sendfile.rs b/src/libos/src/fs/file_ops/sendfile.rs index 1c59d167..6f363c42 100644 --- a/src/libos/src/fs/file_ops/sendfile.rs +++ b/src/libos/src/fs/file_ops/sendfile.rs @@ -7,7 +7,7 @@ pub fn do_sendfile( count: usize, ) -> Result<(usize, usize)> { // (len, offset) - info!( + debug!( "sendfile: out: {}, in: {}, offset: {:?}, count: {}", out_fd, in_fd, offset, count ); diff --git a/src/libos/src/fs/file_ops/stat.rs b/src/libos/src/fs/file_ops/stat.rs index d1abf74f..280912dd 100644 --- a/src/libos/src/fs/file_ops/stat.rs +++ b/src/libos/src/fs/file_ops/stat.rs @@ -140,7 +140,7 @@ fn do_stat(path: &str) -> Result { } pub fn do_fstat(fd: u32) -> Result { - info!("fstat: fd: {}", fd); + debug!("fstat: fd: {}", fd); let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); let file_ref = current_process.get_files().lock().unwrap().get(fd)?; @@ -150,7 +150,7 @@ pub fn do_fstat(fd: u32) -> Result { } pub fn do_lstat(path: &str) -> Result { - info!("lstat: path: {}", path); + debug!("lstat: path: {}", path); let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); let inode = current_process.lookup_inode(&path)?; @@ -159,7 +159,7 @@ pub fn do_lstat(path: &str) -> Result { } pub fn do_fstatat(dirfd: DirFd, path: &str, flags: StatFlags) -> Result { - info!( + debug!( "fstatat: dirfd: {:?}, path: {:?}, flags: {:?}", dirfd, path, flags ); diff --git a/src/libos/src/fs/file_ops/symlink.rs b/src/libos/src/fs/file_ops/symlink.rs index 4b381a8c..b83ee848 100644 --- a/src/libos/src/fs/file_ops/symlink.rs +++ b/src/libos/src/fs/file_ops/symlink.rs @@ -1,7 +1,7 @@ use super::*; pub fn do_readlink(path: &str, buf: &mut [u8]) -> Result { - info!("readlink: path: {:?}", path); + debug!("readlink: path: {:?}", path); let file_path = { if path == "/proc/self/exe" { let current_ref = process::get_current(); diff --git a/src/libos/src/fs/file_ops/truncate.rs b/src/libos/src/fs/file_ops/truncate.rs index fd53e5ec..f287761b 100644 --- a/src/libos/src/fs/file_ops/truncate.rs +++ b/src/libos/src/fs/file_ops/truncate.rs @@ -1,7 +1,7 @@ use super::*; pub fn do_truncate(path: &str, len: usize) -> Result<()> { - info!("truncate: path: {:?}, len: {}", path, len); + debug!("truncate: path: {:?}, len: {}", path, len); let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); current_process.lookup_inode(&path)?.resize(len)?; @@ -9,7 +9,7 @@ pub fn do_truncate(path: &str, len: usize) -> Result<()> { } pub fn do_ftruncate(fd: FileDesc, len: usize) -> Result<()> { - info!("ftruncate: fd: {}, len: {}", fd, len); + debug!("ftruncate: fd: {}, len: {}", fd, len); let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); let file_ref = current_process.get_files().lock().unwrap().get(fd)?; diff --git a/src/libos/src/fs/file_ops/unlink.rs b/src/libos/src/fs/file_ops/unlink.rs index af50d1fc..8143fd2f 100644 --- a/src/libos/src/fs/file_ops/unlink.rs +++ b/src/libos/src/fs/file_ops/unlink.rs @@ -3,7 +3,7 @@ use super::*; pub fn do_unlink(path: &str) -> Result<()> { let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); - info!("unlink: path: {:?}", path); + debug!("unlink: path: {:?}", path); let (dir_path, file_name) = split_path(&path); let dir_inode = current_process.lookup_inode(dir_path)?; diff --git a/src/libos/src/fs/file_ops/write.rs b/src/libos/src/fs/file_ops/write.rs index a8ae8825..3e49e267 100644 --- a/src/libos/src/fs/file_ops/write.rs +++ b/src/libos/src/fs/file_ops/write.rs @@ -1,7 +1,7 @@ use super::*; pub fn do_write(fd: FileDesc, buf: &[u8]) -> Result { - info!("write: fd: {}", fd); + debug!("write: fd: {}", fd); let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); let file_ref = current_process.get_files().lock().unwrap().get(fd)?; @@ -9,7 +9,7 @@ pub fn do_write(fd: FileDesc, buf: &[u8]) -> Result { } pub fn do_writev(fd: FileDesc, bufs: &[&[u8]]) -> Result { - info!("writev: fd: {}", fd); + debug!("writev: fd: {}", fd); let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); let file_ref = current_process.get_files().lock().unwrap().get(fd)?; @@ -17,7 +17,7 @@ pub fn do_writev(fd: FileDesc, bufs: &[&[u8]]) -> Result { } pub fn do_pwrite(fd: FileDesc, buf: &[u8], offset: usize) -> Result { - info!("pwrite: fd: {}, offset: {}", fd, offset); + debug!("pwrite: fd: {}, offset: {}", fd, offset); let current_ref = process::get_current(); let current_process = current_ref.lock().unwrap(); let file_ref = current_process.get_files().lock().unwrap().get(fd)?; diff --git a/src/libos/src/fs/fs_ops/sync.rs b/src/libos/src/fs/fs_ops/sync.rs index 2de54a5b..a32a0e64 100644 --- a/src/libos/src/fs/fs_ops/sync.rs +++ b/src/libos/src/fs/fs_ops/sync.rs @@ -1,7 +1,7 @@ use super::*; pub fn do_sync() -> Result<()> { - info!("sync:"); + debug!("sync:"); ROOT_INODE.fs().sync()?; Ok(()) } diff --git a/src/libos/src/fs/pipe.rs b/src/libos/src/fs/pipe.rs index 68a2390f..9141ad5f 100644 --- a/src/libos/src/fs/pipe.rs +++ b/src/libos/src/fs/pipe.rs @@ -156,17 +156,19 @@ unsafe impl Send for PipeWriter {} unsafe impl Sync for PipeWriter {} pub fn do_pipe2(flags: u32) -> Result<[FileDesc; 2]> { - info!("pipe2: flags: {:#x}", flags); let creation_flags = CreationFlags::from_bits_truncate(flags); + let status_flags = StatusFlags::from_bits_truncate(flags); + debug!("pipe2: flags: {:?} {:?}", creation_flags, status_flags); + let current_ref = process::get_current(); let current = current_ref.lock().unwrap(); - let pipe = Pipe::new(StatusFlags::from_bits_truncate(flags))?; + let pipe = Pipe::new(status_flags)?; let file_table_ref = current.get_files(); let mut file_table = file_table_ref.lock().unwrap(); let close_on_spawn = creation_flags.must_close_on_spawn(); let reader_fd = file_table.put(Arc::new(Box::new(pipe.reader)), close_on_spawn); let writer_fd = file_table.put(Arc::new(Box::new(pipe.writer)), close_on_spawn); - info!("pipe2: reader_fd: {}, writer_fd: {}", reader_fd, writer_fd); + trace!("pipe2: reader_fd: {}, writer_fd: {}", reader_fd, writer_fd); Ok([reader_fd, writer_fd]) } diff --git a/src/libos/src/fs/syscalls.rs b/src/libos/src/fs/syscalls.rs index 0dfc5d24..a6837369 100644 --- a/src/libos/src/fs/syscalls.rs +++ b/src/libos/src/fs/syscalls.rs @@ -400,7 +400,6 @@ pub fn do_fcntl(fd: FileDesc, cmd: u32, arg: u64) -> Result { } pub fn do_ioctl(fd: FileDesc, cmd: u32, argp: *mut u8) -> Result { - info!("ioctl: fd: {}, cmd: {}, argp: {:?}", fd, cmd, argp); let mut ioctl_cmd = unsafe { if argp.is_null() == false { from_user::check_mut_ptr(argp)?; diff --git a/src/libos/src/net/io_multiplexing.rs b/src/libos/src/net/io_multiplexing.rs index bda39f6d..db8080c4 100644 --- a/src/libos/src/net/io_multiplexing.rs +++ b/src/libos/src/net/io_multiplexing.rs @@ -15,7 +15,7 @@ pub fn do_select( exceptfds: &mut libc::fd_set, timeout: Option, ) -> Result { - info!("select: nfds: {}", nfds); + debug!("select: nfds: {}", nfds); // convert libos fd to Linux fd let mut host_to_libos_fd = [0; libc::FD_SETSIZE]; let mut polls = Vec::::new(); @@ -117,7 +117,7 @@ pub fn do_select( } pub fn do_poll(pollfds: &mut [libc::pollfd], timeout: c_int) -> Result { - info!( + debug!( "poll: {:?}, timeout: {}", pollfds.iter().map(|p| p.fd).collect::>(), timeout @@ -189,7 +189,7 @@ pub fn do_poll(pollfds: &mut [libc::pollfd], timeout: c_int) -> Result { } pub fn do_epoll_create1(flags: c_int) -> Result { - info!("epoll_create1: flags: {}", flags); + debug!("epoll_create1: flags: {}", flags); let epoll = EpollFile::new()?; let file_ref: Arc> = Arc::new(Box::new(epoll)); @@ -211,7 +211,7 @@ pub fn do_epoll_ctl( fd: FileDesc, event: *const libc::epoll_event, ) -> Result<()> { - info!("epoll_ctl: epfd: {}, op: {:?}, fd: {}", epfd, op, fd); + debug!("epoll_ctl: epfd: {}, op: {:?}, fd: {}", epfd, op, fd); let current_ref = process::get_current(); let mut proc = current_ref.lock().unwrap(); @@ -240,7 +240,7 @@ pub fn do_epoll_wait( events: &mut [libc::epoll_event], timeout: c_int, ) -> Result { - info!( + debug!( "epoll_wait: epfd: {}, len: {:?}, timeout: {}", epfd, events.len(), diff --git a/src/libos/src/net/syscalls.rs b/src/libos/src/net/syscalls.rs index 3d24f70c..80258ad5 100644 --- a/src/libos/src/net/syscalls.rs +++ b/src/libos/src/net/syscalls.rs @@ -6,7 +6,7 @@ use process::Process; use util::mem_util::from_user; pub fn do_sendmsg(fd: c_int, msg_ptr: *const msghdr, flags_c: c_int) -> Result { - info!( + debug!( "sendmsg: fd: {}, msg: {:?}, flags: 0x{:x}", fd, msg_ptr, flags_c ); @@ -36,7 +36,7 @@ pub fn do_sendmsg(fd: c_int, msg_ptr: *const msghdr, flags_c: c_int) -> Result Result { - info!( + debug!( "recvmsg: fd: {}, msg: {:?}, flags: 0x{:x}", fd, msg_mut_ptr, flags_c ); @@ -232,11 +232,8 @@ pub fn do_epoll_pwait( timeout: c_int, sigmask: *const usize, //TODO:add sigset_t ) -> Result { - if sigmask.is_null() { - info!("epoll_wait"); - } else { - info!("epoll_pwait") + if !sigmask.is_null() { + warn!("epoll_pwait cannot handle signal mask, yet"); } - //TODO:add signal support do_epoll_wait(epfd, events, maxevents, timeout) } diff --git a/src/libos/src/prelude.rs b/src/libos/src/prelude.rs index d3658527..68138cc7 100644 --- a/src/libos/src/prelude.rs +++ b/src/libos/src/prelude.rs @@ -14,7 +14,7 @@ pub use std::sync::{ macro_rules! debug_trace { () => { - println!("> Line = {}, File = {}", line!(), file!()) + debug!("> Line = {}, File = {}", line!(), file!()) }; } diff --git a/src/libos/src/process/arch_prctl.rs b/src/libos/src/process/arch_prctl.rs index 730fa31f..c99221a6 100644 --- a/src/libos/src/process/arch_prctl.rs +++ b/src/libos/src/process/arch_prctl.rs @@ -22,7 +22,7 @@ impl ArchPrctlCode { } pub fn do_arch_prctl(code: ArchPrctlCode, addr: *mut usize) -> Result<()> { - info!( + debug!( "do_arch_prctl: code: {:?}, addr: {:#o}", code, addr as usize ); diff --git a/src/libos/src/process/spawn/init_vm.rs b/src/libos/src/process/spawn/init_vm.rs index 5e598737..5750f1dd 100644 --- a/src/libos/src/process/spawn/init_vm.rs +++ b/src/libos/src/process/spawn/init_vm.rs @@ -19,7 +19,7 @@ pub fn do_init<'a, 'b>( fn reloc_symbols(process_base_addr: usize, elf_file: &ElfFile) -> Result<()> { let rela_entries = elf_helper::get_rela_entries(elf_file, ".rela.dyn")?; for rela_entry in rela_entries { - println!( + trace!( "\toffset: {:#X}, symbol index: {}, type: {}, addend: {:#X}", rela_entry.get_offset(), rela_entry.get_symbol_table_index(), diff --git a/src/libos/src/process/spawn/mod.rs b/src/libos/src/process/spawn/mod.rs index d24c0772..b4ad0e4e 100644 --- a/src/libos/src/process/spawn/mod.rs +++ b/src/libos/src/process/spawn/mod.rs @@ -116,6 +116,7 @@ fn new_process( parent_adopts_new_child(&parent_ref, &new_process_ref); process_table::put(new_pid, new_process_ref.clone()); let new_tid = new_pid; + info!("Process created: elf = {}, tid = {}", elf_path, new_tid); Ok((new_tid, new_process_ref)) } diff --git a/src/libos/src/process/task.rs b/src/libos/src/process/task.rs index 4d7b408d..1630202e 100644 --- a/src/libos/src/process/task.rs +++ b/src/libos/src/process/task.rs @@ -123,6 +123,8 @@ pub fn run_task(libos_tid: pid_t, host_tid: pid_t) -> Result { (process.get_exit_status(), parent.get_tid()) }; + info!("Thread exited: tid = {}", libos_tid); + // If process's parent is the IDLE_PROCESS (pid = 0), so it has to release itself if parent_pid == 0 { process_table::remove(pid); diff --git a/src/libos/src/process/thread.rs b/src/libos/src/process/thread.rs index 42ad1295..11e66625 100644 --- a/src/libos/src/process/thread.rs +++ b/src/libos/src/process/thread.rs @@ -42,7 +42,7 @@ pub fn do_clone( ctid: Option<*mut pid_t>, new_tls: Option, ) -> Result { - info!( + debug!( "clone: flags: {:?}, stack_addr: {:?}, ptid: {:?}, ctid: {:?}, new_tls: {:?}", flags, user_rsp, ptid, ctid, new_tls ); @@ -99,6 +99,7 @@ pub fn do_clone( } process_table::put(new_thread_pid, new_thread_ref.clone()); + info!("Thread created: tid = {}", new_thread_pid); if let Some(ptid) = ptid { unsafe { @@ -111,7 +112,7 @@ pub fn do_clone( } pub fn do_set_tid_address(tidptr: *mut pid_t) -> Result { - info!("set_tid_address: tidptr: {:#x}", tidptr as usize); + debug!("set_tid_address: tidptr: {:#x}", tidptr as usize); let current_ref = get_current(); let mut current = current_ref.lock().unwrap(); current.clear_child_tid = Some(tidptr); diff --git a/src/libos/src/syscall/mod.rs b/src/libos/src/syscall/mod.rs index 603e907d..17544c29 100644 --- a/src/libos/src/syscall/mod.rs +++ b/src/libos/src/syscall/mod.rs @@ -703,7 +703,7 @@ fn do_spawn( let envp = clone_cstrings_safely(envp)?; let file_actions = clone_file_actions_safely(fdop_list)?; let parent = process::get_current(); - info!( + debug!( "spawn: path: {:?}, argv: {:?}, envp: {:?}, fdop: {:?}", path, argv, envp, file_actions ); @@ -947,7 +947,7 @@ fn do_nanosleep(req_u: *const timespec_t, rem_u: *mut timespec_t) -> Result ! { - info!("exit: {}", status); + debug!("exit: {}", status); extern "C" { fn do_exit_task() -> !; } @@ -1028,7 +1028,7 @@ fn do_sched_setaffinity(pid: pid_t, cpusize: size_t, buf: *const c_uchar) -> Res } fn do_socket(domain: c_int, socket_type: c_int, protocol: c_int) -> Result { - info!( + debug!( "socket: domain: {}, socket_type: 0x{:x}, protocol: {}", domain, socket_type, protocol ); @@ -1052,7 +1052,7 @@ fn do_socket(domain: c_int, socket_type: c_int, protocol: c_int) -> Result Result { - info!( + debug!( "connect: fd: {}, addr: {:?}, addr_len: {}", fd, addr, addr_len ); @@ -1089,7 +1089,7 @@ fn do_accept4( addr_len: *mut libc::socklen_t, flags: c_int, ) -> Result { - info!( + debug!( "accept4: fd: {}, addr: {:?}, addr_len: {:?}, flags: {:#x}", fd, addr, addr_len, flags ); @@ -1119,7 +1119,7 @@ fn do_accept4( } fn do_shutdown(fd: c_int, how: c_int) -> Result { - info!("shutdown: fd: {}, how: {}", fd, how); + debug!("shutdown: fd: {}, how: {}", fd, how); let current_ref = process::get_current(); let mut proc = current_ref.lock().unwrap(); let file_ref = proc.get_files().lock().unwrap().get(fd as FileDesc)?; @@ -1132,7 +1132,7 @@ fn do_shutdown(fd: c_int, how: c_int) -> Result { } fn do_bind(fd: c_int, addr: *const libc::sockaddr, addr_len: libc::socklen_t) -> Result { - info!("bind: fd: {}, addr: {:?}, addr_len: {}", fd, addr, addr_len); + debug!("bind: fd: {}, addr: {:?}, addr_len: {}", fd, addr, addr_len); let current_ref = process::get_current(); let mut proc = current_ref.lock().unwrap(); let file_ref = proc.get_files().lock().unwrap().get(fd as FileDesc)?; @@ -1154,7 +1154,7 @@ fn do_bind(fd: c_int, addr: *const libc::sockaddr, addr_len: libc::socklen_t) -> } fn do_listen(fd: c_int, backlog: c_int) -> Result { - info!("listen: fd: {}, backlog: {}", fd, backlog); + debug!("listen: fd: {}, backlog: {}", fd, backlog); let current_ref = process::get_current(); let mut proc = current_ref.lock().unwrap(); let file_ref = proc.get_files().lock().unwrap().get(fd as FileDesc)?; @@ -1176,7 +1176,7 @@ fn do_setsockopt( optval: *const c_void, optlen: libc::socklen_t, ) -> Result { - info!( + debug!( "setsockopt: fd: {}, level: {}, optname: {}, optval: {:?}, optlen: {:?}", fd, level, optname, optval, optlen ); @@ -1207,7 +1207,7 @@ fn do_getsockopt( optval: *mut c_void, optlen: *mut libc::socklen_t, ) -> Result { - info!( + debug!( "getsockopt: fd: {}, level: {}, optname: {}, optval: {:?}, optlen: {:?}", fd, level, optname, optval, optlen ); @@ -1231,7 +1231,7 @@ fn do_getpeername( addr: *mut libc::sockaddr, addr_len: *mut libc::socklen_t, ) -> Result { - info!( + debug!( "getpeername: fd: {}, addr: {:?}, addr_len: {:?}", fd, addr, addr_len ); @@ -1257,7 +1257,7 @@ fn do_getsockname( addr: *mut libc::sockaddr, addr_len: *mut libc::socklen_t, ) -> Result { - info!( + debug!( "getsockname: fd: {}, addr: {:?}, addr_len: {:?}", fd, addr, addr_len ); @@ -1283,7 +1283,7 @@ fn do_sendto( addr: *const libc::sockaddr, addr_len: libc::socklen_t, ) -> Result { - info!( + debug!( "sendto: fd: {}, base: {:?}, len: {}, addr: {:?}, addr_len: {}", fd, base, len, addr, addr_len ); @@ -1311,7 +1311,7 @@ fn do_recvfrom( addr: *mut libc::sockaddr, addr_len: *mut libc::socklen_t, ) -> Result { - info!( + debug!( "recvfrom: fd: {}, base: {:?}, len: {}, flags: {}, addr: {:?}, addr_len: {:?}", fd, base, len, flags, addr, addr_len ); @@ -1337,7 +1337,7 @@ fn do_socketpair( protocol: c_int, sv: *mut c_int, ) -> Result { - info!( + debug!( "socketpair: domain: {}, type:0x{:x}, protocol: {}", domain, socket_type, protocol ); @@ -1362,7 +1362,7 @@ fn do_socketpair( .unwrap() .put(Arc::new(Box::new(server_socket)), false); - info!("socketpair: ({}, {})", sock_pair[0], sock_pair[1]); + debug!("socketpair: ({}, {})", sock_pair[0], sock_pair[1]); Ok(0) } else if (domain == libc::AF_TIPC) { return_errno!(EAFNOSUPPORT, "cluster domain sockets not supported") diff --git a/src/libos/src/time/profiler.rs b/src/libos/src/time/profiler.rs index f512906c..aa46e07e 100644 --- a/src/libos/src/time/profiler.rs +++ b/src/libos/src/time/profiler.rs @@ -34,7 +34,6 @@ impl GlobalProfiler { self.syscall_exit(SyscallNum::Exit, false); let tid = process::do_gettid(); - println!("thread {} exits", tid); let mut exiting_profiler = self.inner.remove(&tid).ok_or_else(|| { errno!( @@ -99,7 +98,6 @@ impl ThreadProfiler { fn stop(&mut self) -> Result<()> { if self.status != Status::Running { - error!("wrong status is {:?}", self.status); return_errno!(EINVAL, "fail to stop thread profiler"); } let real = time::do_gettimeofday().as_duration() - self.start_time.get_realtime().unwrap(); diff --git a/src/libos/src/util/log.rs b/src/libos/src/util/log.rs index 24c9ca5d..a76b4dc1 100644 --- a/src/libos/src/util/log.rs +++ b/src/libos/src/util/log.rs @@ -1,4 +1,3 @@ -use super::process; /// Log infrastructure. /// /// There are five APIs for producing log messages: @@ -9,6 +8,27 @@ use super::process; /// 5. `trace!` /// which corresponds to five different log levels. /// +/// To give all developers a common sense of "when to use which log level", we give some guidelines +/// and examples here: +/// +/// 1. Use `errno!` to mark errors or unexpected conditions, e.g., a `Result::Err` returned from a +/// system call. +/// +/// 2. Use `warn!` to warn about potentially problematic issues, e.g., executing a workaround or +/// fake implementation. +/// +/// 3. Use `info!` to show important events (from users' perspective) in normal execution, +/// e.g., creating/exiting a process/thread. +/// +/// 4. Use `debug!` to track major events in normal execution, e.g., the high-level +/// arguments of a system call. +/// +/// 5. Use `trace` to record the most detailed info, e.g., when a system call enters +/// and exits the LibOS. +/// +/// One of the most important principles for effective logging is "don't log too much or too little". +/// So log messages should be inserted with discretion. +/// /// 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. @@ -16,6 +36,7 @@ use super::process; /// 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 super::process; use log::*; use std::cell::Cell; diff --git a/src/libos/src/vm/mod.rs b/src/libos/src/vm/mod.rs index bf4cdc3c..69ffb267 100644 --- a/src/libos/src/vm/mod.rs +++ b/src/libos/src/vm/mod.rs @@ -24,12 +24,12 @@ pub fn do_mmap( offset: usize, ) -> Result { if flags.contains(MMapFlags::MAP_ANONYMOUS) { - info!( + debug!( "mmap: addr: {:#x}, size: {:#x}, perms: {:?}, flags: {:?}", addr, size, perms, flags, ); } else { - info!( + debug!( "mmap: addr: {:#x}, size: {:#x}, perms: {:?}, flags: {:?}, fd: {:?}, offset: {:?}", addr, size, perms, flags, fd, offset ); @@ -45,7 +45,7 @@ pub fn do_mmap( } pub fn do_munmap(addr: usize, size: usize) -> Result<()> { - info!("munmap: addr: {:#x}, size: {:#x}", addr, size); + debug!("munmap: addr: {:#x}, size: {:#x}", addr, size); let mut current_vm_ref = { let current_ref = get_current(); let current_process = current_ref.lock().unwrap(); @@ -56,7 +56,7 @@ pub fn do_munmap(addr: usize, size: usize) -> Result<()> { } pub fn do_brk(addr: usize) -> Result { - info!("brk: addr: {:#x}", addr); + debug!("brk: addr: {:#x}", addr); let current_ref = get_current(); let current_process = current_ref.lock().unwrap(); let current_vm_ref = current_process.get_vm();