feat(trace): improve debug msg format

apps/emqx/include/logger.hrl

@@ -76,6 +76,7 @@
 -define(TRACE_FILTER, emqx_trace_filter).
 
 %% Only evaluate when necessary
+%% Always debug the trace events.
 -define(TRACE(Event, Msg, Meta),
     begin
     case persistent_term:get(?TRACE_FILTER, undefined) of
@@ -84,7 +85,8 @@
         List ->
            emqx_trace:log(List, Event, Msg, Meta)
     end,
-    ?SLOG(debug, Meta#{msg => Msg})
+    ?SLOG(debug, (emqx_trace_formatter:format_meta(Meta))#{msg => Msg, trace_event => Event},
+        #{trace_filter => ignore})
     end).
 
 %% print to 'user' group leader

apps/emqx/src/emqx_trace/emqx_trace.erl

@@ -100,7 +100,7 @@ log(List, Event, Msg, Meta0) ->
             undefined -> Meta0;
             ProcMeta -> maps:merge(ProcMeta, Meta0)
         end,
-    Log = #{level => trace, event => Event, meta => Meta, msg => Msg},
+    Log = #{level => debug, trace_event => Event, meta => Meta, msg => Msg},
     log_filter(List, Log).
 
 log_filter([], _Log) -> ok;

apps/emqx/src/emqx_trace/emqx_trace_formatter.erl

@@ -16,13 +16,14 @@
 -module(emqx_trace_formatter).
 
 -export([format/2]).
+-export([format_meta/1]).
 
 %%%-----------------------------------------------------------------
 %%% API
 -spec format(LogEvent, Config) -> unicode:chardata() when
     LogEvent :: logger:log_event(),
     Config :: logger:config().
-format(#{level := trace, event := Event, meta := Meta, msg := Msg},
+format(#{level := debug, trace_event := Event, meta := Meta, msg := Msg},
     #{payload_encode := PEncode}) ->
     Time = calendar:system_time_to_rfc3339(erlang:system_time(second)),
     ClientId = to_iolist(maps:get(clientid, Meta, "")),
@@ -33,22 +34,36 @@ format(#{level := trace, event := Event, meta := Meta, msg := Msg},
 format(Event, Config) ->
     emqx_logger_textfmt:format(Event, Config).
 
+format_meta(Meta) ->
+    Encode = emqx_trace_handler:payload_encode(),
+    format_meta_(Meta, Encode).
+
 format_meta(Meta0, Encode) ->
-    Packet = format_packet(maps:get(packet, Meta0, undefined), Encode),
-    Payload = format_payload(maps:get(payload, Meta0, undefined), Encode),
-    Meta1 = maps:without([msg, clientid, peername, packet, payload], Meta0),
-    case Meta1 =:= #{} of
+    Meta1 = #{packet := Packet0, payload := Payload0} = format_meta_(Meta0, Encode),
+    Packet = enrich(", packet: ", Packet0),
+    Payload = enrich(", payload: ", Payload0),
+    Meta2 = maps:without([msg, clientid, peername, packet, payload], Meta1),
+    case Meta2 =:= #{} of
         true -> [Packet, Payload];
-        false -> [Packet, ", ", map_to_iolist(Meta1), Payload]
+        false -> [Packet, ", ", map_to_iolist(Meta2), Payload]
     end.
 
+enrich(_, "") -> "";
+enrich(Key, Bin) -> [Key, Bin].
+
+format_meta_(Meta, Encode) ->
+    Meta#{
+        packet => format_packet(maps:get(packet, Meta, undefined), Encode),
+        payload => format_payload(maps:get(payload, Meta, undefined), Encode)
+    }.
+
 format_packet(undefined, _) -> "";
-format_packet(Packet, Encode) -> [", packet: ", emqx_packet:format(Packet, Encode)].
+format_packet(Packet, Encode) -> emqx_packet:format(Packet, Encode).
 
 format_payload(undefined, _) -> "";
-format_payload(Payload, text) -> [", payload: ", io_lib:format("~ts", [Payload])];
-format_payload(Payload, hex) -> [", payload(hex): ", emqx_packet:encode_hex(Payload)];
-format_payload(_, hidden) -> ", payload=******".
+format_payload(Payload, text) -> io_lib:format("~ts", [Payload]);
+format_payload(Payload, hex) -> emqx_packet:encode_hex(Payload);
+format_payload(_, hidden) -> "******".
 
 to_iolist(Atom) when is_atom(Atom) -> atom_to_list(Atom);
 to_iolist(Int) when is_integer(Int) -> integer_to_list(Int);

apps/emqx/src/emqx_trace/emqx_trace_handler.erl

@@ -120,10 +120,12 @@ running() ->
     lists:foldl(fun filter_traces/2, [], emqx_logger:get_log_handlers(started)).
 
 -spec filter_clientid(logger:log_event(), {binary(), atom()}) -> logger:log_event() | stop.
+filter_clientid(#{level := debug, meta := #{trace_filter := _}}, _) -> stop;
 filter_clientid(#{meta := #{clientid := ClientId}} = Log, {ClientId, _Name}) -> Log;
 filter_clientid(_Log, _ExpectId) -> stop.
 
 -spec filter_topic(logger:log_event(), {binary(), atom()}) -> logger:log_event() | stop.
+filter_topic(#{level := debug, meta := #{trace_filter := _}}, _) -> stop;
 filter_topic(#{meta := #{topic := Topic}} = Log, {TopicFilter, _Name}) ->
     case emqx_topic:match(Topic, TopicFilter) of
         true -> Log;
@@ -132,6 +134,7 @@ filter_topic(#{meta := #{topic := Topic}} = Log, {TopicFilter, _Name}) ->
 filter_topic(_Log, _ExpectId) -> stop.
 
 -spec filter_ip_address(logger:log_event(), {string(), atom()}) -> logger:log_event() | stop.
+filter_ip_address(#{level := debug, meta := #{trace_filter := _}}, _) -> stop;
 filter_ip_address(#{meta := #{peername := Peername}} = Log, {IP, _Name}) ->
     case lists:prefix(IP, Peername) of
         true -> Log;