diff --git a/etc/emqx.conf b/etc/emqx.conf index 308f59153..03c203321 100644 --- a/etc/emqx.conf +++ b/etc/emqx.conf @@ -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. diff --git a/priv/emqx.schema b/priv/emqx.schema index e5176ca56..d26b14e79 100644 --- a/priv/emqx.schema +++ b/priv/emqx.schema @@ -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}}; diff --git a/src/emqx_logger_formatter.erl b/src/emqx_logger_formatter.erl deleted file mode 100644 index 2528a63b5..000000000 --- a/src/emqx_logger_formatter.erl +++ /dev/null @@ -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. diff --git a/src/emqx_tracer.erl b/src/emqx_tracer.erl index ef7e73a8d..02f735a75 100644 --- a/src/emqx_tracer.erl +++ b/src/emqx_tracer.erl @@ -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}). diff --git a/test/emqx_logger_formatter_SUITE.erl b/test/emqx_logger_formatter_SUITE.erl deleted file mode 100644 index 3d7469dca..000000000 --- a/test/emqx_logger_formatter_SUITE.erl +++ /dev/null @@ -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 = - 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}.