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 6305153388b4d621e98581059e53375aaf74e2b1..de0953b61b9645b51ee69d58ef7d63a97c76f9dc 100644 (file)
--- 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);