From: Aki Tuomi <aki.tuomi@dovecot.fi>
Date: Fri, 31 Aug 2018 06:45:59 +0000 (+0300)
Subject: driver-mysql: Add events
X-Git-Tag: 2.3.4~90
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=3b28c5934e50136873192e3c19e0189e0f1d73bb;p=thirdparty%2Fdovecot%2Fcore.git

driver-mysql: Add events
---

diff --git a/src/lib-sql/driver-mysql.c b/src/lib-sql/driver-mysql.c
index 2e90da4c39..c87e825e4b 100644
--- a/src/lib-sql/driver-mysql.c
+++ b/src/lib-sql/driver-mysql.c
@@ -6,6 +6,7 @@
 #include "hex-binary.h"
 #include "str.h"
 #include "net.h"
+#include "time-util.h"
 #include "sql-api-private.h"
 
 #ifdef BUILD_MYSQL
@@ -64,17 +65,17 @@ struct mysql_transaction_context {
 	const char *error;
 
 	bool failed:1;
+	bool committed:1;
 };
 
 extern const struct sql_db driver_mysql_db;
 extern const struct sql_result driver_mysql_result;
 extern const struct sql_result driver_mysql_error_result;
 
-static const char *mysql_prefix(struct mysql_db *db)
-{
-	return db->host == NULL ? "mysql" :
-		t_strdup_printf("mysql(%s)", db->host);
-}
+static struct event_category event_category_mysql = {
+	.parent = &event_category_sql,
+	.name = "mysql"
+};
 
 static int driver_mysql_connect(struct sql_db *_db)
 {
@@ -110,6 +111,11 @@ static int driver_mysql_connect(struct sql_db *_db)
 			      db->option_file);
 	}
 
+	if (db->host != NULL)
+		event_set_append_log_prefix(_db->event, t_strdup_printf("mysql(%s): ", db->host));
+
+	e_debug(_db->event, "Connecting");
+
 	mysql_options(db->mysql, MYSQL_OPT_CONNECT_TIMEOUT, &db->connect_timeout);
 	mysql_options(db->mysql, MYSQL_OPT_READ_TIMEOUT, &db->read_timeout);
 	mysql_options(db->mysql, MYSQL_OPT_WRITE_TIMEOUT, &db->write_timeout);
@@ -153,10 +159,9 @@ static int driver_mysql_connect(struct sql_db *_db)
 		if (db->api.connect_delay < secs_used)
 			db->api.connect_delay = secs_used;
 		sql_db_set_state(&db->api, SQL_DB_STATE_DISCONNECTED);
-		i_error("%s: Connect failed to database (%s): %s - "
+		e_error(_db->event, "Connect failed to database (%s): %s - "
 			"waiting for %u seconds before retry",
-			mysql_prefix(db), db->dbname,
-			mysql_error(db->mysql), db->api.connect_delay);
+			db->dbname, mysql_error(db->mysql), db->api.connect_delay);
 		return -1;
 	} else {
 		db->last_success = ioloop_time;
@@ -281,6 +286,9 @@ static int driver_mysql_init_full_v(const struct sql_settings *set,
 	db = p_new(pool, struct mysql_db, 1);
 	db->pool = pool;
 	db->api = driver_mysql_db;
+	db->api.event = event_create(set->event_parent);
+	event_add_category(db->api.event, &event_category_mysql);
+	event_set_append_log_prefix(db->api.event, "mysql: ");
 	T_BEGIN {
 		ret = driver_mysql_parse_connect_string(db, set->connect_string, &error);
 		error = p_strdup(db->pool, error);
@@ -304,13 +312,32 @@ static void driver_mysql_deinit_v(struct sql_db *_db)
 	sql_db_set_state(&db->api, SQL_DB_STATE_DISCONNECTED);
 
 	mysql_close(db->mysql);
+
+	sql_connection_log_finished(_db);
+	event_unref(&_db->event);
 	array_free(&_db->module_contexts);
 	pool_unref(&db->pool);
 }
 
-static int driver_mysql_do_query(struct mysql_db *db, const char *query)
+static int driver_mysql_do_query(struct mysql_db *db, const char *query,
+				 struct event *event)
 {
-	if (mysql_query(db->mysql, query) == 0)
+	int ret, diff;
+	struct event_passthrough *e;
+
+	ret = mysql_query(db->mysql, query);
+	io_loop_time_refresh();
+	e = sql_query_finished_event(&db->api, event, query, ret == 0, &diff);
+
+	if (ret != 0) {
+		e->add_int("error_code", mysql_errno(db->mysql));
+		e->add_str("error", mysql_error(db->mysql));
+		e_debug(e->event(), SQL_QUERY_FINISHED_FMT": %s", query,
+			diff, mysql_error(db->mysql));
+	} else
+		e_debug(e->event(), SQL_QUERY_FINISHED_FMT, query, diff);
+
+	if (ret == 0)
 		return 0;
 
 	/* failed */
@@ -359,11 +386,11 @@ driver_mysql_escape_string(struct sql_db *_db, const char *string)
 static void driver_mysql_exec(struct sql_db *_db, const char *query)
 {
 	struct mysql_db *db = (struct mysql_db *)_db;
+	struct event *event = event_create(_db->event);
 
-	if (driver_mysql_do_query(db, query) < 0) {
-		i_error("%s: Query '%s' failed: %s",
-			mysql_prefix(db), query, mysql_error(db->mysql));
-	}
+	(void)driver_mysql_do_query(db, query, event);
+
+	event_unref(&event);
 }
 
 static void driver_mysql_query(struct sql_db *db, const char *query,
@@ -383,12 +410,14 @@ driver_mysql_query_s(struct sql_db *_db, const char *query)
 {
 	struct mysql_db *db = (struct mysql_db *)_db;
 	struct mysql_result *result;
+	struct event *event;
 	int ret;
 
 	result = i_new(struct mysql_result, 1);
 	result->api = driver_mysql_result;
+	event = event_create(_db->event);
 
-	if (driver_mysql_do_query(db, query) < 0)
+	if (driver_mysql_do_query(db, query, event) < 0)
 		result->api = driver_mysql_error_result;
 	else {
 		/* query ok */
@@ -416,6 +445,7 @@ driver_mysql_query_s(struct sql_db *_db, const char *query)
 
 	result->api.db = _db;
 	result->api.refcount = 1;
+	result->api.event = event;
 	return &result->api;
 }
 
@@ -429,6 +459,7 @@ static void driver_mysql_result_free(struct sql_result *_result)
 
 	if (result->result != NULL)
 		mysql_free_result(result->result);
+	event_unref(&_result->event);
 	i_free(result);
 }
 
@@ -565,6 +596,7 @@ driver_mysql_transaction_begin(struct sql_db *db)
 	ctx = i_new(struct mysql_transaction_context, 1);
 	ctx->ctx.db = db;
 	ctx->query_pool = pool_alloconly_create("mysql transaction", 1024);
+	ctx->ctx.event = event_create(db->event);
 	return &ctx->ctx;
 }
 
@@ -644,14 +676,18 @@ driver_mysql_transaction_commit_s(struct sql_transaction_context *_ctx,
 		ret = driver_mysql_try_commit_s(ctx);
 		*error_r = t_strdup(ctx->error);
 		if (ret == 0) {
-			i_info("%s: Disconnected from database, "
-			       "retrying commit", db->dbname);
+			e_info(db->api.event, "Disconnected from database, "
+			       "retrying commit");
 			if (sql_connect(_ctx->db) >= 0) {
 				ctx->failed = FALSE;
 				ret = driver_mysql_try_commit_s(ctx);
 			}
 		}
 	}
+
+	if (ret > 0)
+		ctx->committed = TRUE;
+
 	sql_transaction_rollback(&_ctx);
 	return ret <= 0 ? -1 : 0;
 }
@@ -662,6 +698,19 @@ driver_mysql_transaction_rollback(struct sql_transaction_context *_ctx)
 	struct mysql_transaction_context *ctx =
 		(struct mysql_transaction_context *)_ctx;
 
+	if (ctx->failed)
+		e_debug(sql_transaction_finished_event(_ctx)->
+			add_str("error", ctx->error)->event(),
+			"Transaction failed: %s", ctx->error);
+	else if (ctx->committed)
+		e_debug(sql_transaction_finished_event(_ctx)->event(),
+			"Transaction committed");
+	else
+		e_debug(sql_transaction_finished_event(_ctx)->
+			add_str("error", "Rolled back")->event(),
+			 "Transaction rolled back");
+
+	event_unref(&ctx->ctx.event);
 	pool_unref(&ctx->query_pool);
 	i_free(ctx);
 }