[LibOS] Migrate logging to the new API

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, ...) \
-    debug("GET %s(0x%08lx): " fmt "\n", CP_FUNC_NAME, entry->cp_val, ##__VA_ARGS__)
+    log_debug("GET %s(0x%08lx): " fmt "\n", 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;                                                  \
                                                                            \
-            debug("complete checkpointing data\n");                        \
+            log_debug("complete checkpointing data\n");                    \
         out:                                                               \
             destroy_cp_map((store)->cp_map);                               \
         } while (0);                                                       \

LibOS/shim/include/shim_internal.h

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

LibOS/shim/include/shim_lock.h

@@ -40,46 +40,25 @@ static inline void destroy_lock(struct shim_lock* l) {
     clear_lock(l);
 }
 
-#ifdef DEBUG
-#define lock(l) __lock(l, __FILE__, __LINE__)
-static void __lock(struct shim_lock* l, const char* file, int line) {
-#else
 static void lock(struct shim_lock* l) {
-#endif
     if (!lock_enabled) {
         return;
     }
-    /* TODO: This whole if should be just an assert. Change it once we are sure that it does not
-     * trigger (previous code allowed for this case). Same in unlock below. */
-    if (!l->lock) {
-#ifdef DEBUG
-        debug("Trying to lock an uninitialized lock at %s:%d!\n", file, line);
-#endif // DEBUG
-        __abort();
-    }
+
+    assert(l->lock);
 
     while (!DkSynchronizationObjectWait(l->lock, NO_TIMEOUT))
         /* nop */;
 
     l->owner = get_cur_tid();
 }
 
-#ifdef DEBUG
-#define unlock(l) __unlock(l, __FILE__, __LINE__)
-static inline void __unlock(struct shim_lock* l, const char* file, int line) {
-#else
 static inline void unlock(struct shim_lock* l) {
-#endif
     if (!lock_enabled) {
         return;
     }
-    if (!l->lock) {
-#ifdef DEBUG
-        debug("Trying to unlock an uninitialized lock at %s:%d!\n", file, line);
-#endif // DEBUG
-        __abort();
-    }
 
+    assert(l->lock);
     l->owner = 0;
     DkMutexRelease(l->lock);
 }
@@ -102,11 +81,11 @@ extern struct shim_lock __master_lock;
 #define MASTER_LOCK()                                          \
     do {                                                       \
         lock(&__master_lock);                                  \
-        pal_printf("master lock " __FILE__ ":%d\n", __LINE__); \
+        log_debug("master lock " __FILE__ ":%d\n", __LINE__);  \
     } while (0)
 #define MASTER_UNLOCK()                                          \
     do {                                                         \
-        pal_printf("master unlock " __FILE__ ":%d\n", __LINE__); \
+        log_debug("master unlock " __FILE__ ":%d\n", __LINE__);  \
         unlock(&__master_lock);                                  \
     } while (0)
 #else

LibOS/shim/src/bookkeep/shim_handle.c

@@ -398,7 +398,7 @@ void get_handle(struct shim_handle* hdl) {
 #ifdef DEBUG_REF
     int ref_count = REF_INC(hdl->ref_count);
 
-    debug("get handle %p(%s) (ref_count = %d)\n", hdl, __handle_name(hdl), ref_count);
+    log_debug("get handle %p(%s) (ref_count = %d)\n", hdl, __handle_name(hdl), ref_count);
 #else
     REF_INC(hdl->ref_count);
 #endif
@@ -414,7 +414,7 @@ void put_handle(struct shim_handle* hdl) {
     int ref_count = REF_DEC(hdl->ref_count);
 
 #ifdef DEBUG_REF
-    debug("put handle %p(%s) (ref_count = %d)\n", hdl, __handle_name(hdl), ref_count);
+    log_debug("put handle %p(%s) (ref_count = %d)\n", hdl, __handle_name(hdl), ref_count);
 #endif
 
     if (!ref_count) {
@@ -458,7 +458,7 @@ void put_handle(struct shim_handle* hdl) {
 
         if (hdl->pal_handle) {
 #ifdef DEBUG_REF
-            debug("handle %p closes PAL handle %p\n", hdl, hdl->pal_handle);
+            log_debug("handle %p closes PAL handle %p\n", hdl, hdl->pal_handle);
 #endif
             DkObjectClose(hdl->pal_handle);
             hdl->pal_handle = NULL;

LibOS/shim/src/bookkeep/shim_process.c

@@ -48,7 +48,7 @@ int init_process(void) {
     struct shim_dentry* dent = NULL;
     int ret = path_lookupat(NULL, "/", 0, &dent, NULL);
     if (ret < 0) {
-        debug("Could not set up dentry for \"/\", something is seriously broken.\n");
+        log_error("Could not set up dentry for \"/\", something is seriously broken.\n");
         return ret;
     }
     g_process.root = dent;
@@ -147,7 +147,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) {
-            debug("Sending child death signal failed: %d!\n", x);
+            log_error("Sending child death signal failed: %d!\n", x);
         }
     }
 

LibOS/shim/src/bookkeep/shim_signal.c

@@ -61,7 +61,7 @@ void thread_sigaction_reset_on_execve(void) {
 }
 
 static noreturn void sighandler_kill(int sig) {
-    debug("killed by signal %d\n", sig & ~__WCOREDUMP_BIT);
+    log_debug("killed by signal %d\n", sig & ~__WCOREDUMP_BIT);
     process_exit(0, sig);
 }
 
@@ -311,12 +311,12 @@ 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))
-        warn("%s at 0x%08lx (IP = +0x%lx, VMID = %u, TID = %u)\n", errstr, addr,
-             (void*)ip - (void*)&__load_address, g_process_ipc_info.vmid,
-             is_internal_tid(tid) ? 0 : tid);
+        log_error("%s at 0x%08lx (IP = +0x%lx, VMID = %u, TID = %u)\n", errstr, addr,
+                  (void*)ip - (void*)&__load_address, g_process_ipc_info.vmid,
+                  is_internal_tid(tid) ? 0 : tid);
     else
-        warn("%s at 0x%08lx (IP = 0x%08lx, VMID = %u, TID = %u)\n", errstr, addr,
-             context ? ip : 0, g_process_ipc_info.vmid, is_internal_tid(tid) ? 0 : tid);
+        log_error("%s at 0x%08lx (IP = 0x%08lx, VMID = %u, TID = %u)\n", errstr, addr,
+                  context ? ip : 0, g_process_ipc_info.vmid, is_internal_tid(tid) ? 0 : tid);
 
     DEBUG_BREAK_ON_FAILURE();
     DkProcessExit(1);
@@ -330,7 +330,7 @@ static void arithmetic_error_upcall(bool is_in_pal, PAL_NUM addr, PAL_CONTEXT* c
     if (is_internal_tid(get_cur_tid()) || context_is_libos(context)) {
         internal_fault("Internal arithmetic fault", addr, context);
     } else {
-        debug("arithmetic fault at 0x%08lx\n", pal_context_get_ip(context));
+        log_debug("arithmetic fault at 0x%08lx\n", pal_context_get_ip(context));
         siginfo_t info = {
             .si_signo = SIGFPE,
             .si_code = FPE_INTDIV,
@@ -361,7 +361,7 @@ static void memfault_upcall(bool is_in_pal, PAL_NUM addr, PAL_CONTEXT* context)
         internal_fault("Internal memory fault", addr, context);
     }
 
-    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)\n", addr, pal_context_get_ip(context));
 
     siginfo_t info = {
         .si_addr = (void*)addr,
@@ -590,7 +590,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);
-        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\n", rip);
         siginfo_t info = {
             .si_signo = SIGILL,
             .si_code = ILL_ILLOPC,
@@ -641,7 +641,7 @@ int init_signal_handling(void) {
     int ret = toml_int_in(g_manifest_root, "sys.enable_sigterm_injection", /*defaultval=*/0,
                           &allow_injection);
     if (ret < 0 || (allow_injection != 0 && allow_injection != 1)) {
-        debug("Cannot parse 'sys.enable_sigterm_injection' (the value must be 0 or 1)\n");
+        log_error("Cannot parse 'sys.enable_sigterm_injection' (the value must be 0 or 1)\n");
         return -EINVAL;
     }
     g_inject_host_signal_enabled = !!allow_injection;
@@ -650,7 +650,7 @@ int init_signal_handling(void) {
     ret = toml_int_in(g_manifest_root, "libos.check_invalid_pointers",
                       /*defaultval=*/1, &check_invalid_ptrs_int);
     if (ret < 0 || (check_invalid_ptrs_int != 0 && check_invalid_ptrs_int != 1)) {
-        debug("Cannot parse 'libos.check_invalid_pointers' (the value must be 0 or 1)\n");
+        log_error("Cannot parse 'libos.check_invalid_pointers' (the value must be 0 or 1)\n");
         return -EINVAL;
     }
     g_check_invalid_ptrs = !!check_invalid_ptrs_int;
@@ -902,13 +902,13 @@ int append_signal(struct shim_thread* thread, siginfo_t* info) {
         }
     }
 
-    debug("Signal %d queue of ", info->si_signo);
+    log_debug("Signal %d queue of ", info->si_signo);
     if (thread) {
-        debug("thread %u", thread->tid);
+        log_debug("thread %u", thread->tid);
     } else {
-        debug("process");
+        log_debug("process");
     }
-    debug(" is full, dropping the incoming signal\n");
+    log_debug(" is full, dropping the incoming signal\n");
     /* This is counter-intuitive, but we report success here: after all signal was successfully
      * delivered, just the queue was full. */
 out:

LibOS/shim/src/bookkeep/shim_thread.c

@@ -36,7 +36,7 @@ static IDTYPE g_internal_tid_alloc_idx = INTERNAL_TID_BASE;
 //#define DEBUG_REF
 
 #ifdef DEBUG_REF
-#define DEBUG_PRINT_REF_COUNT(rc) debug("%s %p ref_count = %d\n", __func__, dispositions, rc)
+#define DEBUG_PRINT_REF_COUNT(rc) log_debug("%s %p ref_count = %d\n", __func__, dispositions, rc)
 #else
 #define DEBUG_PRINT_REF_COUNT(rc) __UNUSED(rc)
 #endif
@@ -166,7 +166,7 @@ static int init_main_thread(void) {
 
     cur_thread->tid = get_new_tid();
     if (!cur_thread->tid) {
-        debug("Cannot allocate pid for the initial thread!\n");
+        log_error("Cannot allocate pid for the initial thread!\n");
         put_thread(cur_thread);
         return -ESRCH;
     }
@@ -255,7 +255,7 @@ struct shim_thread* get_new_thread(void) {
 
     thread->tid = get_new_tid();
     if (!thread->tid) {
-        debug("get_new_thread: could not allocate a tid!\n");
+        log_error("get_new_thread: could not allocate a tid!\n");
         put_thread(thread);
         return NULL;
     }
@@ -344,8 +344,8 @@ 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) {
-                debug("[put_thread] Failed to remove bookkeeped memory at %p-%p!\n",
-                      addr, (char*)addr + SHIM_THREAD_LIBOS_STACK_SIZE);
+                log_error("[put_thread] Failed to remove bookkeeped memory at %p-%p!\n",
+                          addr, (char*)addr + SHIM_THREAD_LIBOS_STACK_SIZE);
                 BUG();
             }
             DkVirtualMemoryFree(addr, SHIM_THREAD_LIBOS_STACK_SIZE);