Merge pull request #552 from ChinYikMing/feat/logging-api

Standardize logging utility

Author: jserv

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)

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