From c72b455a83719957cb28cf9f178d727c3cf7f3e7 Mon Sep 17 00:00:00 2001 From: zhongwencool Date: Wed, 12 Jun 2024 22:51:45 +0800 Subject: [PATCH 1/2] feat: add hidden option to record MFA and line in the log is very useful for debug. --- apps/emqx/include/logger.hrl | 5 +++- apps/emqx/src/config/emqx_config_logger.erl | 17 +++++++------ apps/emqx/src/emqx_logger_jsonfmt.erl | 5 ++-- apps/emqx/src/emqx_logger_textfmt.erl | 22 +++++++++++------ apps/emqx_conf/src/emqx_conf_schema.erl | 11 ++++++++- apps/emqx_utils/src/emqx_utils.erl | 27 +++++++++++++++++++++ 6 files changed, 69 insertions(+), 18 deletions(-) diff --git a/apps/emqx/include/logger.hrl b/apps/emqx/include/logger.hrl index 31fe0e36a..0083a9660 100644 --- a/apps/emqx/include/logger.hrl +++ b/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 diff --git a/apps/emqx/src/config/emqx_config_logger.erl b/apps/emqx/src/config/emqx_config_logger.erl index 73b4d0b3b..a77488cc9 100644 --- a/apps/emqx/src/config/emqx_config_logger.erl +++ b/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 diff --git a/apps/emqx/src/emqx_logger_jsonfmt.erl b/apps/emqx/src/emqx_logger_jsonfmt.erl index d8dcc77dc..dd47d129d 100644 --- a/apps/emqx/src/emqx_logger_jsonfmt.erl +++ b/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) -> diff --git a/apps/emqx/src/emqx_logger_textfmt.erl b/apps/emqx/src/emqx_logger_textfmt.erl index bbba75c51..ee8321f9d 100644 --- a/apps/emqx/src/emqx_logger_textfmt.erl +++ b/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), - fmt(Event1#{msg := Msg2}, Config). + Msg2 = enrich_mfa(Msg1, Meta, 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} diff --git a/apps/emqx_conf/src/emqx_conf_schema.erl b/apps/emqx_conf/src/emqx_conf_schema.erl index 4aa68c1cb..2c0de10aa 100644 --- a/apps/emqx_conf/src/emqx_conf_schema.erl +++ b/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 + } )} ]. diff --git a/apps/emqx_utils/src/emqx_utils.erl b/apps/emqx_utils/src/emqx_utils.erl index 536b427b3..644ed7ae8 100644 --- a/apps/emqx_utils/src/emqx_utils.erl +++ b/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 From 800a79addea59469a68dc62ba9723d9b6da68783 Mon Sep 17 00:00:00 2001 From: zhongwencool Date: Thu, 13 Jun 2024 09:50:52 +0800 Subject: [PATCH 2/2] test: test failed with_mfa --- apps/emqx/src/emqx_vm.erl | 1 - apps/emqx_conf/test/emqx_conf_schema_tests.erl | 3 ++- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/apps/emqx/src/emqx_vm.erl b/apps/emqx/src/emqx_vm.erl index 5877ab184..a694ce95a 100644 --- a/apps/emqx/src/emqx_vm.erl +++ b/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) -> diff --git a/apps/emqx_conf/test/emqx_conf_schema_tests.erl b/apps/emqx_conf/test/emqx_conf_schema_tests.erl index 4b4dff4cf..31699dbe2 100644 --- a/apps/emqx_conf/test/emqx_conf_schema_tests.erl +++ b/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 }} ).