[kernel] Add spam logging to trace mailbox calls

Added a new IPC log category, and logging of mailbox calls in it. Also added
some logs in init's service locator to help track down the bug fixed in the
previous commit.

src/kernel/objects/mailbox.cpp

@@ -2,6 +2,7 @@
 #include <util/counted.h>
 #include <j6/memutils.h>
 
+#include "logger.h"
 #include "objects/mailbox.h"
 #include "objects/thread.h"
 
@@ -26,6 +27,8 @@ mailbox::close()
     bool was_closed = __atomic_exchange_n(&m_closed, true, __ATOMIC_ACQ_REL);
     if (was_closed) return;
 
+    log::spam(logs::ipc, "mbx[%2x] closing...", obj_id());
+
     m_callers.clear(j6_status_closed);
     m_responders.clear(j6_status_closed);
 
@@ -44,8 +47,14 @@ mailbox::call()
     m_callers.add_thread(&current);
 
     thread *responder = m_responders.pop_next();
-    if (responder)
+    if (responder) {
+        log::spam(logs::ipc, "thread[%2x]:: mbx[%2x] call() waking thread[%2x]...",
+            current.obj_id(), obj_id(), responder->obj_id());
         responder->wake(j6_status_ok);
+    } else {
+        log::spam(logs::ipc, "thread[%2x]:: mbx[%2x] call() found no responder yet.",
+            current.obj_id(), obj_id());
+    }
 
     return current.block();
 }
@@ -59,6 +68,7 @@ mailbox::receive(ipc::message &data, reply_tag_t &reply_tag, bool block)
     thread &current = thread::current();
     thread *caller = nullptr;
 
+
     while (true) {
         caller = m_callers.pop_next();
         if (caller)
@@ -67,17 +77,24 @@ mailbox::receive(ipc::message &data, reply_tag_t &reply_tag, bool block)
         if (!block)
             return j6_status_would_block;
 
+        log::spam(logs::ipc, "thread[%2x]:: mbx[%2x] receive() blocking waiting for a caller",
+            current.obj_id(), obj_id());
+
         m_responders.add_thread(&current);
         j6_status_t s = current.block();
         if (s != j6_status_ok)
             return s;
     }
 
+
     util::scoped_lock lock {m_reply_lock};
     reply_tag = ++m_next_reply_tag;
     m_reply_map.insert({ reply_tag, caller });
     lock.release();
 
+    log::spam(logs::ipc, "thread[%2x]:: mbx[%2x] receive() found caller thread[%2x], rt = %x",
+        current.obj_id(), obj_id(), caller->obj_id(), reply_tag);
+
     data = caller->get_message_data();
     return j6_status_ok;
 }
@@ -97,6 +114,10 @@ mailbox::reply(reply_tag_t reply_tag, ipc::message &&data)
     m_reply_map.erase(reply_tag);
     lock.release();
 
+    thread &current = thread::current();
+    log::spam(logs::ipc, "thread[%2x]:: mbx[%2x] reply() to caller thread[%2x], rt = %x",
+        current.obj_id(), obj_id(), caller->obj_id(), reply_tag);
+
     caller->set_message_data(util::move(data));
     caller->wake(j6_status_ok);
     return j6_status_ok;

src/libraries/j6/include/j6/tables/log_areas.inc

@@ -2,10 +2,11 @@ LOG(apic,   info)
 LOG(boot,   info)
 LOG(device, spam)
 LOG(irq,    info)
-LOG(memory, info)
-LOG(objs,   info)
+LOG(memory, verbose)
+LOG(objs,   spam)
 LOG(paging, info)
-LOG(sched,  info)
-LOG(syscall,info)
+LOG(sched,  verbose)
+LOG(syscall,verbose)
 LOG(task,   verbose)
 LOG(timer,  info)
+LOG(ipc,    spam)

src/user/srv.init/service_locator.cpp

@@ -6,6 +6,7 @@
 #include <j6/types.h>
 #include <j6/protocols/service_locator.h>
 #include <j6/syscalls.h>
+#include <j6/syslog.hh>
 #include <util/node_map.h>
 
 #include "service_locator.h"
@@ -32,6 +33,8 @@ service_locator_start(j6_handle_t mb)
     j6_handle_t give_handle = j6_handle_invalid;
     uint64_t proto_id;
 
+    j6::syslog("SL> Starting service locator on mbx handle %x", mb);
+
     while (true) {
         uint64_t data_len = sizeof(uint64_t);
         j6_status_t s = j6_mailbox_respond(mb, &tag,
@@ -53,6 +56,8 @@ service_locator_start(j6_handle_t mb)
                 break;
             }
 
+            j6::syslog("SL> Registering handle %x for proto %x", give_handle, proto_id);
+
             services.insert( {proto_id, give_handle} );
             tag = j6_proto_base_status;
             data = j6_status_ok;
@@ -66,10 +71,13 @@ service_locator_start(j6_handle_t mb)
 
             {
                 auto found = services.find(proto_id);
-                if (found != services.end())
+                if (found != services.end()) {
+                    j6::syslog("SL> Found handle %x for proto %x", give_handle, proto_id);
                     give_handle = found->second;
-                else
+                } else {
+                    j6::syslog("SL> Found no handles for proto %x", proto_id);
                     give_handle = j6_handle_invalid;
+                }
             }
             break;