dovecot-2.2: director: Log more clearly why a request timeouts.

[dovecot at dovecot.org]

details:   http://hg.dovecot.org/dovecot-2.2/rev/10fae591707c
changeset: 15322:10fae591707c
user:      Timo Sirainen <tss at iki.fi>
date:      Mon Oct 22 15:23:25 2012 +0300
description:
director: Log more clearly why a request timeouts.

diffstat:

 src/director/director-request.c |  51 +++++++++++++++++++++++++++++++++-------
 1 files changed, 42 insertions(+), 9 deletions(-)

diffs (156 lines):

diff -r cd646623a1a8 -r 10fae591707c src/director/director-request.c
--- a/src/director/director-request.c	Mon Oct 22 15:20:57 2012 +0300
+++ b/src/director/director-request.c	Mon Oct 22 15:23:25 2012 +0300
@@ -12,24 +12,44 @@
 #define DIRECTOR_REQUEST_TIMEOUT_SECS 30
 #define RING_NOCONN_WARNING_DELAY_MSECS (2*1000)
 
+enum director_request_delay_reason {
+	REQUEST_DELAY_NONE = 0,
+	REQUEST_DELAY_RINGNOTHANDSHAKED,
+	REQUEST_DELAY_RINGNOTSYNCED,
+	REQUEST_DELAY_NOHOSTS,
+	REQUEST_DELAY_WEAK,
+	REQUEST_DELAY_KILL
+};
+
+static const char *delay_reason_strings[] = {
+	"unknown",
+	"ring not handshaked",
+	"ring not synced",
+	"no hosts",
+	"weak user",
+	"kill waiting"
+};
+
 struct director_request {
 	struct director *dir;
 
 	time_t create_time;
 	unsigned int username_hash;
+	enum director_request_delay_reason delay_reason;
 
 	director_request_callback *callback;
 	void *context;
 };
 
 static const char *
-director_request_get_timeout_error(struct director_request *request)
+director_request_get_timeout_error(struct director_request *request,
+				   struct user *user, string_t *str)
 {
-	string_t *str = t_str_new(128);
-	struct user *user;
 	unsigned int secs;
 
-	str_printfa(str, "Timeout - queued for %u secs (",
+	str_truncate(str, 0);
+	str_printfa(str, "Timeout because %s - queued for %u secs (",
+		    delay_reason_strings[request->delay_reason],
 		    (unsigned int)(ioloop_time - request->create_time));
 
 	if (request->dir->ring_last_sync_time == 0)
@@ -42,8 +62,6 @@
 			str_printfa(str, "Ring not synced for %u secs", secs);
 	}
 
-	user = user_directory_lookup(request->dir->users,
-				     request->username_hash);
 	if (user != NULL) {
 		if (user->weak)
 			str_append(str, ", weak user");
@@ -57,7 +75,9 @@
 static void director_request_timeout(struct director *dir)
 {
 	struct director_request **requestp, *request;
+	struct user *user;
 	const char *errormsg;
+	string_t *str = t_str_new(128);
 
 	while (array_count(&dir->pending_requests) > 0) {
 		requestp = array_idx_modifiable(&dir->pending_requests, 0);
@@ -67,8 +87,12 @@
 		    DIRECTOR_REQUEST_TIMEOUT_SECS > ioloop_time)
 			break;
 
+		user = user_directory_lookup(request->dir->users,
+					     request->username_hash);
+		errormsg = director_request_get_timeout_error(request,
+							      user, str);
+
 		array_delete(&dir->pending_requests, 0, 1);
-		errormsg = director_request_get_timeout_error(request);
 		T_BEGIN {
 			request->callback(NULL, errormsg, request->context);
 		} T_END;
@@ -127,13 +151,16 @@
 						ring_noconn_warning, dir);
 }
 
-static bool director_request_existing(struct director *dir, struct user *user)
+static bool
+director_request_existing(struct director_request *request, struct user *user)
 {
+	struct director *dir = request->dir;
 	struct mail_host *host;
 
 	if (user->kill_state != USER_KILL_STATE_NONE) {
 		/* delay processing this user's connections until
 		   its existing connections have been killed */
+		request->delay_reason = REQUEST_DELAY_KILL;
 		return FALSE;
 	}
 	if (dir->right == NULL && dir->ring_synced) {
@@ -147,6 +174,7 @@
 
 	if (user->weak) {
 		/* wait for user to become non-weak */
+		request->delay_reason = REQUEST_DELAY_WEAK;
 		return FALSE;
 	}
 	if (!user_directory_user_is_near_expiring(dir->users, user))
@@ -157,6 +185,7 @@
 	host = mail_host_get_by_hash(dir->mail_hosts, user->username_hash);
 	if (!dir->ring_synced) {
 		/* try again later once ring is synced */
+		request->delay_reason = REQUEST_DELAY_RINGNOTSYNCED;
 		return FALSE;
 	}
 	if (user->host == host) {
@@ -200,6 +229,7 @@
 	} else {
 		user->weak = TRUE;
 		director_update_user_weak(dir, dir->self_host, NULL, user);
+		request->delay_reason = REQUEST_DELAY_WEAK;
 		return FALSE;
 	}
 }
@@ -213,24 +243,27 @@
 	if (!dir->ring_handshaked) {
 		/* delay requests until ring handshaking is complete */
 		ring_log_delayed_warning(dir);
+		request->delay_reason = REQUEST_DELAY_RINGNOTHANDSHAKED;
 		return FALSE;
 	}
 
 	user = user_directory_lookup(dir->users, request->username_hash);
 	if (user != NULL) {
-		if (!director_request_existing(dir, user))
+		if (!director_request_existing(request, user))
 			return FALSE;
 		user_directory_refresh(dir->users, user);
 	} else {
 		if (!dir->ring_synced) {
 			/* delay adding new users until ring is again synced */
 			ring_log_delayed_warning(dir);
+			request->delay_reason = REQUEST_DELAY_RINGNOTSYNCED;
 			return FALSE;
 		}
 		host = mail_host_get_by_hash(dir->mail_hosts,
 					     request->username_hash);
 		if (host == NULL) {
 			/* all hosts have been removed */
+			request->delay_reason = REQUEST_DELAY_NOHOSTS;
 			return FALSE;
 		}
 		user = user_directory_add(dir->users, request->username_hash,