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.

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 5be3619f2..4d81f184f 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 a8f69b221..795efcf29 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\\]"
     ]).