diff --git a/LibOS/shim/include/shim_checkpoint.h b/LibOS/shim/include/shim_checkpoint.h index 6ba776c983..f5820e0a32 100644 --- a/LibOS/shim/include/shim_checkpoint.h +++ b/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); \ diff --git a/LibOS/shim/include/shim_internal.h b/LibOS/shim/include/shim_internal.h index 324a399bac..cff57dabd0 100644 --- a/LibOS/shim/include/shim_internal.h +++ b/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; } diff --git a/LibOS/shim/include/shim_lock.h b/LibOS/shim/include/shim_lock.h index a04ad6ad1e..5d03b97738 100644 --- a/LibOS/shim/include/shim_lock.h +++ b/LibOS/shim/include/shim_lock.h @@ -40,23 +40,12 @@ 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 */; @@ -64,22 +53,12 @@ static void lock(struct shim_lock* l) { 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 diff --git a/LibOS/shim/src/bookkeep/shim_handle.c b/LibOS/shim/src/bookkeep/shim_handle.c index a52df2fa0a..17ed85f70a 100644 --- a/LibOS/shim/src/bookkeep/shim_handle.c +++ b/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; diff --git a/LibOS/shim/src/bookkeep/shim_process.c b/LibOS/shim/src/bookkeep/shim_process.c index bced8a124f..c3c0ae3a51 100644 --- a/LibOS/shim/src/bookkeep/shim_process.c +++ b/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); } } diff --git a/LibOS/shim/src/bookkeep/shim_signal.c b/LibOS/shim/src/bookkeep/shim_signal.c index d5530393cc..322a70006d 100644 --- a/LibOS/shim/src/bookkeep/shim_signal.c +++ b/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: diff --git a/LibOS/shim/src/bookkeep/shim_thread.c b/LibOS/shim/src/bookkeep/shim_thread.c index b2e9e5535e..42d1bf7317 100644 --- a/LibOS/shim/src/bookkeep/shim_thread.c +++ b/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); diff --git a/LibOS/shim/src/bookkeep/shim_vma.c b/LibOS/shim/src/bookkeep/shim_vma.c index 28f3184cca..3fd6595376 100644 --- a/LibOS/shim/src/bookkeep/shim_vma.c +++ b/LibOS/shim/src/bookkeep/shim_vma.c @@ -221,9 +221,9 @@ static int _vma_bkeep_remove(uintptr_t begin, uintptr_t end, bool is_internal, while (vma && vma->begin < end) { if (!!(vma->flags & VMA_INTERNAL) != is_internal) { if (is_internal) { - debug("Warning: LibOS tried to free a user vma!\n"); + log_warning("Warning: LibOS tried to free a user vma!\n"); } else { - debug("Warning: user app tried to free an internal vma!\n"); + log_warning("Warning: user app tried to free an internal vma!\n"); } return -EACCES; } @@ -236,7 +236,7 @@ static int _vma_bkeep_remove(uintptr_t begin, uintptr_t end, bool is_internal, if (vma->begin < begin) { if (end < vma->end) { if (!new_vma_ptr) { - debug("Warning: need an additional vma to free this range!\n"); + log_warning("Warning: need an additional vma to free this range!\n"); return -ENOMEM; } struct shim_vma* new_vma = *new_vma_ptr; @@ -304,7 +304,7 @@ static void* _vma_malloc(size_t size) { NULL, &vmas_to_free); spinlock_unlock(&vma_tree_lock); if (ret < 0) { - debug("Removing a vma we just created failed with %d!\n", ret); + log_error("Removing a vma we just created failed with %d!\n", ret); BUG(); } @@ -442,7 +442,7 @@ static struct shim_vma* alloc_vma(void) { struct shim_vma tmp_vma = {0}; /* vma cache is empty, as we checked it before. */ if (!add_to_thread_vma_cache(&tmp_vma)) { - debug("Failed to add tmp vma to cache!\n"); + log_error("Failed to add tmp vma to cache!\n"); BUG(); } if (!enlarge_mem_mgr(vma_mgr, size_align_up(DEFAULT_VMA_COUNT))) { @@ -452,7 +452,7 @@ static struct shim_vma* alloc_vma(void) { struct shim_vma* vma_migrate = get_mem_obj_from_mgr(vma_mgr); if (!vma_migrate) { - debug("Failed to allocate a vma right after enlarge_mem_mgr!\n"); + log_error("Failed to allocate a vma right after enlarge_mem_mgr!\n"); BUG(); } @@ -554,24 +554,24 @@ int init_vma(void) { assert(init_vmas[i].begin <= init_vmas[i].end); /* Skip empty areas. */ if (init_vmas[i].begin == init_vmas[i].end) { - debug("Skipping bookkeeping of empty region at 0x%lx (comment: \"%s\")\n", - init_vmas[i].begin, init_vmas[i].comment); + log_debug("Skipping bookkeeping of empty region at 0x%lx (comment: \"%s\")\n", + init_vmas[i].begin, init_vmas[i].comment); continue; } if (!IS_ALLOC_ALIGNED(init_vmas[i].begin) || !IS_ALLOC_ALIGNED(init_vmas[i].end)) { - debug("Unaligned VMA region: 0x%lx-0x%lx (%s)\n", init_vmas[i].begin, init_vmas[i].end, - init_vmas[i].comment); + log_error("Unaligned VMA region: 0x%lx-0x%lx (%s)\n", init_vmas[i].begin, + init_vmas[i].end, init_vmas[i].comment); ret = -EINVAL; break; } ret = _bkeep_initial_vma(&init_vmas[i]); if (ret < 0) { - debug("Failed to bookkeep initial VMA region 0x%lx-0x%lx (%s)\n", init_vmas[i].begin, - init_vmas[i].end, init_vmas[i].comment); + log_error("Failed to bookkeep initial VMA region 0x%lx-0x%lx (%s)\n", + init_vmas[i].begin, init_vmas[i].end, init_vmas[i].comment); break; } - debug("Initial VMA region 0x%lx-0x%lx (%s) bookkeeped\n", init_vmas[i].begin, - init_vmas[i].end, init_vmas[i].comment); + log_debug("Initial VMA region 0x%lx-0x%lx (%s) bookkeeped\n", init_vmas[i].begin, + init_vmas[i].end, init_vmas[i].comment); } spinlock_unlock(&vma_tree_lock); /* From now on if we return with an error we might leave a structure local to this function in @@ -600,20 +600,20 @@ int init_vma(void) { gap = ALLOC_ALIGN_DOWN(gap % gap_max_size); g_aslr_addr_top = (char*)g_aslr_addr_top - gap; - debug("ASLR top address adjusted to %p\n", g_aslr_addr_top); + log_debug("ASLR top address adjusted to %p\n", g_aslr_addr_top); } else { - debug("Not enough space to make meaningful address space randomization.\n"); + log_warning("Not enough space to make meaningful address space randomization.\n"); } } /* We need 1 vma to create the memmgr. */ if (!add_to_thread_vma_cache(&init_vmas[0])) { - debug("Failed to add tmp vma to cache!\n"); + log_error("Failed to add tmp vma to cache!\n"); BUG(); } vma_mgr = create_mem_mgr(DEFAULT_VMA_COUNT); if (!vma_mgr) { - debug("Failed to create VMA memory manager!\n"); + log_error("Failed to create VMA memory manager!\n"); return -ENOMEM; } @@ -1321,7 +1321,7 @@ BEGIN_RS_FUNC(vma) { } if (need_mapped < vma->addr + vma->length) { - debug("vma %p-%p cannot be allocated!\n", need_mapped, vma->addr + vma->length); + log_error("vma %p-%p cannot be allocated!\n", need_mapped, vma->addr + vma->length); return -ENOMEM; } } @@ -1359,16 +1359,16 @@ END_CP_FUNC_NO_RS(all_vmas) static void debug_print_vma(struct shim_vma* vma) { - debug("[0x%lx-0x%lx] prot=0x%x flags=0x%x%s%s file=%p (offset=%ld)%s%s\n", - vma->begin, vma->end, - vma->prot, - vma->flags & ~(VMA_INTERNAL | VMA_UNMAPPED), - vma->flags & VMA_INTERNAL ? "(INTERNAL " : "(", - vma->flags & VMA_UNMAPPED ? "UNMAPPED)" : ")", - vma->file, - vma->offset, - vma->comment[0] ? " comment=" : "", - vma->comment[0] ? vma->comment : ""); + log_debug("[0x%lx-0x%lx] prot=0x%x flags=0x%x%s%s file=%p (offset=%ld)%s%s\n", + vma->begin, vma->end, + vma->prot, + vma->flags & ~(VMA_INTERNAL | VMA_UNMAPPED), + vma->flags & VMA_INTERNAL ? "(INTERNAL " : "(", + vma->flags & VMA_UNMAPPED ? "UNMAPPED)" : ")", + vma->file, + vma->offset, + vma->comment[0] ? " comment=" : "", + vma->comment[0] ? vma->comment : ""); } void debug_print_all_vmas(void) { diff --git a/LibOS/shim/src/elf/shim_rtld.c b/LibOS/shim/src/elf/shim_rtld.c index 59750d8f3c..723cab8413 100644 --- a/LibOS/shim/src/elf/shim_rtld.c +++ b/LibOS/shim/src/elf/shim_rtld.c @@ -455,7 +455,7 @@ static struct link_map* __map_elf_object(struct shim_handle* file, const void* f call_lose: free(new_phdr); - debug("loading %s: %s\n", l->l_name, errstring); + log_debug("loading %s: %s\n", l->l_name, errstring); free(l); return NULL; } @@ -505,7 +505,7 @@ static int __remove_elf_object(struct link_map* l) { } static int __free_elf_object(struct link_map* l) { - debug("removing %s as runtime object loaded at 0x%08lx\n", l->l_name, l->l_map_start); + log_debug("removing %s as runtime object loaded at 0x%08lx\n", l->l_name, l->l_map_start); struct loadcmd* c = l->loadcmds; @@ -595,7 +595,7 @@ static int __check_elf_header(void* fbp, size_t len) { return 0; verify_failed: - debug("load runtime object: %s\n", errstring); + log_debug("load runtime object: %s\n", errstring); return -EINVAL; } @@ -649,7 +649,7 @@ int load_elf_object(struct shim_handle* file) { if (!file) return -EINVAL; - debug("loading \"%s\"\n", file ? qstrgetstr(&file->uri) : "(unknown)"); + log_debug("loading \"%s\"\n", file ? qstrgetstr(&file->uri) : "(unknown)"); return __load_elf_object(file, NULL, OBJECT_LOAD); } @@ -759,7 +759,7 @@ static int __load_interp_object(struct link_map* exec_map) { interp_path[plen] = '/'; memcpy(interp_path + plen + 1, filename, len + 1); - debug("search interpreter: %s\n", interp_path); + log_debug("searching for interpreter: %s\n", interp_path); struct shim_dentry* dent = NULL; int ret = 0; @@ -899,10 +899,10 @@ int init_loader(void) { ret = load_elf_object(exec); if (ret < 0) { // TODO: Actually verify that the non-PIE-ness was the real cause of loading failure. - warn("ERROR: Failed to load %s. This may be caused by the binary being non-PIE, in " - "which case Graphene requires a specially-crafted memory layout. You can enable " - "it by adding 'sgx.nonpie_binary = 1' to the manifest.\n", - qstrgetstr(&exec->path)); + log_error("ERROR: Failed to load %s. This may be caused by the binary being non-PIE, " + "in which case Graphene requires a specially-crafted memory layout. You can " + "enable it by adding 'sgx.nonpie_binary = 1' to the manifest.\n", + qstrgetstr(&exec->path)); goto out; } @@ -939,7 +939,7 @@ int init_brk_from_executable(struct shim_handle* exec) { } int register_library(const char* name, unsigned long load_address) { - debug("glibc register library %s loaded at 0x%08lx\n", name, load_address); + log_debug("glibc register library %s loaded at 0x%08lx\n", name, load_address); struct shim_handle* hdl = get_new_handle(); @@ -960,7 +960,7 @@ int register_library(const char* name, unsigned long load_address) { noreturn void execute_elf_object(struct shim_handle* exec, void* argp, ElfW(auxv_t)* auxp) { int ret = vdso_map_init(); if (ret < 0) { - warn("Could not initialize vDSO (error code = %d)", ret); + log_error("Could not initialize vDSO (error code = %d)", ret); process_exit(/*error_code=*/0, /*term_signal=*/SIGKILL); } @@ -1016,7 +1016,7 @@ noreturn void execute_elf_object(struct shim_handle* exec, void* argp, ElfW(auxv ElfW(Addr) random = auxp_extra; /* random 16B for AT_RANDOM */ ret = DkRandomBitsRead((PAL_PTR)random, 16); if (ret < 0) { - debug("execute_elf_object: DkRandomBitsRead failed.\n"); + log_error("execute_elf_object: DkRandomBitsRead failed.\n"); DkThreadExit(/*clear_child_tid=*/NULL); /* UNREACHABLE */ } diff --git a/LibOS/shim/src/fs/pipe/fs.c b/LibOS/shim/src/fs/pipe/fs.c index fe9d1e3119..426c2a61e9 100644 --- a/LibOS/shim/src/fs/pipe/fs.c +++ b/LibOS/shim/src/fs/pipe/fs.c @@ -51,7 +51,7 @@ static ssize_t pipe_write(struct shim_handle* hdl, const void* buf, size_t count .si_code = SI_USER, }; if (kill_current_proc(&info) < 0) { - debug("pipe_write: failed to deliver a signal\n"); + log_error("pipe_write: failed to deliver a signal\n"); } } return -err; @@ -171,8 +171,8 @@ static int fifo_open(struct shim_handle* hdl, struct shim_dentry* dent, int flag /* POSIX disallows FIFOs opened for read-write, but Linux allows it. We must choose only * one end (read or write) in our emulation, so we treat such FIFOs as read-only. This * covers most apps seen in the wild (in particular, LTP apps). */ - debug("FIFO (named pipe) '%s' cannot be opened in read-write mode in Graphene. " - "Treating it as read-only.", qstrgetstr(&dent->fs->path)); + log_warning("FIFO (named pipe) '%s' cannot be opened in read-write mode in Graphene. " + "Treating it as read-only.", qstrgetstr(&dent->fs->path)); flags = O_RDONLY; } diff --git a/LibOS/shim/src/fs/shim_dcache.c b/LibOS/shim/src/fs/shim_dcache.c index 5a252b71b5..f80783bdb7 100644 --- a/LibOS/shim/src/fs/shim_dcache.c +++ b/LibOS/shim/src/fs/shim_dcache.c @@ -92,8 +92,8 @@ void get_dentry(struct shim_dentry* dent) { #ifdef DEBUG_REF int count = REF_INC(dent->ref_count); - debug("get dentry %p(%s/%s) (ref_count = %d)\n", dent, - dent->fs ? qstrgetstr(&dent->fs->path) : "", qstrgetstr(&dent->rel_path), count); + log_debug("get dentry %p(%s/%s) (ref_count = %d)\n", dent, + dent->fs ? qstrgetstr(&dent->fs->path) : "", qstrgetstr(&dent->rel_path), count); #else REF_INC(dent->ref_count); #endif diff --git a/LibOS/shim/src/fs/shim_fs.c b/LibOS/shim/src/fs/shim_fs.c index 157a0c2832..f50a2bca8b 100644 --- a/LibOS/shim/src/fs/shim_fs.c +++ b/LibOS/shim/src/fs/shim_fs.c @@ -102,28 +102,28 @@ static int __mount_root(struct shim_dentry** root) { ret = toml_string_in(g_manifest_root, "fs.root.type", &fs_root_type); if (ret < 0) { - debug("Cannot parse 'fs.root.type' (the value must be put in double quotes!)\n"); + log_error("Cannot parse 'fs.root.type' (the value must be put in double quotes!)\n"); ret = -EINVAL; goto out; } ret = toml_string_in(g_manifest_root, "fs.root.uri", &fs_root_uri); if (ret < 0) { - debug("Cannot parse 'fs.root.uri' (the value must be put in double quotes!)\n"); + log_error("Cannot parse 'fs.root.uri' (the value must be put in double quotes!)\n"); ret = -EINVAL; goto out; } if (fs_root_type && fs_root_uri) { - debug("Mounting root as %s filesystem: from %s to /\n", fs_root_type, fs_root_uri); + log_debug("Mounting root as %s filesystem: from %s to /\n", fs_root_type, fs_root_uri); if ((ret = mount_fs(fs_root_type, fs_root_uri, "/", NULL, root, 0)) < 0) { - debug("Mounting root filesystem failed (%d)\n", ret); + log_error("Mounting root filesystem failed (%d)\n", ret); goto out; } } else { - debug("Mounting root as chroot filesystem: from file:. to /\n"); + log_debug("Mounting root as chroot filesystem: from file:. to /\n"); if ((ret = mount_fs("chroot", URI_PREFIX_FILE, "/", NULL, root, 0)) < 0) { - debug("Mounting root filesystem failed (%d)\n", ret); + log_error("Mounting root filesystem failed (%d)\n", ret); goto out; } } @@ -138,29 +138,29 @@ static int __mount_root(struct shim_dentry** root) { static int __mount_sys(struct shim_dentry* root) { int ret; - debug("Mounting special proc filesystem: /proc\n"); + log_debug("Mounting special proc filesystem: /proc\n"); if ((ret = mount_fs("proc", NULL, "/proc", root, NULL, 0)) < 0) { - debug("Mounting /proc filesystem failed (%d)\n", ret); + log_error("Mounting /proc filesystem failed (%d)\n", ret); return ret; } - debug("Mounting special dev filesystem: /dev\n"); + log_debug("Mounting special dev filesystem: /dev\n"); struct shim_dentry* dev_dent = NULL; if ((ret = mount_fs("dev", NULL, "/dev", root, &dev_dent, 0)) < 0) { - debug("Mounting dev filesystem failed (%d)\n", ret); + log_error("Mounting dev filesystem failed (%d)\n", ret); return ret; } - debug("Mounting terminal device /dev/tty under /dev\n"); + log_debug("Mounting terminal device /dev/tty under /dev\n"); if ((ret = mount_fs("chroot", URI_PREFIX_DEV "tty", "/dev/tty", dev_dent, NULL, 0)) < 0) { - debug("Mounting terminal device /dev/tty failed (%d)\n", ret); + log_error("Mounting terminal device /dev/tty failed (%d)\n", ret); return ret; } - debug("Mounting special sys filesystem: /sys\n"); + log_debug("Mounting special sys filesystem: /sys\n"); if ((ret = mount_fs("sys", NULL, "/sys", root, NULL, 0)) < 0) { - debug("Mounting sys filesystem failed (%d)\n", ret); + log_error("Mounting sys filesystem failed (%d)\n", ret); return ret; } @@ -175,19 +175,19 @@ static int __mount_one_other(toml_table_t* mount) { toml_raw_t mount_type_raw = toml_raw_in(mount, "type"); if (!mount_type_raw) { - debug("Cannot find 'fs.mount.%s.type'\n", key); + log_error("Cannot find 'fs.mount.%s.type'\n", key); return -EINVAL; } toml_raw_t mount_path_raw = toml_raw_in(mount, "path"); if (!mount_path_raw) { - debug("Cannot find 'fs.mount.%s.path'\n", key); + log_error("Cannot find 'fs.mount.%s.path'\n", key); return -EINVAL; } toml_raw_t mount_uri_raw = toml_raw_in(mount, "uri"); if (!mount_uri_raw) { - debug("Cannot find 'fs.mount.%s.uri'\n", key); + log_error("Cannot find 'fs.mount.%s.uri'\n", key); return -EINVAL; } @@ -197,44 +197,48 @@ static int __mount_one_other(toml_table_t* mount) { ret = toml_rtos(mount_type_raw, &mount_type); if (ret < 0) { - debug("Cannot parse 'fs.mount.%s.type' (the value must be put in double quotes!)\n", key); + log_error("Cannot parse 'fs.mount.%s.type' (the value must be put in double quotes!)\n", + key); ret = -EINVAL; goto out; } ret = toml_rtos(mount_path_raw, &mount_path); if (ret < 0) { - debug("Cannot parse 'fs.mount.%s.path' (the value must be put in double quotes!)\n", key); + log_error("Cannot parse 'fs.mount.%s.path' (the value must be put in double quotes!)\n", + key); ret = -EINVAL; goto out; } ret = toml_rtos(mount_uri_raw, &mount_uri); if (ret < 0) { - debug("Cannot parse 'fs.mount.%s.uri' (the value must be put in double quotes!)\n", key); + log_error("Cannot parse 'fs.mount.%s.uri' (the value must be put in double quotes!)\n", + key); ret = -EINVAL; goto out; } - debug("Mounting as %s filesystem: from %s to %s\n", mount_type, mount_uri, mount_path); + log_debug("Mounting as %s filesystem: from %s to %s\n", mount_type, mount_uri, mount_path); if (!strcmp(mount_path, "/")) { - debug("Root mount / already exists, verify that there are no duplicate mounts in manifest\n" - "(note that root / is automatically mounted in Graphene and can be changed via " - "'fs.root' manifest entry).\n"); + log_error( + "Root mount / already exists, verify that there are no duplicate mounts in manifest\n" + "(note that root / is automatically mounted in Graphene and can be changed via " + "'fs.root' manifest entry).\n"); ret = -EEXIST; goto out; } if (!strcmp(mount_path, ".") || !strcmp(mount_path, "..")) { - debug("Mount points '.' and '..' are not allowed, remove them from manifest.\n"); + log_error("Mount points '.' and '..' are not allowed, remove them from manifest.\n"); ret = -EINVAL; goto out; } if ((ret = mount_fs(mount_type, mount_uri, mount_path, NULL, NULL, 1)) < 0) { - debug("Mounting %s on %s (type=%s) failed (%d)\n", mount_uri, mount_path, mount_type, - -ret); + log_error("Mounting %s on %s (type=%s) failed (%d)\n", mount_uri, mount_path, mount_type, + -ret); goto out; } @@ -304,7 +308,8 @@ int init_mount(void) { char* fs_start_dir = NULL; ret = toml_string_in(g_manifest_root, "fs.start_dir", &fs_start_dir); if (ret < 0) { - debug("Can't parse 'fs.start_dir' (note that the value must be put in double quotes)!\n"); + log_error("Can't parse 'fs.start_dir' (note that the value must be put in double quotes)!" + "\n"); return ret; } @@ -313,7 +318,7 @@ int init_mount(void) { ret = path_lookupat(NULL, fs_start_dir, 0, &dent, NULL); free(fs_start_dir); if (ret < 0) { - debug("Invalid 'fs.start_dir' in manifest.\n"); + log_error("Invalid 'fs.start_dir' in manifest.\n"); return ret; } lock(&g_process.fs_lock); @@ -485,7 +490,7 @@ int mount_fs(const char* type, const char* uri, const char* mount_point, struct parent_path[parent_len] = 0; if ((ret = __path_lookupat(dentry_root, parent_path, 0, &parent, 0, dentry_root->fs, make_ancestor)) < 0) { - debug("Path lookup failed %d\n", ret); + log_error("Path lookup failed %d\n", ret); goto out_with_unlock; } need_parent_put = true; @@ -496,7 +501,7 @@ int mount_fs(const char* type, const char* uri, const char* mount_point, struct /* Newly created dentry's relative path will be a concatenation of parent * + last strings (see get_new_dentry), make sure it fits into qstr */ if (parent->rel_path.len + 1 + last_len >= STR_SIZE) { /* +1 for '/' */ - debug("Relative path exceeds the limit %d\n", STR_SIZE); + log_error("Relative path exceeds the limit %d\n", STR_SIZE); ret = -ENAMETOOLONG; goto out_with_unlock; } @@ -532,8 +537,9 @@ int mount_fs(const char* type, const char* uri, const char* mount_point, struct } if (dent != dentry_root && dent->state & DENTRY_VALID) { - debug("Mount %s already exists, verify that there are no duplicate mounts in manifest\n" - "(note that /proc and /dev are automatically mounted in Graphene).\n", mount_point); + log_error("Mount %s already exists, verify that there are no duplicate mounts in manifest\n" + "(note that /proc and /dev are automatically mounted in Graphene).\n", + mount_point); ret = -EEXIST; goto out_with_unlock; } diff --git a/LibOS/shim/src/fs/shim_namei.c b/LibOS/shim/src/fs/shim_namei.c index 6accee6256..8e5e589696 100644 --- a/LibOS/shim/src/fs/shim_namei.c +++ b/LibOS/shim/src/fs/shim_namei.c @@ -143,7 +143,7 @@ int lookup_dentry(struct shim_dentry* parent, const char* name, int namelen, /* Newly created dentry's relative path will be a concatenation of parent * + name strings (see get_new_dentry), make sure it fits into qstr */ if (parent->rel_path.len + 1 + namelen >= STR_SIZE) { /* +1 for '/' */ - debug("Relative path exceeds the limit %d\n", STR_SIZE); + log_error("Relative path exceeds the limit %d\n", STR_SIZE); err = -ENAMETOOLONG; goto out; } diff --git a/LibOS/shim/src/fs/socket/fs.c b/LibOS/shim/src/fs/socket/fs.c index 3a7ec5d052..7c3408b799 100644 --- a/LibOS/shim/src/fs/socket/fs.c +++ b/LibOS/shim/src/fs/socket/fs.c @@ -92,7 +92,7 @@ static ssize_t socket_write(struct shim_handle* hdl, const void* buf, size_t cou .si_code = SI_USER, }; if (kill_current_proc(&info) < 0) { - debug("socket_write: failed to deliver a signal\n"); + log_error("socket_write: failed to deliver a signal\n"); } } @@ -190,7 +190,7 @@ static off_t socket_poll(struct shim_handle* hdl, int poll_type) { out: if (ret < 0) { - debug("socket_poll failed (%ld)\n", ret); + log_error("socket_poll failed (%ld)\n", ret); sock->error = -ret; } diff --git a/LibOS/shim/src/fs/str/fs.c b/LibOS/shim/src/fs/str/fs.c index 6120c4aa91..cc04ef1781 100644 --- a/LibOS/shim/src/fs/str/fs.c +++ b/LibOS/shim/src/fs/str/fs.c @@ -85,7 +85,7 @@ ssize_t str_read(struct shim_handle* hdl, void* buf, size_t count) { struct shim_str_data* data = strhdl->data; if (!data->str) { - debug("str_data has no str\n"); + log_error("str_data has no str\n"); ret = -EACCES; goto out; } diff --git a/LibOS/shim/src/fs/sys/cache_info.c b/LibOS/shim/src/fs/sys/cache_info.c index da4a42a2da..e712cdb165 100644 --- a/LibOS/shim/src/fs/sys/cache_info.c +++ b/LibOS/shim/src/fs/sys/cache_info.c @@ -44,7 +44,7 @@ static int cache_info_open(struct shim_handle* hdl, const char* name, int flags) } else if (!strcmp(filename, "physical_line_partition")) { cache_filebuf = pal_control.topo_info.core_topology[cpunum].cache[idx].physical_line_partition; } else { - debug("Unrecognized file %s\n", name); + log_debug("Unrecognized file %s\n", name); return -ENOENT; } diff --git a/LibOS/shim/src/fs/sys/cpu_info.c b/LibOS/shim/src/fs/sys/cpu_info.c index ada2664103..79d3c84110 100644 --- a/LibOS/shim/src/fs/sys/cpu_info.c +++ b/LibOS/shim/src/fs/sys/cpu_info.c @@ -51,7 +51,7 @@ static int cpu_info_open(struct shim_handle* hdl, const char* name, int flags) { } else if (!strcmp(filename, "thread_siblings")) { cpu_filebuf = pal_control.topo_info.core_topology[cpunum].thread_siblings; } else { - debug("Unrecognized file %s\n", name); + log_debug("Unrecognized file %s\n", name); return -ENOENT; } } diff --git a/LibOS/shim/src/fs/sys/fs.c b/LibOS/shim/src/fs/sys/fs.c index 02fb01ad21..5ad2bbd0a4 100644 --- a/LibOS/shim/src/fs/sys/fs.c +++ b/LibOS/shim/src/fs/sys/fs.c @@ -83,14 +83,14 @@ int sys_match_resource_num(const char* pathname) { } totalcnt = pal_control.topo_info.num_cache_index; } else { - debug("Invalid resource %s in file %s!", token, pathname); + log_debug("Invalid resource %s in file %s!", token, pathname); ret = 0; goto out; } /* sysfs resources like NUMA nodes, CPU cores, CPU caches have indexes from 0 to totalcnt - 1 */ if (num >= totalcnt) { - debug("Incorrect index %d in file %s (max supported is %d)\n", num, pathname, totalcnt); + log_debug("Incorrect index %d in file %s (max supported is %d)\n", num, pathname, totalcnt); ret = 0; goto out; } @@ -116,7 +116,7 @@ int sys_list_resource_num(const char* pathname, struct shim_dirent** buf, size_t } else if (!strcmp(filename, "cpu")) { totalcnt = pal_control.cpu_info.online_logical_cores; } else { - debug("Invalid resource name in file %s\n", pathname); + log_debug("Invalid resource name in file %s\n", pathname); return -EINVAL; } diff --git a/LibOS/shim/src/fs/sys/node_info.c b/LibOS/shim/src/fs/sys/node_info.c index 36ff88811d..c587ea69b6 100644 --- a/LibOS/shim/src/fs/sys/node_info.c +++ b/LibOS/shim/src/fs/sys/node_info.c @@ -39,7 +39,7 @@ static int node_info_open(struct shim_handle* hdl, const char* name, int flags) node_filebuf = pal_control.topo_info.numa_topology[nodenum].hugepages[HUGEPAGES_1G].nr_hugepages; } else { - debug("Unrecognized file %s\n", name); + log_debug("Unrecognized file %s\n", name); return -ENOENT; } } diff --git a/LibOS/shim/src/ipc/shim_ipc.c b/LibOS/shim/src/ipc/shim_ipc.c index 8b7ef091e4..ce0021ee8d 100644 --- a/LibOS/shim/src/ipc/shim_ipc.c +++ b/LibOS/shim/src/ipc/shim_ipc.c @@ -252,7 +252,7 @@ int send_ipc_message(struct shim_ipc_msg* msg, struct shim_ipc_port* port) { assert(msg->size >= IPC_MSG_MINIMAL_SIZE); msg->src = g_process_ipc_info.vmid; - debug("Sending ipc message to port %p (handle %p)\n", port, port->pal_handle); + log_debug("Sending ipc message to port %p (handle %p)\n", port, port->pal_handle); size_t total_bytes = msg->size; size_t bytes = 0; @@ -265,7 +265,7 @@ int send_ipc_message(struct shim_ipc_msg* msg, struct shim_ipc_port* port) { if (PAL_ERRNO() == EINTR || PAL_ERRNO() == EAGAIN || PAL_ERRNO() == EWOULDBLOCK) continue; - debug("Port %p (handle %p) was removed during sending\n", port, port->pal_handle); + log_debug("Port %p (handle %p) was removed during sending\n", port, port->pal_handle); del_ipc_port_fini(port); return -PAL_ERRNO(); } @@ -321,7 +321,7 @@ int send_ipc_message_with_ack(struct shim_ipc_msg_with_ack* msg, struct shim_ipc if (seq) *seq = msg->msg.seq; - debug("Waiting for response (seq = %lu)\n", msg->msg.seq); + log_debug("Waiting for response (seq = %lu)\n", msg->msg.seq); /* force thread which will send the message to wait for response; * ignore unrelated interrupts but fail on actual errors */ @@ -331,7 +331,7 @@ int send_ipc_message_with_ack(struct shim_ipc_msg_with_ack* msg, struct shim_ipc goto out; } while (ret != 0); - debug("Finished waiting for response (seq = %lu, ret = %d)\n", msg->msg.seq, msg->retval); + log_debug("Finished waiting for response (seq = %lu, ret = %d)\n", msg->msg.seq, msg->retval); ret = msg->retval; out: lock(&port->msgs_lock); diff --git a/LibOS/shim/src/ipc/shim_ipc_child.c b/LibOS/shim/src/ipc/shim_ipc_child.c index b306e7b27c..a2682cda7b 100644 --- a/LibOS/shim/src/ipc/shim_ipc_child.c +++ b/LibOS/shim/src/ipc/shim_ipc_child.c @@ -29,9 +29,9 @@ void ipc_port_with_child_fini(struct shim_ipc_port* port, IDTYPE vmid) { * killed by SIGKILL. */ if (mark_child_exited_by_vmid(vmid, /*uid=*/0, /*exit_code=*/0, SIGKILL)) { - debug("Child process (vmid: 0x%x) got disconnected\n", vmid); + log_debug("Child process (vmid: 0x%x) got disconnected\n", vmid); } else { - debug("Unknown process (vmid: 0x%x) disconnected\n", vmid); + log_debug("Unknown process (vmid: 0x%x) disconnected\n", vmid); } } @@ -78,16 +78,16 @@ int ipc_cld_exit_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* port) __UNUSED(port); struct shim_ipc_cld_exit* msgin = (struct shim_ipc_cld_exit*)&msg->msg; - debug("IPC callback from %u: IPC_MSG_CHILDEXIT(%u, %u, %d, %u)\n", msg->src, + log_debug("IPC callback from %u: IPC_MSG_CHILDEXIT(%u, %u, %d, %u)\n", msg->src, msgin->ppid, msgin->pid, msgin->exitcode, msgin->term_signal); /* Message cannot come from our own process. */ assert(msg->src != g_process_ipc_info.vmid); if (mark_child_exited_by_pid(msgin->pid, msgin->uid, msgin->exitcode, msgin->term_signal)) { - debug("Child process (pid: %u) died\n", msgin->pid); + log_debug("Child process (pid: %u) died\n", msgin->pid); } else { - debug("Unknown process died, pid: %d\n", msgin->pid); + log_debug("Unknown process died, pid: %d\n", msgin->pid); } return 0; diff --git a/LibOS/shim/src/ipc/shim_ipc_helper.c b/LibOS/shim/src/ipc/shim_ipc_helper.c index 24dabfe8be..c73affcc40 100644 --- a/LibOS/shim/src/ipc/shim_ipc_helper.c +++ b/LibOS/shim/src/ipc/shim_ipc_helper.c @@ -138,7 +138,7 @@ static int init_ns_ipc_port(void) { lock(&g_process_ipc_info.lock); if (!g_process_ipc_info.ns->pal_handle) { - debug("Reconnecting IPC port %s\n", qstrgetstr(&g_process_ipc_info.ns->uri)); + log_debug("Reconnecting IPC port %s\n", qstrgetstr(&g_process_ipc_info.ns->uri)); g_process_ipc_info.ns->pal_handle = DkStreamOpen(qstrgetstr(&g_process_ipc_info.ns->uri), 0, 0, 0, 0); if (!g_process_ipc_info.ns->pal_handle) { @@ -285,7 +285,7 @@ static void __add_ipc_port(struct shim_ipc_port* port, IDTYPE vmid, IDTYPE type, static void __del_ipc_port(struct shim_ipc_port* port) { assert(locked(&ipc_helper_lock)); - debug("Deleting port %p (handle %p) of process %u\n", port, port->pal_handle, port->vmid); + log_debug("Deleting port %p (handle %p) of process %u\n", port, port->pal_handle, port->vmid); DkStreamDelete(port->pal_handle, 0); LISTP_DEL_INIT(port, &port_list, list); @@ -298,8 +298,8 @@ static void __del_ipc_port(struct shim_ipc_port* port) { LISTP_DEL_INIT(msg, &port->msgs, list); msg->retval = -ECONNRESET; if (msg->thread) { - debug("Deleted pending message on port %p, wake up blocking thread %d\n", port, - msg->thread->tid); + log_debug("Deleted pending message on port %p, wake up blocking thread %d\n", port, + msg->thread->tid); thread_wakeup(msg->thread); } } @@ -313,8 +313,8 @@ static void __del_ipc_port(struct shim_ipc_port* port) { } void add_ipc_port(struct shim_ipc_port* port, IDTYPE vmid, IDTYPE type, port_fini fini) { - debug("Adding port %p (handle %p) for process %u (type=%04x)\n", port, port->pal_handle, - port->vmid, type); + log_debug("Adding port %p (handle %p) for process %u (type=%04x)\n", port, port->pal_handle, + port->vmid, type); lock(&ipc_helper_lock); __add_ipc_port(port, vmid, type, fini); @@ -323,7 +323,7 @@ void add_ipc_port(struct shim_ipc_port* port, IDTYPE vmid, IDTYPE type, port_fin void add_ipc_port_by_id(IDTYPE vmid, PAL_HANDLE hdl, IDTYPE type, port_fini fini, struct shim_ipc_port** portptr) { - debug("Adding port (handle %p) for process %u (type %04x)\n", hdl, vmid, type); + log_debug("Adding port (handle %p) for process %u (type %04x)\n", hdl, vmid, type); struct shim_ipc_port* port = NULL; if (portptr) @@ -346,7 +346,7 @@ void add_ipc_port_by_id(IDTYPE vmid, PAL_HANDLE hdl, IDTYPE type, port_fini fini /* port does not yet exist, create it */ port = __create_ipc_port(hdl); if (!port) { - debug("Failed to create IPC port for handle %p\n", hdl); + log_error("Failed to create IPC port for handle %p\n", hdl); goto out; } } @@ -408,8 +408,8 @@ struct shim_ipc_port* lookup_ipc_port(IDTYPE vmid, IDTYPE type) { struct shim_ipc_port* tmp; LISTP_FOR_EACH_ENTRY(tmp, &port_list, list) { if (tmp->vmid == vmid && (tmp->type & type)) { - debug("Found port %p (handle %p) for process %u (type %04x)\n", tmp, tmp->pal_handle, - tmp->vmid, tmp->type); + log_debug("Found port %p (handle %p) for process %u (type %04x)\n", tmp, + tmp->pal_handle, tmp->vmid, tmp->type); port = tmp; __get_ipc_port(port); break; @@ -454,7 +454,7 @@ int broadcast_ipc(struct shim_ipc_msg* msg, int target_type, struct shim_ipc_por malloc(sizeof(struct shim_ipc_port*) * target_ports_cnt); if (!target_ports_heap) { unlock(&ipc_helper_lock); - debug("Allocation of target_ports_heap failed\n"); + log_error("Allocation of target_ports_heap failed\n"); return -ENOMEM; } @@ -477,14 +477,14 @@ int broadcast_ipc(struct shim_ipc_msg* msg, int target_type, struct shim_ipc_por for (size_t i = 0; i < target_ports_cnt; i++) { port = target_ports[i]; - debug("Broadcast to port %p (handle %p) for process %u (type %x, target %x)\n", port, - port->pal_handle, port->vmid, port->type, target_type); + log_debug("Broadcast to port %p (handle %p) for process %u (type %x, target %x)\n", port, + port->pal_handle, port->vmid, port->type, target_type); msg->dst = port->vmid; ret = send_ipc_message(msg, port); if (ret < 0) { - debug("Broadcast to port %p (handle %p) for process %u failed (errno = %d)!\n", port, - port->pal_handle, port->vmid, ret); + log_error("Broadcast to port %p (handle %p) for process %u failed (errno = %d)!\n", + port, port->pal_handle, port->vmid, ret); goto out; } } @@ -500,7 +500,7 @@ int broadcast_ipc(struct shim_ipc_msg* msg, int target_type, struct shim_ipc_por static int ipc_resp_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* port) { struct shim_ipc_resp* resp = (struct shim_ipc_resp*)&msg->msg; - debug("IPC callback from %u: IPC_MSG_RESP(%d)\n", msg->src, resp->retval); + log_debug("IPC callback from %u: IPC_MSG_RESP(%d)\n", msg->src, resp->retval); if (!msg->seq) return resp->retval; @@ -531,7 +531,7 @@ int send_response_ipc_message(struct shim_ipc_port* port, IDTYPE dest, int ret, struct shim_ipc_resp* resp = (struct shim_ipc_resp*)resp_msg->msg; resp->retval = ret; - debug("IPC send to %u: IPC_MSG_RESP(%d)\n", resp_msg->dst, ret); + log_debug("IPC send to %u: IPC_MSG_RESP(%d)\n", resp_msg->dst, ret); return send_ipc_message(resp_msg, port); } @@ -572,8 +572,8 @@ static int receive_ipc_message(struct shim_ipc_port* port) { if (err == EINTR || err == EAGAIN || err == EWOULDBLOCK) continue; - debug("Port %p (handle %p) closed while receiving IPC message\n", port, - port->pal_handle); + log_warning("Port %p (handle %p) closed while receiving IPC message\n", port, + port->pal_handle); del_ipc_port_fini(port); ret = -err; goto out; @@ -586,7 +586,7 @@ static int receive_ipc_message(struct shim_ipc_port* port) { expected_size = msg->size; } - debug( + log_debug( "Received IPC message from port %p (handle %p): code=%d size=%lu " "src=%u dst=%u seq=%lx\n", port, port->pal_handle, msg->code, msg->size, msg->src, msg->dst, msg->seq); @@ -600,8 +600,8 @@ static int receive_ipc_message(struct shim_ipc_port* port) { /* send IPC_MSG_RESP message to sender of this msg */ ret = send_response_ipc_message(port, msg->src, ret, msg->seq); if (ret < 0) { - debug("Sending IPC_MSG_RESP msg on port %p (handle %p) to %u failed\n", - port, port->pal_handle, msg->src); + log_error("Sending IPC_MSG_RESP msg on port %p (handle %p) to %u failed\n", + port, port->pal_handle, msg->src); ret = -PAL_ERRNO(); goto out; } @@ -657,19 +657,19 @@ noreturn static void shim_ipc_helper(void* dummy) { size_t ports_max_cnt = 32; struct shim_ipc_port** ports = malloc(sizeof(*ports) * ports_max_cnt); if (!ports) { - debug("shim_ipc_helper: allocation of ports failed\n"); + log_error("shim_ipc_helper: allocation of ports failed\n"); goto out_err; } PAL_HANDLE* pals = malloc(sizeof(*pals) * (1 + ports_max_cnt)); if (!pals) { - debug("shim_ipc_helper: allocation of pals failed\n"); + log_error("shim_ipc_helper: allocation of pals failed\n"); goto out_err; } /* allocate one memory region to hold two PAL_FLG arrays: events and revents */ PAL_FLG* pal_events = malloc(sizeof(*pal_events) * (1 + ports_max_cnt) * 2); if (!pal_events) { - debug("shim_ipc_helper: allocation of pal_events failed\n"); + log_error("shim_ipc_helper: allocation of pal_events failed\n"); goto out_err; } PAL_FLG* ret_events = pal_events + 1 + ports_max_cnt; @@ -704,17 +704,17 @@ noreturn static void shim_ipc_helper(void* dummy) { /* grow `ports` and `pals` to accommodate more objects */ struct shim_ipc_port** tmp_ports = malloc(sizeof(*tmp_ports) * ports_max_cnt * 2); if (!tmp_ports) { - debug("shim_ipc_helper: allocation of tmp_ports failed\n"); + log_error("shim_ipc_helper: allocation of tmp_ports failed\n"); goto out_err_unlock; } PAL_HANDLE* tmp_pals = malloc(sizeof(*tmp_pals) * (1 + ports_max_cnt * 2)); if (!tmp_pals) { - debug("shim_ipc_helper: allocation of tmp_pals failed\n"); + log_error("shim_ipc_helper: allocation of tmp_pals failed\n"); goto out_err_unlock; } PAL_FLG* tmp_pal_events = malloc(sizeof(*tmp_pal_events) * (2 + ports_max_cnt * 4)); if (!tmp_pal_events) { - debug("shim_ipc_helper: allocation of tmp_pal_events failed\n"); + log_error("shim_ipc_helper: allocation of tmp_pal_events failed\n"); goto out_err_unlock; } PAL_FLG* tmp_ret_events = tmp_pal_events + 1 + ports_max_cnt * 2; @@ -743,8 +743,8 @@ noreturn static void shim_ipc_helper(void* dummy) { ret_events[ports_cnt + 1] = 0; ports_cnt++; - debug("Listening to process %u on port %p (handle %p, type %04x)\n", port->vmid, port, - port->pal_handle, port->type); + log_debug("Listening to process %u on port %p (handle %p, type %04x)\n", port->vmid, + port, port->pal_handle, port->type); } unlock(&ipc_helper_lock); @@ -757,7 +757,7 @@ noreturn static void shim_ipc_helper(void* dummy) { if (ret_events[i]) { if (pals[i] == install_new_event_pal) { /* some thread wants to install new event; this event is found in `ports` */ - debug("New IPC event was requested (port was added/removed)\n"); + log_debug("New IPC event was requested (port was added/removed)\n"); continue; } @@ -774,8 +774,8 @@ noreturn static void shim_ipc_helper(void* dummy) { IPC_PORT_CONNECTION; add_ipc_port_by_id(polled_port->vmid, client, client_type, NULL, NULL); } else { - debug("Port %p (handle %p) was removed during accepting client\n", - polled_port, polled_port->pal_handle); + log_debug("Port %p (handle %p) was removed during accepting client\n", + polled_port, polled_port->pal_handle); del_ipc_port_fini(polled_port); } } else { @@ -787,13 +787,13 @@ noreturn static void shim_ipc_helper(void* dummy) { receive_ipc_message(polled_port); } if (attr.disconnected) { - debug("Port %p (handle %p) disconnected\n", polled_port, - polled_port->pal_handle); + log_debug("Port %p (handle %p) disconnected\n", polled_port, + polled_port->pal_handle); del_ipc_port_fini(polled_port); } } else { - debug("Port %p (handle %p) was removed during attr querying\n", polled_port, - polled_port->pal_handle); + log_debug("Port %p (handle %p) was removed during attr querying\n", + polled_port, polled_port->pal_handle); del_ipc_port_fini(polled_port); } } @@ -810,7 +810,7 @@ noreturn static void shim_ipc_helper(void* dummy) { free(pal_events); put_thread(self); - debug("IPC helper thread terminated\n"); + log_debug("IPC helper thread terminated\n"); DkThreadExit(/*clear_child_tid=*/NULL); /* UNREACHABLE */ @@ -818,7 +818,7 @@ noreturn static void shim_ipc_helper(void* dummy) { out_err_unlock: unlock(&ipc_helper_lock); out_err: - debug("Terminating the process due to a fatal error in ipc helper\n"); + log_error("Terminating the process due to a fatal error in ipc helper\n"); put_thread(self); DkProcessExit(1); } @@ -848,7 +848,7 @@ static void shim_ipc_helper_prepare(void* arg) { /* UNREACHABLE */ } - debug("IPC helper thread started\n"); + log_debug("IPC helper thread started\n"); /* swap stack to be sure we don't drain the small stack PAL provides */ self->stack_top = stack + IPC_HELPER_STACK_SIZE; @@ -907,7 +907,7 @@ struct shim_thread* terminate_ipc_helper(void) { * through the host-OS stream, the host OS will close the stream, and the message will never be * seen by child. To prevent such cases, we simply wait for a bit before exiting. */ - debug("Waiting for 0.5s for all in-flight IPC messages to reach their destinations\n"); + log_debug("Waiting for 0.5s for all in-flight IPC messages to reach their destinations\n"); DkThreadDelayExecution(500000); /* in microseconds */ lock(&ipc_helper_lock); diff --git a/LibOS/shim/src/ipc/shim_ipc_pid.c b/LibOS/shim/src/ipc/shim_ipc_pid.c index f84d201e0c..b67cc232df 100644 --- a/LibOS/shim/src/ipc/shim_ipc_pid.c +++ b/LibOS/shim/src/ipc/shim_ipc_pid.c @@ -68,12 +68,13 @@ int ipc_pid_kill_send(IDTYPE sender, IDTYPE target, enum kill_type type, int sig msgin->signum = signum; if (type == KILL_ALL) { - debug("IPC broadcast: IPC_MSG_PID_KILL(%u, %d, %u, %d)\n", sender, type, target, signum); + log_debug("IPC broadcast: IPC_MSG_PID_KILL(%u, %d, %u, %d)\n", sender, type, target, + signum); ret = broadcast_ipc(msg, IPC_PORT_DIRECTCHILD | IPC_PORT_DIRECTPARENT, /*exclude_port=*/NULL); } else { - debug("IPC send to %u: IPC_MSG_PID_KILL(%u, %d, %u, %d)\n", dest, sender, type, - target, signum); + log_debug("IPC send to %u: IPC_MSG_PID_KILL(%u, %d, %u, %d)\n", dest, sender, type, + target, signum); ret = send_ipc_message(msg, port); put_ipc_port(port); } @@ -85,8 +86,8 @@ int ipc_pid_kill_send(IDTYPE sender, IDTYPE target, enum kill_type type, int sig int ipc_pid_kill_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* port) { struct shim_ipc_pid_kill* msgin = (struct shim_ipc_pid_kill*)msg->msg; - debug("IPC callback from %u: IPC_MSG_PID_KILL(%u, %d, %u, %d)\n", msg->src, - msgin->sender, msgin->type, msgin->id, msgin->signum); + log_debug("IPC callback from %u: IPC_MSG_PID_KILL(%u, %d, %u, %d)\n", msg->src, + msgin->sender, msgin->type, msgin->id, msgin->signum); int ret = 0; @@ -119,7 +120,7 @@ int ipc_pid_getstatus_send(struct shim_ipc_port* port, IDTYPE dest, int npids, I msgin->npids = npids; memcpy(msgin->pids, pids, sizeof(IDTYPE) * npids); - debug("ipc send to %u: IPC_MSG_PID_GETSTATUS(%d, [%u, ...])\n", dest, npids, pids[0]); + log_debug("ipc send to %u: IPC_MSG_PID_GETSTATUS(%d, [%u, ...])\n", dest, npids, pids[0]); return send_ipc_message_with_ack(msg, port, NULL, status); } @@ -157,8 +158,8 @@ int ipc_pid_getstatus_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* p struct shim_ipc_pid_getstatus* msgin = (struct shim_ipc_pid_getstatus*)msg->msg; int ret = 0; - debug("ipc callback from %u: IPC_MSG_PID_GETSTATUS(%d, [%u, ...])\n", msg->src, msgin->npids, - msgin->pids[0]); + log_debug("ipc callback from %u: IPC_MSG_PID_GETSTATUS(%d, [%u, ...])\n", msg->src, + msgin->npids, msgin->pids[0]); struct thread_status status; status.npids = msgin->npids; @@ -189,10 +190,10 @@ int ipc_pid_retstatus_send(struct shim_ipc_port* port, IDTYPE dest, int nstatus, msg->seq = seq; if (nstatus) - debug("ipc send to %u: IPC_MSG_PID_RETSTATUS(%d, [%u, ...])\n", dest, nstatus, - status[0].pid); + log_debug("ipc send to %u: IPC_MSG_PID_RETSTATUS(%d, [%u, ...])\n", dest, nstatus, + status[0].pid); else - debug("ipc send to %u: IPC_MSG_PID_RETSTATUS(0, [])\n", dest); + log_debug("ipc send to %u: IPC_MSG_PID_RETSTATUS(0, [])\n", dest); return send_ipc_message(msg, port); } @@ -201,10 +202,10 @@ int ipc_pid_retstatus_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* p struct shim_ipc_pid_retstatus* msgin = (struct shim_ipc_pid_retstatus*)msg->msg; if (msgin->nstatus) - debug("ipc callback from %u: IPC_MSG_PID_RETSTATUS(%d, [%u, ...])\n", msg->src, + log_debug("ipc callback from %u: IPC_MSG_PID_RETSTATUS(%d, [%u, ...])\n", msg->src, msgin->nstatus, msgin->status[0].pid); else - debug("ipc callback from %u: IPC_MSG_PID_RETSTATUS(0, [])\n", msg->src); + log_debug("ipc callback from %u: IPC_MSG_PID_RETSTATUS(0, [])\n", msg->src); struct shim_ipc_msg_with_ack* obj = pop_ipc_msg_with_ack(port, msg->seq); if (obj) { @@ -246,7 +247,7 @@ int ipc_pid_getmeta_send(IDTYPE pid, enum pid_meta_code code, void** data) { msgin->pid = pid; msgin->code = code; - debug("ipc send to %u: IPC_MSG_PID_GETMETA(%u, %s)\n", dest, pid, pid_meta_code_str[code]); + log_debug("ipc send to %u: IPC_MSG_PID_GETMETA(%u, %s)\n", dest, pid, pid_meta_code_str[code]); ret = send_ipc_message_with_ack(msg, port, NULL, data); put_ipc_port(port); @@ -258,8 +259,8 @@ int ipc_pid_getmeta_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* por struct shim_ipc_pid_getmeta* msgin = (struct shim_ipc_pid_getmeta*)msg->msg; int ret = 0; - debug("ipc callback from %u: IPC_MSG_PID_GETMETA(%u, %s)\n", msg->src, msgin->pid, - pid_meta_code_str[msgin->code]); + log_debug("ipc callback from %u: IPC_MSG_PID_GETMETA(%u, %s)\n", msg->src, msgin->pid, + pid_meta_code_str[msgin->code]); struct shim_thread* thread = lookup_thread(msgin->pid); void* data = NULL; @@ -349,8 +350,8 @@ int ipc_pid_retmeta_send(struct shim_ipc_port* port, IDTYPE dest, IDTYPE pid, memcpy(msgin->data, data, datasize); msg->seq = seq; - debug("ipc send to %u: IPC_MSG_PID_RETMETA(%d, %s, %d)\n", dest, pid, pid_meta_code_str[code], - datasize); + log_debug("ipc send to %u: IPC_MSG_PID_RETMETA(%d, %s, %d)\n", dest, pid, + pid_meta_code_str[code], datasize); return send_ipc_message(msg, port); } @@ -358,8 +359,8 @@ int ipc_pid_retmeta_send(struct shim_ipc_port* port, IDTYPE dest, IDTYPE pid, int ipc_pid_retmeta_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* port) { struct shim_ipc_pid_retmeta* msgin = (struct shim_ipc_pid_retmeta*)msg->msg; - debug("ipc callback from %u: IPC_MSG_PID_RETMETA(%u, %s, %d)\n", msg->src, msgin->pid, - pid_meta_code_str[msgin->code], msgin->datasize); + log_debug("ipc callback from %u: IPC_MSG_PID_RETMETA(%u, %s, %d)\n", msg->src, msgin->pid, + pid_meta_code_str[msgin->code], msgin->datasize); struct shim_ipc_msg_with_ack* obj = pop_ipc_msg_with_ack(port, msg->seq); if (obj) { diff --git a/LibOS/shim/src/ipc/shim_ipc_ranges.c b/LibOS/shim/src/ipc/shim_ipc_ranges.c index cbc78fee6d..4b1f8deb9e 100644 --- a/LibOS/shim/src/ipc/shim_ipc_ranges.c +++ b/LibOS/shim/src/ipc/shim_ipc_ranges.c @@ -625,7 +625,7 @@ static void ipc_leader_exit(struct shim_ipc_port* port, IDTYPE vmid) { g_process_ipc_info.ns = NULL; unlock(&g_process_ipc_info.lock); - debug("ipc port %p of process %u closed suggests leader exits\n", port, vmid); + log_debug("ipc port %p of process %u closed suggests leader exits\n", port, vmid); put_ipc_info(info); } @@ -859,7 +859,7 @@ int ipc_findns_send(bool block) { struct shim_ipc_msg_with_ack* msg = __alloca(total_msg_size); init_ipc_msg_with_ack(msg, IPC_MSG_FINDNS, total_msg_size, dest); - debug("ipc send to %u: IPC_MSG_FINDNS\n", dest); + log_debug("ipc send to %u: IPC_MSG_FINDNS\n", dest); ret = send_ipc_message_with_ack(msg, port, NULL, NULL); goto out_port; @@ -869,7 +869,7 @@ int ipc_findns_send(bool block) { struct shim_ipc_msg* msg = __alloca(total_msg_size); init_ipc_msg(msg, IPC_MSG_FINDNS, total_msg_size, dest); - debug("ipc send to %u: IPC_MSG_FINDNS\n", dest); + log_debug("ipc send to %u: IPC_MSG_FINDNS\n", dest); ret = send_ipc_message(msg, port); out_port: @@ -879,7 +879,7 @@ int ipc_findns_send(bool block) { } int ipc_findns_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* port) { - debug("ipc callback from %u: IPC_MSG_FINDNS\n", msg->src); + log_debug("ipc callback from %u: IPC_MSG_FINDNS\n", msg->src); int ret = 0; __discover_ns(false, true); // This function cannot be called with g_process_ipc_info.lock held @@ -917,7 +917,7 @@ int ipc_tellns_send(struct shim_ipc_port* port, IDTYPE dest, struct shim_ipc_inf memcpy(msgin->uri, qstrgetstr(&leader->uri), leader->uri.len + 1); msg->seq = seq; - debug("ipc send to %u: IPC_MSG_TELLNS(%u, %s)\n", dest, leader->vmid, msgin->uri); + log_debug("ipc send to %u: IPC_MSG_TELLNS(%u, %s)\n", dest, leader->vmid, msgin->uri); int ret = send_ipc_message(msg, port); return ret; @@ -927,7 +927,7 @@ int ipc_tellns_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* port) { struct shim_ipc_tellns* msgin = (void*)&msg->msg; int ret = 0; - debug("ipc callback from %u: IPC_MSG_TELLNS(%u, %s)\n", msg->src, msgin->vmid, msgin->uri); + log_debug("ipc callback from %u: IPC_MSG_TELLNS(%u, %s)\n", msg->src, msgin->vmid, msgin->uri); lock(&g_process_ipc_info.lock); @@ -992,7 +992,7 @@ int ipc_lease_send(void) { memcpy(msgin->uri, qstrgetstr(&self->uri), len + 1); put_ipc_info(self); - debug("ipc send to %u: IPC_MSG_LEASE(%s)\n", leader, msgin->uri); + log_debug("ipc send to %u: IPC_MSG_LEASE(%s)\n", leader, msgin->uri); ret = send_ipc_message_with_ack(msg, port, NULL, NULL); out: @@ -1004,7 +1004,7 @@ int ipc_lease_send(void) { int ipc_lease_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* port) { struct shim_ipc_lease* msgin = (void*)&msg->msg; - debug("ipc callback from %u: IPC_MSG_LEASE(%s)\n", msg->src, msgin->uri); + log_debug("ipc callback from %u: IPC_MSG_LEASE(%s)\n", msg->src, msgin->uri); IDTYPE base = 0; @@ -1030,7 +1030,7 @@ int ipc_offer_send(struct shim_ipc_port* port, IDTYPE dest, IDTYPE base, IDTYPE msgin->size = size; msg->seq = seq; - debug("ipc send to %u: IPC_MSG_OFFER(%u, %u)\n", port->vmid, base, size); + log_debug("ipc send to %u: IPC_MSG_OFFER(%u, %u)\n", port->vmid, base, size); ret = send_ipc_message(msg, port); return ret; } @@ -1038,7 +1038,7 @@ int ipc_offer_send(struct shim_ipc_port* port, IDTYPE dest, IDTYPE base, IDTYPE int ipc_offer_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* port) { struct shim_ipc_offer* msgin = (void*)&msg->msg; - debug("ipc callback from %u: IPC_MSG_OFFER(%u, %u)\n", msg->src, msgin->base, msgin->size); + log_debug("ipc callback from %u: IPC_MSG_OFFER(%u, %u)\n", msg->src, msgin->base, msgin->size); struct shim_ipc_msg_with_ack* obj = pop_ipc_msg_with_ack(port, msg->seq); @@ -1081,7 +1081,7 @@ int ipc_renew_send(IDTYPE base, IDTYPE size) { msgin->base = base; msgin->size = size; - debug("ipc send to : IPC_MSG_RENEW(%u, %u)\n", base, size); + log_debug("ipc send to : IPC_MSG_RENEW(%u, %u)\n", base, size); ret = send_ipc_message(msg, port); put_ipc_port(port); out: @@ -1093,7 +1093,7 @@ int ipc_renew_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* port) { struct shim_ipc_renew* msgin = (void*)&msg->msg; int ret = 0; - debug("ipc callback from %u: IPC_MSG_RENEW(%u, %u)\n", msg->src, msgin->base, msgin->size); + log_debug("ipc callback from %u: IPC_MSG_RENEW(%u, %u)\n", msg->src, msgin->base, msgin->size); if (msgin->size != 1 && msgin->size != RANGE_SIZE) { ret = -EINVAL; @@ -1144,7 +1144,7 @@ int ipc_sublease_send(IDTYPE tenant, IDTYPE idx, const char* uri) { msgin->idx = idx; memcpy(msgin->uri, uri, len + 1); - debug("ipc send to %u: IPC_MSG_SUBLEASE(%u, %u, %s)\n", leader, tenant, idx, msgin->uri); + log_debug("ipc send to %u: IPC_MSG_SUBLEASE(%u, %u, %s)\n", leader, tenant, idx, msgin->uri); ret = send_ipc_message_with_ack(msg, port, NULL, NULL); out: @@ -1156,8 +1156,8 @@ int ipc_sublease_send(IDTYPE tenant, IDTYPE idx, const char* uri) { int ipc_sublease_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* port) { struct shim_ipc_sublease* msgin = (void*)&msg->msg; - debug("ipc callback from %u: IPC_MSG_SUBLEASE(%u, %u, %s)\n", msg->src, msgin->idx, - msgin->tenant, msgin->uri); + log_debug("ipc callback from %u: IPC_MSG_SUBLEASE(%u, %u, %s)\n", msg->src, msgin->idx, + msgin->tenant, msgin->uri); int ret = add_ipc_subrange(msgin->idx, msgin->tenant, msgin->uri); @@ -1190,7 +1190,7 @@ int ipc_query_send(IDTYPE idx) { struct shim_ipc_query* msgin = (void*)&msg->msg.msg; msgin->idx = idx; - debug("ipc send to %u: IPC_MSG_QUERY(%u)\n", leader, idx); + log_debug("ipc send to %u: IPC_MSG_QUERY(%u)\n", leader, idx); ret = send_ipc_message_with_ack(msg, port, NULL, NULL); out: @@ -1202,7 +1202,7 @@ int ipc_query_send(IDTYPE idx) { int ipc_query_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* port) { struct shim_ipc_query* msgin = (void*)&msg->msg; - debug("ipc callback from %u: IPC_MSG_QUERY(%u)\n", msg->src, msgin->idx); + log_debug("ipc callback from %u: IPC_MSG_QUERY(%u)\n", msg->src, msgin->idx); struct ipc_range range; int ret = 0; @@ -1246,7 +1246,7 @@ int ipc_queryall_send(void) { struct shim_ipc_msg_with_ack* msg = __alloca(total_msg_size); init_ipc_msg_with_ack(msg, IPC_MSG_QUERYALL, total_msg_size, leader); - debug("ipc send to %u: IPC_MSG_QUERYALL\n", leader); + log_debug("ipc send to %u: IPC_MSG_QUERYALL\n", leader); ret = send_ipc_message_with_ack(msg, port, NULL, NULL); put_ipc_port(port); @@ -1255,7 +1255,7 @@ int ipc_queryall_send(void) { } int ipc_queryall_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* port) { - debug("ipc callback from %u: IPC_MSG_QUERYALL\n", msg->src); + log_debug("ipc callback from %u: IPC_MSG_QUERYALL\n", msg->src); LISTP_TYPE(range)* list = &offered_ranges; struct range* r; @@ -1361,10 +1361,11 @@ int ipc_answer_send(struct shim_ipc_port* port, IDTYPE dest, size_t answers_cnt, msg->seq = seq; if (answers_cnt == 1) - debug("ipc send to %u: IPC_MSG_ANSWER([%u, %u])\n", dest, answers[0].base, answers[0].size); + log_debug("ipc send to %u: IPC_MSG_ANSWER([%u, %u])\n", dest, answers[0].base, + answers[0].size); else if (answers_cnt) - debug("ipc send to %u: IPC_MSG_ANSWER([%u, %u], ...)\n", dest, answers[0].base, - answers[0].size); + log_debug("ipc send to %u: IPC_MSG_ANSWER([%u, %u], ...)\n", dest, answers[0].base, + answers[0].size); return send_ipc_message(msg, port); } @@ -1373,11 +1374,11 @@ int ipc_answer_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* port) { struct shim_ipc_answer* msgin = (void*)&msg->msg; if (msgin->answers_cnt == 1) - debug("ipc callback from %u: IPC_MSG_ANSWER([%u, %u])\n", msg->src, msgin->answers[0].base, - msgin->answers[0].size); + log_debug("ipc callback from %u: IPC_MSG_ANSWER([%u, %u])\n", msg->src, + msgin->answers[0].base, msgin->answers[0].size); else if (msgin->answers_cnt) - debug("ipc callback from %u: IPC_MSG_ANSWER([%u, %u], ...)\n", msg->src, - msgin->answers[0].base, msgin->answers[0].size); + log_debug("ipc callback from %u: IPC_MSG_ANSWER([%u, %u], ...)\n", msg->src, + msgin->answers[0].base, msgin->answers[0].size); for (size_t i = 0; i < msgin->answers_cnt; i++) { struct ipc_ns_offered* ans = &msgin->answers[i]; @@ -1591,7 +1592,7 @@ int sysv_add_key(struct sysv_key* key, IDTYPE id) { INIT_LIST_HEAD(k, hlist); LISTP_ADD(k, head, hlist); - debug("add key/id pair (%lu, %u) to hash list: %p\n", key->key, id, head); + log_debug("added key/id pair (%lu, %u) to hash list: %p\n", key->key, id, head); ret = 0; out: unlock(&range_map_lock); diff --git a/LibOS/shim/src/ipc/shim_ipc_sysv.c b/LibOS/shim/src/ipc/shim_ipc_sysv.c index 9d9e55820a..b3fe4bdd7e 100644 --- a/LibOS/shim/src/ipc/shim_ipc_sysv.c +++ b/LibOS/shim/src/ipc/shim_ipc_sysv.c @@ -45,7 +45,7 @@ int ipc_sysv_findkey_send(struct sysv_key* key) { msgin->key.key = key->key; msgin->key.type = key->type; - debug("ipc send to %u: IPC_MSG_SYSV_FINDKEY(%lu)\n", dest, key->key); + log_debug("ipc send to %u: IPC_MSG_SYSV_FINDKEY(%lu)\n", dest, key->key); ret = send_ipc_message_with_ack(msg, port, NULL, NULL); put_ipc_port(port); @@ -60,7 +60,7 @@ int ipc_sysv_findkey_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* po int ret = 0; struct shim_ipc_sysv_findkey* msgin = (void*)&msg->msg; - debug("ipc callback from %u: IPC_MSG_SYSV_FINDKEY(%lu)\n", msg->src, msgin->key.key); + log_debug("ipc callback from %u: IPC_MSG_SYSV_FINDKEY(%lu)\n", msg->src, msgin->key.key); ret = sysv_get_key(&msgin->key, false); if (ret < 0) @@ -98,7 +98,7 @@ int ipc_sysv_tellkey_send(struct shim_ipc_port* port, IDTYPE dest, struct sysv_k msgin->id = id; msg->seq = seq; - debug("ipc send to %u: IPC_MSG_SYSV_TELLKEY(%lu, %u)\n", dest, key->key, id); + log_debug("ipc send to %u: IPC_MSG_SYSV_TELLKEY(%lu, %u)\n", dest, key->key, id); ret = send_ipc_message(msg, port); goto out; @@ -113,7 +113,7 @@ int ipc_sysv_tellkey_send(struct shim_ipc_port* port, IDTYPE dest, struct sysv_k msgin->key.type = key->type; msgin->id = id; - debug("ipc send to %u: IPC_MSG_SYSV_TELLKEY(%lu, %u)\n", dest, key->key, id); + log_debug("ipc send to %u: IPC_MSG_SYSV_TELLKEY(%lu, %u)\n", dest, key->key, id); ret = send_ipc_message_with_ack(msg, port, NULL, NULL); put_ipc_port(port); @@ -125,8 +125,8 @@ int ipc_sysv_tellkey_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* po int ret = 0; struct shim_ipc_sysv_tellkey* msgin = (void*)&msg->msg; - debug("ipc callback from %u: IPC_MSG_SYSV_TELLKEY(%lu, %u)\n", msg->src, msgin->key.key, - msgin->id); + log_debug("ipc callback from %u: IPC_MSG_SYSV_TELLKEY(%lu, %u)\n", msg->src, msgin->key.key, + msgin->id); ret = sysv_add_key(&msgin->key, msgin->id); @@ -164,7 +164,8 @@ int ipc_sysv_delres_send(struct shim_ipc_port* port, IDTYPE dest, IDTYPE resid, msgin->resid = resid; msgin->type = type; - debug("ipc send to %u: IPC_MSG_SYSV_DELRES(%u, %s)\n", dest, resid, SYSV_TYPE_STR(type)); + log_debug("ipc send to %u: IPC_MSG_SYSV_DELRES(%u, %s)\n", dest, resid, + SYSV_TYPE_STR(type)); ret = send_ipc_message(msg, port); goto out; @@ -178,7 +179,8 @@ int ipc_sysv_delres_send(struct shim_ipc_port* port, IDTYPE dest, IDTYPE resid, msgin->resid = resid; msgin->type = type; - debug("ipc send to %u: IPC_MSG_SYSV_DELRES(%u, %s)\n", dest, resid, SYSV_TYPE_STR(type)); + log_debug("ipc send to %u: IPC_MSG_SYSV_DELRES(%u, %s)\n", dest, resid, + SYSV_TYPE_STR(type)); ret = send_ipc_message_with_ack(msg, port, NULL, NULL); put_ipc_port(port); @@ -192,8 +194,8 @@ int ipc_sysv_delres_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* por int ret = 0; struct shim_ipc_sysv_delres* msgin = (struct shim_ipc_sysv_delres*)&msg->msg; - debug("ipc callback from %u: IPC_MSG_SYSV_DELRES(%u, %s)\n", msg->src, msgin->resid, - SYSV_TYPE_STR(msgin->type)); + log_debug("ipc callback from %u: IPC_MSG_SYSV_DELRES(%u, %s)\n", msg->src, msgin->resid, + SYSV_TYPE_STR(msgin->type)); bool owned = false; ret = -ENOENT; @@ -239,8 +241,8 @@ int ipc_sysv_movres_send(struct sysv_client* client, IDTYPE owner, const char* u memcpy(msgin->uri, uri, len + 1); msg->seq = client->seq; - debug("ipc send to %u: IPC_MSG_SYSV_MOVRES(%u, %s, %u, %s)\n", client->vmid, resid, - SYSV_TYPE_STR(type), owner, uri); + log_debug("ipc send to %u: IPC_MSG_SYSV_MOVRES(%u, %s, %u, %s)\n", client->vmid, resid, + SYSV_TYPE_STR(type), owner, uri); return send_ipc_message(msg, client->port); } @@ -249,8 +251,8 @@ int ipc_sysv_movres_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* por int ret = 0; struct shim_ipc_sysv_movres* msgin = (struct shim_ipc_sysv_movres*)&msg->msg; - debug("ipc callback from %u: IPC_MSG_SYSV_MOVRES(%u, %s, %u, %s)\n", msg->src, msgin->resid, - SYSV_TYPE_STR(msgin->type), msgin->owner, msgin->uri); + log_debug("ipc callback from %u: IPC_MSG_SYSV_MOVRES(%u, %s, %u, %s)\n", msg->src, msgin->resid, + SYSV_TYPE_STR(msgin->type), msgin->owner, msgin->uri); struct shim_ipc_msg_with_ack* obj = pop_ipc_msg_with_ack(port, msg->seq); if (!obj) @@ -296,7 +298,7 @@ int ipc_sysv_msgsnd_send(struct shim_ipc_port* port, IDTYPE dest, IDTYPE msgid, memcpy(msgin->msg, buf, size); msg->seq = seq; - debug("ipc send to %u: IPC_MSG_SYSV_MSGSND(%u, %ld)\n", dest, msgid, msgtype); + log_debug("ipc send to %u: IPC_MSG_SYSV_MSGSND(%u, %ld)\n", dest, msgid, msgtype); ret = send_ipc_message(msg, port); @@ -310,8 +312,8 @@ int ipc_sysv_msgsnd_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* por int ret = 0; struct shim_ipc_sysv_msgsnd* msgin = (struct shim_ipc_sysv_msgsnd*)&msg->msg; - debug("ipc callback from %u: IPC_MSG_SYSV_MSGSND(%u, %ld)\n", msg->src, msgin->msgid, - msgin->msgtype); + log_debug("ipc callback from %u: IPC_MSG_SYSV_MSGSND(%u, %ld)\n", msg->src, msgin->msgid, + msgin->msgtype); size_t size = msg->size - sizeof(*msg) - sizeof(*msgin); @@ -378,7 +380,7 @@ int ipc_sysv_msgrcv_send(IDTYPE msgid, long msgtype, int flags, void* buf, size_ msgin->size = size; msgin->flags = flags; - debug("ipc send to %u: IPC_MSG_SYSV_MSGRCV(%u, %ld)\n", owner, msgid, msgtype); + log_debug("ipc send to %u: IPC_MSG_SYSV_MSGRCV(%u, %ld)\n", owner, msgid, msgtype); ret = send_ipc_message_with_ack(msg, port, NULL, buf); put_ipc_port(port); @@ -390,8 +392,8 @@ int ipc_sysv_msgrcv_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* por int ret = 0; struct shim_ipc_sysv_msgrcv* msgin = (struct shim_ipc_sysv_msgrcv*)&msg->msg; - debug("ipc callback from %u: IPC_MSG_SYSV_MSGRCV(%u, %ld)\n", msg->src, msgin->msgid, - msgin->msgtype); + log_debug("ipc callback from %u: IPC_MSG_SYSV_MSGRCV(%u, %ld)\n", msg->src, msgin->msgid, + msgin->msgtype); struct shim_msg_handle* msgq = get_msg_handle_by_id(msgin->msgid); @@ -455,7 +457,8 @@ int ipc_sysv_semop_send(IDTYPE semid, struct sembuf* sops, int nsops, unsigned l memcpy(msgin->sops, sops, sizeof(struct sembuf) * nsops); msg->seq = *seq; - debug("ipc send to %u: IPC_MSG_SYSV_SEMOP(%u, %ld, %u)\n", owner, semid, timeout, nsops); + log_debug("ipc send to %u: IPC_MSG_SYSV_SEMOP(%u, %ld, %u)\n", owner, semid, timeout, + nsops); ret = send_ipc_message(msg, port); put_ipc_port(port); @@ -474,7 +477,7 @@ int ipc_sysv_semop_send(IDTYPE semid, struct sembuf* sops, int nsops, unsigned l memcpy(msgin->sops, sops, sizeof(struct sembuf) * nsops); msg->msg.seq = *seq; - debug("ipc send to %u: IPC_MSG_SYSV_SEMOP(%u, %ld, %u)\n", owner, semid, timeout, nsops); + log_debug("ipc send to %u: IPC_MSG_SYSV_SEMOP(%u, %ld, %u)\n", owner, semid, timeout, nsops); ret = send_ipc_message_with_ack(msg, port, seq, NULL); put_ipc_port(port); @@ -486,8 +489,8 @@ int ipc_sysv_semop_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* port int ret = 0; struct shim_ipc_sysv_semop* msgin = (struct shim_ipc_sysv_semop*)&msg->msg; - debug("ipc callback from %u: IPC_MSG_SYSV_SEMOP(%u, %ld, %u)\n", msg->src, msgin->semid, - msgin->timeout, msgin->nsops); + log_debug("ipc callback from %u: IPC_MSG_SYSV_SEMOP(%u, %ld, %u)\n", msg->src, msgin->semid, + msgin->timeout, msgin->nsops); struct shim_sem_handle* sem = get_sem_handle_by_id(msgin->semid); if (!sem) { @@ -528,7 +531,7 @@ int ipc_sysv_semctl_send(IDTYPE semid, int semnum, int cmd, void* vals, size_t v if (ctlvalsize) memcpy(msgin->vals, vals, ctlvalsize); - debug("ipc send to %u: IPC_MSG_SYSV_SEMCTL(%u, %d, %d)\n", owner, semid, semnum, cmd); + log_debug("ipc send to %u: IPC_MSG_SYSV_SEMCTL(%u, %d, %d)\n", owner, semid, semnum, cmd); ret = send_ipc_message_with_ack(msg, port, NULL, vals); put_ipc_port(port); @@ -540,8 +543,8 @@ int ipc_sysv_semctl_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* por int ret = 0; struct shim_ipc_sysv_semctl* msgin = (struct shim_ipc_sysv_semctl*)&msg->msg; - debug("ipc callback from %u: IPC_MSG_SYSV_SEMCTL(%u, %d, %d)\n", msg->src, msgin->semid, - msgin->semnum, msgin->cmd); + log_debug("ipc callback from %u: IPC_MSG_SYSV_SEMCTL(%u, %d, %d)\n", msg->src, msgin->semid, + msgin->semnum, msgin->cmd); struct shim_sem_handle* sem = get_sem_handle_by_id(msgin->semid); if (!sem) { @@ -635,7 +638,7 @@ int ipc_sysv_semret_send(struct shim_ipc_port* port, IDTYPE dest, void* vals, si memcpy(msgin->vals, vals, valsize); msg->seq = seq; - debug("ipc send to %u: IPC_MSG_SYSV_SEMRET\n", dest); + log_debug("ipc send to %u: IPC_MSG_SYSV_SEMRET\n", dest); return send_ipc_message(msg, port); } @@ -643,7 +646,7 @@ int ipc_sysv_semret_send(struct shim_ipc_port* port, IDTYPE dest, void* vals, si int ipc_sysv_semret_callback(struct shim_ipc_msg* msg, struct shim_ipc_port* port) { struct shim_ipc_sysv_semret* semret = (struct shim_ipc_sysv_semret*)&msg->msg; - debug("ipc callback from %u: IPC_MSG_SYSV_SEMRET\n", msg->src); + log_debug("ipc callback from %u: IPC_MSG_SYSV_SEMRET\n", msg->src); struct shim_ipc_msg_with_ack* obj = pop_ipc_msg_with_ack(port, msg->seq); if (obj) { diff --git a/LibOS/shim/src/shim_async.c b/LibOS/shim/src/shim_async.c index 24a2689f16..0a6f923a25 100644 --- a/LibOS/shim/src/shim_async.c +++ b/LibOS/shim/src/shim_async.c @@ -116,7 +116,7 @@ int64_t install_async_event(PAL_HANDLE object, uint64_t time, unlock(&async_helper_lock); - debug("Installed async event at %lu\n", now); + log_debug("Installed async event at %lu\n", now); set_event(&install_new_event, 1); return max_prev_expire_time - now; } @@ -161,7 +161,7 @@ static void shim_async_helper(void* arg) { /* Assume async helper thread will not drain the stack that PAL provides, * so for efficiency we don't swap the stack. */ - debug("Async helper thread started\n"); + log_debug("Async helper thread started\n"); /* Simple heuristic to not burn cycles when no async events are installed: * async helper thread sleeps IDLE_SLEEP_TIME for MAX_IDLE_CYCLES and @@ -173,14 +173,14 @@ static void shim_async_helper(void* arg) { size_t pals_max_cnt = 32; PAL_HANDLE* pals = malloc(sizeof(*pals) * (1 + pals_max_cnt)); if (!pals) { - debug("Allocation of pals failed\n"); + log_error("Allocation of pals failed\n"); goto out_err; } /* allocate one memory region to hold two PAL_FLG arrays: events and revents */ PAL_FLG* pal_events = malloc(sizeof(*pal_events) * (1 + pals_max_cnt) * 2); if (!pal_events) { - debug("Allocation of pal_events failed\n"); + log_error("Allocation of pal_events failed\n"); goto out_err; } PAL_FLG* ret_events = pal_events + 1 + pals_max_cnt; @@ -193,7 +193,7 @@ static void shim_async_helper(void* arg) { while (true) { uint64_t now = DkSystemTimeQuery(); if ((int64_t)now < 0) { - debug("DkSystemTimeQuery failed with: %ld\n", (int64_t)now); + log_error("DkSystemTimeQuery failed with: %ld\n", (int64_t)now); goto out_err; } @@ -217,13 +217,13 @@ static void shim_async_helper(void* arg) { /* grow `pals` to accommodate more objects */ PAL_HANDLE* tmp_pals = malloc(sizeof(*tmp_pals) * (1 + pals_max_cnt * 2)); if (!tmp_pals) { - debug("tmp_pals allocation failed\n"); + log_error("tmp_pals allocation failed\n"); goto out_err_unlock; } PAL_FLG* tmp_pal_events = malloc(sizeof(*tmp_pal_events) * (2 + pals_max_cnt * 4)); if (!tmp_pal_events) { - debug("tmp_pal_events allocation failed\n"); + log_error("tmp_pal_events allocation failed\n"); goto out_err_unlock; } PAL_FLG* tmp_ret_events = tmp_pal_events + 1 + pals_max_cnt * 2; @@ -276,7 +276,7 @@ static void shim_async_helper(void* arg) { async_helper_state = HELPER_NOTALIVE; async_helper_thread = NULL; unlock(&async_helper_lock); - debug("Async helper thread has been idle for some time; stopping it\n"); + log_debug("Async helper thread has been idle for some time; stopping it\n"); break; } unlock(&async_helper_lock); @@ -287,7 +287,7 @@ static void shim_async_helper(void* arg) { now = DkSystemTimeQuery(); if ((int64_t)now < 0) { - debug("DkSystemTimeQuery failed with: %ld\n", (int64_t)now); + log_error("DkSystemTimeQuery failed with: %ld\n", (int64_t)now); goto out_err; } @@ -309,7 +309,7 @@ static void shim_async_helper(void* arg) { /* check if this event is an IO event found in async_list */ LISTP_FOR_EACH_ENTRY_SAFE(tmp, n, &async_list, list) { if (tmp->object == pals[i]) { - debug("Async IO event triggered at %lu\n", now); + log_debug("Async IO event triggered at %lu\n", now); LISTP_ADD_TAIL(tmp, &triggered, triggered_list); break; } @@ -320,11 +320,11 @@ static void shim_async_helper(void* arg) { /* check if exit-child or alarm/timer events were triggered */ LISTP_FOR_EACH_ENTRY_SAFE(tmp, n, &async_list, list) { if (tmp->callback == &cleanup_thread) { - debug("Thread exited, cleaning up\n"); + log_debug("Thread exited, cleaning up\n"); LISTP_DEL(tmp, &async_list, list); LISTP_ADD_TAIL(tmp, &triggered, triggered_list); } else if (tmp->expire_time && tmp->expire_time <= now) { - debug("Alarm/timer triggered at %lu (expired at %lu)\n", now, tmp->expire_time); + log_debug("Alarm/timer triggered at %lu (expired at %lu)\n", now, tmp->expire_time); LISTP_DEL(tmp, &async_list, list); LISTP_ADD_TAIL(tmp, &triggered, triggered_list); } @@ -346,7 +346,7 @@ static void shim_async_helper(void* arg) { } put_thread(self); - debug("Async helper thread terminated\n"); + log_debug("Async helper thread terminated\n"); free(pals); free(pal_events); @@ -357,7 +357,7 @@ static void shim_async_helper(void* arg) { out_err_unlock: unlock(&async_helper_lock); out_err: - debug("Terminating the process due to a fatal error in async helper\n"); + log_error("Terminating the process due to a fatal error in async helper\n"); put_thread(self); DkProcessExit(1); } diff --git a/LibOS/shim/src/shim_checkpoint.c b/LibOS/shim/src/shim_checkpoint.c index 2a6790b574..65a5e88a07 100644 --- a/LibOS/shim/src/shim_checkpoint.c +++ b/LibOS/shim/src/shim_checkpoint.c @@ -343,14 +343,14 @@ static int receive_memory_on_stream(PAL_HANDLE handle, struct checkpoint_hdr* hd for (; entry; entry = entry->next) { CP_REBASE(entry->next); - debug("memory entry [%p]: %p-%p\n", entry, entry->addr, entry->addr + entry->size); + log_debug("memory entry [%p]: %p-%p\n", entry, entry->addr, entry->addr + entry->size); PAL_PTR addr = ALLOC_ALIGN_DOWN_PTR(entry->addr); PAL_NUM size = (char*)ALLOC_ALIGN_UP_PTR(entry->addr + entry->size) - (char*)addr; PAL_FLG prot = entry->prot; if (!DkVirtualMemoryAlloc(addr, size, 0, prot | PAL_PROT_WRITE)) { - debug("failed allocating %p-%p\n", addr, addr + size); + log_error("failed allocating %p-%p\n", addr, addr + size); return -PAL_ERRNO(); } @@ -360,7 +360,7 @@ static int receive_memory_on_stream(PAL_HANDLE handle, struct checkpoint_hdr* hd } if (!(prot & PAL_PROT_WRITE) && !DkVirtualMemoryProtect(addr, size, prot)) { - debug("failed protecting %p-%p\n", addr, addr + size); + log_error("failed protecting %p-%p\n", addr, addr + size); return -PAL_ERRNO(); } } @@ -373,7 +373,7 @@ static int restore_checkpoint(struct checkpoint_hdr* hdr, uintptr_t base) { size_t cpoffset = hdr->offset; size_t* offset = &cpoffset; - debug("restoring checkpoint at 0x%08lx rebased from %p\n", base, hdr->addr); + log_debug("restoring checkpoint at 0x%08lx rebased from %p\n", base, hdr->addr); struct shim_cp_entry* cpent = NEXT_CP_ENTRY(); ssize_t rebase = base - (uintptr_t)hdr->addr; @@ -387,13 +387,14 @@ static int restore_checkpoint(struct checkpoint_hdr* hdr, uintptr_t base) { rs_func rs = __rs_func[cpent->cp_type - CP_FUNC_BASE]; int ret = (*rs)(cpent, base, offset, rebase); if (ret < 0) { - debug("failed restoring checkpoint at %s (%d)\n", CP_FUNC_NAME(cpent->cp_type), ret); + log_error("failed restoring checkpoint at %s (%d)\n", CP_FUNC_NAME(cpent->cp_type), + ret); return ret; } cpent = NEXT_CP_ENTRY(); } - debug("successfully restored checkpoint at 0x%08lx - 0x%08lx\n", base, base + hdr->size); + log_debug("successfully restored checkpoint at 0x%08lx - 0x%08lx\n", base, base + hdr->size); return 0; } @@ -407,7 +408,7 @@ static int receive_handles_on_stream(struct checkpoint_hdr* hdr, void* base, ssi if (!entries_cnt) return 0; - debug("receiving %lu PAL handles\n", entries_cnt); + log_debug("receiving %lu PAL handles\n", entries_cnt); struct shim_palhdl_entry** entries = malloc(sizeof(*entries) * entries_cnt); @@ -445,7 +446,7 @@ static int receive_handles_on_stream(struct checkpoint_hdr* hdr, void* base, ssi static void* cp_alloc(void* addr, size_t size) { if (addr) { - debug("extending checkpoint store: %p-%p (size = %lu)\n", addr, addr + size, size); + log_debug("extending checkpoint store: %p-%p (size = %lu)\n", addr, addr + size, size); if (bkeep_mmap_fixed(addr, size, PROT_READ | PROT_WRITE, CP_MMAP_FLAGS | MAP_FIXED_NOREPLACE, NULL, 0, "cpstore") < 0) @@ -460,7 +461,7 @@ static void* cp_alloc(void* addr, size_t size) { * reserved space is half of the size of the checkpoint space. */ size_t reserve_size = ALLOC_ALIGN_UP(size >> 1); - debug("allocating checkpoint store (size = %ld, reserve = %ld)\n", size, reserve_size); + log_debug("allocating checkpoint store (size = %ld, reserve = %ld)\n", size, reserve_size); int ret = bkeep_mmap_any(size + reserve_size, PROT_READ | PROT_WRITE, CP_MMAP_FLAGS, NULL, 0, "cpstore", &addr); @@ -533,7 +534,7 @@ int create_process_and_send_checkpoint(migrate_func_t migrate_func, if (!cpstore.base) { ret = -ENOMEM; - debug("failed allocating enough memory for checkpoint\n"); + log_error("failed allocating enough memory for checkpoint\n"); goto out; } @@ -542,11 +543,11 @@ int create_process_and_send_checkpoint(migrate_func_t migrate_func, ret = (*migrate_func)(&cpstore, process_description, thread_description, process_ipc_info, ap); va_end(ap); if (ret < 0) { - debug("failed creating checkpoint (ret = %d)\n", ret); + log_error("failed creating checkpoint (ret = %d)\n", ret); goto out; } - debug("checkpoint of %lu bytes created\n", cpstore.offset); + log_debug("checkpoint of %lu bytes created\n", cpstore.offset); struct checkpoint_hdr hdr; memset(&hdr, 0, sizeof(hdr)); @@ -567,26 +568,26 @@ int create_process_and_send_checkpoint(migrate_func_t migrate_func, /* send a checkpoint header to child process to notify it to start receiving checkpoint */ ret = write_exact(pal_process, &hdr, sizeof(hdr)); if (ret < 0) { - debug("failed writing checkpoint header to child process (ret = %d)\n", ret); + log_error("failed writing checkpoint header to child process (ret = %d)\n", ret); goto out; } ret = send_checkpoint_on_stream(pal_process, &cpstore); if (ret < 0) { - debug("failed sending checkpoint (ret = %d)\n", ret); + log_error("failed sending checkpoint (ret = %d)\n", ret); goto out; } ret = send_handles_on_stream(pal_process, &cpstore); if (ret < 0) { - debug("failed sending PAL handles as part of checkpoint (ret = %d)\n", ret); + log_error("failed sending PAL handles as part of checkpoint (ret = %d)\n", ret); goto out; } void* tmp_vma = NULL; ret = bkeep_munmap((void*)cpstore.base, cpstore.bound, /*is_internal=*/true, &tmp_vma); if (ret < 0) { - debug("failed unmaping checkpoint (ret = %d)\n", ret); + log_error("failed unmaping checkpoint (ret = %d)\n", ret); goto out; } DkVirtualMemoryFree((PAL_PTR)cpstore.base, cpstore.bound); @@ -623,7 +624,7 @@ int create_process_and_send_checkpoint(migrate_func_t migrate_func, if (ret < 0) { if (pal_process) DkObjectClose(pal_process); - debug("process creation failed\n"); + log_error("process creation failed\n"); } return ret; @@ -662,7 +663,7 @@ int receive_checkpoint_and_restore(struct checkpoint_hdr* hdr) { mapsize = (PAL_NUM)ALLOC_ALIGN_UP(hdr->size); } - debug("checkpoint mapped at %p-%p\n", base, base + hdr->size); + log_debug("checkpoint mapped at %p-%p\n", base, base + hdr->size); mapped = DkVirtualMemoryAlloc(mapaddr, mapsize, 0, PAL_PROT_READ | PAL_PROT_WRITE); if (!mapped) { @@ -675,13 +676,13 @@ int receive_checkpoint_and_restore(struct checkpoint_hdr* hdr) { if (ret < 0) { goto out; } - debug("read checkpoint of %lu bytes from parent\n", hdr->size); + log_debug("read checkpoint of %lu bytes from parent\n", hdr->size); ret = receive_memory_on_stream(PAL_CB(parent_process), hdr, (uintptr_t)base); if (ret < 0) { goto out; } - debug("restored memory from checkpoint\n"); + log_debug("restored memory from checkpoint\n"); /* if checkpoint is loaded at a different address in child from where it was created in parent, * need to rebase the pointers in the checkpoint */ diff --git a/LibOS/shim/src/shim_context-x86_64.c b/LibOS/shim/src/shim_context-x86_64.c index 7a42a703ad..551168a34e 100644 --- a/LibOS/shim/src/shim_context-x86_64.c +++ b/LibOS/shim/src/shim_context-x86_64.c @@ -69,8 +69,8 @@ void shim_xstate_init(void) { g_shim_xsave_size = xsavesize; out: - debug("LibOS xsave_enabled %d, xsave_size 0x%x(%u), xsave_features 0x%lx\n", - g_shim_xsave_enabled, g_shim_xsave_size, g_shim_xsave_size, g_shim_xsave_features); + log_debug("LibOS xsave_enabled %d, xsave_size 0x%x(%u), xsave_features 0x%lx\n", + g_shim_xsave_enabled, g_shim_xsave_size, g_shim_xsave_size, g_shim_xsave_features); } #if 0 @@ -275,8 +275,8 @@ void prepare_sigframe(PAL_CONTEXT* context, siginfo_t* siginfo, void* handler, v * register arguments in `rax`. */ context->rax = 0; - debug("Created sigframe for sig: %d at %p (handler: %p, restorer: %p)\n", - siginfo->si_signo, sigframe, handler, restorer); + log_debug("Created sigframe for sig: %d at %p (handler: %p, restorer: %p)\n", + siginfo->si_signo, sigframe, handler, restorer); } void restart_syscall(PAL_CONTEXT* context, uint64_t syscall_nr) { diff --git a/LibOS/shim/src/shim_debug.c b/LibOS/shim/src/shim_debug.c index 9cb418bb70..67880b593a 100644 --- a/LibOS/shim/src/shim_debug.c +++ b/LibOS/shim/src/shim_debug.c @@ -69,7 +69,7 @@ void remove_r_debug(void* addr) { if (!m) return; - debug("remove a library for gdb: %s\n", m->l_name); + log_debug("removing a library for gdb: %s\n", m->l_name); if (m->l_prev) { m->l_prev->l_next = m->l_next; @@ -107,7 +107,7 @@ void append_r_debug(const char* uri, void* addr) { tail = &(*tail)->l_next; } - debug("add a library for gdb: %s\n", uri); + log_debug("adding a library for gdb: %s\n", uri); new->l_prev = prev; new->l_next = NULL; diff --git a/LibOS/shim/src/shim_init.c b/LibOS/shim/src/shim_init.c index ebf82f9469..f24bfaade5 100644 --- a/LibOS/shim/src/shim_init.c +++ b/LibOS/shim/src/shim_init.c @@ -56,7 +56,7 @@ noreturn void __abort(void) { /* we use GCC's stack protector; when it detects corrupted stack, it calls __stack_chk_fail() */ noreturn void __stack_chk_fail(void); /* to suppress GCC's warning "no previous prototype" */ noreturn void __stack_chk_fail(void) { - debug("Stack protector: Graphene LibOS internal stack corruption detected\n"); + log_error("Stack protector: Graphene LibOS internal stack corruption detected\n"); __abort(); } @@ -146,7 +146,7 @@ void* allocate_stack(size_t size, size_t protect_size, bool user) { if (bkeep_mprotect(stack, size, PROT_READ | PROT_WRITE, !!(flags & VMA_INTERNAL)) < 0) return NULL; - debug("Allocated stack at %p (size = %ld)\n", stack, size); + log_debug("Allocated stack at %p (size = %ld)\n", stack, size); return stack; } @@ -283,7 +283,7 @@ int init_stack(const char** argv, const char** envp, const char*** out_argp, ret = toml_sizestring_in(g_manifest_root, "sys.stack.size", get_rlimit_cur(RLIMIT_STACK), &stack_size); if (ret < 0) { - debug("Cannot parse \'sys.stack.size\' (the value must be put in double quotes!)\n"); + log_error("Cannot parse \'sys.stack.size\' (the value must be put in double quotes!)\n"); return -EINVAL; } @@ -353,13 +353,13 @@ static int read_environs(const char** envp) { #define CALL_INIT(func, args...) func(args) -#define RUN_INIT(func, ...) \ - do { \ - int _err = CALL_INIT(func, ##__VA_ARGS__); \ - if (_err < 0) { \ - debug("Error during shim_init() in " #func " (%d)\n", _err); \ - DkProcessExit(-_err); \ - } \ +#define RUN_INIT(func, ...) \ + do { \ + int _err = CALL_INIT(func, ##__VA_ARGS__); \ + if (_err < 0) { \ + log_error("Error during shim_init() in " #func " (%d)\n", _err); \ + DkProcessExit(-_err); \ + } \ } while (0) noreturn void* shim_init(int argc, void* args) { @@ -372,13 +372,13 @@ noreturn void* shim_init(int argc, void* args) { struct debug_buf debug_buf; (void)debug_setbuf(shim_get_tcb(), &debug_buf); - debug("Host: %s\n", PAL_CB(host_type)); + log_debug("Host: %s\n", PAL_CB(host_type)); DkSetExceptionHandler(&handle_failure, PAL_EVENT_FAILURE); g_pal_alloc_align = PAL_CB(alloc_align); if (!IS_POWER_OF_2(g_pal_alloc_align)) { - debug("Error during shim_init(): PAL allocation alignment not a power of 2\n"); + log_error("Error during shim_init(): PAL allocation alignment not a power of 2\n"); DkProcessExit(EINVAL); } @@ -387,7 +387,7 @@ noreturn void* shim_init(int argc, void* args) { shim_xstate_init(); if (!create_lock(&__master_lock)) { - debug("Error during shim_init(): failed to allocate __master_lock\n"); + log_error("Error during shim_init(): failed to allocate __master_lock\n"); DkProcessExit(ENOMEM); } @@ -404,7 +404,7 @@ noreturn void* shim_init(int argc, void* args) { RUN_INIT(init_dcache); RUN_INIT(init_handle); - debug("Shim loaded at %p, ready to initialize\n", &__load_address); + log_debug("Shim loaded at %p, ready to initialize\n", &__load_address); if (PAL_CB(parent_process)) { struct checkpoint_hdr hdr; @@ -451,7 +451,7 @@ noreturn void* shim_init(int argc, void* args) { DkProcessExit(PAL_ERRNO()); } - debug("Shim process initialized\n"); + log_debug("Shim process initialized\n"); shim_tcb_t* cur_tcb = shim_get_tcb(); @@ -510,7 +510,7 @@ int create_pipe(char* name, char* uri, size_t size, PAL_HANDLE* hdl, struct shim return ret; } - debug("Creating pipe: " URI_PREFIX_PIPE_SRV "%s\n", pipename); + log_debug("Creating pipe: " URI_PREFIX_PIPE_SRV "%s\n", pipename); len = snprintf(uri, size, URI_PREFIX_PIPE_SRV "%s", pipename); if (len >= size) return -ERANGE; diff --git a/LibOS/shim/src/shim_malloc.c b/LibOS/shim/src/shim_malloc.c index 014eebcd06..dab5002505 100644 --- a/LibOS/shim/src/shim_malloc.c +++ b/LibOS/shim/src/shim_malloc.c @@ -52,7 +52,7 @@ void* __system_malloc(size_t size) { continue; } - debug("failed to allocate memory (%ld)\n", -PAL_ERRNO()); + log_error("failed to allocate memory (%ld)\n", -PAL_ERRNO()); void* tmp_vma = NULL; if (bkeep_munmap(addr, alloc_size, /*is_internal=*/true, &tmp_vma) < 0) { BUG(); @@ -94,7 +94,7 @@ void* malloc(size_t size) { * If malloc() failed internally, we cannot handle the * condition and must terminate the current process. */ - warn("******** Out-of-memory in library OS ********\n"); + log_error("Out-of-memory in library OS\n"); __abort(); } diff --git a/LibOS/shim/src/shim_object.c b/LibOS/shim/src/shim_object.c index c4558042d5..e32569c4d3 100644 --- a/LibOS/shim/src/shim_object.c +++ b/LibOS/shim/src/shim_object.c @@ -9,7 +9,7 @@ int object_wait_with_retry(PAL_HANDLE handle) { PAL_NATIVE_ERRNO() == PAL_ERROR_TRYAGAIN)); if (!ret) { - debug("waiting on %p resulted in error %s", handle, pal_strerror(PAL_NATIVE_ERRNO())); + log_error("waiting an object resulted in error %s", pal_strerror(PAL_NATIVE_ERRNO())); return -PAL_NATIVE_ERRNO(); } return 0; diff --git a/LibOS/shim/src/shim_parser.c b/LibOS/shim/src/shim_parser.c index 2dcc7a9eee..c3ae6e5aaa 100644 --- a/LibOS/shim/src/shim_parser.c +++ b/LibOS/shim/src/shim_parser.c @@ -627,17 +627,17 @@ static const char* signal_name(int sig, char str[6]) { return str; } -#define PRINTF(fmt, ...) \ - do { \ - debug_printf(fmt, __VA_ARGS__); \ +#define PRINTF(fmt, ...) \ + do { \ + log_trace(fmt, __VA_ARGS__); \ } while (0) -#define PUTS(str) \ - do { \ - debug_puts(str); \ +#define PUTS(str) \ + do { \ + log_trace("%s", str); \ } while (0) -#define PUTCH(ch) \ - do { \ - debug_putch(ch); \ +#define PUTCH(ch) \ + do { \ + log_trace("%c", ch); \ } while (0) struct flag_table { diff --git a/LibOS/shim/src/sys/shim_alarm.c b/LibOS/shim/src/sys/shim_alarm.c index bdb989e0ea..a66392d165 100644 --- a/LibOS/shim/src/sys/shim_alarm.c +++ b/LibOS/shim/src/sys/shim_alarm.c @@ -23,7 +23,7 @@ static void signal_alarm(IDTYPE caller, void* arg) { .si_code = SI_USER, }; if (kill_current_proc(&info) < 0) { - debug("signal_alarm: failed to deliver a signal\n"); + log_warning("signal_alarm: failed to deliver a signal\n"); } } diff --git a/LibOS/shim/src/sys/shim_brk.c b/LibOS/shim/src/sys/shim_brk.c index 1339ffa2cc..51a1ae8852 100644 --- a/LibOS/shim/src/sys/shim_brk.c +++ b/LibOS/shim/src/sys/shim_brk.c @@ -31,7 +31,7 @@ int init_brk_region(void* brk_start, size_t data_segment_size) { int ret; if (!create_lock(&brk_lock)) { - debug("Creating brk_lock failed!\n"); + log_error("Creating brk_lock failed!\n"); return -ENOMEM; } @@ -48,16 +48,16 @@ int init_brk_region(void* brk_start, size_t data_segment_size) { ret = toml_sizestring_in(g_manifest_root, "sys.brk.max_size", DEFAULT_BRK_MAX_SIZE, &brk_max_size); if (ret < 0) { - debug("Cannot parse \'sys.brk.max_size\' (the value must be put in double quotes!)\n"); + log_error("Cannot parse \'sys.brk.max_size\' (the value must be put in double quotes!)\n"); return -EINVAL; } if (brk_start && !IS_ALLOC_ALIGNED_PTR(brk_start)) { - debug("Starting brk address is not aligned!\n"); + log_error("Starting brk address is not aligned!\n"); return -EINVAL; } if (!IS_ALLOC_ALIGNED(brk_max_size)) { - debug("Max brk size is not aligned!\n"); + log_error("Max brk size is not aligned!\n"); return -EINVAL; } diff --git a/LibOS/shim/src/sys/shim_clone.c b/LibOS/shim/src/sys/shim_clone.c index f4148c8db0..46b5fef814 100644 --- a/LibOS/shim/src/sys/shim_clone.c +++ b/LibOS/shim/src/sys/shim_clone.c @@ -250,7 +250,7 @@ long shim_do_clone(unsigned long flags, unsigned long user_stack_addr, int* pare CSIGNAL; if (flags & ~supported_flags) { - debug("clone called with unsupported flags argument.\n"); + log_warning("clone called with unsupported flags argument.\n"); return -EINVAL; } @@ -270,7 +270,7 @@ long shim_do_clone(unsigned long flags, unsigned long user_stack_addr, int* pare * explicitly disallowed for now. */ if (flags & CLONE_VM) { if (!((flags & CLONE_THREAD) || (flags & CLONE_VFORK))) { - debug("CLONE_VM without either CLONE_THREAD or CLONE_VFORK is unsupported\n"); + log_warning("CLONE_VM without either CLONE_THREAD or CLONE_VFORK is unsupported\n"); return -EINVAL; } } @@ -280,7 +280,8 @@ long shim_do_clone(unsigned long flags, unsigned long user_stack_addr, int* pare * corner-cases in signal handling and syscalls -- we simply treat vfork() as fork(). We * assume that performance hit is negligible (Graphene has to migrate internal state anyway * which is slow) and apps do not rely on insane Linux-specific semantics of vfork(). */ - debug("vfork was called by the application, implemented as an alias to fork in Graphene\n"); + log_warning("vfork was called by the application, implemented as an alias to fork in " + "Graphene\n"); flags &= ~(CLONE_VFORK | CLONE_VM); } diff --git a/LibOS/shim/src/sys/shim_epoll.c b/LibOS/shim/src/sys/shim_epoll.c index 830164f7dc..8ec8fe1fa1 100644 --- a/LibOS/shim/src/sys/shim_epoll.c +++ b/LibOS/shim/src/sys/shim_epoll.c @@ -184,7 +184,7 @@ long shim_do_epoll_ctl(int epfd, int op, int fd, struct __kernel_epoll_event* ev goto out; } - debug("add fd %d (handle %p) to epoll handle %p\n", fd, hdl, epoll); + log_debug("add fd %d (handle %p) to epoll handle %p\n", fd, hdl, epoll); epoll_item->fd = fd; epoll_item->events = event->events; epoll_item->data = event->data; @@ -216,7 +216,7 @@ long shim_do_epoll_ctl(int epfd, int op, int fd, struct __kernel_epoll_event* ev epoll_item->events = event->events; epoll_item->data = event->data; - debug("modified fd %d at epoll handle %p\n", fd, epoll); + log_debug("modified fd %d at epoll handle %p\n", fd, epoll); notify_epoll_waiters(epoll); goto out; } @@ -230,7 +230,7 @@ long shim_do_epoll_ctl(int epfd, int op, int fd, struct __kernel_epoll_event* ev LISTP_FOR_EACH_ENTRY(epoll_item, &epoll->fds, list) { if (epoll_item->fd == fd) { struct shim_handle* hdl = epoll_item->handle; - debug("delete fd %d (handle %p) from epoll handle %p\n", fd, hdl, epoll); + log_debug("delete fd %d (handle %p) from epoll handle %p\n", fd, hdl, epoll); /* unregister hdl (corresponding to FD) in epoll (corresponding to EPFD): * - unbind hdl from epoll-item via the `back` list @@ -464,7 +464,7 @@ BEGIN_CP_FUNC(epoll_item) { LISTP_TYPE(shim_epoll_item)* new_list = (LISTP_TYPE(shim_epoll_item)*)objp; struct shim_epoll_item* epoll_item; - debug("checkpoint epoll: %p -> %p (base = 0x%08lx)\n", old_list, new_list, base); + log_debug("checkpoint epoll: %p -> %p (base = 0x%08lx)\n", old_list, new_list, base); INIT_LISTP(new_list); diff --git a/LibOS/shim/src/sys/shim_eventfd.c b/LibOS/shim/src/sys/shim_eventfd.c index 8ec7ae9d96..998e05a06c 100644 --- a/LibOS/shim/src/sys/shim_eventfd.c +++ b/LibOS/shim/src/sys/shim_eventfd.c @@ -27,7 +27,7 @@ static int create_eventfd(PAL_HANDLE* efd, unsigned count, int flags) { ret = toml_int_in(g_manifest_root, "sys.insecure__allow_eventfd", /*defaultval=*/0, &allow_eventfd); if (ret < 0 || (allow_eventfd != 0 && allow_eventfd != 1)) { - debug("Cannot parse \'sys.insecure__allow_eventfd\' (the value must be 0 or 1)\n"); + log_error("Cannot parse \'sys.insecure__allow_eventfd\' (the value must be 0 or 1)\n"); return -ENOSYS; } @@ -46,7 +46,7 @@ static int create_eventfd(PAL_HANDLE* efd, unsigned count, int flags) { /* eventfd() requires count (aka initval) but PAL's DkStreamOpen() doesn't have such an * argument. Using create arg as a work-around (note: initval is uint32 but create is int32). */ if (!(hdl = DkStreamOpen(URI_PREFIX_EVENTFD, 0, 0, count, pal_flags))) { - debug("eventfd open failure\n"); + log_error("eventfd open failure\n"); return -PAL_ERRNO(); } diff --git a/LibOS/shim/src/sys/shim_exec.c b/LibOS/shim/src/sys/shim_exec.c index 897e4d51b7..e7999143c1 100644 --- a/LibOS/shim/src/sys/shim_exec.c +++ b/LibOS/shim/src/sys/shim_exec.c @@ -92,13 +92,13 @@ noreturn static void __shim_do_execve_rtld(struct execve_rtld_arg* __arg) { cur_thread->robust_list = NULL; - debug("execve: start execution\n"); + log_debug("execve: start execution\n"); /* Passing ownership of `exec` to `execute_elf_object`. */ execute_elf_object(exec, arg.new_argp, arg.new_auxv); /* NOTREACHED */ error: - debug("execve: failed %d\n", ret); + log_error("execve: failed %d\n", ret); process_exit(/*error_code=*/0, /*term_signal=*/SIGKILL); } @@ -283,7 +283,7 @@ long shim_do_execve(const char* file, const char** argv, const char** envp) { } while (!ended); if (!started) { - debug("file not recognized as ELF or shebang"); + log_warning("file not recognized as ELF or shebang"); put_handle(exec); return -ENOEXEC; } @@ -295,7 +295,7 @@ long shim_do_execve(const char* file, const char** argv, const char** envp) { struct sharg* first = LISTP_FIRST_ENTRY(&new_shargs, struct sharg, list); assert(first); - debug("detected as script: run by %s\n", first->arg); + log_debug("detected as script: run by %s\n", first->arg); file = first->arg; LISTP_SPLICE(&new_shargs, &shargs, list, sharg); put_handle(exec); diff --git a/LibOS/shim/src/sys/shim_exit.c b/LibOS/shim/src/sys/shim_exit.c index 4bd36a10f4..0cb3729b2a 100644 --- a/LibOS/shim/src/sys/shim_exit.c +++ b/LibOS/shim/src/sys/shim_exit.c @@ -40,7 +40,7 @@ static noreturn void libos_clean_and_exit(int exit_code) { store_all_msg_persist(); del_all_ipc_ports(); - debug("process %u exited with status %d\n", g_process_ipc_info.vmid, exit_code); + log_debug("process %u exited with status %d\n", g_process_ipc_info.vmid, exit_code); /* TODO: We exit whole libos, but there are some objects that might need cleanup, e.g. we should * release this (last) thread pid. We should do a proper cleanup of everything. */ @@ -66,8 +66,8 @@ noreturn void thread_exit(int error_code, int term_signal) { put_thread(cur_thread); if (ret < 0) { - debug("failed to set up async cleanup_thread (exiting without clear child tid)," - " return code: %ld\n", ret); + log_error("failed to set up async cleanup_thread (exiting without clear child tid)," + " return code: %ld\n", ret); /* `cleanup_thread` did not get this reference, clean it. We have to be careful, as * this is most likely the last reference and will free this `cur_thread`. */ put_thread(cur_thread); @@ -82,7 +82,7 @@ noreturn void thread_exit(int error_code, int term_signal) { /* This is the last thread of the process. Let parent know we exited. */ int ret = ipc_cld_exit_send(error_code, term_signal); if (ret < 0) { - debug("Sending IPC process-exit notification failed: %d\n", ret); + log_error("Sending IPC process-exit notification failed: %d\n", ret); } /* At this point other threads might be still in the middle of an exit routine, but we don't @@ -150,7 +150,7 @@ long shim_do_exit_group(int error_code) { error_code &= 0xFF; - debug("---- shim_exit_group (returning %d)\n", error_code); + log_debug("---- shim_exit_group (returning %d)\n", error_code); process_exit(error_code, 0); } @@ -160,7 +160,7 @@ long shim_do_exit(int error_code) { error_code &= 0xFF; - debug("---- shim_exit (returning %d)\n", error_code); + log_debug("---- shim_exit (returning %d)\n", error_code); thread_exit(error_code, 0); } diff --git a/LibOS/shim/src/sys/shim_fs.c b/LibOS/shim/src/sys/shim_fs.c index f2f315dc85..16ddd6837e 100644 --- a/LibOS/shim/src/sys/shim_fs.c +++ b/LibOS/shim/src/sys/shim_fs.c @@ -347,7 +347,7 @@ static ssize_t handle_copy(struct shim_handle* hdli, off_t* offseti, struct shim if (!do_mapi && (hdli->flags & O_NONBLOCK) && fsi->fs_ops->setflags) { int ret = fsi->fs_ops->setflags(hdli, 0); if (!ret) { - debug("mark handle %s as blocking\n", qstrgetstr(&hdli->uri)); + log_debug("mark handle %s as blocking\n", qstrgetstr(&hdli->uri)); do_marki = true; } } @@ -355,7 +355,7 @@ static ssize_t handle_copy(struct shim_handle* hdli, off_t* offseti, struct shim if (!do_mapo && (hdlo->flags & O_NONBLOCK) && fso->fs_ops->setflags) { int ret = fso->fs_ops->setflags(hdlo, 0); if (!ret) { - debug("mark handle %s as blocking\n", qstrgetstr(&hdlo->uri)); + log_debug("mark handle %s as blocking\n", qstrgetstr(&hdlo->uri)); do_marko = true; } } @@ -378,7 +378,7 @@ static ssize_t handle_copy(struct shim_handle* hdli, off_t* offseti, struct shim if ((hdli->flags & O_NONBLOCK) && fsi->fs_ops->setflags) { int ret = fsi->fs_ops->setflags(hdli, 0); if (!ret) { - debug("mark handle %s as blocking\n", qstrgetstr(&hdli->uri)); + log_debug("mark handle %s as blocking\n", qstrgetstr(&hdli->uri)); do_marki = true; } } @@ -397,7 +397,7 @@ static ssize_t handle_copy(struct shim_handle* hdli, off_t* offseti, struct shim if ((hdlo->flags & O_NONBLOCK) && fso->fs_ops->setflags) { int ret = fso->fs_ops->setflags(hdlo, 0); if (!ret) { - debug("mark handle %s as blocking\n", qstrgetstr(&hdlo->uri)); + log_debug("mark handle %s as blocking\n", qstrgetstr(&hdlo->uri)); do_marko = true; } } @@ -450,7 +450,7 @@ static ssize_t handle_copy(struct shim_handle* hdli, off_t* offseti, struct shim break; } - debug("copy %d bytes\n", copysize); + log_debug("copy %d bytes\n", copysize); bytes += copysize; offi += copysize; offo += copysize; @@ -472,12 +472,12 @@ static ssize_t handle_copy(struct shim_handle* hdli, off_t* offseti, struct shim } if (do_marki && (hdli->flags & O_NONBLOCK)) { - debug("mark handle %s as nonblocking\n", qstrgetstr(&hdli->uri)); + log_debug("mark handle %s as nonblocking\n", qstrgetstr(&hdli->uri)); fsi->fs_ops->setflags(hdli, O_NONBLOCK); } if (do_marko && (hdlo->flags & O_NONBLOCK)) { - debug("mark handle %s as nonblocking\n", qstrgetstr(&hdlo->uri)); + log_debug("mark handle %s as nonblocking\n", qstrgetstr(&hdlo->uri)); fso->fs_ops->setflags(hdlo, O_NONBLOCK); } diff --git a/LibOS/shim/src/sys/shim_futex.c b/LibOS/shim/src/sys/shim_futex.c index 765b68d8c0..30f8573502 100644 --- a/LibOS/shim/src/sys/shim_futex.c +++ b/LibOS/shim/src/sys/shim_futex.c @@ -746,11 +746,12 @@ static int _shim_do_futex(uint32_t* uaddr, int op, uint32_t val, void* utime, ui return -ENOSYS; } /* Graphene has only one clock for now. */ - debug("Ignoring FUTEX_CLOCK_REALTIME flag\n"); + log_warning("Ignoring FUTEX_CLOCK_REALTIME flag\n"); } if (!(op & FUTEX_PRIVATE_FLAG)) { - debug("Non-private futexes are not supported, assuming implicit FUTEX_PRIVATE_FLAG\n"); + log_warning("Non-private futexes are not supported, assuming implicit " + "FUTEX_PRIVATE_FLAG\n"); } int ret = 0; @@ -795,10 +796,10 @@ static int _shim_do_futex(uint32_t* uaddr, int op, uint32_t val, void* utime, ui case FUTEX_UNLOCK_PI: case FUTEX_CMP_REQUEUE_PI: case FUTEX_WAIT_REQUEUE_PI: - debug("PI futexes are not yet supported!\n"); + log_warning("PI futexes are not yet supported!\n"); return -ENOSYS; default: - debug("Invalid futex op: %d\n", cmd); + log_warning("Invalid futex op: %d\n", cmd); return -ENOSYS; } } diff --git a/LibOS/shim/src/sys/shim_getcwd.c b/LibOS/shim/src/sys/shim_getcwd.c index 0b2973bf16..f480b10d7d 100644 --- a/LibOS/shim/src/sys/shim_getcwd.c +++ b/LibOS/shim/src/sys/shim_getcwd.c @@ -71,7 +71,7 @@ long shim_do_chdir(const char* filename) { if (!(dent->state & DENTRY_ISDIRECTORY)) { char buffer[dentry_get_path_size(dent)]; - debug("%s is not a directory\n", dentry_get_path(dent, buffer)); + log_debug("%s is not a directory\n", dentry_get_path(dent, buffer)); put_dentry(dent); return -ENOTDIR; } @@ -93,7 +93,7 @@ long shim_do_fchdir(int fd) { if (!(dent->state & DENTRY_ISDIRECTORY)) { char buffer[dentry_get_path_size(dent)]; - debug("%s is not a directory\n", dentry_get_path(dent, buffer)); + log_debug("%s is not a directory\n", dentry_get_path(dent, buffer)); put_handle(hdl); return -ENOTDIR; } diff --git a/LibOS/shim/src/sys/shim_ioctl.c b/LibOS/shim/src/sys/shim_ioctl.c index 5fe4ed2c5e..d49f6b2c7f 100644 --- a/LibOS/shim/src/sys/shim_ioctl.c +++ b/LibOS/shim/src/sys/shim_ioctl.c @@ -25,7 +25,7 @@ static void signal_io(IDTYPE caller, void* arg) { .si_fd = 0, }; if (kill_current_proc(&info) < 0) { - debug("signal_io: failed to deliver a signal\n"); + log_warning("signal_io: failed to deliver a signal\n"); } } diff --git a/LibOS/shim/src/sys/shim_mmap.c b/LibOS/shim/src/sys/shim_mmap.c index cb12cdaf32..636d81b990 100644 --- a/LibOS/shim/src/sys/shim_mmap.c +++ b/LibOS/shim/src/sys/shim_mmap.c @@ -176,7 +176,7 @@ void* shim_do_mmap(void* addr, size_t length, int prot, int flags, int fd, off_t void* ret_addr = addr; ret = hdl->fs->fs_ops->mmap(hdl, &ret_addr, length, prot, flags, offset); if (ret_addr != addr) { - debug("Requested address (%p) differs from allocated (%p)!\n", addr, ret_addr); + log_error("Requested address (%p) differs from allocated (%p)!\n", addr, ret_addr); BUG(); } } @@ -184,8 +184,9 @@ void* shim_do_mmap(void* addr, size_t length, int prot, int flags, int fd, off_t if (ret < 0) { void* tmp_vma = NULL; if (bkeep_munmap(addr, length, /*is_internal=*/false, &tmp_vma) < 0) { - debug("[mmap] Failed to remove bookkeeped memory that was not allocated at %p-%p!\n", - addr, (char*)addr + length); + log_error( + "[mmap] Failed to remove bookkeeped memory that was not allocated at %p-%p!\n", + addr, (char*)addr + length); BUG(); } bkeep_remove_tmp_vma(tmp_vma); @@ -251,7 +252,8 @@ long shim_do_mprotect(void* addr, size_t length, int prot) { put_handle(vma_info.file); } } else { - warn("Memory that was about to be mprotected was unmapped, your program is buggy!\n"); + log_warning("Memory that was about to be mprotected was unmapped, your program is " + "buggy!\n"); return -ENOTRECOVERABLE; } } @@ -311,7 +313,8 @@ long shim_do_mincore(void* addr, size_t len, unsigned char* vec) { static atomic_bool warned = false; if (!warned) { warned = true; - warn("mincore emulation always tells pages are _NOT_ in RAM. This may cause issues.\n"); + log_warning( + "mincore emulation always tells pages are _NOT_ in RAM. This may cause issues.\n"); } /* There is no good way to know if the page is in RAM. diff --git a/LibOS/shim/src/sys/shim_msgget.c b/LibOS/shim/src/sys/shim_msgget.c index 3942f3520d..e1cc25c16e 100644 --- a/LibOS/shim/src/sys/shim_msgget.c +++ b/LibOS/shim/src/sys/shim_msgget.c @@ -680,7 +680,7 @@ static int __store_msg_persist(struct shim_msg_handle* msgq) { if (msgq->deleted) goto out; - debug("store msgq %d to persistent store\n", msgq->msqid); + log_debug("store msgq %d to persistent store\n", msgq->msqid); char fileuri[20]; snprintf(fileuri, 20, URI_PREFIX_FILE "msgq.%08x", msgq->msqid); diff --git a/LibOS/shim/src/sys/shim_pipe.c b/LibOS/shim/src/sys/shim_pipe.c index 201815ee54..2ee40a67eb 100644 --- a/LibOS/shim/src/sys/shim_pipe.c +++ b/LibOS/shim/src/sys/shim_pipe.c @@ -31,19 +31,19 @@ static int create_pipes(struct shim_handle* srv, struct shim_handle* cli, int fl if ((ret = create_pipe(name, uri, PIPE_URI_SIZE, &hdl0, qstr, /*use_vmid_for_name=*/false)) < 0) { - debug("pipe creation failure\n"); + log_error("pipe creation failure\n"); return ret; } if (!(hdl2 = DkStreamOpen(uri, 0, 0, 0, LINUX_OPEN_FLAGS_TO_PAL_OPTIONS(flags)))) { ret = -PAL_ERRNO(); - debug("pipe connection failure\n"); + log_error("pipe connection failure\n"); goto out; } if (!(hdl1 = DkStreamWaitForClient(hdl0))) { ret = -PAL_ERRNO(); - debug("pipe acception failure\n"); + log_error("pipe acceptation failure\n"); goto out; } @@ -87,7 +87,7 @@ long shim_do_pipe2(int* filedes, int flags) { int ret = 0; if (flags & O_DIRECT) { - debug("shim_do_pipe2(): ignoring a not supported O_DIRECT flag\n"); + log_warning("shim_do_pipe2(): ignoring not supported O_DIRECT flag\n"); flags &= ~O_DIRECT; } diff --git a/LibOS/shim/src/sys/shim_sched.c b/LibOS/shim/src/sys/shim_sched.c index 65fd39098d..52d831993f 100644 --- a/LibOS/shim/src/sys/shim_sched.c +++ b/LibOS/shim/src/sys/shim_sched.c @@ -185,8 +185,8 @@ long shim_do_sched_getaffinity(pid_t pid, unsigned int cpumask_size, unsigned lo * to sizeof(long) */ size_t bitmask_size_in_bytes = BITS_TO_LONGS(cpu_cnt) * sizeof(long); if (cpumask_size < bitmask_size_in_bytes) { - debug("size of cpumask must be at least %lu but supplied cpumask is %u\n", - bitmask_size_in_bytes, cpumask_size); + log_warning("size of cpumask must be at least %lu but supplied cpumask is %u\n", + bitmask_size_in_bytes, cpumask_size); return -EINVAL; } diff --git a/LibOS/shim/src/sys/shim_semget.c b/LibOS/shim/src/sys/shim_semget.c index 130ef9378d..cbab120c23 100644 --- a/LibOS/shim/src/sys/shim_semget.c +++ b/LibOS/shim/src/sys/shim_semget.c @@ -441,26 +441,26 @@ static bool __handle_sysv_sems(struct shim_sem_handle* sem) { again: if (op->sem_op > 0) { sobj->val += op->sem_op; - debug("sem %u: add %u => %u\n", sobj->num, op->sem_op, sobj->val); + log_debug("sem %u: add %u => %u\n", sobj->num, op->sem_op, sobj->val); } else if (op->sem_op < 0) { if (sobj->val < -op->sem_op) { if (op->sem_flg & IPC_NOWAIT) { - debug("sem %u: wait for %u failed\n", sobj->num, -op->sem_op); + log_error("sem %u: wait for %u failed\n", sobj->num, -op->sem_op); goto failed; } continue; } sobj->val -= -op->sem_op; - debug("sem %u: wait for %u => %u\n", sobj->num, -op->sem_op, sobj->val); + log_debug("sem %u: wait for %u => %u\n", sobj->num, -op->sem_op, sobj->val); } else { if (sobj->val) { if (op->sem_flg & IPC_NOWAIT) { - debug("sem %u: wait for 0 failed\n", sobj->num); + log_error("sem %u: wait for 0 failed\n", sobj->num); goto failed; } continue; } - debug("sem %u: wait for 0\n", sobj->num); + log_debug("sem %u: wait for 0\n", sobj->num); } progressed = true; @@ -526,30 +526,30 @@ static void __handle_one_sysv_sem(struct shim_sem_handle* sem, struct sem_stat* if (op->sem_op > 0) { progressed = true; sobj->val += op->sem_op; - debug("sem %u: add %u => %u\n", sobj->num, op->sem_op, sobj->val); + log_debug("sem %u: add %u => %u\n", sobj->num, op->sem_op, sobj->val); } else if (op->sem_op < 0) { if (sobj->val < -op->sem_op) { if (op->sem_flg & IPC_NOWAIT) { stat->failed = true; - debug("sem %u: wait for %u failed\n", sobj->num, -op->sem_op); + log_error("sem %u: wait for %u failed\n", sobj->num, -op->sem_op); return; } goto failed; } progressed = true; sobj->val -= -op->sem_op; - debug("sem %u: wait for %u => %u\n", sobj->num, -op->sem_op, sobj->val); + log_debug("sem %u: wait for %u => %u\n", sobj->num, -op->sem_op, sobj->val); } else { if (sobj->val) { if (op->sem_flg & IPC_NOWAIT) { stat->failed = true; - debug("sem %u: wait for 0 failed\n", sobj->num); + log_error("sem %u: wait for 0 failed\n", sobj->num); return; } goto failed; } progressed = true; - debug("sem %u: wait for 0\n", sobj->num); + log_debug("sem %u: wait for 0\n", sobj->num); } stat->current++; diff --git a/LibOS/shim/src/sys/shim_sigaction.c b/LibOS/shim/src/sys/shim_sigaction.c index 1a01b42f56..58967c2dbb 100644 --- a/LibOS/shim/src/sys/shim_sigaction.c +++ b/LibOS/shim/src/sys/shim_sigaction.c @@ -43,7 +43,7 @@ long shim_do_rt_sigaction(int signum, const struct __kernel_sigaction* act, if (act && !(act->sa_flags & SA_RESTORER)) { /* XXX: This might not be true for all architectures (but is for x86_64)... * Check `shim_signal.c` if you update this! */ - debug("SA_RESTORER flag is required!\n"); + log_warning("rt_sigaction: SA_RESTORER flag is required!\n"); return -EINVAL; } diff --git a/LibOS/shim/src/sys/shim_sleep.c b/LibOS/shim/src/sys/shim_sleep.c index e876eae4ef..738b185082 100644 --- a/LibOS/shim/src/sys/shim_sleep.c +++ b/LibOS/shim/src/sys/shim_sleep.c @@ -51,7 +51,7 @@ long shim_do_clock_nanosleep(clockid_t clock_id, int flags, const struct __kerne return -EINVAL; if (flags) { - debug("Graphene's clock_nanosleep does not support non-zero flags (%d)\n", flags); + log_warning("Graphene's clock_nanosleep does not support non-zero flags (0x%x)\n", flags); return -EINVAL; } diff --git a/LibOS/shim/src/sys/shim_socket.c b/LibOS/shim/src/sys/shim_socket.c index 28c5c099ae..b9c7946f40 100644 --- a/LibOS/shim/src/sys/shim_socket.c +++ b/LibOS/shim/src/sys/shim_socket.c @@ -85,7 +85,7 @@ long shim_do_socket(int family, int type, int protocol) { break; default: - debug("shim_socket: unknown socket domain %d\n", sock->domain); + log_warning("shim_socket: unknown socket domain %d\n", sock->domain); goto err; } @@ -97,7 +97,7 @@ long shim_do_socket(int family, int type, int protocol) { break; default: - debug("shim_socket: unknown socket type %d\n", sock->sock_type); + log_warning("shim_socket: unknown socket type %d\n", sock->sock_type); goto err; } @@ -260,7 +260,7 @@ static inline void unix_copy_addr(struct sockaddr* saddr, struct shim_dentry* de dentry_get_path(dent, path); if (size > ARRAY_SIZE(un->sun_path)) { - debug("unix_copy_addr(): path too long, truncating: %s\n", path); + log_warning("unix_copy_addr(): path too long, truncating: %s\n", path); memcpy(un->sun_path, path, ARRAY_SIZE(un->sun_path) - 1); un->sun_path[ARRAY_SIZE(un->sun_path) - 1] = 0; } else { @@ -425,7 +425,7 @@ long shim_do_bind(int sockfd, struct sockaddr* addr, int _addrlen) { enum shim_sock_state state = sock->sock_state; if (state != SOCK_CREATED) { - debug("shim_bind: bind on a bound socket\n"); + log_debug("shim_bind: bind on a bound socket\n"); goto out; } @@ -481,7 +481,7 @@ long shim_do_bind(int sockfd, struct sockaddr* addr, int _addrlen) { if (!pal_hdl) { ret = (PAL_NATIVE_ERRNO() == PAL_ERROR_STREAMEXIST) ? -EADDRINUSE : -PAL_ERRNO(); - debug("bind: invalid handle returned\n"); + log_error("bind: invalid handle returned\n"); goto out; } @@ -616,7 +616,7 @@ long shim_do_listen(int sockfd, int backlog) { struct shim_sock_handle* sock = &hdl->info.sock; if (sock->sock_type != SOCK_STREAM) { - debug("shim_listen: not a stream socket\n"); + log_warning("shim_listen: not a stream socket\n"); put_handle(hdl); return -EINVAL; } @@ -627,7 +627,7 @@ long shim_do_listen(int sockfd, int backlog) { int ret = -EINVAL; if (state != SOCK_BOUND && state != SOCK_LISTENED) { - debug("shim_listen: listen on unbound socket\n"); + log_warning("shim_listen: listen on unbound socket\n"); goto out; } @@ -685,18 +685,18 @@ long shim_do_connect(int sockfd, struct sockaddr* addr, int _addrlen) { hdl->pal_handle = NULL; pal_handle_updated = true; } - debug("shim_connect: reconnect on a stream socket\n"); + log_debug("shim_connect: reconnect on a stream socket\n"); ret = 0; goto out; } - debug("shim_connect: reconnect on a stream socket\n"); + log_debug("shim_connect: reconnect on a stream socket\n"); ret = -EISCONN; goto out; } if (state != SOCK_BOUND && state != SOCK_CREATED) { - debug("shim_connect: connect on invalid socket\n"); + log_warning("shim_connect: connect on invalid socket\n"); goto out; } @@ -826,7 +826,7 @@ static int __do_accept(struct shim_handle* hdl, int flags, struct sockaddr* addr PAL_HANDLE accepted = NULL; if (sock->sock_type != SOCK_STREAM) { - debug("shim_accept: not a stream socket\n"); + log_warning("shim_accept: not a stream socket\n"); return -EOPNOTSUPP; } @@ -845,7 +845,7 @@ static int __do_accept(struct shim_handle* hdl, int flags, struct sockaddr* addr PAL_HANDLE handle = hdl->pal_handle; if (sock->sock_state != SOCK_LISTENED) { - debug("shim_accept: invalid socket\n"); + log_warning("shim_accept: invalid socket\n"); ret = -EINVAL; goto out; } @@ -866,7 +866,7 @@ static int __do_accept(struct shim_handle* hdl, int flags, struct sockaddr* addr assert(hdl->pal_handle == handle); if (sock->sock_state != SOCK_LISTENED) { - debug("shim_accept: socket changed while waiting for a client connection\n"); + log_debug("shim_accept: socket changed while waiting for a client connection\n"); ret = -ECONNABORTED; goto out; } @@ -991,8 +991,8 @@ static ssize_t do_sendmsg(int fd, struct iovec* bufs, int nbufs, int flags, goto out; if (flags & ~(MSG_NOSIGNAL | MSG_DONTWAIT)) { - debug("sendmsg()/sendmmsg()/sendto(): unknown flag (only MSG_NOSIGNAL and MSG_DONTWAIT" - " are supported).\n"); + log_warning("sendmsg()/sendmmsg()/sendto(): unknown flag (only MSG_NOSIGNAL and " + "MSG_DONTWAIT are supported).\n"); ret = -EOPNOTSUPP; goto out; } @@ -1010,8 +1010,8 @@ static ssize_t do_sendmsg(int fd, struct iovec* bufs, int nbufs, int flags, if (flags & MSG_DONTWAIT) { if (!(hdl->flags & O_NONBLOCK)) { - debug("Warning: MSG_DONTWAIT on blocking socket is ignored, may lead to a write that" - " unexpectedly blocks.\n"); + log_warning("Warning: MSG_DONTWAIT on blocking socket is ignored, may lead to a write " + "that unexpectedly blocks.\n"); } flags &= ~MSG_DONTWAIT; } @@ -1077,7 +1077,7 @@ static ssize_t do_sendmsg(int fd, struct iovec* bufs, int nbufs, int flags, goto out_locked; } - debug("next packet send to %s\n", uri); + log_debug("next packet send to %s\n", uri); } int bytes = 0; @@ -1094,7 +1094,7 @@ static ssize_t do_sendmsg(int fd, struct iovec* bufs, int nbufs, int flags, .si_code = SI_USER, }; if (kill_current_proc(&info) < 0) { - debug("do_sendmsg: failed to deliver a signal\n"); + log_error("do_sendmsg: failed to deliver a signal\n"); } } @@ -1239,8 +1239,8 @@ static ssize_t do_recvmsg(int fd, struct iovec* bufs, size_t nbufs, int flags, } if (flags & ~(MSG_PEEK | MSG_DONTWAIT | MSG_WAITALL)) { - debug("recvmsg()/recvmmsg()/recvfrom(): unknown flag (only MSG_PEEK, MSG_DONTWAIT and" - " MSG_WAITALL are supported).\n"); + log_warning("recvmsg()/recvmmsg()/recvfrom(): unknown flag (only MSG_PEEK, MSG_DONTWAIT and" + " MSG_WAITALL are supported).\n"); ret = -EOPNOTSUPP; goto out; } @@ -1248,15 +1248,15 @@ static ssize_t do_recvmsg(int fd, struct iovec* bufs, size_t nbufs, int flags, lock(&hdl->lock); if (flags & MSG_WAITALL) { - log_debug("recvmsg()/recvmmsg()/recvfrom(): MSG_WAITALL is ignored, may lead to a read" - " that returns less data.\n"); + log_warning("recvmsg()/recvmmsg()/recvfrom(): MSG_WAITALL is ignored, may lead to a read" + " that returns less data.\n"); flags &= ~MSG_WAITALL; } if (flags & MSG_DONTWAIT) { if (!(hdl->flags & O_NONBLOCK)) { - debug("Warning: MSG_DONTWAIT on blocking socket is ignored, may lead to a read that" - " unexpectedly blocks.\n"); + log_warning("Warning: MSG_DONTWAIT on blocking socket is ignored, may lead to a read " + "that unexpectedly blocks.\n"); } flags &= ~MSG_DONTWAIT; } @@ -1383,7 +1383,7 @@ static ssize_t do_recvmsg(int fd, struct iovec* bufs, size_t nbufs, int flags, goto out_locked; } - debug("last packet received from %s\n", uri); + log_debug("last packet received from %s\n", uri); inet_rebase_port(true, sock->domain, &conn, false); *addrlen = inet_copy_addr(sock->domain, addr, *addrlen, &conn); @@ -1506,7 +1506,7 @@ long shim_do_recvmmsg(int sockfd, struct mmsghdr* msg, unsigned int vlen, int fl // Issue # 753 - https://github.com/oscarlab/graphene/issues/753 /* TODO(donporter): timeout properly. For now, explicitly return an error. */ if (timeout) { - debug("recvmmsg(): timeout parameter unsupported.\n"); + log_warning("recvmmsg(): timeout parameter unsupported.\n"); return -EOPNOTSUPP; } diff --git a/LibOS/shim/src/sys/shim_stat.c b/LibOS/shim/src/sys/shim_stat.c index 648f12081f..c52f1abd4a 100644 --- a/LibOS/shim/src/sys/shim_stat.c +++ b/LibOS/shim/src/sys/shim_stat.c @@ -156,7 +156,7 @@ static int __do_statfs(struct shim_mount* fs, struct statfs* buf) { buf->f_bfree = 10000000; buf->f_bavail = 10000000; - debug("statfs: %ld %ld %ld\n", buf->f_blocks, buf->f_bfree, buf->f_bavail); + log_debug("statfs: %ld %ld %ld\n", buf->f_blocks, buf->f_bfree, buf->f_bavail); return 0; } @@ -199,7 +199,7 @@ long shim_do_newfstatat(int dirfd, const char* pathname, struct stat* statbuf, i lookup_flags &= ~LOOKUP_FOLLOW; if (flags & AT_NO_AUTOMOUNT) { /* Do nothing as automount isn't supported */ - debug("ignoring AT_NO_AUTOMOUNT."); + log_warning("newfstatat: ignoring AT_NO_AUTOMOUNT."); } int ret = 0; diff --git a/LibOS/shim/src/sys/shim_wait.c b/LibOS/shim/src/sys/shim_wait.c index 83a921749a..31fd238f6f 100644 --- a/LibOS/shim/src/sys/shim_wait.c +++ b/LibOS/shim/src/sys/shim_wait.c @@ -99,17 +99,17 @@ static long do_waitid(int which, pid_t id, siginfo_t* infop, int options) { } if (options & WSTOPPED) { - debug("Ignoring unsupported WSTOPPED flag to wait4\n"); + log_warning("Ignoring unsupported WSTOPPED flag to wait4\n"); options &= ~WSTOPPED; } if (options & WCONTINUED) { - debug("Ignoring unsupported WCONTINUED flag to wait4\n"); + log_warning("Ignoring unsupported WCONTINUED flag to wait4\n"); options &= ~WCONTINUED; } assert(options & WEXITED); if (options & __WNOTHREAD) { - debug("Ignoring unsupported __WNOTHREAD flag to wait4\n"); + log_warning("Ignoring unsupported __WNOTHREAD flag to wait4\n"); options &= ~__WNOTHREAD; } @@ -187,7 +187,7 @@ static long do_waitid(int which, pid_t id, siginfo_t* infop, int options) { } ret = thread_sleep(NO_TIMEOUT, /*ignore_pending_signals=*/false); if (ret < 0 && ret != -EINTR && ret != -EAGAIN) { - debug("thread_sleep failed in waitid\n"); + log_warning("thread_sleep failed in waitid\n"); remove_qnode_from_wait_queue(&qnode); /* `ret` is already set. */ goto out;