refactor(logging): Log to single line

This commit is contained in:
Zaiming Shi 2021-04-22 18:10:47 +02:00 committed by Zaiming (Stone) Shi
parent 4178e1a023
commit fd69969014
5 changed files with 19 additions and 1024 deletions

View File

@ -445,6 +445,10 @@ log.file = emqx.log
## Default: No Limit
#log.chars_limit = 8192
## Log to single line
## Value: boolean
#log.single_line = true
## Enables the log rotation.
## With this enabled, new log files will be created when the current
## log file is full, max to `log.rotation.size` files will be created.

View File

@ -490,6 +490,12 @@ end}.
{datatype, integer}
]}.
%% @doc format logs in a single line.
{mapping, "log.single_line", "kernel.logger", [
{default, true},
{datatype, {enum, [true, false]}}
]}.
{mapping, "log.rotation", "kernel.logger", [
{default, on},
{datatype, flag}
@ -592,7 +598,8 @@ end}.
-1 -> unlimited;
V -> V
end,
Formatter = {emqx_logger_formatter,
SingleLine = cuttlefish:conf_get("log.single_line", Conf),
Formatter = {logger_formatter,
#{template =>
[time," [",level,"] ",
{clientid,
@ -603,7 +610,9 @@ end}.
[peername," "],
[]}]},
msg,"\n"],
chars_limit => CharsLimit}},
chars_limit => CharsLimit,
single_line => SingleLine
}},
{BustLimitOn, {MaxBurstCount, TimeWindow}} =
case string:tokens(cuttlefish:conf_get("log.burst_limit", Conf), ", ") of
["disabled"] -> {false, {20000, 1000}};

View File

@ -1,363 +0,0 @@
%%
%% %CopyrightBegin%
%%
%% Copyright Ericsson AB 2013-2019. 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.
%%
%% %CopyrightEnd%
%%
%% This file is copied from lib/kernel/src/logger_formatter.erl, and
%% modified for a more concise time format other than the default RFC3339.
-module(emqx_logger_formatter).
-export([format/2]).
-export([check_config/1]).
-define(DEFAULT_FORMAT_TEMPLATE_SINGLE, [time," ",level,": ",msg,"\n"]).
-define(FormatP, "~0tp").
-define(IS_STRING(String),
(is_list(String) orelse is_binary(String))).
%%--------------------------------------------------------------------
%% Types
-type(config() :: #{chars_limit => pos_integer() | unlimited,
depth => pos_integer() | unlimited,
max_size => pos_integer() | unlimited,
report_cb => logger:report_cb(),
quit => template()}).
-type(template() :: [metakey() | {metakey(),template(),template()} | string()]).
-type(metakey() :: atom() | [atom()]).
%%--------------------------------------------------------------------
%% API
-spec format(LogEvent,Config) -> unicode:chardata() when
LogEvent :: logger:log_event(),
Config :: config().
format(#{level:=Level,msg:=Msg0,meta:=Meta},Config0)
when is_map(Config0) ->
Config = add_default_config(Config0),
Template = maps:get(template,Config),
{BT,AT0} = lists:splitwith(fun(msg) -> false; (_) -> true end, Template),
{DoMsg,AT} =
case AT0 of
[msg|Rest] -> {true,Rest};
_ ->{false,AT0}
end,
B = do_format(Level,Meta,BT,Config),
A = do_format(Level,Meta,AT,Config),
MsgStr =
if DoMsg ->
Config1 =
case maps:get(chars_limit,Config) of
unlimited ->
Config;
Size0 ->
Size =
case Size0 - string:length([B,A]) of
S when S>=0 -> S;
_ -> 0
end,
Config#{chars_limit=>Size}
end,
format_msg(Msg0,Meta,Config1);
true ->
""
end,
truncate([B,MsgStr,A],maps:get(max_size,Config)).
do_format(Level,Data,[level|Format],Config) ->
[to_string(level,Level,Config)|do_format(Level,Data,Format,Config)];
do_format(Level,Data,[{Key,IfExist,Else}|Format],Config) ->
String =
case value(Key,Data) of
{ok,Value} -> do_format(Level,Data#{Key=>Value},IfExist,Config);
error -> do_format(Level,Data,Else,Config)
end,
[String|do_format(Level,Data,Format,Config)];
do_format(Level,Data,[Key|Format],Config)
when is_atom(Key) orelse
(is_list(Key) andalso is_atom(hd(Key))) ->
String =
case value(Key,Data) of
{ok,Value} -> to_string(Key,Value,Config);
error -> ""
end,
[String|do_format(Level,Data,Format,Config)];
do_format(Level,Data,[Str|Format],Config) ->
[Str|do_format(Level,Data,Format,Config)];
do_format(_Level,_Data,[],_Config) ->
[].
value(Key,Meta) when is_map_key(Key,Meta) ->
{ok,maps:get(Key,Meta)};
value([Key|Keys],Meta) when is_map_key(Key,Meta) ->
value(Keys,maps:get(Key,Meta));
value([],Value) ->
{ok,Value};
value(_,_) ->
error.
to_string(time,Time,Config) ->
format_time(Time,Config);
to_string(mfa,MFA,Config) ->
format_mfa(MFA,Config);
to_string(_,Value,Config) ->
to_string(Value,Config).
to_string(X,_) when is_atom(X) ->
atom_to_list(X);
to_string(X,_) when is_integer(X) ->
integer_to_list(X);
to_string(X,_) when is_pid(X) ->
pid_to_list(X);
to_string(X,_) when is_reference(X) ->
ref_to_list(X);
to_string(X,_) when is_list(X) ->
case printable_list(lists:flatten(X)) of
true -> X;
_ -> io_lib:format(?FormatP,[X])
end;
to_string(X,_) ->
io_lib:format(?FormatP,[X]).
printable_list([]) ->
false;
printable_list(X) ->
io_lib:printable_list(X).
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) ->
try Fun(Report) of
{Format,Args} when is_list(Format), is_list(Args) ->
format_msg({Format,Args},maps:remove(report_cb,Meta),Config);
Other ->
format_msg({"REPORT_CB/1 ERROR: ~0tp; Returned: ~0tp",
[Report,Other]},Meta,Config)
catch C:R:S ->
format_msg({"REPORT_CB/1 CRASH: ~0tp; Reason: ~0tp",
[Report,{C,R,logger:filter_stacktrace(?MODULE,S)}]},Meta,Config)
end;
format_msg({report,Report},#{report_cb:=Fun}=Meta,Config) when is_function(Fun,2) ->
try Fun(Report,maps:with([depth,chars_limit,single_line],Config)) of
Chardata when ?IS_STRING(Chardata) ->
try chardata_to_list(Chardata) % already size limited by report_cb
catch _:_ ->
format_msg({"REPORT_CB/2 ERROR: ~0tp; Returned: ~0tp",
[Report,Chardata]},Meta,Config)
end;
Other ->
format_msg({"REPORT_CB/2 ERROR: ~0tp; Returned: ~0tp",
[Report,Other]},Meta,Config)
catch C:R:S ->
format_msg({"REPORT_CB/2 CRASH: ~0tp; Reason: ~0tp",
[Report,{C,R,logger:filter_stacktrace(?MODULE,S)}]},
Meta,Config)
end;
format_msg({report,Report},Meta,Config) ->
format_msg({report,Report},
Meta#{report_cb=>fun logger:format_report/1},
Config);
format_msg(Msg,_Meta,#{depth:=Depth,chars_limit:=CharsLimit}) ->
Opts = chars_limit_to_opts(CharsLimit),
do_format_msg(Msg, Depth, Opts).
chars_limit_to_opts(unlimited) -> [];
chars_limit_to_opts(CharsLimit) -> [{chars_limit,CharsLimit}].
do_format_msg({Format0,Args},Depth,Opts) ->
try
Format1 = io_lib:scan_format(Format0, Args),
Format = reformat(Format1, Depth),
io_lib:build_text(Format,Opts)
catch C:R:S ->
FormatError = "FORMAT ERROR: ~0tp - ~0tp",
case Format0 of
FormatError ->
%% already been here - avoid failing cyclically
erlang:raise(C,R,S);
_ ->
do_format_msg({FormatError,[Format0,Args]},Depth,Opts)
end
end.
reformat(Format,unlimited) ->
Format;
reformat([#{control_char:=C}=M|T], Depth) when C =:= $p ->
[limit_depth(M#{width => 0}, Depth)|reformat(T, Depth)];
reformat([#{control_char:=C}=M|T], Depth) when C =:= $P ->
[M#{width => 0}|reformat(T, Depth)];
reformat([#{control_char:=C}=M|T], Depth) when C =:= $p; C =:= $w ->
[limit_depth(M, Depth)|reformat(T, Depth)];
reformat([H|T], Depth) ->
[H|reformat(T, Depth)];
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]}.
chardata_to_list(Chardata) ->
case unicode:characters_to_list(Chardata,unicode) of
List when is_list(List) ->
List;
Error ->
throw(Error)
end.
truncate(String,unlimited) ->
String;
truncate(String,Size) ->
Length = string:length(String),
if Length>Size ->
case lists:reverse(lists:flatten(String)) of
[$\n|_] ->
string:slice(String,0,Size-4)++"...\n";
_ ->
string:slice(String,0,Size-3)++"..."
end;
true ->
String
end.
%% Convert microseconds-timestamp into local datatime string in milliseconds
format_time(SysTime,#{})
when is_integer(SysTime) ->
Ms = SysTime rem 1000000 div 1000,
{Date, _Time = {H, Mi, S}} = calendar:system_time_to_local_time(SysTime, microsecond),
format_time({Date, {H, Mi, S, Ms}}).
format_time({{Y, M, D}, {H, Mi, S, Ms}}) ->
io_lib:format("~b-~2..0b-~2..0b ~2..0b:~2..0b:~2..0b.~3..0b", [Y, M, D, H, Mi, S, Ms]).
format_mfa({M,F,A},_) when is_atom(M), is_atom(F), is_integer(A) ->
atom_to_list(M)++":"++atom_to_list(F)++"/"++integer_to_list(A);
format_mfa({M,F,A},Config) when is_atom(M), is_atom(F), is_list(A) ->
format_mfa({M,F,length(A)},Config);
format_mfa(MFA,Config) ->
to_string(MFA,Config).
%% Ensure that all valid configuration parameters exist in the final
%% configuration map
add_default_config(Config0) ->
Default =
#{chars_limit=>unlimited,
error_logger_notice_header=>info},
MaxSize = get_max_size(maps:get(max_size,Config0,undefined)),
Depth = get_depth(maps:get(depth,Config0,undefined)),
add_default_template(maps:merge(Default,Config0#{max_size=>MaxSize,
depth=>Depth})).
add_default_template(#{template:=_}=Config) ->
Config;
add_default_template(Config) ->
Config#{template=>?DEFAULT_FORMAT_TEMPLATE_SINGLE}.
get_max_size(undefined) ->
unlimited;
get_max_size(S) ->
max(10,S).
get_depth(undefined) ->
error_logger:get_format_depth();
get_depth(S) ->
max(5,S).
-spec check_config(Config) -> ok | {error,term()} when
Config :: config().
check_config(Config) when is_map(Config) ->
do_check_config(maps:to_list(Config));
check_config(Config) ->
{error,{invalid_formatter_config,?MODULE,Config}}.
do_check_config([{Type,L}|Config]) when Type == chars_limit;
Type == depth;
Type == max_size ->
case check_limit(L) of
ok -> do_check_config(Config);
error -> {error,{invalid_formatter_config,?MODULE,{Type,L}}}
end;
do_check_config([{error_logger_notice_header,ELNH}|Config]) when ELNH == info;
ELNH == notice ->
do_check_config(Config);
do_check_config([{report_cb,RCB}|Config]) when is_function(RCB,1);
is_function(RCB,2) ->
do_check_config(Config);
do_check_config([{template,T}|Config]) ->
case check_template(T) of
ok -> do_check_config(Config);
error -> {error,{invalid_formatter_template,?MODULE,T}}
end;
do_check_config([C|_]) ->
{error,{invalid_formatter_config,?MODULE,C}};
do_check_config([]) ->
ok.
check_limit(L) when is_integer(L), L>0 ->
ok;
check_limit(unlimited) ->
ok;
check_limit(_) ->
error.
check_template([Key|T]) when is_atom(Key) ->
check_template(T);
check_template([Key|T]) when is_list(Key), is_atom(hd(Key)) ->
case lists:all(fun(X) when is_atom(X) -> true;
(_) -> false
end,
Key) of
true ->
check_template(T);
false ->
error
end;
check_template([{Key,IfExist,Else}|T])
when is_atom(Key) orelse
(is_list(Key) andalso is_atom(hd(Key))) ->
case check_template(IfExist) of
ok ->
case check_template(Else) of
ok ->
check_template(T);
error ->
error
end;
error ->
error
end;
check_template([Str|T]) when is_list(Str) ->
case io_lib:printable_unicode_list(Str) of
true -> check_template(T);
false -> error
end;
check_template([]) ->
ok;
check_template(_) ->
error.

View File

@ -31,7 +31,7 @@
-type(trace_who() :: {clientid | topic, binary()}).
-define(TRACER, ?MODULE).
-define(FORMAT, {emqx_logger_formatter,
-define(FORMAT, {logger_formatter,
#{template =>
[time, " [", level, "] ",
{clientid,
@ -41,7 +41,9 @@
[{peername,
[peername, " "],
[]}]},
msg, "\n"]}}).
msg, "\n"],
single_line => true
}}).
-define(TOPIC_TRACE_ID(T), "trace_topic_"++T).
-define(CLIENT_TRACE_ID(C), "trace_clientid_"++C).
-define(TOPIC_TRACE(T), {topic, T}).

View File

@ -1,657 +0,0 @@
%%
%% %CopyrightBegin%
%%
%% Copyright Ericsson AB 2018. 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.
%%
%% %CopyrightEnd%
%%
-module(emqx_logger_formatter_SUITE).
-compile(export_all).
-compile(nowarn_export_all).
-include_lib("eunit/include/eunit.hrl").
-include_lib("common_test/include/ct.hrl").
-include_lib("kernel/include/logger.hrl").
-define(TRY(X), my_try(fun() -> X end)).
suite() ->
[{timetrap,{seconds,30}}].
init_per_suite(Config) ->
Config.
end_per_suite(_Config) ->
ok.
init_per_group(_Group, Config) ->
Config.
end_per_group(_Group, _Config) ->
ok.
init_per_testcase(_TestCase, Config) ->
Config.
end_per_testcase(Case, Config) ->
try apply(?MODULE,Case,[cleanup,Config])
catch error:undef -> ok
end,
ok.
groups() ->
[].
all() ->
[default,
single_line,
template,
format_msg,
report_cb,
max_size,
depth,
chars_limit,
format_mfa,
level_or_msg_in_meta,
faulty_log,
faulty_config,
faulty_msg,
check_config,
update_config].
default(_Config) ->
String1 = format(info,{"~p",[term]},#{},#{}),
ct:log(String1),
?assertMatch([_Date, _Time,"info:","term\n"], string:lexemes(String1," ")),
Time = timestamp(),
ExpectedTimestamp = default_time_format(Time),
String2 = format(info,{"~p",[term]},#{time=>Time},#{}),
ct:log("ExpectedTimestamp: ~p, got: ~p", [ExpectedTimestamp, String2]),
" info: term\n" = string:prefix(String2,ExpectedTimestamp),
ok.
single_line(_Config) ->
Time = timestamp(),
ExpectedTimestamp = default_time_format(Time),
String1 = format(info,{"~p",[term]},#{time=>Time},#{}),
ct:log(String1),
?assertMatch(" info: term\n", string:prefix(String1,ExpectedTimestamp)),
String2 = format(info,{"a:~n~p",[term]},#{time=>Time},#{}),
ct:log(String2),
?assertMatch(" info: a:\nterm\n", string:prefix(String2,ExpectedTimestamp)),
Prefix =
"Some characters to fill the line ------------------------------------- ",
%% There would actually be newlines inside the
%% list and map.
String4 = format(info,{"~s~p~n~s~p~n",[Prefix,
lists:seq(1,10),
Prefix,
#{a=>map,with=>a,few=>accociations}]},
#{time=>Time},
#{}),
ct:log(String4),
match = re:run(String4,"\\[1,2,3,\n",[global,{capture,none}]),
{match,Match4} = re:run(String4,"=>\n",[global,{capture,all}]),
3 = length(Match4),
%% Test that big metadata fields do not get line breaks
String5 = format(info,"",
#{mymeta=>lists:seq(1,100)},
#{template=>[mymeta,"\n"]}),
ct:log(String5),
[_] = string:lexemes(String5,"\n"),
ok.
template(_Config) ->
Time = timestamp(),
Template1 = [msg],
String1 = format(info,{"~p",[term]},#{time=>Time},#{template=>Template1}),
ct:log(String1),
"term" = String1,
Template2 = [msg,unknown],
String2 = format(info,{"~p",[term]},#{time=>Time},#{template=>Template2}),
ct:log(String2),
"term" = String2,
Template3 = ["string"],
String3 = format(info,{"~p",[term]},#{time=>Time},#{template=>Template3}),
ct:log(String3),
"string" = String3,
Template4 = ["string\nnewline"],
String4 = format(info,{"~p",[term]},#{time=>Time},#{template=>Template4}),
ct:log(String4),
"string\nnewline" = String4,
Template5 = [],
String5 = format(info,{"~p",[term]},#{time=>Time},#{template=>Template5}),
ct:log(String5),
"" = String5,
Ref6 = erlang:make_ref(),
Meta6 = #{atom=>some_atom,
integer=>632,
list=>[list,"string",4321,#{},{tuple}],
mfa=>{mod,func,0},
pid=>self(),
ref=>Ref6,
string=>"some string",
time=>Time,
tuple=>{1,atom,"list"},
nested=>#{subkey=>subvalue}},
Template6 = lists:join(";",lists:sort(maps:keys(maps:remove(nested,Meta6))) ++
[[nested,subkey]]),
String6 = format(info,{"~p",[term]},Meta6,#{template=>Template6}),
ct:log(String6),
SelfStr = pid_to_list(self()),
RefStr6 = ref_to_list(Ref6),
ListStr = "[list,\"string\",4321,#{},{tuple}]",
ExpectedTime6 = default_time_format(Time),
["some_atom",
"632",
ListStr,
"mod:func/0",
SelfStr,
RefStr6,
"some string",
ExpectedTime6,
"{1,atom,\"list\"}",
"subvalue"] = string:lexemes(String6,";"),
Meta7 = #{time=>Time,
nested=>#{key1=>#{subkey1=>value1},
key2=>value2}},
Template7 = lists:join(";",[nested,
[nested,key1],
[nested,key1,subkey1],
[nested,key2],
[nested,key2,subkey2],
[nested,key3],
[nested,key3,subkey3]]),
String7 = format(info,{"~p",[term]},Meta7,#{template=>Template7}),
ct:log(String7),
[MultipleKeysStr7,
"#{subkey1 => value1}",
"value1",
"value2",
"",
"",
""] = string:split(String7,";",all),
%% Order of keys is not fixed
case MultipleKeysStr7 of
"#{key2 => value2,key1 => #{subkey1 => value1}}" -> ok;
"#{key1 => #{subkey1 => value1},key2 => value2}" -> ok;
_ -> ct:fail({full_nested_map_unexpected,MultipleKeysStr7})
end,
Meta8 = #{time=>Time,
nested=>#{key1=>#{subkey1=>value1},
key2=>value2}},
Template8 =
lists:join(
";",
[{nested,["exist:",nested],["noexist"]},
{[nested,key1],["exist:",[nested,key1]],["noexist"]},
{[nested,key1,subkey1],["exist:",[nested,key1,subkey1]],["noexist"]},
{[nested,key2],["exist:",[nested,key2]],["noexist"]},
{[nested,key2,subkey2],["exist:",[nested,key2,subkey2]],["noexist"]},
{[nested,key3],["exist:",[nested,key3]],["noexist"]},
{[nested,key3,subkey3],["exist:",[nested,key3,subkey3]],["noexist"]}]),
String8 = format(info,{"~p",[term]},Meta8,#{template=>Template8}),
ct:log(String8),
[MultipleKeysStr8,
"exist:#{subkey1 => value1}",
"exist:value1",
"exist:value2",
"noexist",
"noexist",
"noexist"] = string:split(String8,";",all),
%% Order of keys is not fixed
case MultipleKeysStr8 of
"exist:#{key2 => value2,key1 => #{subkey1 => value1}}" -> ok;
"exist:#{key1 => #{subkey1 => value1},key2 => value2}" -> ok;
_ -> ct:fail({full_nested_map_unexpected,MultipleKeysStr8})
end,
ok.
format_msg(_Config) ->
Template = [msg],
String1 = format(info,{"~p",[term]},#{},#{template=>Template}),
ct:log(String1),
"term" = String1,
String2 = format(info,{"list",[term]},#{},#{template=>Template}),
ct:log(String2),
"FORMAT ERROR: \"list\" - [term]" = String2,
String3 = format(info,{report,term},#{},#{template=>Template}),
ct:log(String3),
"term" = String3,
String4 = format(info,{report,term},
#{report_cb=>fun(_)-> {"formatted",[]} end},
#{template=>Template}),
ct:log(String4),
"formatted" = String4,
String5 = format(info,{report,term},
#{report_cb=>fun(_)-> faulty_return end},
#{template=>Template}),
ct:log(String5),
"REPORT_CB/1 ERROR: term; Returned: faulty_return" = String5,
String6 = format(info,{report,term},
#{report_cb=>fun(_)-> erlang:error(fun_crashed) end},
#{template=>Template}),
ct:log(String6),
"REPORT_CB/1 CRASH: term; Reason: {error,fun_crashed,"++_ = String6,
String7 = format(info,{report,term},
#{report_cb=>fun(_,_)-> ['not',a,string] end},
#{template=>Template}),
ct:log(String7),
"REPORT_CB/2 ERROR: term; Returned: ['not',a,string]" = String7,
String8 = format(info,{report,term},
#{report_cb=>fun(_,_)-> faulty_return end},
#{template=>Template}),
ct:log(String8),
"REPORT_CB/2 ERROR: term; Returned: faulty_return" = String8,
String9 = format(info,{report,term},
#{report_cb=>fun(_,_)-> erlang:error(fun_crashed) end},
#{template=>Template}),
ct:log(String9),
"REPORT_CB/2 CRASH: term; Reason: {error,fun_crashed,"++_ = String9,
%% strings are not formatted
String10 = format(info,{string,"string"},
#{report_cb=>fun(_)-> {"formatted",[]} end},
#{template=>Template}),
ct:log(String10),
"string" = String10,
String11 = format(info,{string,['not',printable,list]},
#{report_cb=>fun(_)-> {"formatted",[]} end},
#{template=>Template}),
ct:log("~ts",[String11]), % avoiding ct_log crash
"FORMAT ERROR: \"~ts\" - [['not',printable,list]]" = String11,
String12 = format(info,{string,"string"},#{},#{template=>Template}),
ct:log(String12),
"string" = String12,
ok.
report_cb(_Config) ->
Template = [msg],
MetaFun = fun(_) -> {"meta_rcb",[]} end,
ConfigFun = fun(_) -> {"config_rcb",[]} end,
"term" = format(info,{report,term},#{},#{template=>Template}),
"meta_rcb" =
format(info,{report,term},#{report_cb=>MetaFun},#{template=>Template}),
"config_rcb" =
format(info,{report,term},#{},#{template=>Template,
report_cb=>ConfigFun}),
"config_rcb" =
format(info,{report,term},#{report_cb=>MetaFun},#{template=>Template,
report_cb=>ConfigFun}),
ok.
max_size(_Config) ->
Cfg = #{template=>[msg]},
"12345678901234567890" = format(info,{"12345678901234567890",[]},#{},Cfg),
%% application:set_env(kernel,logger_max_size,11),
%% "12345678901234567890" = % min value is 50, so this is not limited
%% format(info,{"12345678901234567890",[]},#{},Cfg),
%% "12345678901234567890123456789012345678901234567..." = % 50
%% format(info,
%% {"123456789012345678901234567890123456789012345678901234567890",
%% []},
%% #{},
%% Cfg),
%% application:set_env(kernel,logger_max_size,53),
%% "12345678901234567890123456789012345678901234567890..." = %53
%% format(info,
%% {"123456789012345678901234567890123456789012345678901234567890",
%% []},
%% #{},
%% Cfg),
"123456789012..." =
format(info,{"12345678901234567890",[]},#{},Cfg#{max_size=>15}),
"12345678901234567890" =
format(info,{"12345678901234567890",[]},#{},Cfg#{max_size=>unlimited}),
%% Check that one newline at the end of the line is kept (if it exists)
"12345678901...\n" =
format(info,{"12345678901234567890\n",[]},#{},Cfg#{max_size=>15}),
"12345678901...\n" =
format(info,{"12345678901234567890",[]},#{},Cfg#{template=>[msg,"\n"],
max_size=>15}),
ok.
max_size(cleanup,_Config) ->
application:unset_env(kernel,logger_max_size),
ok.
depth(_Config) ->
Template = [msg],
"[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]" =
format(info,
{"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]},
#{},
#{template=>Template}),
application:set_env(kernel,error_logger_format_depth,11),
"[1,2,3,4,5,6,7,8,9,0|...]" =
format(info,
{"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]},
#{},
#{template=>Template}),
"[1,2,3,4,5,6,7,8,9,0,1,2|...]" =
format(info,
{"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]},
#{},
#{template=>Template,
depth=>13}),
"[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]" =
format(info,
{"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]},
#{},
#{template=>Template,
depth=>unlimited}),
ok.
depth(cleanup,_Config) ->
application:unset_env(kernel,error_logger_format_depth),
ok.
chars_limit(_Config) ->
FA = {"LoL: ~p~nL: ~p~nMap: ~p~n",
[lists:duplicate(10,lists:seq(1,100)),
lists:seq(1,100),
maps:from_list(lists:zip(lists:seq(1,100),
lists:duplicate(100,value)))]},
Meta = #{time=>timestamp()},
Template = [time," - ", msg, "\n"],
FC = #{template=>Template,
depth=>unlimited,
max_size=>unlimited,
chars_limit=>unlimited},
CL1 = 80,
String1 = format(info,FA,Meta,FC#{chars_limit=>CL1}),
L1 = string:length(String1),
ct:log("String1: ~p~nLength1: ~p~n",[lists:flatten(String1),L1]),
true = L1 > CL1,
true = L1 < CL1 + 15,
String2 = format(info,FA,Meta,FC#{chars_limit=>CL1,depth=>10}),
L2 = string:length(String2),
ct:log("String2: ~p~nLength2: ~p~n",[lists:flatten(String2),L2]),
String2 = String1,
CL3 = 200,
String3 = format(info,FA,Meta,FC#{chars_limit=>CL3}),
L3 = string:length(String3),
ct:log("String3: ~p~nLength3: ~p~n",[lists:flatten(String3),L3]),
true = L3 > CL3,
true = L3 < CL3 + 15,
String4 = format(info,FA,Meta,FC#{chars_limit=>CL3,depth=>10}),
L4 = string:length(String4),
ct:log("String4: ~p~nLength4: ~p~n",[lists:flatten(String4),L4]),
true = L4 > CL3,
true = L4 < CL3 + 15,
%% Test that max_size truncates the string which is limited by
%% depth and chars_limit
MS5 = 150,
String5 = format(info,FA,Meta,FC#{chars_limit=>CL3,depth=>10,max_size=>MS5}),
L5 = string:length(String5),
ct:log("String5: ~p~nLength5: ~p~n",[String5,L5]),
L5 = MS5,
true = lists:prefix(lists:sublist(String5,L5-4),String4),
%% Test that chars_limit limits string also
Str = "123456789012345678901234567890123456789012345678901234567890123456789",
CL6 = 80,
String6 = format(info,{string,Str},Meta,FC#{chars_limit=>CL6}),
L6 = string:length(String6),
ct:log("String6: ~p~nLength6: ~p~n",[String6,L6]),
L6 = CL6,
ok.
format_mfa(_Config) ->
Template = [mfa],
Meta1 = #{mfa=>{mod,func,0}},
String1 = format(info,{"~p",[term]},Meta1,#{template=>Template}),
ct:log(String1),
"mod:func/0" = String1,
Meta2 = #{mfa=>{mod,func,[]}},
String2 = format(info,{"~p",[term]},Meta2,#{template=>Template}),
ct:log(String2),
"mod:func/0" = String2,
Meta3 = #{mfa=>"mod:func/0"},
String3 = format(info,{"~p",[term]},Meta3,#{template=>Template}),
ct:log(String3),
"mod:func/0" = String3,
Meta4 = #{mfa=>othermfa},
String4 = format(info,{"~p",[term]},Meta4,#{template=>Template}),
ct:log(String4),
"othermfa" = String4,
ok.
level_or_msg_in_meta(_Config) ->
%% The template contains atoms to pick out values from meta,
%% or level/msg to add these from the log event. What if you have
%% a key named 'level' or 'msg' in meta and want to display
%% its value?
%% For now we simply ignore Meta on this and display the
%% actual level and msg from the log event.
Meta = #{level=>mylevel,
msg=>"metamsg"},
Template = [level,";",msg],
String = format(info,{"~p",[term]},Meta,#{template=>Template}),
ct:log(String),
"info;term" = String, % so mylevel and "metamsg" are ignored
ok.
faulty_log(_Config) ->
%% Unexpected log (should be type logger:log_event()) - print error
{error,
function_clause,
{emqx_logger_formatter,format,[_,_],_}} =
?TRY(emqx_logger_formatter:format(unexp_log,#{})),
ok.
faulty_config(_Config) ->
{error,
function_clause,
{emqx_logger_formatter,format,[_,_],_}} =
?TRY(emqx_logger_formatter:format(#{level=>info,
msg=>{"~p",[term]},
meta=>#{time=>timestamp()}},
unexp_config)),
ok.
faulty_msg(_Config) ->
{error,
function_clause,
{emqx_logger_formatter,_,_,_}} =
?TRY(emqx_logger_formatter:format(#{level=>info,
msg=>term,
meta=>#{time=>timestamp()}},
#{})),
ok.
-define(cfgerr(X), {error,{invalid_formatter_config,emqx_logger_formatter,X}}).
check_config(_Config) ->
ok = emqx_logger_formatter:check_config(#{}),
?cfgerr(bad) = emqx_logger_formatter:check_config(bad),
C1 = #{chars_limit => 1,
depth => 1,
max_size => 1,
report_cb => fun(R) -> {"~p",[R]} end,
template => []},
ok = emqx_logger_formatter:check_config(C1),
ok = emqx_logger_formatter:check_config(#{chars_limit => unlimited}),
?cfgerr({chars_limit,bad}) =
emqx_logger_formatter:check_config(#{chars_limit => bad}),
ok = emqx_logger_formatter:check_config(#{depth => unlimited}),
?cfgerr({depth,bad}) =
emqx_logger_formatter:check_config(#{depth => bad}),
ok = emqx_logger_formatter:check_config(#{max_size => unlimited}),
?cfgerr({max_size,bad}) =
emqx_logger_formatter:check_config(#{max_size => bad}),
ok =
emqx_logger_formatter:check_config(#{report_cb => fun(_,_) -> "" end}),
?cfgerr({report_cb,F}) =
emqx_logger_formatter:check_config(#{report_cb => F=fun(_,_,_) -> {"",[]} end}),
?cfgerr({report_cb,bad}) =
emqx_logger_formatter:check_config(#{report_cb => bad}),
Ts = [[key],
[[key1,key2]],
[{key,[key],[]}],
[{[key1,key2],[[key1,key2]],["noexist"]}],
["string"]],
[begin
ct:log("check template: ~p",[T]),
ok = emqx_logger_formatter:check_config(#{template => T})
end
|| T <- Ts],
ETs = [bad,
[{key,bad}],
[{key,[key],bad}],
[{key,[key],"bad"}],
"bad",
[[key,$a,$b,$c]],
[[$a,$b,$c,key]]],
[begin
ct:log("check template: ~p",[T]),
{error,{invalid_formatter_template,emqx_logger_formatter,T}} =
emqx_logger_formatter:check_config(#{template => T})
end
|| T <- ETs],
ok.
%% Test that formatter config can be changed, and that the default
%% template is updated accordingly
update_config(_Config) ->
#{level := OldLevel} = logger:get_primary_config(),
logger:set_primary_config(level, debug),
{error,{not_found,?MODULE}} = logger:update_formatter_config(?MODULE,#{}),
logger:add_handler_filter(default,silence,{fun(_,_) -> stop end,ok}),
ok = logger:add_handler(?MODULE,?MODULE,#{formatter => {emqx_logger_formatter, #{chars_limit => unlimited}},
config => #{type => standard_io}}),
D = lists:seq(1,1000),
logger:notice("~p~n",[D]),
{Lines1,C1} = check_log(),
ct:log("lines1: ~p", [Lines1]),
ct:log("c1: ~p",[C1]),
[Line1 | _] = Lines1,
[_Date, WithOutDate1] = string:split(Line1," "),
[_, "notice: "++D1] = string:split(WithOutDate1," "),
?assert(length(D1)<1000),
?assertMatch(#{chars_limit := unlimited}, C1),
error_logger:error_msg("~p",[D]),
{Lines5,C5} = check_log(),
ct:log("Lines5: ~p", [Lines5]),
ct:log("c5: ~p",[C5]),
[Line5 | _] = Lines5,
[_Date, WithOutDate5] = string:split(Line5," "),
[_, "error: "++_D5] = string:split(WithOutDate5," "),
?assertMatch({error,{invalid_formatter_config,bad}},
logger:update_formatter_config(?MODULE,bad)),
?assertMatch({error,{invalid_formatter_config,emqx_logger_formatter,{depth,bad}}},
logger:update_formatter_config(?MODULE,depth,bad)),
logger:set_primary_config(level, OldLevel),
ok.
update_config(cleanup,_Config) ->
_ = logger:remove_handler(?MODULE),
_ = logger:remove_handler_filter(default,silence),
ok.
%%%-----------------------------------------------------------------
%%% Internal
format(Level,Msg,Meta,Config) ->
format(#{level=>Level,msg=>Msg,meta=>add_time(Meta)},Config).
format(Log,Config) ->
lists:flatten(emqx_logger_formatter:format(Log,Config)).
default_time_format(SysTime) when is_integer(SysTime) ->
Ms = SysTime rem 1000000 div 1000,
{Date, _Time = {H, Mi, S}} = calendar:system_time_to_local_time(SysTime, microsecond),
default_time_format({Date, {H, Mi, S, Ms}});
default_time_format({{Y, M, D}, {H, Mi, S, Ms}}) ->
io_lib:format("~b-~2..0b-~2..0b ~2..0b:~2..0b:~2..0b.~3..0b", [Y, M, D, H, Mi, S, Ms]);
default_time_format({{Y, M, D}, {H, Mi, S}}) ->
io_lib:format("~b-~2..0b-~2..0b ~2..0b:~2..0b:~2..0b", [Y, M, D, H, Mi, S]).
integer(Str) ->
is_integer(list_to_integer(Str)).
integer(Str,Max) ->
integer(Str,0,Max).
integer(Str,Min,Max) ->
Int = list_to_integer(Str),
Int >= Min andalso Int =<Max.
%%%-----------------------------------------------------------------
%%% Called by macro ?TRY(X)
my_try(Fun) ->
try Fun() catch C:R:S -> {C,R,hd(S)} end.
timestamp() ->
erlang:system_time(microsecond).
%% necessary?
add_time(#{time:=_}=Meta) ->
Meta;
add_time(Meta) ->
Meta#{time=>timestamp()}.
%%%-----------------------------------------------------------------
%%% handler callback
log(Log,#{formatter:={M,C}}) ->
put(log,{M:format(Log,C),C}),
ok.
check_log() ->
{S,C} = erase(log),
{string:lexemes(S,"\n"),C}.