From 1dc7b2bcd380897876cd84947bacaad5809e9f44 Mon Sep 17 00:00:00 2001
From: Stephan Bosch <stephan.bosch@open-xchange.com>
Date: Tue, 22 Oct 2019 21:47:23 +0200
Subject: [PATCH] managesieve: Emit command events.

---
 src/managesieve/cmd-deletescript.c   |  9 +++-
 src/managesieve/cmd-getscript.c      | 12 ++++-
 src/managesieve/cmd-havespace.c      |  8 ++++
 src/managesieve/cmd-listscripts.c    | 13 +++++-
 src/managesieve/cmd-putscript.c      | 58 +++++++++++++++++++++----
 src/managesieve/cmd-renamescript.c   | 17 +++++++-
 src/managesieve/cmd-setactive.c      | 42 +++++++++++++++---
 src/managesieve/managesieve-client.c | 33 +++++++++++++-
 src/managesieve/managesieve-client.h | 15 +++++--
 src/managesieve/managesieve-quota.c  | 65 ++++++++++++++++++----------
 10 files changed, 222 insertions(+), 50 deletions(-)

diff --git a/src/managesieve/cmd-deletescript.c b/src/managesieve/cmd-deletescript.c
index 1f622e216..b4de76f8a 100644
--- a/src/managesieve/cmd-deletescript.c
+++ b/src/managesieve/cmd-deletescript.c
@@ -21,13 +21,20 @@ bool cmd_deletescript(struct client_command_context *cmd)
 	if (!client_read_string_args(cmd, TRUE, 1, &scriptname))
 		return FALSE;
 
+	event_add_str(cmd->event, "managesieve_script_name", scriptname);
+
 	script = sieve_storage_open_script(storage, scriptname, NULL);
 	if (script == NULL || sieve_script_delete(script, FALSE) < 0) {
-		client_send_storage_error(client, storage);
+		client_command_storage_error(
+			cmd, "Failed to delete script `%s'", scriptname);
 		sieve_script_unref(&script);
 		return TRUE;
 	}
 
+	struct event_passthrough *e =
+		client_command_create_finish_event(cmd);
+	e_debug(e->event(), "Deleted script `%s'", scriptname);
+
 	client->deleted_count++;
 	client_send_ok(client, "Deletescript completed.");
 
diff --git a/src/managesieve/cmd-getscript.c b/src/managesieve/cmd-getscript.c
index 1b2511368..064465d58 100644
--- a/src/managesieve/cmd-getscript.c
+++ b/src/managesieve/cmd-getscript.c
@@ -18,6 +18,7 @@ struct cmd_getscript_context {
 	struct sieve_storage *storage;
 	uoff_t script_size;
 
+	const char *scriptname;
 	struct sieve_script *script;
 	struct istream *script_stream;
 
@@ -26,6 +27,7 @@ struct cmd_getscript_context {
 
 static bool cmd_getscript_finish(struct cmd_getscript_context *ctx)
 {
+	struct client_command_context *cmd = ctx->cmd;
 	struct client *client = ctx->client;
 
 	if (ctx->script != NULL)
@@ -37,13 +39,18 @@ static bool cmd_getscript_finish(struct cmd_getscript_context *ctx)
 			return TRUE;
 		}
 
-		client_send_storage_error(client, client->storage);
+		client_command_storage_error(
+			cmd, "Failed to retrieve script `%s'", ctx->scriptname);
 		return TRUE;
 	}
 
 	client->get_count++;
 	client->get_bytes += ctx->script_size;
 
+	struct event_passthrough *e =
+		client_command_create_finish_event(cmd);
+	e_debug(e->event(), "Retrieved script `%s'", ctx->scriptname);
+
 	client_send_line(client, "");
 	client_send_ok(client, "Getscript completed.");
 	return TRUE;
@@ -105,9 +112,12 @@ bool cmd_getscript(struct client_command_context *cmd)
 	if (!client_read_string_args(cmd, TRUE, 1, &scriptname))
 		return FALSE;
 
+	event_add_str(cmd->event, "managesieve_script_name", scriptname);
+
 	ctx = p_new(cmd->pool, struct cmd_getscript_context, 1);
 	ctx->cmd = cmd;
 	ctx->client = client;
+	ctx->scriptname = p_strdup(cmd->pool, scriptname);
 	ctx->storage = client->storage;
 	ctx->failed = FALSE;
 
diff --git a/src/managesieve/cmd-havespace.c b/src/managesieve/cmd-havespace.c
index 50146f2d1..454172d19 100644
--- a/src/managesieve/cmd-havespace.c
+++ b/src/managesieve/cmd-havespace.c
@@ -44,9 +44,17 @@ bool cmd_havespace(struct client_command_context *cmd)
 		return TRUE;
 	}
 
+	event_add_str(cmd->event, "managesieve_script_name", scriptname);
+	event_add_int(cmd->event, "managesieve_script_size", size);
+
 	if (!managesieve_quota_check_all(cmd, scriptname, size))
 		return TRUE;
 
+	struct event_passthrough *e =
+		client_command_create_finish_event(cmd);
+	e_debug(e->event(), "Quota is within limits for script `%s' "
+		"with size %"PRIuSIZE_T, scriptname, size);
+
 	client_send_ok(client, "Putscript would succeed.");
 	return TRUE;
 }
diff --git a/src/managesieve/cmd-listscripts.c b/src/managesieve/cmd-listscripts.c
index b5d692c76..9e6abd271 100644
--- a/src/managesieve/cmd-listscripts.c
+++ b/src/managesieve/cmd-listscripts.c
@@ -17,6 +17,7 @@ bool cmd_listscripts(struct client_command_context *cmd)
 	struct client *client = cmd->client;
 	struct sieve_storage_list_context *ctx;
 	const char *scriptname;
+	unsigned int script_count = 0;
 	bool active;
 	string_t *str;
 
@@ -25,7 +26,8 @@ bool cmd_listscripts(struct client_command_context *cmd)
 		return FALSE;
 
 	if ((ctx = sieve_storage_list_init(client->storage)) == NULL) {
-		client_send_storage_error(client, client->storage);
+		client_command_storage_error(
+			cmd, "Failed to list scripts");
 		return TRUE;
 	}
 
@@ -44,13 +46,20 @@ bool cmd_listscripts(struct client_command_context *cmd)
 
 			client_send_line(client, str_c(str));
 		} T_END;
+
+		script_count++;
 	}
 
 	if (sieve_storage_list_deinit(&ctx) < 0) {
-		client_send_storage_error(client, client->storage);
+		client_command_storage_error(
+			cmd, "Failed to list scripts");
 		return TRUE;
 	}
 
+	struct event_passthrough *e =
+		client_command_create_finish_event(cmd);
+	e_debug(e->event(), "Listed %u scripts", script_count);
+
 	client_send_ok(client, "Listscripts completed.");
 	return TRUE;
 }
diff --git a/src/managesieve/cmd-putscript.c b/src/managesieve/cmd-putscript.c
index 70c31c25d..3fd718565 100644
--- a/src/managesieve/cmd-putscript.c
+++ b/src/managesieve/cmd-putscript.c
@@ -144,9 +144,14 @@ static bool cmd_putscript_cancel(struct cmd_putscript_context *ctx, bool skip)
 
 static void cmd_putscript_storage_error(struct cmd_putscript_context *ctx)
 {
-	struct client *client = ctx->client;
+	struct client_command_context *cmd = ctx->cmd;
 
-	client_send_storage_error(client, ctx->storage);
+	if (ctx->scriptname == NULL) {
+		client_command_storage_error(cmd, "Failed to check script");
+	} else {
+		client_command_storage_error(cmd, "Failed to store script `%s'",
+					     ctx->scriptname);
+	}
 }
 
 static bool cmd_putscript_save(struct cmd_putscript_context *ctx)
@@ -168,6 +173,7 @@ cmd_putscript_finish_script(struct cmd_putscript_context *ctx,
 			    struct sieve_script *script)
 {
 	struct client *client = ctx->client;
+	struct client_command_context *cmd = ctx->cmd;
 	struct sieve_error_handler *ehandler;
 	enum sieve_compile_flags cpflags =
 		SIEVE_COMPILE_FLAG_NOGLOBAL | SIEVE_COMPILE_FLAG_UPLOADED;
@@ -190,16 +196,37 @@ cmd_putscript_finish_script(struct cmd_putscript_context *ctx,
 	/* Compile */
 	sbin = sieve_compile_script(script, ehandler, cpflags, &error);
 	if (sbin == NULL) {
+		const char *errormsg = NULL, *action;
+
 		if (error != SIEVE_ERROR_NOT_VALID) {
-			const char *errormsg =
-				sieve_script_get_last_error(script, &error);
-			if (error != SIEVE_ERROR_NONE)
-				client_send_no(client, errormsg);
-			else
-				client_send_no(client, str_c(errors));
-		} else {
+			errormsg = sieve_script_get_last_error(script, &error);
+			if (error == SIEVE_ERROR_NONE)
+				errormsg = NULL;
+		}
+
+		action = (ctx->scriptname != NULL ?
+			  t_strdup_printf("store script `%s'",
+					  ctx->scriptname) :
+			  "check script");
+
+		if (errormsg == NULL) {
+			struct event_passthrough *e =
+				client_command_create_finish_event(cmd);
+			e_debug(e->event(), "Failed to %s: "
+				"Compilation failed (%u errors, %u warnings)",
+				action, sieve_get_errors(ehandler),
+				sieve_get_warnings(ehandler));
+
 			client_send_no(client, str_c(errors));
+		} else {
+			struct event_passthrough *e =
+				client_command_create_finish_event(cmd);
+			e_debug(e->event(), "Failed to %s: %s",
+				action, errormsg);
+
+			client_send_no(client, errormsg);
 		}
+
 		success = FALSE;
 	} else {
 		sieve_close(&sbin);
@@ -221,6 +248,17 @@ cmd_putscript_finish_script(struct cmd_putscript_context *ctx,
 			client->check_bytes += ctx->script_size;
 		}
 
+		struct event_passthrough *e =
+			client_command_create_finish_event(cmd);
+		if (ctx->scriptname != NULL) {
+			e_debug(e->event(), "Stored script `%s' successfully "
+				"(%u warnings)", ctx->scriptname,
+				sieve_get_warnings(ehandler));
+		} else {
+			e_debug(e->event(), "Checked script successfully "
+				"(%u warnings)", sieve_get_warnings(ehandler));
+		}
+
 		if (sieve_get_warnings(ehandler) > 0)
 			client_send_okresp(client, "WARNINGS", str_c(errors));
 		else if (ctx->scriptname != NULL)
@@ -518,6 +556,8 @@ bool cmd_putscript(struct client_command_context *cmd)
 	if (!client_read_string_args(cmd, FALSE, 1, &scriptname))
 		return FALSE;
 
+	event_add_str(cmd->event, "managesieve_script_name", scriptname);
+
 	return cmd_putscript_start(cmd, scriptname);
 }
 
diff --git a/src/managesieve/cmd-renamescript.c b/src/managesieve/cmd-renamescript.c
index a748acf2c..c15bc3f75 100644
--- a/src/managesieve/cmd-renamescript.c
+++ b/src/managesieve/cmd-renamescript.c
@@ -22,16 +22,29 @@ bool cmd_renamescript(struct client_command_context *cmd)
 	if (!client_read_string_args(cmd, TRUE, 2, &scriptname, &newname))
 		return FALSE;
 
+	event_add_str(cmd->event, "managesieve_script_name", scriptname);
+	event_add_str(cmd->event, "managesieve_script_new_name", newname);
+
 	script = sieve_storage_open_script(storage, scriptname, NULL);
 	if (script == NULL) {
-		client_send_storage_error(client, storage);
+		client_command_storage_error(
+			cmd, "Failed to open script `%s' for rename to `%s'",
+			scriptname, newname);
 		return TRUE;
 	}
 
 	if (sieve_script_rename(script, newname) < 0) {
-		client_send_storage_error(client, storage);
+		client_command_storage_error(
+			cmd, "Failed to rename script `%s' to `%s'",
+			scriptname, newname);
 	} else {
 		client->renamed_count++;
+
+		struct event_passthrough *e =
+			client_command_create_finish_event(cmd);
+		e_debug(e->event(), "Renamed script `%s' to `%s'",
+			scriptname, newname);
+
 		client_send_ok(client, "Renamescript completed.");
 	}
 
diff --git a/src/managesieve/cmd-setactive.c b/src/managesieve/cmd-setactive.c
index 2f40e9261..cb025cd35 100644
--- a/src/managesieve/cmd-setactive.c
+++ b/src/managesieve/cmd-setactive.c
@@ -20,13 +20,17 @@ cmd_setactive_activate(struct client_command_context *cmd,
 	struct sieve_script *script;
 	string_t *errors = NULL;
 	const char *errormsg = NULL;
-	bool warnings = FALSE;
+	unsigned int warning_count = 0, error_count = 0;
 	bool success = TRUE;
 	int ret;
 
+	event_add_str(cmd->event, "managesieve_script_name", scriptname);
+
 	script = sieve_storage_open_script(storage, scriptname, NULL);
 	if (script == NULL) {
-		client_send_storage_error(client, storage);
+		client_command_storage_error(
+			cmd, "Failed to open script `%s' for activation",
+			scriptname);
 		return;
 	}
 
@@ -60,7 +64,8 @@ cmd_setactive_activate(struct client_command_context *cmd,
 			sieve_close(&sbin);
 		}
 
-		warnings = (sieve_get_warnings(ehandler) > 0);
+		warning_count = sieve_get_warnings(ehandler);
+		error_count = sieve_get_errors(ehandler);
 		sieve_error_handler_unref(&ehandler);
 	} T_END;
 
@@ -70,9 +75,18 @@ cmd_setactive_activate(struct client_command_context *cmd,
 		   resolve some erroneous situations. */
 		ret = sieve_script_activate(script, (time_t)-1);
 		if (ret < 0) {
-			client_send_storage_error(client, storage);
+			client_command_storage_error(
+				cmd, "Failed to activate script `%s'",
+				scriptname);
 		} else {
-			if (warnings) {
+			struct event_passthrough *e =
+				client_command_create_finish_event(cmd);
+			e_debug(e->event(), "Activated script `%s' "
+				" (%u warnings%s)",
+				scriptname, warning_count,
+				(ret == 0 ? ", redundant" : ""));
+
+			if (warning_count > 0) {
 				client_send_okresp(
 					client, "WARNINGS",
 					str_c(errors));
@@ -84,8 +98,19 @@ cmd_setactive_activate(struct client_command_context *cmd,
 			}
 		}
 	} else if (errormsg == NULL) {
+		struct event_passthrough *e =
+			client_command_create_finish_event(cmd);
+		e_debug(e->event(), "Failed to activate script `%s': "
+			"Compilation failed (%u errors, %u warnings)",
+			scriptname, error_count, warning_count);
+
 		client_send_no(client, str_c(errors));
 	} else {
+		struct event_passthrough *e =
+			client_command_create_finish_event(cmd);
+		e_debug(e->event(), "Failed to activate script `%s': %s",
+			scriptname, errormsg);
+
 		client_send_no(client, errormsg);
 	}
 
@@ -103,10 +128,15 @@ cmd_setactive_deactivate(struct client_command_context *cmd)
 
 	ret = sieve_storage_deactivate(storage, (time_t)-1);
 	if (ret < 0) {
-		client_send_storage_error(client, storage);
+		client_command_storage_error(
+			cmd, "Failed to deactivate script");
 		return;
 	}
 
+	struct event_passthrough *e =
+		client_command_create_finish_event(cmd);
+	e_debug(e->event(), "Deactivated script");
+
 	client_send_ok(client, (ret > 0 ?
 				"Active script is now deactivated." :
 				"No scripts currently active."));
diff --git a/src/managesieve/managesieve-client.c b/src/managesieve/managesieve-client.c
index 3a552da6c..03d8f1dfc 100644
--- a/src/managesieve/managesieve-client.c
+++ b/src/managesieve/managesieve-client.c
@@ -377,6 +377,15 @@ void client_send_response(struct client *client, const char *oknobye,
 	client_send_line(client, str_c(str));
 }
 
+struct event_passthrough *
+client_command_create_finish_event(struct client_command_context *cmd)
+{
+	struct event_passthrough *e =
+		event_create_passthrough(cmd->event)->
+		set_name("managesieve_command_finished");
+	return e;
+}
+
 void client_send_command_error(struct client_command_context *cmd,
 			       const char *msg)
 {
@@ -414,11 +423,22 @@ void client_send_command_error(struct client_command_context *cmd,
 	cmd->param_error = TRUE;
 }
 
-void client_send_storage_error(struct client *client,
-			       struct sieve_storage *storage)
+#undef client_command_storage_error
+void client_command_storage_error(struct client_command_context *cmd,
+				  const char *source_filename,
+				  unsigned int source_linenum,
+				  const char *log_prefix, ...)
 {
+	struct event_log_params params = {
+		.log_type = LOG_TYPE_INFO,
+		.source_filename = source_filename,
+		.source_linenum = source_linenum,
+	};
+	struct client *client = cmd->client;
+	struct sieve_storage *storage = client->storage;
 	enum sieve_error error_code;
 	const char *error;
+	va_list args;
 
 	error = sieve_storage_get_last_error(storage, &error_code);
 
@@ -443,6 +463,15 @@ void client_send_storage_error(struct client *client,
 		client_send_no(client, error);
 		break;
 	}
+
+	struct event_passthrough *e =
+		client_command_create_finish_event(cmd)->
+		add_str("error", error);
+
+	va_start(args, log_prefix);
+	event_log(e->event(), &params, "%s: %s",
+		  t_strdup_vprintf(log_prefix, args), error);
+	va_end(args);
 }
 
 bool client_read_args(struct client_command_context *cmd, unsigned int count,
diff --git a/src/managesieve/managesieve-client.h b/src/managesieve/managesieve-client.h
index 89eeec04a..8367c259c 100644
--- a/src/managesieve/managesieve-client.h
+++ b/src/managesieve/managesieve-client.h
@@ -120,13 +120,22 @@ void client_send_response(struct client *client, const char *oknobye,
 #define client_send_byeresp(cmd, resp_code, msg) \
 	client_send_response(client, "BYE", resp_code, msg)
 
+struct event_passthrough *
+client_command_create_finish_event(struct client_command_context *cmd);
+
 /* Send BAD command error to client. msg can be NULL. */
 void client_send_command_error(struct client_command_context *cmd,
 			       const char *msg);
 
-/* Send storage or sieve related errors to the client */
-void client_send_storage_error(struct client *client,
-			       struct sieve_storage *storage);
+/* Send storage or sieve-related errors to the client. Returns command finish
+   event with the "error" field set accordingly. */
+void client_command_storage_error(struct client_command_context *cmd,
+				  const char *source_filename,
+				  unsigned int source_linenum,
+				  const char *log_prefix, ...)
+				  ATTR_FORMAT(4, 5);
+#define client_command_storage_error(cmd, ...) \
+	client_command_storage_error(cmd, __FILE__, __LINE__, __VA_ARGS__)
 
 /* Read a number of arguments. Returns TRUE if everything was read or
    FALSE if either needs more data or error occurred. */
diff --git a/src/managesieve/managesieve-quota.c b/src/managesieve/managesieve-quota.c
index aeede4662..4cf034c15 100644
--- a/src/managesieve/managesieve-quota.c
+++ b/src/managesieve/managesieve-quota.c
@@ -22,10 +22,20 @@ bool managesieve_quota_check_validsize(struct client_command_context *cmd,
 	uint64_t limit;
 
 	if (!sieve_storage_quota_validsize(client->storage, size, &limit)) {
-		client_send_noresp(
-			client, "QUOTA/MAXSIZE",
-			t_strdup_printf("Script is too large (max %llu bytes).",
-					(unsigned long long int) limit));
+		const char *error_msg;
+
+		error_msg = t_strdup_printf(
+			"Script is too large (max %llu bytes).",
+			(unsigned long long int)limit);
+
+		struct event_passthrough *e =
+			client_command_create_finish_event(cmd);
+		e_debug(e->event(),
+			"Script size check failed "
+			"(size %"PRIuSIZE_T" bytes): %s",
+			size, error_msg);
+
+		client_send_noresp(client, "QUOTA/MAXSIZE", error_msg);
 		return FALSE;
 	}
 	return TRUE;
@@ -37,6 +47,7 @@ bool managesieve_quota_check_all(struct client_command_context *cmd,
 	struct client *client = cmd->client;
 	enum sieve_storage_quota quota;
 	uint64_t limit;
+	const char *resp_code = NULL, *error_msg = NULL;
 	int ret;
 
 	ret = sieve_storage_quota_havespace(client->storage, scriptname,
@@ -44,39 +55,45 @@ bool managesieve_quota_check_all(struct client_command_context *cmd,
 	if (ret > 0)
 		return TRUE;
 	if (ret < 0) {
-		client_send_storage_error(client, client->storage);
+		client_command_storage_error(
+			cmd, "Failed to check quota for script `%s' "
+			     "(size %"PRIuSIZE_T" bytes)", scriptname, size);
 		return FALSE;
 	}
 
 	switch (quota) {
 	case SIEVE_STORAGE_QUOTA_MAXSIZE:
-		client_send_noresp(
-			client, "QUOTA/MAXSIZE",
-			t_strdup_printf(
-				"Script is too large "
-				"(max %llu bytes).",
-				(unsigned long long int) limit));
+		resp_code = "QUOTA/MAXSIZE";
+		error_msg = t_strdup_printf("Script is too large "
+					    "(max %llu bytes).",
+					    (unsigned long long int)limit);
 		break;
 	case SIEVE_STORAGE_QUOTA_MAXSCRIPTS:
-		client_send_noresp(
-			client, "QUOTA/MAXSCRIPTS",
-			t_strdup_printf(
-				"Script count quota exceeded "
-				"(max %llu scripts).",
-				(unsigned long long int) limit));
+		resp_code = "QUOTA/MAXSCRIPTS";
+		error_msg = t_strdup_printf("Script count quota exceeded "
+					    "(max %llu scripts).",
+					    (unsigned long long int)limit);
 		break;
 	case SIEVE_STORAGE_QUOTA_MAXSTORAGE:
-		client_send_noresp(
-			client, "QUOTA/MAXSTORAGE",
-			t_strdup_printf(
-				"Script storage quota exceeded "
-				"(max %llu bytes).",
-				(unsigned long long int) limit));
+		resp_code = "QUOTA/MAXSTORAGE";
+		error_msg = t_strdup_printf("Script storage quota exceeded "
+					    "(max %llu bytes).",
+					    (unsigned long long int)limit);
 		break;
 	default:
-		client_send_noresp(client, "QUOTA", "Quota exceeded.");
+		resp_code = "QUOTA";
+		error_msg = "Quota exceeded.";
 	}
 
+	struct event_passthrough *e =
+		client_command_create_finish_event(cmd);
+	e_debug(e->event(),
+		"Quota check failed for script `%s' "
+		"(size %"PRIuSIZE_T" bytes): %s",
+		scriptname, size, error_msg);
+
+	client_send_noresp(client, resp_code, error_msg);
+
 	return FALSE;
 }
 
-- 
GitLab