From 34ec0cc04b3d7f39fb484991e319b931c6ba2ac4 Mon Sep 17 00:00:00 2001
From: DDDHuang <44492639+DDDHuang@users.noreply.github.com>
Date: Mon, 23 May 2022 14:33:40 +0800
Subject: [PATCH] fix: logger formatter

---
 etc/emqx.conf               |  29 +++++-
 priv/emqx.schema            | 100 ++++++++++++++++++++-
 src/emqx_logger_textfmt.erl | 173 +++++++++++++++++++++++++++++++++++-
 3 files changed, 296 insertions(+), 6 deletions(-)

diff --git a/etc/emqx.conf b/etc/emqx.conf
index bc45df1fc..fb7263f85 100644
--- a/etc/emqx.conf
+++ b/etc/emqx.conf
@@ -458,7 +458,34 @@ log.file = emqx.log
 
 ## Log formatter
 ## Value: text | json
-#log.formatter = text
+log.formatter = text
+
+## Text logger, date format.
+##
+## Value: rfc3339 | FormatString
+##   FormatString:
+##     %Y: year
+##     %m: month
+##     %d: day
+##     %H: hour
+##     %M: minute
+##     %S: second
+##     %6N: microseconds
+##     %z: timezone
+## For example:
+## log.formatter.text.date.format = emqx-server-date: %Y-%m-%dT%H:%M:%S:%6N %z
+## Default: rfc3339
+# log.formatter.text.date.format = rfc3339
+
+## Text logger, timezone.
+## Only takes effect when log.formatter.text.date.format not rfc3339.
+##
+## Value: local | z | UTC TimeOffset
+## TimeOffset: [+|-]HH:MM:SS, for example: +08:00
+## z: UTC zulu timezone.
+## local is the system local time timezone.
+## Default: local
+# log.formatter.text.date.timezone = local
 
 ## Log to single line
 ## Value: Boolean
diff --git a/priv/emqx.schema b/priv/emqx.schema
index 4d7b1beda..7fde30c02 100644
--- a/priv/emqx.schema
+++ b/priv/emqx.schema
@@ -528,6 +528,18 @@ end}.
   {datatype, {enum, [text, json]}}
 ]}.
 
+%% @doc format logs as text, date format part
+{mapping, "log.formatter.text.date.format", "kernel.logger", [
+  {default, rfc3339},
+  {datatype, string}
+]}.
+
+%% @doc format logs as text, date format part. local or any UTC offset
+{mapping, "log.formatter.text.date.timezone", "kernel.logger", [
+  {default, local},
+  {datatype, string}
+]}.
+
 %% @doc format logs in a single line.
 {mapping, "log.single_line", "kernel.logger", [
   {default, true},
@@ -629,9 +641,93 @@ end}.
                     single_line => SingleLine
                    }};
         text ->
+            DateFormat =
+              case cuttlefish:conf_get("log.formatter.text.date.format", Conf) of
+                "rfc3339" ->
+                  rfc3339;
+                DateStr ->
+                  DateStrTrans =
+                    fun
+                      DST(<<>>, Formatter) -> lists:reverse(Formatter);
+                      DST(<<"%Y", Tail/binary>>, Formatter) -> DST(Tail, [year | Formatter]);
+                      DST(<<"%m", Tail/binary>>, Formatter) -> DST(Tail, [month | Formatter]);
+                      DST(<<"%d", Tail/binary>>, Formatter) -> DST(Tail, [day | Formatter]);
+                      DST(<<"%H", Tail/binary>>, Formatter) -> DST(Tail, [hour | Formatter]);
+                      DST(<<"%M", Tail/binary>>, Formatter) -> DST(Tail, [minute | Formatter]);
+                      DST(<<"%S", Tail/binary>>, Formatter) -> DST(Tail, [second | Formatter]);
+                      DST(<<"%6N", Tail/binary>>, Formatter) -> DST(Tail, [nano_second | Formatter]);
+                      DST(<<"%z", Tail/binary>>, Formatter) -> DST(Tail, [timezone | Formatter]);
+                      DST(<<Char:8, Tail/binary>>, [Str | Formatter]) when is_list(Str) ->
+                          DST(Tail, [lists:append(Str, [Char]) | Formatter]);
+                      DST(<<Char:8, Tail/binary>>, Formatter) ->
+                          DST(Tail, [[Char] | Formatter])
+                    end,
+                    DateStrTrans(list_to_binary(DateStr), [])
+              end,
+            {DateOffsetStr, DateOffset} =
+              case cuttlefish:conf_get("log.formatter.text.date.timezone", Conf) of
+                "z" ->
+                  {"z", 0};
+                "Z" ->
+                  {"Z", 0};
+                "local" ->
+                    UniversalTime =
+                      calendar:system_time_to_universal_time(
+                        erlang:system_time(second),
+                        second),
+                    LocalTime = erlang:universaltime_to_localtime(UniversalTime),
+                    LocalSecs = calendar:datetime_to_gregorian_seconds(LocalTime),
+                    UniversalSecs = calendar:datetime_to_gregorian_seconds(UniversalTime),
+                    OffsetSecond = LocalSecs - UniversalSecs,
+                    {Sign, PosOffsetSecond} =
+                      case OffsetSecond >= 0 of
+                        true -> {$+, OffsetSecond};
+                        false -> {$-, - OffsetSecond}
+                      end,
+                    {H, M, S} = calendar:seconds_to_time(PosOffsetSecond),
+                    Str =
+                      case S of
+                        0 ->
+                          io_lib:format("~c~p:~p", [Sign, H, M]);
+                        S ->
+                          io_lib:format("~c~p:~p:~p", [Sign, H, M, S])
+                      end,
+                    {Str, OffsetSecond};
+                DateOStr ->
+                  Sign = hd(DateOStr),
+                  Signs = #{$+ => 1, $- => -1},
+                  case maps:get(Sign, Signs, undefined) of
+                      undefined ->
+                        error(bad_logger_offset);
+                      PosNeg ->
+                        try
+                          [Sign | HM] = DateOStr,
+                          {HourStr, MinuteStr, SecondStr} =
+                            case string:tokens(HM, ":") of
+                              [H, M] ->
+                                {H, M, "0"};
+                              [H, M, S] ->
+                                {H, M, S}
+                            end,
+                          Hour = erlang:list_to_integer(HourStr),
+                          Minute = erlang:list_to_integer(MinuteStr),
+                          Second = erlang:list_to_integer(SecondStr),
+                          true = (Hour =< 23),
+                          true = (Minute =< 59),
+                          true = (Second =< 59),
+                          {DateOStr, PosNeg * (Hour * 3600 + Minute * 60 + Second)}
+                        catch _E : _R ->
+                          error(bad_logger_offset)
+                        end
+                  end
+              end,
             {emqx_logger_textfmt,
-                  #{template =>
-                      [time," [",level,"] ",
+                  #{
+                    date_format => DateFormat,
+                    timezone_offset => DateOffset,
+                    timezone => DateOffsetStr,
+                    template =>
+                      [" [",level,"] ",
                        {clientid,
                           [{peername,
                               [clientid,"@",peername," "],
diff --git a/src/emqx_logger_textfmt.erl b/src/emqx_logger_textfmt.erl
index 98104f58c..df4118ba4 100644
--- a/src/emqx_logger_textfmt.erl
+++ b/src/emqx_logger_textfmt.erl
@@ -16,6 +16,16 @@
 
 -module(emqx_logger_textfmt).
 
+-define(SECONDS_PER_MINUTE, 60).
+-define(SECONDS_PER_HOUR, 3600).
+-define(SECONDS_PER_DAY, 86400).
+-define(DAYS_PER_YEAR, 365).
+-define(DAYS_PER_LEAP_YEAR, 366).
+-define(DAYS_FROM_0_TO_1970, 719528).
+-define(DAYS_FROM_0_TO_10000, 2932897).
+-define(SECONDS_FROM_0_TO_1970, ?DAYS_FROM_0_TO_1970 * ?SECONDS_PER_DAY).
+-define(SECONDS_FROM_0_TO_10000, ?DAYS_FROM_0_TO_10000 * ?SECONDS_PER_DAY).
+
 -export([format/2]).
 -export([check_config/1]).
 
@@ -28,11 +38,21 @@
         , gl        % not interesting
         ]).
 
-check_config(X) -> logger_formatter:check_config(X).
+check_config(Config0) ->
+    Config = maps:without([date_format, timezone_offset, timezone], Config0),
+    logger_formatter:check_config(Config).
 
-format(#{msg := Msg0, meta := Meta} = Event, Config) ->
+format(#{msg := Msg0, meta := Meta} = Event,
+       #{date_format := rfc3339, template := Template0} = Config) ->
     Msg = maybe_merge(Msg0, Meta),
-    logger_formatter:format(Event#{msg := Msg}, Config).
+    Template = [time | Template0],
+    logger_formatter:format(Event#{msg := Msg}, Config#{template => Template});
+
+format(#{msg := Msg0, meta := Meta} = Event,
+       #{timezone_offset := TZO, timezone := TZ, date_format := DFS} = Config) ->
+    Msg = maybe_merge(Msg0, Meta),
+    Time = maps:get(time, Event, undefined),
+    [date_format(Time, TZO, TZ, DFS) | logger_formatter:format(Event#{msg := Msg}, Config)].
 
 maybe_merge({report, Report}, Meta) when is_map(Report) ->
     {report, maps:merge(Report, filter(Meta))};
@@ -41,3 +61,150 @@ maybe_merge(Report, _Meta) ->
 
 filter(Meta) ->
     maps:without(?WITHOUT_MERGE, Meta).
+
+date_format(undefined, Offset, OffsetStr, Formatter) ->
+    Time = erlang:system_time(microsecond),
+    date_format(Time, Offset, OffsetStr, Formatter);
+date_format(Time, Offset, OffsetStr, Formatter) ->
+    Adjustment = erlang:convert_time_unit(Offset, second, microsecond),
+    AdjustedTime = Time + Adjustment,
+    %% Factor 1000000 for microsecond.
+    Factor = 1000000,
+    Secs = AdjustedTime div Factor,
+    DateTime = system_time_to_datetime(Secs),
+    {{Year, Month, Day}, {Hour, Min, Sec}} = DateTime,
+    FractionStr = fraction_str(Factor, AdjustedTime),
+    Date = #{
+        year => padding(Year, 4),
+        month => padding(Month, 2),
+        day => padding(Day, 2),
+        hour => padding(Hour, 2),
+        minute => padding(Min, 2),
+        second => padding(Sec, 2),
+        nano_second => FractionStr,
+        timezone => OffsetStr
+    },
+    [maps:get(Key, Date, Key) || Key <- Formatter].
+
+system_time_to_datetime(Seconds) ->
+    gregorian_seconds_to_datetime(Seconds + ?SECONDS_FROM_0_TO_1970).
+
+gregorian_seconds_to_datetime(Secs) when Secs >= 0 ->
+    Days = Secs div ?SECONDS_PER_DAY,
+    Rest = Secs rem ?SECONDS_PER_DAY,
+    {gregorian_days_to_date(Days), seconds_to_time(Rest)}.
+
+seconds_to_time(Secs) when Secs >= 0, Secs < ?SECONDS_PER_DAY ->
+    Secs0 = Secs rem ?SECONDS_PER_DAY,
+    Hour = Secs0 div ?SECONDS_PER_HOUR,
+    Secs1 = Secs0 rem ?SECONDS_PER_HOUR,
+    Minute = Secs1 div ?SECONDS_PER_MINUTE,
+    Second = Secs1 rem ?SECONDS_PER_MINUTE,
+    {Hour, Minute, Second}.
+
+gregorian_days_to_date(Days) ->
+    {Year, DayOfYear} = day_to_year(Days),
+    {Month, DayOfMonth} = year_day_to_date(Year, DayOfYear),
+    {Year, Month, DayOfMonth}.
+
+day_to_year(DayOfEpoch) when DayOfEpoch >= 0 ->
+    YMax = DayOfEpoch div ?DAYS_PER_YEAR,
+    YMin = DayOfEpoch div ?DAYS_PER_LEAP_YEAR,
+    {Y1, D1} = dty(YMin, YMax, DayOfEpoch, dy(YMin), dy(YMax)),
+    {Y1, DayOfEpoch - D1}.
+
+year_day_to_date(Year, DayOfYear) ->
+    ExtraDay =
+        case is_leap_year(Year) of
+            true ->
+                1;
+            false ->
+                0
+        end,
+    {Month, Day} = year_day_to_date2(ExtraDay, DayOfYear),
+    {Month, Day + 1}.
+
+dty(Min, Max, _D1, DMin, _DMax) when Min == Max ->
+    {Min, DMin};
+dty(Min, Max, D1, DMin, DMax) ->
+    Diff = Max - Min,
+    Mid = Min + Diff * (D1 - DMin) div (DMax - DMin),
+    MidLength =
+        case is_leap_year(Mid) of
+            true ->
+                ?DAYS_PER_LEAP_YEAR;
+            false ->
+                ?DAYS_PER_YEAR
+        end,
+    case dy(Mid) of
+        D2 when D1 < D2 ->
+            NewMax = Mid - 1,
+            dty(Min, NewMax, D1, DMin, dy(NewMax));
+        D2 when D1 - D2 >= MidLength ->
+            NewMin = Mid + 1,
+            dty(NewMin, Max, D1, dy(NewMin), DMax);
+        D2 ->
+            {Mid, D2}
+    end.
+
+dy(Y) when Y =< 0 ->
+    0;
+dy(Y) ->
+    X = Y - 1,
+    X div 4 - X div 100 + X div 400 + X * ?DAYS_PER_YEAR + ?DAYS_PER_LEAP_YEAR.
+
+is_leap_year(Y) when is_integer(Y), Y >= 0 ->
+    is_leap_year1(Y).
+
+is_leap_year1(Year) when Year rem 4 =:= 0, Year rem 100 > 0 ->
+    true;
+is_leap_year1(Year) when Year rem 400 =:= 0 ->
+    true;
+is_leap_year1(_) ->
+    false.
+
+year_day_to_date2(_, Day) when Day < 31 ->
+    {1, Day};
+year_day_to_date2(E, Day) when 31 =< Day, Day < 59 + E ->
+    {2, Day - 31};
+year_day_to_date2(E, Day) when 59 + E =< Day, Day < 90 + E ->
+    {3, Day - (59 + E)};
+year_day_to_date2(E, Day) when 90 + E =< Day, Day < 120 + E ->
+    {4, Day - (90 + E)};
+year_day_to_date2(E, Day) when 120 + E =< Day, Day < 151 + E ->
+    {5, Day - (120 + E)};
+year_day_to_date2(E, Day) when 151 + E =< Day, Day < 181 + E ->
+    {6, Day - (151 + E)};
+year_day_to_date2(E, Day) when 181 + E =< Day, Day < 212 + E ->
+    {7, Day - (181 + E)};
+year_day_to_date2(E, Day) when 212 + E =< Day, Day < 243 + E ->
+    {8, Day - (212 + E)};
+year_day_to_date2(E, Day) when 243 + E =< Day, Day < 273 + E ->
+    {9, Day - (243 + E)};
+year_day_to_date2(E, Day) when 273 + E =< Day, Day < 304 + E ->
+    {10, Day - (273 + E)};
+year_day_to_date2(E, Day) when 304 + E =< Day, Day < 334 + E ->
+    {11, Day - (304 + E)};
+year_day_to_date2(E, Day) when 334 + E =< Day ->
+    {12, Day - (334 + E)}.
+
+fraction_str(1, _Time) ->
+    "";
+fraction_str(Factor, Time) ->
+    Fraction = Time rem Factor,
+    S = integer_to_list(abs(Fraction)),
+    [padding(S, log10(Factor) - length(S))].
+
+log10(1000) ->
+    3;
+log10(1000000) ->
+    6;
+log10(1000000000) ->
+    9.
+
+padding(Data, Len) when is_integer(Data) ->
+    padding(integer_to_list(Data), Len);
+padding(Data, Len) when Len > 0 andalso erlang:length(Data) < Len ->
+    [$0 | padding(Data, Len - 1)];
+padding(Data, _Len) ->
+    Data.