File 3054-logger-Fix-simple-logger-to-work-when-init-process-i.patch of Package erlang
From 44a998b6ef8913de1152f33e137a9e58111889b8 Mon Sep 17 00:00:00 2001
From: Lukas Larsson <lukas@erlang.org>
Date: Mon, 2 May 2022 22:24:50 +0200
Subject: [PATCH 4/4] logger: Fix simple logger to work when init process is
busy
When wanting to log during system shutdown, the init process
is not always available to load new modules. So we need to
make sure that the simple logger can handle the fact that it
cannot load the correct formatting modules.
---
erts/preloaded/src/init.erl | 1 +
lib/kernel/src/logger_simple_h.erl | 63 ++++++++++++++++-------
lib/kernel/test/logger_simple_h_SUITE.erl | 16 ++++++
3 files changed, 62 insertions(+), 18 deletions(-)
diff --git a/erts/preloaded/src/init.erl b/erts/preloaded/src/init.erl
index 29a6766455..d175ce9a88 100644
--- a/erts/preloaded/src/init.erl
+++ b/erts/preloaded/src/init.erl
@@ -833,6 +833,7 @@ del(_Item, []) -> [].
terminate(Pid,Kernel,Reason) ->
case kernel_pid(Pid,Kernel) of
{ok,Name} ->
+ %% If you change this time, also change the time in logger_simple_h.erl
sleep(500), %% Flush error printouts!
% erlang:display({"Kernel pid terminated",Name,Reason}),
crash("Kernel pid terminated", [Name, Reason]);
diff --git a/lib/kernel/src/logger_simple_h.erl b/lib/kernel/src/logger_simple_h.erl
index db0dce97a7..72b0236183 100644
--- a/lib/kernel/src/logger_simple_h.erl
+++ b/lib/kernel/src/logger_simple_h.erl
@@ -68,14 +68,14 @@ log(#{msg:=_,meta:=#{time:=_}=M}=Log,_Config) ->
%% Log directly from client just to get it out
case maps:get(internal_log_event, M, false) of
false ->
- do_log(
+ do_log(simple,
#{level=>error,
msg=>{report,{error,simple_handler_process_dead}},
meta=>#{time=>logger:timestamp()}});
true ->
ok
end,
- do_log(Log);
+ do_log(simple,Log);
_ ->
?MODULE ! {log,Log}
end,
@@ -90,9 +90,9 @@ log(_,_) ->
init(Starter) ->
register(?MODULE,self()),
Starter ! {self(),started},
- loop(#{buffer_size=>10,dropped=>0,buffer=>[]}).
+ loop(rich, #{buffer_size=>10,dropped=>0,buffer=>[]}).
-loop(Buffer) ->
+loop(Mode, Buffer) ->
receive
stop ->
%% We replay the logger messages if there is
@@ -109,11 +109,11 @@ loop(Buffer) ->
unlink(whereis(logger)),
ok;
{log,#{msg:=_,meta:=#{time:=_}}=Log} ->
- do_log(Log),
- loop(update_buffer(Buffer,Log));
+ NewMode = do_log(Mode, Log),
+ loop(NewMode, update_buffer(Buffer,Log));
_ ->
%% Unexpected message - flush it!
- loop(Buffer)
+ loop(Mode, Buffer)
end.
update_buffer(#{buffer_size:=0,dropped:=D}=Buffer,_Log) ->
@@ -139,16 +139,42 @@ drop_msg(N) ->
%%%-----------------------------------------------------------------
%%% Internal
-do_log(Log) ->
- try
- Str = logger_formatter:format(Log,
- #{ legacy_header => true, single_line => false
- ,depth => unlimited, time_offset => ""
- }),
- erlang:display_string(stdout, lists:flatten(unicode:characters_to_list(Str)))
- catch _E:_R:_ST ->
- % erlang:display({_E,_R,_ST}),
- display_log(Log)
+%% If the init process is busy (for instance doing a shutdown)
+%% we can get blocked while trying to load code. So we spawn a process
+%% for each log message that can potentially block. If the logging cannot
+%% be done within 300ms, we instead log the raw log message to stdout
+%% and switch mode to always log using the raw format.
+do_log(simple, Log) ->
+ display_log(Log), simple;
+do_log(rich = Mode, Log) ->
+
+ {Pid, Ref} =
+ spawn_monitor(
+ fun() ->
+ Str = logger_formatter:format(
+ Log,
+ #{ legacy_header => true, single_line => false,
+ depth => unlimited, time_offset => ""
+ }),
+ erlang:display_string(stdout, lists:flatten(unicode:characters_to_list(Str)))
+ end),
+ receive
+ {'DOWN', Ref, _, _, normal} ->
+ Mode;
+ {'DOWN', Ref, _, _, _Else} ->
+ display_log(Log),
+ Mode
+ after 300 ->
+ %% init:terminate/3 sleeps for 500 ms before exiting,
+ %% so we wait for 300 ms for the log to happen
+ exit(Pid, kill),
+ receive
+ {'DOWN', Ref, _, _, normal} ->
+ Mode;
+ {'DOWN', Ref, _, _, _Else} ->
+ display_log(Log),
+ simple
+ end
end.
display_log(#{msg:={report,Report},
@@ -164,7 +190,8 @@ display_date(Timestamp) when is_integer(Timestamp) ->
Sec = Timestamp div 1000000,
{{Y,Mo,D},{H,Mi,S}} = erlang:universaltime_to_localtime(
erlang:posixtime_to_universaltime(Sec)),
- erlang:display_string(stdout,
+ erlang:display_string(
+ stdout,
integer_to_list(Y) ++ "-" ++
pad(Mo,2) ++ "-" ++
pad(D,2) ++ " " ++
diff --git a/lib/kernel/test/logger_simple_h_SUITE.erl b/lib/kernel/test/logger_simple_h_SUITE.erl
index 8ac52e54c7..9bc910a04b 100644
--- a/lib/kernel/test/logger_simple_h_SUITE.erl
+++ b/lib/kernel/test/logger_simple_h_SUITE.erl
@@ -80,6 +80,7 @@ groups() ->
all() ->
[start_stop,
+ start_crash,
replace_default,
replace_file,
replace_disk_log
@@ -101,6 +102,21 @@ start_stop(_Config) ->
start_stop(cleanup,_Config) ->
logger:remove_handler(simple).
+%% Test that the simple logger works during startup crash
+start_crash(_Config) ->
+
+ Output = os:cmd(ct:get_progname() ++ " -user baduser"),
+ ErrorOutput = re:replace(unicode:characters_to_binary(Output),"\r\n","\n",[global]),
+ ct:log("~ts",[ErrorOutput]),
+ {match,[_]} = re:run(ErrorOutput,"^(=SUPERVISOR REPORT====| supervisor_report *\n)",[global]),
+ {match,[_, _]} = re:run(ErrorOutput," crash_report *\n",[global]),
+ {match,[_]} = re:run(ErrorOutput," std_info *\n",[global]),
+ {match,[[CD]]} = re:run(ErrorOutput,"\nCrash dump is being written to: (.*)\\.\\.\\.done",
+ [{capture, all_but_first, binary}, global]),
+ ok = file:delete(CD),
+ ok.
+
+
%% This testcase just tests that it does not crash, the default handler prints
%% to stdout which we cannot read from in a detached slave.
replace_default(Config) ->
--
2.35.3
