feat(logger): add formatter emqx_logger_jsonfmt
This commit is contained in:
Zaiming Shi
Zaiming (Stone) Shi
parent
c4f070c9c6
commit
79181072e2
|
|
@ -444,9 +444,15 @@ log.file = emqx.log
|
|||
## Default: No Limit
|
||||
#log.chars_limit = 8192
|
||||
|
||||
## Log to single line
|
||||
## Log as JSON objects
|
||||
## Value: boolean
|
||||
#log.single_line = false
|
||||
#log.use_json_formatter = false
|
||||
|
||||
## Log to single line
|
||||
## Value: formatter_default | true | false
|
||||
## 'default' is equivalent to 'true' when use_json_formatter is 'true'
|
||||
## 'default' is equivalent to 'false' when `use_json_formatter is 'false'
|
||||
#log.single_line = formatter_default
|
||||
|
||||
## Enables the log rotation.
|
||||
## With this enabled, new log files will be created when the current
|
||||
|
|
|
|||
|
|
@ -498,12 +498,18 @@ end}.
|
|||
{datatype, [{enum, [unlimited]}, integer]}
|
||||
]}.
|
||||
|
||||
%% @doc format logs in a single line.
|
||||
{mapping, "log.single_line", "kernel.logger", [
|
||||
%% @doc format logs as JSON objects
|
||||
{mapping, "log.use_json_formatter", "kernel.logger", [
|
||||
{default, false},
|
||||
{datatype, {enum, [true, false]}}
|
||||
]}.
|
||||
|
||||
%% @doc format logs in a single line.
|
||||
{mapping, "log.single_line", "kernel.logger", [
|
||||
{default, formatter_default},
|
||||
{datatype, {enum, [formatter_default, true, false]}}
|
||||
]}.
|
||||
|
||||
{mapping, "log.rotation", "kernel.logger", [
|
||||
{default, on},
|
||||
{datatype, flag}
|
||||
|
|
@ -600,8 +606,24 @@ end}.
|
|||
-1 -> unlimited;
|
||||
V -> V
|
||||
end,
|
||||
SingleLine = cuttlefish:conf_get("log.single_line", Conf),
|
||||
Formatter = {logger_formatter,
|
||||
SingleLine0 = cuttlefish:conf_get("log.single_line", Conf),
|
||||
AsJson = cuttlefish:conf_get("log.use_json_formatter", Conf),
|
||||
SingleLine = case SingleLine0 =:= formatter_default of
|
||||
true ->
|
||||
%% single-line when logging in JSON format
|
||||
AsJson;
|
||||
false ->
|
||||
SingleLine0
|
||||
end,
|
||||
Formatter =
|
||||
case AsJson of
|
||||
true ->
|
||||
{emqx_logger_jsonfmt,
|
||||
#{chars_limit => CharsLimit,
|
||||
single_line => SingleLine
|
||||
}};
|
||||
false ->
|
||||
{logger_formatter,
|
||||
#{template =>
|
||||
[time," [",level,"] ",
|
||||
{clientid,
|
||||
|
|
@ -614,7 +636,8 @@ end}.
|
|||
msg,"\n"],
|
||||
chars_limit => CharsLimit,
|
||||
single_line => SingleLine
|
||||
}},
|
||||
}}
|
||||
end,
|
||||
{BustLimitOn, {MaxBurstCount, TimeWindow}} =
|
||||
case string:tokens(cuttlefish:conf_get("log.burst_limit", Conf), ", ") of
|
||||
["disabled"] -> {false, {20000, 1000}};
|
||||
|
|
|
|||
|
|
@ -0,0 +1,294 @@
|
|||
%%--------------------------------------------------------------------
|
||||
%% Copyright (c) 2021 EMQ Technologies Co., Ltd. All Rights Reserved.
|
||||
%%
|
||||
%% Licensed under the Apache License, Version 2.0 (the "License");
|
||||
%% you may not use this file except in compliance with the License.
|
||||
%% You may obtain a copy of the License at
|
||||
%%
|
||||
%% http://www.apache.org/licenses/LICENSE-2.0
|
||||
%%
|
||||
%% Unless required by applicable law or agreed to in writing, software
|
||||
%% distributed under the License is distributed on an "AS IS" BASIS,
|
||||
%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
||||
%% See the License for the specific language governing permissions and
|
||||
%% limitations under the License.
|
||||
%%--------------------------------------------------------------------
|
||||
|
||||
%% @doc This logger formatter tries format logs into JSON objects
|
||||
%%
|
||||
%% Due to the fact that the `Report' body of log entries are *NOT*
|
||||
%% structured, we only try to JSON-ify `Meta',
|
||||
%%
|
||||
%% `Report' body format is pretty-printed and used as the `msg'
|
||||
%% JSON field in the finale result.
|
||||
%%
|
||||
%% e.g. logger:log(info, _Data = #{foo => bar}, _Meta = #{metaf1 => 2})
|
||||
%% will results in a JSON object look like below:
|
||||
%%
|
||||
%% {"time": 1620226963427808, "level": "info", msg": "foo: bar", "metaf1": 2}
|
||||
|
||||
-module(emqx_logger_jsonfmt).
|
||||
|
||||
-export([format/2]).
|
||||
|
||||
-ifdef(TEST).
|
||||
-export([report_cb_1/1, report_cb_2/2, report_cb_crash/2]).
|
||||
-endif.
|
||||
|
||||
-export_type([config/0]).
|
||||
|
||||
-elvis([{elvis_style, no_nested_try_catch, #{ ignore => [emqx_logger_jsonfmt]}}]).
|
||||
|
||||
-type config() :: #{depth => pos_integer() | unlimited,
|
||||
report_cb => logger:report_cb(),
|
||||
single_line => boolean()}.
|
||||
|
||||
-define(IS_STRING(String), (is_list(String) orelse is_binary(String))).
|
||||
|
||||
-spec format(logger:log_event(), config()) -> iodata().
|
||||
format(#{level := Level, msg := Msg, meta := Meta}, Config0) when is_map(Config0) ->
|
||||
Config = add_default_config(Config0),
|
||||
format(Msg, Meta#{level => Level}, Config).
|
||||
|
||||
format(Msg, Meta, Config) ->
|
||||
Data0 =
|
||||
try Meta#{msg => format_msg(Msg, Meta, Config)}
|
||||
catch
|
||||
C:R:S ->
|
||||
Meta#{ msg => "emqx_logger_jsfmt_format_error"
|
||||
, fmt_raw_input => Msg
|
||||
, fmt_error => C
|
||||
, fmt_reason => R
|
||||
, fmt_stacktrace => S
|
||||
}
|
||||
end,
|
||||
Data = maps:without([report_cb], Data0),
|
||||
jiffy:encode(json_obj(Data, Config)).
|
||||
|
||||
format_msg({string, Chardata}, Meta, Config) ->
|
||||
format_msg({"~ts", [Chardata]}, Meta, Config);
|
||||
format_msg({report, _} = Msg, Meta, #{report_cb := Fun} = Config)
|
||||
when is_function(Fun,1); is_function(Fun,2) ->
|
||||
format_msg(Msg, Meta#{report_cb => Fun}, maps:remove(report_cb, Config));
|
||||
format_msg({report, Report}, #{report_cb := Fun} = Meta, Config) when is_function(Fun, 1) ->
|
||||
case Fun(Report) of
|
||||
{Format, Args} when is_list(Format), is_list(Args) ->
|
||||
format_msg({Format, Args}, maps:remove(report_cb, Meta), Config);
|
||||
Other ->
|
||||
#{ msg => "report_cb_bad_return"
|
||||
, report_cb_fun => Fun
|
||||
, report_cb_return => Other
|
||||
}
|
||||
end;
|
||||
format_msg({report, Report}, #{report_cb := Fun}, Config) when is_function(Fun, 2) ->
|
||||
case Fun(Report, maps:with([depth, single_line], Config)) of
|
||||
Chardata when ?IS_STRING(Chardata) ->
|
||||
try
|
||||
unicode:characters_to_binary(Chardata, utf8)
|
||||
catch
|
||||
_:_ ->
|
||||
#{ msg => "report_cb_bad_return"
|
||||
, report_cb_fun => Fun
|
||||
, report_cb_return => Chardata
|
||||
}
|
||||
end;
|
||||
Other ->
|
||||
#{ msg => "report_cb_bad_return"
|
||||
, report_cb_fun => Fun
|
||||
, report_cb_return => Other
|
||||
}
|
||||
end;
|
||||
format_msg({Fmt, Args}, _Meta, Config) ->
|
||||
do_format_msg(Fmt, Args, Config).
|
||||
|
||||
do_format_msg(Format0, Args, #{depth := Depth,
|
||||
single_line := SingleLine
|
||||
}) ->
|
||||
Format1 = io_lib:scan_format(Format0, Args),
|
||||
Format = reformat(Format1, Depth, SingleLine),
|
||||
Text0 = io_lib:build_text(Format, []),
|
||||
Text = case SingleLine of
|
||||
true -> re:replace(Text0, ",?\r?\n\s*",", ", [{return, list}, global, unicode]);
|
||||
false -> Text0
|
||||
end,
|
||||
trim(unicode:characters_to_binary(Text, utf8)).
|
||||
|
||||
%% Get rid of the leading spaces.
|
||||
%% leave alone the trailing spaces.
|
||||
trim(<<$\s, Rest/binary>>) -> trim(Rest);
|
||||
trim(Bin) -> Bin.
|
||||
|
||||
reformat(Format, unlimited, false) ->
|
||||
Format;
|
||||
reformat([#{control_char := C} = M | T], Depth, true) when C =:= $p ->
|
||||
[limit_depth(M#{width => 0}, Depth) | reformat(T, Depth, true)];
|
||||
reformat([#{control_char := C} = M | T], Depth, true) when C =:= $P ->
|
||||
[M#{width => 0} | reformat(T, Depth, true)];
|
||||
reformat([#{control_char := C}=M | T], Depth, Single) when C =:= $p; C =:= $w ->
|
||||
[limit_depth(M, Depth) | reformat(T, Depth, Single)];
|
||||
reformat([H | T], Depth, Single) ->
|
||||
[H | reformat(T, Depth, Single)];
|
||||
reformat([], _, _) ->
|
||||
[].
|
||||
|
||||
limit_depth(M0, unlimited) -> M0;
|
||||
limit_depth(#{control_char:=C0, args:=Args}=M0, Depth) ->
|
||||
C = C0 - ($a - $A), %To uppercase.
|
||||
M0#{control_char := C, args := Args ++ [Depth]}.
|
||||
|
||||
add_default_config(Config0) ->
|
||||
Default = #{single_line => true},
|
||||
Depth = get_depth(maps:get(depth, Config0, undefined)),
|
||||
maps:merge(Default, Config0#{depth => Depth}).
|
||||
|
||||
get_depth(undefined) -> error_logger:get_format_depth();
|
||||
get_depth(S) -> max(5, S).
|
||||
|
||||
best_effort_unicode(Input, Config) ->
|
||||
try unicode:characters_to_binary(Input, utf8) of
|
||||
B when is_binary(B) -> B;
|
||||
_ -> do_format_msg("~p", [Input], Config)
|
||||
catch
|
||||
_ : _ ->
|
||||
do_format_msg("~p", [Input], Config)
|
||||
end.
|
||||
|
||||
best_effort_json_obj(List, Config) when is_list(List) ->
|
||||
try
|
||||
json_obj(maps:from_list(List), Config)
|
||||
catch
|
||||
_ : _ ->
|
||||
[json(I, Config) || I <- List]
|
||||
end;
|
||||
best_effort_json_obj(Map, Config) ->
|
||||
try
|
||||
json_obj(Map, Config)
|
||||
catch
|
||||
_ : _ ->
|
||||
do_format_msg("~p", [Map], Config)
|
||||
end.
|
||||
|
||||
json([], _) -> "[]";
|
||||
json(<<"">>, _) -> "\"\"";
|
||||
json(A, _) when is_atom(A) -> atom_to_binary(A, utf8);
|
||||
json(I, _) when is_integer(I) -> I;
|
||||
json(F, _) when is_float(F) -> F;
|
||||
json(P, C) when is_pid(P) -> json(pid_to_list(P), C);
|
||||
json(P, C) when is_port(P) -> json(port_to_list(P), C);
|
||||
json(F, C) when is_function(F) -> json(erlang:fun_to_list(F), C);
|
||||
json(B, Config) when is_binary(B) ->
|
||||
best_effort_unicode(B, Config);
|
||||
json(L, Config) when is_list(L), is_integer(hd(L))->
|
||||
best_effort_unicode(L, Config);
|
||||
json(M, Config) when is_list(M), is_tuple(hd(M)), tuple_size(hd(M)) =:= 2 ->
|
||||
best_effort_json_obj(M, Config);
|
||||
json(L, Config) when is_list(L) ->
|
||||
[json(I, Config) || I <- L];
|
||||
json(Map, Config) when is_map(Map) ->
|
||||
best_effort_json_obj(Map, Config);
|
||||
json(Term, Config) ->
|
||||
do_format_msg("~p", [Term], Config).
|
||||
|
||||
json_obj(Data, Config) ->
|
||||
maps:fold(fun (K, V, D) ->
|
||||
json_kv(K, V, D, Config)
|
||||
end, maps:new(), Data).
|
||||
|
||||
json_kv(mfa, {M, F, A}, Data, _Config) -> %% emqx/snabbkaffe
|
||||
maps:put(mfa, <<(atom_to_binary(M, utf8))/binary, $:,
|
||||
(atom_to_binary(F, utf8))/binary, $/,
|
||||
(integer_to_binary(A))/binary>>, Data);
|
||||
json_kv('$kind', Kind, Data, Config) -> %% snabbkaffe
|
||||
maps:put(msg, json(Kind, Config), Data);
|
||||
json_kv(K0, V, Data, Config) ->
|
||||
K = json_key(K0),
|
||||
case is_map(V) of
|
||||
true -> maps:put(json(K, Config), json_obj(V, Config), Data);
|
||||
false -> maps:put(json(K, Config), json(V, Config), Data)
|
||||
end.
|
||||
|
||||
json_key('') -> throw({badkey, ''});
|
||||
json_key("") -> throw({badkey, ""});
|
||||
json_key(<<>>) -> throw({badkey, <<>>});
|
||||
json_key(A) when is_atom(A) -> atom_to_binary(A, utf8);
|
||||
json_key(Term) ->
|
||||
try unicode:characters_to_binary(Term, utf8) of
|
||||
OK when is_binary(OK) -> OK;
|
||||
_ -> throw({badkey, Term})
|
||||
catch _:_ -> throw({badkey, Term})
|
||||
end.
|
||||
|
||||
-ifdef(TEST).
|
||||
-include_lib("proper/include/proper.hrl").
|
||||
-include_lib("eunit/include/eunit.hrl").
|
||||
|
||||
no_crash_test_() ->
|
||||
Opts = [{numtests, 1000}, {to_file, user}],
|
||||
{timeout, 30,
|
||||
fun() -> ?assert(proper:quickcheck(t_no_crash(), Opts)) end}.
|
||||
|
||||
t_no_crash() ->
|
||||
?FORALL({Level, Report, Meta, Config},
|
||||
{p_level(), p_report(), p_meta(), p_config()},
|
||||
t_no_crash_run(Level, Report, Meta, Config)).
|
||||
|
||||
t_no_crash_run(Level, Report, {undefined, Meta}, Config) ->
|
||||
t_no_crash_run(Level, Report, maps:from_list(Meta), Config);
|
||||
t_no_crash_run(Level, Report, {ReportCb, Meta}, Config) ->
|
||||
t_no_crash_run(Level, Report, maps:from_list([{report_cb, ReportCb} | Meta]), Config);
|
||||
t_no_crash_run(Level, Report, Meta, Config) ->
|
||||
Input = #{ level => Level
|
||||
, msg => {report, Report}
|
||||
, meta => filter(Meta)
|
||||
},
|
||||
_ = format(Input, maps:from_list(Config)),
|
||||
true.
|
||||
|
||||
%% assume top level Report and Meta are sane
|
||||
filter(Map) ->
|
||||
Keys = lists:filter(
|
||||
fun(K) ->
|
||||
try json_key(K), true
|
||||
catch _ : _ -> false
|
||||
end
|
||||
end, maps:keys(Map)),
|
||||
maps:with(Keys, Map).
|
||||
|
||||
p_report_cb() ->
|
||||
proper_types:oneof([ fun ?MODULE:report_cb_1/1
|
||||
, fun ?MODULE:report_cb_2/2
|
||||
, fun ?MODULE:report_cb_crash/2
|
||||
, fun logger:format_otp_report/1
|
||||
, fun logger:format_report/1
|
||||
, format_reportundefined
|
||||
]).
|
||||
|
||||
report_cb_1(Input) -> {"~p", [Input]}.
|
||||
|
||||
report_cb_2(Input, _Config) -> io_lib:format("~p", [Input]).
|
||||
|
||||
report_cb_crash(_Input, _Config) -> error(report_cb_crash).
|
||||
|
||||
p_kvlist() ->
|
||||
proper_types:list({
|
||||
proper_types:oneof([proper_types:atom(),
|
||||
proper_types:binary()
|
||||
]), proper_types:term()}).
|
||||
|
||||
%% meta type is 2-tuple, report_cb type, and some random key value pairs
|
||||
p_meta() ->
|
||||
{p_report_cb(), p_kvlist()}.
|
||||
|
||||
p_report() -> p_kvlist().
|
||||
|
||||
p_limit() -> proper_types:oneof([proper_types:pos_integer(), unlimited]).
|
||||
|
||||
p_level() -> proper_types:oneof([info, debug, error, warning, foobar]).
|
||||
|
||||
p_config() ->
|
||||
proper_types:shrink_list(
|
||||
[ {depth, p_limit()}
|
||||
, {single_line, proper_types:boolean()}
|
||||
]).
|
||||
|
||||
-endif.
|
||||
Loading…
Reference in New Issue