diff options
author | Raimo Niskanen <[email protected]> | 2018-12-17 10:04:00 +0100 |
---|---|---|
committer | Raimo Niskanen <[email protected]> | 2018-12-17 10:04:00 +0100 |
commit | 0211d244886bf09c2262c55bdf8a9b7c29280e89 (patch) | |
tree | bc01747342d739277210ce30fe88aba58f9f8021 /lib/stdlib | |
parent | 501ff83ade9ee2e8b88bc0c2c6d34f357fc57b6d (diff) | |
parent | 9f2c972e88f8fc8581c9e90b1fcccf9f5c7f1c0f (diff) | |
download | otp-0211d244886bf09c2262c55bdf8a9b7c29280e89.tar.gz otp-0211d244886bf09c2262c55bdf8a9b7c29280e89.tar.bz2 otp-0211d244886bf09c2262c55bdf8a9b7c29280e89.zip |
Merge branch 'raimo/stdlib/sys-log-of-gen-in-terminate-report/OTP-15381'
* raimo/stdlib/sys-log-of-gen-in-terminate-report/OTP-15381:
sys:log timeout 0 events
Filter gen_server State in crash sys:log
Fix statement duplication
Document system_events better
Adjust sys:log(N, get) to documentation
Unify system_events in gen_*
Log code change
Use from/1 type check
Limit more error_logger terms
Add client stacktrace
Print sys:log in error report
Optimize sys:handle_debug/4
Optimize sys:log
Fix sys:log functionality
Conflicts:
lib/stdlib/doc/src/sys.xml
Diffstat (limited to 'lib/stdlib')
-rw-r--r-- | lib/stdlib/doc/src/sys.xml | 166 | ||||
-rw-r--r-- | lib/stdlib/src/gen_fsm.erl | 154 | ||||
-rw-r--r-- | lib/stdlib/src/gen_server.erl | 53 | ||||
-rw-r--r-- | lib/stdlib/src/gen_statem.erl | 280 | ||||
-rw-r--r-- | lib/stdlib/src/otp_internal.erl | 8 | ||||
-rw-r--r-- | lib/stdlib/src/sys.erl | 150 | ||||
-rw-r--r-- | lib/stdlib/test/gen_fsm_SUITE.erl | 12 | ||||
-rw-r--r-- | lib/stdlib/test/gen_statem_SUITE.erl | 43 | ||||
-rw-r--r-- | lib/stdlib/test/stdlib_bench_SUITE.erl | 57 | ||||
-rw-r--r-- | lib/stdlib/test/stdlib_bench_SUITE_data/generic_server.erl | 4 | ||||
-rw-r--r-- | lib/stdlib/test/stdlib_bench_SUITE_data/generic_statem.erl | 4 |
11 files changed, 706 insertions, 225 deletions
diff --git a/lib/stdlib/doc/src/sys.xml b/lib/stdlib/doc/src/sys.xml index 6fc508b853..c5075f31c5 100644 --- a/lib/stdlib/doc/src/sys.xml +++ b/lib/stdlib/doc/src/sys.xml @@ -114,6 +114,154 @@ </datatype> <datatype> <name name="system_event"/> + <desc> + <taglist> + <tag><c>{in,<anno>Msg</anno>}</c></tag> + <item> + <p> + Is produced by <c>gen_server</c> and <c>gen_event</c> + when the message <c>Msg</c> arrives. + </p> + </item> + <tag><c>{in,<anno>Msg</anno>,<anno>State</anno>}</c></tag> + <item> + <p> + Is produced by <c>gen_statem</c> + when the message <c>Msg</c> arrives in state <c>State</c>. + </p> + <p> + For <c>gen_statem</c> the <c><anno>Msg</anno></c> term is + an <c>{EventType,EventContent}</c> tuple. + </p> + </item> + <tag><c>{out,<anno>Msg</anno>,<anno>To</anno>}</c></tag> + <item> + <p> + Is produced by <c>gen_statem</c> when the reply <c>Msg</c> + is sent back to <c>To</c> by returning + a <c>{reply,To,Msg}</c> action from the callback module. + </p> + <p> + <c><anno>To</anno></c> is of the same type + as the first argument to <c>gen_statem:reply/2</c>. + </p> + </item> + <tag> + <c>{out,<anno>Msg</anno>,<anno>To</anno>,<anno>State</anno>}</c> + </tag> + <item> + <p> + Is produced by <c>gen_server</c> + when the reply <c><anno>Msg</anno></c> + is sent back to <c><anno>To</anno></c> + by returning a <c>{reply,...}</c> tuple + from the callback module. + </p> + <p> + <c><anno>To</anno></c> is of the same type + as the first argument to <c>gen_server:reply/2</c>. + </p> + <p> + <c><anno>State</anno></c> is the new server state. + </p> + </item> + <tag> + <c>{noreply,<anno>State</anno>}</c> + </tag> + <item> + <p> + Is produced by <c>gen_server</c> + when a <c>{noreply,...}</c> tuple is returned + from the callback module. + </p> + <p> + <c><anno>State</anno></c> is the new server state. + </p> + </item> + <tag> + <c>{continue,<anno>Continuation</anno>}</c> + </tag> + <item> + <p> + Is produced by <c>gen_server</c> + when a <c>{continue,<anno>Continuation</anno>}</c> + tuple is returned from the callback module. + </p> + </item> + <tag> + <c>{code_change,<anno>Event</anno>,<anno>State</anno>}</c> + </tag> + <item> + <p> + Is produced by <c>gen_statem</c> + when the message <c><anno>Event</anno></c> + arrives in state <c><anno>State</anno></c> + as the first event after a code change. + </p> + <p> + <c><anno>Event</anno></c> is + an <c>{EventType,EventContent}</c> tuple. + </p> + </item> + <tag> + <c> + {postpone,<anno>Event</anno>,<anno>State</anno>,<anno>NextState</anno>} + </c> + </tag> + <item> + <p> + Is produced by <c>gen_statem</c> + when the message <c><anno>Event</anno></c> + is postponed in state <c><anno>State</anno></c>. + <c><anno>NextState</anno></c> is the new state. + </p> + <p> + <c><anno>Event</anno></c> is + an <c>{EventType,EventContent}</c> tuple. + </p> + </item> + <tag> + <c> + {consume,<anno>Event</anno>,<anno>State</anno>,<anno>NextState</anno>} + </c> + </tag> + <item> + <p> + Is produced by <c>gen_statem</c> + when the message <c><anno>Event</anno></c> + is consumed in state <c><anno>State</anno></c>. + <c><anno>NextState</anno></c> is the new state. + </p> + <p> + <c><anno>Event</anno></c> is + an <c>{EventType,EventContent}</c> tuple. + </p> + </item> + <tag> + <c> + {enter,<anno>State</anno>} + </c> + </tag> + <item> + <p> + Is produced by <c>gen_statem</c> + when the first state <c><anno>State</anno></c> is entered. + </p> + </item> + <tag> + <c> + {terminate,<anno>Reason</anno>,<anno>State</anno>} + </c> + </tag> + <item> + <p> + Is produced by <c>gen_statem</c> + when it terminates with reason <c><anno>Reason</anno></c> + in state <c><anno>State</anno></c>. + </p> + </item> + </taglist> + </desc> </datatype> <datatype> <name name="dbg_opt"/> @@ -532,6 +680,12 @@ <name name="get_debug" arity="3" since=""/> <fsummary>Get the data associated with a debug option.</fsummary> <desc> + <warning> + <p> + <c>get_debug/3</c> is deprecated since it returns + data of an internal type only useful for debugging. + </p> + </warning> <p>Gets the data associated with a debug option. <c><anno>Default</anno></c> is returned if <c><anno>Item</anno></c> is not found. Can be @@ -605,6 +759,18 @@ </func> <func> + <name name="get_log" arity="1" since="OTP-22.0"/> + <fsummary>Return the logged events in the debug structure.</fsummary> + <desc> + <p> + Returns the logged system events in the debug structure, + that is the last argument to + <seealso marker="#handle_debug/4"><c>handle_debug/4</c></seealso>. + </p> + </desc> + </func> + + <func> <name since="">Module:system_code_change(Misc, Module, OldVsn, Extra) -> {ok, NMisc}</name> <fsummary>Called when the process is to perform a code change.</fsummary> diff --git a/lib/stdlib/src/gen_fsm.erl b/lib/stdlib/src/gen_fsm.erl index caaaf8fa2e..1e18710738 100644 --- a/lib/stdlib/src/gen_fsm.erl +++ b/lib/stdlib/src/gen_fsm.erl @@ -411,12 +411,13 @@ decode_msg(Msg,Parent, Name, StateName, StateData, Mod, Time, HibernateAfterTime sys:handle_system_msg(Req, From, Parent, ?MODULE, Debug, [Name, StateName, StateData, Mod, Time, HibernateAfterTimeout], Hib); {'EXIT', Parent, Reason} -> - terminate(Reason, Name, Msg, Mod, StateName, StateData, Debug); + terminate( + Reason, Name, undefined, Msg, Mod, StateName, StateData, Debug); _Msg when Debug =:= [] -> handle_msg(Msg, Parent, Name, StateName, StateData, Mod, Time, HibernateAfterTimeout); _Msg -> Debug1 = sys:handle_debug(Debug, fun print_event/3, - {Name, StateName}, {in, Msg}), + Name, {in, Msg, StateName}), handle_msg(Msg, Parent, Name, StateName, StateData, Mod, Time, HibernateAfterTimeout, Debug1) end. @@ -431,7 +432,7 @@ system_continue(Parent, Debug, [Name, StateName, StateData, Mod, Time, Hibernate system_terminate(Reason, _Parent, Debug, [Name, StateName, StateData, Mod, _Time, _HibernateAfterTimeout]) -> - terminate(Reason, Name, [], Mod, StateName, StateData, Debug). + terminate(Reason, Name, undefined, [], Mod, StateName, StateData, Debug). system_code_change([Name, StateName, StateData, Mod, Time, HibernateAfterTimeout], _Module, OldVsn, Extra) -> @@ -452,7 +453,7 @@ system_replace_state(StateFun, [Name, StateName, StateData, Mod, Time, Hibernate %% Format debug messages. Print them as the call-back module sees %% them, not as the real erlang messages. Use trace for that. %%----------------------------------------------------------------- -print_event(Dev, {in, Msg}, {Name, StateName}) -> +print_event(Dev, {in, Msg, StateName}, Name) -> case Msg of {'$gen_event', Event} -> io:format(Dev, "*DBG* ~tp got event ~tp in state ~tw~n", @@ -461,6 +462,16 @@ print_event(Dev, {in, Msg}, {Name, StateName}) -> io:format(Dev, "*DBG* ~tp got all_state_event ~tp in state ~tw~n", [Name, Event, StateName]); + {'$gen_sync_event', {From,_Tag}, Event} -> + io:format(Dev, + "*DBG* ~tp got sync_event ~tp " + "from ~tw in state ~tw~n", + [Name, Event, From, StateName]); + {'$gen_sync_all_state_event', {From,_Tag}, Event} -> + io:format(Dev, + "*DBG* ~tp got sync_all_state_event ~tp " + "from ~tw in state ~tw~n", + [Name, Event, From, StateName]); {timeout, Ref, {'$gen_timer', Message}} -> io:format(Dev, "*DBG* ~tp got timer ~tp in state ~tw~n", @@ -473,11 +484,11 @@ print_event(Dev, {in, Msg}, {Name, StateName}) -> io:format(Dev, "*DBG* ~tp got ~tp in state ~tw~n", [Name, Msg, StateName]) end; -print_event(Dev, {out, Msg, To, StateName}, Name) -> +print_event(Dev, {out, Msg, {To,_Tag}, StateName}, Name) -> io:format(Dev, "*DBG* ~tp sent ~tp to ~tw~n" " and switched to state ~tw~n", [Name, Msg, To, StateName]); -print_event(Dev, return, {Name, StateName}) -> +print_event(Dev, {noreply, StateName}, Name) -> io:format(Dev, "*DBG* ~tp switched to state ~tw~n", [Name, StateName]). @@ -495,9 +506,9 @@ handle_msg(Msg, Parent, Name, StateName, StateData, Mod, _Time, HibernateAfterTi reply(From, Reply), loop(Parent, Name, NStateName, NStateData, Mod, Time1, HibernateAfterTimeout, []); {stop, Reason, NStateData} -> - terminate(Reason, Name, Msg, Mod, StateName, NStateData, []); + terminate(Reason, Name, From, Msg, Mod, StateName, NStateData, []); {stop, Reason, Reply, NStateData} when From =/= undefined -> - {'EXIT', R} = (catch terminate(Reason, Name, Msg, Mod, + {'EXIT', R} = (catch terminate(Reason, Name, From, Msg, Mod, StateName, NStateData, [])), reply(From, Reply), exit(R); @@ -510,10 +521,10 @@ handle_msg(Msg, Parent, Name, StateName, StateData, Mod, _Time, HibernateAfterTi error_logger=>#{tag=>warning_msg}}), loop(Parent, Name, StateName, StateData, Mod, infinity, HibernateAfterTimeout, []); {'EXIT', What} -> - terminate(What, Name, Msg, Mod, StateName, StateData, []); + terminate(What, Name, From, Msg, Mod, StateName, StateData, []); Reply -> terminate({bad_return_value, Reply}, - Name, Msg, Mod, StateName, StateData, []) + Name, From, Msg, Mod, StateName, StateData, []) end. handle_msg(Msg, Parent, Name, StateName, StateData, Mod, _Time, HibernateAfterTimeout, Debug) -> @@ -521,11 +532,11 @@ handle_msg(Msg, Parent, Name, StateName, StateData, Mod, _Time, HibernateAfterTi case catch dispatch(Msg, Mod, StateName, StateData) of {next_state, NStateName, NStateData} -> Debug1 = sys:handle_debug(Debug, fun print_event/3, - {Name, NStateName}, return), + Name, {noreply, NStateName}), loop(Parent, Name, NStateName, NStateData, Mod, infinity, HibernateAfterTimeout, Debug1); {next_state, NStateName, NStateData, Time1} -> Debug1 = sys:handle_debug(Debug, fun print_event/3, - {Name, NStateName}, return), + Name, {noreply, NStateName}), loop(Parent, Name, NStateName, NStateData, Mod, Time1, HibernateAfterTimeout, Debug1); {reply, Reply, NStateName, NStateData} when From =/= undefined -> Debug1 = reply(Name, From, Reply, Debug, NStateName), @@ -534,17 +545,18 @@ handle_msg(Msg, Parent, Name, StateName, StateData, Mod, _Time, HibernateAfterTi Debug1 = reply(Name, From, Reply, Debug, NStateName), loop(Parent, Name, NStateName, NStateData, Mod, Time1, HibernateAfterTimeout, Debug1); {stop, Reason, NStateData} -> - terminate(Reason, Name, Msg, Mod, StateName, NStateData, Debug); + terminate( + Reason, Name, From, Msg, Mod, StateName, NStateData, Debug); {stop, Reason, Reply, NStateData} when From =/= undefined -> - {'EXIT', R} = (catch terminate(Reason, Name, Msg, Mod, + {'EXIT', R} = (catch terminate(Reason, Name, From, Msg, Mod, StateName, NStateData, Debug)), _ = reply(Name, From, Reply, Debug, StateName), exit(R); {'EXIT', What} -> - terminate(What, Name, Msg, Mod, StateName, StateData, Debug); + terminate(What, Name, From, Msg, Mod, StateName, StateData, Debug); Reply -> terminate({bad_return_value, Reply}, - Name, Msg, Mod, StateName, StateData, Debug) + Name, From, Msg, Mod, StateName, StateData, Debug) end. dispatch({'$gen_event', Event}, Mod, StateName, StateData) -> @@ -571,24 +583,25 @@ from(_) -> undefined. reply({To, Tag}, Reply) -> catch To ! {Tag, Reply}. -reply(Name, {To, Tag}, Reply, Debug, StateName) -> - reply({To, Tag}, Reply), +reply(Name, From, Reply, Debug, StateName) -> + reply(From, Reply), sys:handle_debug(Debug, fun print_event/3, Name, - {out, Reply, To, StateName}). + {out, Reply, From, StateName}). %%% --------------------------------------------------- %%% Terminate the server. %%% --------------------------------------------------- --spec terminate(term(), _, _, atom(), _, _, _) -> no_return(). +-spec terminate(term(), _, _, _, atom(), _, _, _) -> no_return(). -terminate(Reason, Name, Msg, Mod, StateName, StateData, Debug) -> +terminate(Reason, Name, From, Msg, Mod, StateName, StateData, Debug) -> case erlang:function_exported(Mod, terminate, 3) of true -> case catch Mod:terminate(Reason, StateName, StateData) of {'EXIT', R} -> FmtStateData = format_status(terminate, Mod, get(), StateData), - error_info(R, Name, Msg, StateName, FmtStateData, Debug), + error_info( + R, Name, From, Msg, StateName, FmtStateData, Debug), exit(R); _ -> ok @@ -605,29 +618,51 @@ terminate(Reason, Name, Msg, Mod, StateName, StateData, Debug) -> exit(Shutdown); _ -> FmtStateData1 = format_status(terminate, Mod, get(), StateData), - error_info(Reason,Name,Msg,StateName,FmtStateData1,Debug), + error_info( + Reason, Name, From, Msg, StateName, FmtStateData1, Debug), exit(Reason) end. -error_info(Reason, Name, Msg, StateName, StateData, Debug) -> +error_info(Reason, Name, From, Msg, StateName, StateData, Debug) -> + Log = sys:get_log(Debug), ?LOG_ERROR(#{label=>{gen_fsm,terminate}, name=>Name, last_message=>Msg, state_name=>StateName, state_data=>StateData, - reason=>Reason}, + log=>Log, + reason=>Reason, + client_info=>client_stacktrace(From)}, #{domain=>[otp], report_cb=>fun gen_fsm:format_log/1, error_logger=>#{tag=>error}}), - sys:print_log(Debug), ok. +client_stacktrace(undefined) -> + undefined; +client_stacktrace({Pid,_Tag}) -> + client_stacktrace(Pid); +client_stacktrace(Pid) when is_pid(Pid), node(Pid) =:= node() -> + case process_info(Pid, [current_stacktrace, registered_name]) of + undefined -> + {Pid,dead}; + [{current_stacktrace, Stacktrace}, {registered_name, []}] -> + {Pid,{Pid,Stacktrace}}; + [{current_stacktrace, Stacktrace}, {registered_name, Name}] -> + {Pid,{Name,Stacktrace}} + end; +client_stacktrace(Pid) when is_pid(Pid) -> + {Pid,remote}. + + format_log(#{label:={gen_fsm,terminate}, name:=Name, last_message:=Msg, state_name:=StateName, state_data:=StateData, - reason:=Reason}) -> + log:=Log, + reason:=Reason, + client_info:=ClientInfo}) -> Reason1 = case Reason of {undef,[{M,F,A,L}|MFAs]} -> @@ -645,27 +680,39 @@ format_log(#{label:={gen_fsm,terminate}, _ -> Reason end, + {ClientFmt,ClientArgs} = format_client_log(ClientInfo), {"** State machine ~tp terminating \n" ++ get_msg_str(Msg) ++ "** When State == ~tp~n" "** Data == ~tp~n" - "** Reason for termination = ~n** ~tp~n", - [Name, get_msg(Msg), StateName, StateData, Reason1]}; + "** Reason for termination ==~n** ~tp~n" ++ + case Log of + [] -> []; + _ -> "** Log ==~n** ~tp~n" + end ++ ClientFmt, + [Name|error_logger:limit_term(get_msg(Msg))] ++ + [StateName, + error_logger:limit_term(StateData), + error_logger:limit_term(Reason1) | + case Log of + [] -> []; + _ -> [[error_logger:limit_term(D) || D <- Log]] + end] ++ ClientArgs}; format_log(#{label:={gen_fsm,no_handle_info}, module:=Mod, message:=Msg}) -> {"** Undefined handle_info in ~p~n" "** Unhandled message: ~tp~n", - [Mod, Msg]}. + [Mod, error_logger:limit_term(Msg)]}. get_msg_str({'$gen_event', _Event}) -> "** Last event in was ~tp~n"; -get_msg_str({'$gen_sync_event', _Event}) -> - "** Last sync event in was ~tp~n"; +get_msg_str({'$gen_sync_event', _From, _Event}) -> + "** Last sync event in was ~tp from ~tw~n"; get_msg_str({'$gen_all_state_event', _Event}) -> "** Last event in was ~tp (for all states)~n"; -get_msg_str({'$gen_sync_all_state_event', _Event}) -> - "** Last sync event in was ~tp (for all states)~n"; +get_msg_str({'$gen_sync_all_state_event', _From, _Event}) -> + "** Last sync event in was ~tp (for all states) from ~tw~n"; get_msg_str({timeout, _Ref, {'$gen_timer', _Msg}}) -> "** Last timer event in was ~tp~n"; get_msg_str({timeout, _Ref, {'$gen_event', _Msg}}) -> @@ -673,13 +720,24 @@ get_msg_str({timeout, _Ref, {'$gen_event', _Msg}}) -> get_msg_str(_Msg) -> "** Last message in was ~tp~n". -get_msg({'$gen_event', Event}) -> Event; -get_msg({'$gen_sync_event', Event}) -> Event; -get_msg({'$gen_all_state_event', Event}) -> Event; -get_msg({'$gen_sync_all_state_event', Event}) -> Event; -get_msg({timeout, Ref, {'$gen_timer', Msg}}) -> {timeout, Ref, Msg}; -get_msg({timeout, _Ref, {'$gen_event', Event}}) -> Event; -get_msg(Msg) -> Msg. +get_msg({'$gen_event', Event}) -> [Event]; +get_msg({'$gen_sync_event', {From,_Tag}, Event}) -> [Event,From]; +get_msg({'$gen_all_state_event', Event}) -> [Event]; +get_msg({'$gen_sync_all_state_event', {From,_Tag}, Event}) -> [Event,From]; +get_msg({timeout, Ref, {'$gen_timer', Msg}}) -> [{timeout, Ref, Msg}]; +get_msg({timeout, _Ref, {'$gen_event', Event}}) -> [Event]; +get_msg(Msg) -> [Msg]. + +format_client_log(undefined) -> + {"", []}; +format_client_log({From,dead}) -> + {"** Client ~p is dead~n", [From]}; +format_client_log({From,remote}) -> + {"** Client ~p is remote on node ~p~n", [From, node(From)]}; +format_client_log({_From,{Name,Stacktrace}}) -> + {"** Client ~tp stacktrace~n" + "** ~tp~n", + [Name, error_logger:limit_term(Stacktrace)]}. %%----------------------------------------------------------------- %% Status information @@ -689,18 +747,18 @@ format_status(Opt, StatusData) -> StatusData, Header = gen:format_status_header("Status for state machine", Name), - Log = sys:get_debug(log, Debug, []), - Specfic = format_status(Opt, Mod, PDict, StateData), - Specfic = case format_status(Opt, Mod, PDict, StateData) of - S when is_list(S) -> S; - S -> [S] - end, + Log = sys:get_log(Debug), + Specific = + case format_status(Opt, Mod, PDict, StateData) of + S when is_list(S) -> S; + S -> [S] + end, [{header, Header}, {data, [{"Status", SysState}, {"Parent", Parent}, {"Logged events", Log}, {"StateName", StateName}]} | - Specfic]. + Specific]. format_status(Opt, Mod, PDict, State) -> DefStatus = case Opt of diff --git a/lib/stdlib/src/gen_server.erl b/lib/stdlib/src/gen_server.erl index 44e9231ebe..c7b6406f54 100644 --- a/lib/stdlib/src/gen_server.erl +++ b/lib/stdlib/src/gen_server.erl @@ -773,10 +773,10 @@ handle_common_reply(Reply, Parent, Name, From, Msg, Mod, HibernateAfterTimeout, terminate({bad_return_value, BadReply}, ?STACKTRACE(), Name, From, Msg, Mod, State, Debug) end. -reply(Name, {To, Tag}, Reply, State, Debug) -> - reply({To, Tag}, Reply), +reply(Name, From, Reply, State, Debug) -> + reply(From, Reply), sys:handle_debug(Debug, fun print_event/3, Name, - {out, Reply, To, State} ). + {out, Reply, From, State} ). %%----------------------------------------------------------------- @@ -810,7 +810,7 @@ system_replace_state(StateFun, [Name, State, Mod, Time, HibernateAfterTimeout]) print_event(Dev, {in, Msg}, Name) -> case Msg of {'$gen_call', {From, _Tag}, Call} -> - io:format(Dev, "*DBG* ~tp got call ~tp from ~w~n", + io:format(Dev, "*DBG* ~tp got call ~tp from ~tw~n", [Name, Call, From]); {'$gen_cast', Cast} -> io:format(Dev, "*DBG* ~tp got cast ~tp~n", @@ -818,8 +818,8 @@ print_event(Dev, {in, Msg}, Name) -> _ -> io:format(Dev, "*DBG* ~tp got ~tp~n", [Name, Msg]) end; -print_event(Dev, {out, Msg, To, State}, Name) -> - io:format(Dev, "*DBG* ~tp sent ~tp to ~w, new state ~tp~n", +print_event(Dev, {out, Msg, {To,_Tag}, State}, Name) -> + io:format(Dev, "*DBG* ~tp sent ~tp to ~tw, new state ~tp~n", [Name, Msg, To, State]); print_event(Dev, {noreply, State}, Name) -> io:format(Dev, "*DBG* ~tp new state ~tp~n", [Name, State]); @@ -885,16 +885,17 @@ error_info(_Reason, application_controller, _From, _Msg, _Mod, _State, _Debug) - %% of it instead ok; error_info(Reason, Name, From, Msg, Mod, State, Debug) -> + Log = sys:get_log(Debug), ?LOG_ERROR(#{label=>{gen_server,terminate}, name=>Name, last_message=>Msg, state=>format_status(terminate, Mod, get(), State), + log=>format_log_state(Mod, Log), reason=>Reason, client_info=>client_stacktrace(From)}, #{domain=>[otp], report_cb=>fun gen_server:format_log/1, error_logger=>#{tag=>error}}), - sys:print_log(Debug), ok. client_stacktrace(undefined) -> @@ -917,6 +918,7 @@ format_log(#{label:={gen_server,terminate}, name:=Name, last_message:=Msg, state:=State, + log:=Log, reason:=Reason, client_info:=Client}) -> Reason1 = @@ -934,20 +936,30 @@ format_log(#{label:={gen_server,terminate}, end end; _ -> - error_logger:limit_term(Reason) + Reason end, {ClientFmt,ClientArgs} = format_client_log(Client), + [LimitedMsg,LimitedState,LimitedReason|LimitedLog] = + [error_logger:limit_term(D) || D <- [Msg,State,Reason1|Log]], {"** Generic server ~tp terminating \n" "** Last message in was ~tp~n" "** When Server state == ~tp~n" - "** Reason for termination == ~n** ~tp~n" ++ ClientFmt, - [Name, Msg, error_logger:limit_term(State), Reason1] ++ ClientArgs}; + "** Reason for termination ==~n** ~tp~n" ++ + case LimitedLog of + [] -> []; + _ -> "** Log ==~n** ~tp~n" + end ++ ClientFmt, + [Name, LimitedMsg, LimitedState, LimitedReason] ++ + case LimitedLog of + [] -> []; + _ -> [LimitedLog] + end ++ ClientArgs}; format_log(#{label:={gen_server,no_handle_info}, module:=Mod, message:=Msg}) -> {"** Undefined handle_info in ~p~n" "** Unhandled message: ~tp~n", - [Mod, Msg]}. + [Mod, error_logger:limit_term(Msg)]}. format_client_log(undefined) -> {"", []}; @@ -958,7 +970,7 @@ format_client_log({From,remote}) -> format_client_log({_From,{Name,Stacktrace}}) -> {"** Client ~tp stacktrace~n" "** ~tp~n", - [Name, Stacktrace]}. + [Name, error_logger:limit_term(Stacktrace)]}. %%----------------------------------------------------------------- %% Status information @@ -966,16 +978,25 @@ format_client_log({_From,{Name,Stacktrace}}) -> format_status(Opt, StatusData) -> [PDict, SysState, Parent, Debug, [Name, State, Mod, _Time, _HibernateAfterTimeout]] = StatusData, Header = gen:format_status_header("Status for generic server", Name), - Log = sys:get_debug(log, Debug, []), - Specfic = case format_status(Opt, Mod, PDict, State) of + Log = sys:get_log(Debug), + Specific = case format_status(Opt, Mod, PDict, State) of S when is_list(S) -> S; S -> [S] end, [{header, Header}, {data, [{"Status", SysState}, {"Parent", Parent}, - {"Logged events", Log}]} | - Specfic]. + {"Logged events", format_log_state(Mod, Log)}]} | + Specific]. + +format_log_state(Mod, Log) -> + [case Event of + {out,Msg,From,State} -> + {out,Msg,From,format_status(terminate, Mod, get(), State)}; + {noreply,State} -> + {noreply,format_status(terminate, Mod, get(), State)}; + _ -> Event + end || Event <- Log]. format_status(Opt, Mod, PDict, State) -> DefStatus = case Opt of diff --git a/lib/stdlib/src/gen_statem.erl b/lib/stdlib/src/gen_statem.erl index 24b268cd38..6f1f6a0228 100644 --- a/lib/stdlib/src/gen_statem.erl +++ b/lib/stdlib/src/gen_statem.erl @@ -586,7 +586,12 @@ enter_loop(Module, Opts, State, Data, Server_or_Actions) -> enter_loop(Module, Opts, State, Data, Server, Actions) -> is_atom(Module) orelse error({atom,Module}), Parent = gen:get_parent(), - enter(Module, Opts, State, Data, Server, Actions, Parent). + Name = gen:get_proc_name(Server), + Debug = gen:debug_options(Name, Opts), + HibernateAfterTimeout = gen:hibernate_after(Opts), + enter( + Parent, Debug, Module, Name, HibernateAfterTimeout, + State, Data, Actions). %%--------------------------------------------------------------------------- %% API helpers @@ -658,11 +663,10 @@ send(Proc, Msg) -> ok. %% Here the init_it/6 and enter_loop/5,6,7 functions converge -enter(Module, Opts, State, Data, Server, Actions, Parent) -> +enter( + Parent, Debug, Module, Name, HibernateAfterTimeout, + State, Data, Actions) -> %% The values should already have been type checked - Name = gen:get_proc_name(Server), - Debug = gen:debug_options(Name, Opts), - HibernateAfterTimeout = gen:hibernate_after(Opts), Events = [], Event = {internal,init_state}, %% We enforce {postpone,false} to ensure that @@ -676,7 +680,7 @@ enter(Module, Opts, State, Data, Server, Actions, Parent) -> data = Data, hibernate_after = HibernateAfterTimeout}, CallEnter = true, - NewDebug = ?sys_debug(Debug, {Name,State}, {enter,Event,State}), + NewDebug = ?sys_debug(Debug, Name, {enter,State}), case call_callback_mode(S) of #state{} = NewS -> loop_event_actions_list( @@ -695,18 +699,24 @@ enter(Module, Opts, State, Data, Server, Actions, Parent) -> init_it(Starter, self, ServerRef, Module, Args, Opts) -> init_it(Starter, self(), ServerRef, Module, Args, Opts); init_it(Starter, Parent, ServerRef, Module, Args, Opts) -> + Name = gen:get_proc_name(ServerRef), + Debug = gen:debug_options(Name, Opts), + HibernateAfterTimeout = gen:hibernate_after(Opts), try Module:init(Args) of Result -> - init_result(Starter, Parent, ServerRef, Module, Result, Opts) + init_result( + Starter, Parent, ServerRef, Module, Result, + Name, Debug, HibernateAfterTimeout) catch Result -> - init_result(Starter, Parent, ServerRef, Module, Result, Opts); + init_result( + Starter, Parent, ServerRef, Module, Result, + Name, Debug, HibernateAfterTimeout); Class:Reason:Stacktrace -> - Name = gen:get_proc_name(ServerRef), gen:unregister_name(ServerRef), proc_lib:init_ack(Starter, {error,Reason}), error_info( - Class, Reason, Stacktrace, + Class, Reason, Stacktrace, Debug, #state{name = Name}, []), erlang:raise(Class, Reason, Stacktrace) @@ -715,14 +725,20 @@ init_it(Starter, Parent, ServerRef, Module, Args, Opts) -> %%--------------------------------------------------------------------------- %% gen callbacks helpers -init_result(Starter, Parent, ServerRef, Module, Result, Opts) -> +init_result( + Starter, Parent, ServerRef, Module, Result, + Name, Debug, HibernateAfterTimeout) -> case Result of {ok,State,Data} -> proc_lib:init_ack(Starter, {ok,self()}), - enter(Module, Opts, State, Data, ServerRef, [], Parent); + enter( + Parent, Debug, Module, Name, HibernateAfterTimeout, + State, Data, []); {ok,State,Data,Actions} -> proc_lib:init_ack(Starter, {ok,self()}), - enter(Module, Opts, State, Data, ServerRef, Actions, Parent); + enter( + Parent, Debug, Module, Name, HibernateAfterTimeout, + State, Data, Actions); {stop,Reason} -> gen:unregister_name(ServerRef), proc_lib:init_ack(Starter, {error,Reason}), @@ -732,12 +748,11 @@ init_result(Starter, Parent, ServerRef, Module, Result, Opts) -> proc_lib:init_ack(Starter, ignore), exit(normal); _ -> - Name = gen:get_proc_name(ServerRef), gen:unregister_name(ServerRef), Error = {bad_return_from_init,Result}, proc_lib:init_ack(Starter, {error,Error}), error_info( - error, Error, ?STACKTRACE(), + error, Error, ?STACKTRACE(), Debug, #state{name = Name}, []), exit(Error) @@ -792,7 +807,7 @@ format_status( [PDict,SysState,Parent,Debug, #state{name = Name, postponed = P} = S]) -> Header = gen:format_status_header("Status for state machine", Name), - Log = sys:get_debug(log, Debug, []), + Log = sys:get_log(Debug), [{header,Header}, {data, [{"Status",SysState}, @@ -812,34 +827,46 @@ format_status( sys_debug(Debug, NameState, Entry) -> sys:handle_debug(Debug, fun print_event/3, NameState, Entry). -print_event(Dev, {in,Event}, {Name,State}) -> - io:format( - Dev, "*DBG* ~tp receive ~ts in state ~tp~n", - [Name,event_string(Event),State]); -print_event(Dev, {out,Reply,{To,_Tag}}, {Name,State}) -> - io:format( - Dev, "*DBG* ~tp send ~tp to ~p from state ~tp~n", - [Name,Reply,To,State]); -print_event(Dev, {terminate,Reason}, {Name,State}) -> - io:format( - Dev, "*DBG* ~tp terminate ~tp in state ~tp~n", - [Name,Reason,State]); -print_event(Dev, {Tag,Event,NextState}, {Name,State}) -> - StateString = - case NextState of - State -> - io_lib:format("~tp", [State]); - _ -> - io_lib:format("~tp => ~tp", [State,NextState]) - end, - io:format( - Dev, "*DBG* ~tp ~tw ~ts in state ~ts~n", - [Name,Tag,event_string(Event),StateString]). +print_event(Dev, SystemEvent, Name) -> + case SystemEvent of + {in,Event,State} -> + io:format( + Dev, "*DBG* ~tp receive ~ts in state ~tp~n", + [Name,event_string(Event),State]); + {code_change,Event,State} -> + io:format( + Dev, "*DBG* ~tp receive ~ts after code change in state ~tp~n", + [Name,event_string(Event),State]); + {out,Reply,{To,_Tag}} -> + io:format( + Dev, "*DBG* ~tp send ~tp to ~tw~n", + [Name,Reply,To]); + {enter,State} -> + io:format( + Dev, "*DBG* ~tp enter in state ~tp~n", + [Name,State]); + {terminate,Reason,State} -> + io:format( + Dev, "*DBG* ~tp terminate ~tp in state ~tp~n", + [Name,Reason,State]); + {Tag,Event,State,NextState} + when Tag =:= postpone; Tag =:= consume -> + StateString = + case NextState of + State -> + io_lib:format("~tp", [State]); + _ -> + io_lib:format("~tp => ~tp", [State,NextState]) + end, + io:format( + Dev, "*DBG* ~tp ~tw ~ts in state ~ts~n", + [Name,Tag,event_string(Event),StateString]) + end. event_string(Event) -> case Event of {{call,{Pid,_Tag}},Request} -> - io_lib:format("call ~tp from ~w", [Request,Pid]); + io_lib:format("call ~tp from ~tw", [Request,Pid]); {EventType,EventContent} -> io_lib:format("~tw ~tp", [EventType,EventContent]) end. @@ -981,7 +1008,14 @@ loop_receive_result(Parent, ?not_sys_debug, S, Type, Content) -> loop_event(Parent, ?not_sys_debug, S, Events, Type, Content); loop_receive_result( Parent, Debug, #state{name = Name, state = State} = S, Type, Content) -> - NewDebug = sys_debug(Debug, {Name,State}, {in,{Type,Content}}), + Event = {Type,Content}, + NewDebug = + case S#state.callback_mode of + undefined -> + sys_debug(Debug, Name, {code_change,Event,State}); + _ -> + sys_debug(Debug, Name, {in,Event,State}) + end, %% Here is the queue of not yet handled events created Events = [], loop_event(Parent, NewDebug, S, Events, Type, Content). @@ -1291,13 +1325,13 @@ parse_actions_reply( ?STACKTRACE(), Debug] end; parse_actions_reply( - StateCall, Debug, #state{name = Name, state = State} = S, + StateCall, Debug, #state{name = Name} = S, Actions, TransOpts, From, Reply) -> %% case from(From) of true -> reply(From, Reply), - NewDebug = sys_debug(Debug, {Name,State}, {out,Reply,From}), + NewDebug = sys_debug(Debug, Name, {out,Reply,From}), parse_actions(StateCall, NewDebug, S, Actions, TransOpts); false -> [error, @@ -1326,7 +1360,7 @@ parse_actions_next_event( Actions, TransOpts, Type, Content) -> case event_type(Type) of true when StateCall -> - NewDebug = sys_debug(Debug, {Name,State}, {in,{Type,Content}}), + NewDebug = sys_debug(Debug, Name, {in,{Type,Content},State}), NextEventsR = TransOpts#trans_opts.next_events_r, parse_actions( StateCall, NewDebug, S, Actions, @@ -1443,14 +1477,14 @@ loop_event_done( true -> [?sys_debug( Debug_0, - {S#state.name,State}, - {postpone,Event_0,NextState}), + S#state.name, + {postpone,Event_0,State,NextState}), Event_0|P_0]; false -> [?sys_debug( Debug_0, - {S#state.name,State}, - {consume,Event_0,NextState})|P_0] + S#state.name, + {consume,Event_0,State,NextState})|P_0] end, {Events_2,P_2, Timers_2} = @@ -1475,9 +1509,11 @@ loop_event_done( %% Place next events last in reversed queue Events_3R = lists:reverse(Events_2, NextEventsR), %% Enqueue immediate timeout events - Events_4R = prepend_timeout_events(TimeoutEvents, Events_3R), + [Debug_2|Events_4R] = + prepend_timeout_events( + NextState, Debug_1, S, TimeoutEvents, Events_3R), loop_event_done( - Parent, Debug_1, + Parent, Debug_2, S#state{ state = NextState, data = NewData, @@ -1814,22 +1850,31 @@ parse_timers( %% so if there are enqueued events before the event timer %% timeout 0 event - the event timer is cancelled hence no event. %% -%% Other (state_timeout) timeout 0 events that are after -%% the event timer timeout 0 events are considered to +%% Other (state_timeout and {timeout,Name}) timeout 0 events +%% that are after an event timer timeout 0 event are considered to %% belong to timers that were started after the event timer %% timeout 0 event fired, so they do not cancel the event timer. %% -prepend_timeout_events([], EventsR) -> - EventsR; -prepend_timeout_events([{timeout,_} = TimeoutEvent|TimeoutEvents], []) -> - prepend_timeout_events(TimeoutEvents, [TimeoutEvent]); -prepend_timeout_events([{timeout,_}|TimeoutEvents], EventsR) -> +prepend_timeout_events(_NextState, Debug, _S, [], EventsR) -> + [Debug|EventsR]; +prepend_timeout_events( + NextState, Debug, S, [{timeout,_} = TimeoutEvent|TimeoutEvents], []) -> + prepend_timeout_events( + NextState, + sys_debug(Debug, S#state.name, {in,TimeoutEvent,NextState}), + S, TimeoutEvents, [TimeoutEvent]); +prepend_timeout_events( + NextState, Debug, S, [{timeout,_}|TimeoutEvents], EventsR) -> %% Ignore since there are other events in queue %% so they have cancelled the event timeout 0. - prepend_timeout_events(TimeoutEvents, EventsR); -prepend_timeout_events([TimeoutEvent|TimeoutEvents], EventsR) -> + prepend_timeout_events(NextState, Debug, S, TimeoutEvents, EventsR); +prepend_timeout_events( + NextState, Debug, S, [TimeoutEvent|TimeoutEvents], EventsR) -> %% Just prepend all others - prepend_timeout_events(TimeoutEvents, [TimeoutEvent|EventsR]). + prepend_timeout_events( + NextState, + sys_debug(Debug, S#state.name, {in,TimeoutEvent,NextState}), + S, TimeoutEvents, [TimeoutEvent|EventsR]). @@ -1846,18 +1891,24 @@ do_reply_then_terminate( do_reply_then_terminate( Class, Reason, Stacktrace, Debug, S, Q, [R|Rs]) -> case R of - {reply,{_To,_Tag}=From,Reply} -> - reply(From, Reply), - NewDebug = - ?sys_debug( - Debug, - begin - #state{name = Name, state = State} = S, - {Name,State} - end, - {out,Reply,From}), - do_reply_then_terminate( - Class, Reason, Stacktrace, NewDebug, S, Q, Rs); + {reply,From,Reply} -> + case from(From) of + true -> + reply(From, Reply), + NewDebug = + ?sys_debug( + Debug, + S#state.name, + {out,Reply,From}), + do_reply_then_terminate( + Class, Reason, Stacktrace, NewDebug, S, Q, Rs); + false -> + terminate( + error, + {bad_reply_action_from_state_function,R}, + ?STACKTRACE(), + Debug, S, Q) + end; _ -> terminate( error, @@ -1877,8 +1928,7 @@ terminate( catch _ -> ok; C:R:ST -> - error_info(C, R, ST, S, Q), - sys:print_log(Debug), + error_info(C, R, ST, Debug, S, Q), erlang:raise(C, R, ST) end; false -> @@ -1893,8 +1943,7 @@ terminate( {shutdown,_} -> terminate_sys_debug(Debug, S, State, Reason); _ -> - error_info(Class, Reason, Stacktrace, S, Q), - sys:print_log(Debug) + error_info(Class, Reason, Stacktrace, Debug, S, Q) end, case Stacktrace of [] -> @@ -1904,17 +1953,18 @@ terminate( end. terminate_sys_debug(Debug, S, State, Reason) -> - ?sys_debug(Debug, {S#state.name,State}, {terminate,Reason}). + ?sys_debug(Debug, S#state.name, {terminate,Reason,State}). error_info( - Class, Reason, Stacktrace, + Class, Reason, Stacktrace, Debug, #state{ name = Name, callback_mode = CallbackMode, state_enter = StateEnter, postponed = P} = S, Q) -> + Log = sys:get_log(Debug), ?LOG_ERROR(#{label=>{gen_statem,terminate}, name=>Name, queue=>Q, @@ -1922,11 +1972,37 @@ error_info( callback_mode=>CallbackMode, state_enter=>StateEnter, state=>format_status(terminate, get(), S), - reason=>{Class,Reason,Stacktrace}}, + log=>Log, + reason=>{Class,Reason,Stacktrace}, + client_info=>client_stacktrace(Q)}, #{domain=>[otp], report_cb=>fun gen_statem:format_log/1, error_logger=>#{tag=>error}}). +client_stacktrace([]) -> + undefined; +client_stacktrace([{{call,{Pid,_Tag}},_Req}|_]) when is_pid(Pid) -> + if + node(Pid) =:= node() -> + case + process_info(Pid, [current_stacktrace, registered_name]) + of + undefined -> + {Pid,dead}; + [{current_stacktrace, Stacktrace}, + {registered_name, []}] -> + {Pid,{Pid,Stacktrace}}; + [{current_stacktrace, Stacktrace}, + {registered_name, Name}] -> + {Pid,{Name,Stacktrace}} + end; + true -> + {Pid,remote} + end; +client_stacktrace([_|_]) -> + undefined. + + format_log(#{label:={gen_statem,terminate}, name:=Name, queue:=Q, @@ -1934,7 +2010,9 @@ format_log(#{label:={gen_statem,terminate}, callback_mode:=CallbackMode, state_enter:=StateEnter, state:=FmtData, - reason:={Class,Reason,Stacktrace}}) -> + log:=Log, + reason:={Class,Reason,Stacktrace}, + client_info:=ClientInfo}) -> {FixedReason,FixedStacktrace} = case Stacktrace of [{M,F,Args,_}|ST] @@ -1954,14 +2032,12 @@ format_log(#{label:={gen_statem,terminate}, true -> {Reason,Stacktrace}; false -> - {{'function not exported',{M,F,Arity}}, - ST} + {{'function not exported',{M,F,Arity}},ST} end end; _ -> {Reason,Stacktrace} end, - [LimitedP, LimitedFmtData, LimitedFixedReason] = - [error_logger:limit_term(D) || D <- [P, FmtData, FixedReason]], + {ClientFmt,ClientArgs} = format_client_log(ClientInfo), CBMode = case StateEnter of true -> @@ -1988,27 +2064,47 @@ format_log(#{label:={gen_statem,terminate}, case FixedStacktrace of [] -> ""; _ -> "** Stacktrace =~n** ~tp~n" - end, + end ++ + case Log of + [] -> ""; + _ -> "** Log =~n** ~tp~n" + end ++ ClientFmt, [Name | case Q of [] -> []; - [Event|_] -> [Event] + [Event|_] -> [error_logger:limit_term(Event)] end] ++ - [LimitedFmtData, - Class,LimitedFixedReason, + [error_logger:limit_term(FmtData), + Class,error_logger:limit_term(FixedReason), CBMode] ++ case Q of - [_|[_|_] = Events] -> [Events]; + [_|[_|_] = Events] -> [error_logger:limit_term(Events)]; _ -> [] end ++ case P of [] -> []; - _ -> [LimitedP] + _ -> [error_logger:limit_term(P)] end ++ case FixedStacktrace of [] -> []; - _ -> [FixedStacktrace] - end}. + _ -> [error_logger:limit_term(FixedStacktrace)] + end ++ + case Log of + [] -> []; + _ -> [[error_logger:limit_term(T) || T <- Log]] + end ++ ClientArgs}. + +format_client_log(undefined) -> + {"", []}; +format_client_log({Pid,dead}) -> + {"** Client ~p is dead~n", [Pid]}; +format_client_log({Pid,remote}) -> + {"** Client ~p is remote on node ~p~n", [Pid, node(Pid)]}; +format_client_log({_Pid,{Name,Stacktrace}}) -> + {"** Client ~tp stacktrace~n" + "** ~tp~n", + [Name, error_logger:limit_term(Stacktrace)]}. + %% Call Module:format_status/2 or return a default value format_status( diff --git a/lib/stdlib/src/otp_internal.erl b/lib/stdlib/src/otp_internal.erl index 2cfc702b53..f2b50c354a 100644 --- a/lib/stdlib/src/otp_internal.erl +++ b/lib/stdlib/src/otp_internal.erl @@ -55,6 +55,14 @@ obsolete_1(erlang, now, 0) -> obsolete_1(calendar, local_time_to_universal_time, 1) -> {deprecated, {calendar, local_time_to_universal_time_dst, 1}}; +%% *** STDLIB added in OTP 22 *** + +obsolete_1(sys, get_debug, 3) -> + {deprecated, + "Deprecated function. " + "Incorrectly documented and in fact only for internal use. " + "Can often be replaced with sys:get_log/1."}; + %% *** STDLIB added in OTP 20 *** obsolete_1(gen_fsm, start, 3) -> diff --git a/lib/stdlib/src/sys.erl b/lib/stdlib/src/sys.erl index 0064414d6f..a04195c9ed 100644 --- a/lib/stdlib/src/sys.erl +++ b/lib/stdlib/src/sys.erl @@ -30,7 +30,8 @@ log_to_file/2, log_to_file/3, no_debug/1, no_debug/2, install/2, install/3, remove/2, remove/3]). -export([handle_system_msg/6, handle_system_msg/7, handle_debug/4, - print_log/1, get_debug/3, debug_options/1, suspend_loop_hib/6]). + print_log/1, get_log/1, get_debug/3, debug_options/1, suspend_loop_hib/6]). +-deprecated([{get_debug,3,eventually}]). %%----------------------------------------------------------------- %% Types @@ -42,10 +43,17 @@ | {'global', term()} | {'via', module(), term()}. -type system_event() :: {'in', Msg :: _} - | {'in', Msg :: _, From :: _} + | {'in', Msg :: _, State :: _} | {'out', Msg :: _, To :: _} | {'out', Msg :: _, To :: _, State :: _} - | term(). + | {'noreply', State :: _} + | {'continue', Continuation :: _} + | {'code_change', Event :: _, State :: _} + | {'postpone', Event :: _, State :: _, NextState :: _} + | {'consume', Event :: _, State :: _, NextState :: _} + | {'enter', State :: _} + | {'terminate', Reason :: _, State :: _} + | term(). -opaque dbg_opt() :: {'trace', 'true'} | {'log', {N :: non_neg_integer(), @@ -385,31 +393,41 @@ handle_system_msg(SysState, Msg, From, Parent, Mod, Debug, Misc, Hib) -> FormFunc :: format_fun(), Extra :: term(), Event :: system_event(). -handle_debug([{trace, true} | T], FormFunc, State, Event) -> +handle_debug([{trace, true} = DbgOpt | T], FormFunc, State, Event) -> print_event({Event, State, FormFunc}), - [{trace, true} | handle_debug(T, FormFunc, State, Event)]; -handle_debug([{log, {N, LogData}} | T], FormFunc, State, Event) -> - NLogData = [{Event, State, FormFunc} | trim(N, LogData)], - [{log, {N, NLogData}} | handle_debug(T, FormFunc, State, Event)]; -handle_debug([{log_to_file, Fd} | T], FormFunc, State, Event) -> + [DbgOpt | handle_debug(T, FormFunc, State, Event)]; +handle_debug([{log, NLog} | T], FormFunc, State, Event) -> + Item = {Event, State, FormFunc}, + [{log, nlog_put(Item, NLog)} | handle_debug(T, FormFunc, State, Event)]; +handle_debug([{log_to_file, Fd} = DbgOpt | T], FormFunc, State, Event) -> print_event(Fd, {Event, State, FormFunc}), - [{log_to_file, Fd} | handle_debug(T, FormFunc, State, Event)]; + [DbgOpt | handle_debug(T, FormFunc, State, Event)]; handle_debug([{statistics, StatData} | T], FormFunc, State, Event) -> NStatData = stat(Event, StatData), [{statistics, NStatData} | handle_debug(T, FormFunc, State, Event)]; handle_debug([{FuncId, {Func, FuncState}} | T], FormFunc, State, Event) -> - case catch Func(FuncState, Event, State) of + try Func(FuncState, Event, State) of done -> handle_debug(T, FormFunc, State, Event); - {'EXIT', _} -> handle_debug(T, FormFunc, State, Event); NFuncState -> - [{FuncId, {Func, NFuncState}} | handle_debug(T, FormFunc, State, Event)] + [{FuncId, {Func, NFuncState}} | + handle_debug(T, FormFunc, State, Event)] + catch + done -> handle_debug(T, FormFunc, State, Event); + NFuncState -> + [{FuncId, {Func, NFuncState}} | + handle_debug(T, FormFunc, State, Event)]; + _:_ -> handle_debug(T, FormFunc, State, Event) end; handle_debug([{Func, FuncState} | T], FormFunc, State, Event) -> - case catch Func(FuncState, Event, State) of + try Func(FuncState, Event, State) of done -> handle_debug(T, FormFunc, State, Event); - {'EXIT', _} -> handle_debug(T, FormFunc, State, Event); - NFuncState -> + NFuncState -> [{Func, NFuncState} | handle_debug(T, FormFunc, State, Event)] + catch + done -> handle_debug(T, FormFunc, State, Event); + NFuncState -> + [{Func, NFuncState} | handle_debug(T, FormFunc, State, Event)]; + _:_ -> handle_debug(T, FormFunc, State, Event) end; handle_debug([], _FormFunc, _State, _Event) -> []. @@ -526,19 +544,19 @@ debug_cmd({trace, true}, Debug) -> debug_cmd({trace, false}, Debug) -> {ok, remove_debug(trace, Debug)}; debug_cmd({log, true}, Debug) -> - {_N, Logs} = get_debug(log, Debug, {0, []}), - {ok, install_debug(log, {10, trim(10, Logs)}, Debug)}; -debug_cmd({log, {true, N}}, Debug) when is_integer(N), N > 0 -> - {_N, Logs} = get_debug(log, Debug, {0, []}), - {ok, install_debug(log, {N, trim(N, Logs)}, Debug)}; + NLog = get_debug(log, Debug, nlog_new()), + {ok, install_debug(log, nlog_new(NLog), Debug)}; +debug_cmd({log, {true, N}}, Debug) when is_integer(N), 1 =< N -> + NLog = get_debug(log, Debug, nlog_new(N)), + {ok, install_debug(log, nlog_new(N, NLog), Debug)}; debug_cmd({log, false}, Debug) -> {ok, remove_debug(log, Debug)}; debug_cmd({log, print}, Debug) -> print_log(Debug), {ok, Debug}; debug_cmd({log, get}, Debug) -> - {_N, Logs} = get_debug(log, Debug, {0, []}), - {{ok, lists:reverse(Logs)}, Debug}; + NLog = get_debug(log, Debug, nlog_new()), + {{ok, [Event || {Event, _State, _FormFunc} <- nlog_get(NLog)]}, Debug}; debug_cmd({log_to_file, false}, Debug) -> NDebug = close_log_file(Debug), {ok, NDebug}; @@ -595,9 +613,6 @@ stat({out, _Msg, _To}, {Time, Reds, In, Out}) -> {Time, Reds, In, Out+1}; stat({out, _Msg, _To, _State}, {Time, Reds, In, Out}) -> {Time, Reds, In, Out+1}; stat(_, StatData) -> StatData. -trim(N, LogData) -> - lists:sublist(LogData, 1, N-1). - %%----------------------------------------------------------------- %% Debug structure manipulating functions %%----------------------------------------------------------------- @@ -625,9 +640,14 @@ get_debug2(Item, Debug, Default) -> -spec print_log(Debug) -> 'ok' when Debug :: [dbg_opt()]. print_log(Debug) -> - {_N, Logs} = get_debug(log, Debug, {0, []}), - lists:foreach(fun print_event/1, - lists:reverse(Logs)). + NLog = get_debug(log, Debug, nlog_new()), + lists:foreach(fun print_event/1, nlog_get(NLog)). + +-spec get_log(Debug) -> [system_event()] when + Debug :: [dbg_opt()]. +get_log(Debug) -> + NLog = get_debug(log, Debug, nlog_new()), + [Event || {Event, _State, _FormFunc} <- nlog_get(NLog)]. close_log_file(Debug) -> case get_debug2(log_to_file, Debug, []) of @@ -639,6 +659,74 @@ close_log_file(Debug) -> end. %%----------------------------------------------------------------- +%% Keep the last N Log functions +%%----------------------------------------------------------------- +%% +%% Streamlined Okasaki queue as base for "keep the last N" log. +%% +%% To the reverse list head we cons new items. +%% The forward list contains elements in insertion order, +%% so the head is the oldest and the one to drop off +%% when the log is full. +%% +%% Here is how we can get away with only using one cons cell +%% to wrap the forward and reverse list, and the log size: +%% +%% A full log does not need a counter; we just cons one +%% and drop one: +%% +%% [ReverseList|ForwardList] +%% +%% A non-full log is filling up to N elements; +%% use a down counter instead of a list as first element: +%% +%% [RemainingToFullCount|ReverseList] + +nlog_new() -> + nlog_new(10). +%% +nlog_new([_|_] = NLog) -> + nlog_new(10, NLog); +nlog_new(N) -> + [N]. % Empty log size N >= 1 +%% +nlog_new(N, NLog) -> + lists:foldl( + fun (Item, NL) -> nlog_put(Item, NL) end, + nlog_new(N), + nlog_get(NLog)). + +%% +nlog_put(Item, NLog) -> + case NLog of + [R|FF] when is_list(R) -> + %% Full log + case FF of + [_|F] -> + %% Cons to reverse list, drop from forward list + [[Item|R]|F]; + [] -> + %% Create new forward list from reverse list, + %% create new empty reverse list + [_|F] = lists:reverse(R, [Item]), + [[]|F] + end; + [1|R] -> + %% Log now gets full + [[Item|R]]; + [J|R] -> + %% Filling up to N elements + [J - 1,Item|R] + end. + +nlog_get([[]|F]) -> + F; +nlog_get([[_|_] = R|F]) -> + F ++ lists:reverse(R); +nlog_get([_J|R]) -> + lists:reverse(R). + +%%----------------------------------------------------------------- %% Func: debug_options/1 %% Purpose: Initiate a debug structure. Called by a process that %% wishes to initiate the debug structure without the @@ -665,9 +753,9 @@ debug_options(Options) -> debug_options([trace | T], Debug) -> debug_options(T, install_debug(trace, true, Debug)); debug_options([log | T], Debug) -> - debug_options(T, install_debug(log, {10, []}, Debug)); + debug_options(T, install_debug(log, nlog_new(), Debug)); debug_options([{log, N} | T], Debug) when is_integer(N), N > 0 -> - debug_options(T, install_debug(log, {N, []}, Debug)); + debug_options(T, install_debug(log, nlog_new(N), Debug)); debug_options([statistics | T], Debug) -> debug_options(T, install_debug(statistics, init_stat(), Debug)); debug_options([{log_to_file, FileName} | T], Debug) -> diff --git a/lib/stdlib/test/gen_fsm_SUITE.erl b/lib/stdlib/test/gen_fsm_SUITE.erl index a8264e5a84..62d9d0e0ae 100644 --- a/lib/stdlib/test/gen_fsm_SUITE.erl +++ b/lib/stdlib/test/gen_fsm_SUITE.erl @@ -521,14 +521,16 @@ error_format_status(Config) when is_list(Config) -> error_logger_forwarder:register(), OldFl = process_flag(trap_exit, true), StateData = "called format_status", + Parent = self(), {ok, Pid} = gen_fsm:start(gen_fsm_SUITE, {state_data, StateData}, []), %% bad return value in the gen_fsm loop {'EXIT',{{bad_return_value, badreturn},_}} = (catch gen_fsm:sync_send_event(Pid, badreturn)), receive {error,_GroupLeader,{Pid, - "** State machine"++_, - [Pid,{_,_,badreturn},idle,{formatted,StateData},_]}} -> + "** State machine "++_, + [Pid,badreturn,Parent,idle,{formatted,StateData}, + {bad_return_value,badreturn}|_]}} -> ok; Other -> io:format("Unexpected: ~p", [Other]), @@ -541,12 +543,14 @@ terminate_crash_format(Config) when is_list(Config) -> error_logger_forwarder:register(), OldFl = process_flag(trap_exit, true), StateData = crash_terminate, + Parent = self(), {ok, Pid} = gen_fsm:start(gen_fsm_SUITE, {state_data, StateData}, []), stop_it(Pid), receive {error,_GroupLeader,{Pid, - "** State machine"++_, - [Pid,{_,_,_},idle,{formatted, StateData},_]}} -> + "** State machine "++_, + [Pid,stop,Parent,idle,{formatted, StateData}, + {crash,terminate}|_]}} -> ok; Other -> io:format("Unexpected: ~p", [Other]), diff --git a/lib/stdlib/test/gen_statem_SUITE.erl b/lib/stdlib/test/gen_statem_SUITE.erl index 017939fdd6..16cf8f43f9 100644 --- a/lib/stdlib/test/gen_statem_SUITE.erl +++ b/lib/stdlib/test/gen_statem_SUITE.erl @@ -513,7 +513,9 @@ abnormal1dirty(Config) -> %% trap exit since we must link to get the real bad_return_ error abnormal2(Config) -> OldFl = process_flag(trap_exit, true), - {ok,Pid} = gen_statem:start_link(?MODULE, start_arg(Config, []), []), + {ok,Pid} = + gen_statem:start_link( + ?MODULE, start_arg(Config, []), [{debug,[log]}]), %% bad return value in the gen_statem loop {{{bad_return_from_state_function,badreturn},_},_} = @@ -531,7 +533,9 @@ abnormal2(Config) -> %% trap exit since we must link to get the real bad_return_ error abnormal3(Config) -> OldFl = process_flag(trap_exit, true), - {ok,Pid} = gen_statem:start_link(?MODULE, start_arg(Config, []), []), + {ok,Pid} = + gen_statem:start_link( + ?MODULE, start_arg(Config, []), [{debug,[log]}]), %% bad return value in the gen_statem loop {{{bad_action_from_state_function,badaction},_},_} = @@ -549,7 +553,9 @@ abnormal3(Config) -> %% trap exit since we must link to get the real bad_return_ error abnormal4(Config) -> OldFl = process_flag(trap_exit, true), - {ok,Pid} = gen_statem:start_link(?MODULE, start_arg(Config, []), []), + {ok,Pid} = + gen_statem:start_link( + ?MODULE, start_arg(Config, []), [{debug,[log]}]), %% bad return value in the gen_statem loop BadTimeout = {badtimeout,4711,ouch}, @@ -689,7 +695,10 @@ state_enter(_Config) -> end}, {ok,STM} = gen_statem:start_link( - ?MODULE, {map_statem,Machine,[state_enter]}, [{debug,[trace]}]), + ?MODULE, {map_statem,Machine,[state_enter]}, + [{debug,[trace,{log,17}]}]), + ok = sys:log(STM, false), + ok = sys:log(STM, true), [{1,enter,start,start}] = flush(), {2,echo,start} = gen_statem:call(STM, echo), @@ -708,6 +717,11 @@ state_enter(_Config) -> {13,internal,start,wait}] = flush(), {14,repeat,start} = gen_statem:call(STM, repeat), [{15,enter,start,start}] = flush(), + + {ok,Log} = sys:log(STM, get), + io:format("sys:log ~p~n", [Log]), + ok = sys:log(STM, print), + {16,stop} = gen_statem:call(STM, {stop,bye}), [{'EXIT',STM,bye}] = flush(), @@ -1470,7 +1484,8 @@ enter_loop(_Config) -> %% Locally registered process + {local,Name} {ok,Pid1a} = - proc_lib:start_link(?MODULE, enter_loop, [local,local]), + proc_lib:start_link( + ?MODULE, enter_loop, [local,local,[{debug,[{log,7}]}]]), yes = gen_statem:call(Pid1a, 'alive?'), stopped = gen_statem:call(Pid1a, stop), receive @@ -1482,7 +1497,8 @@ enter_loop(_Config) -> %% Unregistered process + {local,Name} {ok,Pid1b} = - proc_lib:start_link(?MODULE, enter_loop, [anon,local]), + proc_lib:start_link( + ?MODULE, enter_loop, [anon,local,[{debug,[log]}]]), receive {'EXIT',Pid1b,process_not_registered} -> ok @@ -1591,6 +1607,9 @@ enter_loop(_Config) -> ok = verify_empty_msgq(). enter_loop(Reg1, Reg2) -> + enter_loop(Reg1, Reg2, []). +%% +enter_loop(Reg1, Reg2, Opts) -> process_flag(trap_exit, true), case Reg1 of local -> register(armitage, self()); @@ -1602,15 +1621,15 @@ enter_loop(Reg1, Reg2) -> case Reg2 of local -> gen_statem:enter_loop( - ?MODULE, [], state0, [], {local,armitage}); + ?MODULE, Opts, state0, [], {local,armitage}); global -> gen_statem:enter_loop( - ?MODULE, [], state0, [], {global,armitage}); + ?MODULE, Opts, state0, [], {global,armitage}); via -> gen_statem:enter_loop( - ?MODULE, [], state0, [], {via, dummy_via, armitage}); + ?MODULE, Opts, state0, [], {via, dummy_via, armitage}); anon -> - gen_statem:enter_loop(?MODULE, [], state0, []) + gen_statem:enter_loop(?MODULE, Opts, state0, []) end. undef_code_change(_Config) -> @@ -1642,7 +1661,9 @@ undef_terminate2(_Config) -> undef_in_terminate(_Config) -> Data = {undef_in_terminate, {?MODULE, terminate}}, - {ok, Statem} = gen_statem:start(?MODULE, {data, Data}, []), + {ok, Statem} = + gen_statem:start( + ?MODULE, {data, Data}, [{debug,[log]}]), try gen_statem:stop(Statem), ct:fail(should_crash) diff --git a/lib/stdlib/test/stdlib_bench_SUITE.erl b/lib/stdlib/test/stdlib_bench_SUITE.erl index 436aa78a0f..3456442088 100644 --- a/lib/stdlib/test/stdlib_bench_SUITE.erl +++ b/lib/stdlib/test/stdlib_bench_SUITE.erl @@ -67,9 +67,9 @@ cases(gen_server) -> [simple, simple_timer, simple_mon, simple_timer_mon, generic, generic_timer]; cases(gen_statem) -> - [generic, generic_fsm, generic_fsm_transit, - generic_statem, generic_statem_transit, - generic_statem_complex]. + [generic, generic_log, generic_log100, generic_fsm, generic_fsm_transit, + generic_statem, generic_statem_log, generic_statem_log100, + generic_statem_transit, generic_statem_complex]. init_per_group(gen_server, Config) -> compile_servers(Config), @@ -294,12 +294,24 @@ simple_timer_mon(Config) when is_list(Config) -> generic(Config) when is_list(Config) -> comment(do_tests(generic, single_small, Config)). +generic_log(Config) when is_list(Config) -> + comment(do_tests(generic_log, single_small, Config)). + +generic_log100(Config) when is_list(Config) -> + comment(do_tests(generic_log100, single_small, Config)). + generic_timer(Config) when is_list(Config) -> comment(do_tests(generic_timer, single_small, Config)). generic_statem(Config) when is_list(Config) -> comment(do_tests(generic_statem, single_small, Config)). +generic_statem_log(Config) when is_list(Config) -> + comment(do_tests(generic_statem_log, single_small, Config)). + +generic_statem_log100(Config) when is_list(Config) -> + comment(do_tests(generic_statem_log100, single_small, Config)). + generic_statem_transit(Config) when is_list(Config) -> comment(do_tests(generic_statem_transit, single_small, Config)). @@ -371,9 +383,9 @@ norm(T, Ref) -> do_tests(Test, ParamSet, Config) -> BenchmarkSuite = ?config(benchmark_suite, Config), - {Client, ServerMod} = bench(Test), + {Client, ServerMod, ServerArg} = bench(Test), {Parallelism, Message} = bench_params(ParamSet), - Fun = create_clients(Message, ServerMod, Client, Parallelism), + Fun = create_clients(Message, ServerMod, ServerArg, Client, Parallelism), {TotalLoops, AllPidTime} = run_test(Fun), try ?CALLS_PER_LOOP * round((1000 * TotalLoops) / AllPidTime) of PerSecond -> @@ -488,27 +500,35 @@ generic_fsm_transit_client(N, M, P) -> generic_fsm_transit_client(N+1, M, P). bench(simple) -> - {fun simple_client/3, simple_server}; + {fun simple_client/3, simple_server, term}; bench(simple_timer) -> - {fun simple_client_timer/3, simple_server_timer}; + {fun simple_client_timer/3, simple_server_timer, term}; bench(simple_mon) -> - {fun simple_client_mon/3, simple_server_mon}; + {fun simple_client_mon/3, simple_server_mon, term}; bench(simple_timer_mon) -> - {fun simple_client_timer_mon/3, simple_server_timer_mon}; + {fun simple_client_timer_mon/3, simple_server_timer_mon, term}; bench(generic) -> - {fun generic_client/3, generic_server}; + {fun generic_client/3, generic_server, [term]}; +bench(generic_log) -> + {fun generic_client/3, generic_server, [term,{debug,[log]}]}; +bench(generic_log100) -> + {fun generic_client/3, generic_server, [term,{debug,[{log,100}]}]}; bench(generic_timer) -> - {fun generic_timer_client/3, generic_server_timer}; + {fun generic_timer_client/3, generic_server_timer, term}; bench(generic_statem) -> - {fun generic_statem_client/3, generic_statem}; + {fun generic_statem_client/3, generic_statem, [term]}; +bench(generic_statem_log) -> + {fun generic_statem_client/3, generic_statem, [term,{debug,[log]}]}; +bench(generic_statem_log100) -> + {fun generic_statem_client/3, generic_statem, [term,{debug,[{log,100}]}]}; bench(generic_statem_transit) -> - {fun generic_statem_transit_client/3, generic_statem}; + {fun generic_statem_transit_client/3, generic_statem, [term]}; bench(generic_statem_complex) -> - {fun generic_statem_complex_client/3, generic_statem_complex}; + {fun generic_statem_complex_client/3, generic_statem_complex, term}; bench(generic_fsm) -> - {fun generic_fsm_client/3, generic_fsm}; + {fun generic_fsm_client/3, generic_fsm, term}; bench(generic_fsm_transit) -> - {fun generic_fsm_transit_client/3, generic_fsm}. + {fun generic_fsm_transit_client/3, generic_fsm, term}. %% -> {Parallelism, MessageTerm} bench_params(single_small) -> {1, small()}; @@ -536,10 +556,9 @@ parallelism() -> _ -> 1 end. -create_clients(M, ServerMod, Client, Parallel) -> +create_clients(M, ServerMod, ServerArg, Client, Parallel) -> fun() -> - State = term, - ServerPid = ServerMod:start(State), + ServerPid = ServerMod:start(ServerArg), PidRefs = [spawn_monitor(fun() -> Client(0, M, ServerPid) end) || _ <- lists:seq(1, Parallel)], timer:sleep(?MAX_TIME), diff --git a/lib/stdlib/test/stdlib_bench_SUITE_data/generic_server.erl b/lib/stdlib/test/stdlib_bench_SUITE_data/generic_server.erl index abd61dcdef..3707d00dee 100644 --- a/lib/stdlib/test/stdlib_bench_SUITE_data/generic_server.erl +++ b/lib/stdlib/test/stdlib_bench_SUITE_data/generic_server.erl @@ -8,8 +8,8 @@ -define(GEN_SERVER, gen_server). -start(State) -> - {ok, Pid} = ?GEN_SERVER:start(?MODULE, State, []), +start([State|Opts]) -> + {ok, Pid} = ?GEN_SERVER:start(?MODULE, State, Opts), Pid. init(State) -> diff --git a/lib/stdlib/test/stdlib_bench_SUITE_data/generic_statem.erl b/lib/stdlib/test/stdlib_bench_SUITE_data/generic_statem.erl index 2e0491f060..cfeb974abd 100644 --- a/lib/stdlib/test/stdlib_bench_SUITE_data/generic_statem.erl +++ b/lib/stdlib/test/stdlib_bench_SUITE_data/generic_statem.erl @@ -28,8 +28,8 @@ %% API -start(Data) -> - {ok, Pid} = gen_statem:start(?MODULE, Data, []), +start([Data|Opts]) -> + {ok, Pid} = gen_statem:start(?MODULE, Data, Opts), Pid. stop(P) -> |