# HG changeset patch
# User Timo Sirainen <timo.sirainen@dovecot.fi>
# Date 1525430543 -10800
# Node ID 9b388281d133a98461b60e812561f29278fc4271
# Parent  97f4fd2d1566b2d6f17686e31cd3ac0609f8bc88
lib-master: Improve error logging for post-login script failures

diff -r 97f4fd2d1566 -r 9b388281d133 src/lib-master/master-login.c
--- a/src/lib-master/master-login.c	Fri May 04 13:23:07 2018 +0300
+++ b/src/lib-master/master-login.c	Fri May 04 13:42:23 2018 +0300
@@ -39,6 +39,7 @@
 	struct master_login_client *client;
 
 	int fd;
+	struct timeval create_time;
 	struct io *io;
 	struct timeout *to;
 	string_t *input;
@@ -129,6 +130,14 @@
 			    (long)client->auth_req.auth_pid,
 			    client->auth_req.client_pid,
 			    client->auth_req.auth_id);
+		if (client->postlogin_client != NULL) {
+			struct master_login_postlogin *pl =
+				client->postlogin_client;
+			str_printfa(str, ", post-login script %s started %d msecs ago",
+				    pl->socket_path,
+				    timeval_diff_msecs(&ioloop_timeval,
+						       &pl->create_time));
+		}
 	}
 	i_error("%s (%s)", t_strdup_vprintf(fmt, args), str_c(str));
 	va_end(args);
@@ -261,6 +270,10 @@
 
 static void master_login_postlogin_free(struct master_login_postlogin *pl)
 {
+	if (pl->client != NULL) {
+		i_assert(pl->client->postlogin_client == pl);
+		master_login_client_free(&pl->client);
+	}
 	timeout_remove(&pl->to);
 	io_remove(&pl->io);
 	if (close(pl->fd) < 0)
@@ -273,6 +286,7 @@
 
 static void master_login_postlogin_input(struct master_login_postlogin *pl)
 {
+	struct master_login_connection *conn = pl->client->conn;
 	char buf[1024];
 	const char **auth_args, **p;
 	size_t len;
@@ -283,7 +297,7 @@
 		if (fd != -1) {
 			/* post-login script replaced fd */
 			if (close(pl->client->fd) < 0)
-				i_error("close(client) failed: %m");
+				conn_error(conn, "close(client) failed: %m");
 			pl->client->fd = fd;
 		}
 		str_append_n(pl->input, buf, ret);
@@ -298,15 +312,14 @@
 			if (errno == EAGAIN)
 				return;
 
-			i_error("fd_read(%s) failed: %m", pl->socket_path);
+			conn_error(conn, "fd_read(%s) failed: %m", pl->socket_path);
 		} else if (str_len(pl->input) > 0) {
-			i_error("fd_read(%s) failed: disconnected",
-				pl->socket_path);
+			conn_error(conn, "fd_read(%s) failed: disconnected",
+				   pl->socket_path);
 		} else {
-			i_info("Post-login script denied access to user %s",
-			       pl->username);
+			conn_error(conn, "Post-login script denied access to user %s",
+				   pl->username);
 		}
-		master_login_client_free(&pl->client);
 		master_login_postlogin_free(pl);
 		return;
 	}
@@ -315,16 +328,18 @@
 	for (p = auth_args; *p != NULL; p++)
 		*p = str_tabunescape(t_strdup_noconst(*p));
 
+	pl->client->postlogin_client = NULL;
 	master_login_auth_finish(pl->client, auth_args);
+
+	pl->client = NULL;
 	master_login_postlogin_free(pl);
 }
 
 static void master_login_postlogin_timeout(struct master_login_postlogin *pl)
 {
-	i_error("%s: Timeout waiting for post-login script to finish, aborting",
-		pl->socket_path);
+	conn_error(pl->client->conn,
+		   "Timeout waiting for post-login script to finish, aborting");
 
-	master_login_client_free(&pl->client);
 	master_login_postlogin_free(pl);
 }
 
@@ -341,9 +356,9 @@
 
 	fd = net_connect_unix_with_retries(socket_path, 1000);
 	if (fd == -1) {
-		i_error("net_connect_unix(%s) failed: %m%s",
-			socket_path, errno != EAGAIN ? "" :
-			" - http://wiki2.dovecot.org/SocketUnavailable");
+		conn_error(client->conn, "net_connect_unix(%s) failed: %m%s",
+			   socket_path, errno != EAGAIN ? "" :
+			   " - http://wiki2.dovecot.org/SocketUnavailable");
 		return -1;
 	}
 
@@ -359,24 +374,29 @@
 	ret = fd_send(fd, client->fd, str_data(str), str_len(str));
 	if (ret != (ssize_t)str_len(str)) {
 		if (ret < 0) {
-			i_error("write(%s) failed: %m", socket_path);
+			conn_error(client->conn, "write(%s) failed: %m", socket_path);
 		} else {
-			i_error("write(%s) failed: partial write", socket_path);
+			conn_error(client->conn, "write(%s) failed: partial write", socket_path);
 		}
 		i_close_fd(&fd);
 		return -1;
 	}
 	net_set_nonblock(fd, TRUE);
+	io_loop_time_refresh();
 
 	pl = i_new(struct master_login_postlogin, 1);
 	pl->client = client;
 	pl->username = i_strdup(auth_args[0]);
 	pl->socket_path = i_strdup(socket_path);
+	pl->create_time = ioloop_timeval;
 	pl->fd = fd;
 	pl->io = io_add(fd, IO_READ, master_login_postlogin_input, pl);
 	pl->to = timeout_add(login->postlogin_timeout_secs * 1000,
 			     master_login_postlogin_timeout, pl);
 	pl->input = str_new(default_pool, 512);
+
+	i_assert(client->postlogin_client == NULL);
+	client->postlogin_client = pl;
 	return 0;
 }
 
diff -r 97f4fd2d1566 -r 9b388281d133 src/lib-master/master-login.h
--- a/src/lib-master/master-login.h	Fri May 04 13:23:07 2018 +0300
+++ b/src/lib-master/master-login.h	Fri May 04 13:42:23 2018 +0300
@@ -10,6 +10,8 @@
 	struct master_login_connection *conn;
 	/* linked list of all clients within the connection */
 	struct master_login_client *prev, *next;
+	/* non-NULL while running postlogin script */
+	struct master_login_postlogin *postlogin_client;
 
 	int fd;
 	struct timeval create_time;