More consistent logging

Don't trash the request->number or name for internal requests

diff --git a/src/lib/io/worker.c b/src/lib/io/worker.c
index 8c4d578d7ac7aa73d5bfed26893a07bb112af7f1..be7b375a56557ff02a197e56f276be4424ebbd01 100644 (file)
--- a/src/lib/io/worker.c
+++ b/src/lib/io/worker.c
@@ -654,7 +654,8 @@ static char *itoa_internal(TALLOC_CTX *ctx, uint64_t number)
 /** Initialize various request fields needed by the worker.
  *
  */
-static void worker_request_init(fr_worker_t *worker, request_t *request, fr_time_t now)
+static inline CC_HINT(always_inline)
+void worker_request_init(fr_worker_t *worker, request_t *request, fr_time_t now)
 {
        request->el = worker->el;
        request->backlog = worker->runnable;
@@ -664,15 +665,19 @@ static void worker_request_init(fr_worker_t *worker, request_t *request, fr_time
        request->reply = fr_radius_packet_alloc(request, false);
        fr_assert(request->reply != NULL);
 
-       request->number = atomic_fetch_add_explicit(&request_number, 1, memory_order_seq_cst);
-
-       request->name = itoa_internal(request, request->number);
-
        request->async = talloc_zero(request, fr_async_t);
        request->async->recv_time = now;
        request->async->el = worker->el;
 }
 
+static inline CC_HINT(always_inline)
+void worker_request_name_number(request_t *request)
+{
+       request->number = atomic_fetch_add_explicit(&request_number, 1, memory_order_seq_cst);
+       if (request->name) talloc_free(UNCONST(char *, request->name));
+       request->name = itoa_internal(request, request->number);
+}
+
 static void worker_request_bootstrap(fr_worker_t *worker, fr_channel_data_t *cd, fr_time_t now)
 {
        bool                    is_dup;
@@ -687,6 +692,7 @@ static void worker_request_bootstrap(fr_worker_t *worker, fr_channel_data_t *cd,
        if (!request) goto nak;
 
        worker_request_init(worker, request, now);
+       worker_request_name_number(request);
 
        /*
         *      Associate our interpreter with the request
@@ -988,7 +994,7 @@ static void _worker_request_external_done(request_t *request, UNUSED rlm_rcode_t
 
        worker_send_reply(worker, request, 0, fr_time());
 
-       DEBUG3("Freeing request %s", request->name);
+       DEBUG3("Worker - Request freed (%s)", request->name);
        talloc_free(request);
 }
 
@@ -999,7 +1005,7 @@ static void _worker_request_runnable(request_t *request, void *uctx)
 {
        fr_worker_t     *worker = uctx;
 
-       RDEBUG3("Marked as runnable");
+       RDEBUG3("Worker - Request marked as runnable");
        fr_heap_insert(worker->runnable, request);
 }
 
@@ -1008,7 +1014,7 @@ static void _worker_request_runnable(request_t *request, void *uctx)
  */
 static void _worker_request_yield(request_t *request, UNUSED void *uctx)
 {
-       RDEBUG3("Yielded");
+       RDEBUG3("Worker - Request yielded");
        fr_time_tracking_yield(&request->async->tracking, fr_time());
 }
 
@@ -1017,7 +1023,7 @@ static void _worker_request_yield(request_t *request, UNUSED void *uctx)
  */
 static void _worker_request_resume(request_t *request, UNUSED void *uctx)
 {
-       RDEBUG3("Resuming");
+       RDEBUG3("Worker - Request resuming");
        fr_time_tracking_resume(&request->async->tracking, fr_time());
 }
 
@@ -1311,6 +1317,7 @@ int fr_worker_request_add(request_t *request, module_method_t process, void *uct
        now = fr_time();
 
        worker_request_init(worker, request, now);
+       worker_request_name_number(request);
 
        fr_assert(request_is_internal(request));
        request->async->process = process;

diff --git a/src/lib/unlang/interpret.c b/src/lib/unlang/interpret.c
index c77a3fff17c57ec94e73eb2e7754f39aa64428a4..6487084e980cf168b8caa8c23e8cfeccc41288ef 100644 (file)
--- a/src/lib/unlang/interpret.c
+++ b/src/lib/unlang/interpret.c
@@ -972,13 +972,13 @@ void unlang_interpret_mark_runnable(request_t *request)
         *      runnable, before the parent request starts running.
         */
        if (!is_yielded(frame) || scheduled) {
-               RDEBUG3("Not marking resumable due to%s%s",
+               RDEBUG3("Not marking runnable due to%s%s",
                        !is_yielded(frame) ?
                        " it not being yielded " : "", scheduled ? " it already being scheduled" : "");
                return;
        }
 
-       RDEBUG3("Marked as resumable");
+       RDEBUG3("Interpreter - Request marked as runnable");
 
        intp->funcs.mark_runnable(request, intp->uctx);
 }