From 0afab64f105c09976c7c07a64f54bf962ff9a18f Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Wed, 16 May 2018 14:12:23 +0200 Subject: Format logger timestamps according to RFC3339 --- lib/kernel/doc/src/logger_formatter.xml | 53 +++++++++--- lib/kernel/src/logger_formatter.erl | 125 +++++++++++++++++++--------- lib/kernel/test/error_logger_warn_SUITE.erl | 14 +++- lib/kernel/test/logger_SUITE.erl | 41 +++++++-- lib/kernel/test/logger_formatter_SUITE.erl | 102 ++++++++++++++--------- lib/sasl/doc/src/sasl_app.xml | 12 +-- 6 files changed, 243 insertions(+), 104 deletions(-) diff --git a/lib/kernel/doc/src/logger_formatter.xml b/lib/kernel/doc/src/logger_formatter.xml index 5f13e54365..370d61d338 100644 --- a/lib/kernel/doc/src/logger_formatter.xml +++ b/lib/kernel/doc/src/logger_formatter.xml @@ -155,11 +155,40 @@ and single_line. See Default Templates for more information

- utc = boolean() + time_designator = byte() -

If set to true, all dates are displayed in Universal - Coordinated Time.

-

Default is false.

+

Timestamps are formatted according to RFC3339, and the time + designator is the character used as date and time + separator.

+

Default is $T.

+

The value of this parameter is used as + the time_designator option + to + calendar:system_time_to_rcf3339/2.

+ + time_offset = integer() | [byte()] + +

The time offset, either a string or an integer, to be + used when formatting the timestamp.

+

An empty string is interpreted as local time. The + values "Z", "z" or 0 are interpreted as + Universal Coordinated Time (UTC).

+

Strings, other than "Z", "z", or "", + must be on the form ±[hh]:[mm], for + example "-02:00" or "+00:00".

+

Integers must be in microseconds, meaning that the + offset 7200000000 is equivalent + to "+02:00".

+

The default value is an empty string, meaning that + timestamps are displayed in local time. However, for + backwards compatibility, if the SASL environment + variable + utc_log=true, the default is + changed to "Z", meaning that timestamps are displayed + in UTC.

+

The value of this parameter is used as the offset + option to + calendar:system_time_to_rcf3339/2.

 @@ -174,7 +203,7 @@

The log event used in the examples is:

-?LOG_ERROR("name: ~p~nexit_reason: ~p",[my_reg_name,"It crashed"]) +?LOG_ERROR("name: ~p~nexit_reason: ~p",[my_name,"It crashed"]) legacy_header=true @@ -182,9 +211,9 @@

Default template: [{logger_formatter,header},"\n",msg,"\n"]

Example log entry:

- -=ERROR REPORT==== 29-Dec-2017::13:30:51.245123 === -name: my_reg_name + +2018-05-16T11:55:50.448382+02:00 error: +name: my_name exit_reason: "It crashed"

Notice that all eight levels might occur in the heading, @@ -198,7 +227,7 @@ exit_reason: "It crashed"

Default template: [time," ",level,": ",msg,"\n"]

Example log entry:

- 2017-12-29 13:31:49.640317 error: name: my_reg_name, exit_reason: "It crashed" + 2018-05-16T11:55:50.448382+02:00 error: name: my_name, exit_reason: "It crashed" legacy_header=false, single_line=false @@ -206,9 +235,9 @@ exit_reason: "It crashed"

Default template: [time," ",level,":\n",msg,"\n"]

Example log entry:

- -2017-12-29 13:32:25.191925 error: -name: my_reg_name + +2018-05-16T11:55:50.448382+02:00 error: +name: my_name exit_reason: "It crashed" diff --git a/lib/kernel/src/logger_formatter.erl b/lib/kernel/src/logger_formatter.erl index 0d55244034..602c666cc7 100644 --- a/lib/kernel/src/logger_formatter.erl +++ b/lib/kernel/src/logger_formatter.erl @@ -39,7 +39,8 @@ max_size=>pos_integer() | unlimited, depth=>pos_integer() | unlimited, template=>template(), - utc=>boolean()}. + time_designator=>byte(), + time_offset=>integer()|[byte()]}. format(#{level:=Level,msg:=Msg0,meta:=Meta},Config0) when is_map(Config0) -> Config = add_default_config(Config0), @@ -196,16 +197,12 @@ truncate(String,Size) -> String end. -format_time(Timestamp,Config) when is_integer(Timestamp) -> - {Date,Time,Micro} = timestamp_to_datetimemicro(Timestamp,Config), - format_time(Date,Time,Micro); -format_time(Other,_Config) -> - %% E.g. a string - to_string(Other). - -format_time({Y,M,D},{H,Min,S},Micro) -> - io_lib:format("~4w-~2..0w-~2..0w ~2w:~2..0w:~2..0w.~6..0w", - [Y,M,D,H,Min,S,Micro]). +format_time(Timestamp,#{time_offset:=Offset,time_designator:=Des}) + when is_integer(Timestamp) -> + SysTime = Timestamp + erlang:time_offset(microsecond), + calendar:system_time_to_rfc3339(SysTime,[{unit,microsecond}, + {offset,Offset}, + {time_designator,Des}]). %% Assuming this is monotonic time in microseconds timestamp_to_datetimemicro(Timestamp,Config) when is_integer(Timestamp) -> @@ -213,12 +210,12 @@ timestamp_to_datetimemicro(Timestamp,Config) when is_integer(Timestamp) -> Micro = SysTime rem 1000000, Sec = SysTime div 1000000, UniversalTime = erlang:posixtime_to_universaltime(Sec), - {Date,Time} = - case Config of - #{utc:=true} -> UniversalTime; - _ -> erlang:universaltime_to_localtime(UniversalTime) + {{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}. + {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); @@ -231,9 +228,11 @@ maybe_add_legacy_header(Level, #{time:=Timestamp}=Meta, #{legacy_header:=true}=Config) -> #{title:=Title}=MyMeta = add_legacy_title(Level,maps:get(?MODULE,Meta,#{})), - {{Y,Mo,D},{H,Mi,S},Micro} = 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(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. @@ -257,20 +256,20 @@ month(10) -> "Oct"; month(11) -> "Nov"; month(12) -> "Dec". -utcstr(#{utc:=true}) -> "UTC "; -utcstr(_) -> "". - +%% Ensure that all valid configuration parameters exist in the final +%% configuration map add_default_config(Config0) -> Default = #{legacy_header=>false, single_line=>true, - chars_limit=>unlimited}, - MaxSize = get_max_size(maps:get(max_size,Config0,false)), - Depth = get_depth(maps:get(depth,Config0,false)), - Utc = get_utc(maps:get(utc,Config0,false)), + chars_limit=>unlimited, + 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, - utc=>Utc})). + time_offset=>Offset})). add_default_template(#{template:=_}=Config) -> Config; @@ -284,33 +283,50 @@ default_template(#{single_line:=true}) -> default_template(_) -> ?DEFAULT_FORMAT_TEMPLATE. -get_max_size(false) -> +get_max_size(undefined) -> unlimited; get_max_size(S) -> max(10,S). -get_depth(false) -> +get_depth(undefined) -> error_logger:get_format_depth(); get_depth(S) -> max(5,S). -get_utc(false) -> - get_utc_config(); -get_utc(U) -> - U. +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} -> Val; - undefined -> + {ok, Val} when is_boolean(Val) -> Val; + _ -> case application:get_env(stdlib, utc_log) of - {ok, Val} -> Val; - undefined -> false + {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. + check_config(Config) when is_map(Config) -> do_check_config(maps:to_list(Config)); check_config(Config) -> @@ -341,8 +357,20 @@ do_check_config([{template,T}|Config]) when is_list(T) -> false -> {error,{invalid_formatter_template,?MODULE,T}} end; -do_check_config([{utc,Utc}|Config]) when is_boolean(Utc) -> - do_check_config(Config); +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([]) -> @@ -354,3 +382,22 @@ check_limit(unlimited) -> ok; check_limit(_) -> 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. diff --git a/lib/kernel/test/error_logger_warn_SUITE.erl b/lib/kernel/test/error_logger_warn_SUITE.erl index a8087e11f9..ef55a2d339 100644 --- a/lib/kernel/test/error_logger_warn_SUITE.erl +++ b/lib/kernel/test/error_logger_warn_SUITE.erl @@ -480,9 +480,12 @@ rb_utc() -> UtcLog=case application:get_env(sasl,utc_log) of {ok,true} -> true; - _AllOthers -> + {ok,false} -> application:set_env(sasl,utc_log,true), - false + false; + undefined -> + application:set_env(sasl,utc_log,true), + undefined end, application:start(sasl), rb:start([{report_dir, rd()}]), @@ -494,7 +497,12 @@ rb_utc() -> Sum=one_rb_findstr([],"UTC"), rb:stop(), application:stop(sasl), - application:set_env(sasl,utc_log,UtcLog), + case UtcLog of + undefined -> + application:unset_env(sasl,utc_log); + _ -> + application:set_env(sasl,utc_log,UtcLog) + end, stop_node(Node), ok. diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl index 64968cbca2..e602fa2576 100644 --- a/lib/kernel/test/logger_SUITE.erl +++ b/lib/kernel/test/logger_SUITE.erl @@ -580,11 +580,6 @@ config_sanity_check(_Config) -> #{report_cb=>fun(R) -> {"~p",[R]} end}}), - {error,{invalid_formatter_config,logger_formatter,{utc,bad}}} = - logger:set_handler_config(h1,formatter,{logger_formatter, - #{utc=>bad}}), - ok = logger:set_handler_config(h1,formatter,{logger_formatter, - #{utc=>true}}), {error,{invalid_formatter_config,logger_formatter,{chars_limit,bad}}} = logger:set_handler_config(h1,formatter,{logger_formatter, #{chars_limit=>bad}}), @@ -610,6 +605,42 @@ config_sanity_check(_Config) -> {error,{callback_crashed,{error,{badmatch,3},[{?MODULE,check_config,1,_}]}}} = logger:set_handler_config(h1,formatter,{?MODULE,crash}), ok = logger:set_handler_config(h1,custom,custom), + + %% Old utc parameter is no longer allowed (replaced by time_offset) + {error,{invalid_formatter_config,logger_formatter,{utc,true}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{utc=>true}}), + {error,{invalid_formatter_config,logger_formatter,{time_offset,bad}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>bad}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>0}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>""}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>"Z"}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>"z"}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>"-0:0"}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>"+10:13"}}), + + {error,{invalid_formatter_config,logger_formatter,{time_offset,"+0"}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>"+0"}}), + + {error,{invalid_formatter_config,logger_formatter,{time_designator,bad}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_designator=>bad}}), + {error,{invalid_formatter_config,logger_formatter,{time_designator,"s"}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_designator=>"s"}}), + {error,{invalid_formatter_config,logger_formatter,{time_designator,0}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_designator=>0}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_designator=>$\s}}), ok. config_sanity_check(cleanup,_Config) -> diff --git a/lib/kernel/test/logger_formatter_SUITE.erl b/lib/kernel/test/logger_formatter_SUITE.erl index bd5bc2d2e4..9baadfd65a 100644 --- a/lib/kernel/test/logger_formatter_SUITE.erl +++ b/lib/kernel/test/logger_formatter_SUITE.erl @@ -73,7 +73,7 @@ all() -> default(_Config) -> String1 = format(info,{"~p",[term]},#{},#{}), ct:log(String1), - [_Date,_Time,"info:","term\n"] = string:lexemes(String1," "), + [_DateTime,"info:","term\n"] = string:lexemes(String1," "), Time = timestamp(), ExpectedTimestamp = default_time_format(Time), @@ -364,7 +364,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, @@ -376,7 +376,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), @@ -388,13 +388,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 @@ -433,29 +433,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: term\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: term\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: term\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) -> @@ -514,22 +543,17 @@ format(Log,Config) -> default_time_format(Timestamp) -> default_time_format(Timestamp,false). -default_time_format(Timestamp0,Utc) when is_integer(Timestamp0) -> +default_time_format(Timestamp,Utc) -> + default_time_format(Timestamp,Utc,$T). + +default_time_format(Timestamp0,Utc,Sep) -> 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])). + 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)). diff --git a/lib/sasl/doc/src/sasl_app.xml b/lib/sasl/doc/src/sasl_app.xml index 8f92a22cf7..26b9bece2a 100644 --- a/lib/sasl/doc/src/sasl_app.xml +++ b/lib/sasl/doc/src/sasl_app.xml @@ -86,12 +86,6 @@ RELDIR is used. By default, this is $OTP_ROOT/releases.

- - -

If set to true, all dates in textual log outputs are - displayed in Universal Coordinated Time with the string - UTC appended.

- @@ -175,6 +169,12 @@ sasl_error_logger to error reports or progress reports, or both. Default is all.

+ + +

If set to true, all dates in textual log outputs are + displayed in Universal Coordinated Time with the string + UTC appended.

+

The error logger event handler log_mf_h can also still -- cgit v1.2.3