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

@@ -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)?;

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()?;

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();

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<usize> {
-    info!(
+    debug!(
         "getdents64: fd: {}, buf: {:?}, buf_size: {}",
         fd,
         buf.as_ptr(),

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<isize> {
-    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();

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)?;

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)?;

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)?;

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)?;

src/libos/src/fs/file_ops/open.rs

@@ -18,7 +18,7 @@ fn do_open(path: &str, flags: u32, mode: u32) -> Result<FileDesc> {
 }
 
 pub fn do_openat(dirfd: DirFd, path: &str, flags: u32, mode: u32) -> Result<FileDesc> {
-    info!(
+    debug!(
         "openat: dirfd: {:?}, path: {:?}, flags: {:#o}, mode: {:#o}",
         dirfd, path, flags, mode
     );

src/libos/src/fs/file_ops/read.rs

@@ -1,7 +1,7 @@
 use super::*;
 
 pub fn do_read(fd: FileDesc, buf: &mut [u8]) -> Result<usize> {
-    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<usize> {
 }
 
 pub fn do_readv(fd: FileDesc, bufs: &mut [&mut [u8]]) -> Result<usize> {
-    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<usize> {
 }
 
 pub fn do_pread(fd: FileDesc, buf: &mut [u8], offset: usize) -> Result<usize> {
-    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)?;

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);

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)?;

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
     );

src/libos/src/fs/file_ops/stat.rs

@@ -140,7 +140,7 @@ fn do_stat(path: &str) -> Result<Stat> {
 }
 
 pub fn do_fstat(fd: u32) -> Result<Stat> {
-    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<Stat> {
 }
 
 pub fn do_lstat(path: &str) -> Result<Stat> {
-    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<Stat> {
 }
 
 pub fn do_fstatat(dirfd: DirFd, path: &str, flags: StatFlags) -> Result<Stat> {
-    info!(
+    debug!(
         "fstatat: dirfd: {:?}, path: {:?}, flags: {:?}",
         dirfd, path, flags
     );

src/libos/src/fs/file_ops/symlink.rs

@@ -1,7 +1,7 @@
 use super::*;
 
 pub fn do_readlink(path: &str, buf: &mut [u8]) -> Result<usize> {
-    info!("readlink: path: {:?}", path);
+    debug!("readlink: path: {:?}", path);
     let file_path = {
         if path == "/proc/self/exe" {
             let current_ref = process::get_current();

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)?;

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)?;

src/libos/src/fs/file_ops/write.rs

@@ -1,7 +1,7 @@
 use super::*;
 
 pub fn do_write(fd: FileDesc, buf: &[u8]) -> Result<usize> {
-    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<usize> {
 }
 
 pub fn do_writev(fd: FileDesc, bufs: &[&[u8]]) -> Result<usize> {
-    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<usize> {
 }
 
 pub fn do_pwrite(fd: FileDesc, buf: &[u8], offset: usize) -> Result<usize> {
-    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)?;

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(())
 }

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])
 }

src/libos/src/fs/syscalls.rs

@@ -400,7 +400,6 @@ pub fn do_fcntl(fd: FileDesc, cmd: u32, arg: u64) -> Result<isize> {
 }
 
 pub fn do_ioctl(fd: FileDesc, cmd: u32, argp: *mut u8) -> Result<isize> {
-    info!("ioctl: fd: {}, cmd: {}, argp: {:?}", fd, cmd, argp);
     let mut ioctl_cmd = unsafe {
         if argp.is_null() == false {
             from_user::check_mut_ptr(argp)?;

src/libos/src/net/io_multiplexing.rs

@@ -15,7 +15,7 @@ pub fn do_select(
     exceptfds: &mut libc::fd_set,
     timeout: Option<libc::timeval>,
 ) -> Result<usize> {
-    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::<libc::pollfd>::new();
@@ -117,7 +117,7 @@ pub fn do_select(
 }
 
 pub fn do_poll(pollfds: &mut [libc::pollfd], timeout: c_int) -> Result<usize> {
-    info!(
+    debug!(
         "poll: {:?}, timeout: {}",
         pollfds.iter().map(|p| p.fd).collect::<Vec<_>>(),
         timeout
@@ -189,7 +189,7 @@ pub fn do_poll(pollfds: &mut [libc::pollfd], timeout: c_int) -> Result<usize> {
 }
 
 pub fn do_epoll_create1(flags: c_int) -> Result<FileDesc> {
-    info!("epoll_create1: flags: {}", flags);
+    debug!("epoll_create1: flags: {}", flags);
 
     let epoll = EpollFile::new()?;
     let file_ref: Arc<Box<dyn File>> = 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<usize> {
-    info!(
+    debug!(
         "epoll_wait: epfd: {}, len: {:?}, timeout: {}",
         epfd,
         events.len(),

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<isize> {
-    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<i
 }
 
 pub fn do_recvmsg(fd: c_int, msg_mut_ptr: *mut msghdr_mut, flags_c: c_int) -> Result<isize> {
-    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<isize> {
-    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)
 }

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!())
     };
 }
 

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
     );

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(),

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))
 }
 

src/libos/src/process/task.rs

@@ -123,6 +123,8 @@ pub fn run_task(libos_tid: pid_t, host_tid: pid_t) -> Result<i32> {
         (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);

src/libos/src/process/thread.rs

@@ -42,7 +42,7 @@ pub fn do_clone(
     ctid: Option<*mut pid_t>,
     new_tls: Option<usize>,
 ) -> Result<pid_t> {
-    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<pid_t> {
-    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);

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<isiz
 const MAP_FAILED: *const c_void = ((-1) as i64) as *const c_void;
 
 fn do_exit(status: i32) -> ! {
-    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<isize> {
-    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<isize
 }
 
 fn do_connect(fd: c_int, addr: *const libc::sockaddr, addr_len: libc::socklen_t) -> Result<isize> {
-    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<isize> {
-    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<isize> {
-    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<isize> {
 }
 
 fn do_bind(fd: c_int, addr: *const libc::sockaddr, addr_len: libc::socklen_t) -> Result<isize> {
-    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<isize> {
-    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<isize> {
-    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<isize> {
-    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<isize> {
-    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<isize> {
-    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<isize> {
-    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<isize> {
-    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<isize> {
-    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")

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();

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;
 

src/libos/src/vm/mod.rs

@@ -24,12 +24,12 @@ pub fn do_mmap(
     offset: usize,
 ) -> Result<usize> {
     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<usize> {
-    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();