diff --git a/Makefile b/Makefile index f896206a..694631d3 100644 --- a/Makefile +++ b/Makefile @@ -28,6 +28,10 @@ $(call set-feature, MOP_FUSION) ENABLE_BLOCK_CHAINING ?= 1 $(call set-feature, BLOCK_CHAINING) +# Enable logging with color +ENABLE_LOG_COLOR ?= 1 +$(call set-feature, LOG_COLOR) + # Enable system emulation ENABLE_SYSTEM ?= 0 $(call set-feature, SYSTEM) @@ -293,6 +297,7 @@ OBJS := \ syscall.o \ emulate.o \ riscv.o \ + log.o \ elf.o \ cache.o \ mpool.o \ @@ -347,54 +352,48 @@ EXPECTED_puzzle = success in 2005 trials EXPECTED_fcalc = Performed 12 tests, 0 failures, 100% success rate. EXPECTED_pi = 3.141592653589793238462643383279502884197169399375105820974944592307816406286208998628034825342117067982148086 +LOG_FILTER=sed -E '/^[0-9]{2}:[0-9]{2}:[0-9]{2} /d' + +define exec +$(eval OUTPUT_FILE := $(shell mktemp)) +$(eval _ := $(shell LC_ALL=C $(BIN) $(1) $(2) > $(OUTPUT_FILE))) +$(eval RC := $(.SHELLSTATUS)) +endef + +# $(1): rv32emu's extra CLI parameter +# $(2): ELF executable +# $(3): ELF executable name +# $(4): extra command in the pipeline +# $(5): expected output +define check-test +$(call exec, $(1), $(2)) +$(Q)$(PRINTF) "Running $(3) ... "; \ +if [ 0 -eq $(RC) ] && [ "$(strip $(shell cat $(OUTPUT_FILE) | $(LOG_FILTER) | $(4)))" = "$(strip $(5))" ]; then \ + $(call notice, [OK]); \ +else \ + $(PRINTF) "Failed.\n"; \ + exit 1; \ +fi; \ +$(RM) $(OUTPUT_FILE) +endef + check-hello: $(BIN) - $(Q)$(PRINTF) "Running hello.elf ... "; \ - if [ "$(shell LC_ALL=C $(BIN) $(OUT)/hello.elf | uniq)" = "$(strip $(EXPECTED_hello)) inferior exit code 0" ]; then \ - $(call notice, [OK]); \ - else \ - $(PRINTF) "Failed.\n"; \ - exit 1; \ - fi; + $(call check-test, , $(OUT)/hello.elf, hello.elf, uniq, $(EXPECTED_hello)) check: $(BIN) check-hello artifact - $(Q)$(foreach e,$(CHECK_ELF_FILES),\ - $(PRINTF) "Running $(e) ... "; \ - if [ "$(shell LC_ALL=C $(BIN) $(OUT)/riscv32/$(e) | uniq)" = "$(strip $(EXPECTED_$(e))) inferior exit code 0" ]; then \ - $(call notice, [OK]); \ - else \ - $(PRINTF) "Failed.\n"; \ - exit 1; \ - fi; \ - ) - -EXPECTED_aes_sha1 = 1242a6757c8aef23e50b5264f5941a2f4b4a347e - + $(Q)$(foreach e, $(CHECK_ELF_FILES), $(call check-test, , $(OUT)/riscv32/$(e), $(e), uniq, $(EXPECTED_$(e)))) + +EXPECTED_aes_sha1 = 89169ec034bec1c6bb2c556b26728a736d350ca3 - misalign: $(BIN) artifact - $(Q)$(PRINTF) "Running uaes ... "; - $(Q)if [ "$(shell LC_ALL=C $(BIN) -m $(OUT)/riscv32/uaes | $(SHA1SUM))" = "$(EXPECTED_aes_sha1)" ]; then \ - $(call notice, [OK]); \ - else \ - $(PRINTF) "Failed.\n"; \ - fi + $(call check-test, -m, $(OUT)/riscv32/uaes, uaes.elf, $(SHA1SUM), $(EXPECTED_aes_sha1)) EXPECTED_misalign = MISALIGNED INSTRUCTION FETCH TEST PASSED! misalign-in-blk-emu: $(BIN) - $(Q)$(PRINTF) "Running misalign.elf ... "; \ - if [ "$(shell LC_ALL=C $(BIN) tests/system/alignment/misalign.elf | tail -n 2)" = "$(strip $(EXPECTED_misalign)) inferior exit code 0" ]; then \ - $(call notice, [OK]); \ - else \ - $(PRINTF) "Failed.\n"; \ - exit 1; \ - fi; + $(call check-test, , tests/system/alignment/misalign.elf, misalign.elf, tail -n 1, $(EXPECTED_misalign)) EXPECTED_mmu = STORE PAGE FAULT TEST PASSED! mmu-test: $(BIN) - $(Q)$(PRINTF) "Running vm.elf ... "; \ - if [ "$(shell LC_ALL=C $(BIN) tests/system/mmu/vm.elf | tail -n 2)" = "$(strip $(EXPECTED_mmu)) inferior exit code 0" ]; then \ - $(call notice, [OK]); \ - else \ - $(PRINTF) "Failed.\n"; \ - exit 1; \ - fi; + $(call check-test, , tests/system/mmu/vm.elf, vm.elf, tail -n 1, $(EXPECTED_mmu)) # Non-trivial demonstration programs ifeq ($(call has, SDL), 1) diff --git a/README.md b/README.md index 4b7ee4e5..43f346b5 100644 --- a/README.md +++ b/README.md @@ -155,6 +155,7 @@ The image containing all the necessary tools for development and testing can be * `ENABLE_SYSTEM`: Experimental system emulation, allowing booting Linux kernel. To enable this feature, additional features must also be enabled. However, by default, when `ENABLE_SYSTEM` is enabled, CSR, fence, integer multiplication/division, and atomic Instructions are automatically enabled * `ENABLE_MOP_FUSION` : Macro-operation fusion * `ENABLE_BLOCK_CHAINING` : Block chaining of translated blocks +* `ENABLE_LOG_COLOR` : Logging with colors (default) e.g., run `make ENABLE_EXT_F=0` for the build without floating-point support. diff --git a/src/common.h b/src/common.h index 838b6552..bce9f0f2 100644 --- a/src/common.h +++ b/src/common.h @@ -9,6 +9,7 @@ #include #include "feature.h" +#include "log.h" #if defined(__GNUC__) || defined(__clang__) #define UNUSED __attribute__((unused)) diff --git a/src/devices/uart.c b/src/devices/uart.c index 69bed7d1..a373f976 100644 --- a/src/devices/uart.c +++ b/src/devices/uart.c @@ -47,7 +47,7 @@ void u8250_check_ready(u8250_state_t *uart) static void u8250_handle_out(u8250_state_t *uart, uint8_t value) { if (write(uart->out_fd, &value, 1) < 1) - fprintf(stderr, "failed to write UART output: %s\n", strerror(errno)); + rv_log_error("Failed to write UART output: %s", strerror(errno)); } static uint8_t u8250_handle_in(u8250_state_t *uart) @@ -58,13 +58,13 @@ static uint8_t u8250_handle_in(u8250_state_t *uart) return value; if (read(uart->in_fd, &value, 1) < 0) - fprintf(stderr, "failed to read UART input: %s\n", strerror(errno)); + rv_log_error("Failed to read UART input: %s", strerror(errno)); uart->in_ready = false; u8250_check_ready(uart); if (value == 1) { /* start of heading (Ctrl-a) */ if (getchar() == 120) { /* keyboard x */ - printf("\n"); /* end emulator with newline */ + rv_log_info("RISC-V emulator is destroyed"); exit(EXIT_SUCCESS); } } diff --git a/src/devices/virtio-blk.c b/src/devices/virtio-blk.c index 94af5ea1..45f7d52f 100644 --- a/src/devices/virtio-blk.c +++ b/src/devices/virtio-blk.c @@ -190,7 +190,7 @@ static int virtio_blk_desc_handler(virtio_blk_state_t *vblk, virtio_blk_write_handler(vblk, sector, vq_desc[1].addr, vq_desc[1].len); break; default: - fprintf(stderr, "unsupported virtio-blk operation!\n"); + rv_log_error("Unsupported virtio-blk operation"); *status = VIRTIO_BLK_S_UNSUPP; return -1; } @@ -215,7 +215,7 @@ static void virtio_queue_notify_handler(virtio_blk_state_t *vblk, int index) /* Check for new buffers */ uint16_t new_avail = ram[queue->queue_avail] >> 16; if (new_avail - queue->last_avail > (uint16_t) queue->queue_num) { - fprintf(stderr, "size check fail\n"); + rv_log_error("Size check fail"); return virtio_blk_set_fail(vblk); } @@ -374,9 +374,8 @@ void virtio_blk_write(virtio_blk_state_t *vblk, uint32_t addr, uint32_t value) uint32_t *virtio_blk_init(virtio_blk_state_t *vblk, char *disk_file) { if (vblk_dev_cnt >= VBLK_DEV_CNT_MAX) { - fprintf(stderr, - "Exceeded the number of virtio-blk devices that can be " - "allocated.\n"); + rv_log_error( + "Exceeded the number of virtio-blk devices that can be allocated"); exit(EXIT_FAILURE); } @@ -394,7 +393,7 @@ uint32_t *virtio_blk_init(virtio_blk_state_t *vblk, char *disk_file) /* Open disk file */ int disk_fd = open(disk_file, O_RDWR); if (disk_fd < 0) { - fprintf(stderr, "could not open %s\n", disk_file); + rv_log_error("Could not open %s", disk_file); exit(EXIT_FAILURE); } @@ -408,16 +407,12 @@ uint32_t *virtio_blk_init(virtio_blk_state_t *vblk, char *disk_file) #if HAVE_MMAP disk_mem = mmap(NULL, VBLK_PRIV(vblk)->disk_size, PROT_READ | PROT_WRITE, MAP_SHARED, disk_fd, 0); - if (disk_mem == MAP_FAILED) { - fprintf(stderr, "Could not map disk\n"); - return NULL; - } + if (disk_mem == MAP_FAILED) + goto err; #else disk_mem = malloc(VBLK_PRIV(vblk)->disk_size); - if (!disk_mem) { - fprintf(stderr, "Could not map disk\n"); - return NULL; - } + if (!disk_mem) + goto err; #endif assert(!(((uintptr_t) disk_mem) & 0b11)); close(disk_fd); @@ -427,6 +422,10 @@ uint32_t *virtio_blk_init(virtio_blk_state_t *vblk, char *disk_file) (VBLK_PRIV(vblk)->disk_size - 1) / DISK_BLK_SIZE + 1; return disk_mem; + +err: + rv_log_error("Could not map disk %s", disk_file); + return NULL; } virtio_blk_state_t *vblk_new() diff --git a/src/emulate.c b/src/emulate.c index 76df73e0..73aff57f 100644 --- a/src/emulate.c +++ b/src/emulate.c @@ -1131,7 +1131,6 @@ void rv_step(void *arg) #ifdef __EMSCRIPTEN__ if (rv_has_halted(rv)) { - printf("inferior exit code %d\n", attr->exit_code); emscripten_cancel_main_loop(); rv_delete(rv); /* clean up and reuse memory */ } @@ -1346,7 +1345,7 @@ void dump_registers(riscv_t *rv, char *out_file_path) { FILE *f = out_file_path[0] == '-' ? stdout : fopen(out_file_path, "w"); if (!f) { - fprintf(stderr, "Cannot open registers output file.\n"); + rv_log_error("Cannot open registers output file"); return; } diff --git a/src/feature.h b/src/feature.h index 8e8523b1..4591e6a1 100644 --- a/src/feature.h +++ b/src/feature.h @@ -108,5 +108,10 @@ #define RV32_FEATURE_BLOCK_CHAINING 1 #endif +/* Logging with color */ +#ifndef RV32_FEATURE_LOG_COLOR +#define RV32_FEATURE_LOG_COLOR 1 +#endif + /* Feature test macro */ #define RV32_HAS(x) RV32_FEATURE_##x diff --git a/src/log.c b/src/log.c new file mode 100644 index 00000000..ad2746c6 --- /dev/null +++ b/src/log.c @@ -0,0 +1,125 @@ +/* + * Copyright (c) 2020 rxi + * + * Permission is hereby granted, free of charge, to any person obtaining a copy + * of this software and associated documentation files (the "Software"), to + * deal in the Software without restriction, including without limitation the + * rights to use, copy, modify, merge, publish, distribute, sublicense, and/or + * sell copies of the Software, and to permit persons to whom the Software is + * furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in + * all copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE + * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS + * IN THE SOFTWARE. + */ + +#include "log.h" + +static struct { + void *udata; + log_lock_func_t lock; + int level; + bool quiet; +} L; + +static const char *level_strings[] = { + "TRACE", "DEBUG", "INFO", "WARN", "ERROR", "FATAL", +}; + +#if RV32_HAS(LOG_COLOR) +static const char *level_colors[] = { + "\x1b[94m", "\x1b[36m", "\x1b[32m", "\x1b[33m", "\x1b[31m", "\x1b[35m", +}; +#endif /* RV32_HAS(LOG_COLOR) */ + +static void stdout_callback(log_event_t *ev) +{ + char buf[16]; + buf[strftime(buf, sizeof(buf), "%H:%M:%S", ev->time)] = '\0'; +#if RV32_HAS(LOG_COLOR) + fprintf(ev->udata, "%s %s%-5s\x1b[0m \x1b[90m%s:%d:\x1b[0m ", buf, + level_colors[ev->level], level_strings[ev->level], ev->file, + ev->line); +#else + fprintf(ev->udata, "%s %-5s %s:%d: ", buf, level_strings[ev->level], + ev->file, ev->line); +#endif /* RV32_HAS(LOG_COLOR) */ + vfprintf(ev->udata, ev->fmt, ev->ap); + fprintf(ev->udata, "\n"); + fflush(ev->udata); +} + +static void lock(void) +{ + if (L.lock) + L.lock(true, L.udata); +} + +static void unlock(void) +{ + if (L.lock) + L.lock(false, L.udata); +} + +const char *log_level_string(int level) +{ + return level_strings[level]; +} + +void log_set_lock(log_lock_func_t fn, void *udata) +{ + L.lock = fn; + L.udata = udata; +} + +void log_set_level(int level) +{ + L.level = level; +} + +void log_set_quiet(bool enable) +{ + L.quiet = enable; +} + +static void init_event(log_event_t *ev, void *udata) +{ + if (!ev->time) { + time_t t = time(NULL); + ev->time = localtime(&t); + } + ev->udata = udata; +} + +void log_set_stdout_stream(FILE *stream) +{ + L.udata = stream; +} + +void log_impl(int level, const char *file, int line, const char *fmt, ...) +{ + log_event_t ev = { + .fmt = fmt, + .file = file, + .line = line, + .level = level, + }; + + lock(); + + if (!L.quiet && level >= L.level) { + init_event(&ev, L.udata ? L.udata : stdout); + va_start(ev.ap, fmt); + stdout_callback(&ev); + va_end(ev.ap); + } + + unlock(); +} diff --git a/src/log.h b/src/log.h new file mode 100644 index 00000000..371efd72 --- /dev/null +++ b/src/log.h @@ -0,0 +1,79 @@ +/* + * Copyright (c) 2020 rxi + * + * Permission is hereby granted, free of charge, to any person obtaining a copy + * of this software and associated documentation files (the "Software"), to + * deal in the Software without restriction, including without limitation the + * rights to use, copy, modify, merge, publish, distribute, sublicense, and/or + * sell copies of the Software, and to permit persons to whom the Software is + * furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in + * all copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE + * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS + * IN THE SOFTWARE. + */ + +#pragma once + +#include +#include +#include +#include + +typedef struct { + va_list ap; + const char *fmt; + const char *file; + struct tm *time; + void *udata; + int line; + int level; +} log_event_t; + +typedef void (*log_func_t)(log_event_t *ev); +typedef void (*log_lock_func_t)(bool lock, void *udata); + +enum LOG_LEVEL { + LOG_TRACE = 0, + LOG_DEBUG, + LOG_INFO, + LOG_WARN, + LOG_ERROR, + LOG_FATAL, +}; + +/* lowest level logging */ +#define rv_log_trace(...) log_impl(LOG_TRACE, __FILE__, __LINE__, __VA_ARGS__) +#define rv_log_debug(...) log_impl(LOG_DEBUG, __FILE__, __LINE__, __VA_ARGS__) +#define rv_log_info(...) log_impl(LOG_INFO, __FILE__, __LINE__, __VA_ARGS__) +#define rv_log_warn(...) log_impl(LOG_WARN, __FILE__, __LINE__, __VA_ARGS__) +#define rv_log_error(...) log_impl(LOG_ERROR, __FILE__, __LINE__, __VA_ARGS__) +#define rv_log_fatal(...) log_impl(LOG_FATAL, __FILE__, __LINE__, __VA_ARGS__) +/* highest level logging */ + +#define rv_log_level_string(...) log_level_string(__VA_ARGS__) +#define rv_log_set_lock(...) log_set_lock(__VA_ARGS__) +#define rv_log_set_level(...) log_set_level(__VA_ARGS__) +#define rv_log_set_quiet(...) log_set_quiet(__VA_ARGS__) +/* + * By default, log messages are directed to stdout. However, + * rv_remap_stdstream() may redirect stdout to a different target, such as a + * file. Therefore, rv_log_set_stdout_stream() should be invoked within + * rv_remap_stdstream() to properly handle any changes to the stdout stream. + */ +#define rv_log_set_stdout_stream(...) log_set_stdout_stream(__VA_ARGS__) + +const char *log_level_string(int level); +void log_set_lock(log_lock_func_t fn, void *udata); +void log_set_level(int level); +void log_set_quiet(bool enable); +void log_set_stdout_stream(FILE *stream); + +void log_impl(int level, const char *file, int line, const char *fmt, ...); diff --git a/src/main.c b/src/main.c index fc68bbcc..0ebaed56 100644 --- a/src/main.c +++ b/src/main.c @@ -61,31 +61,31 @@ static char *opt_virtio_blk_img; static void print_usage(const char *filename) { - fprintf(stderr, - "RV32I[MAFC] Emulator which loads an ELF file to execute.\n" - "Usage: %s [options] [filename] [arguments]\n" - "Options:\n" + rv_log_error( + "\nRV32I[MAFC] Emulator which loads an ELF file to execute.\n" + "Usage: %s [options] [filename] [arguments]\n" + "Options:\n" #if !RV32_HAS(SYSTEM) || (RV32_HAS(SYSTEM) && RV32_HAS(ELF_LOADER)) - " -t : print executable trace\n" + " -t : print executable trace\n" #endif #if RV32_HAS(GDBSTUB) - " -g : allow remote GDB connections (as gdbstub)\n" + " -g : allow remote GDB connections (as gdbstub)\n" #endif #if RV32_HAS(SYSTEM) && !RV32_HAS(ELF_LOADER) - " -k : use as kernel image\n" - " -i : use as rootfs\n" - " -x vblk: : use as virtio-blk disk image\n" - " -b : use customized for the kernel\n" + " -k : use as kernel image\n" + " -i : use as rootfs\n" + " -x vblk: : use as virtio-blk disk image\n" + " -b : use customized for the kernel\n" #endif - " -d [filename]: dump registers as JSON to the " - "given file or `-` (STDOUT)\n" - " -q : Suppress outputs other than `dump-registers`\n" - " -a [filename] : dump signature to the given file, " - "required by arch-test test\n" - " -m : enable misaligned memory access\n" - " -p : generate profiling data\n" - " -h : show this message\n", - filename); + " -d [filename]: dump registers as JSON to the " + "given file or `-` (STDOUT)\n" + " -q : Suppress outputs other than `dump-registers`\n" + " -a [filename] : dump signature to the given file, " + "required by arch-test test\n" + " -m : enable misaligned memory access\n" + " -p : generate profiling data\n" + " -h : show this message", + filename); } static bool parse_args(int argc, char **args) @@ -188,7 +188,8 @@ static void dump_test_signature(const char *prog_name) const struct Elf32_Sym *sym; FILE *f = fopen(signature_out_file, "w"); if (!f) { - fprintf(stderr, "Cannot open signature output file.\n"); + rv_log_fatal("Cannot open signature output file: %s", + signature_out_file); return; } @@ -257,7 +258,7 @@ int main(int argc, char **args) .args_offset_size = ARGS_OFFSET_SIZE, .argc = prog_argc, .argv = prog_args, - .log_level = 0, + .log_level = LOG_TRACE, .run_flag = run_flag, .profile_output_file = prof_out_file, .cycle_per_step = CYCLE_PER_STEP, @@ -275,10 +276,11 @@ int main(int argc, char **args) /* create the RISC-V runtime */ rv = rv_create(&attr); if (!rv) { - fprintf(stderr, "Unable to create riscv emulator\n"); + rv_log_fatal("Unable to create riscv emulator"); attr.exit_code = 1; goto end; } + rv_log_info("RISC-V emulator is created and ready to run"); rv_run(rv); @@ -292,8 +294,7 @@ int main(int argc, char **args) /* finalize the RISC-V runtime */ rv_delete(rv); - - printf("inferior exit code %d\n", attr.exit_code); + rv_log_info("RISC-V emulator is destroyed"); end: free(prof_out_file); diff --git a/src/riscv.c b/src/riscv.c index ec14c0e1..95ff4ddb 100644 --- a/src/riscv.c +++ b/src/riscv.c @@ -164,9 +164,10 @@ void rv_remap_stdstream(riscv_t *rv, fd_stream_pair_t *fsp, uint32_t fsp_size) if (fd == STDIN_FILENO) attr->fd_stdin = new_fd; - else if (fd == STDOUT_FILENO) + else if (fd == STDOUT_FILENO) { attr->fd_stdout = new_fd; - else + rv_log_set_stdout_stream(file); + } else attr->fd_stderr = new_fd; } } @@ -256,7 +257,7 @@ static void map_file(char **ram_loc, const char *name) cleanup: close(fd); fail: - fprintf(stderr, "Error: %s\n", strerror(errno)); + rv_log_fatal("map_file() %s failed: %s", name, strerror(errno)); exit(EXIT_FAILURE); } @@ -400,6 +401,8 @@ riscv_t *rv_create(riscv_user_t rv_attr) * default standard stream. * rv_remap_stdstream() can be called to overwrite them * + * The logging stdout stream will be remapped as well + * */ attr->fd_map = map_init(int, FILE *, map_cmp_int); rv_remap_stdstream(rv, @@ -410,9 +413,25 @@ riscv_t *rv_create(riscv_user_t rv_attr) }, 3); + /* set the log level to TRACE, everything is captured */ + rv_log_set_level(attr->log_level); + rv_log_info("Log level: %s", rv_log_level_string(attr->log_level)); + + /* enable the log */ + rv_log_set_quiet(false); + #if !RV32_HAS(SYSTEM) || (RV32_HAS(SYSTEM) && RV32_HAS(ELF_LOADER)) elf_t *elf = elf_new(); - assert(elf && elf_open(elf, attr->data.user.elf_program)); + assert(elf); + + if (!elf_open(elf, attr->data.user.elf_program)) { + rv_log_fatal("elf_open() failed"); + map_delete(attr->fd_map); + memory_delete(attr->mem); + free(rv); + exit(EXIT_FAILURE); + } + rv_log_info("%s ELF loaded", attr->data.user.elf_program); const struct Elf32_Sym *end; if ((end = elf_get_symbol(elf, "_end"))) @@ -466,10 +485,12 @@ riscv_t *rv_create(riscv_user_t rv_attr) char *ram_loc = (char *) attr->mem->mem_base; map_file(&ram_loc, attr->data.system.kernel); + rv_log_info("Kernel loaded"); uint32_t dtb_addr = attr->mem->mem_size - DTB_SIZE; ram_loc = ((char *) attr->mem->mem_base) + dtb_addr; load_dtb(&ram_loc, attr->data.system.bootargs); + rv_log_info("DTB loaded"); /* * Load optional initrd image at last 8 MiB before the dtb region to * prevent kernel from overwritting it @@ -478,6 +499,7 @@ riscv_t *rv_create(riscv_user_t rv_attr) uint32_t initrd_addr = dtb_addr - INITRD_SIZE; ram_loc = ((char *) attr->mem->mem_base) + initrd_addr; map_file(&ram_loc, attr->data.system.initrd); + rv_log_info("Rootfs loaded"); } /* this variable has external linkage to mmu_io defined in system.c */ @@ -559,7 +581,7 @@ static void rv_run_and_trace(riscv_t *rv) /* trace execution */ uint32_t pc = rv_get_pc(rv); const char *sym = elf_find_symbol(elf, pc); - printf("%08x %s\n", pc, (sym ? sym : "")); + rv_log_trace("%08x %s", pc, (sym ? sym : "")); rv_step(rv); /* step instructions */ } @@ -848,12 +870,12 @@ static void profile(block_t *block, uint32_t freq, FILE *output_file) void rv_profile(riscv_t *rv, char *out_file_path) { if (!out_file_path) { - fprintf(stderr, "Profiling data output file is NULL.\n"); + rv_log_warn("Profiling data output file is NULL"); return; } FILE *f = fopen(out_file_path, "w"); if (!f) { - fprintf(stderr, "Cannot open profiling data output file.\n"); + rv_log_error("Cannot open profiling data output file"); return; } #if RV32_HAS(JIT) diff --git a/src/riscv.h b/src/riscv.h index 0eccba00..5344c8a4 100644 --- a/src/riscv.h +++ b/src/riscv.h @@ -10,6 +10,7 @@ #include #include "io.h" +#include "log.h" #include "map.h" #if RV32_HAS(SYSTEM) @@ -516,7 +517,7 @@ typedef struct { /* emulation program error code */ int error; - /* TODO: for logging feature */ + /* log level */ int log_level; /* userspace or system emulation data */ diff --git a/src/syscall.c b/src/syscall.c index 1834550d..09eab564 100644 --- a/src/syscall.c +++ b/src/syscall.c @@ -462,7 +462,7 @@ static void syscall_sbi_rst(riscv_t *rv) switch (fid) { case SBI_RST_SYSTEM_RESET: - fprintf(stderr, "system reset: type=%u, reason=%u\n", a0, a1); + rv_log_info("System reset: type=%u, reason=%u", a0, a1); rv_halt(rv); rv_set_reg(rv, rv_reg_a0, SBI_SUCCESS); rv_set_reg(rv, rv_reg_a1, 0); @@ -492,7 +492,7 @@ void syscall_handler(riscv_t *rv) SUPPORTED_SYSCALLS #undef _ default: - fprintf(stderr, "unknown syscall %d\n", (int) syscall); + rv_log_fatal("Unknown syscall: %d", (int) syscall); break; } diff --git a/src/syscall_sdl.c b/src/syscall_sdl.c index 9b1ae055..e07c26b3 100644 --- a/src/syscall_sdl.c +++ b/src/syscall_sdl.c @@ -254,15 +254,15 @@ static bool check_sdl(riscv_t *rv, int width, int height) { if (!window) { /* check if video has been initialized. */ if (SDL_Init(SDL_INIT_VIDEO | SDL_INIT_AUDIO) != 0) { - fprintf(stderr, "Failed to call SDL_Init()\n"); + rv_log_fatal("Failed to call SDL_Init()"); exit(EXIT_FAILURE); } window = SDL_CreateWindow("rv32emu", SDL_WINDOWPOS_UNDEFINED, SDL_WINDOWPOS_UNDEFINED, width, height, SDL_WINDOW_RESIZABLE); if (!window) { - fprintf(stderr, "Window could not be created! SDL_Error: %s\n", - SDL_GetError()); + rv_log_fatal("Window could not be created! SDL_Error: %s", + SDL_GetError()); exit(EXIT_FAILURE); } @@ -764,19 +764,19 @@ static void *music_handler(void *arg) music_midi_data = mus2midi(music->data, (int *) &music->size); if (!music_midi_data) { - fprintf(stderr, "mus2midi failed\n"); + rv_log_error("mus2midi() failed"); return NULL; } SDL_RWops *rwops = SDL_RWFromMem(music_midi_data, music->size); if (!rwops) { - fprintf(stderr, "SDL_RWFromMem failed: %s\n", SDL_GetError()); + rv_log_error("SDL_RWFromMem failed: %s", SDL_GetError()); return NULL; } mid = Mix_LoadMUSType_RW(rwops, MUS_MID, SDL_TRUE); if (!mid) { - fprintf(stderr, "Mix_LoadMUSType_RW failed: %s\n", Mix_GetError()); + rv_log_error("Mix_LoadMUSType_RW failed: %s", Mix_GetError()); return NULL; } @@ -786,7 +786,7 @@ static void *music_handler(void *arg) Mix_VolumeMusic(music->volume * 8); if (Mix_PlayMusic(mid, looping) == -1) { - fprintf(stderr, "Mix_PlayMusic failed: %s\n", Mix_GetError()); + rv_log_error("Mix_PlayMusic failed: %s", Mix_GetError()); return NULL; } @@ -920,7 +920,7 @@ static void init_audio(void) { if (!(SDL_WasInit(-1) & SDL_INIT_AUDIO)) { if (SDL_Init(SDL_INIT_AUDIO) != 0) { - fprintf(stderr, "Failed to call SDL_Init()\n"); + rv_log_fatal("Failed to call SDL_Init()"); exit(EXIT_FAILURE); } } @@ -928,17 +928,17 @@ static void init_audio(void) /* sfx samples buffer */ sfx_samples = malloc(SFX_SAMPLE_SIZE); if (unlikely(!sfx_samples)) { - fprintf(stderr, "Failed to allocate memory for buffer\n"); + rv_log_fatal("Failed to allocate memory for buffer"); exit(EXIT_FAILURE); } /* Initialize SDL2 Mixer */ if (Mix_Init(MIX_INIT_MID) != MIX_INIT_MID) { - fprintf(stderr, "Mix_Init failed: %s\n", Mix_GetError()); + rv_log_fatal("Mix_Init failed: %s", Mix_GetError()); exit(EXIT_FAILURE); } if (Mix_OpenAudio(SAMPLE_RATE, AUDIO_U8, CHANNEL_USED, CHUNK_SIZE) == -1) { - fprintf(stderr, "Mix_OpenAudio failed: %s\n", Mix_GetError()); + rv_log_fatal("Mix_OpenAudio failed: %s", Mix_GetError()); Mix_Quit(); exit(EXIT_FAILURE); } @@ -1007,7 +1007,7 @@ void syscall_setup_audio(riscv_t *rv) shutdown_audio(); break; default: - fprintf(stderr, "unknown sound request\n"); + rv_log_error("Unknown sound request: %d", request); break; } } @@ -1031,7 +1031,7 @@ void syscall_control_audio(riscv_t *rv) stop_music(); break; default: - fprintf(stderr, "unknown sound control request\n"); + rv_log_error("Unknown sound control request: %d", request); break; } } diff --git a/src/system.c b/src/system.c index 82d381b0..e92d71af 100644 --- a/src/system.c +++ b/src/system.c @@ -95,7 +95,7 @@ enum SUPPORTED_MMIO { ) \ break; \ default: \ - fprintf(stderr, "unknown MMIO type %d\n", io); \ + rv_log_error("Unknown MMIO type %d", io); \ break; \ } /* clang-format on */ diff --git a/src/t2c.c b/src/t2c.c index bcbd76b1..1dc07188 100644 --- a/src/t2c.c +++ b/src/t2c.c @@ -294,9 +294,7 @@ void t2c_compile(riscv_t *rv, block_t *block) LLVMInitializeNativeTarget(); LLVMInitializeNativeAsmPrinter(); if (LLVMGetTargetFromTriple(triple, &target, &error) != 0) { - fprintf(stderr, - "failed to create " - "Target\n"); + rv_log_fatal("Failed to create target"); abort(); } LLVMTargetMachineRef tm = LLVMCreateTargetMachine( @@ -308,9 +306,7 @@ void t2c_compile(riscv_t *rv, block_t *block) pb_option); if (LLVMCreateExecutionEngineForModule(&engine, module, &error) != 0) { - fprintf(stderr, - "failed to create " - "execution engine\n"); + rv_log_fatal("Failed to create execution engine"); abort(); }