From 5ec0ade4105d5d72f318b657bff1a628881cbf9d Mon Sep 17 00:00:00 2001 From: Steve Vinoski Date: Sat, 27 Feb 2010 23:36:20 -0500 Subject: Extend format_status for gen_server/gen_fsm termination error logging When a gen_server or gen_fsm process terminates abnormally, sometimes the text representation of the process state can occupy many lines of the error log, depending on the definition of the state term. Developers sometimes would like a way to trim out parts of the state from the log if those parts don't contribute to documenting the circumstances of the error, thereby helping to reduce the amount of logged output. Since the format_status callback can already format and specialize gen_server and gen_fsm state for inclusion in the term returned from sys:get_status, this patch extends format_status in a backward-compatible way to also be able to specialize the state logged for abnormal gen_server and gen_fsm termination, and includes new unit tests to verify the new functionality. This patch also eliminates the previous restriction that the status returned by format_status must be a list. It can now be any term. The documentation is extended to cover the new usage for format_status, and it's been improved to recommend a form for the normal case that allows the returned status to fit well with the rest of the term returned by sys:get_status. The documentation is clear that this form is only recommended, not required. --- lib/stdlib/doc/src/gen_fsm.xml | 58 +++++++++++++++++++++++++----------- lib/stdlib/doc/src/gen_server.xml | 55 ++++++++++++++++++++++++---------- lib/stdlib/src/gen_fsm.erl | 23 ++++++++++---- lib/stdlib/src/gen_server.erl | 23 ++++++++++---- lib/stdlib/test/gen_fsm_SUITE.erl | 31 +++++++++++++++++-- lib/stdlib/test/gen_server_SUITE.erl | 42 ++++++++++++++++++++++---- 6 files changed, 182 insertions(+), 50 deletions(-) diff --git a/lib/stdlib/doc/src/gen_fsm.xml b/lib/stdlib/doc/src/gen_fsm.xml index 739cd0bffd..a18d31da17 100644 --- a/lib/stdlib/doc/src/gen_fsm.xml +++ b/lib/stdlib/doc/src/gen_fsm.xml @@ -730,33 +730,58 @@ gen_fsm:sync_send_all_state_event -----> Module:handle_sync_event/4 - Module:format_status(normal, [PDict, StateData]) -> Status + Module:format_status(Opt, [PDict, StateData]) -> Status Optional function for providing a term describing the current gen_fsm status. + Opt = normal | terminate PDict = [{Key, Value}] StateData = term() - Status = [term()] + Status = term() -

This callback is optional, so callback modules need not - export it. The gen_fsm module provides a default - implementation of this function that returns the callback - module state data.

-

This function is called by a gen_fsm process when one - of sys:get_status/1,2 - is invoked to get the gen_fsm status. A callback module - wishing to customise the sys:get_status/1,2 return - value exports an instance of format_status/2 that - returns a term describing the current status of the - gen_fsm.

+ +

This callback is optional, so callback modules need not + export it. The gen_fsm module provides a default + implementation of this function that returns the callback + module state data.

+ +

This function is called by a gen_fsm process when:

+ + One + of sys:get_status/1,2 + is invoked to get the gen_fsm status. Opt is set to + the atom normal for this case. + The gen_fsm terminates abnormally and logs an + error. Opt is set to the atom terminate for + this case. + +

This function is useful for customising the form and + appearance of the gen_fsm status for these cases. A callback + module wishing to customise the sys:get_status/1,2 + return value as well as how its status appears in + termination error logs exports an instance + of format_status/2 that returns a term describing the + current status of the gen_fsm.

PDict is the current value of the gen_fsm's process dictionary.

StateData is the internal state data of the gen_fsm.

-

The function should return Status, a list of one or - more terms that customise the details of the current state - and status of the gen_fsm.

+

The function should return Status, a term that + customises the details of the current state and status of + the gen_fsm. There are no restrictions on the + form Status can take, but for + the sys:get_status/1,2 case (when Opt + is normal), the recommended form for + the Status value is [{data, [{"StateData", + Term}]}] where Term provides relevant details of + the gen_fsm state data. Following this recommendation isn't + required, but doing so will make the callback module status + consistent with the rest of the sys:get_status/1,2 + return value.

+

One use for this function is to return compact alternative + state data representations to avoid having large state terms + printed in logfiles.

 @@ -770,4 +795,3 @@ gen_fsm:sync_send_all_state_event -----> Module:handle_sync_event/4 sys(3)

- diff --git a/lib/stdlib/doc/src/gen_server.xml b/lib/stdlib/doc/src/gen_server.xml index 30c04d1d52..7a4aff4b11 100644 --- a/lib/stdlib/doc/src/gen_server.xml +++ b/lib/stdlib/doc/src/gen_server.xml @@ -599,32 +599,57 @@ gen_server:abcast -----> Module:handle_cast/2 - Module:format_status(normal, [PDict, State]) -> Status + Module:format_status(Opt, [PDict, State]) -> Status Optional function for providing a term describing the current gen_server status. + Opt = normal | terminate PDict = [{Key, Value}] State = term() - Status = [term()] + Status = term() -

This callback is optional, so callback modules need not - export it. The gen_server module provides a default - implementation of this function that returns the callback - module state.

-

This function is called by a gen_server process when one + +

This callback is optional, so callback modules need not + export it. The gen_server module provides a default + implementation of this function that returns the callback + module state.

+ +

This function is called by a gen_server process when:

+ + One of sys:get_status/1,2 - is invoked to get the gen_server status. A callback module - wishing to customise the sys:get_status/1,2 return - value exports an instance of format_status/2 that - returns a term describing the current status of the - gen_server.

+ is invoked to get the gen_server status. Opt is set + to the atom normal for this case. + The gen_server terminates abnormally and logs an + error. Opt is set to the atom terminate for this + case. + +

This function is useful for customising the form and + appearance of the gen_server status for these cases. A + callback module wishing to customise + the sys:get_status/1,2 return value as well as how + its status appears in termination error logs exports an + instance of format_status/2 that returns a term + describing the current status of the gen_server.

PDict is the current value of the gen_server's process dictionary.

State is the internal state of the gen_server.

-

The function should return Status, a list of one or - more terms that customise the details of the current state - and status of the gen_server.

+

The function should return Status, a term that + customises the details of the current state and status of + the gen_server. There are no restrictions on the + form Status can take, but for + the sys:get_status/1,2 case (when Opt + is normal), the recommended form for + the Status value is [{data, [{"State", + Term}]}] where Term provides relevant details of + the gen_server state. Following this recommendation isn't + required, but doing so will make the callback module status + consistent with the rest of the sys:get_status/1,2 + return value.

+

One use for this function is to return compact alternative + state representations to avoid having large state terms + printed in logfiles.

 diff --git a/lib/stdlib/src/gen_fsm.erl b/lib/stdlib/src/gen_fsm.erl index 9961646418..8d1b46d6ab 100644 --- a/lib/stdlib/src/gen_fsm.erl +++ b/lib/stdlib/src/gen_fsm.erl @@ -542,7 +542,18 @@ terminate(Reason, Name, Msg, Mod, StateName, StateData, Debug) -> {shutdown,_}=Shutdown -> exit(Shutdown); _ -> - error_info(Reason, Name, Msg, StateName, StateData, Debug), + FmtStateData = + case erlang:function_exported(Mod, format_status, 2) of + true -> + Args = [get(), StateData], + case catch Mod:format_status(terminate, Args) of + {'EXIT', _} -> StateData; + Else -> Else + end; + _ -> + StateData + end, + error_info(Reason,Name,Msg,StateName,FmtStateData,Debug), exit(Reason) end end. @@ -610,15 +621,17 @@ format_status(Opt, StatusData) -> end, Header = lists:concat(["Status for state machine ", NameTag]), Log = sys:get_debug(log, Debug, []), - Specfic = + DefaultStatus = [{data, [{"StateData", StateData}]}], + Specfic = case erlang:function_exported(Mod, format_status, 2) of true -> case catch Mod:format_status(Opt,[PDict,StateData]) of - {'EXIT', _} -> [{data, [{"StateData", StateData}]}]; - Else -> Else + {'EXIT', _} -> DefaultStatus; + StatusList when is_list(StatusList) -> StatusList; + Else -> [Else] end; _ -> - [{data, [{"StateData", StateData}]}] + DefaultStatus end, [{header, Header}, {data, [{"Status", SysState}, diff --git a/lib/stdlib/src/gen_server.erl b/lib/stdlib/src/gen_server.erl index 1c9e5270b6..dc8e7ecd16 100644 --- a/lib/stdlib/src/gen_server.erl +++ b/lib/stdlib/src/gen_server.erl @@ -705,7 +705,18 @@ terminate(Reason, Name, Msg, Mod, State, Debug) -> {shutdown,_}=Shutdown -> exit(Shutdown); _ -> - error_info(Reason, Name, Msg, State, Debug), + FmtState = + case erlang:function_exported(Mod, format_status, 2) of + true -> + Args = [get(), State], + case catch Mod:format_status(terminate, Args) of + {'EXIT', _} -> State; + Else -> Else + end; + _ -> + State + end, + error_info(Reason, Name, Msg, FmtState, Debug), exit(Reason) end end. @@ -836,15 +847,17 @@ format_status(Opt, StatusData) -> end, Header = lists:concat(["Status for generic server ", NameTag]), Log = sys:get_debug(log, Debug, []), - Specfic = + DefaultStatus = [{data, [{"State", State}]}], + Specfic = case erlang:function_exported(Mod, format_status, 2) of true -> case catch Mod:format_status(Opt, [PDict, State]) of - {'EXIT', _} -> [{data, [{"State", State}]}]; - Else -> Else + {'EXIT', _} -> DefaultStatus; + StatusList when is_list(StatusList) -> StatusList; + Else -> [Else] end; _ -> - [{data, [{"State", State}]}] + DefaultStatus end, [{header, Header}, {data, [{"Status", SysState}, diff --git a/lib/stdlib/test/gen_fsm_SUITE.erl b/lib/stdlib/test/gen_fsm_SUITE.erl index 23c1d9a193..1f28216375 100644 --- a/lib/stdlib/test/gen_fsm_SUITE.erl +++ b/lib/stdlib/test/gen_fsm_SUITE.erl @@ -30,7 +30,7 @@ -export([shutdown/1]). --export([sys/1, sys1/1, call_format_status/1]). +-export([sys/1, sys1/1, call_format_status/1, error_format_status/1]). -export([hibernate/1,hiber_idle/3,hiber_wakeup/3,hiber_idle/2,hiber_wakeup/2]). @@ -305,7 +305,7 @@ shutdown(Config) when is_list(Config) -> ok. -sys(suite) -> [sys1, call_format_status]. +sys(suite) -> [sys1, call_format_status, error_format_status]. sys1(Config) when is_list(Config) -> ?line {ok, Pid} = @@ -324,6 +324,27 @@ call_format_status(Config) when is_list(Config) -> ?line [format_status_called | _] = lists:reverse(Data), ?line stop_it(Pid). +error_format_status(Config) when is_list(Config) -> + ?line error_logger_forwarder:register(), + OldFl = process_flag(trap_exit, true), + StateData = "called format_status", + ?line {ok, Pid} = gen_fsm:start(gen_fsm_SUITE, {state_data, StateData}, []), + %% bad return value in the gen_fsm loop + ?line {'EXIT',{{bad_return_value, badreturn},_}} = + (catch gen_fsm:sync_send_event(Pid, badreturn)), + receive + {error,_GroupLeader,{Pid, + "** State machine"++_, + [Pid,{_,_,badreturn},idle,StateData,_]}} -> + ok; + Other -> + ?line io:format("Unexpected: ~p", [Other]), + ?line ?t:fail() + end, + ?t:messages_get(), + process_flag(trap_exit, OldFl), + ok. + %% Hibernation hibernate(suite) -> []; @@ -704,6 +725,8 @@ init(hiber) -> {ok, hiber_idle, []}; init(hiber_now) -> {ok, hiber_idle, [], hibernate}; +init({state_data, StateData}) -> + {ok, idle, StateData}; init(_) -> {ok, idle, state_data}. @@ -844,5 +867,7 @@ handle_sync_event(stop_shutdown_reason, _From, _State, Data) -> handle_sync_event({get, _Pid}, _From, State, Data) -> {reply, {state, State, Data}, State, Data}. -format_status(_Opt, [_Pdict, _StateData]) -> +format_status(terminate, [_Pdict, StateData]) -> + StateData; +format_status(normal, [_Pdict, _StateData]) -> [format_status_called]. diff --git a/lib/stdlib/test/gen_server_SUITE.erl b/lib/stdlib/test/gen_server_SUITE.erl index 0f60c2c4ee..0966734c89 100644 --- a/lib/stdlib/test/gen_server_SUITE.erl +++ b/lib/stdlib/test/gen_server_SUITE.erl @@ -31,7 +31,7 @@ spec_init_local_registered_parent/1, spec_init_global_registered_parent/1, otp_5854/1, hibernate/1, otp_7669/1, call_format_status/1, - call_with_huge_message_queue/1 + error_format_status/1, call_with_huge_message_queue/1 ]). % spawn export @@ -52,7 +52,8 @@ all(suite) -> call_remote_n2, call_remote_n3, spec_init, spec_init_local_registered_parent, spec_init_global_registered_parent, - otp_5854, hibernate, otp_7669, call_format_status, + otp_5854, hibernate, otp_7669, + call_format_status, error_format_status, call_with_huge_message_queue]. -define(default_timeout, ?t:minutes(1)). @@ -897,7 +898,7 @@ call_format_status(doc) -> ["Test that sys:get_status/1,2 calls format_status/2"]; call_format_status(Config) when is_list(Config) -> ?line {ok, Pid} = gen_server:start_link({local, call_format_status}, - gen_server_SUITE, [], []), + ?MODULE, [], []), ?line Status1 = sys:get_status(call_format_status), ?line {status, Pid, _Mod, [_PDict, running, _Parent, _, Data1]} = Status1, ?line [format_status_called | _] = lists:reverse(Data1), @@ -906,6 +907,35 @@ call_format_status(Config) when is_list(Config) -> ?line [format_status_called | _] = lists:reverse(Data2), ok. +%% Verify that error termination correctly calls our format_status/2 fun +%% +error_format_status(suite) -> + []; +error_format_status(doc) -> + ["Test that an error termination calls format_status/2"]; +error_format_status(Config) when is_list(Config) -> + ?line error_logger_forwarder:register(), + OldFl = process_flag(trap_exit, true), + State = "called format_status", + ?line {ok, Pid} = gen_server:start_link(?MODULE, {state, State}, []), + ?line {'EXIT',{crashed,_}} = (catch gen_server:call(Pid, crash)), + receive + {'EXIT', Pid, crashed} -> + ok + end, + receive + {error,_GroupLeader,{Pid, + "** Generic server"++_, + [Pid,crash,State,crashed]}} -> + ok; + Other -> + ?line io:format("Unexpected: ~p", [Other]), + ?line ?t:fail() + end, + ?t:messages_get(), + process_flag(trap_exit, OldFl), + ok. + %% Test that the time for a huge message queue is not %% significantly slower than with an empty message queue. call_with_huge_message_queue(Config) when is_list(Config) -> @@ -1105,5 +1135,7 @@ terminate({From, stopped_info}, _State) -> terminate(_Reason, _State) -> ok. -format_status(_Opt, [_PDict, _State]) -> - [format_status_called]. +format_status(terminate, [_PDict, State]) -> + State; +format_status(normal, [_PDict, _State]) -> + format_status_called. -- cgit v1.2.3 From 6281020ef3ac85afbfbe811de662ae5e1f19901d Mon Sep 17 00:00:00 2001 From: Steve Vinoski Date: Sun, 28 Feb 2010 00:13:10 -0500 Subject: Add support for the format_status callback to gen_event The gen_server and gen_fsm behaviors support the format_status callback to allow developers to specialize how callback module state appears within the return value of sys:get_status and within logged output resulting from abnormal process termination. This patch adds similar support to gen_event. Event handlers that export a format_status/2 function, which is an optional callback, and are registered with an event manager will now have their format_status callbacks invoked when sys:get_status is called on the event manager. The term returned from format_status for this case replaces the default handler state in the sys:get_status return value. This patch also extends gen_event to call an event handler's format_status function (if it exports one) should the handler terminate abnormally. The term returned from format_status is logged in place of the handler's state. This is intended to allow developers to control how much output is logged in the case of abnormal termination. The documentation is appropriately extended and new unit tests are added to cover the new gen_event format_status functionality. --- lib/stdlib/doc/src/gen_event.xml | 58 ++++++++++++++++++++++++++++++++++-- lib/stdlib/src/gen_event.erl | 29 +++++++++++++++--- lib/stdlib/test/dummy1_h.erl | 5 ++-- lib/stdlib/test/gen_event_SUITE.erl | 59 +++++++++++++++++++++++++++++++++++-- 4 files changed, 141 insertions(+), 10 deletions(-) diff --git a/lib/stdlib/doc/src/gen_event.xml b/lib/stdlib/doc/src/gen_event.xml index df09294de6..4f4931eed0 100644 --- a/lib/stdlib/doc/src/gen_event.xml +++ b/lib/stdlib/doc/src/gen_event.xml @@ -630,12 +630,66 @@ gen_event:stop -----> Module:terminate/2

The function should return the updated internal state.

+ + Module:format_status(Opt, [PDict, State]) -> Status + Optional function for providing a term describing the + current event handler state. + + Opt = normal | terminate + PDict = [{Key, Value}] + State = term() + Status = term() + + + +

This callback is optional, so event handler modules need + not export it. If a handler does not export this function, + the gen_event module uses the handler state directly for + the purposes described below.

+ +

This function is called by a gen_event process when:

+ + One + of sys:get_status/1,2 + is invoked to get the gen_event status. Opt is set + to the atom normal for this case. + The event handler terminates abnormally and gen_event + logs an error. Opt is set to the + atom terminate for this case. + +

This function is useful for customising the form and + appearance of the event handler state for these cases. An + event handler callback module wishing to customise + the sys:get_status/1,2 return value as well as how + its state appears in termination error logs exports an + instance of format_status/2 that returns a term + describing the current state of the event handler.

+

PDict is the current value of the gen_event's + process dictionary.

+

State is the internal state of the event + handler.

+

The function should return Status, a term that + customises the details of the current state of the event + handler. Any term is allowed for Status. The + gen_event module uses Status as follows:

+ + When sys:get_status/1,2 is called, gen_event + ensures that its return value contains Status in + place of the event handler's actual state term. + When an event handler terminates abnormally, gen_event + logs Status in place of the event handler's actual + state term. + +

One use for this function is to return compact alternative + state representations to avoid having large state terms + printed in logfiles.

+ +
SEE ALSO -

supervisor(3), +

supervisor(3), sys(3)

- diff --git a/lib/stdlib/src/gen_event.erl b/lib/stdlib/src/gen_event.erl index 27ff9441e6..b1e9e3a02f 100644 --- a/lib/stdlib/src/gen_event.erl +++ b/lib/stdlib/src/gen_event.erl @@ -677,12 +677,23 @@ report_error(Handler, Reason, State, LastIn, SName) -> _ -> Reason end, + Mod = Handler#handler.module, + FmtState = case erlang:function_exported(Mod, format_status, 2) of + true -> + Args = [get(), State], + case catch Mod:format_status(terminate, Args) of + {'EXIT', _} -> State; + Else -> Else + end; + _ -> + State + end, error_msg("** gen_event handler ~p crashed.~n" "** Was installed in ~p~n" "** Last event was: ~p~n" "** When handler state == ~p~n" "** Reason == ~p~n", - [handler(Handler),SName,LastIn,State,Reason1]). + [handler(Handler),SName,LastIn,FmtState,Reason1]). handler(Handler) when not Handler#handler.id -> Handler#handler.module; @@ -711,10 +722,20 @@ get_modules(MSL) -> %%----------------------------------------------------------------- %% Status information %%----------------------------------------------------------------- -format_status(_Opt, StatusData) -> - [_PDict, SysState, Parent, _Debug, [ServerName, MSL, _Hib]] = StatusData, +format_status(Opt, StatusData) -> + [PDict, SysState, Parent, _Debug, [ServerName, MSL, _Hib]] = StatusData, Header = lists:concat(["Status for event handler ", ServerName]), + FmtMSL = [case erlang:function_exported(Mod, format_status, 2) of + true -> + Args = [PDict, State], + case catch Mod:format_status(Opt, Args) of + {'EXIT', _} -> MSL; + Else -> MS#handler{state = Else} + end; + _ -> + MS + end || #handler{module = Mod, state = State} = MS <- MSL], [{header, Header}, {data, [{"Status", SysState}, {"Parent", Parent}]}, - {items, {"Installed handlers", MSL}}]. + {items, {"Installed handlers", FmtMSL}}]. diff --git a/lib/stdlib/test/dummy1_h.erl b/lib/stdlib/test/dummy1_h.erl index 4377d774a3..8bbe729646 100644 --- a/lib/stdlib/test/dummy1_h.erl +++ b/lib/stdlib/test/dummy1_h.erl @@ -21,7 +21,7 @@ %% Test event handler for gen_event_SUITE.erl -export([init/1, handle_event/2, handle_call/2, handle_info/2, - terminate/2]). + terminate/2, format_status/2]). init(make_error) -> {error, my_error}; @@ -67,4 +67,5 @@ terminate(remove_handler, Parent) -> terminate(_Reason, _State) -> ok. - +format_status(_Opt, [_PDict, _State]) -> + "dummy1_h handler state". diff --git a/lib/stdlib/test/gen_event_SUITE.erl b/lib/stdlib/test/gen_event_SUITE.erl index 8cbffaca56..4f7de451e3 100644 --- a/lib/stdlib/test/gen_event_SUITE.erl +++ b/lib/stdlib/test/gen_event_SUITE.erl @@ -23,9 +23,11 @@ -export([all/1]). -export([start/1, test_all/1, add_handler/1, add_sup_handler/1, delete_handler/1, swap_handler/1, swap_sup_handler/1, - notify/1, sync_notify/1, call/1, info/1, hibernate/1]). + notify/1, sync_notify/1, call/1, info/1, hibernate/1, + call_format_status/1, error_format_status/1]). -all(suite) -> {req, [stdlib], [start, test_all, hibernate]}. +all(suite) -> {req, [stdlib], [start, test_all, hibernate, + call_format_status, error_format_status]}. %% -------------------------------------- %% Start an event manager. @@ -844,3 +846,56 @@ info(Config) when is_list(Config) -> ?line ok = gen_event:stop(my_dummy_handler), ok. + +call_format_status(suite) -> + []; +call_format_status(doc) -> + ["Test that sys:get_status/1,2 calls format_status/2"]; +call_format_status(Config) when is_list(Config) -> + ?line {ok, Pid} = gen_event:start({local, my_dummy_handler}), + %% State here intentionally differs from what we expect from format_status + State = self(), + FmtState = "dummy1_h handler state", + ?line ok = gen_event:add_handler(my_dummy_handler, dummy1_h, [State]), + ?line Status1 = sys:get_status(Pid), + ?line Status2 = sys:get_status(Pid, 5000), + ?line ok = gen_event:stop(Pid), + ?line {status, Pid, _, [_, _, Pid, [], Data1]} = Status1, + ?line HandlerInfo1 = proplists:get_value(items, Data1), + ?line {"Installed handlers", [{_,dummy1_h,_,FmtState,_}]} = HandlerInfo1, + ?line {status, Pid, _, [_, _, Pid, [], Data2]} = Status2, + ?line HandlerInfo2 = proplists:get_value(items, Data2), + ?line {"Installed handlers", [{_,dummy1_h,_,FmtState,_}]} = HandlerInfo2, + ok. + +error_format_status(suite) -> + []; +error_format_status(doc) -> + ["Test that a handler error calls format_status/2"]; +error_format_status(Config) when is_list(Config) -> + ?line error_logger_forwarder:register(), + OldFl = process_flag(trap_exit, true), + State = self(), + ?line {ok, Pid} = gen_event:start({local, my_dummy_handler}), + ?line ok = gen_event:add_sup_handler(my_dummy_handler, dummy1_h, [State]), + ?line ok = gen_event:notify(my_dummy_handler, do_crash), + ?line receive + {gen_event_EXIT,dummy1_h,{'EXIT',_}} -> ok + after 5000 -> + ?t:fail(exit_gen_event) + end, + FmtState = "dummy1_h handler state", + receive + {error,_GroupLeader, {Pid, + "** gen_event handler"++_, + [dummy1_h,my_dummy_handler,do_crash, + FmtState, _]}} -> + ok; + Other -> + ?line io:format("Unexpected: ~p", [Other]), + ?line ?t:fail() + end, + ?t:messages_get(), + ?line ok = gen_event:stop(Pid), + process_flag(trap_exit, OldFl), + ok. -- cgit v1.2.3