From: Aki Tuomi <aki.tuomi@dovecot.fi>
Date: Mon, 11 Jun 2018 12:25:54 +0000 (+0300)
Subject: lib-dict: Add named events
X-Git-Tag: 2.3.11.2~495
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=62974b783757905ecd87f7ac95b49904c660f643;p=thirdparty%2Fdovecot%2Fcore.git

lib-dict: Add named events
---

diff --git a/src/lib-dict/dict-private.h b/src/lib-dict/dict-private.h
index 9fedff4f96..01d55ede1c 100644
--- 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 01764a6a80..53bd2c6059 100644
--- 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);