lib-dict: Add named events

diff --git a/src/lib-dict/dict-private.h b/src/lib-dict/dict-private.h
index 9fedff4f96ce06e530a3a89cfb2a046f030931ea..01d55ede1c2601cbfbaf80735cb67fa5c4d10406 100644 (file)
--- a/src/lib-dict/dict-private.h
+++ b/src/lib-dict/dict-private.h
@@ -61,6 +61,7 @@ struct dict {
 
 struct dict_iterate_context {
        struct dict *dict;
+       struct event *event;
 
        dict_iterate_callback_t *async_callback;
        void *async_context;
@@ -74,6 +75,7 @@ struct dict_transaction_context {
        struct dict *dict;
        struct dict_transaction_context *prev, *next;
 
+       struct event *event;
        struct timespec timestamp;
 
        bool changed:1;

diff --git a/src/lib-dict/dict.c b/src/lib-dict/dict.c
index 01764a6a800118745e6f80e2c8a893a2976712d3..53bd2c6059b477bdc04b9946f575f5912dbd7991 100644 (file)
--- a/src/lib-dict/dict.c
+++ b/src/lib-dict/dict.c
@@ -2,6 +2,7 @@
 
 #include "lib.h"
 #include "array.h"
+#include "guid.h"
 #include "llist.h"
 #include "ioloop.h"
 #include "str.h"
@@ -10,12 +11,14 @@
 
 struct dict_commit_callback_ctx {
        struct dict *dict;
+       struct event *event;
        dict_transaction_commit_callback_t *callback;
        void *context;
 };
 
 struct dict_lookup_callback_ctx {
        struct dict *dict;
+       struct event *event;
        dict_lookup_callback_t *callback;
        void *context;
 };
@@ -151,6 +154,7 @@ void dict_deinit(struct dict **_dict)
 
 void dict_wait(struct dict *dict)
 {
+       e_debug(dict->event, "Waiting for dict to finish pending operations");
        if (dict->v.wait != NULL)
                dict->v.wait(dict);
 }
@@ -187,6 +191,37 @@ void dict_post_api_callback(struct dict *dict)
        }
 }
 
+static void dict_lookup_finished(struct event *event, int ret, const char *error)
+{
+       i_assert(ret >= 0 || error != NULL);
+       const char *key = event_find_field_str(event, "key");
+       if (ret < 0)
+               event_add_str(event, "error", error);
+       else if (ret == 0)
+               event_add_str(event, "key_not_found", "yes");
+       event_set_name(event, "dict_lookup_finished");
+       e_debug(event, "Lookup finished for '%s': %s",  key, ret > 0 ?
+                       "found" :
+                       "not found");
+}
+
+static void dict_transaction_finished(struct event *event, enum dict_commit_ret ret,
+                                     bool rollback, const char *error)
+{
+       i_assert(ret > DICT_COMMIT_RET_FAILED || error != NULL);
+       if (ret == DICT_COMMIT_RET_FAILED || ret == DICT_COMMIT_RET_WRITE_UNCERTAIN) {
+                if (ret == DICT_COMMIT_RET_WRITE_UNCERTAIN)
+                       event_add_str(event, "write_uncertain", "yes");
+               event_add_str(event, "error", error);
+       } else if (rollback) {
+               event_add_str(event, "rollback", "yes");
+       } else if (ret == 0) {
+               event_add_str(event, "key_not_found", "yes");
+       }
+       event_set_name(event, "dict_transaction_finished");
+       e_debug(event, "Dict transaction finished");
+}
+
 static void
 dict_lookup_callback(const struct dict_lookup_result *result,
                     void *context)
@@ -196,6 +231,8 @@ dict_lookup_callback(const struct dict_lookup_result *result,
        dict_pre_api_callback(ctx->dict);
        ctx->callback(result, ctx->context);
        dict_post_api_callback(ctx->dict);
+       dict_lookup_finished(ctx->event, result->ret, result->error);
+       event_unref(&ctx->event);
 
        dict_unref(&ctx->dict);
        i_free(ctx);
@@ -210,11 +247,13 @@ static void dict_commit_callback(const struct dict_commit_result *result,
        dict_pre_api_callback(ctx->dict);
        if (ctx->callback != NULL)
                ctx->callback(result, ctx->context);
-       else if (result->ret < 0)
-               i_error("dict(%s): Commit failed: %s",
-                       ctx->dict->name, result->error);
+       else if (result->ret < 0) {
+               e_error(ctx->event, "Commit failed: %s", result->error);
+       }
        dict_post_api_callback(ctx->dict);
 
+       dict_transaction_finished(ctx->event, result->ret, FALSE, result->error);
+       event_unref(&ctx->event);
        dict_unref(&ctx->dict);
        i_free(ctx);
 }
@@ -222,8 +261,16 @@ static void dict_commit_callback(const struct dict_commit_result *result,
 int dict_lookup(struct dict *dict, pool_t pool, const char *key,
                const char **value_r, const char **error_r)
 {
+       struct event *event = event_create(dict->event);
+       int ret;
        i_assert(dict_key_prefix_is_valid(key));
-       return dict->v.lookup(dict, pool, key, value_r, error_r);
+
+       e_debug(event, "Looking up '%s'", key);
+       event_add_str(event, "key", key);
+       ret = dict->v.lookup(dict, pool, key, value_r, error_r);
+       dict_lookup_finished(event, ret, *error_r);
+       event_unref(&event);
+       return ret;
 }
 
 void dict_lookup_async(struct dict *dict, const char *key,
@@ -233,6 +280,7 @@ void dict_lookup_async(struct dict *dict, const char *key,
                struct dict_lookup_result result;
 
                i_zero(&result);
+               /* event is going to be sent by dict_lookup */
                result.ret = dict_lookup(dict, pool_datastack_create(),
                                         key, &result.value, &result.error);
                const char *const values[] = { result.value, NULL };
@@ -246,6 +294,9 @@ void dict_lookup_async(struct dict *dict, const char *key,
        dict_ref(lctx->dict);
        lctx->callback = callback;
        lctx->context = context;
+       lctx->event = event_create(dict->event);
+       event_add_str(lctx->event, "key", key);
+       e_debug(lctx->event, "Looking up (async) '%s'", key);
        dict->v.lookup_async(dict, key, dict_lookup_callback, lctx);
 }
 
@@ -280,6 +331,11 @@ dict_iterate_init_multiple(struct dict *dict, const char *const *paths,
        /* the dict in context can differ from the dict
           passed as parameter, e.g. it can be dict-fail when
           iteration is not supported. */
+       ctx->event = event_create(dict->event);
+
+       event_add_str(ctx->event, "key", paths[0]);
+       event_set_name(ctx->event, "dict_iteration_started");
+       e_debug(ctx->event, "Iterating prefix %s", paths[0]);
        ctx->dict->iter_count++;
        return ctx;
 }
@@ -288,6 +344,8 @@ bool dict_iterate(struct dict_iterate_context *ctx,
                  const char **key_r, const char **value_r)
 {
        if (ctx->max_rows > 0 && ctx->row_count >= ctx->max_rows) {
+               e_debug(ctx->event, "Maximum row count (%"PRIu64") reached",
+                       ctx->max_rows);
                /* row count was limited */
                ctx->has_more = FALSE;
                return FALSE;
@@ -321,17 +379,37 @@ int dict_iterate_deinit(struct dict_iterate_context **_ctx,
                        const char **error_r)
 {
        struct dict_iterate_context *ctx = *_ctx;
+       struct event *event = ctx->event;
+       int ret;
+       uint64_t rows;
 
        i_assert(ctx->dict->iter_count > 0);
        ctx->dict->iter_count--;
 
        *_ctx = NULL;
-       return ctx->dict->v.iterate_deinit(ctx, error_r);
+       rows = ctx->row_count;
+       ret = ctx->dict->v.iterate_deinit(ctx, error_r);
+
+       event_add_int(event, "rows", rows);
+       event_set_name(event, "dict_iteration_finished");
+
+       if (ret < 0) {
+               event_add_str(event, "error", *error_r);
+               e_debug(event, "Iteration finished: %s", *error_r);
+       } else {
+               if (rows == 0)
+                       event_add_str(event, "key_not_found", "yes");
+               e_debug(event, "Iteration finished, got %"PRIu64" rows", rows);
+       }
+
+       event_unref(&event);
+       return ret;
 }
 
 struct dict_transaction_context *dict_transaction_begin(struct dict *dict)
 {
        struct dict_transaction_context *ctx;
+       guid_128_t guid;
        if (dict->v.transaction_init == NULL)
                ctx = &dict_transaction_unsupported;
        else
@@ -341,6 +419,11 @@ struct dict_transaction_context *dict_transaction_begin(struct dict *dict)
           transactions are not supported. */
        ctx->dict->transaction_count++;
        DLLIST_PREPEND(&ctx->dict->transactions, ctx);
+       ctx->event = event_create(dict->event);
+       guid_128_generate(guid);
+       event_add_str(ctx->event, "txid", guid_128_to_string(guid));
+       event_set_name(ctx->event, "dict_transaction_started");
+       e_debug(ctx->event, "Starting transaction");
        return ctx;
 }
 
@@ -361,6 +444,11 @@ void dict_transaction_set_timestamp(struct dict_transaction_context *ctx,
        i_assert(ts->tv_sec > 0);
 
        ctx->timestamp = *ts;
+       struct event_passthrough *e = event_create_passthrough(ctx->event)->
+               set_name("dict_set_timestamp");
+
+       e_debug(e->event(), "Setting timestamp on transaction to (%"PRIdTIME_T", %ld)",
+                ts->tv_sec, ts->tv_nsec);
        if (ctx->dict->v.set_timestamp != NULL)
                ctx->dict->v.set_timestamp(ctx, ts);
 }
@@ -398,6 +486,7 @@ int dict_transaction_commit(struct dict_transaction_context **_ctx,
        dict_ref(cctx->dict);
        cctx->callback = dict_transaction_commit_sync_callback;
        cctx->context = &result;
+       cctx->event = ctx->event;
 
        ctx->dict->v.transaction_commit(ctx, FALSE, dict_commit_callback, cctx);
        *error_r = t_strdup(result.error);
@@ -423,6 +512,7 @@ void dict_transaction_commit_async(struct dict_transaction_context **_ctx,
        dict_ref(cctx->dict);
        cctx->callback = callback;
        cctx->context = context;
+       cctx->event = ctx->event;
 
        ctx->dict->v.transaction_commit(ctx, TRUE, dict_commit_callback, cctx);
 }
@@ -430,18 +520,26 @@ void dict_transaction_commit_async(struct dict_transaction_context **_ctx,
 void dict_transaction_rollback(struct dict_transaction_context **_ctx)
 {
        struct dict_transaction_context *ctx = *_ctx;
+       struct event *event = ctx->event;
 
        *_ctx = NULL;
        i_assert(ctx->dict->transaction_count > 0);
        ctx->dict->transaction_count--;
        DLLIST_REMOVE(&ctx->dict->transactions, ctx);
        ctx->dict->v.transaction_rollback(ctx);
+       dict_transaction_finished(event, DICT_COMMIT_RET_OK, TRUE, NULL);
+       event_unref(&event);
 }
 
 void dict_set(struct dict_transaction_context *ctx,
              const char *key, const char *value)
 {
        i_assert(dict_key_prefix_is_valid(key));
+       struct event_passthrough *e = event_create_passthrough(ctx->event)->
+               set_name("dict_set_key")->
+               add_str("key", key);
+
+       e_debug(e->event(), "Setting '%s' to '%s'", key, value);
 
        T_BEGIN {
                ctx->dict->v.set(ctx, key, value);
@@ -453,6 +551,11 @@ void dict_unset(struct dict_transaction_context *ctx,
                const char *key)
 {
        i_assert(dict_key_prefix_is_valid(key));
+       struct event_passthrough *e = event_create_passthrough(ctx->event)->
+               set_name("dict_unset_key")->
+               add_str("key", key);
+
+       e_debug(e->event(), "Unsetting '%s'", key);
 
        T_BEGIN {
                ctx->dict->v.unset(ctx, key);
@@ -464,6 +567,11 @@ void dict_atomic_inc(struct dict_transaction_context *ctx,
                     const char *key, long long diff)
 {
        i_assert(dict_key_prefix_is_valid(key));
+       struct event_passthrough *e = event_create_passthrough(ctx->event)->
+               set_name("dict_increment_key")->
+               add_str("key", key);
+
+       e_debug(e->event(), "Incrementing '%s' with %lld", key, diff);
 
        if (diff != 0) T_BEGIN {
                ctx->dict->v.atomic_inc(ctx, key, diff);