From: Arran Cudbard-Bell <a.cudbardb@freeradius.org>
Date: Thu, 25 Mar 2021 17:39:16 +0000 (+0000)
Subject: More consistent logging
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=d642027f320dcd9c0e3368cbdbd3d51c2986ad74;p=thirdparty%2Ffreeradius-server.git

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 8c4d578d7ac..be7b375a565 100644
--- 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 c77a3fff17c..6487084e980 100644
--- 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);
 }