[Dovecot] verbose imap logging

Jens Laas jens.laas at data.slu.se
Wed Aug 24 15:06:08 EEST 2005


Implements more verbose imap logging (when client exits).
Similar to existing logging in POP3.

Due to the nature of imap and my incomplete understanding (of the 
dovecot code) the session statistics reported have varying accuracy.

Much better than nothing IMO.

Cheers,
Jens

-----------------------------------------------------------------------
     'This mail automatically becomes portable when carried.'
-----------------------------------------------------------------------
     Jens Låås                              Email: jens.laas at data.slu.se
     Department of Computer Services, SLU   Phone: +46 18 67 35 15
     Vindbrovägen 1
     P.O. Box 7079
     S-750 07 Uppsala
     SWEDEN
-----------------------------------------------------------------------
-------------- next part --------------
diff -ur dovecot-1.0.alpha1.orig/src/imap/client.c dovecot-1.0.alpha1/src/imap/client.c
--- dovecot-1.0.alpha1.orig/src/imap/client.c	2005-07-03 23:32:21.000000000 +0200
+++ dovecot-1.0.alpha1/src/imap/client.c	2005-08-23 10:39:08.000000000 +0200
@@ -56,10 +56,22 @@
 	return client;
 }
 
-void client_destroy(struct client *client)
+static const char *client_stats(struct client *client)
+{
+	return t_strdup_printf("retr=%dB/%d#, del=%d exp=%d", 
+			       client->retr_bytes,
+			       client->retr_messages,
+			       client->deleted_count,
+			       client->expunged_count);
+}
+
+void client_destroy(struct client *client, const char *reason)
 {
 	int ret;
 
+	if (reason != NULL)
+	  i_info("%s %s", reason, client_stats(client));
+	
 	if (client->command_pending) {
 		/* try to deinitialize the command */
 		i_stream_close(client->input);
@@ -88,8 +100,11 @@
 	io_loop_stop(ioloop);
 }
 
-void client_disconnect(struct client *client)
+void client_disconnect(struct client *client, const char *reason)
 {
+  	if (reason != NULL)
+	  i_info("%s %s", reason, client_stats(client));
+	
 	(void)o_stream_flush(client->output);
 
 	i_stream_close(client->input);
@@ -99,7 +114,7 @@
 void client_disconnect_with_error(struct client *client, const char *msg)
 {
 	client_send_line(client, t_strconcat("* BYE ", msg, NULL));
-	client_disconnect(client);
+	client_disconnect(client, msg);
 }
 
 int client_send_line(struct client *client, const char *data)
@@ -367,7 +382,7 @@
 	switch (i_stream_read(client->input)) {
 	case -1:
 		/* disconnected */
-		client_destroy(client);
+		client_destroy(client, "Disconnected (read input)");
 		return;
 	case -2:
 		/* parameter word is longer than max. input buffer size.
@@ -392,7 +407,7 @@
 		client->input_pending = TRUE;
 
 	if (client->output->closed)
-		client_destroy(client);
+		client_destroy(client, "Disconnected (output closed)");
 }
 
 int _client_output(void *context)
@@ -404,7 +419,7 @@
 	client->last_output = ioloop_time;
 
 	if ((ret = o_stream_flush(client->output)) < 0) {
-		client_destroy(client);
+		client_destroy(client, "Disconnect (output)");
 		return 1;
 	}
 
@@ -449,14 +464,14 @@
 	    o_stream_get_buffer_used_size(my_client->output) > 0 &&
 	    idle_time >= CLIENT_OUTPUT_TIMEOUT) {
 		/* client isn't reading our output */
-		client_destroy(my_client);
+		client_destroy(my_client, "Disconnect (client hang)");
 	} else if (idle_time >= CLIENT_IDLE_TIMEOUT) {
 		/* client isn't sending us anything */
 		if (!my_client->command_pending) {
 			client_send_line(my_client,
 					 "* BYE Disconnected for inactivity.");
 		}
-		client_destroy(my_client);
+		client_destroy(my_client, "Disconnect (inactivity)");
 	}
 }
 
@@ -470,7 +485,7 @@
 {
 	if (my_client != NULL) {
 		client_send_line(my_client, "* BYE Server shutting down.");
-		client_destroy(my_client);
+		client_destroy(my_client, "Disconnect (server shutdown)");
 	}
 
 	timeout_remove(to_idle);
diff -ur dovecot-1.0.alpha1.orig/src/imap/client.h dovecot-1.0.alpha1/src/imap/client.h
--- dovecot-1.0.alpha1.orig/src/imap/client.h	2005-08-07 13:39:04.000000000 +0200
+++ dovecot-1.0.alpha1/src/imap/client.h	2005-08-23 10:39:08.000000000 +0200
@@ -40,6 +40,8 @@
 	unsigned int select_counter; /* increased when mailbox is changed */
 	uint32_t messages_count, recent_count;
 
+  int deleted_count, expunged_count, retr_bytes, retr_messages;
+
 	time_t last_input, last_output;
 	unsigned int bad_counter;
 
@@ -57,10 +59,10 @@
 /* Create new client with specified input/output handles. socket specifies
    if the handle is a socket. */
 struct client *client_create(int hin, int hout, struct namespace *namespaces);
-void client_destroy(struct client *client);
+void client_destroy(struct client *client, const char *reason);
 
 /* Disconnect client connection */
-void client_disconnect(struct client *client);
+void client_disconnect(struct client *client, const char *reason);
 void client_disconnect_with_error(struct client *client, const char *msg);
 
 /* Send a line of data to client. Returns 1 if ok, 0 if buffer is getting full,
diff -ur dovecot-1.0.alpha1.orig/src/imap/cmd-append.c dovecot-1.0.alpha1/src/imap/cmd-append.c
--- dovecot-1.0.alpha1.orig/src/imap/cmd-append.c	2005-06-28 22:58:17.000000000 +0200
+++ dovecot-1.0.alpha1/src/imap/cmd-append.c	2005-08-23 10:39:08.000000000 +0200
@@ -38,7 +38,7 @@
 	switch (i_stream_read(client->input)) {
 	case -1:
 		/* disconnected */
-		client_destroy(client);
+		client_destroy(client, "Disconnected (input)");
 		return;
 	case -2:
 		if (client->command_pending) {
diff -ur dovecot-1.0.alpha1.orig/src/imap/cmd-close.c dovecot-1.0.alpha1/src/imap/cmd-close.c
--- dovecot-1.0.alpha1.orig/src/imap/cmd-close.c	2005-03-08 21:26:55.000000000 +0100
+++ dovecot-1.0.alpha1/src/imap/cmd-close.c	2005-08-23 10:39:08.000000000 +0200
@@ -17,7 +17,7 @@
 	client->mailbox = NULL;
 
 	if (!mailbox_is_readonly(mailbox)) {
-		if (!imap_expunge(mailbox, NULL))
+		if (!imap_expunge(mailbox, NULL, client))
 			client_send_untagged_storage_error(client, storage);
 	}
 
diff -ur dovecot-1.0.alpha1.orig/src/imap/cmd-expunge.c dovecot-1.0.alpha1/src/imap/cmd-expunge.c
--- dovecot-1.0.alpha1.orig/src/imap/cmd-expunge.c	2005-05-08 12:06:07.000000000 +0200
+++ dovecot-1.0.alpha1/src/imap/cmd-expunge.c	2005-08-23 10:39:08.000000000 +0200
@@ -28,7 +28,7 @@
 	if (search_arg == NULL)
 		return TRUE;
 
-	if (imap_expunge(client->mailbox, search_arg))
+	if (imap_expunge(client->mailbox, search_arg, client))
 		return cmd_sync(cmd, 0, "OK Expunge completed.");
 	else {
 		client_send_storage_error(cmd,
@@ -44,7 +44,7 @@
 	if (!client_verify_open_mailbox(cmd))
 		return TRUE;
 
-	if (imap_expunge(client->mailbox, NULL))
+	if (imap_expunge(client->mailbox, NULL, client))
 		return cmd_sync(cmd, 0, "OK Expunge completed.");
 	else {
 		client_send_storage_error(cmd,
diff -ur dovecot-1.0.alpha1.orig/src/imap/cmd-idle.c dovecot-1.0.alpha1/src/imap/cmd-idle.c
--- dovecot-1.0.alpha1.orig/src/imap/cmd-idle.c	2005-08-07 13:39:04.000000000 +0200
+++ dovecot-1.0.alpha1/src/imap/cmd-idle.c	2005-08-23 10:39:08.000000000 +0200
@@ -70,7 +70,7 @@
 	switch (i_stream_read(client->input)) {
 	case -1:
 		/* disconnected */
-		client_destroy(client);
+		client_destroy(client, "Disconnected (input)");
 		return;
 	case -2:
 		client->input_skip_line = TRUE;
diff -ur dovecot-1.0.alpha1.orig/src/imap/cmd-logout.c dovecot-1.0.alpha1/src/imap/cmd-logout.c
--- dovecot-1.0.alpha1.orig/src/imap/cmd-logout.c	2005-03-08 21:26:56.000000000 +0100
+++ dovecot-1.0.alpha1/src/imap/cmd-logout.c	2005-08-23 10:39:08.000000000 +0200
@@ -20,6 +20,6 @@
 	}
 
 	client_send_tagline(cmd, "OK Logout completed.");
-	client_disconnect(client);
+	client_disconnect(client, "Logout");
 	return TRUE;
 }
diff -ur dovecot-1.0.alpha1.orig/src/imap/cmd-store.c dovecot-1.0.alpha1/src/imap/cmd-store.c
--- dovecot-1.0.alpha1.orig/src/imap/cmd-store.c	2005-03-29 10:38:42.000000000 +0200
+++ dovecot-1.0.alpha1/src/imap/cmd-store.c	2005-08-23 10:39:08.000000000 +0200
@@ -99,6 +99,10 @@
 				failed = TRUE;
 				break;
 			}
+			
+			if( ( (mail_get_flags(mail) & MAIL_DELETED) == 0) &&
+			    (flags & MAIL_DELETED))
+			  client->deleted_count++;
 		}
 		if (modify_type == MODIFY_REPLACE || keywords != NULL) {
 			if (mail_update_keywords(mail, modify_type,
diff -ur dovecot-1.0.alpha1.orig/src/imap/imap-expunge.c dovecot-1.0.alpha1/src/imap/imap-expunge.c
--- dovecot-1.0.alpha1.orig/src/imap/imap-expunge.c	2005-03-29 10:38:42.000000000 +0200
+++ dovecot-1.0.alpha1/src/imap/imap-expunge.c	2005-08-23 10:39:08.000000000 +0200
@@ -5,7 +5,8 @@
 #include "mail-search.h"
 #include "imap-expunge.h"
 
-int imap_expunge(struct mailbox *box, struct mail_search_arg *next_search_arg)
+int imap_expunge(struct mailbox *box, struct mail_search_arg *next_search_arg,
+		 struct client *client)
 {
 	struct mail_search_context *ctx;
         struct mailbox_transaction_context *t;
@@ -29,6 +30,7 @@
 				failed = TRUE;
 				break;
 			}
+			client->expunged_count++;
 		}
 		mail_free(mail);
 	}
diff -ur dovecot-1.0.alpha1.orig/src/imap/imap-expunge.h dovecot-1.0.alpha1/src/imap/imap-expunge.h
--- dovecot-1.0.alpha1.orig/src/imap/imap-expunge.h	2004-06-24 10:14:14.000000000 +0200
+++ dovecot-1.0.alpha1/src/imap/imap-expunge.h	2005-08-23 10:39:08.000000000 +0200
@@ -1,6 +1,7 @@
 #ifndef __IMAP_EXPUNGE_H
 #define __IMAP_EXPUNGE_H
 
-int imap_expunge(struct mailbox *box, struct mail_search_arg *next_search_arg);
+int imap_expunge(struct mailbox *box, struct mail_search_arg *next_search_arg,
+		 struct client *client);
 
 #endif
diff -ur dovecot-1.0.alpha1.orig/src/imap/imap-fetch-body.c dovecot-1.0.alpha1/src/imap/imap-fetch-body.c
--- dovecot-1.0.alpha1.orig/src/imap/imap-fetch-body.c	2005-07-12 22:29:53.000000000 +0200
+++ dovecot-1.0.alpha1/src/imap/imap-fetch-body.c	2005-08-23 10:39:08.000000000 +0200
@@ -292,7 +292,7 @@
 			seek_partial(ctx->select_counter, ctx->cur_mail->uid,
 				     &partial, ctx->cur_input, body->skip);
 	}
-
+	ctx->client->retr_bytes+=size->virtual_size;
 	return fetch_stream(ctx, size);
 }
 
@@ -317,6 +317,7 @@
 		/* BODY[] - fetch everything */
 		message_size_add(&body_size, &hdr_size);
                 fetch_size = &body_size;
+		ctx->client->retr_messages++;
 		break;
 	case 'H':
 		/* BODY[HEADER] - fetch only header */
@@ -326,6 +327,7 @@
 		/* BODY[TEXT] - skip header */
 		i_stream_skip(ctx->cur_input, hdr_size.physical_size);
                 fetch_size = &body_size;
+		ctx->client->retr_messages++;
 		break;
 	default:
 		i_unreached();
@@ -537,6 +539,7 @@
 	if (strcmp(section, "TEXT") == 0) {
 		i_stream_seek(ctx->cur_input, part->physical_pos +
 			      part->header_size.physical_size);
+		ctx->client->retr_messages++;
 		return fetch_data(ctx, body, &part->body_size);
 	}
 
diff -ur dovecot-1.0.alpha1.orig/src/imap/imap-fetch.c dovecot-1.0.alpha1/src/imap/imap-fetch.c
--- dovecot-1.0.alpha1.orig/src/imap/imap-fetch.c	2005-07-04 13:30:25.000000000 +0200
+++ dovecot-1.0.alpha1/src/imap/imap-fetch.c	2005-08-23 10:39:08.000000000 +0200
@@ -353,10 +353,12 @@
 			return -1;
 	}
 
+	ctx->client->retr_bytes+=strlen(body);
 	if (o_stream_send(ctx->client->output, "BODY (", 6) < 0 ||
 	    o_stream_send_str(ctx->client->output, body) < 0 ||
 	    o_stream_send(ctx->client->output, ")", 1) < 0)
 		return -1;
+	ctx->client->retr_messages++;
 	return 1;
 }
 
@@ -387,6 +389,7 @@
 			return -1;
 	}
 
+	ctx->client->retr_bytes+=strlen(bodystructure);
 	if (o_stream_send(ctx->client->output, "BODYSTRUCTURE (", 15) < 0 ||
 	    o_stream_send_str(ctx->client->output, bodystructure) < 0 ||
 	    o_stream_send(ctx->client->output, ")", 1) < 0)
@@ -420,6 +423,7 @@
 			return -1;
 	}
 
+	ctx->client->retr_bytes+=strlen(envelope);
 	if (o_stream_send(ctx->client->output, "ENVELOPE (", 10) < 0 ||
 	    o_stream_send_str(ctx->client->output, envelope) < 0 ||
 	    o_stream_send(ctx->client->output, ")", 1) < 0)


More information about the dovecot mailing list