feat(log): rfc3339 date-time format in logs

e.g. default: 2021-04-09T22:53:50.183617+02:00

etc/emqx.conf

@@ -425,6 +425,13 @@ log.to = file
 ## Default: warning
 log.level = warning
 
+## Timezone offset to display in logs
+## Value:
+##  - "system" use system zone
+##  - "utc" for Universal Coordinated Time (UTC)
+##  - "+hh:mm" or "-hh:mm" for a specified offset
+log.time_offset = system
+
 ## The dir for log files.
 ##
 ## Value: Folder

priv/emqx.schema

@@ -465,6 +465,15 @@ end}.
   {datatype, {enum, [debug, info, notice, warning, error, critical, alert, emergency, all]}}
 ]}.
 
+%% @doc Timezone offset to display in logs,
+%% "system" use system time zone
+%% "utc" for Universal Coordinated Time (UTC)
+%% "+hh:mm" or "-hh:mm" for a specified offset
+{mapping, "log.time_offset", "kernel.logger", [
+  {default, "system"},
+  {datatype, string}
+]}.
+
 {mapping, "log.primary_log_level", "kernel.logger_level", [
    {default, warning},
    {datatype, {enum, [debug, info, notice, warning, error, critical, alert, emergency, all]}}
@@ -584,6 +593,26 @@ end}.
 {translation, "kernel.logger", fun(Conf) ->
     LogTo = cuttlefish:conf_get("log.to", Conf),
     LogLevel = cuttlefish:conf_get("log.level", Conf),
+    LogTimeoffset =
+        case cuttlefish:conf_get("log.time_offset", Conf) of
+            "system" -> "";
+            "utc" -> "0";
+            [S, H1, H2, $:, M1, M2] = HHMM ->
+                (S =:= $+ orelse S =:= $-) andalso
+                try
+                    begin
+                        H = list_to_integer([H1, H2]),
+                        M = list_to_integer([M1, M2]),
+                        H >=0 andalso H =< 14 andalso
+                        M >= 0 andalso M =< 59
+                    end
+                catch
+                    _ : _ ->
+                        error({"invalid_log_time_offset", HHMM})
+                end andalso HHMM;
+            Other ->
+                error({"invalid_log_time_offset", Other})
+        end,
     LogType = case cuttlefish:conf_get("log.rotation.enable", Conf) of
                   true -> wrap;
                   false -> halt
@@ -603,7 +632,9 @@ end}.
                               [peername," "],
                               []}]},
                        msg,"\n"],
-                    chars_limit => CharsLimit}},
+                    chars_limit => CharsLimit,
+                    time_offset => LogTimeoffset
+                   }},
     {BustLimitOn, {MaxBurstCount, TimeWindow}} =
         case string:tokens(cuttlefish:conf_get("log.burst_limit", Conf), ", ") of
             ["disabled"] -> {false, {20000, 1000}};

src/emqx_logger_formatter.erl

@@ -246,14 +246,10 @@ truncate(String,Size) ->
             String
     end.
 
-%% Convert microseconds-timestamp into local datatime string in milliseconds
+format_time(SysTime, Config) when is_integer(SysTime) ->
-format_time(SysTime,#{})
+    Offset = maps:get(time_offset, Config, ""),
-  when is_integer(SysTime) ->
+    calendar:system_time_to_rfc3339(SysTime, [{unit,microsecond},
-    Ms = SysTime rem 1000000 div 1000,
+                                              {offset,Offset}]).
-    {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);
@@ -313,12 +309,31 @@ do_check_config([{template,T}|Config]) ->
         ok -> do_check_config(Config);
         error -> {error,{invalid_formatter_template,?MODULE,T}}
     end;
-
+do_check_config([{time_offset, Offset} | Config]) ->
+    case lists:member(Offset, ["", "0", "Z", "z"]) orelse check_time_offset(Offset) of
+        true -> do_check_config(Config);
+        error -> {error, {time_offset, ?MODULE, Offset}}
+    end;
 do_check_config([C|_]) ->
     {error,{invalid_formatter_config,?MODULE,C}};
 do_check_config([]) ->
     ok.
 
+check_time_offset([S, H1, H2, $:, M1, M2]) ->
+    (S =:= $+ orelse S =:= $-) andalso
+    try
+        begin
+            H = list_to_integer([H1, H2]),
+            M = list_to_integer([M1, M2]),
+            H >=0 andalso H =< 14 andalso
+            M >= 0 andalso M =< 59
+        end
+    catch
+        _ : _ ->
+            error
+    end;
+check_time_offset(_) -> error.
+
 check_limit(L) when is_integer(L), L>0 ->
     ok;
 check_limit(unlimited) ->

test/emqx_logger_formatter_SUITE.erl

@@ -75,7 +75,7 @@ all() ->
 default(_Config) ->
     String1 = format(info,{"~p",[term]},#{},#{}),
     ct:log(String1),
-    ?assertMatch([_Date, _Time,"info:","term\n"], string:lexemes(String1," ")),
+    ?assertMatch([_DateTime,"info:","term\n"], string:lexemes(String1, " ")),
 
     Time = timestamp(),
     ExpectedTimestamp = default_time_format(Time),
@@ -581,8 +581,8 @@ update_config(_Config) ->
     ct:log("lines1: ~p", [Lines1]),
     ct:log("c1: ~p",[C1]),
     [Line1 | _] = Lines1,
-    [_Date, WithOutDate1] = string:split(Line1," "),
+    [_DateTime1, WithOutDate1] = string:split(Line1, " "),
-    [_, "notice: "++D1] = string:split(WithOutDate1," "),
+    ["notice:", D1] = string:split(WithOutDate1, " "),
     ?assert(length(D1)<1000),
     ?assertMatch(#{chars_limit := unlimited}, C1),
 
@@ -591,8 +591,8 @@ update_config(_Config) ->
     ct:log("Lines5: ~p", [Lines5]),
     ct:log("c5: ~p",[C5]),
     [Line5 | _] = Lines5,
-    [_Date, WithOutDate5] = string:split(Line5," "),
+    [_DateTime2, WithOutDate5] = string:split(Line5, " "),
-    [_, "error: "++_D5] = string:split(WithOutDate5," "),
+    ["error:", _D5] = string:split(WithOutDate5, " "),
 
     ?assertMatch({error,{invalid_formatter_config,bad}},
         logger:update_formatter_config(?MODULE,bad)),
@@ -616,13 +616,8 @@ 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,
+    calendar:system_time_to_rfc3339(SysTime, [{unit,microsecond},
-    {Date, _Time = {H, Mi, S}} = calendar:system_time_to_local_time(SysTime, microsecond),
+                                              {offset,""}]).
-    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)).