# HG changeset patch
# User Timo Sirainen <timo.sirainen@dovecot.fi>
# Date 1525436834 -10800
# Node ID 9d607779f1923befbe532d11873642cabb281aee
# Parent  642077a33b6ab8705d08a3410f6b4546fd7e7968
auth: Improve auth-master connections' error logging

Include connect and handshake times in the error message.

diff -r 642077a33b6a -r 9d607779f192 src/auth/auth-master-connection.c
--- a/src/auth/auth-master-connection.c	Fri May 04 14:14:35 2018 +0300
+++ b/src/auth/auth-master-connection.c	Fri May 04 15:27:14 2018 +0300
@@ -7,6 +7,7 @@
 #include "str.h"
 #include "strescape.h"
 #include "str-sanitize.h"
+#include "time-util.h"
 #include "hostpid.h"
 #include "hex-binary.h"
 #include "ioloop.h"
@@ -85,6 +86,24 @@
 	o_stream_nsendv(conn->output, iov, 2);
 }
 
+void auth_master_log_error(struct auth_master_connection *conn,
+			   const char *fmt, ...)
+{
+	va_list args;
+	string_t *str = t_str_new(128);
+
+	str_printfa(str, "created %d msecs ago",
+		    timeval_diff_msecs(&ioloop_timeval, &conn->create_time));
+	if (conn->handshake_time.tv_sec != 0) {
+		str_printfa(str, ", handshake %d msecs ago",
+			    timeval_diff_msecs(&ioloop_timeval, &conn->create_time));
+	}
+
+	va_start(args, fmt);
+	i_error("%s (%s)", t_strdup_vprintf(fmt, args), str_c(str));
+	va_end(args);
+}
+
 static bool
 master_input_request(struct auth_master_connection *conn, const char *args)
 {
@@ -100,31 +119,35 @@
 	    str_to_uint(list[0], &id) < 0 ||
 	    str_to_uint(list[1], &client_pid) < 0 ||
 	    str_to_uint(list[2], &client_id) < 0) {
-		i_error("BUG: Master sent broken REQUEST");
+		auth_master_log_error(conn, "BUG: Master sent broken REQUEST");
 		return FALSE;
 	}
 
 	buffer_create_from_data(&buf, cookie, sizeof(cookie));
 	if (hex_to_binary(list[3], &buf) < 0) {
-		i_error("BUG: Master sent broken REQUEST cookie");
+		auth_master_log_error(conn,
+			"BUG: Master sent broken REQUEST cookie");
 		return FALSE;
 	}
 	params = list + 4;
 
 	client_conn = auth_client_connection_lookup(client_pid);
 	if (client_conn == NULL) {
-		i_error("Master requested auth for nonexistent client %u",
+		auth_master_log_error(conn,
+			"Master requested auth for nonexistent client %u",
 			client_pid);
 		o_stream_nsend_str(conn->output,
 				   t_strdup_printf("FAIL\t%u\n", id));
 	} else if (!mem_equals_timing_safe(client_conn->cookie, cookie, sizeof(cookie))) {
-		i_error("Master requested auth for client %u with invalid cookie",
+		auth_master_log_error(conn,
+			"Master requested auth for client %u with invalid cookie",
 			client_pid);
 		o_stream_nsend_str(conn->output,
 				   t_strdup_printf("FAIL\t%u\n", id));
 	} else if (!auth_request_handler_master_request(
 			client_conn->request_handler, conn, id, client_id, params)) {
-		i_error("Master requested auth for non-login client %u",
+		auth_master_log_error(conn,
+			"Master requested auth for non-login client %u",
 			client_pid);
 		o_stream_nsend_str(conn->output,
 				   t_strdup_printf("FAIL\t%u\n", id));
@@ -141,7 +164,8 @@
 	/* <id> [<user> [<user> [..]] */
 	list = t_strsplit_tabescaped(args);
 	if (list[0] == NULL) {
-		i_error("BUG: doveadm sent broken CACHE-FLUSH");
+		auth_master_log_error(conn,
+			"BUG: doveadm sent broken CACHE-FLUSH");
 		return FALSE;
 	}
 
@@ -172,7 +196,7 @@
 	list = t_strsplit_tabescaped(args);
 	if (list[0] == NULL || list[1] == NULL ||
 	    str_to_uint(list[0], &id) < 0) {
-		i_error("BUG: Master sent broken %s", cmd);
+		auth_master_log_error(conn, "BUG: Master sent broken %s", cmd);
 		return -1;
 	}
 
@@ -196,7 +220,8 @@
 	}
 
 	if (auth_request->service == NULL) {
-		i_error("BUG: Master sent %s request without service", cmd);
+		auth_master_log_error(conn,
+			"BUG: Master sent %s request without service", cmd);
 		auth_request_unref(&auth_request);
 		auth_master_connection_unref(&conn);
 		return -1;
@@ -533,20 +558,22 @@
 	/* <id> [<parameters>] */
 	list = t_strsplit_tabescaped(args);
 	if (list[0] == NULL || str_to_uint(list[0], &id) < 0) {
-		i_error("BUG: Master sent broken LIST");
+		auth_master_log_error(conn, "BUG: Master sent broken LIST");
 		return FALSE;
 	}
 	list++;
 
 	if (conn->iter_ctx != NULL) {
-		i_error("Auth client is already iterating users");
+		auth_master_log_error(conn,
+			"Auth client is already iterating users");
 		str = t_strdup_printf("DONE\t%u\tfail\n", id);
 		o_stream_nsend_str(conn->output, str);
 		return TRUE;
 	}
 
 	if (conn->userdb_restricted_uid != 0) {
-		i_error("Auth client doesn't have permissions to list users: %s",
+		auth_master_log_error(conn,
+			"Auth client doesn't have permissions to list users: %s",
 			auth_restricted_reason(conn));
 		str = t_strdup_printf("DONE\t%u\tfail\n", id);
 		o_stream_nsend_str(conn->output, str);
@@ -556,7 +583,8 @@
 	while (userdb != NULL && userdb->userdb->iface->iterate_init == NULL)
 		userdb = userdb->next;
 	if (userdb == NULL) {
-		i_error("Trying to iterate users, but userdbs don't support it");
+		auth_master_log_error(conn,
+			"Trying to iterate users, but userdbs don't support it");
 		str = t_strdup_printf("DONE\t%u\tfail\n", id);
 		o_stream_nsend_str(conn->output, str);
 		return TRUE;
@@ -624,13 +652,14 @@
 		if (strncmp(line, "CACHE-FLUSH\t", 12) == 0)
 			return master_input_cache_flush(conn, line + 12);
 		if (strncmp(line, "CPID\t", 5) == 0) {
-			i_error("Authentication client trying to connect to "
+			auth_master_log_error(conn,
+				"Authentication client trying to connect to "
 				"master socket");
 			return FALSE;
 		}
 	}
 
-	i_error("BUG: Unknown command in %s socket: %s",
+	auth_master_log_error(conn, "BUG: Unknown command in %s socket: %s",
 		conn->userdb_only ? "userdb" : "master",
 		str_sanitize(line, 80));
 	return FALSE;
@@ -650,7 +679,8 @@
 		return;
 	case -2:
 		/* buffer full */
-		i_error("BUG: Master sent us more than %d bytes",
+		auth_master_log_error(conn,
+			"BUG: Master sent us more than %d bytes",
 			(int)MAX_INBUF_SIZE);
                 auth_master_connection_destroy(&conn);
 		return;
@@ -665,12 +695,14 @@
 		if (strncmp(line, "VERSION\t", 8) != 0 ||
 		    !str_uint_equals(t_strcut(line + 8, '\t'),
 				     AUTH_MASTER_PROTOCOL_MAJOR_VERSION)) {
-			i_error("Master not compatible with this server "
+			auth_master_log_error(conn,
+				"Master not compatible with this server "
 				"(mixed old and new binaries?)");
 			auth_master_connection_destroy(&conn);
 			return;
 		}
 		conn->version_received = TRUE;
+		conn->handshake_time = ioloop_timeval;
 	}
 
 	while ((line = i_stream_next_line(conn->input)) != NULL) {
@@ -718,7 +750,8 @@
 	}
 
 	if (net_getunixcred(conn->fd, &cred) < 0) {
-		i_error("userdb connection: Failed to get peer's credentials");
+		auth_master_log_error(conn,
+			"userdb connection: Failed to get peer's credentials");
 		return -1;
 	}
 
@@ -746,6 +779,7 @@
 	conn = i_new(struct auth_master_connection, 1);
 	conn->refcount = 1;
 	conn->fd = fd;
+	conn->create_time = ioloop_timeval;
 	conn->path = i_strdup(path);
 	conn->auth = auth;
 	conn->input = i_stream_create_fd(fd, MAX_INBUF_SIZE, FALSE);
diff -r 642077a33b6a -r 9d607779f192 src/auth/auth-master-connection.h
--- a/src/auth/auth-master-connection.h	Fri May 04 14:14:35 2018 +0300
+++ b/src/auth/auth-master-connection.h	Fri May 04 15:27:14 2018 +0300
@@ -9,6 +9,8 @@
 	struct auth *auth;
 	int refcount;
 
+	struct timeval create_time, handshake_time;
+
 	int fd;
 	char *path;
 	struct istream *input;
@@ -25,6 +27,9 @@
 	unsigned int userdb_only:1;
 };
 
+void auth_master_log_error(struct auth_master_connection *conn,
+			   const char *fmt, ...) ATTR_FORMAT(2, 3);
+
 struct auth_master_connection *
 auth_master_connection_create(struct auth *auth, int fd,
 			      const char *path, const struct stat *socket_st,
diff -r 642077a33b6a -r 9d607779f192 src/auth/auth-request-handler.c
--- a/src/auth/auth-request-handler.c	Fri May 04 14:14:35 2018 +0300
+++ b/src/auth/auth-request-handler.c	Fri May 04 15:27:14 2018 +0300
@@ -736,7 +736,7 @@
 
 	request = hash_table_lookup(handler->requests, POINTER_CAST(client_id));
 	if (request == NULL) {
-		i_error("Master request %u.%u not found",
+		auth_master_log_error(master, "Master request %u.%u not found",
 			handler->client_pid, client_id);
 		return auth_master_request_failed(handler, master, id);
 	}
@@ -762,7 +762,8 @@
 	if (request->session_pid != (pid_t)-1 &&
 	    net_getunixcred(master->fd, &cred) == 0 &&
 	    cred.pid != (pid_t)-1 && request->session_pid != cred.pid) {
-		i_error("Session pid %ld provided by master for request %u.%u "
+		auth_master_log_error(master,
+			"Session pid %ld provided by master for request %u.%u "
 			"did not match peer credentials (pid=%ld, uid=%ld)",
 			(long)request->session_pid,
 			handler->client_pid, client_id,
@@ -772,7 +773,8 @@
 
 	if (request->state != AUTH_REQUEST_STATE_FINISHED ||
 	    !request->successful) {
-		i_error("Master requested unfinished authentication request "
+		auth_master_log_error(master,
+			"Master requested unfinished authentication request "
 			"%u.%u", handler->client_pid, client_id);
 		handler->master_callback(t_strdup_printf("FAIL\t%u", id),
 					 master);