Overhaul logging system in runtime

See https://github.com/graydon/rust/wiki/Logging-vision

The runtime logging categories are now treated in the same way as
modules in compiled code. Each domain now has a log_lvl that can be
used to restrict the logging from that domain (will be used to allow
logging to be restricted to a single domain).

Features dropped (can be brought back to life if there is interest):
  - Logger indentation
  - Multiple categories per log statement
  - I possibly broke some of the color code -- it confuses me

1 files changed, 106 insertions, 106 deletions

diff --git a/src/rt/rust_upcall.cpp b/src/rt/rust_upcall.cpp
index b022b8531a5..9178aac2d30 100644
--- a/src/rt/rust_upcall.cpp
+++ b/src/rt/rust_upcall.cpp
@@ -3,20 +3,19 @@
 // Upcalls.
 
 #ifdef __GNUC__
-#define LOG_UPCALL_ENTRY(task)                              \
-    LOG_I(task, rust_log::UPCALL,                           \
-          "> UPCALL %s - task: %s 0x%" PRIxPTR              \
-          " retpc: x%" PRIxPTR                              \
-          " ref_count: %d",                                 \
-          __FUNCTION__,                                     \
-          (task)->name, (task),                             \
-          __builtin_return_address(0),                      \
-          (task->ref_count));
+#define LOG_UPCALL_ENTRY(task)                            \
+    LOG(task, upcall,                                     \
+        "> UPCALL %s - task: %s 0x%" PRIxPTR              \
+        " retpc: x%" PRIxPTR                              \
+        " ref_count: %d",                                 \
+        __FUNCTION__,                                     \
+        (task)->name, (task),                             \
+        __builtin_return_address(0),                      \
+        (task->ref_count));
 #else
-#define LOG_UPCALL_ENTRY(task)                              \
-    LOG_I(task, rust_log::UPCALL,                           \
-          "> UPCALL task: %s @x%" PRIxPTR,                  \
-          (task)->name, (task));
+#define LOG_UPCALL_ENTRY(task)                            \
+    LOG(task, upcall, "> UPCALL task: %s @x%" PRIxPTR,    \
+        (task)->name, (task));
 #endif
 
 extern "C" CDECL char const *
@@ -29,61 +28,78 @@ upcall_grow_task(rust_task *task, size_t n_frame_bytes) {
 }
 
 extern "C" CDECL
-void upcall_log_int(rust_task *task, int32_t level, int32_t i) {
+void upcall_log_int(rust_task *task, uint32_t level, int32_t i) {
     LOG_UPCALL_ENTRY(task);
-    LOG(task, rust_log::UPCALL | rust_log::ULOG,
-        "rust: %" PRId32 " (0x%" PRIx32 ")", i, i);
+    if (task->dom->log_lvl >= level)
+        task->dom->log(task, level, "rust: %" PRId32 " (0x%" PRIx32 ")",
+                       i, i);
 }
 
 extern "C" CDECL
-void upcall_log_float(rust_task *task, int32_t level, float f) {
+void upcall_log_int_rustboot(rust_task *task, uint32_t level, int32_t i) {
     LOG_UPCALL_ENTRY(task);
-    LOG(task, rust_log::UPCALL | rust_log::ULOG,
-        "rust: %12.12f", f);
+    if (task->dom->log_lvl >= level && log_rustboot >= level)
+        task->dom->log(task, level, "rust: %" PRId32 " (0x%" PRIx32 ")",
+                       i, i);
 }
 
 extern "C" CDECL
-void upcall_log_double(rust_task *task, int32_t level, double *f) {
+void upcall_log_float(rust_task *task, uint32_t level, float f) {
     LOG_UPCALL_ENTRY(task);
-    LOG(task, rust_log::UPCALL | rust_log::ULOG,
-              "rust: %12.12f", *f);
+    if (task->dom->log_lvl >= level)
+        task->dom->log(task, level, "rust: %12.12f", f);
+}
+
+extern "C" CDECL
+void upcall_log_double(rust_task *task, uint32_t level, double *f) {
+    LOG_UPCALL_ENTRY(task);
+    if (task->dom->log_lvl >= level)
+        task->dom->log(task, level, "rust: %12.12f", *f);
 }
 
 extern "C" CDECL void
-upcall_log_str(rust_task *task, int32_t level, rust_str *str) {
+upcall_log_str_rustboot(rust_task *task, uint32_t level, rust_str *str) {
     LOG_UPCALL_ENTRY(task);
-    const char *c = str_buf(task, str);
-    LOG(task, rust_log::UPCALL | rust_log::ULOG, "rust: %s", c);
+    if (task->dom->log_lvl >= level && log_rustboot >= level) {
+        const char *c = str_buf(task, str);
+        task->dom->log(task, level, "rust: %s", c);
+    }
+}
+
+extern "C" CDECL void
+upcall_log_str(rust_task *task, uint32_t level, rust_str *str) {
+    LOG_UPCALL_ENTRY(task);
+    if (task->dom->log_lvl >= level) {
+        const char *c = str_buf(task, str);
+        task->dom->log(task, level, "rust: %s", c);
+    }
 }
 
 extern "C" CDECL void
 upcall_trace_word(rust_task *task, uintptr_t i) {
     LOG_UPCALL_ENTRY(task);
-    LOG(task, rust_log::UPCALL | rust_log::TRACE, "trace: 0x%" PRIxPTR "", i,
-              i, (char) i);
+    task->dom->log(task, 2, "trace: 0x%" PRIxPTR "", i, i, (char) i);
 }
 
 extern "C" CDECL void
 upcall_trace_str(rust_task *task, char const *c) {
     LOG_UPCALL_ENTRY(task);
-    LOG(task, rust_log::UPCALL | rust_log::TRACE, "trace: %s", c);
+    task->dom->log(task, 2, "trace: %s", c);
 }
 
 extern "C" CDECL rust_port*
 upcall_new_port(rust_task *task, size_t unit_sz) {
     LOG_UPCALL_ENTRY(task);
     rust_dom *dom = task->dom;
-    LOG(task, rust_log::UPCALL | rust_log::MEM | rust_log::COMM,
-              "upcall_new_port(task=0x%" PRIxPTR " (%s), unit_sz=%d)",
-              (uintptr_t) task, task->name, unit_sz);
+    LOG(task, comm, "upcall_new_port(task=0x%" PRIxPTR " (%s), unit_sz=%d)",
+        (uintptr_t) task, task->name, unit_sz);
     return new (dom) rust_port(task, unit_sz);
 }
 
 extern "C" CDECL void
 upcall_del_port(rust_task *task, rust_port *port) {
     LOG_UPCALL_ENTRY(task);
-    LOG(task, rust_log::UPCALL | rust_log::MEM | rust_log::COMM,
-              "upcall del_port(0x%" PRIxPTR ")", (uintptr_t) port);
+    LOG(task, comm, "upcall del_port(0x%" PRIxPTR ")", (uintptr_t) port);
     I(task->dom, !port->ref_count);
     delete port;
 }
@@ -95,10 +111,9 @@ extern "C" CDECL rust_chan*
 upcall_new_chan(rust_task *task, rust_port *port) {
     LOG_UPCALL_ENTRY(task);
     rust_dom *dom = task->dom;
-    LOG(task, rust_log::UPCALL | rust_log::MEM | rust_log::COMM,
-              "upcall_new_chan("
-              "task=0x%" PRIxPTR " (%s), port=0x%" PRIxPTR ")",
-              (uintptr_t) task, task->name, port);
+    LOG(task, comm, "upcall_new_chan("
+        "task=0x%" PRIxPTR " (%s), port=0x%" PRIxPTR ")",
+        (uintptr_t) task, task->name, port);
     I(dom, port);
     return new (dom) rust_chan(task, port, port->unit_sz);
 }
@@ -124,8 +139,7 @@ extern "C" CDECL
 void upcall_del_chan(rust_task *task, rust_chan *chan) {
     LOG_UPCALL_ENTRY(task);
 
-    LOG(task, rust_log::UPCALL | rust_log::MEM | rust_log::COMM,
-              "upcall del_chan(0x%" PRIxPTR ")", (uintptr_t) chan);
+    LOG(task, comm, "upcall del_chan(0x%" PRIxPTR ")", (uintptr_t) chan);
 
     A(task->dom, chan->ref_count == 0,
       "Channel's ref count should be zero.");
@@ -175,7 +189,7 @@ upcall_clone_chan(rust_task *task, maybe_proxy<rust_task> *target,
         rust_handle<rust_port> *handle =
             task->dom->kernel->get_port_handle(port->as_referent());
         maybe_proxy<rust_port> *proxy = new rust_proxy<rust_port> (handle);
-        LOG(task, rust_log::MEM, "new proxy: " PTR, proxy);
+        LOG(task, mem, "new proxy: " PTR, proxy);
         port = proxy;
         target_task = target->as_proxy()->handle()->referent();
     }
@@ -185,16 +199,16 @@ upcall_clone_chan(rust_task *task, maybe_proxy<rust_task> *target,
 extern "C" CDECL void
 upcall_yield(rust_task *task) {
     LOG_UPCALL_ENTRY(task);
-    LOG(task, rust_log::UPCALL | rust_log::COMM, "upcall yield()");
+    LOG(task, comm, "upcall yield()");
     task->yield(1);
 }
 
 extern "C" CDECL void
 upcall_sleep(rust_task *task, size_t time_in_us) {
     LOG_UPCALL_ENTRY(task);
-    LOG(task, rust_log::UPCALL | rust_log::TASK, "elapsed %d",
+    LOG(task, task, "elapsed %d",
               task->yield_timer.get_elapsed_time());
-    LOG(task, rust_log::UPCALL | rust_log::TASK, "sleep %d us", time_in_us);
+    LOG(task, task, "sleep %d us", time_in_us);
     task->yield(2, time_in_us);
 }
 
@@ -228,17 +242,16 @@ extern "C" CDECL void
 upcall_send(rust_task *task, rust_chan *chan, void *sptr) {
     LOG_UPCALL_ENTRY(task);
     chan->send(sptr);
-    LOG(task, rust_log::COMM, "=== sent data ===>");
+    LOG(task, comm, "=== sent data ===>");
 }
 
 extern "C" CDECL void
 upcall_recv(rust_task *task, uintptr_t *dptr, rust_port *port) {
     LOG_UPCALL_ENTRY(task);
-    LOG(task, rust_log::UPCALL | rust_log::COMM,
-              "port: 0x%" PRIxPTR ", dptr: 0x%" PRIxPTR
-              ", size: 0x%" PRIxPTR ", chan_no: %d",
-              (uintptr_t) port, (uintptr_t) dptr, port->unit_sz,
-              port->chans.length());
+    LOG(task, comm, "port: 0x%" PRIxPTR ", dptr: 0x%" PRIxPTR
+        ", size: 0x%" PRIxPTR ", chan_no: %d",
+        (uintptr_t) port, (uintptr_t) dptr, port->unit_sz,
+        port->chans.length());
 
     if (port->receive(dptr)) {
         return;
@@ -248,7 +261,7 @@ upcall_recv(rust_task *task, uintptr_t *dptr, rust_port *port) {
     // on the port. Remember the rendezvous location so that any sender
     // task can write to it before waking up this task.
 
-    LOG(task, rust_log::COMM, "<=== waiting for rendezvous data ===");
+    LOG(task, comm, "<=== waiting for rendezvous data ===");
     task->rendezvous_ptr = dptr;
     task->block(port, "waiting for rendezvous data");
     task->yield(3);
@@ -260,8 +273,7 @@ upcall_fail(rust_task *task,
             char const *file,
             size_t line) {
     LOG_UPCALL_ENTRY(task);
-    LOG(task, rust_log::UPCALL | rust_log::ERR,
-              "upcall fail '%s', %s:%" PRIdPTR, expr, file, line);
+    LOG_ERR(task, upcall, "upcall fail '%s', %s:%" PRIdPTR, expr, file, line);
     task->fail(4);
     if (getenv("RUST_TRAP_FAILURE")) {
         // FIXME: x86-ism.
@@ -292,8 +304,7 @@ upcall_kill(rust_task *task, maybe_proxy<rust_task> *target) {
 extern "C" CDECL void
 upcall_exit(rust_task *task) {
     LOG_UPCALL_ENTRY(task);
-    LOG(task, rust_log::UPCALL | rust_log::TASK,
-              "task ref_count: %d", task->ref_count);
+    LOG(task, task, "task ref_count: %d", task->ref_count);
     A(task->dom, task->ref_count >= 0,
       "Task ref_count should not be negative on exit!");
     task->die();
@@ -305,12 +316,12 @@ extern "C" CDECL uintptr_t
 upcall_malloc(rust_task *task, size_t nbytes, type_desc *td) {
     LOG_UPCALL_ENTRY(task);
 
-    LOG(task, rust_log::UPCALL|rust_log::MEM,
+    LOG(task, mem,
                    "upcall malloc(%" PRIdPTR ", 0x%" PRIxPTR ")"
                    " with gc-chain head = 0x%" PRIxPTR,
                    nbytes, td, task->gc_alloc_chain);
     void *p = task->malloc(nbytes, td);
-    LOG(task, rust_log::UPCALL|rust_log::MEM,
+    LOG(task, mem,
                    "upcall malloc(%" PRIdPTR ", 0x%" PRIxPTR
                    ") = 0x%" PRIxPTR
                    " with gc-chain head = 0x%" PRIxPTR,
@@ -325,7 +336,7 @@ extern "C" CDECL void
 upcall_free(rust_task *task, void* ptr, uintptr_t is_gc) {
     LOG_UPCALL_ENTRY(task);
     rust_dom *dom = task->dom;
-    DLOG(dom, rust_log::UPCALL|rust_log::MEM,
+    DLOG(dom, mem,
              "upcall free(0x%" PRIxPTR ", is_gc=%" PRIdPTR ")",
              (uintptr_t)ptr, is_gc);
     task->free(ptr, (bool) is_gc);
@@ -339,8 +350,7 @@ upcall_mark(rust_task *task, void* ptr) {
     if (ptr) {
         gc_alloc *gcm = (gc_alloc*) (((char*)ptr) - sizeof(gc_alloc));
         uintptr_t marked = (uintptr_t) gcm->mark();
-        DLOG(dom, rust_log::UPCALL|rust_log::MEM|rust_log::GC,
-                 "upcall mark(0x%" PRIxPTR ") = %" PRIdPTR,
+        DLOG(dom, gc, "upcall mark(0x%" PRIxPTR ") = %" PRIdPTR,
                  (uintptr_t)gcm, marked);
         return marked;
     }
@@ -358,9 +368,9 @@ upcall_new_str(rust_task *task, char const *s, size_t fill) {
         return NULL;
     }
     rust_str *st = new (mem) rust_str(dom, alloc, fill, (uint8_t const *) s);
-    LOG(task, rust_log::UPCALL | rust_log::MEM,
-              "upcall new_str('%s', %" PRIdPTR ") = 0x%" PRIxPTR,
-              s, fill, st);
+    LOG(task, mem,
+        "upcall new_str('%s', %" PRIdPTR ") = 0x%" PRIxPTR,
+        s, fill, st);
     return st;
 }
 
@@ -368,9 +378,7 @@ extern "C" CDECL rust_vec *
 upcall_new_vec(rust_task *task, size_t fill, type_desc *td) {
     LOG_UPCALL_ENTRY(task);
     rust_dom *dom = task->dom;
-    DLOG(dom, rust_log::UPCALL|rust_log::MEM,
-             "upcall new_vec(%" PRIdPTR ")",
-             fill);
+    DLOG(dom, mem, "upcall new_vec(%" PRIdPTR ")", fill);
     size_t alloc = next_power_of_two(sizeof(rust_vec) + fill);
     void *mem = task->malloc(alloc, td);
     if (!mem) {
@@ -378,7 +386,7 @@ upcall_new_vec(rust_task *task, size_t fill, type_desc *td) {
         return NULL;
     }
     rust_vec *v = new (mem) rust_vec(dom, alloc, 0, NULL);
-    LOG(task, rust_log::UPCALL | rust_log::MEM,
+    LOG(task, mem,
               "upcall new_vec(%" PRIdPTR ") = 0x%" PRIxPTR, fill, v);
     return v;
 }
@@ -392,7 +400,7 @@ upcall_vec_grow(rust_task *task,
 {
     LOG_UPCALL_ENTRY(task);
     rust_dom *dom = task->dom;
-    LOG(task, rust_log::UPCALL | rust_log::MEM,
+    LOG(task, mem,
               "upcall vec_grow(0x%" PRIxPTR ", %" PRIdPTR
               "), alloc=%" PRIdPTR ", fill=%" PRIdPTR
               ", need_copy=0x%" PRIxPTR,
@@ -405,12 +413,12 @@ upcall_vec_grow(rust_task *task,
 
         // Fastest path: already large enough.
         if (v->alloc >= alloc) {
-            LOG(task, rust_log::UPCALL | rust_log::MEM, "no-growth path");
+            LOG(task, mem, "no-growth path");
             return v;
         }
 
         // Second-fastest path: can at least realloc.
-        LOG(task, rust_log::UPCALL | rust_log::MEM, "realloc path");
+        LOG(task, mem, "realloc path");
         v = (rust_vec*) task->realloc(v, alloc, td->is_stateful);
         if (!v) {
             task->fail(4);
@@ -432,7 +440,7 @@ upcall_vec_grow(rust_task *task,
          * need_copy outparam flag to indicate to our caller (vec-copy glue)
          * that we need the copies performed for us.
          */
-        LOG(task, rust_log::UPCALL | rust_log::MEM, "new vec path");
+        LOG(task, mem, "new vec path");
         void *mem = task->malloc(alloc, td);
         if (!mem) {
             task->fail(4);
@@ -472,24 +480,22 @@ upcall_require_rust_sym(rust_task *task,
     LOG_UPCALL_ENTRY(task);
     rust_dom *dom = task->dom;
 
-    LOG(task, rust_log::UPCALL | rust_log::CACHE,
-              "upcall require rust sym: lib #%" PRIdPTR
-              " = %s, c_sym #%" PRIdPTR
-              ", rust_sym #%" PRIdPTR
-              ", curr_crate = 0x%" PRIxPTR, lib_num, library, c_sym_num,
-              rust_sym_num, curr_crate);
+    LOG(task, cache, "upcall require rust sym: lib #%" PRIdPTR
+        " = %s, c_sym #%" PRIdPTR
+        ", rust_sym #%" PRIdPTR
+        ", curr_crate = 0x%" PRIxPTR, lib_num, library, c_sym_num,
+        rust_sym_num, curr_crate);
     for (char const **c = crate_rel(curr_crate, path); *c; ++c) {
-        LOG(task, rust_log::UPCALL, " + %s", crate_rel(curr_crate, *c));
+        LOG(task, upcall, " + %s", crate_rel(curr_crate, *c));
     }
 
-    LOG(task, rust_log::UPCALL | rust_log::CACHE,
-              "require C symbol 'rust_crate' from lib #%" PRIdPTR, lib_num);
+    LOG(task, cache, "require C symbol 'rust_crate' from lib #%" PRIdPTR,
+        lib_num);
     rust_crate_cache::c_sym *c =
             fetch_c_sym(task, curr_crate, lib_num, c_sym_num, library,
                         "rust_crate");
 
-    LOG(task, rust_log::UPCALL | rust_log::CACHE,
-              "require rust symbol inside crate");
+    LOG(task, cache, "require rust symbol inside crate");
     rust_crate_cache::rust_sym *s = task->cache->get_rust_sym(rust_sym_num,
                                                               dom,
                                                               curr_crate, c,
@@ -497,11 +503,9 @@ upcall_require_rust_sym(rust_task *task,
 
     uintptr_t addr = s->get_val();
     if (addr) {
-        LOG(task, rust_log::UPCALL | rust_log::CACHE,
-                  "found-or-cached addr: 0x%" PRIxPTR, addr);
+        LOG(task, cache, "found-or-cached addr: 0x%" PRIxPTR, addr);
     } else {
-        LOG(task, rust_log::UPCALL | rust_log::CACHE | rust_log::ERR,
-                  "failed to resolve symbol");
+        LOG_ERR(task, cache, "failed to resolve symbol");
         task->fail(7);
     }
     return addr;
@@ -516,23 +520,22 @@ upcall_require_c_sym(rust_task *task,
                      char const *symbol) {
     LOG_UPCALL_ENTRY(task);
 
-    LOG(task, rust_log::UPCALL | rust_log::CACHE,
-              "upcall require c sym: lib #%" PRIdPTR
-              " = %s, c_sym #%" PRIdPTR
-              " = %s"
-              ", curr_crate = 0x%" PRIxPTR, lib_num, library, c_sym_num,
-              symbol, curr_crate);
+    LOG(task, cache, "upcall require c sym: lib #%" PRIdPTR
+        " = %s, c_sym #%" PRIdPTR
+        " = %s"
+        ", curr_crate = 0x%" PRIxPTR, lib_num, library, c_sym_num,
+        symbol, curr_crate);
 
     rust_crate_cache::c_sym *c = fetch_c_sym(task, curr_crate, lib_num,
                                              c_sym_num, library, symbol);
 
     uintptr_t addr = c->get_val();
     if (addr) {
-        LOG(task, rust_log::UPCALL | rust_log::CACHE,
+        LOG(task, cache,
                   "found-or-cached addr: 0x%" PRIxPTR, addr);
     } else {
-        LOG(task, rust_log::UPCALL | rust_log::CACHE | rust_log::ERR,
-                  "failed to resolve symbol %s in %s", symbol, library);
+        LOG_ERR(task, cache, "failed to resolve symbol %s in %s",
+                symbol, library);
         task->fail(6);
     }
     return addr;
@@ -546,14 +549,12 @@ upcall_get_type_desc(rust_task *task,
                      size_t n_descs,
                      type_desc const **descs) {
     LOG_UPCALL_ENTRY(task);
-    LOG(task, rust_log::UPCALL | rust_log::CACHE,
-              "upcall get_type_desc with size=%" PRIdPTR
-              ", align=%" PRIdPTR ", %" PRIdPTR " descs", size, align,
-              n_descs);
+    LOG(task, cache, "upcall get_type_desc with size=%" PRIdPTR
+        ", align=%" PRIdPTR ", %" PRIdPTR " descs", size, align,
+        n_descs);
     rust_crate_cache *cache = task->get_crate_cache(curr_crate);
     type_desc *td = cache->get_type_desc(size, align, n_descs, descs);
-    LOG(task, rust_log::UPCALL | rust_log::CACHE,
-              "returning tydesc 0x%" PRIxPTR, td);
+    LOG(task, cache, "returning tydesc 0x%" PRIxPTR, td);
     return td;
 }
 
@@ -575,7 +576,7 @@ upcall_start_task(rust_task *spawner,
     LOG_UPCALL_ENTRY(spawner);
 
     rust_dom *dom = spawner->dom;
-    DLOG(dom, rust_log::UPCALL | rust_log::MEM | rust_log::TASK,
+    DLOG(dom, task,
              "upcall start_task(task %s @0x%" PRIxPTR
              " exit_task_glue 0x%" PRIxPTR
              ", spawnee 0x%" PRIxPTR
@@ -598,10 +599,9 @@ upcall_new_thread(rust_task *task, const char *name) {
         kernel->create_domain(parent_dom->root_crate, name);
     rust_handle<rust_task> *child_task_handle =
         kernel->get_task_handle(child_dom_handle->referent()->root_task);
-    LOG(task, rust_log::UPCALL | rust_log::MEM,
-              "child name: %s, child_dom_handle: " PTR
-              ", child_task_handle: " PTR,
-              name, child_dom_handle, child_task_handle);
+    LOG(task, mem, "child name: %s, child_dom_handle: " PTR
+        ", child_task_handle: " PTR,
+        name, child_dom_handle, child_task_handle);
     rust_proxy<rust_task> *child_task_proxy =
         new rust_proxy<rust_task> (child_task_handle);
     return child_task_proxy;
@@ -641,7 +641,7 @@ upcall_start_thread(rust_task *task,
     LOG_UPCALL_ENTRY(task);
     rust_dom *parenet_dom = task->dom;
     rust_handle<rust_task> *child_task_handle = child_task_proxy->handle();
-    LOG(task, rust_log::UPCALL | rust_log::MEM | rust_log::TASK,
+    LOG(task, task,
               "exit_task_glue: " PTR ", spawnee_fn " PTR
               ", callsz %" PRIdPTR ")",
               exit_task_glue, spawnee_fn, callsz);