driver-mysql: Add events

diff --git a/src/lib-sql/driver-mysql.c b/src/lib-sql/driver-mysql.c
index 2e90da4c39df1150efcc51710b0dd3c7d8fde59d..c87e825e4b51d78750d9fadc3687953bf43ae8ae 100644 (file)
--- 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);
 }