From a1e2c58afc9bc4b5ecd734578abe39dd6b574ea1 Mon Sep 17 00:00:00 2001
From: "Justin C. Miller" <justin@devjustinian.com>
Date: Wed, 21 Feb 2024 19:40:28 -0800
Subject: [PATCH] [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                | 23 ++++++++++++++++++-
 .../j6/include/j6/tables/log_areas.inc        |  9 ++++----
 src/user/srv.init/service_locator.cpp         | 12 ++++++++--
 3 files changed, 37 insertions(+), 7 deletions(-)

diff --git a/src/kernel/objects/mailbox.cpp b/src/kernel/objects/mailbox.cpp
index c57ad89..8423b8e 100644
--- a/src/kernel/objects/mailbox.cpp
+++ b/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;
diff --git a/src/libraries/j6/include/j6/tables/log_areas.inc b/src/libraries/j6/include/j6/tables/log_areas.inc
index dc52173..90aa00d 100644
--- a/src/libraries/j6/include/j6/tables/log_areas.inc
+++ b/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)
diff --git a/src/user/srv.init/service_locator.cpp b/src/user/srv.init/service_locator.cpp
index 3dee0c1..5088319 100644
--- a/src/user/srv.init/service_locator.cpp
+++ b/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;