Centralized internal logging

lib/filter/filter-call.c

@@ -50,9 +50,10 @@ filter_call_eval(FilterExprNode *s, LogMessage **msgs, gint num_msg, LogTemplate
   else
     stats_counter_inc(self->super.not_matched);
 
+  msg_set_context(msgs[num_msg - 1]);
   msg_trace("filter() evaluation started",
-            evt_tag_str("called-rule", self->rule),
-            evt_tag_msg_reference(msgs[num_msg - 1]));
+            evt_tag_str("called-rule", self->rule));
+  msg_set_context(NULL);
 
   return res ^ s->comp;
 }

lib/filter/filter-cmp.c

@@ -295,15 +295,16 @@ fop_cmp_eval(FilterExprNode *s, LogMessage **msgs, gint num_msg, LogTemplateEval
   else
     g_assert_not_reached();
 
+  msg_set_context(msgs[num_msg - 1]);
   msg_trace("cmp() evaluation result",
             evt_tag_str("left", left_buf->str),
             evt_tag_str("operator", self->super.type),
             evt_tag_str("right", right_buf->str),
             evt_tag_str("compare_mode", _compare_mode_to_string(self->compare_mode)),
             evt_tag_str("left_type", log_msg_value_type_to_str(left_type)),
             evt_tag_str("right_type", log_msg_value_type_to_str(right_type)),
-            evt_tag_int("result", result),
-            evt_tag_msg_reference(msgs[num_msg - 1]));
+            evt_tag_int("result", result));
+  msg_set_context(NULL);
 
   scratch_buffers_reclaim_marked(marker);
   return result ^ s->comp;

lib/filter/filter-in-list.c

@@ -50,9 +50,10 @@ filter_in_list_eval(FilterExprNode *s, LogMessage **msgs, gint num_msg, LogTempl
   APPEND_ZERO(value, value, len);
 
   gboolean result = (g_tree_lookup(self->tree, value) != NULL);
+  msg_set_context(msg);
   msg_trace("in-list() evaluation started",
-            evt_tag_str("value", value),
-            evt_tag_msg_reference(msg));
+            evt_tag_str("value", value));
+  msg_set_context(NULL);
 
   return result ^ s->comp;
 }

lib/filter/filter-netmask.c

@@ -63,11 +63,12 @@ filter_netmask_eval(FilterExprNode *s, LogMessage **msgs, gint num_msg, LogTempl
   else
     res = FALSE;
 
+  msg_set_context(msg);
   msg_trace("netmask() evaluation started",
             evt_tag_inaddr("msg_address", addr),
             evt_tag_inaddr("address", &self->address),
-            evt_tag_inaddr("netmask", &self->netmask),
-            evt_tag_msg_reference(msg));
+            evt_tag_inaddr("netmask", &self->netmask));
+  msg_set_context(NULL);
   return res ^ s->comp;
 }
 

lib/filter/filter-netmask6.c

@@ -128,11 +128,12 @@ _eval(FilterExprNode *s, LogMessage **msgs, gint num_msg, LogTemplateEvalOptions
   else
     result = FALSE;
 
+  msg_set_context(msg);
   msg_trace("netmask6() evaluation started",
             evt_tag_inaddr6("msg_address", address),
             evt_tag_inaddr6("address", &self->address),
-            evt_tag_int("prefix", self->prefix),
-            evt_tag_msg_reference(msg));
+            evt_tag_int("prefix", self->prefix));
+  msg_set_context(NULL);
   return result ^ s->comp;
 }
 

lib/filter/filter-pipe.c

@@ -59,18 +59,18 @@ log_filter_pipe_queue(LogPipe *s, LogMessage *msg, const LogPathOptions *path_op
   LogFilterPipe *self = (LogFilterPipe *) s;
   gboolean res;
 
+  msg_set_context(msg);
   msg_trace(">>>>>> filter rule evaluation begin",
             evt_tag_str("rule", self->name),
-            log_pipe_location_tag(s),
-            evt_tag_msg_reference(msg));
+            log_pipe_location_tag(s));
 
   res = filter_expr_eval_root(self->expr, &msg, path_options);
 
+  msg_set_context(msg);
   msg_trace("<<<<<< filter rule evaluation result",
             evt_tag_str("result", res ? "matched" : "unmatched"),
             evt_tag_str("rule", self->name),
-            log_pipe_location_tag(s),
-            evt_tag_msg_reference(msg));
+            log_pipe_location_tag(s));
 
   if (res)
     {
@@ -84,6 +84,7 @@ log_filter_pipe_queue(LogPipe *s, LogMessage *msg, const LogPathOptions *path_op
       log_msg_drop(msg, path_options, AT_PROCESSED);
       stats_counter_inc(self->not_matched);
     }
+  msg_set_context(NULL);
 }
 
 static LogPipe *

lib/filter/filter-pri.c

@@ -49,11 +49,12 @@ filter_facility_eval(FilterExprNode *s, LogMessage **msgs, gint num_msg, LogTemp
     {
       res = !!(self->valid & (1 << fac_num));
     }
+  msg_set_context(msg);
   msg_trace("facility() evaluation started",
             evt_tag_int("fac", fac_num),
-            evt_tag_printf("valid_fac", "%08x", self->valid),
-            evt_tag_msg_reference(msg));
+            evt_tag_printf("valid_fac", "%08x", self->valid));
 
+  msg_set_context(NULL);
   return res ^ s->comp;
 }
 
@@ -79,11 +80,12 @@ filter_severity_eval(FilterExprNode *s, LogMessage **msgs, gint num_msg, LogTemp
 
   res = !!((1 << pri) & self->valid);
 
+  msg_set_context(msg);
   msg_trace("severity() evaluation started",
             evt_tag_int("pri", pri),
-            evt_tag_printf("valid_pri", "%08x", self->valid),
-            evt_tag_msg_reference(msg));
+            evt_tag_printf("valid_pri", "%08x", self->valid));
 
+  msg_set_context(NULL);
   return res ^ s->comp;
 }
 

lib/filter/filter-re.c

@@ -43,12 +43,13 @@ filter_re_eval(FilterExprNode *s, LogMessage **msgs, gint num_msg, LogTemplateEv
   LogMessage *msg = msgs[num_msg - 1];
   gboolean result;
 
+  msg_set_context(msg);
   msg_trace("match() evaluation started against a name-value pair",
             evt_tag_msg_value_name("name", self->value_handle),
             evt_tag_msg_value("value", msg, self->value_handle),
-            evt_tag_str("pattern", self->matcher->pattern),
-            evt_tag_msg_reference(msg));
+            evt_tag_str("pattern", self->matcher->pattern));
   result = log_matcher_match_value(self->matcher, msg, self->value_handle);
+  msg_set_context(NULL);
   return result ^ s->comp;
 }
 
@@ -178,12 +179,13 @@ filter_match_eval_against_program_pid_msg(FilterExprNode *s, LogMessage **msgs,
                         pid_len > 0 ? "]" : "",
                         log_msg_get_value(msg, LM_V_MESSAGE, NULL));
 
+  msg_set_context(msg);
   msg_trace("match() evaluation started against constructed $PROGRAM[$PID]: $MESSAGE string for compatibility",
             evt_tag_printf("input", "%s", str),
-            evt_tag_str("pattern", self->super.matcher->pattern),
-            evt_tag_msg_reference(msg));
+            evt_tag_str("pattern", self->super.matcher->pattern));
 
   result = log_matcher_match_buffer(self->super.matcher, msg, str, -1);
+  msg_set_context(NULL);
 
   g_free(str);
   return result ^ s->comp;
@@ -195,12 +197,13 @@ filter_match_eval_against_template(FilterExprNode *s, LogMessage **msgs, gint nu
   FilterMatch *self = (FilterMatch *) s;
   LogMessage *msg = msgs[num_msg - 1];
 
+  msg_set_context(msg);
   msg_trace("match() evaluation started against template",
             evt_tag_template("input", self->template, msg, options),
             evt_tag_str("pattern", self->super.matcher->pattern),
-            evt_tag_str("template", self->template->template_str),
-            evt_tag_msg_reference(msg));
+            evt_tag_str("template", self->template->template_str));
   gboolean result = log_matcher_match_template(self->super.matcher, msg, self->template, options);
+  msg_set_context(NULL);
   return result ^ s->comp;
 }
 

lib/filter/filter-tags.c

@@ -37,6 +37,7 @@ filter_tags_eval(FilterExprNode *s, LogMessage **msgs, gint num_msg, LogTemplate
 {
   FilterTags *self = (FilterTags *)s;
   LogMessage *msg = msgs[num_msg - 1];
+  msg_set_context(msg);
   gboolean res;
   gint i;
 
@@ -46,8 +47,7 @@ filter_tags_eval(FilterExprNode *s, LogMessage **msgs, gint num_msg, LogTemplate
       if (log_msg_is_tag_by_id(msg, tag_id))
         {
           msg_trace("tags() evaluation result, matching tag is found",
-                    evt_tag_str("tag", log_tags_get_by_id(tag_id)),
-                    evt_tag_msg_reference(msg));
+                    evt_tag_str("tag", log_tags_get_by_id(tag_id)));
 
           res = TRUE;
           return res ^ s->comp;
@@ -56,13 +56,12 @@ filter_tags_eval(FilterExprNode *s, LogMessage **msgs, gint num_msg, LogTemplate
         {
           msg_trace("tags() evaluation progress, tag is not set",
                     evt_tag_str("tag", log_tags_get_by_id(tag_id)),
-                    evt_tag_int("value", log_msg_is_tag_by_id(msg, tag_id)),
-                    evt_tag_msg_reference(msg));
+                    evt_tag_int("value", log_msg_is_tag_by_id(msg, tag_id)));
         }
     }
 
-  msg_trace("tags() evaluation result, none of the tags is present",
-            evt_tag_msg_reference(msg));
+  msg_trace("tags() evaluation result, none of the tags is present");
+  msg_set_context(NULL);
   res = FALSE;
   return res ^ s->comp;
 }

lib/filterx/filterx-pipe.c

@@ -59,20 +59,20 @@ log_filterx_pipe_queue(LogPipe *s, LogMessage *msg, const LogPathOptions *path_o
   if (filterx_scope_has_log_msg_changes(eval_context.scope))
     filterx_scope_invalidate_log_msg_cache(eval_context.scope);
 
+  msg_set_context(msg);
   msg_trace(">>>>>> filterx rule evaluation begin",
             evt_tag_str("rule", self->name),
-            log_pipe_location_tag(s),
-            evt_tag_msg_reference(msg));
+            log_pipe_location_tag(s));
 
   NVTable *payload = nv_table_ref(msg->payload);
   eval_res = filterx_eval_exec(&eval_context, self->block, msg);
 
+  msg_set_context(msg);
   msg_trace("<<<<<< filterx rule evaluation result",
             filterx_format_eval_result(eval_res),
             evt_tag_str("rule", self->name),
             log_pipe_location_tag(s),
-            evt_tag_int("dirty", filterx_scope_is_dirty(eval_context.scope)),
-            evt_tag_msg_reference(msg));
+            evt_tag_int("dirty", filterx_scope_is_dirty(eval_context.scope)));
 
   local_path_options.filterx_context = &eval_context;
   switch (eval_res)
@@ -93,6 +93,7 @@ log_filterx_pipe_queue(LogPipe *s, LogMessage *msg, const LogPathOptions *path_o
       g_assert_not_reached();
       break;
     }
+  msg_set_context(NULL);
 
   filterx_eval_deinit_context(&eval_context);
   nv_table_unref(payload);

lib/logmsg/logmsg.c

@@ -618,6 +618,7 @@ log_msg_set_value_with_type(LogMessage *self, NVHandle handle,
   gboolean new_entry = FALSE;
 
   g_assert(!log_msg_is_write_protected(self));
+  msg_set_context(self);
 
   if (handle == LM_V_NONE)
     return;
@@ -633,8 +634,7 @@ log_msg_set_value_with_type(LogMessage *self, NVHandle handle,
       msg_trace("Setting value",
                 evt_tag_str("name", name),
                 evt_tag_mem("value", value, value_len),
-                evt_tag_str("type", log_msg_value_type_to_str(type)),
-                evt_tag_msg_reference(self));
+                evt_tag_str("type", log_msg_value_type_to_str(type)));
     }
 
   if (!log_msg_chk_flag(self, LF_STATE_OWN_PAYLOAD))
@@ -673,6 +673,7 @@ log_msg_set_value_with_type(LogMessage *self, NVHandle handle,
 
   if (_value_invalidates_legacy_header(handle))
     log_msg_unset_value(self, LM_V_LEGACY_MSGHDR);
+  msg_set_context(NULL);
 }
 
 void
@@ -685,12 +686,12 @@ void
 log_msg_unset_value(LogMessage *self, NVHandle handle)
 {
   g_assert(!log_msg_is_write_protected(self));
+  msg_set_context(self);
 
   if (_log_name_value_updates(self))
     {
       msg_trace("Unsetting value",
-                evt_tag_str("name", log_msg_get_value_name(handle, NULL)),
-                evt_tag_msg_reference(self));
+                evt_tag_str("name", log_msg_get_value_name(handle, NULL)));
     }
 
   if (!log_msg_chk_flag(self, LF_STATE_OWN_PAYLOAD))
@@ -720,6 +721,7 @@ log_msg_unset_value(LogMessage *self, NVHandle handle)
 
   if (_value_invalidates_legacy_header(handle))
     log_msg_unset_value(self, LM_V_LEGACY_MSGHDR);
+  msg_set_context(NULL);
 }
 
 void
@@ -738,6 +740,7 @@ log_msg_set_value_indirect_with_type(LogMessage *self, NVHandle handle,
   gboolean new_entry = FALSE;
 
   g_assert(!log_msg_is_write_protected(self));
+  msg_set_context(self);
 
   if (handle == LM_V_NONE)
     return;
@@ -754,8 +757,7 @@ log_msg_set_value_indirect_with_type(LogMessage *self, NVHandle handle,
                 evt_tag_str("type", log_msg_value_type_to_str(type)),
                 evt_tag_int("ref_handle", ref_handle),
                 evt_tag_int("ofs", ofs),
-                evt_tag_int("len", len),
-                evt_tag_msg_reference(self));
+                evt_tag_int("len", len));
     }
 
   if (!log_msg_chk_flag(self, LF_STATE_OWN_PAYLOAD))
@@ -788,6 +790,8 @@ log_msg_set_value_indirect_with_type(LogMessage *self, NVHandle handle,
   if (new_entry)
     log_msg_update_sdata(self, handle, name, name_len);
   log_msg_update_num_matches(self, handle);
+
+  msg_set_context(NULL);
 }
 
 void
@@ -1509,9 +1513,9 @@ log_msg_clone_cow(LogMessage *msg, const LogPathOptions *path_options)
   memcpy(self, msg, sizeof(*msg));
   msg->allocated_bytes = allocated_bytes;
 
+  msg_set_context(msg);
   msg_trace("Message was cloned",
-            evt_tag_printf("original_msg", "%p", msg),
-            evt_tag_msg_reference(self));
+            evt_tag_printf("original_msg", "%p", msg));
 
   /* every field _must_ be initialized explicitly if its direct
    * copying would cause problems (like copying a pointer by value) */
@@ -1537,6 +1541,8 @@ log_msg_clone_cow(LogMessage *msg, const LogPathOptions *path_options)
 
   if (self->num_tags == 0)
     self->flags |= LF_STATE_OWN_TAGS;
+
+  msg_set_context(NULL);
   return self;
 }
 

lib/logmsg/logmsg.h

@@ -552,17 +552,12 @@ void log_msg_registry_init(void);
 void log_msg_registry_deinit(void);
 void log_msg_global_init(void);
 void log_msg_global_deinit(void);
-void log_msg_stats_global_init(void);
 void log_msg_registry_foreach(GHFunc func, gpointer user_data);
 
 gint log_msg_lookup_time_stamp_name(const gchar *name);
 
 gssize log_msg_get_size(LogMessage *self);
 
-#define evt_tag_msg_reference(msg)             \
-    evt_tag_printf("msg", "%p", (msg)),        \
-    evt_tag_printf("rcptid", "%" G_GUINT64_FORMAT, (msg)->rcptid)
-
 static inline EVTTAG *
 evt_tag_msg_value(const gchar *name, LogMessage *msg, NVHandle value_handle)
 {

lib/logreader.c

@@ -459,9 +459,9 @@ log_reader_handle_line(LogReader *self, const guchar *line, gint length, LogTran
   LogMessage *m;
 
   m = msg_format_construct_message(&self->options->parse_options, line, length);
+  msg_set_context(m);
   msg_debug("Incoming log entry",
-            evt_tag_mem("input", line, length),
-            evt_tag_msg_reference(m));
+            evt_tag_mem("input", line, length));
 
   msg_format_parse_into(&self->options->parse_options, m, line, length);
 
@@ -487,6 +487,7 @@ log_reader_handle_line(LogReader *self, const guchar *line, gint length, LogTran
   log_transport_aux_data_foreach(aux, _add_aux_nvpair, m);
 
   log_source_post(&self->super, m);
+  msg_set_context(NULL);
   log_msg_refcache_stop();
   return log_source_free_to_send(&self->super);
 }

lib/logsource.c

@@ -636,8 +636,7 @@ log_source_queue(LogPipe *s, LogMessage *msg, const LogPathOptions *path_options
   msg_set_context(msg);
 
   msg_diagnostics(">>>>>> Source side message processing begin",
-                  log_pipe_location_tag(s),
-                  evt_tag_msg_reference(msg));
+                  log_pipe_location_tag(s));
 
   /* $HOST setup */
   log_source_mangle_hostname(self, msg);