From: Alan T. DeKok <aland@freeradius.org>
Date: Tue, 22 Apr 2025 16:21:10 +0000 (-0400)
Subject: more debug messages for tracking state
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=4ec341eab44c124f6f5da3b965e5835d540f0922;p=thirdparty%2Ffreeradius-server.git

more debug messages for tracking state
---

diff --git a/src/lib/io/master.c b/src/lib/io/master.c
index c9579e52e87..5b8156298f0 100644
--- a/src/lib/io/master.c
+++ b/src/lib/io/master.c
@@ -1716,6 +1716,11 @@ have_client:
 					return 0;
 				}
 
+				if (track->discard) {
+					DEBUG("Ignoring transmit from client %s - we previously received a newer / conflicting packet", client->radclient->shortname);
+					return 0;
+				}
+
 				if (!track->reply) {
 					fr_assert(!track->finished);
 					DEBUG("Ignoring retransmit from client %s - we are still processing the request", client->radclient->shortname);
@@ -2326,16 +2331,21 @@ static ssize_t mod_write(fr_listen_t *li, void *packet_ctx, fr_time_t request_ti
 	fr_client_t *radclient;
 	fr_listen_t *child;
 	fr_event_list_t *el;
+	char const *name;
 
 	get_inst(li, &inst, &thread, &connection, &child);
 
 	client = track->client;
 	if (connection) {
 		el = connection->el;
+		name = connection->name;
 	} else {
 		el = thread->el;
+		name = li->name;
 	}
 
+	DEBUG3("Processing reply for %s", name);
+
 	/*
 	 *	A fully defined client means that we just send the reply.
 	 */
@@ -2345,15 +2355,13 @@ static ssize_t mod_write(fr_listen_t *li, void *packet_ctx, fr_time_t request_ti
 		track->finished = true;
 
 		/*
-		 *	The request later received a conflicting
-		 *	packet, so we discard this one.
+		 *	The request received a conflicting packet, so we
+		 *	discard this one.
 		 */
 		if (fr_time_neq(track->timestamp, request_time) || track->discard) {
 			fr_assert(track->packets > 0);
 			track->packets--;
-
-			DEBUG3("Suppressing reply as we have a newer packet");
-
+			DEBUG3("Suppressing reply as we have a newer / conflicing packet from the same source");
 			track->discard = true;
 			goto setup_timer;
 		}
@@ -2365,6 +2373,7 @@ static ssize_t mod_write(fr_listen_t *li, void *packet_ctx, fr_time_t request_ti
 		 *	"do not respond" reply for a period of time.
 		 */
 		if ((buffer_len == 1) || track->do_not_respond) {
+			DEBUG3("Not sending response to request - it is marked as 'do not respond'");
 			track->do_not_respond = true;
 			goto setup_timer;
 		}
@@ -2376,6 +2385,7 @@ static ssize_t mod_write(fr_listen_t *li, void *packet_ctx, fr_time_t request_ti
 		packet_len = inst->app_io->write(child, track, request_time,
 						 buffer, buffer_len, written);
 		if (packet_len <= 0) {
+			ERROR("Failed writing the reply - not sending any response on %s", name);
 			track->discard = true;
 			packet_expiry_timer(el->tl, fr_time_wrap(0), track);
 			return packet_len;
@@ -2387,6 +2397,7 @@ static ssize_t mod_write(fr_listen_t *li, void *packet_ctx, fr_time_t request_ti
 		 *	the expiry timer at that point.
 		 */
 		if ((size_t) packet_len < buffer_len) {
+			DEBUG3("Partial write (%zd < %zu)", packet_len, buffer_len);
 			return packet_len;
 		}
 
@@ -2394,7 +2405,10 @@ static ssize_t mod_write(fr_listen_t *li, void *packet_ctx, fr_time_t request_ti
 		 *	We're not tracking duplicates, so just expire
 		 *	the packet now.
 		 */
-		if (!inst->app_io->track_duplicates) goto setup_timer;
+		if (!inst->app_io->track_duplicates) {
+			DEBUG3("Not tracking duplicates - expiring the request");
+			goto setup_timer;
+		}
 
 		/*
 		 *	Cache the reply packet if we're doing dedup.
@@ -2403,6 +2417,7 @@ static ssize_t mod_write(fr_listen_t *li, void *packet_ctx, fr_time_t request_ti
 		 *	already filled out.  So we don't do that twice.
 		 */
 		if (!track->reply) {
+			DEBUG3("Caching reply");
 			MEM(track->reply = talloc_memdup(track, buffer, buffer_len));
 			track->reply_len = buffer_len;
 		}