Merge pull request #13241 from zhongwencool/add-with-mfa-option-for-log

feat: add hidden option to record MFA and line in the log

apps/emqx/include/logger.hrl

@@ -30,7 +30,10 @@
             logger:log(
                 Level,
                 (Data),
-                Meta
+                maps:merge(Meta, #{
+                    mfa => {?MODULE, ?FUNCTION_NAME, ?FUNCTION_ARITY},
+                    line => ?LINE
+                })
             );
         false ->
             ok

apps/emqx/src/config/emqx_config_logger.erl

@@ -237,32 +237,35 @@ log_formatter(HandlerName, Conf) ->
             _ ->
                 conf_get("formatter", Conf)
         end,
-    TsFormat = timstamp_format(Conf),
+    TsFormat = timestamp_format(Conf),
+    WithMfa = conf_get("with_mfa", Conf),
     do_formatter(
-        Format, CharsLimit, SingleLine, TimeOffSet, Depth, TsFormat
+        Format, CharsLimit, SingleLine, TimeOffSet, Depth, TsFormat, WithMfa
     ).
 
 %% auto | epoch | rfc3339
-timstamp_format(Conf) ->
+timestamp_format(Conf) ->
     conf_get("timestamp_format", Conf).
 
 %% helpers
-do_formatter(json, CharsLimit, SingleLine, TimeOffSet, Depth, TsFormat) ->
+do_formatter(json, CharsLimit, SingleLine, TimeOffSet, Depth, TsFormat, WithMfa) ->
     {emqx_logger_jsonfmt, #{
         chars_limit => CharsLimit,
         single_line => SingleLine,
         time_offset => TimeOffSet,
         depth => Depth,
-        timestamp_format => TsFormat
+        timestamp_format => TsFormat,
+        with_mfa => WithMfa
     }};
-do_formatter(text, CharsLimit, SingleLine, TimeOffSet, Depth, TsFormat) ->
+do_formatter(text, CharsLimit, SingleLine, TimeOffSet, Depth, TsFormat, WithMfa) ->
     {emqx_logger_textfmt, #{
         template => ["[", level, "] ", msg, "\n"],
         chars_limit => CharsLimit,
         single_line => SingleLine,
         time_offset => TimeOffSet,
         depth => Depth,
-        timestamp_format => TsFormat
+        timestamp_format => TsFormat,
+        with_mfa => WithMfa
     }}.
 
 %% Don't record all logger message

apps/emqx/src/emqx_logger_jsonfmt.erl

@@ -292,6 +292,7 @@ json_obj_root(Data0, Config) ->
             _ ->
                 json(Msg1, Config)
         end,
+    MFA = emqx_utils:format_mfal(Data0, Config),
     Data =
         maps:fold(
             fun(K, V, D) ->
@@ -300,12 +301,12 @@ json_obj_root(Data0, Config) ->
             end,
             [],
             maps:without(
-                [time, gl, file, report_cb, msg, '$kind', level, is_trace], Data0
+                [time, gl, file, report_cb, msg, '$kind', level, mfa, is_trace], Data0
             )
         ),
     lists:filter(
         fun({_, V}) -> V =/= undefined end,
-        [{time, format_ts(Time, Config)}, {level, Level}, {msg, Msg}]
+        [{time, format_ts(Time, Config)}, {level, Level}, {msg, Msg}, {mfa, MFA}]
     ) ++ Data.
 
 format_ts(Ts, #{timestamp_format := rfc3339, time_offset := Offset}) when is_integer(Ts) ->

apps/emqx/src/emqx_logger_textfmt.erl

@@ -24,7 +24,7 @@
 %% 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)).
+check_config(X) -> logger_formatter:check_config(maps:without([timestamp_format, with_mfa], 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
@@ -32,7 +32,7 @@ format(#{msg := {report, ReportMap0}, meta := _Meta} = Event0, Config) when is_m
     #{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),
+    ReportList = enrich_report(ReportMap, Meta, Config),
     Report =
         case is_list_report_acceptable(Meta) of
             true ->
@@ -40,18 +40,24 @@ format(#{msg := {report, ReportMap0}, meta := _Meta} = Event0, Config) when is_m
             false ->
                 maps:from_list(ReportList)
         end,
-    fmt(Event#{msg := {report, Report}}, Config);
+    fmt(Event#{msg := {report, Report}}, maps:remove(with_mfa, Config));
 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(Event#{msg => {"~ts ", [String]}}, maps:remove(with_mfa, 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),
+    Msg2 = enrich_mfa(Msg1, Meta, Config),
-    fmt(Event1#{msg := Msg2}, Config).
+    Msg3 = enrich_topic(Msg2, Meta),
+    fmt(Event1#{msg := Msg3}, maps:remove(with_mfa, Config)).
+
+enrich_mfa({Fmt, Args}, Data, #{with_mfa := true} = Config) when is_list(Fmt) ->
+    {Fmt ++ " mfa: ~ts", Args ++ [emqx_utils:format_mfal(Data, Config)]};
+enrich_mfa(Msg, _, _) ->
+    Msg.
 
 %% 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
@@ -101,7 +107,7 @@ is_list_report_acceptable(#{report_cb := Cb}) ->
 is_list_report_acceptable(_) ->
     false.
 
-enrich_report(ReportRaw, Meta) ->
+enrich_report(ReportRaw, Meta, Config) ->
     %% clientid and peername always in emqx_conn's process metadata.
     %% topic and username can be put in meta using ?SLOG/3, or put in msg's report by ?SLOG/2
     Topic =
@@ -117,6 +123,7 @@ enrich_report(ReportRaw, Meta) ->
     ClientId = maps:get(clientid, Meta, undefined),
     Peer = maps:get(peername, Meta, undefined),
     Msg = maps:get(msg, ReportRaw, undefined),
+    MFA = emqx_utils:format_mfal(Meta, Config),
     %% TODO: move all tags to Meta so we can filter traces
     %% based on tags (currently not supported)
     Tag = maps:get(tag, ReportRaw, maps:get(tag, Meta, undefined)),
@@ -131,6 +138,7 @@ enrich_report(ReportRaw, Meta) ->
             {topic, try_format_unicode(Topic)},
             {username, try_format_unicode(Username)},
             {peername, Peer},
+            {mfa, try_format_unicode(MFA)},
             {msg, Msg},
             {clientid, try_format_unicode(ClientId)},
             {tag, Tag}

apps/emqx/src/emqx_vm.erl

@@ -399,7 +399,6 @@ compat_windows(Fun) when is_function(Fun, 0) ->
             0.0
     end;
 compat_windows(Fun) ->
-    ?SLOG(warning, "Invalid function: ~p", [Fun]),
     error({badarg, Fun}).
 
 load(Avg) ->

apps/emqx_conf/src/emqx_conf_schema.erl

@@ -1247,7 +1247,7 @@ tr_cluster_discovery(Conf) ->
 log_handler_common_confs(Handler, Default) ->
     %% We rarely support dynamic defaults like this.
     %% For this one, we have build-time default the same as runtime default so it's less tricky
-    %% Buildtime default: "" (which is the same as "file")
+    %% Build time default: "" (which is the same as "file")
     %% Runtime default: "file" (because .service file sets EMQX_DEFAULT_LOG_HANDLER to "file")
     EnableValues =
         case Handler of
@@ -1369,6 +1369,15 @@ log_handler_common_confs(Handler, Default) ->
                     desc => ?DESC("common_handler_max_depth"),
                     importance => ?IMPORTANCE_HIDDEN
                 }
+            )},
+        {"with_mfa",
+            sc(
+                boolean(),
+                #{
+                    default => false,
+                    desc => <<"Recording MFA and line in the log(usefully).">>,
+                    importance => ?IMPORTANCE_HIDDEN
+                }
             )}
     ].
 

apps/emqx_conf/test/emqx_conf_schema_tests.erl

@@ -133,7 +133,8 @@ log.file_handlers {
         single_line => true,
         template => ["[", level, "] ", msg, "\n"],
         time_offset => TimeOffset,
-        timestamp_format => auto
+        timestamp_format => auto,
+        with_mfa => false
     }}
 ).
 

apps/emqx_utils/src/emqx_utils.erl

@@ -65,6 +65,7 @@
     flattermap/2,
     tcp_keepalive_opts/4,
     format/1,
+    format_mfal/2,
     call_first_defined/1,
     ntoa/1,
     foldl_while/3,
@@ -565,6 +566,32 @@ tcp_keepalive_opts(OS, _Idle, _Interval, _Probes) ->
 format(Term) ->
     iolist_to_binary(io_lib:format("~0p", [Term])).
 
+%% @doc Helper function for log formatters.
+-spec format_mfal(map(), map()) -> undefined | binary().
+format_mfal(Data, #{with_mfa := true}) ->
+    Line =
+        case maps:get(line, Data, undefined) of
+            undefined ->
+                <<"">>;
+            Num ->
+                ["(", integer_to_list(Num), ")"]
+        end,
+    case maps:get(mfa, Data, undefined) of
+        {M, F, A} ->
+            iolist_to_binary([
+                atom_to_binary(M, utf8),
+                $:,
+                atom_to_binary(F, utf8),
+                $/,
+                integer_to_binary(A),
+                Line
+            ]);
+        _ ->
+            undefined
+    end;
+format_mfal(_, _) ->
+    undefined.
+
 -spec call_first_defined(list({module(), atom(), list()})) -> term() | no_return().
 call_first_defined([{Module, Function, Args} | Rest]) ->
     try