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(-) (limited to 'lib') 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