From: Timo Sirainen <timo.sirainen@dovecot.fi>
Date: Fri, 4 May 2018 11:14:35 +0000 (+0300)
Subject: lib-master: Add auth connect & handshake times to master_login_auth_request errors
X-Git-Tag: 2.2.36~6
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=78e847e733dacb4d8e350c3ffdd025c47e3c0a18;p=thirdparty%2Fdovecot%2Fcore.git

lib-master: Add auth connect & handshake times to master_login_auth_request errors
---

diff --git a/src/lib-master/master-login-auth.c b/src/lib-master/master-login-auth.c
index 6305153388..de0953b61b 100644
--- a/src/lib-master/master-login-auth.c
+++ b/src/lib-master/master-login-auth.c
@@ -42,6 +42,8 @@ struct master_login_auth {
 	const char *auth_socket_path;
 	int refcount;
 
+	struct timeval connect_time, handshake_time;
+
 	int fd;
 	struct io *io;
 	struct istream *input;
@@ -81,21 +83,32 @@ master_login_auth_init(const char *auth_socket_path, bool request_auth_token)
 	return auth;
 }
 
-static void request_failure(struct master_login_auth_request *request,
+static void request_failure(struct master_login_auth *auth,
+			    struct master_login_auth_request *request,
 			    const char *log_reason, const char *client_reason)
 {
-	i_error("%s (Request took %u msecs, client-pid=%u client-id=%u)",
-		log_reason,
-		timeval_diff_msecs(&ioloop_timeval, &request->create_stamp),
-		request->client_pid, request->auth_id);
+	string_t *str = t_str_new(128);
+
+	str_printfa(str, "auth connected %u msecs ago",
+		    timeval_diff_msecs(&ioloop_timeval, &auth->connect_time));
+	if (auth->handshake_time.tv_sec != 0) {
+		str_printfa(str, ", handshake %u msecs ago",
+			    timeval_diff_msecs(&ioloop_timeval, &auth->handshake_time));
+	}
+	str_printfa(str, ", request took %u msecs, client-pid=%u client-id=%u",
+		    timeval_diff_msecs(&ioloop_timeval, &request->create_stamp),
+		    request->client_pid, request->auth_id);
+
+	i_error("%s (%s)", log_reason, str_c(str));
 	request->callback(NULL, client_reason, request->context);
 }
 
 static void
-request_internal_failure(struct master_login_auth_request *request,
+request_internal_failure(struct master_login_auth *auth,
+			 struct master_login_auth_request *request,
 			 const char *reason)
 {
-	request_failure(request, reason, MASTER_AUTH_ERRMSG_INTERNAL_FAILURE);
+	request_failure(auth, request, reason, MASTER_AUTH_ERRMSG_INTERNAL_FAILURE);
 }
 
 void master_login_auth_disconnect(struct master_login_auth *auth)
@@ -107,7 +120,7 @@ void master_login_auth_disconnect(struct master_login_auth *auth)
 		DLLIST2_REMOVE(&auth->request_head,
 			       &auth->request_tail, request);
 
-		request_internal_failure(request,
+		request_internal_failure(auth, request,
 			"Disconnected from auth server, aborting");
 		i_free(request);
 	}
@@ -127,6 +140,8 @@ void master_login_auth_disconnect(struct master_login_auth *auth)
 		auth->fd = -1;
 	}
 	auth->version_received = FALSE;
+	i_zero(&auth->connect_time);
+	i_zero(&auth->handshake_time);
 }
 
 static void master_login_auth_unref(struct master_login_auth **_auth)
@@ -177,7 +192,7 @@ static void master_login_auth_timeout(struct master_login_auth *auth)
 		reason = t_strdup_printf(
 			"Auth server request timed out after %u secs",
 			(unsigned int)(ioloop_time - request->create_stamp.tv_sec));
-		request_internal_failure(request, reason);
+		request_internal_failure(auth, request, reason);
 		i_free(request);
 	}
 	timeout_remove(&auth->to);
@@ -273,7 +288,7 @@ master_login_auth_input_notfound(struct master_login_auth *auth,
 		const char *reason = t_strdup_printf(
 			"Authenticated user not found from userdb, "
 			"auth lookup id=%u", id);
-		request_internal_failure(request, reason);
+		request_internal_failure(auth, request, reason);
 		i_free(request);
 	}
 	return TRUE;
@@ -300,12 +315,12 @@ master_login_auth_input_fail(struct master_login_auth *auth,
 	request = master_login_auth_lookup_request(auth, id);
 	if (request != NULL) {
 		if (error == NULL) {
-			request_internal_failure(request,
+			request_internal_failure(auth, request,
 						 "Internal auth failure");
 		} else {
 			const char *log_reason = t_strdup_printf(
 				"Internal auth failure: %s", error);
-			request_failure(request, log_reason, error);
+			request_failure(auth, request, log_reason, error);
 		}
 		i_free(request);
 	}
@@ -349,6 +364,7 @@ static void master_login_auth_input(struct master_login_auth *auth)
 			return;
 		}
 		auth->version_received = TRUE;
+		auth->handshake_time = ioloop_timeval;
 	}
 	if (!auth->spid_received) {
 		line = i_stream_next_line(auth->input);
@@ -398,6 +414,8 @@ master_login_auth_connect(struct master_login_auth *auth)
 			auth->auth_socket_path);
 		return -1;
 	}
+	io_loop_time_refresh();
+	auth->connect_time = ioloop_timeval;
 	auth->fd = fd;
 	auth->input = i_stream_create_fd(fd, AUTH_MAX_INBUF_SIZE, FALSE);
 	auth->output = o_stream_create_fd(fd, (size_t)-1, FALSE);