This is an automated email from the ASF dual-hosted git repository.
vatamane pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/couchdb.git
commit 92c7530fc8d5d881cdb452b5412f91b9ead4f1dd
Author: Nick Vatamaniuc <vatam...@apache.org>
AuthorDate: Wed Oct 17 16:24:28 2018 -0400
Do not crash couch_log application when gen_* servers send extra args
gen_server, gen_fsm and gen_statem might send extra args when terminating.
This
is a recent behavior and not handling these extra args could lead to
couch_log
application crashing and taking down the whole VM with it.
There are two improvements to fix the issue:
1) Handle the extra args. Format them and log as they might have useful
information included.
2) Wrap the whole `format` function in a `try ... catch` statement. This
will
avoid any other cases where the logger itself if crashing when attepting to
format error events.
---
src/couch_log/src/couch_log_formatter.erl | 52 +++++++++-------
src/couch_log/test/couch_log_formatter_test.erl | 83 ++++++++++++++++++++++++-
2 files changed, 112 insertions(+), 23 deletions(-)
diff --git a/src/couch_log/src/couch_log_formatter.erl
b/src/couch_log/src/couch_log_formatter.erl
index 5be3619..4d81f18 100644
--- a/src/couch_log/src/couch_log_formatter.erl
+++ b/src/couch_log/src/couch_log_formatter.erl
@@ -56,23 +56,33 @@ format(Level, Pid, Msg) ->
}.
-format({error, _GL, {Pid, "** Generic server " ++ _, Args}}) ->
+format(Event) ->
+ try
+ do_format(Event)
+ catch
+ Tag:Err ->
+ Msg = "Encountered error ~w when formatting ~w",
+ format(error, self(), Msg, [{Tag, Err}, Event])
+ end.
+
+
+do_format({error, _GL, {Pid, "** Generic server " ++ _, Args}}) ->
%% gen_server terminate
- [Name, LastMsg, State, Reason] = Args,
+ [Name, LastMsg, State, Reason | Extra] = Args,
MsgFmt = "gen_server ~w terminated with reason: ~s~n" ++
- " last msg: ~p~n state: ~p",
- MsgArgs = [Name, format_reason(Reason), LastMsg, State],
+ " last msg: ~p~n state: ~p~n extra: ~p",
+ MsgArgs = [Name, format_reason(Reason), LastMsg, State, Extra],
format(error, Pid, MsgFmt, MsgArgs);
-format({error, _GL, {Pid, "** State machine " ++ _, Args}}) ->
+do_format({error, _GL, {Pid, "** State machine " ++ _, Args}}) ->
%% gen_fsm terminate
- [Name, LastMsg, StateName, State, Reason] = Args,
+ [Name, LastMsg, StateName, State, Reason | Extra] = Args,
MsgFmt = "gen_fsm ~w in state ~w terminated with reason: ~s~n" ++
- " last msg: ~p~n state: ~p",
- MsgArgs = [Name, StateName, format_reason(Reason), LastMsg, State],
+ " last msg: ~p~n state: ~p~n extra: ~p",
+ MsgArgs = [Name, StateName, format_reason(Reason), LastMsg, State, Extra],
format(error, Pid, MsgFmt, MsgArgs);
-format({error, _GL, {Pid, "** gen_event handler" ++ _, Args}}) ->
+do_format({error, _GL, {Pid, "** gen_event handler" ++ _, Args}}) ->
%% gen_event handler terminate
[ID, Name, LastMsg, State, Reason] = Args,
MsgFmt = "gen_event ~w installed in ~w terminated with reason: ~s~n" ++
@@ -80,20 +90,20 @@ format({error, _GL, {Pid, "** gen_event handler" ++ _,
Args}}) ->
MsgArgs = [ID, Name, format_reason(Reason), LastMsg, State],
format(error, Pid, MsgFmt, MsgArgs);
-format({error, _GL, {emulator, "~s~n", [Msg]}}) when is_list(Msg) ->
+do_format({error, _GL, {emulator, "~s~n", [Msg]}}) when is_list(Msg) ->
% These messages are for whenever any process exits due
% to a throw or error. We intercept here to remove the
% extra newlines.
NewMsg = lists:sublist(Msg, length(Msg) - 1),
format(error, emulator, NewMsg);
-format({error, _GL, {Pid, Fmt, Args}}) ->
+do_format({error, _GL, {Pid, Fmt, Args}}) ->
format(error, Pid, Fmt, Args);
-format({error_report, _GL, {Pid, std_error, D}}) ->
+do_format({error_report, _GL, {Pid, std_error, D}}) ->
format(error, Pid, print_silly_list(D));
-format({error_report, _GL, {Pid, supervisor_report, D}}) ->
+do_format({error_report, _GL, {Pid, supervisor_report, D}}) ->
case lists:sort(D) of
[{errorContext, Ctx}, {offender, Off},
{reason, Reason}, {supervisor, Name}] ->
@@ -111,20 +121,20 @@ format({error_report, _GL, {Pid, supervisor_report, D}})
->
format(error, Pid, "SUPERVISOR REPORT " ++ print_silly_list(D))
end;
-format({error_report, _GL, {Pid, crash_report, [Report, Neighbors]}}) ->
+do_format({error_report, _GL, {Pid, crash_report, [Report, Neighbors]}}) ->
Msg = "CRASH REPORT " ++ format_crash_report(Report, Neighbors),
format(error, Pid, Msg);
-format({warning_msg, _GL, {Pid, Fmt, Args}}) ->
+do_format({warning_msg, _GL, {Pid, Fmt, Args}}) ->
format(warning, Pid, Fmt, Args);
-format({warning_report, _GL, {Pid, std_warning, Report}}) ->
+do_format({warning_report, _GL, {Pid, std_warning, Report}}) ->
format(warning, Pid, print_silly_list(Report));
-format({info_msg, _GL, {Pid, Fmt, Args}}) ->
+do_format({info_msg, _GL, {Pid, Fmt, Args}}) ->
format(info, Pid, Fmt, Args);
-format({info_report, _GL, {Pid, std_info, D}}) when is_list(D) ->
+do_format({info_report, _GL, {Pid, std_info, D}}) when is_list(D) ->
case lists:sort(D) of
[{application, App}, {exited, Reason}, {type, _Type}] ->
MsgFmt = "Application ~w exited with reason: ~s",
@@ -133,10 +143,10 @@ format({info_report, _GL, {Pid, std_info, D}}) when
is_list(D) ->
format(info, Pid, print_silly_list(D))
end;
-format({info_report, _GL, {Pid, std_info, D}}) ->
+do_format({info_report, _GL, {Pid, std_info, D}}) ->
format(info, Pid, "~w", [D]);
-format({info_report, _GL, {Pid, progress, D}}) ->
+do_format({info_report, _GL, {Pid, progress, D}}) ->
case lists:sort(D) of
[{application, App}, {started_at, Node}] ->
MsgFmt = "Application ~w started on node ~w",
@@ -150,7 +160,7 @@ format({info_report, _GL, {Pid, progress, D}}) ->
format(info, Pid, "PROGRESS REPORT " ++ print_silly_list(D))
end;
-format(Event) ->
+do_format(Event) ->
format(warning, self(), "Unexpected error_logger event ~w", [Event]).
diff --git a/src/couch_log/test/couch_log_formatter_test.erl
b/src/couch_log/test/couch_log_formatter_test.erl
index a8f69b2..795efcf 100644
--- a/src/couch_log/test/couch_log_formatter_test.erl
+++ b/src/couch_log/test/couch_log_formatter_test.erl
@@ -37,6 +37,29 @@ format_reason_test() ->
?assertEqual(Formatted, lists:flatten(Entry#log_entry.msg)).
+crashing_formatting_test() ->
+ Pid = self(),
+ Event = {
+ error,
+ erlang:group_leader(),
+ {
+ Pid,
+ "** Generic server and some stuff",
+ [a_gen_server, {foo, bar}, server_state] % not enough args!
+ }
+ },
+ ?assertMatch(
+ #log_entry{
+ level = error,
+ pid = Pid
+ },
+ do_format(Event)
+ ),
+ do_matches(do_format(Event), [
+ "Encountered error {error,{badmatch"
+ ]).
+
+
gen_server_error_test() ->
Pid = self(),
Event = {
@@ -59,7 +82,35 @@ gen_server_error_test() ->
"gen_server a_gen_server terminated",
"with reason: some_reason",
"last msg: {foo,bar}",
- "state: server_state"
+ "state: server_state",
+ "extra: \\[\\]"
+ ]).
+
+
+gen_server_error_with_extra_args_test() ->
+ Pid = self(),
+ Event = {
+ error,
+ erlang:group_leader(),
+ {
+ Pid,
+ "** Generic server and some stuff",
+ [a_gen_server, {foo, bar}, server_state, some_reason, sad, args]
+ }
+ },
+ ?assertMatch(
+ #log_entry{
+ level = error,
+ pid = Pid
+ },
+ do_format(Event)
+ ),
+ do_matches(do_format(Event), [
+ "gen_server a_gen_server terminated",
+ "with reason: some_reason",
+ "last msg: {foo,bar}",
+ "state: server_state",
+ "extra: \\[sad,args\\]"
]).
@@ -85,7 +136,35 @@ gen_fsm_error_test() ->
"gen_fsm a_gen_fsm in state state_name",
"with reason: barf",
"last msg: {ohai,there}",
- "state: curr_state"
+ "state: curr_state",
+ "extra: \\[\\]"
+ ]).
+
+
+gen_fsm_error_with_extra_args_test() ->
+ Pid = self(),
+ Event = {
+ error,
+ erlang:group_leader(),
+ {
+ Pid,
+ "** State machine did a thing",
+ [a_gen_fsm, {ohai,there}, state_name, curr_state, barf, sad, args]
+ }
+ },
+ ?assertMatch(
+ #log_entry{
+ level = error,
+ pid = Pid
+ },
+ do_format(Event)
+ ),
+ do_matches(do_format(Event), [
+ "gen_fsm a_gen_fsm in state state_name",
+ "with reason: barf",
+ "last msg: {ohai,there}",
+ "state: curr_state",
+ "extra: \\[sad,args\\]"
]).
