From 2e87a752b6d1796ef5e932caae407e83f2449c83 Mon Sep 17 00:00:00 2001 From: ChinYikMing Date: Mon, 3 Feb 2025 21:56:37 +0800 Subject: [PATCH 1/2] Standardize logging utility Previously, messages were printed using both printf and fprintf, causing the information to be mixed between stdout and stderr. To address this, the log.[ch] was integrated to standardize the logging. The log.[ch]'s API are encapsulated one more layer with prefix 'rv', and included in src/common.h. The logging API uses color to differentiate messages at different levels, ensuring that logging all information to the same stdout stream does not cause confusion. The color feature is controlled by ENABLE_LOG_COLOR and is enabled by default. Note that the logging stdout stream is registered during rv_remap_stdstream() as the new stdout stream could be remapped at there. Related: #310 --- Makefile | 5 ++ README.md | 1 + src/common.h | 1 + src/devices/uart.c | 6 +- src/devices/virtio-blk.c | 27 ++++----- src/emulate.c | 3 +- src/feature.h | 5 ++ src/log.c | 125 +++++++++++++++++++++++++++++++++++++++ src/log.h | 79 +++++++++++++++++++++++++ src/main.c | 49 +++++++-------- src/riscv.c | 36 ++++++++--- src/riscv.h | 3 +- src/syscall.c | 4 +- src/syscall_sdl.c | 26 ++++---- src/system.c | 2 +- src/t2c.c | 8 +-- 16 files changed, 307 insertions(+), 73 deletions(-) create mode 100644 src/log.c create mode 100644 src/log.h diff --git a/Makefile b/Makefile index f896206ab..ae94bc16e 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 \ diff --git a/README.md b/README.md index 4b7ee4e5c..43f346b5a 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 838b65529..bce9f0f24 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 69bed7d1e..a373f9760 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 94af5ea18..45f7d52f9 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 76df73e09..73aff57f8 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 8e8523b14..4591e6a1d 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 000000000..ad2746c6e --- /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 000000000..371efd72a --- /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 fc68bbccb..0ebaed566 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 ec14c0e1c..95ff4ddb8 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 0eccba00f..5344c8a4a 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 1834550d0..09eab5648 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 9b1ae055a..e07c26b34 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 82d381b03..e92d71af0 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 bcbd76b13..1dc07188a 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(); } From 85701c40e26bcfd033bd8fb3e3b511ba317f19fc Mon Sep 17 00:00:00 2001 From: ChinYikMing Date: Tue, 4 Feb 2025 00:10:18 +0800 Subject: [PATCH 2/2] Refine check recipe in Makefile Since the newly introduced logging APIs generate logs during runtime, the check recipe must filter out this log information before validation. Additionally, refine the check recipe into a new target, check-test, which serves as a template to enhance readability. --- Makefile | 70 ++++++++++++++++++++++++++------------------------------ 1 file changed, 32 insertions(+), 38 deletions(-) diff --git a/Makefile b/Makefile index ae94bc16e..694631d34 100644 --- a/Makefile +++ b/Makefile @@ -352,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)