From 8cbfc4c0cd6e91089216bd516e06287d4bf19baf Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Wed, 15 May 2024 11:47:21 +0200 Subject: [PATCH] fix: evaluate lazy values in normal log formatters when level is debug Fixes: https://emqx.atlassian.net/browse/EMQX-12380 --- apps/emqx/src/emqx_logger_jsonfmt.erl | 4 +- apps/emqx/src/emqx_logger_textfmt.erl | 38 +++++++- .../src/emqx_trace/emqx_trace_formatter.erl | 31 ++----- .../emqx_trace/emqx_trace_json_formatter.erl | 4 +- apps/emqx/test/emqx_logger_fmt_SUITE.erl | 90 +++++++++++++++++++ 5 files changed, 137 insertions(+), 30 deletions(-) create mode 100644 apps/emqx/test/emqx_logger_fmt_SUITE.erl diff --git a/apps/emqx/src/emqx_logger_jsonfmt.erl b/apps/emqx/src/emqx_logger_jsonfmt.erl index 776c8f753..005776adf 100644 --- a/apps/emqx/src/emqx_logger_jsonfmt.erl +++ b/apps/emqx/src/emqx_logger_jsonfmt.erl @@ -76,7 +76,9 @@ best_effort_json_obj(Input) -> best_effort_json_obj(Input, Config). -spec format(logger:log_event(), config()) -> iodata(). -format(#{level := Level, msg := Msg, meta := Meta}, Config0) when is_map(Config0) -> +format(#{level := _Level, msg := _Msg, meta := _Meta} = Entry, Config0) when is_map(Config0) -> + #{level := Level, msg := Msg, meta := Meta} = + emqx_logger_textfmt:evaluate_lazy_values_if_dbg_level(Entry), Config = add_default_config(Config0), [format(Msg, Meta#{level => Level}, Config), "\n"]. diff --git a/apps/emqx/src/emqx_logger_textfmt.erl b/apps/emqx/src/emqx_logger_textfmt.erl index 1f26f519e..bbba75c51 100644 --- a/apps/emqx/src/emqx_logger_textfmt.erl +++ b/apps/emqx/src/emqx_logger_textfmt.erl @@ -16,15 +16,20 @@ -module(emqx_logger_textfmt). +-include("emqx_trace.hrl"). + -export([format/2]). -export([check_config/1]). -export([try_format_unicode/1]). +%% Used in the other log formatters +-export([evaluate_lazy_values_if_dbg_level/1, evaluate_lazy_values/1]). 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 -format(#{msg := {report, ReportMap}, meta := Meta} = Event, Config) when is_map(ReportMap) -> +format(#{msg := {report, ReportMap0}, meta := _Meta} = Event0, Config) when is_map(ReportMap0) -> + #{msg := {report, ReportMap}, meta := Meta} = Event = evaluate_lazy_values_if_dbg_level(Event0), %% The most common case, when entering from SLOG macro %% i.e. logger:log(Level, #{msg => "my_msg", foo => bar}) ReportList = enrich_report(ReportMap, Meta), @@ -40,12 +45,39 @@ format(#{msg := {string, String}} = Event, Config) -> %% copied from logger_formatter:format/2 %% unsure how this case is triggered format(Event#{msg => {"~ts ", [String]}}, Config); -format(#{msg := Msg0, meta := Meta} = Event, Config) -> +format(#{msg := _Msg, meta := _Meta} = Event0, Config) -> + #{msg := Msg0, meta := Meta} = Event1 = evaluate_lazy_values_if_dbg_level(Event0), %% For format strings like logger:log(Level, "~p", [Var]) %% and logger:log(Level, "message", #{key => value}) Msg1 = enrich_client_info(Msg0, Meta), Msg2 = enrich_topic(Msg1, Meta), - fmt(Event#{msg := Msg2}, Config). + fmt(Event1#{msg := Msg2}, Config). + +%% Most log entries with lazy values are trace events with level debug. So to +%% be more efficient we only search for lazy values to evaluate in the entries +%% with level debug in the main log formatters. +evaluate_lazy_values_if_dbg_level(#{level := debug} = Map) -> + evaluate_lazy_values(Map); +evaluate_lazy_values_if_dbg_level(Map) -> + Map. + +evaluate_lazy_values(Map) when is_map(Map) -> + maps:map(fun evaluate_lazy_values_kv/2, Map); +evaluate_lazy_values({report, Report}) -> + {report, evaluate_lazy_values(Report)}; +evaluate_lazy_values(V) -> + V. + +evaluate_lazy_values_kv(_K, #emqx_trace_format_func_data{function = Formatter, data = V}) -> + try + NewV = Formatter(V), + evaluate_lazy_values(NewV) + catch + _:_ -> + V + end; +evaluate_lazy_values_kv(_K, V) -> + evaluate_lazy_values(V). fmt(#{meta := #{time := Ts}} = Data, Config) -> Timestamp = diff --git a/apps/emqx/src/emqx_trace/emqx_trace_formatter.erl b/apps/emqx/src/emqx_trace/emqx_trace_formatter.erl index 1e40c6849..c1213459c 100644 --- a/apps/emqx/src/emqx_trace/emqx_trace_formatter.erl +++ b/apps/emqx/src/emqx_trace/emqx_trace_formatter.erl @@ -15,11 +15,9 @@ %%-------------------------------------------------------------------- -module(emqx_trace_formatter). -include("emqx_mqtt.hrl"). --include("emqx_trace.hrl"). -export([format/2]). -export([format_meta_map/1]). --export([evaluate_lazy_values/1]). %% logger_formatter:config/0 is not exported. -type config() :: map(). @@ -30,35 +28,20 @@ LogEvent :: logger:log_event(), Config :: config(). format( - #{level := debug, meta := Meta0 = #{trace_tag := Tag}, msg := Msg}, + #{level := debug, meta := _Meta = #{trace_tag := _Tag}, msg := _Msg} = Entry, #{payload_encode := PEncode} ) -> - Meta1 = evaluate_lazy_values(Meta0), + #{level := debug, meta := Meta = #{trace_tag := Tag}, msg := Msg} = + emqx_logger_textfmt:evaluate_lazy_values(Entry), Time = emqx_utils_calendar:now_to_rfc3339(microsecond), - ClientId = to_iolist(maps:get(clientid, Meta1, "")), - Peername = maps:get(peername, Meta1, ""), - MetaBin = format_meta(Meta1, PEncode), + ClientId = to_iolist(maps:get(clientid, Meta, "")), + Peername = maps:get(peername, Meta, ""), + MetaBin = format_meta(Meta, PEncode), Msg1 = to_iolist(Msg), Tag1 = to_iolist(Tag), [Time, " [", Tag1, "] ", ClientId, "@", Peername, " msg: ", Msg1, ", ", MetaBin, "\n"]; format(Event, Config) -> - emqx_logger_textfmt:format(evaluate_lazy_values(Event), Config). - -evaluate_lazy_values(Map) when is_map(Map) -> - maps:map(fun evaluate_lazy_values_kv/2, Map); -evaluate_lazy_values(V) -> - V. - -evaluate_lazy_values_kv(_K, #emqx_trace_format_func_data{function = Formatter, data = V}) -> - try - NewV = Formatter(V), - evaluate_lazy_values(NewV) - catch - _:_ -> - V - end; -evaluate_lazy_values_kv(_K, V) -> - evaluate_lazy_values(V). + emqx_logger_textfmt:format(Event, Config). format_meta_map(Meta) -> Encode = emqx_trace_handler:payload_encode(), diff --git a/apps/emqx/src/emqx_trace/emqx_trace_json_formatter.erl b/apps/emqx/src/emqx_trace/emqx_trace_json_formatter.erl index 706956c3a..85b846349 100644 --- a/apps/emqx/src/emqx_trace/emqx_trace_json_formatter.erl +++ b/apps/emqx/src/emqx_trace/emqx_trace_json_formatter.erl @@ -36,8 +36,8 @@ format( LogMap, #{payload_encode := PEncode} = Config ) -> - LogMap0 = maybe_format_msg(LogMap, Config), - LogMap1 = emqx_trace_formatter:evaluate_lazy_values(LogMap0), + LogMap0 = emqx_logger_textfmt:evaluate_lazy_values(LogMap), + LogMap1 = maybe_format_msg(LogMap0, Config), %% We just make some basic transformations on the input LogMap and then do %% an external call to create the JSON text Time = emqx_utils_calendar:now_to_rfc3339(microsecond), diff --git a/apps/emqx/test/emqx_logger_fmt_SUITE.erl b/apps/emqx/test/emqx_logger_fmt_SUITE.erl new file mode 100644 index 000000000..63069fd58 --- /dev/null +++ b/apps/emqx/test/emqx_logger_fmt_SUITE.erl @@ -0,0 +1,90 @@ +%%-------------------------------------------------------------------- +%% Copyright (c) 2019-2024 EMQ Technologies Co., Ltd. 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. +%%-------------------------------------------------------------------- + +-module(emqx_logger_fmt_SUITE). + +-compile(export_all). +-compile(nowarn_export_all). + +-include_lib("eunit/include/eunit.hrl"). +-include("emqx_trace.hrl"). + +all() -> emqx_common_test_helpers:all(?MODULE). + +init_per_testcase(_TestCase, Config) -> + Config. + +end_per_testcase(_TestCase, Config) -> + Config. + +t_text_fmt_lazy_values(_) -> + check_fmt_lazy_values(emqx_logger_textfmt). + +t_text_fmt_lazy_values_only_in_debug_level_events(_) -> + check_fmt_lazy_values_only_in_debug_level_events(emqx_logger_textfmt). + +t_json_fmt_lazy_values(_) -> + check_fmt_lazy_values(emqx_logger_jsonfmt). + +t_json_fmt_lazy_values_only_in_debug_level_events(_) -> + check_fmt_lazy_values_only_in_debug_level_events(emqx_logger_jsonfmt). + +check_fmt_lazy_values(FormatModule) -> + LogEntryIOData = FormatModule:format(event_with_lazy_value(), conf()), + LogEntryBin = unicode:characters_to_binary(LogEntryIOData), + %% Result of lazy evealuation should exist + ?assertNotEqual(nomatch, binary:match(LogEntryBin, [<<"hej">>])), + %% The lazy value should have been evaluated + ?assertEqual(nomatch, binary:match(LogEntryBin, [<<"emqx_trace_format_func_data">>])), + ok. + +check_fmt_lazy_values_only_in_debug_level_events(FormatModule) -> + %% For performace reason we only search for lazy values to evaluate if log level is debug + WarningEvent = (event_with_lazy_value())#{level => info}, + LogEntryIOData = FormatModule:format(WarningEvent, conf()), + LogEntryBin = unicode:characters_to_binary(LogEntryIOData), + %% The input data for the formatting should exist + ?assertNotEqual(nomatch, binary:match(LogEntryBin, [<<"hej">>])), + %% The lazy value should not have been evaluated + ?assertNotEqual(nomatch, binary:match(LogEntryBin, [<<"emqx_trace_format_func_data">>])), + ok. + +conf() -> + #{ + time_offset => [], + chars_limit => unlimited, + depth => 100, + single_line => true, + template => ["[", level, "] ", msg, "\n"], + timestamp_format => auto + }. + +event_with_lazy_value() -> + #{ + meta => #{ + pid => what, + time => 1715763862274127, + gl => what, + report_cb => fun logger:format_otp_report/1 + }, + msg => + {report, #{ + reason => + #emqx_trace_format_func_data{function = fun(Data) -> Data end, data = hej}, + msg => hej + }}, + level => debug + }.