From: Timo Sirainen <timo.sirainen@dovecot.fi>
Date: Thu, 16 Feb 2017 18:39:12 +0000 (+0200)
Subject: imap: Include info about last command in disconnection log line.
X-Git-Tag: 2.3.0.rc1~2072
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=9036b11c0f06193bfebab686d75982d7930cb517;p=thirdparty%2Fdovecot%2Fcore.git

imap: Include info about last command in disconnection log line.

Only if LOGOUT isn't sent, because that's already visible.
---

diff --git a/src/imap/imap-client.c b/src/imap/imap-client.c
index 7917a053b6..516f23f560 100644
--- a/src/imap/imap-client.c
+++ b/src/imap/imap-client.c
@@ -26,6 +26,10 @@
 
 #include <unistd.h>
 
+/* If the last command took longer than this to run, log statistics on
+   where the time was spent. */
+#define IMAP_CLIENT_DISCONNECT_LOG_STATS_CMD_MIN_RUNNING_MSECS 1000
+
 extern struct mail_storage_callbacks mail_storage_callbacks;
 extern struct imap_client_vfuncs imap_client_vfuncs;
 
@@ -298,6 +302,33 @@ client_command_stats_append(string_t *str,
 	str_append(str, " B out");
 }
 
+static const char *client_get_last_command_status(struct client *client)
+{
+	if (client->logged_out)
+		return "";
+	if (client->last_cmd_name == NULL)
+		return " (No commands sent)";
+
+	/* client disconnected without sending LOGOUT. if the last command
+	   took over 1 second to run, log it. */
+	const struct client_command_stats *stats = &client->last_cmd_stats;
+
+	string_t *str = t_str_new(128);
+	int last_run_secs = timeval_diff_msecs(&ioloop_timeval,
+					       &stats->last_run_timeval);
+	str_printfa(str, " (%s finished %d.%03d secs ago",
+		    client->last_cmd_name, last_run_secs/1000,
+		    last_run_secs%1000);
+
+	if (timeval_diff_msecs(&stats->last_run_timeval, &stats->start_time) >=
+	    IMAP_CLIENT_DISCONNECT_LOG_STATS_CMD_MIN_RUNNING_MSECS) {
+		str_append(str, " - ");
+		client_command_stats_append(str, stats, "", 0);
+	}
+	str_append_c(str, ')');
+	return str_c(str);
+}
+
 static const char *client_get_commands_status(struct client *client)
 {
 	struct client_command_context *cmd, *last_cmd = NULL;
@@ -307,7 +338,7 @@ static const char *client_get_commands_status(struct client *client)
 	const char *cond_str;
 
 	if (client->command_queue == NULL)
-		return "";
+		return client_get_last_command_status(client);
 
 	i_zero(&all_stats);
 	str = t_str_new(128);
@@ -328,7 +359,7 @@ static const char *client_get_commands_status(struct client *client)
 		last_cmd = cmd;
 	}
 	if (last_cmd == NULL)
-		return "";
+		return client_get_last_command_status(client);
 
 	cond = io_loop_find_fd_conditions(current_ioloop, client->fd_out);
 	if ((cond & (IO_READ | IO_WRITE)) == (IO_READ | IO_WRITE))
@@ -435,6 +466,8 @@ static void client_default_destroy(struct client *client, const char *reason)
 
 	imap_client_count--;
 	DLLIST_REMOVE(&imap_clients, client);
+
+	i_free(client->last_cmd_name);
 	pool_unref(&client->pool);
 
 	master_service_client_connection_destroyed(master_service);
@@ -815,6 +848,10 @@ void client_command_free(struct client_command_context **_cmd)
 		client_send_tagline(cmd, "NO Command cancelled.");
 	}
 
+	i_free(client->last_cmd_name);
+	client->last_cmd_name = i_strdup(cmd->name);
+	client->last_cmd_stats = cmd->stats;
+
 	if (!cmd->param_error)
 		client->bad_counter = 0;
 
diff --git a/src/imap/imap-client.h b/src/imap/imap-client.h
index a8ae2d7d04..b363b3e589 100644
--- a/src/imap/imap-client.h
+++ b/src/imap/imap-client.h
@@ -159,6 +159,9 @@ struct client {
 	struct client_command_context *command_queue;
 	unsigned int command_queue_size;
 
+	char *last_cmd_name;
+	struct client_command_stats last_cmd_stats;
+
 	uint64_t sync_last_full_modseq;
 	uint64_t highest_fetch_modseq;
 	ARRAY_TYPE(seq_range) fetch_failed_uids;