%% %% %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(logger_formatter_SUITE). -compile(export_all). -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, legacy_header, error_logger_notice_header, single_line, template, format_msg, report_cb, max_size, depth, chars_limit, format_mfa, format_time, 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), [_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: term\n" = string:prefix(String2,ExpectedTimestamp), ok. legacy_header(_Config) -> Time = timestamp(), 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," ="), [D,M,Y,H,Min,S,Micro] = string:lexemes(Timestamp,"-:."), integer(D,31), integer(Y,2018,infinity), integer(H,23), integer(Min,59), integer(S,59), integer(Micro,999999), 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, 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, single_line=>false}), ct:log(String3), String3 = String2, String4 = format(info,{"~p",[term]},#{time=>Time}, #{legacy_header=>true, single_line=>true}), % <---ignored ct:log(String4), String4 = String1, String5 = format(info,{"~p",[term]},#{}, % <--- no time #{legacy_header=>true, single_line=>false}), ct:log(String5), "=INFO REPORT==== "++_ = String5, ok. error_logger_notice_header(_Config) -> Meta1 = #{error_logger=>#{tag => info_report,type => std_info}}, String1 = format(notice,{"~p",[term]},Meta1, #{legacy_header=>true, error_logger_notice_header=>notice}), ct:log(String1), "=NOTICE REPORT==== "++_ = String1, String2 = format(notice,{"~p",[term]},Meta1, #{legacy_header=>true, error_logger_notice_header=>info}), ct:log(String2), "=INFO REPORT==== "++_ = String2, String3 = format(notice,{"~p",[term]},#{}, #{legacy_header=>true, error_logger_notice_header=>notice}), ct:log(String3), "=NOTICE REPORT==== "++_ = String3, String4 = format(notice,{"~p",[term]},#{}, #{legacy_header=>true, error_logger_notice_header=>info}), ct:log(String4), "=NOTICE REPORT==== "++_ = String4, ok. single_line(_Config) -> Time = timestamp(), ExpectedTimestamp = default_time_format(Time), String1 = format(info,{"~p",[term]},#{time=>Time},#{single_line=>true}), ct:log(String1), " info: term\n" = string:prefix(String1,ExpectedTimestamp), String2 = format(info,{"~p",[term]},#{time=>Time},#{single_line=>false}), ct:log(String2), " info:\nterm\n" = string:prefix(String2,ExpectedTimestamp), String2 = format(info,{"~p",[term]},#{time=>Time},#{single_line=>bad}), %% Test that no extra commas/spaces are added when removing %% newlines, especially not after "=>" in a map association (as %% was the case in OTP-21.0, when the only single_line adjustment %% was done by regexp replacement of "\n" by ", "). Prefix = "Some characters to fill the line ------------------------------------- ", String3 = format(info,{"~s~p~n~s~p~n",[Prefix, lists:seq(1,10), Prefix, #{a=>map,with=>a,few=>accociations}]}, #{time=>Time}, #{single_line=>true}), ct:log(String3), match = re:run(String3,"\\[1,2,3,4,5,6,7,8,9,10\\]",[{capture,none}]), match = re:run(String3, "#{a => map,few => accociations,with => a}", [{capture,none}]), %% This part is added to make sure that the previous test made %% sense, i.e. that 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}, #{single_line=>false}), 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)}, #{single_line=>true,template=>[mymeta,"\n"]}), ct:log(String5), [_] = string:lexemes(String5,"\n"), %% Ensure that the previous test made sense, i.e. that the %% metadata field does produce multiple lines if %% single_line==false. String6 = format(info,"", #{mymeta=>lists:seq(1,100)}, #{single_line=>false,template=>[mymeta,"\n"]}), ct:log(String6), [_,_|_] = string:lexemes(String6,"\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, single_line=>true}), 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, single_line=>true}), 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, single_line=>true}), 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, single_line=>true}), 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], single_line=>false}, "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, single_line=>true}, 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. format_time(_Config) -> 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(sasl,utc_log), application:unset_env(stdlib,utc_log), 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, {logger_formatter,format,[_,_],_}} = ?TRY(logger_formatter:format(unexp_log,#{})), ok. faulty_config(_Config) -> {error, function_clause, {logger_formatter,format,[_,_],_}} = ?TRY(logger_formatter:format(#{level=>info, msg=>{"~p",[term]}, meta=>#{time=>timestamp()}}, unexp_config)), ok. faulty_msg(_Config) -> {error, function_clause, {logger_formatter,_,_,_}} = ?TRY(logger_formatter:format(#{level=>info, msg=>term, meta=>#{time=>timestamp()}}, #{})), ok. -define(cfgerr(X), {error,{invalid_formatter_config,logger_formatter,X}}). check_config(_Config) -> ok = logger_formatter:check_config(#{}), ?cfgerr(bad) = logger_formatter:check_config(bad), C1 = #{chars_limit => 1, depth => 1, legacy_header => true, error_logger_notice_header => info, max_size => 1, report_cb => fun(R) -> {"~p",[R]} end, single_line => false, template => [], time_designator => $T, time_offset => 0}, ok = logger_formatter:check_config(C1), ok = logger_formatter:check_config(#{chars_limit => unlimited}), ?cfgerr({chars_limit,bad}) = logger_formatter:check_config(#{chars_limit => bad}), ok = logger_formatter:check_config(#{depth => unlimited}), ?cfgerr({depth,bad}) = logger_formatter:check_config(#{depth => bad}), ok = logger_formatter:check_config(#{legacy_header => false}), ?cfgerr({legacy_header,bad}) = logger_formatter:check_config(#{legacy_header => bad}), ok = logger_formatter:check_config(#{error_logger_notice_header => notice}), ?cfgerr({error_logger_notice_header,bad}) = logger_formatter:check_config(#{error_logger_notice_header => bad}), ok = logger_formatter:check_config(#{max_size => unlimited}), ?cfgerr({max_size,bad}) = logger_formatter:check_config(#{max_size => bad}), ok = logger_formatter:check_config(#{report_cb => fun(_,_) -> "" end}), ?cfgerr({report_cb,F}) = logger_formatter:check_config(#{report_cb => F=fun(_,_,_) -> {"",[]} end}), ?cfgerr({report_cb,bad}) = logger_formatter:check_config(#{report_cb => bad}), ok = logger_formatter:check_config(#{single_line => true}), ?cfgerr({single_line,bad}) = logger_formatter:check_config(#{single_line => bad}), Ts = [[key], [[key1,key2]], [{key,[key],[]}], [{[key1,key2],[[key1,key2]],["noexist"]}], ["string"]], [begin ct:log("check template: ~p",[T]), ok = 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,logger_formatter,T}} = logger_formatter:check_config(#{template => T}) end || T <- ETs], ?cfgerr({time_designator,bad}) = logger_formatter:check_config(#{time_designator => bad}), ?cfgerr({time_designator,"b"}) = logger_formatter:check_config(#{time_designator => "b"}), ok = logger_formatter:check_config(#{time_offset => -1}), ok = logger_formatter:check_config(#{time_offset => "+02:00"}), ok = logger_formatter:check_config(#{time_offset => "-23:59"}), ok = logger_formatter:check_config(#{time_offset => "+24:00"}), ok = logger_formatter:check_config(#{time_offset => "-25:00"}), ?cfgerr({time_offset,bad}) = logger_formatter:check_config(#{time_offset => bad}), ?cfgerr({time_offset,"02:00"}) = logger_formatter:check_config(#{time_offset => "02:00"}), ?cfgerr({time_offset,"+02"}) = logger_formatter:check_config(#{time_offset => "+02"}), 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:notice("~p~n",[D]), {Lines1,C1} = check_log(), [ct:log(L) || L <- Lines1], ct:log("~p",[C1]), [Line1] = Lines1, [_Time,"notice: "++D1] = string:split(Line1," "), true = length(D1)>3000, true = #{}==C1, ok = logger:update_formatter_config(?MODULE,single_line,false), logger:notice("~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:notice("~p~n",[D]), {Lines3,C3} = check_log(), [ct:log(L) || L <- Lines3], ct:log("~p",[C3]), ["=NOTICE 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:notice("~p~n",[D]), {Lines4,C4} = check_log(), [ct:log(L) || L <- Lines4], ct:log("~p",[C4]), ["=NOTICE REPORT==== "++_,D4] = Lines4, true = length(D4)>3000, true = #{legacy_header=>true,single_line=>true}==C4, %% Finally, check that error_logger_notice_header works, default=info error_logger:info_msg("~p",[D]), {Lines5,C5} = check_log(), [ct:log(L) || L <- Lines5], ct:log("~p",[C5]), ["=INFO REPORT==== "++_,_D5] = Lines5, ok=logger:update_formatter_config(?MODULE,error_logger_notice_header,notice), error_logger:info_msg("~p",[D]), {Lines6,C6} = check_log(), [ct:log(L) || L <- Lines6], ct:log("~p",[C6]), ["=NOTICE REPORT==== "++_,_D6] = Lines6, 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(logger_formatter:format(Log,Config)). default_time_format(Timestamp) -> default_time_format(Timestamp,false). 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)). 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}.