From 27a8222fbd343554fbac82cc6e69d4dee6970b3d Mon Sep 17 00:00:00 2001
From: "Alan T. DeKok" <aland@freeradius.org>
Date: Sat, 31 Jul 2010 08:57:10 +0200
Subject: [PATCH] More descriptive error messages.

If the thread pool queue is full, or if the packets are stuck in it for
a long time, it's usually because someone has a DB with 10 million rows
and no index.  Or, they're running long-lived queries against a MyISAM
database.  Either way, there's little that the RADIUS server can do
to fix it.

When that happens, produce a descriptive error message suggesting
that they focus the blame in the right place.
---
 src/main/threads.c | 37 +++++++++++++++++++++++++++++++++----
 1 file changed, 33 insertions(+), 4 deletions(-)

diff --git a/src/main/threads.c b/src/main/threads.c
index 34aa93e..1b98e4e 100644
--- a/src/main/threads.c
+++ b/src/main/threads.c
@@ -157,6 +157,7 @@ typedef struct THREAD_POOL {
 static THREAD_POOL thread_pool;
 static int pool_initialized = FALSE;
 static time_t last_cleaned = 0;
+static time_t almost_now = 0;
 
 static void thread_pool_manage(time_t now);
 
@@ -301,10 +302,12 @@ static int request_enqueue(REQUEST *request, RAD_REQUEST_FUNP fun)
 		/*
 		 *	Mark the request as done.
 		 */
-		radlog(L_ERR, "!!! ERROR !!! The server is blocked: discarding new request %d", request->number);
+		radlog(L_ERR, "Something is blocking the server.  There are %d packets in the queue, waiting to be processed.  Ignoring the new request.", thread_pool.max_queue_size);
 		request->child_state = REQUEST_DONE;
 		return 0;
 	}
+	request->child_state = REQUEST_QUEUED;
+	request->component = "<queue>";
 
 	entry = rad_malloc(sizeof(*entry));
 	entry->request = request;
@@ -344,6 +347,7 @@ static int request_enqueue(REQUEST *request, RAD_REQUEST_FUNP fun)
  */
 static int request_dequeue(REQUEST **request, RAD_REQUEST_FUNP *fun)
 {
+	int blocked;
 	RAD_LISTEN_TYPE i, start;
 	request_queue_t *entry;
 
@@ -407,6 +411,8 @@ static int request_dequeue(REQUEST **request, RAD_REQUEST_FUNP *fun)
 	rad_assert((*request)->magic == REQUEST_MAGIC);
 	rad_assert(*fun != NULL);
 
+	(*request)->component = "";
+
 	/*
 	 *	If the request has sat in the queue for too long,
 	 *	kill it.
@@ -421,12 +427,35 @@ static int request_dequeue(REQUEST **request, RAD_REQUEST_FUNP *fun)
 	}
 
 	/*
+	 *	Produce messages for people who have 10 million rows
+	 *	in a database, without indexes.
+	 */
+	rad_assert(almost_now != 0);
+	blocked = almost_now - (*request)->timestamp;
+	if (blocked < 5) {
+		blocked = 0;
+	} else {
+		static time_t last_complained = 0;
+		
+		if (last_complained != almost_now) {
+			last_complained = almost_now;
+		} else {
+			blocked = 0;
+		}
+	}
+
+	/*
 	 *	The thread is currently processing a request.
 	 */
 	thread_pool.active_threads++;
 
 	pthread_mutex_unlock(&thread_pool.queue_mutex);
 
+	if (blocked) {
+		radlog(L_ERR, "Request %u has been waiting in the processing queue for %d seconds.  Check that all databases are running properly!",
+		       (*request)->number, blocked);
+	}
+
 	return 1;
 }
 
@@ -833,7 +862,7 @@ int thread_pool_init(CONF_SECTION *cs, int *spawn_flag)
  */
 int thread_pool_addrequest(REQUEST *request, RAD_REQUEST_FUNP fun)
 {
-	time_t now = request->timestamp;
+	almost_now = request->timestamp;
 
 	/*
 	 *	We've been told not to spawn threads, so don't.
@@ -862,9 +891,9 @@ int thread_pool_addrequest(REQUEST *request, RAD_REQUEST_FUNP fun)
 	 *	in a while, OR if the thread pool appears to be full,
 	 *	go manage it.
 	 */
-	if ((last_cleaned < now) ||
+	if ((last_cleaned < almost_now) ||
 	    (thread_pool.active_threads == thread_pool.total_threads)) {
-		thread_pool_manage(now);
+		thread_pool_manage(almost_now);
 	}
 
 	return 1;
-- 
2.1.4