Merge pull request #13052 from kjellwinblad/kjell/evaluate_lazy_trace_values_in_normal_log_formatters/EMQX-12380

fix: evaluate lazy values in normal log formatters when level is debug

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"].
 

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 =

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, "")),
+    ClientId = to_iolist(maps:get(clientid, Meta, "")),
-    Peername = maps:get(peername, Meta1, ""),
+    Peername = maps:get(peername, Meta, ""),
-    MetaBin = format_meta(Meta1, PEncode),
+    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).
+    emqx_logger_textfmt:format(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).
 
 format_meta_map(Meta) ->
     Encode = emqx_trace_handler:payload_encode(),

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),
+    LogMap0 = emqx_logger_textfmt:evaluate_lazy_values(LogMap),
-    LogMap1 = emqx_trace_formatter:evaluate_lazy_values(LogMap0),
+    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),

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
+    }.