File 0729-logger-Make-sure-to-not-recursively-crash-for-intern.patch of Package erlang
From 9ae69bfdf3b65dcd0dcd88f22c46d0b7002b1b22 Mon Sep 17 00:00:00 2001
From: Lukas Larsson <lukas@erlang.org>
Date: Tue, 3 Dec 2019 10:50:36 +0100
Subject: [PATCH] logger: Make sure to not recursively crash for internal log
events
If a formatter crashes, this will generate an internal log event that
will be sent to all loggers. If the logger then again crashes this will
create a new log event and so on.
This fix adds a meta-data tag that makes it so that the internal log events
don't continue until infinity but instead stop and are only logger by the
simple logger without any formatters in the end. This so that we can get some
information about what has gone wrong.
---
lib/kernel/src/logger_backend.erl | 3 +++
lib/kernel/src/logger_h_common.erl | 24 ++++++++++++------------
lib/kernel/src/logger_internal.hrl | 12 ++++++------
lib/kernel/src/logger_olp.erl | 4 ++--
lib/kernel/src/logger_proxy.erl | 12 ++++++------
lib/kernel/src/logger_server.erl | 22 +++++++++++++++++++++-
lib/kernel/src/logger_simple_h.erl | 15 ++++++++++-----
lib/kernel/test/logger_SUITE.erl | 7 +++++--
lib/kernel/test/logger_std_h_SUITE.erl | 15 +++++++++++----
9 files changed, 76 insertions(+), 38 deletions(-)
diff --git a/lib/kernel/src/logger_backend.erl b/lib/kernel/src/logger_backend.erl
index 432c671afd..7003d2268e 100644
--- a/lib/kernel/src/logger_backend.erl
+++ b/lib/kernel/src/logger_backend.erl
@@ -56,6 +56,7 @@ call_handlers(#{level:=Level}=Log,[Id|Handlers],Tid) ->
error,{removed_failing_handler,Id}),
?LOG_INTERNAL(
debug,
+ Log1,
[{logger,removed_failing_handler},
{handler,{Id,Module}},
{log_event,Log1},
@@ -68,6 +69,7 @@ call_handlers(#{level:=Level}=Log,[Id|Handlers],Tid) ->
{error,Reason} ->
?LOG_INTERNAL(
debug,
+ Log1,
[{logger,remove_handler_failed},
{reason,Reason}])
end
@@ -119,6 +121,7 @@ handle_filter_failed({Id,_}=Filter,Owner,Log,Reason) ->
ok ->
logger:internal_log(error,{removed_failing_filter,Id}),
?LOG_INTERNAL(debug,
+ Log,
[{logger,removed_failing_filter},
{filter,Filter},
{owner,Owner},
diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl
index 16946ff97c..fb150d181b 100644
--- a/lib/kernel/src/logger_h_common.erl
+++ b/lib/kernel/src/logger_h_common.erl
@@ -392,26 +392,26 @@ do_log_to_binary(Log,Config) ->
String = try_format(Log,Formatter,FormatterConfig),
try string_to_binary(String)
catch C2:R2:S2 ->
- ?LOG_INTERNAL(debug,[{formatter_error,Formatter},
- {config,FormatterConfig},
- {log_event,Log},
- {bad_return_value,String},
- {catched,{C2,R2,S2}}]),
- <<"FORMATTER ERROR: bad return value">>
+ ?LOG_INTERNAL(debug,Log,[{formatter_error,Formatter},
+ {config,FormatterConfig},
+ {log_event,Log},
+ {bad_return_value,String},
+ {catched,{C2,R2,S2}}]),
+ <<"FORMATTER ERROR: bad return value\n">>
end.
try_format(Log,Formatter,FormatterConfig) ->
try Formatter:format(Log,FormatterConfig)
catch
C:R:S ->
- ?LOG_INTERNAL(debug,[{formatter_crashed,Formatter},
- {config,FormatterConfig},
- {log_event,Log},
- {reason,
- {C,R,logger:filter_stacktrace(?MODULE,S)}}]),
+ ?LOG_INTERNAL(debug,Log,[{formatter_crashed,Formatter},
+ {config,FormatterConfig},
+ {log_event,Log},
+ {reason,
+ {C,R,logger:filter_stacktrace(?MODULE,S)}}]),
case {?DEFAULT_FORMATTER,#{}} of
{Formatter,FormatterConfig} ->
- "DEFAULT FORMATTER CRASHED";
+ "DEFAULT FORMATTER CRASHED\n";
{DefaultFormatter,DefaultConfig} ->
try_format(Log#{msg=>{"FORMATTER CRASH: ~tp",
[maps:get(msg,Log)]}},
diff --git a/lib/kernel/src/logger_internal.hrl b/lib/kernel/src/logger_internal.hrl
index c2b2d419e7..019f9d130d 100644
--- a/lib/kernel/src/logger_internal.hrl
+++ b/lib/kernel/src/logger_internal.hrl
@@ -41,14 +41,14 @@
-define(DEFAULT_LOGGER_CALL_TIMEOUT, infinity).
--define(LOG_INTERNAL(Level,Report),?DO_LOG_INTERNAL(Level,[Report])).
--define(LOG_INTERNAL(Level,Format,Args),?DO_LOG_INTERNAL(Level,[Format,Args])).
--define(DO_LOG_INTERNAL(Level,Data),
+-define(LOG_INTERNAL(Level,Log,Report),
+ ?DO_LOG_INTERNAL(Level,Log,[Report])).
+-define(LOG_INTERNAL(Level,Log,Format,Args),
+ ?DO_LOG_INTERNAL(Level,Log,[Format,Args])).
+-define(DO_LOG_INTERNAL(Level,Log,Data),
case logger:allow(Level,?MODULE) of
true ->
- %% Spawn this to avoid deadlocks
- _ = spawn(logger,macro_log,[?LOCATION,Level|Data]++
- [logger:add_default_metadata(#{})]),
+ _ = logger_server:do_internal_log(Level,?LOCATION,Log,Data),
ok;
false ->
ok
diff --git a/lib/kernel/src/logger_olp.erl b/lib/kernel/src/logger_olp.erl
index 8365383fe2..9561dc5789 100644
--- a/lib/kernel/src/logger_olp.erl
+++ b/lib/kernel/src/logger_olp.erl
@@ -147,8 +147,8 @@ restart(Fun) ->
catch C:R:S ->
{error,{restart_failed,Fun,C,R,S}}
end,
- ?LOG_INTERNAL(debug,[{logger_olp,restart},
- {result,Result}]),
+ ?LOG_INTERNAL(debug,#{},[{logger_olp,restart},
+ {result,Result}]),
ok.
-spec get_ref() -> olp_ref().
diff --git a/lib/kernel/src/logger_proxy.erl b/lib/kernel/src/logger_proxy.erl
index 24b293805c..10e53006b9 100644
--- a/lib/kernel/src/logger_proxy.erl
+++ b/lib/kernel/src/logger_proxy.erl
@@ -143,13 +143,13 @@ notify({mode_change,Mode0,Mode1},State) ->
true ->
ok
end,
- ?LOG_INTERNAL(notice,"~w switched from ~w to ~w mode",[?MODULE,Mode0,Mode1]),
+ ?LOG_INTERNAL(notice,#{},"~w switched from ~w to ~w mode",[?MODULE,Mode0,Mode1]),
State;
notify({flushed,Flushed},State) ->
- ?LOG_INTERNAL(notice, "~w flushed ~w log events",[?MODULE,Flushed]),
+ ?LOG_INTERNAL(notice,#{},"~w flushed ~w log events",[?MODULE,Flushed]),
State;
notify(restart,State) ->
- ?LOG_INTERNAL(notice, "~w restarted", [?MODULE]),
+ ?LOG_INTERNAL(notice,#{},"~w restarted", [?MODULE]),
State;
notify(_Note,State) ->
State.
@@ -159,7 +159,7 @@ notify(_Note,State) ->
try_log(Args) ->
try apply(logger,log,Args)
catch C:R:S ->
- ?LOG_INTERNAL(debug,[{?MODULE,log_failed},
- {log,Args},
- {reason,{C,R,S}}])
+ ?LOG_INTERNAL(debug,#{},[{?MODULE,log_failed},
+ {log,Args},
+ {reason,{C,R,S}}])
end.
diff --git a/lib/kernel/src/logger_server.erl b/lib/kernel/src/logger_server.erl
index 722246e82c..9b1483038b 100644
--- a/lib/kernel/src/logger_server.erl
+++ b/lib/kernel/src/logger_server.erl
@@ -31,7 +31,7 @@
update_formatter_config/2]).
%% Helper
--export([diff_maps/2]).
+-export([diff_maps/2,do_internal_log/4]).
%% gen_server callbacks
-export([init/1, handle_call/3, handle_cast/2, handle_info/2,
@@ -359,12 +359,14 @@ handle_info(Unexpected,State) when element(1,Unexpected) == 'EXIT' ->
%% The simple handler will send an 'EXIT' message when it is replaced
%% We may as well ignore all 'EXIT' messages that we get
?LOG_INTERNAL(debug,
+ #{},
[{logger,got_unexpected_message},
{process,?SERVER},
{message,Unexpected}]),
{noreply,State};
handle_info(Unexpected,State) ->
?LOG_INTERNAL(info,
+ #{},
[{logger,got_unexpected_message},
{process,?SERVER},
{message,Unexpected}]),
@@ -550,6 +552,7 @@ call_h(Module, Function, Args, DefRet) ->
_ ->
ST = logger:filter_stacktrace(?MODULE,S),
?LOG_INTERNAL(error,
+ #{},
[{logger,callback_crashed},
{process,?SERVER},
{reason,{C,R,ST}}]),
@@ -592,6 +595,7 @@ call_h_reply({'DOWN',Ref,_Proc,Pid,Reason}, #state{ async_req = {Ref,_PostFun,_F
%% to the spawned process. It is only here to make sure that the logger_server does
%% not deadlock if that happens.
?LOG_INTERNAL(error,
+ #{},
[{logger,process_exited},
{process,Pid},
{reason,Reason}]),
@@ -600,6 +604,7 @@ call_h_reply({'DOWN',Ref,_Proc,Pid,Reason}, #state{ async_req = {Ref,_PostFun,_F
State);
call_h_reply(Unexpected,State) ->
?LOG_INTERNAL(info,
+ #{},
[{logger,got_unexpected_message},
{process,?SERVER},
{message,Unexpected}]),
@@ -615,3 +620,18 @@ diffs([{K,V1}|T1],[{K,V2}|T2],D1,D2) ->
diffs(T1,T2,D1#{K=>V1},D2#{K=>V2});
diffs([],[],D1,D2) ->
{D1,D2}.
+
+do_internal_log(Level,Location,Log,[Report] = Data) ->
+ do_internal_log(Level,Location,Log,Data,{report,Report});
+do_internal_log(Level,Location,Log,[Fmt,Args] = Data) ->
+ do_internal_log(Level,Location,Log,Data,{Fmt,Args}).
+do_internal_log(Level,Location,Log,Data,Msg) ->
+ Meta = logger:add_default_metadata(maps:merge(Location,maps:get(meta,Log,#{}))),
+ %% Spawn these to avoid deadlocks
+ case Log of
+ #{ meta := #{ internal_log_event := true } } ->
+ _ = spawn(logger_simple_h,log,[#{level=>Level,msg=>Msg,meta=>Meta},#{}]);
+ _ ->
+ _ = spawn(logger,macro_log,[Location,Level|Data]++
+ [Meta#{internal_log_event=>true}])
+ end.
diff --git a/lib/kernel/src/logger_simple_h.erl b/lib/kernel/src/logger_simple_h.erl
index a0d51dba25..72dfe8a899 100644
--- a/lib/kernel/src/logger_simple_h.erl
+++ b/lib/kernel/src/logger_simple_h.erl
@@ -61,15 +61,20 @@ log(#{meta:=#{error_logger:=#{tag:=info_report,type:=Type}}},_Config)
%% Skip info reports that are not 'std_info' (ref simple logger in
%% error_logger)
ok;
-log(#{msg:=_,meta:=#{time:=_}}=Log,_Config) ->
+log(#{msg:=_,meta:=#{time:=_}=M}=Log,_Config) ->
_ = case whereis(?MODULE) of
undefined ->
%% Is the node on the way down? Real emergency?
%% Log directly from client just to get it out
- do_log(
- #{level=>error,
- msg=>{report,{error,simple_handler_process_dead}},
- meta=>#{time=>logger:timestamp()}}),
+ case maps:get(internal_log_event, M, false) of
+ false ->
+ do_log(
+ #{level=>error,
+ msg=>{report,{error,simple_handler_process_dead}},
+ meta=>#{time=>logger:timestamp()}});
+ true ->
+ ok
+ end,
do_log(Log);
_ ->
?MODULE ! {log,Log}
diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl
index f8f3d27778..2926cd5585 100644
--- a/lib/kernel/test/logger_SUITE.erl
+++ b/lib/kernel/test/logger_SUITE.erl
@@ -569,6 +569,7 @@ filter_failed(cleanup,_Config) ->
ok.
handler_failed(_Config) ->
+ logger:set_primary_config(level,all),
register(callback_receiver,self()),
{error,{invalid_id,1}} = logger:add_handler(1,?MODULE,#{}),
{error,{invalid_module,"nomodule"}} = logger:add_handler(h1,"nomodule",#{}),
@@ -612,7 +613,7 @@ handler_failed(_Config) ->
logger:add_handler(h1,?MODULE,#{add_call=>KillHandler}),
check_no_log(),
- ok = logger:add_handler(h1,?MODULE,#{}),
+ ok = logger:add_handler(h1,?MODULE,#{tc_proc=>self()}),
{error,{attempting_syncronous_call_to_self,_}} =
logger:set_handler_config(h1,#{conf_call=>CallAddHandler}),
{error,{callback_crashed,_}} =
@@ -628,7 +629,8 @@ handler_failed(_Config) ->
logger:set_handler_config(h1,conf_call,KillHandler),
ok = logger:remove_handler(h1),
- [add,remove] = test_server:messages_get(),
+ [add,{#{level:=error},_},{#{level:=error},_},
+ {#{level:=error},_},{#{level:=error},_},remove] = test_server:messages_get(),
check_no_log(),
ok = logger:add_handler(h1,?MODULE,#{rem_call=>CallAddHandler}),
@@ -644,6 +646,7 @@ handler_failed(_Config) ->
handler_failed(cleanup,_Config) ->
logger:remove_handler(h1),
logger:remove_handler(h2),
+ logger:set_primary_config(level,info),
ok.
config_sanity_check(_Config) ->
diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl
index 602a79c78b..ec0e5122e8 100644
--- a/lib/kernel/test/logger_std_h_SUITE.erl
+++ b/lib/kernel/test/logger_std_h_SUITE.erl
@@ -305,6 +305,8 @@ formatter_fail(Config) ->
Dir = ?config(priv_dir,Config),
Log = filename:join(Dir,?FUNCTION_NAME),
+ logger:set_primary_config(level,all),
+
%% no formatter
ok = logger:add_handler(?MODULE,
logger_std_h,
@@ -346,6 +348,7 @@ formatter_fail(Config) ->
ok.
formatter_fail(cleanup,_Config) ->
+ logger:set_primary_config(level,info),
logger:remove_handler(?MODULE).
config_fail(_Config) ->
@@ -2200,10 +2203,14 @@ check_tracer(T,TimeoutFun) ->
TimeoutFun()
end.
-escape([$+|Rest]) ->
- [$\\,$+|escape(Rest)];
-escape([H|T]) ->
- [H|escape(T)];
+escape([C|Rest]) ->
+ %% The characters that have to be escaped in a regex
+ case lists:member(C,"[-[\]{}()*+?.,\\^$|#\s]") of
+ true ->
+ [$\\,C|escape(Rest)];
+ false ->
+ [C|escape(Rest)]
+ end;
escape([]) ->
[].
--
2.16.4
