%% %% %CopyrightBegin% %% %% Copyright Ericsson AB 2017-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). -export([format/2]). -export([check_config/1]). -include("logger_internal.hrl"). %%%----------------------------------------------------------------- %%% Types -type config() :: #{chars_limit => pos_integer() | unlimited, depth => pos_integer() | unlimited, legacy_header => boolean(), max_size => pos_integer() | unlimited, report_cb => logger:report_cb(), single_line => boolean(), template => template(), time_designator => byte(), time_offset => integer() | [byte()]}. -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), Meta1 = maybe_add_legacy_header(Level,Meta,Config), 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,Meta1,BT,Config), A = do_format(Level,Meta1,AT,Config), MsgStr = if DoMsg -> Config1 = case maps:get(chars_limit,Config) of unlimited -> Config; Size0 -> Size = case Size0 - io_lib:chars_length([B,A]) of S when S>=0 -> S; _ -> 0 end, Config#{chars_limit=>Size} end, MsgStr0 = format_msg(Msg0,Meta1,Config1), case maps:get(single_line,Config) of true -> %% Trim leading and trailing whitespaces, and replace %% newlines with ", " T = lists:reverse( trim( lists:reverse( trim(MsgStr0,false)),true)), re:replace(T,",?\r?\n\s*",", ", [{return,list},global,unicode]); _false -> MsgStr0 end; true -> "" end, truncate(B,MsgStr,A,maps:get(max_size,Config)). trim([H|T],Rev) when H==$\s; H==$\r; H==$\n -> trim(T,Rev); trim([H|T],false) when is_list(H) -> case trim(H,false) of [] -> trim(T,false); TrimmedH -> [TrimmedH|T] end; trim([H|T],true) when is_list(H) -> case trim(lists:reverse(H),true) of [] -> trim(T,true); TrimmedH -> [lists:reverse(TrimmedH)|T] end; trim(String,_) -> String. 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,Config) when is_list(X) -> case printable_list(lists:flatten(X)) of true -> X; _ -> io_lib:format(p(Config),[X]) end; to_string(X,Config) -> io_lib:format(p(Config),[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 -> P = p(Config), format_msg({"REPORT_CB/1 ERROR: "++P++"; Returned: "++P, [Report,Other]},Meta,Config) catch C:R:S -> P = p(Config), format_msg({"REPORT_CB/1 CRASH: "++P++"; Reason: "++P, [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 _:_ -> P = p(Config), format_msg({"REPORT_CB/2 ERROR: "++P++"; Returned: "++P, [Report,Chardata]},Meta,Config) end; Other -> P = p(Config), format_msg({"REPORT_CB/2 ERROR: "++P++"; Returned: "++P, [Report,Other]},Meta,Config) catch C:R:S -> P = p(Config), format_msg({"REPORT_CB/2 CRASH: "++P++"; Reason: "++P, [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, single_line:=Single}) -> Opts = chars_limit_to_opts(CharsLimit), format_msg(Msg, Depth, Opts, Single). chars_limit_to_opts(unlimited) -> []; chars_limit_to_opts(CharsLimit) -> [{chars_limit,CharsLimit}]. format_msg({Format0,Args},Depth,Opts,Single) -> try Format1 = io_lib:scan_format(Format0, Args), Format = reformat(Format1, Depth, Single), io_lib:build_text(Format,Opts) catch C:R:S -> P = p(Single), FormatError = "FORMAT ERROR: "++P++" - "++P, case Format0 of FormatError -> %% already been here - avoid failing cyclically erlang:raise(C,R,S); _ -> format_msg({FormatError,[Format0,Args]},Depth,Opts,Single) end end. reformat(Format,unlimited,false) -> Format; reformat([#{control_char:=C}=M|T], Depth, true) when C =:= $p -> [limit_depth(M#{width => 0}, Depth)|reformat(T, Depth, true)]; reformat([#{control_char:=C}=M|T], Depth, true) when C =:= $P -> [M#{width => 0}|reformat(T, Depth, true)]; reformat([#{control_char:=C}=M|T], Depth, Single) when C =:= $p; C =:= $w -> [limit_depth(M, Depth)|reformat(T, Depth, Single)]; reformat([H|T], Depth, Single) -> [H|reformat(T, Depth, Single)]; reformat([], _, _) -> []. limit_depth(M0, unlimited) -> M0; limit_depth(#{control_char:=C0, args:=Args}=M0, Depth) -> C = C0 - ($a - $A), %To uppercase. M0#{control_char:=C,args:=Args++[Depth]}. chardata_to_list(Chardata) -> case unicode:characters_to_list(Chardata,unicode) of List when is_list(List) -> List; Error -> throw(Error) end. truncate(B,Msg,A,unlimited) -> [B,Msg,A]; truncate(B,Msg,A,Size) -> String = [B,Msg,A], Length = io_lib:chars_length(String), if Length>Size -> {Last,FlatString} = case A of [] -> case Msg of [] -> {get_last(B),lists:flatten(B)}; _ -> {get_last(Msg),lists:flatten([B,Msg])} end; _ -> {get_last(A),lists:flatten(String)} end, case Last of $\n-> lists:sublist(FlatString,1,Size-4)++"...\n"; _ -> lists:sublist(FlatString,1,Size-3)++"..." end; true -> String end. get_last(L) -> get_first(lists:reverse(L)). get_first([]) -> error; get_first([C|_]) when is_integer(C) -> C; get_first([L|Rest]) when is_list(L) -> case get_last(L) of error -> get_first(Rest); First -> First end. %% SysTime is the system time in microseconds format_time(SysTime,#{time_offset:=Offset,time_designator:=Des}) when is_integer(SysTime) -> calendar:system_time_to_rfc3339(SysTime,[{unit,microsecond}, {offset,Offset}, {time_designator,Des}]). %% SysTime is the system time in microseconds timestamp_to_datetimemicro(SysTime,Config) when is_integer(SysTime) -> Micro = SysTime rem 1000000, Sec = SysTime div 1000000, UniversalTime = erlang:posixtime_to_universaltime(Sec), {{Date,Time},UtcStr} = case offset_to_utc(maps:get(time_offset,Config)) of true -> {UniversalTime,"UTC "}; _ -> {erlang:universaltime_to_localtime(UniversalTime),""} end, {Date,Time,Micro,UtcStr}. 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). maybe_add_legacy_header(Level, #{time:=Timestamp}=Meta, #{legacy_header:=true}=Config) -> #{title:=Title}=MyMeta = add_legacy_title(Level,Meta,Config), {{Y,Mo,D},{H,Mi,S},Micro,UtcStr} = timestamp_to_datetimemicro(Timestamp,Config), Header = io_lib:format("=~ts==== ~w-~s-~4w::~2..0w:~2..0w:~2..0w.~6..0w ~s===", [Title,D,month(Mo),Y,H,Mi,S,Micro,UtcStr]), Meta#{?MODULE=>MyMeta#{header=>Header}}; maybe_add_legacy_header(_,Meta,_) -> Meta. add_legacy_title(_Level,#{?MODULE:=#{title:=_}=MyMeta},_) -> MyMeta; add_legacy_title(Level,Meta,Config) -> case maps:get(?MODULE,Meta,#{}) of #{title:=_}=MyMeta -> MyMeta; MyMeta -> TitleLevel = case (Level=:=notice andalso maps:find(error_logger,Meta)) of {ok,_} -> maps:get(error_logger_notice_header,Config); _ -> Level end, Title = string:uppercase(atom_to_list(TitleLevel)) ++ " REPORT", MyMeta#{title=>Title} end. month(1) -> "Jan"; month(2) -> "Feb"; month(3) -> "Mar"; month(4) -> "Apr"; month(5) -> "May"; month(6) -> "Jun"; month(7) -> "Jul"; month(8) -> "Aug"; month(9) -> "Sep"; month(10) -> "Oct"; month(11) -> "Nov"; month(12) -> "Dec". %% 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, legacy_header=>false, single_line=>true, time_designator=>$T}, MaxSize = get_max_size(maps:get(max_size,Config0,undefined)), Depth = get_depth(maps:get(depth,Config0,undefined)), Offset = get_offset(maps:get(time_offset,Config0,undefined)), add_default_template(maps:merge(Default,Config0#{max_size=>MaxSize, depth=>Depth, time_offset=>Offset})). add_default_template(#{template:=_}=Config) -> Config; add_default_template(Config) -> Config#{template=>default_template(Config)}. default_template(#{legacy_header:=true}) -> ?DEFAULT_FORMAT_TEMPLATE_HEADER; default_template(#{single_line:=true}) -> ?DEFAULT_FORMAT_TEMPLATE_SINGLE; default_template(_) -> ?DEFAULT_FORMAT_TEMPLATE. 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). get_offset(undefined) -> utc_to_offset(get_utc_config()); get_offset(Offset) -> Offset. utc_to_offset(true) -> "Z"; utc_to_offset(false) -> "". get_utc_config() -> %% SASL utc_log overrides stdlib config - in order to have uniform %% timestamps in log messages case application:get_env(sasl, utc_log) of {ok, Val} when is_boolean(Val) -> Val; _ -> case application:get_env(stdlib, utc_log) of {ok, Val} when is_boolean(Val) -> Val; _ -> false end end. offset_to_utc(Z) when Z=:=0; Z=:="z"; Z=:="Z" -> true; offset_to_utc([$+|Tz]) -> case io_lib:fread("~d:~d", Tz) of {ok, [0, 0], []} -> true; _ -> false end; offset_to_utc(_) -> false. -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([{single_line,SL}|Config]) when is_boolean(SL) -> do_check_config(Config); do_check_config([{legacy_header,LH}|Config]) when is_boolean(LH) -> do_check_config(Config); 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([{time_offset,Offset}|Config]) -> case check_offset(Offset) of ok -> do_check_config(Config); error -> {error,{invalid_formatter_config,?MODULE,{time_offset,Offset}}} end; do_check_config([{time_designator,Char}|Config]) when Char>=0, Char=<255 -> case io_lib:printable_latin1_list([Char]) of true -> do_check_config(Config); false -> {error,{invalid_formatter_config,?MODULE,{time_designator,Char}}} 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. check_offset(I) when is_integer(I) -> ok; check_offset(Tz) when Tz=:=""; Tz=:="Z"; Tz=:="z" -> ok; check_offset([Sign|Tz]) when Sign=:=$+; Sign=:=$- -> check_timezone(Tz); check_offset(_) -> error. check_timezone(Tz) -> try io_lib:fread("~d:~d", Tz) of {ok, [_, _], []} -> ok; _ -> error catch _:_ -> error end. p(#{single_line:=Single}) -> p(Single); p(true) -> "~0tp"; p(false) -> "~tp".