From: Aki Tuomi <aki.tuomi@dovecot.fi>
Date: Tue, 16 Jan 2018 10:20:11 +0000 (+0200)
Subject: aggregator: Add debug logging
X-Git-Tag: 2.4.0~3477
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=28458ba63b933848d4bc7990ddeae894d1be31d4;p=thirdparty%2Fdovecot%2Fcore.git

aggregator: Add debug logging
---

diff --git a/src/replication/aggregator/aggregator-settings.h b/src/replication/aggregator/aggregator-settings.h
index 06c8ac3c53..1ada71de06 100644
--- a/src/replication/aggregator/aggregator-settings.h
+++ b/src/replication/aggregator/aggregator-settings.h
@@ -8,5 +8,6 @@ struct aggregator_settings {
 
 extern const struct setting_parser_info aggregator_setting_parser_info;
 extern const struct aggregator_settings *aggregator_settings;
+extern struct event *aggregator_event;
 
 #endif
diff --git a/src/replication/aggregator/aggregator.c b/src/replication/aggregator/aggregator.c
index 1677f9f76d..7a02d8f58d 100644
--- a/src/replication/aggregator/aggregator.c
+++ b/src/replication/aggregator/aggregator.c
@@ -9,6 +9,11 @@
 #include "replicator-connection.h"
 
 struct replicator_connection *replicator;
+struct event *aggregator_event;
+
+static struct event_category event_category_replication = {
+	.name = "replication"
+};
 
 static void client_connected(struct master_service_connection *conn)
 {
@@ -27,6 +32,9 @@ static void main_preinit(void)
 	sets = master_service_settings_get_others(master_service);
 	set = sets[0];
 
+	aggregator_event = event_create(NULL);
+	event_add_category(aggregator_event, &event_category_replication);
+
 	if (set->replicator_port != 0) {
 		ret = net_gethostbyname(set->replicator_host, &ips, &ips_count);
 		if (ret != 0) {
@@ -69,6 +77,7 @@ int main(int argc, char *argv[])
 
 	notify_connections_destroy_all();
 	replicator_connection_destroy(&replicator);
+	event_unref(&aggregator_event);
 	master_service_deinit(&master_service);
         return 0;
 }
diff --git a/src/replication/aggregator/notify-connection.c b/src/replication/aggregator/notify-connection.c
index 80dc05b590..68dcfc9f87 100644
--- a/src/replication/aggregator/notify-connection.c
+++ b/src/replication/aggregator/notify-connection.c
@@ -11,6 +11,7 @@
 #include "replication-common.h"
 #include "replicator-connection.h"
 #include "notify-connection.h"
+#include "aggregator-settings.h"
 
 #define MAX_INBUF_SIZE 8192
 
@@ -45,6 +46,8 @@ void notify_connection_sync_callback(bool success, void *context)
 {
 	struct notify_connection *conn = context;
 
+	e_debug(conn->event, "Sending %s result",
+		success ? "success" : "failure");
 	o_stream_nsend_str(conn->output, success ? "+\n" : "-\n");
 	notify_connection_unref(conn);
 }
@@ -67,6 +70,10 @@ notify_input_line(struct notify_connection *conn, const char *line,
 			"Client sent invalid priority: %s", args[1]);
 		return -1;
 	}
+
+	e_debug(conn->event, "Received priority %s request for %s",
+		args[1], args[0]);
+
 	if (priority != REPLICATION_PRIORITY_SYNC)
 		replicator_connection_notify(replicator, args[0], priority);
 	else {
@@ -117,6 +124,7 @@ void notify_connection_create(int fd, bool fifo)
 	conn->io = io_add(fd, IO_READ, notify_input, conn);
 	conn->input = i_stream_create_fd(fd, MAX_INBUF_SIZE);
 	conn->event = event_create(NULL);
+	event_set_append_log_prefix(conn->event, "notify: ");
 	if (!fifo) {
 		conn->output = o_stream_create_fd(fd, SIZE_MAX);
 		o_stream_set_no_error_handling(conn->output, TRUE);
@@ -141,6 +149,8 @@ static void notify_connection_destroy(struct notify_connection *conn)
 {
 	i_assert(conn->fd != -1);
 
+	e_debug(conn->event, "Disconnected");
+
 	if (!CONNECTION_IS_FIFO(conn))
 		master_service_client_connection_destroyed(master_service);
 
diff --git a/src/replication/aggregator/replicator-connection.c b/src/replication/aggregator/replicator-connection.c
index b5900db94b..b5bfed1860 100644
--- a/src/replication/aggregator/replicator-connection.c
+++ b/src/replication/aggregator/replicator-connection.c
@@ -10,6 +10,7 @@
 #include "llist.h"
 #include "strescape.h"
 #include "replicator-connection.h"
+#include "aggregator-settings.h"
 
 #define MAX_INBUF_SIZE 1024
 #define REPLICATOR_RECONNECT_MSECS 5000
@@ -56,6 +57,9 @@ replicator_input_line(struct replicator_connection *conn, const char *line)
 		e_error(conn->event, "Replicator sent invalid ID: %u", id);
 		return -1;
 	}
+
+	e_debug(conn->event, "Request id %u has %s",
+		id, line[0] == '+' ? "succeeded" : "failed");
 	hash_table_remove(conn->requests, POINTER_CAST(id));
 	conn->callback(line[0] == '+', context);
 	return 0;
@@ -143,6 +147,9 @@ static void replicator_connection_connect(struct replicator_connection *conn)
 		return;
 
 	if (conn->port == 0) {
+		event_set_append_log_prefix(conn->event,
+					    t_strdup_printf("(unix:%s): ", conn->path));
+		e_debug(conn->event, "Connecting to replicator");
 		fd = net_connect_unix(conn->path);
 		if (fd == -1)
 			e_error(conn->event, "net_connect_unix(%s) failed: %m",
@@ -152,6 +159,9 @@ static void replicator_connection_connect(struct replicator_connection *conn)
 			unsigned int idx = conn->ip_idx;
 
 			conn->ip_idx = (conn->ip_idx + 1) % conn->ips_count;
+			event_set_append_log_prefix(conn->event, t_strdup_printf(
+				"(%s): ", net_ipport2str(&conn->ips[idx], conn->port)));
+			e_debug(conn->event, "Connecting to replicator");
 			fd = net_connect_ip(&conn->ips[idx], conn->port, NULL);
 			if (fd != -1)
 				break;
@@ -161,7 +171,9 @@ static void replicator_connection_connect(struct replicator_connection *conn)
 	}
 
 	if (fd == -1) {
+		event_set_append_log_prefix(conn->event, "");
 		if (conn->to == NULL) {
+			e_debug(conn->event, "Reconnecting in %u msecs", REPLICATOR_RECONNECT_MSECS);
 			conn->to = timeout_add(REPLICATOR_RECONNECT_MSECS,
 					       replicator_connection_connect,
 					       conn);
@@ -174,6 +186,7 @@ static void replicator_connection_connect(struct replicator_connection *conn)
 	conn->io = io_add(fd, IO_READ, replicator_input, conn);
 	conn->input = i_stream_create_fd(fd, MAX_INBUF_SIZE);
 	conn->output = o_stream_create_fd(fd, SIZE_MAX);
+	e_debug(conn->event, "Sending handshake");
 	o_stream_set_no_error_handling(conn->output, TRUE);
 	o_stream_nsend_str(conn->output, REPLICATOR_HANDSHAKE);
 	o_stream_set_flush_callback(conn->output, replicator_output, conn);
@@ -184,6 +197,7 @@ static void replicator_abort_all_requests(struct replicator_connection *conn)
 	struct hash_iterate_context *iter;
 	void *key, *value;
 
+	e_debug(conn->event, "Aborting all requests");
 	iter = hash_table_iterate_init(conn->requests);
 	while (hash_table_iterate(iter, conn->requests, &key, &value))
 		conn->callback(FALSE, value);
@@ -196,11 +210,13 @@ static void replicator_connection_disconnect(struct replicator_connection *conn)
 	if (conn->fd == -1)
 		return;
 
+	e_debug(conn->event, "Disconnecting");
 	replicator_abort_all_requests(conn);
 	io_remove(&conn->io);
 	i_stream_destroy(&conn->input);
 	o_stream_destroy(&conn->output);
 	net_disconnect(conn->fd);
+	event_set_append_log_prefix(conn->event, "");
 	conn->fd = -1;
 }
 
@@ -307,6 +323,8 @@ void replicator_connection_notify(struct replicator_connection *conn,
 	}
 
 	T_BEGIN {
+		e_debug(conn->event, "Requesting replication of %s priority for user %s",
+			priority_str, username);
 		replicator_send(conn, priority, t_strdup_printf(
 			"U\t%s\t%s\n", str_tabescape(username), priority_str));
 	} T_END;
@@ -324,6 +342,8 @@ void replicator_connection_notify_sync(struct replicator_connection *conn,
 	hash_table_insert(conn->requests, POINTER_CAST(id), context);
 
 	T_BEGIN {
+		e_debug(conn->event, "Requesting synchronization with id %u for user %s",
+			id, username);
 		replicator_send(conn, REPLICATION_PRIORITY_SYNC, t_strdup_printf(
 			"U\t%s\tsync\t%u\n", str_tabescape(username), id));
 	} T_END;