changeset 21587:22f153275e33

imap: Include info about last command in disconnection log line. Only if LOGOUT isn't sent, because that's already visible.
author Timo Sirainen <timo.sirainen@dovecot.fi>
date Thu, 16 Feb 2017 20:39:12 +0200
parents 85d1fdc8fc56
children 03b2c50c18af
files src/imap/imap-client.c src/imap/imap-client.h
diffstat 2 files changed, 42 insertions(+), 2 deletions(-) [+]
line wrap: on
line diff
--- a/src/imap/imap-client.c	Thu Feb 16 20:29:46 2017 +0200
+++ b/src/imap/imap-client.c	Thu Feb 16 20:39:12 2017 +0200
@@ -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;
 
@@ -303,6 +307,33 @@
 	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;
@@ -312,7 +343,7 @@
 	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);
@@ -333,7 +364,7 @@
 		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))
@@ -440,6 +471,8 @@
 
 	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);
@@ -813,6 +846,10 @@
 		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;
 
--- a/src/imap/imap-client.h	Thu Feb 16 20:29:46 2017 +0200
+++ b/src/imap/imap-client.h	Thu Feb 16 20:39:12 2017 +0200
@@ -159,6 +159,9 @@
 	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;