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.

Additionally, multiple callbacks can be registered and called during
logging. This is controlled by the feature ENABLE_LOG_CALLBACK,
which is disabled 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

Author: ChinYikMing

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,7 +58,7 @@ 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);
 

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);
     }
 
@@ -409,13 +408,13 @@ uint32_t *virtio_blk_init(virtio_blk_state_t *vblk, char *disk_file)
     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");
+        rv_log_error("could not map disk");
         return NULL;
     }
 #else
     disk_mem = malloc(VBLK_PRIV(vblk)->disk_size);
     if (!disk_mem) {
-        fprintf(stderr, "Could not map disk\n");
+        rv_log_error("could not map disk");
         return NULL;
     }
 #endif

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,15 @@
 #define RV32_FEATURE_BLOCK_CHAINING 1
 #endif
 
+/* Logging use color */
+#ifndef RV32_FEATURE_LOG_COLOR
+#define RV32_FEATURE_LOG_COLOR 1
+#endif
+
+/* Logging callback */
+#ifndef RV32_FEATURE_LOG_CALLBACK
+#define RV32_FEATURE_LOG_CALLBACK 0
+#endif
+
 /* Feature test macro */
 #define RV32_HAS(x) RV32_FEATURE_##x

src/log.c

@@ -0,0 +1,179 @@
+/*
+ * 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"
+
+#if RV32_HAS(LOG_CALLBACK)
+#define MAX_CALLBACKS 32
+
+typedef struct {
+    log_func_t fn;
+    void *udata;
+    int level;
+} callback_t;
+#endif /* RV32_HAS(LOG_CALLBACK) */
+
+static struct {
+    void *udata;
+    log_lock_func_t lock;
+    int level;
+    bool quiet;
+#if RV32_HAS(LOG_CALLBACK)
+    callback_t callbacks[MAX_CALLBACKS];
+#endif /* RV32_HAS(LOG_CALLBACK) */
+} 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);
+}
+
+#if RV32_HAS(LOG_CALLBACK)
+static void file_callback(log_event_t *ev)
+{
+    char buf[64];
+    buf[strftime(buf, sizeof(buf), "%Y-%m-%d %H:%M:%S", ev->time)] = '\0';
+    fprintf(ev->udata, "%s %-5s %s:%d: ", buf, level_strings[ev->level],
+            ev->file, ev->line);
+    vfprintf(ev->udata, ev->fmt, ev->ap);
+    fprintf(ev->udata, "\n");
+    fflush(ev->udata);
+}
+#endif /* RV32_HAS(LOG_CALLBACK) */
+
+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;
+}
+
+#if RV32_HAS(LOG_CALLBACK)
+int log_add_callback(log_func_t fn, void *udata, int level)
+{
+    for (int i = 0; i < MAX_CALLBACKS; i++) {
+        if (!L.callbacks[i].fn) {
+            L.callbacks[i] = (callback_t){fn, udata, level};
+            return 0;
+        }
+    }
+    return -1;
+}
+
+int log_add_fp(FILE *fp, int level)
+{
+    return log_add_callback(file_callback, fp, level);
+}
+#endif /* RV32_HAS(LOG_CALLBACK) */
+
+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 ? : stdout /* L.stdout_stream might be NULL when CLI parsing failed */);
+        va_start(ev.ap, fmt);
+        stdout_callback(&ev);
+        va_end(ev.ap);
+    }
+
+#if RV32_HAS(LOG_CALLBACK)
+    for (int i = 0; i < MAX_CALLBACKS && L.callbacks[i].fn; i++) {
+        callback_t *cb = &L.callbacks[i];
+        if (level >= cb->level) {
+            init_event(&ev, cb->udata);
+            va_start(ev.ap, fmt);
+            cb->fn(&ev);
+            va_end(ev.ap);
+        }
+    }
+#endif /* RV32_HAS(LOG_CALLBACK) */
+
+    unlock();
+}

src/log.h

@@ -0,0 +1,86 @@
+/*
+ * 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_lock(__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);
+
+#if RV32_HAS(LOG_CALLBACK)
+int log_add_callback(log_func_t fn, void *udata, int level);
+int log_add_fp(FILE *fp, int level);
+#define rv_log_add_callback(...) log_add_callback(__VA_ARGS__)
+#define rv_log_add_fp(...) log_add_fp(__VA_ARGS__)
+#endif
+
+void log_impl(int level, const char *file, int line, const char *fmt, ...);