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: sysprog21#310

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 \

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.
 

src/common.h

@@ -9,6 +9,7 @@
 #include <stdint.h>
 
 #include "feature.h"
+#include "log.h"
 
 #if defined(__GNUC__) || defined(__clang__)
 #define UNUSED __attribute__((unused))

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);
         }
     }

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()

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;
     }
 

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

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();
+}

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 <stdarg.h>
+#include <stdbool.h>
+#include <stdio.h>
+#include <time.h>
+
+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, ...);