From c42e9804427b7d814b505add59b6a5cc9993dd93 Mon Sep 17 00:00:00 2001 From: zmstone Date: Tue, 26 Mar 2024 12:44:41 +0100 Subject: [PATCH 1/4] feat(log): configurable time format now logs can be configured to use 'epoch' or 'rfc3339' time format --- apps/emqx/src/config/emqx_config_logger.erl | 19 ++++++++++++------ apps/emqx/src/emqx_logger_jsonfmt.erl | 14 ++++++++++++- apps/emqx/src/emqx_logger_textfmt.erl | 22 ++++++++++++++++++--- apps/emqx_conf/src/emqx_conf_schema.erl | 9 +++++++++ changes/ce/feat-12785.en.md | 10 ++++++++++ rel/i18n/emqx_conf_schema.hocon | 9 +++++++++ 6 files changed, 73 insertions(+), 10 deletions(-) create mode 100644 changes/ce/feat-12785.en.md diff --git a/apps/emqx/src/config/emqx_config_logger.erl b/apps/emqx/src/config/emqx_config_logger.erl index 0d4ffa9ca..73b4d0b3b 100644 --- a/apps/emqx/src/config/emqx_config_logger.erl +++ b/apps/emqx/src/config/emqx_config_logger.erl @@ -237,25 +237,32 @@ log_formatter(HandlerName, Conf) -> _ -> conf_get("formatter", Conf) end, + TsFormat = timstamp_format(Conf), do_formatter( - Format, CharsLimit, SingleLine, TimeOffSet, Depth + Format, CharsLimit, SingleLine, TimeOffSet, Depth, TsFormat ). +%% auto | epoch | rfc3339 +timstamp_format(Conf) -> + conf_get("timestamp_format", Conf). + %% helpers -do_formatter(json, CharsLimit, SingleLine, TimeOffSet, Depth) -> +do_formatter(json, CharsLimit, SingleLine, TimeOffSet, Depth, TsFormat) -> {emqx_logger_jsonfmt, #{ chars_limit => CharsLimit, single_line => SingleLine, time_offset => TimeOffSet, - depth => Depth + depth => Depth, + timestamp_format => TsFormat }}; -do_formatter(text, CharsLimit, SingleLine, TimeOffSet, Depth) -> +do_formatter(text, CharsLimit, SingleLine, TimeOffSet, Depth, TsFormat) -> {emqx_logger_textfmt, #{ - template => [time, " [", level, "] ", msg, "\n"], + template => ["[", level, "] ", msg, "\n"], chars_limit => CharsLimit, single_line => SingleLine, time_offset => TimeOffSet, - depth => Depth + depth => Depth, + timestamp_format => TsFormat }}. %% Don't record all logger message diff --git a/apps/emqx/src/emqx_logger_jsonfmt.erl b/apps/emqx/src/emqx_logger_jsonfmt.erl index 2a26921e9..2efb0e032 100644 --- a/apps/emqx/src/emqx_logger_jsonfmt.erl +++ b/apps/emqx/src/emqx_logger_jsonfmt.erl @@ -285,9 +285,21 @@ json_obj_root(Data0, Config) -> ), lists:filter( fun({_, V}) -> V =/= undefined end, - [{time, Time}, {level, Level}, {msg, Msg}] + [{time, format_ts(Time, Config)}, {level, Level}, {msg, Msg}] ) ++ Data. +format_ts(Ts, #{timestamp_format := rfc3339, time_offset := Offset}) when is_integer(Ts) -> + iolist_to_binary( + calendar:system_time_to_rfc3339(Ts, [ + {unit, microsecond}, + {offset, Offset}, + {time_designator, $T} + ]) + ); +format_ts(Ts, _Config) -> + % auto | epoch + Ts. + json_obj(Data, Config) -> maps:fold( fun(K, V, D) -> diff --git a/apps/emqx/src/emqx_logger_textfmt.erl b/apps/emqx/src/emqx_logger_textfmt.erl index 1b2ea8758..1f26f519e 100644 --- a/apps/emqx/src/emqx_logger_textfmt.erl +++ b/apps/emqx/src/emqx_logger_textfmt.erl @@ -20,7 +20,7 @@ -export([check_config/1]). -export([try_format_unicode/1]). -check_config(X) -> logger_formatter:check_config(X). +check_config(X) -> logger_formatter:check_config(maps:without([timestamp_format], X)). %% Principle here is to delegate the formatting to logger_formatter:format/2 %% as much as possible, and only enrich the report with clientid, peername, topic, username @@ -35,7 +35,7 @@ format(#{msg := {report, ReportMap}, meta := Meta} = Event, Config) when is_map( false -> maps:from_list(ReportList) end, - logger_formatter:format(Event#{msg := {report, Report}}, Config); + fmt(Event#{msg := {report, Report}}, Config); format(#{msg := {string, String}} = Event, Config) -> %% copied from logger_formatter:format/2 %% unsure how this case is triggered @@ -45,7 +45,23 @@ format(#{msg := Msg0, meta := Meta} = Event, Config) -> %% and logger:log(Level, "message", #{key => value}) Msg1 = enrich_client_info(Msg0, Meta), Msg2 = enrich_topic(Msg1, Meta), - logger_formatter:format(Event#{msg := Msg2}, Config). + fmt(Event#{msg := Msg2}, Config). + +fmt(#{meta := #{time := Ts}} = Data, Config) -> + Timestamp = + case Config of + #{timestamp_format := epoch} -> + integer_to_list(Ts); + _ -> + % auto | rfc3339 + TimeOffset = maps:get(time_offset, Config, ""), + calendar:system_time_to_rfc3339(Ts, [ + {unit, microsecond}, + {offset, TimeOffset}, + {time_designator, $T} + ]) + end, + [Timestamp, " ", logger_formatter:format(Data, Config)]. %% Other report callbacks may only accept map() reports such as gen_server formatter is_list_report_acceptable(#{report_cb := Cb}) -> diff --git a/apps/emqx_conf/src/emqx_conf_schema.erl b/apps/emqx_conf/src/emqx_conf_schema.erl index c72f6a87b..69d0b6162 100644 --- a/apps/emqx_conf/src/emqx_conf_schema.erl +++ b/apps/emqx_conf/src/emqx_conf_schema.erl @@ -1277,6 +1277,15 @@ log_handler_common_confs(Handler, Default) -> importance => ?IMPORTANCE_MEDIUM } )}, + {"timestamp_format", + sc( + hoconsc:enum([auto, epoch, rfc3339]), + #{ + default => auto, + desc => ?DESC("common_handler_timestamp_format"), + importance => ?IMPORTANCE_MEDIUM + } + )}, {"time_offset", sc( string(), diff --git a/changes/ce/feat-12785.en.md b/changes/ce/feat-12785.en.md new file mode 100644 index 000000000..31a786325 --- /dev/null +++ b/changes/ce/feat-12785.en.md @@ -0,0 +1,10 @@ +Add `timestamp_format` config to log handers. + +We've added a new configuration option `timestamp_format` to the log handlers. +This new config supports the following values: + +- `auto`: Automatically determines the timestamp format based on the log formatter being used. + Utilizes `rfc3339` format for text formatters, and `epoch` format for JSON formatters. +- `epoch`: Represents timestamps in milliseconds precision Unix epoch format. +- `rfc3339`: Uses RFC3339 compliant format for date-time strings. For example: `2024-03-26T11:52:19.777087+00:00`. + diff --git a/rel/i18n/emqx_conf_schema.hocon b/rel/i18n/emqx_conf_schema.hocon index 619015b01..b2a1cc62f 100644 --- a/rel/i18n/emqx_conf_schema.hocon +++ b/rel/i18n/emqx_conf_schema.hocon @@ -761,6 +761,15 @@ common_handler_formatter.desc: common_handler_formatter.label: """Log Formatter""" +common_handler_timestamp_format.label: +"""Timestamp Format""" + +common_handler_timestamp_format.desc: """~ + Pick a timestamp format: + - `auto`: automatically choose the best format based on log formatter. `epoch` for JSON and `rfc3339` for text. + - `epoch`: Unix epoch time in milliseconds. + - `rfc3339`: RFC3339 format.""" + rpc_async_batch_size.desc: """The maximum number of batch messages sent in asynchronous mode. Note that this configuration does not work in synchronous mode.""" From 067f0183379bf4f80be5f9b3e6c239e6c86b35b2 Mon Sep 17 00:00:00 2001 From: zmstone Date: Tue, 26 Mar 2024 13:36:12 +0100 Subject: [PATCH 2/4] test: fix test cases --- apps/emqx_conf/test/emqx_conf_logger_SUITE.erl | 6 ++++-- apps/emqx_conf/test/emqx_conf_schema_tests.erl | 5 +++-- 2 files changed, 7 insertions(+), 4 deletions(-) diff --git a/apps/emqx_conf/test/emqx_conf_logger_SUITE.erl b/apps/emqx_conf/test/emqx_conf_logger_SUITE.erl index accd3c95e..5ce6535b5 100644 --- a/apps/emqx_conf/test/emqx_conf_logger_SUITE.erl +++ b/apps/emqx_conf/test/emqx_conf_logger_SUITE.erl @@ -77,7 +77,8 @@ t_log_conf(_Conf) -> <<"rotation_count">> => 10, <<"rotation_size">> => <<"50MB">>, <<"time_offset">> => <<"system">>, - <<"path">> => <<"log/emqx.log">> + <<"path">> => <<"log/emqx.log">>, + <<"timestamp_format">> => <<"auto">> }, ExpectLog1 = #{ <<"console">> => @@ -85,7 +86,8 @@ t_log_conf(_Conf) -> <<"enable">> => true, <<"formatter">> => <<"text">>, <<"level">> => <<"debug">>, - <<"time_offset">> => <<"system">> + <<"time_offset">> => <<"system">>, + <<"timestamp_format">> => <<"auto">> }, <<"file">> => #{<<"default">> => FileExpect}, diff --git a/apps/emqx_conf/test/emqx_conf_schema_tests.erl b/apps/emqx_conf/test/emqx_conf_schema_tests.erl index 9d8827fad..4b4dff4cf 100644 --- a/apps/emqx_conf/test/emqx_conf_schema_tests.erl +++ b/apps/emqx_conf/test/emqx_conf_schema_tests.erl @@ -131,8 +131,9 @@ log.file_handlers { chars_limit => unlimited, depth => 100, single_line => true, - template => [time, " [", level, "] ", msg, "\n"], - time_offset => TimeOffset + template => ["[", level, "] ", msg, "\n"], + time_offset => TimeOffset, + timestamp_format => auto }} ). From 78c5f8177cb948bcb1f4f27ea317dedcc3b1a59b Mon Sep 17 00:00:00 2001 From: zmstone Date: Tue, 26 Mar 2024 14:51:21 +0100 Subject: [PATCH 3/4] test: fix test case --- .../test/emqx_enterprise_schema_SUITE.erl | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/apps/emqx_enterprise/test/emqx_enterprise_schema_SUITE.erl b/apps/emqx_enterprise/test/emqx_enterprise_schema_SUITE.erl index 5a707a070..92adf2f17 100644 --- a/apps/emqx_enterprise/test/emqx_enterprise_schema_SUITE.erl +++ b/apps/emqx_enterprise/test/emqx_enterprise_schema_SUITE.erl @@ -78,7 +78,8 @@ t_audit_log_conf(_Config) -> <<"rotation_count">> => 10, <<"rotation_size">> => <<"50MB">>, <<"time_offset">> => <<"system">>, - <<"path">> => <<"log/emqx.log">> + <<"path">> => <<"log/emqx.log">>, + <<"timestamp_format">> => <<"auto">> }, ExpectLog1 = #{ <<"console">> => @@ -86,7 +87,8 @@ t_audit_log_conf(_Config) -> <<"enable">> => false, <<"formatter">> => <<"text">>, <<"level">> => <<"warning">>, - <<"time_offset">> => <<"system">> + <<"time_offset">> => <<"system">>, + <<"timestamp_format">> => <<"auto">> }, <<"file">> => #{<<"default">> => FileExpect}, @@ -99,7 +101,8 @@ t_audit_log_conf(_Config) -> <<"max_filter_size">> => 5000, <<"rotation_count">> => 10, <<"rotation_size">> => <<"50MB">>, - <<"time_offset">> => <<"system">> + <<"time_offset">> => <<"system">>, + <<"timestamp_format">> => <<"auto">> } }, %% The default value of throttling.msgs can be frequently updated, From 874b1ff3f40f3277ffa078b9f31eb1153ebff0d5 Mon Sep 17 00:00:00 2001 From: zmstone Date: Tue, 26 Mar 2024 16:04:00 +0100 Subject: [PATCH 4/4] docs: fix epoch timestamp precision --- changes/ce/feat-12785.en.md | 2 +- rel/i18n/emqx_conf_schema.hocon | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/changes/ce/feat-12785.en.md b/changes/ce/feat-12785.en.md index 31a786325..0643d1068 100644 --- a/changes/ce/feat-12785.en.md +++ b/changes/ce/feat-12785.en.md @@ -5,6 +5,6 @@ This new config supports the following values: - `auto`: Automatically determines the timestamp format based on the log formatter being used. Utilizes `rfc3339` format for text formatters, and `epoch` format for JSON formatters. -- `epoch`: Represents timestamps in milliseconds precision Unix epoch format. +- `epoch`: Represents timestamps in microseconds precision Unix epoch format. - `rfc3339`: Uses RFC3339 compliant format for date-time strings. For example: `2024-03-26T11:52:19.777087+00:00`. diff --git a/rel/i18n/emqx_conf_schema.hocon b/rel/i18n/emqx_conf_schema.hocon index b2a1cc62f..be6526f48 100644 --- a/rel/i18n/emqx_conf_schema.hocon +++ b/rel/i18n/emqx_conf_schema.hocon @@ -767,7 +767,7 @@ common_handler_timestamp_format.label: common_handler_timestamp_format.desc: """~ Pick a timestamp format: - `auto`: automatically choose the best format based on log formatter. `epoch` for JSON and `rfc3339` for text. - - `epoch`: Unix epoch time in milliseconds. + - `epoch`: Unix epoch time in microseconds. - `rfc3339`: RFC3339 format.""" rpc_async_batch_size.desc: