diff --git a/apps/emqx/include/logger.hrl b/apps/emqx/include/logger.hrl index 1341dcf8d..a975cbd38 100644 --- a/apps/emqx/include/logger.hrl +++ b/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 diff --git a/apps/emqx/src/emqx_trace/emqx_trace.erl b/apps/emqx/src/emqx_trace/emqx_trace.erl index 51eea43e8..ac52bc246 100644 --- a/apps/emqx/src/emqx_trace/emqx_trace.erl +++ b/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; diff --git a/apps/emqx/src/emqx_trace/emqx_trace_formatter.erl b/apps/emqx/src/emqx_trace/emqx_trace_formatter.erl index 8538a25f8..147b13825 100644 --- a/apps/emqx/src/emqx_trace/emqx_trace_formatter.erl +++ b/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); diff --git a/apps/emqx/src/emqx_trace/emqx_trace_handler.erl b/apps/emqx/src/emqx_trace/emqx_trace_handler.erl index 2bef3d7d9..676026448 100644 --- a/apps/emqx/src/emqx_trace/emqx_trace_handler.erl +++ b/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;