Change logging functions to always add an implicit newline

Signed-off-by: Michał Kowalczyk <[email protected]>

LibOS/shim/include/shim_checkpoint.h

@@ -296,7 +296,7 @@ struct shim_cp_map_entry* get_cp_map_entry(void* map, void* addr, bool create);
 
 #if DEBUG_RESUME == 1
 #define DEBUG_RS(fmt, ...) \
-    log_debug("GET %s(0x%08lx): " fmt "\n", CP_FUNC_NAME, entry->cp_val, ##__VA_ARGS__)
+    log_debug("GET %s(0x%08lx): " fmt, CP_FUNC_NAME, entry->cp_val, ##__VA_ARGS__)
 #else
 #define DEBUG_RS(...) do {} while (0)
 #endif
@@ -313,7 +313,7 @@ struct shim_cp_map_entry* get_cp_map_entry(void* map, void* addr, bool create);
             if (ret < 0)                                                   \
                 goto out;                                                  \
                                                                            \
-            log_debug("complete checkpointing data\n");                    \
+            log_debug("complete checkpointing data");                      \
         out:                                                               \
             destroy_cp_map((store)->cp_map);                               \
         } while (0);                                                       \

LibOS/shim/include/shim_internal.h

@@ -39,14 +39,14 @@ void shim_log(int level, const char* fmt, ...) __attribute__((format(printf, 2,
 
 #define BUG()                                           \
     do {                                                \
-        log_error("BUG() " __FILE__ ":%d\n", __LINE__); \
+        log_error("BUG() " __FILE__ ":%d", __LINE__);   \
         DEBUG_BREAK_ON_FAILURE();                       \
         die_or_inf_loop();                              \
     } while (0)
 
 #define DEBUG_HERE()                                             \
     do {                                                         \
-        log_debug("%s (" __FILE__ ":%d)\n", __func__, __LINE__); \
+        log_debug("%s (" __FILE__ ":%d)", __func__, __LINE__);   \
     } while (0)
 
 /*!
@@ -301,7 +301,7 @@ static inline int64_t __ref_dec(REFTYPE* ref) {
     do {
         _c = __atomic_load_n(&ref->counter, __ATOMIC_SEQ_CST);
         if (!_c) {
-            log_error("Fail: Trying to drop reference count below 0\n");
+            log_error("Fail: Trying to drop reference count below 0");
             BUG();
             return 0;
         }

LibOS/shim/include/shim_lock.h

@@ -81,11 +81,11 @@ extern struct shim_lock __master_lock;
 #define MASTER_LOCK()                                          \
     do {                                                       \
         lock(&__master_lock);                                  \
-        log_debug("master lock " __FILE__ ":%d\n", __LINE__);  \
+        log_debug("master lock " __FILE__ ":%d", __LINE__);    \
     } while (0)
 #define MASTER_UNLOCK()                                          \
     do {                                                         \
-        log_debug("master unlock " __FILE__ ":%d\n", __LINE__);  \
+        log_debug("master unlock " __FILE__ ":%d", __LINE__);    \
         unlock(&__master_lock);                                  \
     } while (0)
 #else

LibOS/shim/include/shim_sync.h

@@ -147,7 +147,7 @@
 
 #define uthash_fatal(msg)                      \
     do {                                       \
-        log_error("uthash error: %s\n", msg);  \
+        log_error("uthash error: %s", msg);    \
         DkProcessExit(PAL_ERROR_NOMEM);        \
     } while (0)
 #include "uthash.h"

LibOS/shim/src/arch/x86_64/shim_arch_prctl.c

@@ -22,7 +22,7 @@ long shim_do_arch_prctl(int code, void* addr) {
             return pal_to_unix_errno(DkSegmentRegisterGet(PAL_SEGMENT_FS, addr));
 
         default:
-            log_warning("Not supported flag (0x%x) passed to arch_prctl\n", code);
+            log_warning("Not supported flag (0x%x) passed to arch_prctl", code);
             return -ENOSYS;
     }
 }

LibOS/shim/src/arch/x86_64/shim_context.c

@@ -68,7 +68,7 @@ void shim_xstate_init(void) {
     g_shim_xsave_size      = xsavesize;
 
 out:
-    log_debug("LibOS xsave_enabled %d, xsave_size 0x%x(%u), xsave_features 0x%lx\n",
+    log_debug("LibOS xsave_enabled %d, xsave_size 0x%x(%u), xsave_features 0x%lx",
               g_shim_xsave_enabled, g_shim_xsave_size, g_shim_xsave_size, g_shim_xsave_features);
 }
 
@@ -274,7 +274,7 @@ void prepare_sigframe(PAL_CONTEXT* context, siginfo_t* siginfo, void* handler, v
      * register arguments in `rax`. */
     context->rax = 0;
 
-    log_debug("Created sigframe for sig: %d at %p (handler: %p, restorer: %p)\n",
+    log_debug("Created sigframe for sig: %d at %p (handler: %p, restorer: %p)",
               siginfo->si_signo, sigframe, handler, restorer);
 }
 

LibOS/shim/src/bookkeep/shim_handle.c

@@ -102,12 +102,12 @@ static int init_exec_handle(void) {
     assert(g_manifest_root);
     ret = toml_string_in(g_manifest_root, "libos.entrypoint", &entrypoint);
     if (ret < 0) {
-        log_error("Cannot parse 'libos.entrypoint'\n");
+        log_error("Cannot parse 'libos.entrypoint'");
         ret = -EINVAL;
         goto out;
     }
     if (!entrypoint) {
-        log_error("'libos.entrypoint' must be specified in the manifest\n");
+        log_error("'libos.entrypoint' must be specified in the manifest");
         ret = -EINVAL;
         goto out;
     }
@@ -117,7 +117,7 @@ static int init_exec_handle(void) {
     if (strstartswith(exec_path, URI_PREFIX_FILE)) {
         /* TODO: change to error after some deprecation period */
         log_error("'libos.entrypoint' is now a Graphene path, not URI. "
-                  "Ignoring the 'file:' prefix.\n");
+                  "Ignoring the 'file:' prefix.");
         exec_path += strlen(URI_PREFIX_FILE);
     }
 
@@ -129,7 +129,7 @@ static int init_exec_handle(void) {
 
     ret = open_executable(hdl, exec_path);
     if (ret < 0) {
-        log_error("init_exec_handle: error opening executable: %d\n", ret);
+        log_error("init_exec_handle: error opening executable: %d", ret);
         goto out;
     }
 
@@ -442,7 +442,7 @@ void get_handle(struct shim_handle* hdl) {
 #ifdef DEBUG_REF
     int ref_count = REF_INC(hdl->ref_count);
 
-    log_debug("get handle %p(%s) (ref_count = %d)\n", hdl, __handle_name(hdl), ref_count);
+    log_debug("get handle %p(%s) (ref_count = %d)", hdl, __handle_name(hdl), ref_count);
 #else
     REF_INC(hdl->ref_count);
 #endif
@@ -458,7 +458,7 @@ void put_handle(struct shim_handle* hdl) {
     int ref_count = REF_DEC(hdl->ref_count);
 
 #ifdef DEBUG_REF
-    log_debug("put handle %p(%s) (ref_count = %d)\n", hdl, __handle_name(hdl), ref_count);
+    log_debug("put handle %p(%s) (ref_count = %d)", hdl, __handle_name(hdl), ref_count);
 #endif
 
     if (!ref_count) {
@@ -483,7 +483,7 @@ void put_handle(struct shim_handle* hdl) {
 
         if (hdl->pal_handle) {
 #ifdef DEBUG_REF
-            log_debug("handle %p closes PAL handle %p\n", hdl, hdl->pal_handle);
+            log_debug("handle %p closes PAL handle %p", hdl, hdl->pal_handle);
 #endif
             DkObjectClose(hdl->pal_handle); // TODO: handle errors
             hdl->pal_handle = NULL;

LibOS/shim/src/bookkeep/shim_pid.c

@@ -72,14 +72,14 @@ IDTYPE get_new_id(bool remove_from_owned) {
     if (!g_last_range) {
         g_last_range = malloc(sizeof(*g_last_range));
         if (!g_last_range) {
-            log_debug("OOM in %s:%d\n", __FILE__, __LINE__);
+            log_debug("OOM in %s:%d", __FILE__, __LINE__);
             goto out;
         }
         IDTYPE start;
         IDTYPE end;
         int ret = ipc_alloc_id_range(&start, &end);
         if (ret < 0) {
-            log_debug("Failed to allocate new id range: %d\n", ret);
+            log_debug("Failed to allocate new id range: %d", ret);
             free(g_last_range);
             g_last_range = NULL;
             goto out;
@@ -115,7 +115,7 @@ IDTYPE get_new_id(bool remove_from_owned) {
         } else {
             struct id_range* range = malloc(sizeof(*range));
             if (!range) {
-                log_debug("OOM in %s:%d\n", __FILE__, __LINE__);
+                log_debug("OOM in %s:%d", __FILE__, __LINE__);
                 g_last_used_id--;
                 ret_id = 0;
                 goto out;
@@ -152,12 +152,12 @@ void release_id(IDTYPE id) {
         };
         struct avl_tree_node* node = avl_tree_lower_bound(&g_used_ranges_tree, &dummy.node);
         if (!node) {
-            log_error("Trying to release unknown ID!\n");
+            log_error("Trying to release unknown ID!");
             BUG();
         }
         struct id_range* range = container_of(node, struct id_range, node);
         if (id < range->start || range->end < id) {
-            log_error("Trying to release unknown ID!\n");
+            log_error("Trying to release unknown ID!");
             BUG();
         }
         assert(range->taken_count > 0);
@@ -168,7 +168,7 @@ void release_id(IDTYPE id) {
 
             int ret = ipc_release_id_range(range->start, range->end);
             if (ret < 0) {
-                log_error("IPC pid release failed\n");
+                log_error("IPC pid release failed");
                 die_or_inf_loop();
             }
             free(range);

LibOS/shim/src/bookkeep/shim_process.c

@@ -48,7 +48,7 @@ int init_process(int argc, const char** argv) {
     struct shim_dentry* dent = NULL;
     int ret = path_lookupat(/*start=*/NULL, "/", LOOKUP_FOLLOW | LOOKUP_DIRECTORY, &dent);
     if (ret < 0) {
-        log_error("Could not set up dentry for \"/\", something is seriously broken.\n");
+        log_error("Could not set up dentry for \"/\", something is seriously broken.");
         return ret;
     }
     g_process.root = dent;
@@ -162,7 +162,7 @@ static bool mark_child_exited(child_cmp_t child_cmp, unsigned long arg, IDTYPE c
         fill_siginfo_code_and_status(&info, signal, exit_code);
         int x = kill_current_proc(&info);
         if (x < 0) {
-            log_error("Sending child death signal failed: %d!\n", x);
+            log_error("Sending child death signal failed: %d!", x);
         }
     }
 

LibOS/shim/src/bookkeep/shim_signal.c

@@ -59,7 +59,7 @@ void thread_sigaction_reset_on_execve(void) {
 }
 
 static noreturn void sighandler_kill(int sig) {
-    log_debug("killed by signal %d\n", sig & ~__WCOREDUMP_BIT);
+    log_debug("killed by signal %d", sig & ~__WCOREDUMP_BIT);
     process_exit(0, sig);
 }
 
@@ -310,10 +310,10 @@ static noreturn void internal_fault(const char* errstr, PAL_NUM addr, PAL_CONTEX
     PAL_NUM ip = pal_context_get_ip(context);
 
     if (context_is_libos(context))
-        log_error("%s at 0x%08lx (IP = +0x%lx, VMID = %u, TID = %u)\n", errstr, addr,
+        log_error("%s at 0x%08lx (IP = +0x%lx, VMID = %u, TID = %u)", errstr, addr,
                   (void*)ip - (void*)&__load_address, g_self_vmid, tid);
     else
-        log_error("%s at 0x%08lx (IP = 0x%08lx, VMID = %u, TID = %u)\n", errstr, addr,
+        log_error("%s at 0x%08lx (IP = 0x%08lx, VMID = %u, TID = %u)", errstr, addr,
                   context ? ip : 0, g_self_vmid, tid);
 
     DEBUG_BREAK_ON_FAILURE();
@@ -328,7 +328,7 @@ static void arithmetic_error_upcall(bool is_in_pal, PAL_NUM addr, PAL_CONTEXT* c
     if (is_internal(get_cur_thread()) || context_is_libos(context)) {
         internal_fault("Internal arithmetic fault", addr, context);
     } else {
-        log_debug("arithmetic fault at 0x%08lx\n", pal_context_get_ip(context));
+        log_debug("arithmetic fault at 0x%08lx", pal_context_get_ip(context));
         siginfo_t info = {
             .si_signo = SIGFPE,
             .si_code = FPE_INTDIV,
@@ -348,7 +348,7 @@ static void memfault_upcall(bool is_in_pal, PAL_NUM addr, PAL_CONTEXT* context)
         internal_fault("Internal memory fault", addr, context);
     }
 
-    log_debug("memory fault at 0x%08lx (IP = 0x%08lx)\n", addr, pal_context_get_ip(context));
+    log_debug("memory fault at 0x%08lx (IP = 0x%08lx)", addr, pal_context_get_ip(context));
 
     siginfo_t info = {
         .si_addr = (void*)addr,
@@ -470,7 +470,7 @@ static void illegal_upcall(bool is_in_pal, PAL_NUM addr, PAL_CONTEXT* context) {
     /* Emulate syscall instruction, which is prohibited in Linux-SGX PAL and raises a SIGILL. */
     if (!maybe_emulate_syscall(context)) {
         void* rip = (void*)pal_context_get_ip(context);
-        log_debug("Illegal instruction during app execution at %p; delivering to app\n", rip);
+        log_debug("Illegal instruction during app execution at %p; delivering to app", rip);
         siginfo_t info = {
             .si_signo = SIGILL,
             .si_code = ILL_ILLOPC,
@@ -521,15 +521,15 @@ int init_signal_handling(void) {
                            &g_inject_host_signal_enabled);
     if (ret < 0) {
         log_error("Cannot parse 'sys.enable_sigterm_injection' (the value must be `true` or "
-                  "`false`)\n");
+                  "`false`)");
         return -EINVAL;
     }
 
     ret = toml_bool_in(g_manifest_root, "libos.check_invalid_pointers", /*defaultval=*/true,
                        &g_check_invalid_ptrs);
     if (ret < 0) {
         log_error("Cannot parse 'libos.check_invalid_pointers' (the value must be `true` or "
-                  "`false`)\n");
+                  "`false`)");
         return -EINVAL;
     }
 
@@ -797,10 +797,10 @@ int append_signal(struct shim_thread* thread, siginfo_t* info) {
     }
 
     if (thread) {
-        log_debug("Signal %d queue of thread %u is full, dropping incoming signal\n",
+        log_debug("Signal %d queue of thread %u is full, dropping incoming signal",
                   info->si_signo, thread->tid);
     } else {
-        log_debug("Signal %d queue of process is full, dropping incoming signal\n", info->si_signo);
+        log_debug("Signal %d queue of process is full, dropping incoming signal", info->si_signo);
     }
     /* This is counter-intuitive, but we report success here: after all signal was successfully
      * delivered, just the queue was full. */

LibOS/shim/src/bookkeep/shim_thread.c

@@ -32,7 +32,7 @@ struct shim_lock g_thread_list_lock;
 //#define DEBUG_REF
 
 #ifdef DEBUG_REF
-#define DEBUG_PRINT_REF_COUNT(rc) log_debug("%s %p ref_count = %d\n", __func__, dispositions, rc)
+#define DEBUG_PRINT_REF_COUNT(rc) log_debug("%s %p ref_count = %d", __func__, dispositions, rc)
 #else
 #define DEBUG_PRINT_REF_COUNT(rc) __UNUSED(rc)
 #endif
@@ -109,7 +109,7 @@ unmap:;
     void* tmp_vma = NULL;
     if (bkeep_munmap(addr, SHIM_THREAD_LIBOS_STACK_SIZE, /*is_internal=*/true, &tmp_vma) < 0) {
         log_error("[alloc_thread_libos_stack]"
-                  " Failed to remove bookkeeped memory that was not allocated at %p-%p!\n",
+                  " Failed to remove bookkeeped memory that was not allocated at %p-%p!",
                   addr, (char*)addr + SHIM_THREAD_LIBOS_STACK_SIZE);
         BUG();
     }
@@ -143,7 +143,7 @@ static int init_main_thread(void) {
 
     cur_thread->tid = get_new_id(/*remove_from_owned=*/false);
     if (!cur_thread->tid) {
-        log_error("Cannot allocate pid for the initial thread!\n");
+        log_error("Cannot allocate pid for the initial thread!");
         put_thread(cur_thread);
         return -ESRCH;
     }
@@ -307,7 +307,7 @@ void put_thread(struct shim_thread* thread) {
             void* tmp_vma = NULL;
             char* addr = (char*)thread->libos_stack_bottom - SHIM_THREAD_LIBOS_STACK_SIZE;
             if (bkeep_munmap(addr, SHIM_THREAD_LIBOS_STACK_SIZE, /*is_internal=*/true, &tmp_vma) < 0) {
-                log_error("[put_thread] Failed to remove bookkeeped memory at %p-%p!\n",
+                log_error("[put_thread] Failed to remove bookkeeped memory at %p-%p!",
                           addr, (char*)addr + SHIM_THREAD_LIBOS_STACK_SIZE);
                 BUG();
             }