[Minor] Improve debug traces for async events

4 files changed, 61 insertions, 36 deletions

diff --git a/src/libserver/events.c b/src/libserver/events.c
index 55e04985b..2fd0c55ff 100644
--- a/src/libserver/events.c
+++ b/src/libserver/events.c
@@ -49,6 +49,7 @@ static struct rspamd_counter_data events_count;
 
 struct rspamd_async_event {
 	const gchar *subsystem;
+	const gchar *loc;
 	event_finalizer_t fin;
 	void *user_data;
 };
@@ -145,10 +146,11 @@ rspamd_session_create (rspamd_mempool_t * pool,
 }
 
 struct rspamd_async_event *
-rspamd_session_add_event (struct rspamd_async_session *session,
-						  event_finalizer_t fin,
-						  gpointer user_data,
-						  const gchar *subsystem)
+rspamd_session_add_event_full (struct rspamd_async_session *session,
+							   event_finalizer_t fin,
+							   gpointer user_data,
+							   const gchar *subsystem,
+							   const gchar *loc)
 {
 	struct rspamd_async_event *new_event;
 	gint ret;
@@ -171,12 +173,14 @@ rspamd_session_add_event (struct rspamd_async_session *session,
 	new_event->fin = fin;
 	new_event->user_data = user_data;
 	new_event->subsystem = subsystem;
+	new_event->loc = loc;
 
 	msg_debug_session ("added event: %p, pending %d (+1) events, "
-					   "subsystem: %s",
+					   "subsystem: %s (%s)",
 			user_data,
 			kh_size (session->events),
-			subsystem);
+			subsystem,
+			loc);
 
 	kh_put (rspamd_events_hash, session->events, new_event, &ret);
 	g_assert (ret > 0);
@@ -185,9 +189,10 @@ rspamd_session_add_event (struct rspamd_async_session *session,
 }
 
 void
-rspamd_session_remove_event (struct rspamd_async_session *session,
-	event_finalizer_t fin,
-	void *ud)
+rspamd_session_remove_event_full (struct rspamd_async_session *session,
+								  event_finalizer_t fin,
+								  void *ud,
+								  const gchar *loc)
 {
 	struct rspamd_async_event search_ev, *found_ev;
 	khiter_t k;
@@ -209,10 +214,11 @@ rspamd_session_remove_event (struct rspamd_async_session *session,
 	if (k == kh_end (session->events)) {
 		gchar t;
 
-		msg_err_session ("cannot find event: %p(%p)", fin, ud);
+		msg_err_session ("cannot find event: %p(%p) from %s", fin, ud, loc);
 		kh_foreach (session->events, found_ev, t, {
-			msg_err_session ("existing event %s: %p(%p)",
+			msg_err_session ("existing event %s (%s): %p(%p)",
 					found_ev->subsystem,
+					found_ev->loc,
 					found_ev->fin,
 					found_ev->user_data);
 		});
@@ -224,10 +230,12 @@ rspamd_session_remove_event (struct rspamd_async_session *session,
 
 	found_ev = kh_key (session->events, k);
 	msg_debug_session ("removed event: %p, pending %d (-1) events, "
-					   "subsystem: %s",
+					   "subsystem: %s (%s), added at %s",
 			ud,
 			kh_size (session->events),
-			found_ev->subsystem);
+			found_ev->subsystem,
+			loc,
+			found_ev->loc);
 	kh_del (rspamd_events_hash, session->events, k);
 
 	/* Remove event */
diff --git a/src/libserver/events.h b/src/libserver/events.h
index 1cb5dfa11..7e0de8749 100644
--- a/src/libserver/events.h
+++ b/src/libserver/events.h
@@ -46,10 +46,13 @@ struct rspamd_async_session * rspamd_session_create (rspamd_mempool_t *pool,
  * @param forced unused
  */
 struct rspamd_async_event *
-rspamd_session_add_event (struct rspamd_async_session *session,
+rspamd_session_add_event_full (struct rspamd_async_session *session,
 						  event_finalizer_t fin,
 						  gpointer user_data,
-						  const gchar *subsystem);
+						  const gchar *subsystem,
+						  const gchar *loc);
+#define rspamd_session_add_event(session, fin, user_data, subsystem) \
+	rspamd_session_add_event_full(session, fin, user_data, subsystem, G_STRLOC)
 
 /**
  * Remove normal event
@@ -57,9 +60,12 @@ rspamd_session_add_event (struct rspamd_async_session *session,
  * @param fin final callback
  * @param ud user data object
  */
-void rspamd_session_remove_event (struct rspamd_async_session *session,
-	event_finalizer_t fin,
-	gpointer ud);
+void rspamd_session_remove_event_full (struct rspamd_async_session *session,
+								  event_finalizer_t fin,
+								  gpointer ud,
+								  const gchar *loc);
+#define rspamd_session_remove_event(session, fin, user_data) \
+	rspamd_session_remove_event_full(session, fin, user_data, G_STRLOC)
 
 /**
  * Must be called at the end of session, it calls fin functions for all non-forced callbacks
diff --git a/src/libserver/symbols_cache.c b/src/libserver/symbols_cache.c
index e754e2d10..32c81e3c9 100644
--- a/src/libserver/symbols_cache.c
+++ b/src/libserver/symbols_cache.c
@@ -2676,33 +2676,36 @@ rspamd_symbols_cache_finalize_item (struct rspamd_task *task,
 }
 
 guint
-rspamd_symcache_item_async_inc (struct rspamd_task *task,
+rspamd_symcache_item_async_inc_full (struct rspamd_task *task,
 								struct rspamd_symcache_item *item,
-								const gchar *subsystem)
+								const gchar *subsystem,
+								const gchar *loc)
 {
-	msg_debug_cache_task ("increase async events counter for %s(%d) = %d + 1; subsystem %s",
-			item->symbol, item->id, item->async_events, subsystem);
+	msg_debug_cache_task ("increase async events counter for %s(%d) = %d + 1; subsystem %s (%s)",
+			item->symbol, item->id, item->async_events, subsystem, loc);
 	return ++item->async_events;
 }
 
 guint
-rspamd_symcache_item_async_dec (struct rspamd_task *task,
+rspamd_symcache_item_async_dec_full (struct rspamd_task *task,
 								struct rspamd_symcache_item *item,
-								const gchar *subsystem)
+								const gchar *subsystem,
+								const gchar *loc)
 {
-	msg_debug_cache_task ("decrease async events counter for %s(%d) = %d - 1; subsystem %s",
-			item->symbol, item->id, item->async_events, subsystem);
+	msg_debug_cache_task ("decrease async events counter for %s(%d) = %d - 1; subsystem %s (%s)",
+			item->symbol, item->id, item->async_events, subsystem, loc);
 	g_assert (item->async_events > 0);
 
 	return --item->async_events;
 }
 
 gboolean
-rspamd_symcache_item_async_dec_check (struct rspamd_task *task,
+rspamd_symcache_item_async_dec_check_full (struct rspamd_task *task,
 									  struct rspamd_symcache_item *item,
-									  const gchar *subsystem)
+									  const gchar *subsystem,
+									  const gchar *loc)
 {
-	if (rspamd_symcache_item_async_dec (task, item, subsystem) == 0) {
+	if (rspamd_symcache_item_async_dec_full (task, item, subsystem, loc) == 0) {
 		rspamd_symbols_cache_finalize_item (task, item);
 
 		return TRUE;
diff --git a/src/libserver/symbols_cache.h b/src/libserver/symbols_cache.h
index 73a46c270..d3983f91d 100644
--- a/src/libserver/symbols_cache.h
+++ b/src/libserver/symbols_cache.h
@@ -315,16 +315,21 @@ void rspamd_symbols_cache_finalize_item (struct rspamd_task *task,
 /*
  * Increase number of async events pending for an item
  */
-guint rspamd_symcache_item_async_inc (struct rspamd_task *task,
+guint rspamd_symcache_item_async_inc_full (struct rspamd_task *task,
 									  struct rspamd_symcache_item *item,
-									  const gchar *subsystem);
+									  const gchar *subsystem,
+									  const gchar *loc);
+#define rspamd_symcache_item_async_inc(task, item, subsystem) \
+	rspamd_symcache_item_async_inc_full(task, item, subsystem, G_STRLOC)
 /*
  * Decrease number of async events pending for an item, asserts if no events pending
  */
-guint rspamd_symcache_item_async_dec (struct rspamd_task *task,
+guint rspamd_symcache_item_async_dec_full (struct rspamd_task *task,
 									  struct rspamd_symcache_item *item,
-									  const gchar *subsystem);
-
+									  const gchar *subsystem,
+									  const gchar *loc);
+#define rspamd_symcache_item_async_dec(task, item, subsystem) \
+	rspamd_symcache_item_async_dec_full(task, item, subsystem, G_STRLOC)
 /**
  * Decrease number of async events pending for an item, asserts if no events pending
  * If no events are left, this function calls `rspamd_symbols_cache_finalize_item` and returns TRUE
@@ -332,7 +337,10 @@ guint rspamd_symcache_item_async_dec (struct rspamd_task *task,
  * @param item
  * @return
  */
-gboolean rspamd_symcache_item_async_dec_check (struct rspamd_task *task,
+gboolean rspamd_symcache_item_async_dec_check_full (struct rspamd_task *task,
 											   struct rspamd_symcache_item *item,
-											   const gchar *subsystem);
+											   const gchar *subsystem,
+											   const gchar *loc);
+#define rspamd_symcache_item_async_dec_check(task, item, subsystem) \
+	rspamd_symcache_item_async_dec_check_full(task, item, subsystem, G_STRLOC)
 #endif