Merge pull request #391 from erlang-lager/fsm_test

Format gen_fsm/gen_statem crashes correctly

rebar.config

@@ -21,6 +21,7 @@
 
 {erl_opts, [
     {lager_extra_sinks, ['__lager_test_sink']},
+    {platform_define, "19", test_statem},
     debug_info,
     report,
     verbose,
@@ -47,7 +48,7 @@
 ]}.
 
 {deps, [
-    {goldrush, ".*", {git, "https://github.com/basho/goldrush.git", {tag, "0.1.9"}}}
+    {goldrush, ".*", {git, "https://github.com/DeadZen/goldrush.git", {tag, "0.1.9"}}}
 ]}.
 
 {xref_checks, []}.

src/error_logger_lager_h.erl

@@ -33,7 +33,7 @@
 
 -export([format_reason/1, format_mfa/1, format_args/3]).
 
--record(state, { 
+-record(state, {
         sink :: atom(),
         shaper :: lager_shaper(),
         %% group leader strategy
@@ -88,8 +88,8 @@ handle_event(Event, #state{sink=Sink, shaper=Shaper} = State) ->
         {true, 0, NewShaper} ->
             eval_gl(Event, State#state{shaper=NewShaper});
         {true, Drop, #lager_shaper{hwm=Hwm} = NewShaper} when Drop > 0 ->
-            ?LOGFMT(Sink, warning, self(), 
-                "lager_error_logger_h dropped ~p messages in the last second that exceeded the limit of ~p messages/sec", 
+            ?LOGFMT(Sink, warning, self(),
+                "lager_error_logger_h dropped ~p messages in the last second that exceeded the limit of ~p messages/sec",
                 [Drop, Hwm]),
             eval_gl(Event, State#state{shaper=NewShaper});
         {false, _, NewShaper} ->
@@ -106,9 +106,9 @@ terminate(_Reason, _State) ->
 code_change(_OldVsn, {state, Shaper, GLStrategy}, _Extra) ->
     Raw = lager_app:get_env(lager, error_logger_format_raw, false),
     {ok, #state{
-        sink=configured_sink(), 
-        shaper=Shaper, 
-        groupleader_strategy=GLStrategy, 
+        sink=configured_sink(),
+        shaper=Shaper,
+        groupleader_strategy=GLStrategy,
         raw=Raw
         }};
 code_change(_OldVsn, {state, Sink, Shaper, GLS}, _Extra) ->
@@ -152,12 +152,18 @@ log_event(Event, #state{sink=Sink} = State) ->
                     ?LOGFMT(Sink, error, [{pid, Pid}, {name, Name} | Md], "gen_server ~w terminated with reason: ~s",
                         [Name, Formatted]);
                 {false, "** State machine "++_} ->
-                    %% gen_fsm terminate
-                    [Name, _Msg, StateName, _StateData, Reason] = Args,
+                    %% Check if the terminated process is gen_fsm or gen_statem
+                    %% since they generate the same exit message
+                    {Type, Name, StateName, Reason} = case Args of
+                        [TName, _Msg, TStateName, _StateData, TReason] ->
+                            {gen_fsm, TName, TStateName, TReason};
+                        [TName, _Msg, {TStateName, _StateData}, _ExitType, TReason, _FsmType, Stacktrace] ->
+                            {gen_statem, TName, TStateName, {TReason, Stacktrace}}
+                    end,
                     {Md, Formatted} = format_reason_md(Reason),
                     ?CRASH_LOG(Event),
-                    ?LOGFMT(Sink, error, [{pid, Pid}, {name, Name} | Md], "gen_fsm ~w in state ~w terminated with reason: ~s",
-                        [Name, StateName, Formatted]);
+                    ?LOGFMT(Sink, error, [{pid, Pid}, {name, Name} | Md], "~s ~w in state ~w terminated with reason: ~s",
+                        [Type, Name, StateName, Formatted]);
                 {false, "** gen_event handler"++_} ->
                     %% gen_event handler terminate
                     [ID, Name, _Msg, _State, Reason] = Args,

test/crash_fsm.erl

@@ -0,0 +1,34 @@
+-module(crash_fsm).
+-behaviour(gen_fsm).
+
+-export([start/0, crash/0, state1/2]).
+
+%% gen_fsm callbacks
+-export([init/1, handle_event/3, handle_sync_event/4, handle_info/3,
+         terminate/3, code_change/4]).
+
+-record(state, {}).
+
+start() ->
+    gen_fsm:start({local, ?MODULE}, ?MODULE, [], []).
+
+crash() ->
+    gen_fsm:sync_send_event(?MODULE, crash).
+
+%% gen_fsm callbacks
+init([]) ->
+    {ok, state1, #state{}}.
+
+handle_event(_Event, StateName, State) ->
+    {next_state, StateName, State}.
+handle_sync_event(_Event, _From, StateName, State) ->
+    Reply = ok,
+    {reply, Reply, StateName, State}.
+handle_info(_Info, StateName, State) ->
+    {next_state, StateName, State}.
+terminate(_Reason, _StateName, _State) ->
+    ok.
+code_change(_OldVersion, StateName, State, _Extra) ->
+    {ok, StateName, State}.
+
+state1(_Event, S) -> {next_state, state1, S}.

test/crash_statem.erl

@@ -0,0 +1,42 @@
+-module(crash_statem).
+%% we're only going to compile this on OTP 19+
+-ifdef(test_statem).
+-behaviour(gen_statem).
+
+-export([
+         start/0,
+         crash/0,
+         handle_event/4
+]).
+
+-export([terminate/3,code_change/4,init/1,callback_mode/0]).
+
+start() ->
+    gen_statem:start({local,?MODULE}, ?MODULE, [], []).
+
+crash() ->
+    gen_statem:call(?MODULE, boom).
+
+%% Mandatory callback functions
+terminate(_Reason, _State, _Data) -> ok.
+code_change(_Vsn, State, Data, _Extra) -> {ok,State,Data}.
+init([]) ->
+    %% insert rant here about breaking changes in minor versions...
+    case erlang:system_info(version) of
+        "8.0" -> {callback_mode(),state1,undefined};
+        _ -> {ok, state1, undefined}
+    end.
+callback_mode() -> handle_event_function.
+
+%%% state callback(s)
+
+handle_event({call, _From}, state1, _Arg, Data) ->
+    {next_state, state1, Data}.
+
+-else.
+-export([start/0, crash/0]).
+
+start() -> ok.
+crash() -> ok.
+
+-endif.

test/lager_test_backend.erl

@@ -933,6 +933,99 @@ error_logger_redirect_crash_cleanup(_Sink) ->
     end,
     error_logger:tty(true).
 
+crash_fsm_setup() ->
+    error_logger:tty(false),
+    application:load(lager),
+    application:set_env(lager, error_logger_redirect, true),
+    application:set_env(lager, handlers, [{?MODULE, error}]),
+    lager:start(),
+    crash_fsm:start(),
+    crash_statem:start(),
+    lager:log(error, self(), "flush flush"),
+    timer:sleep(100),
+    gen_event:call(lager_event, ?MODULE, flush),
+    lager_event.
+
+crash_fsm_sink_setup() ->
+    ErrorSink = error_logger_lager_event,
+    error_logger:tty(false),
+    application:load(lager),
+    application:set_env(lager, error_logger_redirect, true),
+    application:set_env(lager, handlers, []),
+    application:set_env(lager, extra_sinks, [{ErrorSink, [{handlers, [{?MODULE, error}]}]}]),
+    lager:start(),
+    crash_fsm:start(),
+    crash_statem:start(),
+    lager:log(ErrorSink, error, self(), "flush flush", []),
+    timer:sleep(100),
+    flush(ErrorSink),
+    ErrorSink.
+
+crash_fsm_cleanup(_Sink) ->
+    application:stop(lager),
+    application:stop(goldrush),
+    application:unset_env(lager, extra_sinks),
+    lists:foreach(fun(N) -> kill_crasher(N) end, [crash_fsm, crash_statem]),
+    error_logger:tty(true).
+
+kill_crasher(RegName) ->
+    case whereis(RegName) of
+        undefined -> ok;
+        Pid -> exit(Pid, kill)
+    end.
+
+spawn_fsm_crash(Module) ->
+    spawn(fun() -> Module:crash() end),
+    timer:sleep(100),
+    _ = gen_event:which_handlers(error_logger),
+    ok.
+
+crash_fsm_test_() ->
+    TestBody = fun(Name, FsmModule, Expected) ->
+                   fun(Sink) ->
+                      {Name,
+                       fun() ->
+                            case {FsmModule =:= crash_statem, lager_util:otp_version() < 19} of
+                                {true, true} -> ok;
+                                _ ->
+                                    Pid = whereis(FsmModule),
+                                    spawn_fsm_crash(FsmModule),
+                                    {Level, _, Msg, Metadata} = pop(Sink),
+                                    test_body(Expected, lists:flatten(Msg)),
+                                    ?assertEqual(Pid, proplists:get_value(pid, Metadata)),
+                                    ?assertEqual(lager_util:level_to_num(error), Level)
+                            end
+                       end
+                      }
+                   end
+               end,
+    Tests = [
+        fun(Sink) ->
+            {"again, there is nothing up my sleeve",
+                fun() ->
+                        ?assertEqual(undefined, pop(Sink)),
+                        ?assertEqual(0, count(Sink))
+                end
+            }
+        end,
+
+        TestBody("gen_fsm crash", crash_fsm, "gen_fsm crash_fsm in state state1 terminated with reason: call to undefined function crash_fsm:state1/3 from gen_fsm:handle_msg/7"),
+        TestBody("gen_statem crash", crash_statem, "gen_statem crash_statem in state state1 terminated with reason: no function clause matching crash_statem:handle")
+    ],
+
+    {"FSM crash output tests", [
+        {"Default sink",
+         {foreach,
+            fun crash_fsm_setup/0,
+            fun crash_fsm_cleanup/1,
+            Tests}},
+        {"Error logger sink",
+         {foreach,
+            fun crash_fsm_sink_setup/0,
+            fun crash_fsm_cleanup/1,
+            Tests}}
+    ]}.
+
 error_logger_redirect_crash_test_() ->
     TestBody=fun(Name,CrashReason,Expected) ->
         fun(Sink) ->