--- a/src/lib-master/master-login-auth.c	Fri May 04 14:10:49 2018 +0300
+++ b/src/lib-master/master-login-auth.c	Fri May 04 14:14:35 2018 +0300
@@ -42,6 +42,8 @@
 	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 @@
 	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 @@
 		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 @@
 		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 @@
 		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 @@
 		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 @@
 	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 @@
 			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 @@
 			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);