diff options
Diffstat (limited to 'lib/kernel/test/logger_formatter_SUITE.erl')
| -rw-r--r-- | lib/kernel/test/logger_formatter_SUITE.erl | 252 |
1 files changed, 169 insertions, 83 deletions
diff --git a/lib/kernel/test/logger_formatter_SUITE.erl b/lib/kernel/test/logger_formatter_SUITE.erl index ac1abba629..7a93f2ca79 100644 --- a/lib/kernel/test/logger_formatter_SUITE.erl +++ b/lib/kernel/test/logger_formatter_SUITE.erl @@ -68,23 +68,25 @@ all() -> level_or_msg_in_meta, faulty_log, faulty_config, - faulty_msg]. + faulty_msg, + update_config]. default(_Config) -> String1 = format(info,{"~p",[term]},#{},#{}), ct:log(String1), - [_Date,_Time,"info:\nterm\n"] = string:lexemes(String1," "), + [_DateTime,"info:","term\n"] = string:lexemes(String1," "), Time = timestamp(), ExpectedTimestamp = default_time_format(Time), String2 = format(info,{"~p",[term]},#{time=>Time},#{}), ct:log(String2), - " info:\nterm\n" = string:prefix(String2,ExpectedTimestamp), + " info: term\n" = string:prefix(String2,ExpectedTimestamp), ok. legacy_header(_Config) -> Time = timestamp(), - String1 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>true}), + String1 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>true, + single_line=>false}), ct:log(String1), "=INFO REPORT==== "++Rest = String1, [Timestamp,"\nterm\n"] = string:lexemes(Rest," ="), @@ -98,12 +100,14 @@ legacy_header(_Config) -> true = lists:member(M,["Jan","Feb","Mar","Apr","May","Jun", "Jul","Aug","Sep","Oct","Nov","Dec"]), - String2 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>false}), + String2 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>false, + single_line=>false}), ct:log(String2), ExpectedTimestamp = default_time_format(Time), " info:\nterm\n" = string:prefix(String2,ExpectedTimestamp), - String3 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>bad}), + String3 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>bad, + single_line=>false}), ct:log(String3), String3 = String2, @@ -114,7 +118,8 @@ legacy_header(_Config) -> String4 = String1, String5 = format(info,{"~p",[term]},#{}, % <--- no time - #{legacy_header=>true}), + #{legacy_header=>true, + single_line=>false}), ct:log(String5), "=INFO REPORT==== "++_ = String5, ok. @@ -264,8 +269,8 @@ format_msg(_Config) -> String8 = format(info,{string,['not',printable,list]}, #{report_cb=>fun(_)-> {"formatted",[]} end}, #{template=>Template}), - ct:log(String8), - "INVALID STRING: ['not',printable,list]" = String8, + ct:log("~ts",[String8]), % avoiding ct_log crash + "FORMAT ERROR: \"~ts\" - [['not',printable,list]]" = String8, String9 = format(info,{string,"string"},#{},#{template=>Template}), ct:log(String9), @@ -289,38 +294,36 @@ report_cb(_Config) -> ok. max_size(_Config) -> - Template = [msg], + Cfg = #{template=>[msg], + single_line=>false}, "12345678901234567890" = - format(info,{"12345678901234567890",[]},#{},#{template=>Template}), - application:set_env(kernel,logger_max_size,11), - "12345678901234567890" = % min value is 50, so this is not limited - format(info,{"12345678901234567890",[]},#{},#{template=>Template}), - "12345678901234567890123456789012345678901234567..." = % 50 - format(info, - {"123456789012345678901234567890123456789012345678901234567890", - []}, - #{}, - #{template=>Template}), - application:set_env(kernel,logger_max_size,53), - "12345678901234567890123456789012345678901234567890..." = %53 - format(info, - {"123456789012345678901234567890123456789012345678901234567890", - []}, - #{}, - #{template=>Template}), + 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",[]},#{},#{template=>Template, - max_size=>15}), + format(info,{"12345678901234567890",[]},#{},Cfg#{max_size=>15}), "12345678901234567890" = - format(info,{"12345678901234567890",[]},#{},#{template=>Template, - max_size=>unlimited}), + 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",[]},#{},#{template=>Template, - max_size=>15}), + format(info,{"12345678901234567890\n",[]},#{},Cfg#{max_size=>15}), "12345678901...\n" = - format(info,{"12345678901234567890",[]},#{},#{template=>[msg,"\n"], - max_size=>15}), + format(info,{"12345678901234567890",[]},#{},Cfg#{template=>[msg,"\n"], + max_size=>15}), ok. max_size(cleanup,_Config) -> application:unset_env(kernel,logger_max_size), @@ -339,12 +342,6 @@ depth(_Config) -> {"~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,logger_format_depth,12), - "[1,2,3,4,5,6,7,8,9,0,1|...]" = - 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]]}, @@ -359,7 +356,7 @@ depth(_Config) -> depth=>unlimited}), ok. depth(cleanup,_Config) -> - application:unset_env(kernel,logger_format_depth), + application:unset_env(kernel,error_logger_format_depth), ok. chars_limit(_Config) -> @@ -368,7 +365,7 @@ chars_limit(_Config) -> lists:seq(1,100), maps:from_list(lists:zip(lists:seq(1,100), lists:duplicate(100,value)))]}, - Meta = #{time=>"2018-04-26 9:15:40.449879"}, + Meta = #{time=>timestamp()}, Template = [time," - ", msg, "\n"], FC = #{template=>Template, depth=>unlimited, @@ -380,7 +377,7 @@ chars_limit(_Config) -> L1 = string:length(String1), ct:log("String1: ~p~nLength1: ~p~n",[lists:flatten(String1),L1]), true = L1 > CL1, - true = L1 < CL1 + 10, + true = L1 < CL1 + 15, String2 = format(info,FA,Meta,FC#{chars_limit=>CL1,depth=>10}), L2 = string:length(String2), @@ -392,13 +389,13 @@ chars_limit(_Config) -> L3 = string:length(String3), ct:log("String3: ~p~nLength3: ~p~n",[lists:flatten(String3),L3]), true = L3 > CL3, - true = L3 < CL3 + 10, + 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 + 10, + true = L4 < CL3 + 15, %% Test that max_size truncates the string which is limited by %% depth and chars_limit @@ -409,6 +406,14 @@ chars_limit(_Config) -> 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) -> @@ -437,29 +442,58 @@ format_mfa(_Config) -> ok. format_time(_Config) -> - Time1 = timestamp(), - ExpectedTimestamp1 = default_time_format(Time1), - String1 = format(info,{"~p",[term]},#{time=>Time1},#{}), - ct:log(String1), - " info:\nterm\n" = string:prefix(String1,ExpectedTimestamp1), - - Time2 = timestamp(), - ExpectedTimestamp2 = default_time_format(Time2,true), - String2 = format(info,{"~p",[term]},#{time=>Time2},#{utc=>true}), - ct:log(String2), - " info:\nterm\n" = string:prefix(String2,ExpectedTimestamp2), - - application:set_env(kernel,logger_utc,true), - Time3 = timestamp(), - ExpectedTimestamp3 = default_time_format(Time3,true), - String3 = format(info,{"~p",[term]},#{time=>Time3},#{}), - ct:log(String3), - " info:\nterm\n" = string:prefix(String3,ExpectedTimestamp3), + Time = timestamp(), + Meta = #{time=>Time}, + FC = #{template=>[time]}, + Msg = {string,""}, + ExpectedLocal = default_time_format(Time,false), + ExpectedUtc = default_time_format(Time,true), + + %% default - local time + ExpectedLocal = format(info,Msg,Meta,FC), + + %% time_offset config parameter to formatter + ExpectedLocal = format(info,Msg,Meta,FC#{time_offset=>""}), + ExpectedUtc = format(info,Msg,Meta,FC#{time_offset=>"Z"}), + + %% stdlib utc_log works when time_offset parameter is not set + application:set_env(stdlib,utc_log,true), + ExpectedUtc = format(info,Msg,Meta,FC), + + %% sasl utc_log overwrites stdlib utc_log + application:set_env(sasl,utc_log,false), + ExpectedLocal = format(info,Msg,Meta,FC), + + %% sasl utc_log overwrites stdlib utc_log + application:set_env(sasl,utc_log,true), + application:set_env(stdlib,utc_log,false), + ExpectedUtc = format(info,Msg,Meta,FC), + + %% time_offset config parameter to formatter + %% overwrites sasl and stdlib utc_log + application:set_env(sasl,utc_log,false), + ExpectedUtc = format(info,Msg,Meta,FC#{time_offset=>"Z"}), + + %% time_offset config parameter to formatter + %% overwrites sasl and stdlib utc_log + application:set_env(sasl,utc_log,true), + application:set_env(stdlib,utc_log,true), + ExpectedLocal = format(info,Msg,Meta,FC#{time_offset=>""}), + + %% time_designator config parameter to formatter + ExpectedLocalS = default_time_format(Time,false,$\s), + ExpectedUtcS = default_time_format(Time,true,$\s), + + ExpectedLocalS = format(info,Msg,Meta,FC#{time_offset=>"", + time_designator=>$\s}), + ExpectedUtcS = format(info,Msg,Meta,FC#{time_offset=>"Z", + time_designator=>$\s}), ok. format_time(cleanup,_Config) -> - application:unset_env(kernel,logger_utc), + application:unset_env(sasl,utc_log), + application:unset_env(stdlib,utc_log), ok. level_or_msg_in_meta(_Config) -> @@ -480,7 +514,7 @@ level_or_msg_in_meta(_Config) -> ok. faulty_log(_Config) -> - %% Unexpected log (should be type logger:log()) - print error + %% Unexpected log (should be type logger:log_event()) - print error {error, function_clause, {logger_formatter,format,[_,_],_}} = @@ -507,6 +541,54 @@ faulty_msg(_Config) -> #{})), ok. +%% Test that formatter config can be changed, and that the default +%% template is updated accordingly +update_config(_Config) -> + logger:add_handler_filter(default,silence,{fun(_,_) -> stop end,ok}), + ok = logger:add_handler(?MODULE,?MODULE,#{}), + D = lists:seq(1,1000), + logger:info("~p~n",[D]), + {Lines1,C1} = check_log(), + [ct:log(L) || L <- Lines1], + ct:log("~p",[C1]), + [Line1] = Lines1, + [_Time,"info: "++D1] = string:split(Line1," "), + true = length(D1)>3000, + true = #{}==C1, + + ok = logger:update_formatter_config(?MODULE,single_line,false), + logger:info("~p~n",[D]), + {Lines2,C2} = check_log(), + [ct:log(L) || L <- Lines2], + ct:log("~p",[C2]), + true = length(Lines2)>50, + true = #{single_line=>false}==C2, + + ok = logger:update_formatter_config(?MODULE,#{legacy_header=>true}), + logger:info("~p~n",[D]), + {Lines3,C3} = check_log(), + [ct:log(L) || L <- Lines3], + ct:log("~p",[C3]), + ["=INFO REPORT==== "++_|D3] = Lines3, + true = length(D3)>50, + true = #{legacy_header=>true,single_line=>false}==C3, + + ok = logger:update_formatter_config(?MODULE,single_line,true), + logger:info("~p~n",[D]), + {Lines4,C4} = check_log(), + [ct:log(L) || L <- Lines4], + ct:log("~p",[C4]), + ["=INFO REPORT==== "++_,D4] = Lines4, + true = length(D4)>3000, + true = #{legacy_header=>true,single_line=>true}==C4, + + ok. + +update_config(cleanup,_Config) -> + _ = logger:remove_handler(?MODULE), + _ = logger:remove_handler_filter(default,silence), + ok. + %%%----------------------------------------------------------------- %%% Internal format(Level,Msg,Meta,Config) -> @@ -518,22 +600,16 @@ format(Log,Config) -> default_time_format(Timestamp) -> default_time_format(Timestamp,false). -default_time_format(Timestamp0,Utc) when is_integer(Timestamp0) -> - Timestamp=Timestamp0+erlang:time_offset(microsecond), - %% calendar:system_time_to_rfc3339(Time,[{unit,microsecond}]). - Micro = Timestamp rem 1000000, - Sec = Timestamp div 1000000, - UniversalTime = erlang:posixtime_to_universaltime(Sec), - {Date,Time} = - if Utc -> UniversalTime; - true -> erlang:universaltime_to_localtime(UniversalTime) - end, - default_time_format(Date,Time,Micro). - -default_time_format({Y,M,D},{H,Min,S},Micro) -> - lists:flatten( - io_lib:format("~4w-~2..0w-~2..0w ~2w:~2..0w:~2..0w.~6..0w", - [Y,M,D,H,Min,S,Micro])). +default_time_format(Timestamp,Utc) -> + default_time_format(Timestamp,Utc,$T). + +default_time_format(Timestamp,Utc,Sep) -> + Offset = if Utc -> "Z"; + true -> "" + end, + calendar:system_time_to_rfc3339(Timestamp,[{unit,microsecond}, + {time_designator,Sep}, + {offset,Offset}]). integer(Str) -> is_integer(list_to_integer(Str)). @@ -549,10 +625,20 @@ my_try(Fun) -> try Fun() catch C:R:S -> {C,R,hd(S)} end. timestamp() -> - erlang:monotonic_time(microsecond). + 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}. |