From 43a1165f7d7ede764c260800abc5066ab1cddf04 Mon Sep 17 00:00:00 2001
From: Dimitri Staessens <dimitri@ouroboros.rocks>
Date: Mon, 28 Jul 2025 21:49:04 +0200
Subject: lib: Output TPM debugging to log

The TPM was just printing when debugging, but it's cleaner to just log
it. Cleaned up the debug code a bit as well. Fixed timing bug in IRMd.

Signed-off-by: Dimitri Staessens <dimitri@ouroboros.rocks>
Signed-off-by: Sander Vrijders <sander@ouroboros.rocks>
---
 src/irmd/main.c |  7 ++-----
 src/lib/tpm.c   | 56 ++++++++++++++++++++++++++++++++++++--------------------
 2 files changed, 38 insertions(+), 25 deletions(-)

(limited to 'src')

diff --git a/src/irmd/main.c b/src/irmd/main.c
index e0be8a01..a5c4001e 100644
--- a/src/irmd/main.c
+++ b/src/irmd/main.c
@@ -797,8 +797,6 @@ static int flow_accept(struct flow_info * flow,
                 goto fail_wait;
         }
 
-        log_dbg("Waiting for flow accept %d.", flow->id);
-
         pthread_cleanup_push(__cleanup_flow, flow);
 
         err = reg_wait_flow_accepted(flow, &oap_hdr.hdr, abstime);
@@ -826,7 +824,7 @@ static int flow_accept(struct flow_info * flow,
 
         clock_gettime(CLOCK_REALTIME, &now);
 
-        delta = (ssize_t)(TS_TO_UINT64(now) - oap_hdr.timestamp);
+        delta = (ssize_t)(TS_TO_UINT64(now) - oap_hdr.timestamp) / MILLION;
         if (delta > flow->mpl)
                 log_warn("Flow alloc time exceeds MPL (%zd ms).", delta);
 
@@ -908,7 +906,6 @@ static int flow_accept(struct flow_info * flow,
         freebuf(*symmkey);
         clrbuf(lpk);
         oap_hdr_fini(&oap_hdr);
-        assert(lpk.data == NULL && lpk.len == 0);
         reg_destroy_flow(flow->id);
         return -EIPCP;
 }
@@ -920,7 +917,7 @@ static int flow_join(struct flow_info * flow,
         struct ipcp_info  ipcp;
         struct layer_info layer;
         buffer_t          hash;
-        buffer_t          pbuf = {0, NULL}; /* nothing to piggyback */
+        buffer_t          pbuf = BUF_INIT; /* nothing to piggyback */
         int               err;
 
         log_info("Allocating flow for %d to %s.", flow->n_pid, dst);
diff --git a/src/lib/tpm.c b/src/lib/tpm.c
index ce2dd12d..52c28de7 100644
--- a/src/lib/tpm.c
+++ b/src/lib/tpm.c
@@ -26,12 +26,16 @@
 
 #include <ouroboros/errno.h>
 #include <ouroboros/list.h>
+#include <ouroboros/pthread.h>
 #include <ouroboros/time.h>
 #include <ouroboros/tpm.h>
 
+#ifdef CONFIG_OUROBOROS_DEBUG
+#define OUROBOROS_PREFIX "tpm"
+#include <ouroboros/logs.h>
+#endif
+
 #include <assert.h>
-#include <pthread.h>
-#include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
 #include <unistd.h>
@@ -75,15 +79,37 @@ struct tpm {
         pthread_t        mgr;
 };
 
-static void tpm_join(struct tpm * tpm)
-{
-        struct list_head * p;
-        struct list_head * h;
 #ifdef CONFIG_OUROBOROS_DEBUG
+#define BETWEEN(a, x, y) ((a) > (x) && (a) <= (y))
+static void tpm_debug_thread(struct pthr_el * e)
+{
         struct timespec now;
+        time_t diff;
+        time_t intv;
+
+        if (e->wait || !e->busy)
+                return;
+
         clock_gettime(CLOCK_REALTIME, &now);
+
+        diff = ts_diff_ms(&now, &e->start) / 1000;
+        intv = ts_diff_ms(&now, &e->last) / 1000;
+
+        if (BETWEEN(TPM_DEBUG_REPORT_INTERVAL, 0, intv)) {
+                log_dbg("Thread %d:%lx running for %ld s.\n",
+                        getpid(),e->thr, diff);
+                e->last = now;
+        }
+
+        if (BETWEEN(TPM_DEBUG_ABORT_TIMEOUT, 0, diff))
+                assert(false); /* TODO: Grab a coffee and fire up GDB */
+}
 #endif
 
+static void tpm_join(struct tpm * tpm)
+{
+        struct list_head * p;
+        struct list_head * h;
         list_for_each_safe(p, h, &tpm->pool) {
                 struct pthr_el * e = list_entry(p, struct pthr_el, next);
                 if (tpm->state != TPM_RUNNING) {
@@ -98,19 +124,7 @@ static void tpm_join(struct tpm * tpm)
         list_for_each_safe(p, h, &tpm->pool) {
                 struct pthr_el * e = list_entry(p, struct pthr_el, next);
 #ifdef CONFIG_OUROBOROS_DEBUG
-                time_t diff = ts_diff_ms(&now, &e->start) / 1000;
-                bool hung;
-                if (TPM_DEBUG_REPORT_INTERVAL > 0) {
-                        time_t ldiff = ts_diff_ms(&now, &e->last) / 1000;
-                        if(e->busy && ldiff > TPM_DEBUG_REPORT_INTERVAL) {
-                                e->last = now;
-                                printf("Thread %d:%lx running for %ld s.\n",
-                                       getpid(), (long) e->thr, diff);
-                        }
-                }
-                hung = e->busy && !e->wait && diff > TPM_DEBUG_ABORT_TIMEOUT;
-                if (TPM_DEBUG_ABORT_TIMEOUT > 0 && hung)
-                        assert(false); /* coredump */
+                tpm_debug_thread(e);
 #endif
                 if (e->kill) {
                         pthread_t thr = e->thr;
@@ -178,11 +192,13 @@ static int __tpm(struct tpm * tpm)
                 tpm->cur += i;
         }
 
+        pthread_cleanup_push(__cleanup_mutex_unlock, &tpm->mtx);
+
         if (pthread_cond_timedwait(&tpm->cond, &tpm->mtx, &dl) == ETIMEDOUT)
                 if (tpm->cur - tpm->wrk > tpm->min)
                         tpm_kill(tpm);
 
-        pthread_mutex_unlock(&tpm->mtx);
+        pthread_cleanup_pop(true);
 
         return 0;
 }
-- 
cgit v1.2.3