auth: Improve auth-master connections' error logging

Include connect and handshake times in the error message.

diff --git a/src/auth/auth-master-connection.c b/src/auth/auth-master-connection.c
index 368c78bb61f327c5db0f6c46e2ec12a2dc90b49a..08a92aefca617b701b1fa24a5035c1e1e2e51ced 100644 (file)
--- a/src/auth/auth-master-connection.c
+++ b/src/auth/auth-master-connection.c
@@ -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 @@ void auth_master_request_callback(const char *reply, struct auth_master_connecti
        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 @@ master_input_request(struct auth_master_connection *conn, const char *args)
            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 @@ master_input_cache_flush(struct auth_master_connection *conn, const char *args)
        /* <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 @@ master_input_auth_request(struct auth_master_connection *conn, const char *args,
        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 @@ master_input_auth_request(struct auth_master_connection *conn, const char *args,
        }
 
        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 @@ master_input_list(struct auth_master_connection *conn, const char *args)
        /* <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 @@ master_input_list(struct auth_master_connection *conn, const char *args)
        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 @@ auth_master_input_line(struct auth_master_connection *conn, const char *line)
                if (str_begins(line, "CACHE-FLUSH\t"))
                        return master_input_cache_flush(conn, line + 12);
                if (str_begins(line, "CPID\t")) {
-                       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 @@ static void master_input(struct auth_master_connection *conn)
                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 @@ static void master_input(struct auth_master_connection *conn)
                if (!str_begins(line, "VERSION\t") ||
                    !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 @@ auth_master_connection_set_permissions(struct auth_master_connection *conn,
        }
 
        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 @@ auth_master_connection_create(struct auth *auth, int fd,
        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);

diff --git a/src/auth/auth-master-connection.h b/src/auth/auth-master-connection.h
index d59c6a613f1c8b4afff4192fc6b849327c2b350c..20d52ac7aaf606a36b7f5c47b47d75c00f478b5a 100644 (file)
--- a/src/auth/auth-master-connection.h
+++ b/src/auth/auth-master-connection.h
@@ -9,6 +9,8 @@ struct auth_master_connection {
        struct auth *auth;
        int refcount;
 
+       struct timeval create_time, handshake_time;
+
        int fd;
        char *path;
        struct istream *input;
@@ -25,6 +27,9 @@ struct auth_master_connection {
        bool 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 --git a/src/auth/auth-request-handler.c b/src/auth/auth-request-handler.c
index 239b95e23c041478e9947145b038d1ef6c50fff0..6df08bae2105cbb4d27ab590656b59a21679898f 100644 (file)
--- a/src/auth/auth-request-handler.c
+++ b/src/auth/auth-request-handler.c
@@ -777,7 +777,7 @@ bool auth_request_handler_master_request(struct auth_request_handler *handler,
 
        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);
        }
@@ -803,7 +803,8 @@ bool auth_request_handler_master_request(struct auth_request_handler *handler,
        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,
@@ -813,7 +814,8 @@ bool auth_request_handler_master_request(struct auth_request_handler *handler,
 
        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);