Skip to content

Commit

Permalink
auth: Improve auth-master connections' error logging
Browse files Browse the repository at this point in the history 
Include connect and handshake times in the error message.
  • Loading branch information
@sirainen
sirainen committed May 4, 2018
1 parent 74e4ec1 commit 0ff9d7d
Show file tree
Hide file tree
Showing 3 changed files with 61 additions and 20 deletions.
68 changes: 51 additions & 17 deletions src/auth/auth-master-connection.c
View file
Expand Up @@ -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"
Expand Down Expand Up @@ -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)
{
Expand All @@ -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));
Expand All @@ -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;
}

Expand Down Expand Up @@ -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;
}

Expand All @@ -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;
Expand Down Expand Up @@ -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);
Expand All @@ -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;
Expand Down Expand Up @@ -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;
Expand All @@ -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;
Expand All @@ -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) {
Expand Down Expand Up @@ -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;
}

Expand Down Expand Up @@ -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);
Expand Down
5 changes: 5 additions & 0 deletions src/auth/auth-master-connection.h
View file
Expand Up @@ -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;
Expand All @@ -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,
Expand Down
8 changes: 5 additions & 3 deletions src/auth/auth-request-handler.c
View file
Expand Up @@ -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);
}
Expand All @@ -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,
Expand All @@ -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);
Expand Down

0 comments on commit 0ff9d7d

Please sign in to comment.