diff --git a/rebar.lock b/rebar.lock deleted file mode 100644 index 57afcca..0000000 --- a/rebar.lock +++ /dev/null @@ -1 +0,0 @@ -[]. diff --git a/src/plugins/plugin_tracker.erl b/src/plugins/plugin_tracker.erl new file mode 100644 index 0000000..9b58866 --- /dev/null +++ b/src/plugins/plugin_tracker.erl @@ -0,0 +1,99 @@ +-module(plugin_tracker). +-behaviour(recon_plugins). + +-export([filter_fun/5, start_value/2, is_plugin/0]). +-import(recon_trace, [formatter/5, validate_opts/1, trace_to_io/2, + format/1, extract_info/1, clear/0]). + +is_plugin() -> + true. + +filter_fun(TSpecs, Boundaries, IoServer, Formatter, _Opts) -> + generate_pattern_filter(Boundaries, TSpecs, IoServer, Formatter). + +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% +%%% GENERATE PATTERN FILTER %%% +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% +generate_pattern_filter(TSpecs, {Max, Time}, IoServer, Formatter) -> + clear(), + rate_tracer({Max, Time}, TSpecs, IoServer, Formatter); +generate_pattern_filter(TSpecs, Max, IoServer, Formatter) -> + clear(), + count_tracer(Max, TSpecs, IoServer, Formatter). + +count_tracer(Max, _TSpecs, IoServer, Formatter) -> + fun + (_Trace, {_, _, N}) when N >= Max -> + IoServer ! rate_limit_tripped, clear(); + (Trace, {TSpecs, Session,N}) when (N < Max) and is_tuple(Trace) -> + %% Type = element(1, Trace), + handle_trace(Trace, N, TSpecs, IoServer, Formatter, Session) + end. + +rate_tracer({_Max, _Time}, _TSpecs, _IoServer, _Formatter) -> + io:format("Rate tracer is not supported for module: ~p~n", [?MODULE]). + +handle_trace(_, _, [], IoServer, _, _) -> + IoServer ! rate_limit_tripped, clear(); +handle_trace(Trace, N, [TSpec | TSpecRest] = TSpecs, IoServer, Formatter, Session) -> + Print = filter_call(Trace, TSpec, Session), + case Print of + reject -> {TSpecs, Session, N}; + {print, Value, NewSession} -> + IoServer ! {print_value, Value}, + {TSpecRest, NewSession, N+1}; + {print, NewSession} -> + case Formatter(Trace) of + "" -> ok; + Formatted -> IoServer ! {msg, Formatted} + end, + {TSpecRest, NewSession, N+1}; + _ -> {TSpecs, Session, N} + end. + + +filter_call(TraceMsg, {M, F, PatternFun}, Session) -> + case extract_info(TraceMsg) of + {call, _, _, [{TraceM,TraceF, Args}]} -> + test_match(M, F, TraceM, TraceF, Args, PatternFun, Session); + {call, _, _, [{TraceM, TraceF, Args}, _Msg]} -> + test_match(M, F, TraceM, TraceF, Args, PatternFun, Session); + %% if the trace is not a call, we just print it + _ -> {print, Session} + end. + +test_match(M, F, TraceM, TraceF, Args, PatternFun, Session) -> + Match = + case {M==TraceM, ((F=='_') or (F==TraceF)), PatternFun} of + {true, true, '_'} -> true; + {true, true, _} -> check; + _ -> false + end, + + case Match of + true -> {print, Session}; + false -> reject; + check -> + try erlang:apply(PatternFun, [Args, Session]) of + suppress -> reject; + print -> {print, Session}; + {print, Value} -> {print, Value, Session}; + {print_session, NewSession} -> {print, maps:merge(Session, NewSession)}; + {print_session, Value, NewSession} -> {print, Value, maps:merge(Session, NewSession)}; + _ -> reject + catch + error:function_clause -> + reject; + error:arity_no_match -> + reject; + error:_E -> + reject + end + end. + +%%% Start value for the dbg tracer process state +start_value(_, {_, _}) -> + {0, undefined, 0}; +start_value(Specs, _Max) -> + {Specs, #{}, 0}. + diff --git a/src/recon_plugins.erl b/src/recon_plugins.erl new file mode 100644 index 0000000..e191b10 --- /dev/null +++ b/src/recon_plugins.erl @@ -0,0 +1,21 @@ +%%% @author +%%% [https://flmath.github.io] +%%% @doc +%%% `recon_trace_use_dbg' is a module that allows API of recon use dbg module +%%% The added value of this solution is more flexibility in the pattern matching +%%% you can pattern match any structure you BEAM can put into function guard. +-module(recon_plugins). +%% API + +-type tspec() :: recon_trace_use_dbg:tspec(). +-type device() :: atom() | pid() | standard_io | standard_error | user. +-type property() :: atom() | tuple(). +-type proplist() :: [property()]. +-type init() :: recon_trace_use_dbg:max_traces(). +-type matchspecs() :: recon_trace_use_dbg:matchspecs(). + +-type filter_fun_type() :: fun((tspec() | [tspec()], init()) -> init()). + +-callback filter_fun(matchspecs(), init(), device(), pid(), proplist()) -> filter_fun_type(). +-callback is_plugin() -> boolean(). +-callback start_value(matchspecs(), init()) -> {matchspecs(), map(), init()}. diff --git a/src/recon_trace.erl b/src/recon_trace.erl index 62b3b67..e687701 100644 --- a/src/recon_trace.erl +++ b/src/recon_trace.erl @@ -187,6 +187,9 @@ %% Internal exports -export([count_tracer/1, rate_tracer/2, formatter/5, format_trace_output/1, format_trace_output/2]). +%% For use_dbg feature +-export([trace_to_io/2, extract_info/1, validate_opts/1, fun_to_ms/1]). + -type matchspec() :: [{[term()] | '_', [term()], [term()]}]. -type shellfun() :: fun((_) -> term()). -type formatterfun() :: fun((_) -> iodata()). @@ -228,6 +231,13 @@ clear() -> erlang:trace_pattern({'_','_','_'}, false, []), % unsets global maybe_kill(recon_trace_tracer), maybe_kill(recon_trace_formatter), + + %% for recon_trace_use_dbg + maybe_kill(recon_trace_tracer), + catch unregister(recon_trace_tracer), + dbg:p(all,clear), + dbg:ctp('_'), + dbg:stop(), ok. %% @equiv calls({Mod, Fun, Args}, Max, []) @@ -336,11 +346,18 @@ calls(TSpecs = [_|_], Max) -> calls({Mod, Fun, Args}, Max, Opts) -> calls([{Mod,Fun,Args}], Max, Opts); -calls(TSpecs = [_|_], {Max, Time}, Opts) -> + +calls(TSpecs = [_|_], Boundaries, Opts) -> + case proplists:get_bool(use_dbg, Opts) of + true -> recon_trace_use_dbg:calls_dbg(TSpecs, Boundaries, Opts); + false -> spec_calls(TSpecs, Boundaries, Opts) + end. + +spec_calls(TSpecs = [_|_], {Max, Time}, Opts) -> Pid = setup(rate_tracer, [Max, Time], validate_formatter(Opts), validate_io_server(Opts)), trace_calls(TSpecs, Pid, Opts); -calls(TSpecs = [_|_], Max, Opts) -> +spec_calls(TSpecs = [_|_], Max, Opts) -> Pid = setup(count_tracer, [Max], validate_formatter(Opts), validate_io_server(Opts)), trace_calls(TSpecs, Pid, Opts). @@ -486,7 +503,7 @@ validate_tspec(Mod, Fun, Args) when is_function(Args) -> validate_tspec(Mod, Fun, return_trace) -> validate_tspec(Mod, Fun, [{'_', [], [{return_trace}]}]); validate_tspec(Mod, Fun, Args) -> - BannedMods = ['_', ?MODULE, io, lists], + BannedMods = ['_', ?MODULE, io, lists, recon_trace_use_dbg], %% The banned mod check can be bypassed by using %% match specs if you really feel like being dumb. case {lists:member(Mod, BannedMods), Args} of @@ -515,7 +532,12 @@ validate_io_server(Opts) -> %% Thanks Geoff Cant for the foundations for this. format(TraceMsg) -> {Type, Pid, {Hour,Min,Sec}, TraceInfo} = extract_info(TraceMsg), - {FormatStr, FormatArgs} = case {Type, TraceInfo} of + {FormatStr, FormatArgs} = trace_to_io(Type, TraceInfo), + io_lib:format("~n~p:~p:~9.6.0f ~p " ++ FormatStr ++ "~n", + [Hour, Min, Sec, Pid] ++ FormatArgs). + +trace_to_io(Type, TraceInfo) -> + case {Type, TraceInfo} of %% {trace, Pid, 'receive', Msg} {'receive', [Msg]} -> {"< ~p", [Msg]}; @@ -590,9 +612,7 @@ format(TraceMsg) -> [HeapSize + OldHeapSize + MbufSize]}; _ -> {"unknown trace type ~p -- ~p", [Type, TraceInfo]} - end, - io_lib:format("~n~p:~p:~9.6.0f ~p " ++ FormatStr ++ "~n", - [Hour, Min, Sec, Pid] ++ FormatArgs). + end. extract_info(TraceMsg) -> case tuple_to_list(TraceMsg) of diff --git a/src/recon_trace_use_dbg.erl b/src/recon_trace_use_dbg.erl new file mode 100755 index 0000000..37d08da --- /dev/null +++ b/src/recon_trace_use_dbg.erl @@ -0,0 +1,418 @@ +%%% @author +%%% [https://flmath.github.io] +%%% @doc +%%% `recon_trace_use_dbg' is a module that allows API of recon use dbg module +%%% The added value of this solution is more flexibility in the pattern matching +%%% you can pattern match any structure you BEAM can put into function guard. +%%% @end +-module(recon_trace_use_dbg). +-include_lib("stdlib/include/ms_transform.hrl"). + +-import(recon_trace, [formatter/5, validate_opts/1, trace_to_io/2, + format/1, extract_info/1, clear/0]). + +%% API +-export([calls_dbg/3]). + +%% Internal exports +-export([count_tracer/4, rate_tracer/4, print_actuator/2]). + +-type matchspec() :: [{[term()] | '_', [term()], [term()]}]. +-type shellfun() :: fun((_) -> term()). +-type formatterfun() :: fun((_) -> iodata()). +-type millisecs() :: non_neg_integer(). +-type pidspec() :: all | existing | new | recon:pid_term(). +-type max_traces() :: non_neg_integer(). +-type max_rate() :: {max_traces(), millisecs()}. + + %% trace options +-type options() :: [ {pid, pidspec() | [pidspec(),...]} % default: all + | {timestamp, formatter | trace} % default: formatter + | {args, args | arity} % default: args + | {io_server, pid() | atom()} % default: group_leader() + | {formatter, formatterfun()} % default: internal formatter + | return_to | {return_to, boolean()} % default: false + %% match pattern options + | {scope, global | local} % default: global + ]. + +-type mod() :: '_' | module(). +-type fn() :: '_' | atom(). +-type args() :: '_' | 0..255 | return_trace | matchspec() | shellfun(). +-type tspec() :: {mod(), fn(), args()}. +-type max() :: max_traces() | max_rate(). +-type num_matches() :: non_neg_integer(). + +-export_type([mod/0, fn/0, args/0, tspec/0, num_matches/0, options/0, + max_traces/0, max_rate/0]). + +%%%%%%%%%%%%%% +%%% PUBLIC %%% +%%%%%%%%%%%%%% +%% @doc +%% Allows to set trace patterns and pid specifications to trace +%% function calls using dbg module functions. +%% @end +-spec calls_dbg(tspec() | [tspec(),...], max(), options()) -> num_matches(). +calls_dbg(TSpecs, Boundaries, Opts) -> + case trace_function_types(TSpecs, Opts) of + {shell_fun, _} -> + io:format("Warning: TSpecs contain erlang trace template function "++ + "use_dbg flag ignored, falling back to default recon_trace behaviour~n"), + recon_trace:calls(TSpecs, Boundaries, proplists:delete(use_dbg, Opts)); + {standard_fun, Plugin} -> + clear(), + FunTSpecs = tspecs_normalization(TSpecs), + Formatter = validate_formatter(Opts), + IoServer = validate_io_server(Opts), + + {PidSpecs, TraceOpts, MatchOpts} = validate_opts(Opts), + {PatternsFun, StartValue} = + if Plugin == default -> + {generate_pattern_filter(FunTSpecs, Boundaries, IoServer, Formatter), + start_value(FunTSpecs, Boundaries)}; + true -> {Plugin:filter_fun(FunTSpecs, Boundaries, IoServer, Formatter, Opts), + Plugin:start_value(FunTSpecs, Boundaries)} + end, + dbg:tracer(process,{PatternsFun, StartValue}), + %% we want to receive full traces to match them then we can calculate arity + ProcessOpts = [c]++proplists:delete(arity, TraceOpts), + lists:foreach(fun(Pid) -> dbg:p(Pid, ProcessOpts) end, PidSpecs), + dbg_tp(TSpecs, MatchOpts) + end. + +%%%%%%%%%%%%%%%%%%%%%%% +%%% PRIVATE EXPORTS %%% +%%%%%%%%%%%%%%%%%%%%%%% + +%%%%%%%%%%%%%%%%%%%%%%%%%%%% +%%% TSPECS NORMALIZATION %%% +%%%%%%%%%%%%%%%%%%%%%%%%%%%% + +tspecs_normalization(TSpecs) -> + %% Normalizes the TSpecs to be a list of tuples + %% {Mod, Fun, Args} where Args is a function. + [case Args of + '_' -> {Mod, Fun, fun pass_all/1}; + N when is_integer(N) -> + ArgsNoFun = args_no_fun(N), + {Mod, Fun, ArgsNoFun}; + _ -> TSpec + end || {Mod, Fun, Args} = TSpec <- TSpecs]. + +pass_all(_) -> print. + +args_no_fun(N) -> + fun(V) -> + case erlang:length(V) of + N -> print; + _ -> throw(arity_no_match) + end + end. + +%%%%%%%%%%%%%%%%%%%%%%%%%% +%%% VALIDATE FORMATTER %%% +%%%%%%%%%%%%%%%%%%%%%%%%%% + +validate_formatter(Opts) -> + Formatter = proplists:get_value(formatter, Opts), + ArgsOrArity = proplists:get_value(args, Opts), + case {ArgsOrArity, Formatter} of + {arity, Formatter} when is_function(Formatter, 1) -> + io:format("Custom formater, arity option ignored ~n"), + Formatter; + {_args, Formatter} when is_function(Formatter, 1) -> Formatter; + {Args, _Formatter} -> default_formatter(Args) + end. + +default_formatter(arity) -> + fun(TraceMsg) -> + {Type, Pid, {Hour,Min,Sec}, TraceInfo} = extract_info(TraceMsg), + {_, UpdTrace} = trace_calls_to_arity({Type, TraceInfo}), + {FormatStr, FormatArgs} = + trace_to_io(Type, UpdTrace), + io_lib:format("~n~p:~p:~9.6.0f ~p " ++ FormatStr ++ "~n", + [Hour, Min, Sec, Pid] ++ FormatArgs) + end; +default_formatter(_) -> + fun recon_trace:format/1. + +trace_calls_to_arity(TypeTraceInfo) -> + case TypeTraceInfo of + {call, [{M,F,Args}]} -> + {call, [{M,F,length(Args)}]}; + {call, [{M,F,Args}, Msg]} -> + {call, [{M,F,length(Args)}, Msg]}; + Trace -> Trace + end. + +%%%%%%%%%%%%%%%%%%%%%%%%%% +%%% VALIDATE IO SERVER %%% +%%%%%%%%%%%%%%%%%%%%%%%%%% + +validate_io_server(Opts) -> + IoServer = proplists:get_value(io_server, Opts, group_leader()), + IoDelay = proplists:get_value(io_delay, Opts, 1), + Pid = proc_lib:spawn_link(?MODULE, print_actuator, [IoServer, IoDelay]), + reregister(recon_trace_printer, Pid), + Pid. + +print_actuator(IoServer, IoDelay) -> + receive + {msg, Msg} -> + try io:format(IoServer, Msg, []) + catch + error:_ -> + io:format("Recon output process stopped when trace was sent.~n"), + clear(), exit(normal) + end; + {print_value, Value} -> + try io:format(IoServer, " ~p~n", [Value]) + catch + error:_ -> + io:format("Recon output process stopped when value was sent.~n"), + clear(), exit(normal) + end; + rate_limit_tripped -> + io:format("Recon tracer rate limit tripped.~n"), + clear(), exit(normal) + end, + receive + after IoDelay -> print_actuator(IoServer, IoDelay) + end. + + +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% +%%% GENERATE PATTERN FILTER %%% +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% +generate_pattern_filter(TSpecs, {Max, Time}, IoServer, Formatter) -> + clear(), + rate_tracer({Max, Time}, TSpecs, IoServer, Formatter); +generate_pattern_filter(TSpecs, Max, IoServer, Formatter) -> + clear(), + count_tracer(Max, TSpecs, IoServer, Formatter). + +count_tracer(Max, TSpecs, IoServer, Formatter) -> + fun + (_Trace, N) when N >= Max -> + IoServer ! rate_limit_tripped, clear(); + (Trace, N) when (N < Max) and is_tuple(Trace) -> + %% Type = element(1, Trace), + handle_trace(Trace, N, TSpecs, IoServer, Formatter) + end. + +rate_tracer({Max, Time}, TSpecs, IoServer, Formatter) -> + fun(Trace, {N, Timestamp}) -> + Now = os:timestamp(), + Delay = timer:now_diff(Now, Timestamp) div 1000, + + if Delay > Time -> + NewN = handle_trace(Trace, 0, TSpecs, IoServer, Formatter), + {NewN, Now}; + Max >= N -> + NewN = handle_trace(Trace, N, TSpecs, IoServer, Formatter), + {NewN, Timestamp}; + true -> + IoServer ! rate_limit_tripped, clear() + end + end. + +handle_trace(Trace, N, TSpecs, IoServer, Formatter) -> + Print = filter_call(Trace, TSpecs), + case Print of + reject -> N; + {print, Value} -> + IoServer ! {print_value, Value}, + N+1; + print -> + case Formatter(Trace) of + "" -> ok; + Formatted -> IoServer ! {msg, Formatted} + end, + N+1; + _ -> N + end. + +filter_call(TraceMsg, TSpecs) -> + filter_call(TraceMsg, TSpecs, reject). + +filter_call(_TraceMsg, _, {print, Value}) -> {print, Value}; +filter_call(_TraceMsg, _, print) -> print; +filter_call(_TraceMsg, [], Answer) -> Answer; +filter_call(TraceMsg, [{M, F, PatternFun} | TSpecs], reject) -> + NewAnswer = case extract_info(TraceMsg) of + {call, _, _, [{TraceM,TraceF, Args}]} -> + test_match(M, F, TraceM, TraceF, Args, PatternFun); + {call, _, _, [{TraceM, TraceF, Args}, _Msg]} -> + test_match(M, F, TraceM, TraceF, Args, PatternFun); + %% if the trace is not a call, we just print it + _ -> print + end, + filter_call(TraceMsg, TSpecs, NewAnswer). + +test_match(M, F, TraceM, TraceF, Args, PatternFun) -> + Match = + case {M==TraceM, ((F=='_') or (F==TraceF)), PatternFun} of + {true, true, '_'} -> true; + {true, true, _} -> check; + _ -> false + end, + + case Match of + true -> print; + false -> reject; + check -> + try erlang:apply(PatternFun, [Args]) of + suppress -> reject; + print -> print; + {print, Value} -> {print, Value}; + _ -> reject + catch + error:function_clause -> + reject; + error:arity_no_match -> + reject; + error:_E -> + reject + end + end. + +%%% Start value for the dbg tracer process state +start_value(_, {_, _}) -> + {0, os:timestamp()}; +start_value(_, _Max) -> + 0. + + +%%%%%%%%%%%%%%%%%%%%%%%%%%%% +%%% DEBUG TRACE PATTERN %%% +%%%%%%%%%%%%%%%%%%%%%%%%%%%% +%%% @doc +%%% The function is used to establish call trace patterns +%%% If the matchspec {M,F,Args} is on the list all calls module M +%%% and function F will be sending traces to the tracer process which will use +%%% the function to print the matching traces. +%%% @end + +-spec dbg_tp([{atom(),atom(),term()}], [local] | [global]) -> num_matches(). +dbg_tp(MFAList, MatchOpts) -> + case MatchOpts of + [local] -> + Matches = [dbg:tpl({M, F, '_'}, [{'_', [], []}]) || {M, F, _A} <- MFAList], + lists:sum([Cnt || {ok,[{_,_,Cnt},_]}<- Matches]); + [global] -> + Matches = [dbg:tp({M, F, '_'}, [{'_', [], []}]) || {M, F, _A} <- MFAList], + lists:sum([Cnt || {ok,[{_,_,Cnt},_]}<- Matches]) + end. + +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% +%%% CHECK IF FUNCTION IS NOT STANDARD RECON %%% +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% +%% In the list of TSpecs, the third element of the tuple +%% is responsible for matching arguments. +%% In standard recon_trace, the third element is a template function +%% transformed to a matchspec. +%% If use_dbg is set to true, the third element is used as actual function and interpreted +%% in a totally different way. +%% The function is used to determine the type of the functions to be traced. +%% They should be possible to interpret all functions in the same way. +%% For example '_' can be interpreted as a dbg trace function or a function. +%% Since use_dbg is set to true, the function is considered by default a function. +%% The function is considered a trace function if its every clause +%% ends with a functions like return_trace(), +%% that are translated into a {return_trace} in the matchspecs list. +%% ---------------------------------------------------- +trace_function_types(TSpecs, Opts) -> + case proplists:get_value(plugin, Opts, default) of + default -> {trace_function_types(TSpecs), default}; + Plugin -> + try Plugin:is_plugin() of + true -> {standard_fun, Plugin} + catch + _:_ -> + io:format("Warning: Plugin ~p does not implement is_plugin/0 function,~n", [Plugin]), + recon_trace:clear(), + fail + end + end. + +trace_function_types(TSpecs) -> +FunTypes= [trace_function_type(Args) || {_, _, Args} <- TSpecs], + + HasShell = lists:any(fun(T) -> T == shell_fun end, FunTypes), + HasStandard = lists:any(fun(T) -> T == standard_fun end, FunTypes), + case {HasShell, HasStandard} of + {true, true} -> exit(mixed_function_types); + {true, false} -> shell_fun; + {false, _true_or_false} -> standard_fun + end. + +%% in case of fun_to_ms, the function is transformed to '_' +%% for this implementation it is transformed to fun(A) -> A end +trace_function_type('_') -> undecided_fun; +trace_function_type(N) when is_integer(N) -> undecided_fun; + +%% shorthand used by shell functions +trace_function_type(return_trace) -> shell_fun; +%% if the function is a matchspec, we check if every clause has *_trace() +trace_function_type(Patterns) when is_list(Patterns) -> + trace_function_type(Patterns, shell_fun); + +%% if function transforms it still can be proper functor, +%% check if the is *_trace() is absent +%% if every clause has *_trace() it is a shell function +trace_function_type(PatternFun) when is_function(PatternFun, 1) -> + try silent_fun_to_ms(PatternFun) of + {error,transform_error} -> standard_fun; + Patterns -> trace_function_type(Patterns, undecided) + catch + _:_ -> standard_fun + end. + +silent_fun_to_ms(ShellFun) when is_function(ShellFun) -> + case erl_eval:fun_data(ShellFun) of + {fun_data,ImportList,Clauses} -> + case ms_transform:transform_from_shell( + dbg,Clauses,ImportList) of + {error,[{_,[{_,_,_Code}|_]}|_],_} -> + {error,transform_error}; + Else -> + Else + end; + false -> + exit(shell_funs_only) + end. + + +%% all function clauses are '_' +trace_function_type([], shell_fun) -> shell_fun; +trace_function_type([], standard_fun) -> standard_fun; +trace_function_type([], undecided_fun) -> undecided_fun; + +trace_function_type([Clause | Rest], Type) -> + ClauseType = clause_type(Clause), + case Type of + undecided -> + trace_function_type(Rest, ClauseType); + _ -> + if ClauseType =/= Type -> exit(mixed_clauses_types); + true -> trace_function_type(Rest, Type) + end + end. + +clause_type({_head,_guard, Return}) -> + case lists:last(Return) of + %% can return_trace, current_stacktrace, exception_trace + {_return_trace} -> shell_fun; + _ -> standard_fun + end. + +reregister(Name, Pid) -> + case whereis(Name) of + undefined -> ok; + OldPid -> + unlink(OldPid), + exit(OldPid, kill), + unregister(Name) + end, + register(Name, Pid). \ No newline at end of file diff --git a/test/fake_reg.erl b/test/fake_reg.erl new file mode 100644 index 0000000..ec41a78 --- /dev/null +++ b/test/fake_reg.erl @@ -0,0 +1,89 @@ +%% @author +%% [https://flmath.github.io] +%% @doc +%% Minimal fake registration module for testing +%% purposes. This module simulates the behavior of the +%% registration in Erlang, allowing us to +%% test the functionality of our code without +%% relying on the actual Erlang registry. +%% @end +-module(fake_reg). +-behaviour(gen_server). + +%% API for the gen_server +-export([start/0, stop/0]). + +%% Callbacks +-export([init/1, handle_call/3, handle_cast/2, handle_info/2, + terminate/2, code_change/3]). + +%% gen_registry callbacks +-export([register_name/2, unregister_name/1, whereis_name/1, send/2]). + +-define(SERVER, ?MODULE). + +%%%=================================================================== +%%% Public API +%%%=================================================================== + +start() -> + gen_server:start({local, ?SERVER}, ?MODULE, #{}, []). + +stop() -> + gen_server:call(?SERVER, stop). + +%%%=================================================================== +%%% gen_registry required callbacks +%%%=================================================================== + +register_name(Name, Pid) when is_pid(Pid) -> + gen_server:call(?SERVER, {register, Name, Pid}). + +unregister_name(Name) -> + gen_server:call(?SERVER, {unregister, Name}). + +whereis_name(Name) -> + gen_server:call(?SERVER, {whereis, Name}). + +send(Name, Msg) -> + case whereis_name(Name) of + undefined -> exit({badarg, {Name, Msg}}); + Pid when is_pid(Pid) -> Pid ! Msg, Pid + end. + +%%%=================================================================== +%%% gen_server callbacks +%%%=================================================================== + +init(StateMap) -> + {ok, StateMap}. + +handle_call({register, Name, Pid}, _From, Registry) -> + case maps:is_key(Name, Registry) of + true -> {reply, {error, already_registered}, Registry}; + false -> {reply, yes, Registry#{Name => Pid}} + end; + +handle_call({unregister, Name}, _From, Registry) -> + {reply, ok, maps:remove(Name, Registry)}; + +handle_call({whereis, Name}, _From, Registry) -> + {reply, maps:get(Name, Registry, undefined), Registry}; + +handle_call(stop, _From, Registry) -> + {stop, normal, ok, Registry}; + +handle_call(_, _From, State) -> + {reply, error, State}. + +handle_cast(_, State) -> + {noreply, State}. + +handle_info(_, State) -> + {noreply, State}. + +terminate(_Reason, _State) -> + ok. + +code_change(_OldVsn, State, _Extra) -> + {ok, State}. diff --git a/test/recon_trace_SUITE.erl b/test/recon_trace_SUITE.erl new file mode 100644 index 0000000..77be571 --- /dev/null +++ b/test/recon_trace_SUITE.erl @@ -0,0 +1,575 @@ +%%% @author +%%% [https://flmath.github.io] +%%% @doc +%%% Common Test Suite for recon_trace functionality. +%%% Tests various scenarios based on the recon_trace documentation. +%%% @end +%%%------------------------------------------------------------------- + +-module(recon_trace_SUITE). + +-include_lib("common_test/include/ct.hrl"). +-include_lib("stdlib/include/ms_transform.hrl"). +-compile({parse_transform, ms_transform}). + +-export([ + all/0, groups/0, + init_per_suite/1, end_per_suite/1, + init_per_group/2, end_per_group/2, + init_per_testcase/2, end_per_testcase/2 + ]). + +-export([ + count_trace_match/3, + assert_trace_match/2, + assert_trace_no_match/2 + ]). + +%% Test cases +-export([ + dummy_basic_test/1, + trace_full_module_test/1, + trace_one_function_test/1, + trace_rate_limit_test/1, + trace_even_arg_test/1, + trace_iolist_to_binary_with_binary_test/1, + trace_specific_pid_test/1, + trace_arity_test/1, + trace_spec_list_new_procs_only_test/1, + trace_handle_call_new_and_custom_registry_test/1, + trace_return_shellfun_test/1, + trace_return_matchspec_test/1, + trace_return_shorthand_test/1, + trace_timestamp_test/1, + trace_return_to_test/1 + ]). + +%%-------------------------------------------------------------------- +%% Suite Configuration +%%-------------------------------------------------------------------- + +%% @doc Returns list of test cases and/or groups to be executed. +all() -> + [{group, basic_test}, {group, doc_based_test}]. + +%% @doc Defines the test groups. +groups() -> + [ + {basic_test, [sequence], [ + dummy_basic_test + ]}, + {doc_based_test, [sequence], [ + trace_full_module_test, + trace_one_function_test, + trace_rate_limit_test, + trace_even_arg_test, + trace_iolist_to_binary_with_binary_test, + trace_specific_pid_test, + trace_arity_test, + trace_spec_list_new_procs_only_test, + trace_handle_call_new_and_custom_registry_test, + trace_return_shellfun_test, + trace_return_matchspec_test, + trace_return_shorthand_test, + trace_timestamp_test, + trace_return_to_test + ] + } + ]. + +%%-------------------------------------------------------------------- +%% Init and Teardown Functions +%%-------------------------------------------------------------------- + +init_per_suite(Config) -> + {ok, Pid} = test_statem:start(), + ct:log("Starting test_statem process with PID: ~p", [Pid]), + State = test_statem:get_state(), + ct:log("Init per suite state: ~p", [State]), + ct:log("Init per suite config: ~p", [Config]), + Config. + + +end_per_suite(_Config) -> + %% Cleanup after all tests run + test_statem:stop(). + + +init_per_group(_GroupName, Config) -> + Config. + +end_per_group(_GroupName, Config) -> + Config. + +init_per_testcase(TestName, Config) -> + LogFileName = "test_statem_"++atom_to_list(TestName)++".log", + {ok, FH} = file:open(LogFileName, [write]), + [{file, {FH, LogFileName}} | Config]. + +end_per_testcase(_TestName, Config) -> + {FH, _FileName} = proplists:get_value(file, Config), + file:close(FH), + recon_trace:clear(), % Ensure traces are cleared between tests + proplists:delete(file, Config). + +%%-------------------------------------------------------------------- +%% Helper Functions +%%-------------------------------------------------------------------- + +assert_trace_match(RegexString, TraceOutput) -> + ct:log("Asserting match for ~p in output:~n~p", [RegexString, TraceOutput]), + case re:run(TraceOutput, RegexString, [{capture, none}]) of + match -> ok; + nomatch -> ct:fail({regex_did_not_match, RegexString}) + end. +count_trace_match(RegexString, TraceOutput, ExpCnt) -> + ct:log("Counting if ~p matches for ~p in output:~n~p", [ExpCnt, RegexString, TraceOutput]), + + case re:run(TraceOutput, RegexString, [global]) of + {match, List} when length(List) == ExpCnt -> ok; + {match, List} -> ct:fail({wrong_match_count, RegexString, length(List), ExpCnt}); + nomatch -> ct:fail({regex_did_not_match, RegexString}); + _ -> ct:fail({unexpected, RegexString, ExpCnt}) + + end. + +assert_trace_no_match(RegexString, TraceOutput) -> + ct:log("Asserting match for ~p in output:~n~p", [RegexString, TraceOutput]), + case re:run(TraceOutput, RegexString, [{capture, none}]) of + match -> ct:fail({regex_unexpectedly_matched, RegexString}); + nomatch -> ok + end. + +%%-------------------------------------------------------------------- +%% Test Cases +%%-------------------------------------------------------------------- + +dummy_basic_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + recon_trace:calls({test_statem, light_state, '_'}, 10, [{io_server, FH},{scope,local}]), + test_statem:switch_state(), + S = test_statem:get_state(), + ct:log("State: ~p", [S]), + timer:sleep(100), + {ok, TraceOutput} = file:read_file(FileName), + assert_trace_match("test_statem:light_state\\(cast, switch_state, #{iterator=>0", TraceOutput), + ok. + +%%====================================================================== +%% --------------------------------------------------------------------------- +%% Test cases based on https://ferd.github.io/recon/recon_trace.html#calls/3 +%% --------------------------------------------------------------------------- +%%====================================================================== + +%%====================================================================== +%% Documentation: All calls from the queue module, with 10 calls printed at most: +%% recon_trace:calls({queue, '_', '_'}, 10) +%%--- +%% Test: All calls from the test_statem module, with 10 calls printed at most. +%%--- +%% Function: recon_trace:calls({test_statem, '_', '_'}, 10) +%%====================================================================== +trace_full_module_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + recon_trace:calls({test_statem, '_', '_'}, 100, [{io_server, FH},{scope,local}]), + + timer:sleep(100), + ok = test_statem:switch_state(), + _ = test_statem:get_state(), + timer:sleep(100), + ok = test_statem:switch_state(), + timer:sleep(100), + lists:foreach(fun(_)->test_statem:get_state(), timer:sleep(50) end, lists:seq(1, 7)), % Call get_state multiple times + + {ok, TraceOutput} = file:read_file(FileName), + + count_trace_match("test_statem:get_state\\(\\)", TraceOutput,8), + count_trace_match("test_statem:light_state\\(cast, switch_state, #{iterator=>", TraceOutput,1), + count_trace_match("test_statem:heavy_state\\(cast, switch_state, #{iterator=>", TraceOutput,1), + ok. +%%====================================================================== +%% Documentation: All calls to lists:seq(A,B), with 100 calls printed at most: recon_trace:calls({lists, seq, 2}, 100) +%%--- +%% Test: All calls from the test_statem:get_state module, with 10 calls printed at most. +%%--- +%% Function: recon_trace:calls({test_statem, get_state, '_'}, 10) +%%====================================================================== +trace_one_function_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + recon_trace:calls({test_statem, get_state, 0}, 100, [{io_server, FH},{scope,local}]), + + timer:sleep(100), + ok = test_statem:switch_state(), + _ = test_statem:get_state(), + timer:sleep(100), + ok = test_statem:switch_state(), + timer:sleep(100), + lists:foreach(fun(_)->test_statem:get_state(), timer:sleep(50) end, lists:seq(1, 7)), % Call get_state multiple times + + {ok, TraceOutput} = file:read_file(FileName), + + count_trace_match("test_statem:get_state\\(\\)", TraceOutput,8), + ok. + +%%====================================================================== +%% Documentation: All calls to lists:seq(A,B), with 100 calls per second at most: recon_trace:calls({lists, seq, 2}, {100, 1000}) +%%--- +%% Test: All calls to test_statem:heavy_state(A,B), with 1 call per second printed at most: +%%--- +%% Function: recon_trace:calls({test_statem, heavy_state, 2}, 10) +%%====================================================================== + +trace_rate_limit_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + case test_statem:get_state() of + {ok,light_state,_} -> test_statem:switch_state(); + {ok,heavy_state,_} -> ok + end, + + recon_trace:calls({test_statem, heavy_state, 3}, {1, 1000}, [ {io_server, FH},{scope,local}]), + + timer:sleep(2200), % Allow more time for potential rate limiting delays + recon_trace:clear(), + + {ok, TraceOutput} = file:read_file(FileName), + + count_trace_match("test_statem:heavy_state", TraceOutput, 2), + ok. + +%%====================================================================== +%% Documentation: All calls to lists:seq(A,B,2) (all sequences increasing by two) with 100 calls at most: +%% recon_trace:calls({lists, seq, fun([_,_,2]) -> ok end}, 100) +%%--- +%% Test: All calls to test_statem:heavy_state(A,B) where B is even, with 10 calls at most: +%%--- +%% Function: recon_trace:calls({test_statem, heavy_state, fun([_, B]) when is_integer(B), B rem 2 == 0 -> ok end}, 10) +%%====================================================================== + +trace_even_arg_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + case test_statem:get_state() of + {ok,light_state,_} -> test_statem:switch_state(); + {ok,heavy_state,_} -> ok + + end, + MatchSpec = dbg:fun2ms(fun([_,_,#{iterator=>N}]) when N rem 2 == 0 -> return_trace() end), + + recon_trace:calls({test_statem, heavy_state, MatchSpec}, 10, [{io_server, FH},{scope,local}]), + timer:sleep(1900), + recon_trace:clear(), + {ok, TraceOutput} = file:read_file(FileName), + + count_trace_match("test_statem:heavy_state\\(timeout", TraceOutput, 3), + ok. +%%====================================================================== +%% Documentation: All calls to iolist_to_binary/1 made with a binary as an argument already (kind of useless conversion!): +%% recon_trace:calls({erlang, iolist_to_binary, fun([X]) when is_binary(X) -> ok end}, 10) +%%--- +%% Test: All calls to iolist_to_binary/1 made with a binary argument. +%%--- +%% Function: recon_trace:calls({erlang, iolist_to_binary, fun([X]) when is_binary(X) -> ok end}, 10) +%%--- +%% NOTE: Maybe there is a way to transform fun_shell directly in recon as in erlang shell +%%====================================================================== + +trace_iolist_to_binary_with_binary_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + MatchSpec = dbg:fun2ms(fun([X]) when is_binary(X) -> return_trace() end), + recon_trace:calls({erlang, iolist_to_binary, MatchSpec}, 10, [ {io_server, FH},{scope,local}]), + + _ = erlang:iolist_to_binary(<<"already binary">>), % Should trace + _ = erlang:iolist_to_binary(["not binary"]), % Should NOT trace + _ = erlang:iolist_to_binary([<<"mix">>, "ed"]), % Should NOT trace + _ = erlang:iolist_to_binary(<<"another binary">>), % Should trace + + timer:sleep(100), + {ok, TraceOutput} = file:read_file(FileName), + + recon_trace:clear(), + + assert_trace_match("erlang:iolist_to_binary\\(<<\"already binary\">>\\)", TraceOutput), + assert_trace_match("erlang:iolist_to_binary\\(<<\"another binary\">>\\)", TraceOutput), + assert_trace_no_match("erlang:iolist_to_binary\\(\\[\"not binary\"\\]\\)", TraceOutput), + assert_trace_no_match("erlang:iolist_to_binary\\(\\[<<\"mix\">>,\"ed\"\\]\\)", TraceOutput), + ok. + +%%====================================================================== +%% Documentation: Calls to the queue module only in a given process Pid, +%% at a rate of 50 per second at most: recon_trace:calls({queue, '_', '_'}, {50,1000}, [{pid, Pid}]) +%%--- +%% Test: Calls to the test_statem module only in the test_statem process Pid, at a rate of 10 per second at most. +%%--- +%% Function: recon_trace:calls({test_statem, '_', '_'}, {10,1000}, [{pid, Pid}]) +%%====================================================================== +trace_specific_pid_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + %%default statem state is heavy_state + case test_statem:get_state() of + {ok,light_state,_} -> test_statem:switch_state(); + {ok,heavy_state,_} -> ok + end, + %% new statem in light state + {ok, Pid} = gen_statem:start(test_statem, [], []), + + recon_trace:calls({test_statem, '_', '_'}, {10,1000}, [{pid, Pid}, {io_server, FH},{scope,local}]), + + gen_statem:call(Pid, get_value), + gen_statem:call(Pid, get_value), + %% Call from another process - should NOT trace + test_statem:get_state(), + test_statem:get_state(), + test_statem:get_state(), + timer:sleep(100), + recon_trace:clear(), + + {ok, TraceOutput} = file:read_file(FileName), + %% Check calls originating from are traced (e.g., handle_event) + count_trace_match(".*test_statem:light_state", TraceOutput,2), + %% Check calls from the other process are NOT traced + assert_trace_no_match(".*test_statem:heavy_state", TraceOutput), + is_process_alive(Pid) andalso exit(Pid, kill), % Cleanup spawned proc + ok. + +%%====================================================================== +%% Documentation: Print the traces with the function arity instead of literal arguments: +%% recon_trace:calls(TSpec, Max, [{args, arity}]) +%%--- +%% Test: Print traces for test_statem calls with arity instead of arguments. +%%--- +%% Function: recon_trace:calls({test_statem, '_', '_'}, 10, [{args, arity}]) +%%====================================================================== +trace_arity_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + recon_trace:calls({test_statem, '_', '_'}, 10, [{args, arity}, {io_server, FH},{scope,local}]), + + test_statem:get_state(), + ok = test_statem:switch_state(), + ok = test_statem:switch_state(), + timer:sleep(100), + recon_trace:clear(), + {ok, TraceOutput} = file:read_file(FileName), + %% Check for arity format, e.g., module:function/arity + assert_trace_match("test_statem:get_state/0", TraceOutput), % gen_statem callback arity + assert_trace_match("test_statem:light_state/3", TraceOutput), % gen_statem callback arity + %% Ensure literal args are not present + assert_trace_no_match("switch_state\\(", TraceOutput), + assert_trace_no_match("iterator", TraceOutput), + ok. + +%%====================================================================== +%% Documentation: Matching the filter/2 functions of both dict and lists modules, across new processes only: +%% recon_trace:calls([{dict,filter,2},{lists,filter,2}], 10, [{pid, new}]) +%%--- +%% Test: Matching light_state/2 and heavy_state/2 calls in test_statem across new processes only. +%%--- +%% Function: recon_trace:calls([{test_statem, light_state, 2}, {test_statem, heavy_state, 2}], 10, [{pid, new}]) +%%====================================================================== +trace_spec_list_new_procs_only_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + case test_statem:get_state() of + {ok,light_state,_} -> test_statem:switch_state(); + {ok,heavy_state,_} -> ok + end, + + recon_trace:calls([{test_statem, light_state, '_'}, {test_statem, heavy_state, '_'}], 10, [{pid, new}, {io_server, FH},{scope,local}]), + + {ok, heavy_state,_} = test_statem:get_state(), + %% Call from a *new* process - should trace + {ok, NewPid} = gen_statem:start(test_statem, [], []), + + gen_statem:call(NewPid, get_value), + gen_statem:call(NewPid, get_value), + + %% Call from old process - should NOT trace + test_statem:get_state(), + test_statem:get_state(), + test_statem:get_state(), + timer:sleep(1000), + recon_trace:clear(), + + {ok, TraceOutput} = file:read_file(FileName), + %% Check calls from the new process ARE traced + count_trace_match("test_statem:light_state", TraceOutput, 2), + assert_trace_no_match("test_statem:heavy_state", TraceOutput), + is_process_alive(NewPid) andalso exit(NewPid, kill), % Cleanup spawned proc + ok. +%%====================================================================== +%% Documentation: Tracing the handle_call/3 functions of a given module for all new processes, and those of an existing one registered with gproc: +%% recon_trace:calls({Mod,handle_call,3}, {10,100}, [{pid, [{via, gproc, Name}, new]}]) +%%--- +%% Test: Tracing test_statem for new processes and one via custom process register. +%%--- +%% Function: recon_trace:calls({test_statem, handle_call, 3}, {10, 100}, [{pid, [{via, fake_reg, ts_test}, new]}]) +%%====================================================================== +trace_handle_call_new_and_custom_registry_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + try + case test_statem:get_state() of + {ok,light_state,_} -> test_statem:switch_state(); + {ok,heavy_state,_} -> ok + end, + fake_reg:start(), + {ok, NewPid} = gen_statem:start({via, fake_reg, ts_test}, test_statem, [], []), + + recon_trace:calls([{test_statem, light_state, '_'}, {test_statem, heavy_state, '_'}], 10, + [{pid, [{via, fake_reg, ts_test}, new]}, {io_server, FH},{scope,local}]), + + gen_statem:call({via, fake_reg, ts_test}, get_value), + gen_statem:call(NewPid, get_value), + + %% Call from old process - should NOT trace + test_statem:get_state(), + test_statem:get_state(), + test_statem:get_state(), + timer:sleep(100), + recon_trace:clear(), + + {ok, TraceOutput} = file:read_file(FileName), + %% Check calls from the new process ARE traced + count_trace_match("test_statem:light_state", TraceOutput, 2), + assert_trace_no_match("test_statem:heavy_state", TraceOutput) + after + gen_statem:stop({via, fake_reg, ts_test}), + fake_reg:stop() + end. +%%====================================================================== +%% Documentation: Show the result of a given function call: recon_trace:calls({Mod,Fun,fun(_) -> return_trace() end}, Max, Opts) +%%--- +%% Test: Show the result of test_statem:get_state/0 calls. +%%--- +%% Function: recon_trace:calls({test_statem, get_state, fun(_) -> return_trace() end}, 10) +%%--- +%% NOTE: Maybe there is a way to transform fun_shell directly in recon as in erlang shell +%%====================================================================== +trace_return_shellfun_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + case test_statem:get_state() of + {ok,light_state,_} -> ok; + {ok,heavy_state,_} -> test_statem:switch_state() + end, + + MatchSpec = dbg:fun2ms(fun(_) -> return_trace() end), + + recon_trace:calls({test_statem, get_state, MatchSpec}, 10, [ {io_server, FH},{scope,local}]), + + {ok,light_state, N} = test_statem:get_state(), + + timer:sleep(100), + recon_trace:clear(), + + {ok, TraceOutput} = file:read_file(FileName), + %% Check for the call and its return value + assert_trace_match("test_statem:get_state/0 --> {ok,light_state,"++integer_to_list(N)++"}", TraceOutput), + ok. +%%====================================================================== +%% Documentation: Show the result of a given function call: +%% recon_trace:calls({Mod,Fun,[{'_', [], [{return_trace}]}]}, Max, Opts), +%%--- +%% Test: Show the result of test_statem:get_state/0 calls (using match spec). +%%--- +%% Function: recon_trace:calls({test_statem, get_state, [{'_', [], [{return_trace}]}]}, 10) +%%====================================================================== +trace_return_matchspec_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + case test_statem:get_state() of + {ok,heavy_state,_} -> ok; + {ok,light_state,_} -> test_statem:switch_state() + end, + %% Trace the API function test_statem:get_state/1 using match spec + recon_trace:calls({test_statem, get_state, [{'_', [], [{return_trace}]}]}, 10, [ {io_server, FH},{scope,local}]), + + {ok,heavy_state, N} = test_statem:get_state(), + timer:sleep(100), + recon_trace:clear(), + {ok, TraceOutput} = file:read_file(FileName), + + %% Check for the call and its return value + assert_trace_match("test_statem:get_state/0 --> {ok,heavy_state,"++integer_to_list(N)++"}", TraceOutput), + ok. + +%%====================================================================== +%% Documentation: A short-hand version for this pattern of 'match anything, trace everything' +%% for a function is recon_trace:calls({Mod, Fun, return_trace}). +%%--- +%% Test: Show the result of test_statem:get_state/0 calls (shorthand). +%%--- +%% Function: recon_trace:calls({test_statem, get_state, return_trace}, 10). +%%====================================================================== +trace_return_shorthand_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + case test_statem:get_state() of + {ok,light_state,_} -> ok; + {ok,heavy_state,_} -> test_statem:switch_state() + end, + %% Trace the API function test_statem:get_state/1 using shorthand + recon_trace:calls({test_statem, get_state, return_trace}, 10, [ {io_server, FH},{scope,local}]), + {ok,light_state, N} = test_statem:get_state(), + timer:sleep(100), + recon_trace:clear(), + + {ok, TraceOutput} = file:read_file(FileName), + + %% Check for the call and its return value + assert_trace_match("test_statem:get_state/0 --> {ok,light_state,"++integer_to_list(N)++"}", TraceOutput), + ok. +%%====================================================================== +%% Documentation: The timestamp option adds a timestamp to the trace output. +%% recon_trace:calls({Mod, Fun, return_trace}, 10, [{timestamp, true}]). +%%--- +%% Test: Show the result of test_statem:get_state/0 calls. +%%--- +%% Function: recon_trace:calls({test_statem, get_state, '_'}, 10). +%%====================================================================== +trace_timestamp_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + case test_statem:get_state() of + {ok,light_state,_} -> ok; + {ok,heavy_state,_} -> test_statem:switch_state() + end, + %% Trace the API function test_statem:get_state/1 using shorthand + recon_trace:calls({test_statem, get_state, '_'}, 10, + [ {io_server, FH},{scope,local}, {timestamp, trace}]), + {ok,light_state, _} = test_statem:get_state(), + timer:sleep(100), + recon_trace:clear(), + + {ok, TraceOutput} = file:read_file(FileName), + + %% Check for the call and its return value + assert_trace_match("test_statem:get_state\\(", TraceOutput), + ok. + +%%====================================================================== +%% Documentation: The return_to option adds a traces for calls pointing where +%% local functions return result to. +%% recon_trace:calls({Mod, Fun, return_trace}, 10, [{return_to, true}]). +%%--- +%% Test: Show the result of test_statem:get_state/0 calls and the return to trace. +%%--- +%% Function: recon_trace:calls({test_statem, get_state, '_'}, 10). +%%====================================================================== +trace_return_to_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + case test_statem:get_state() of + {ok,light_state,_} -> ok; + {ok,heavy_state,_} -> test_statem:switch_state() + end, + %% Trace the API function test_statem:get_state/1 using shorthand + recon_trace:calls({test_statem, get_state, '_'}, 10, + [ {io_server, FH},{scope,local}, {return_to, true}]), + {ok,light_state, _} = test_statem:get_state(), + timer:sleep(100), + recon_trace:clear(), + + {ok, TraceOutput} = file:read_file(FileName), + + %% Check for the call and its return value + assert_trace_match("test_statem:get_state\\(", TraceOutput), + assert_trace_match("--> "++atom_to_list(?MODULE)++":trace_return_to_test/1", TraceOutput), + ok. diff --git a/test/recon_trace_use_dbg_SUITE.erl b/test/recon_trace_use_dbg_SUITE.erl new file mode 100755 index 0000000..c683a7b --- /dev/null +++ b/test/recon_trace_use_dbg_SUITE.erl @@ -0,0 +1,870 @@ +%%%------------------------------------------------------------------- +%%% @author +%%% [https://flmath.github.io] +%%% @doc +%%% Common Test Suite for recon_trace_use_dbg functionality. +%%% Tests various scenarios related to use_dbg flag. +%%% @end +%%%------------------------------------------------------------------- + +-module(recon_trace_use_dbg_SUITE). + +-include_lib("common_test/include/ct.hrl"). +-include_lib("stdlib/include/ms_transform.hrl"). +-compile({parse_transform, ms_transform}). + +-export([ + all/0, groups/0, + init_per_suite/1, end_per_suite/1, + init_per_group/2, end_per_group/2, + init_per_testcase/2, end_per_testcase/2 + ]). + +-export([ + count_trace_match/3, + assert_trace_match/2, + assert_trace_no_match/2 + ]). + +%% Test cases +-export([ + dummy_basic_test/1, + dummy_basic_trace_test/1, + trace_full_module_test/1, + trace_one_function_test/1, + trace_map_match_test/1, + trace_binary_all_pattern_test/1, + trace_binary_patterns_test/1, + trace_rate_limit_test/1, + trace_even_arg_test/1, + trace_iolist_to_binary_with_binary_test/1, + trace_specific_pid_test/1, + trace_multi_pid_test/1, + trace_arity_test/1, + trace_spec_list_new_procs_only_test/1, + trace_handle_call_new_and_custom_registry_test/1, + trace_return_shellfun_test/1, + trace_return_matchspec_test/1, + trace_return_shorthand_test/1, + trace_timestamp_test/1, + trace_return_to_test/1, + trace_no_return_to_test/1, + trace_suppress_print_test/1, + trace_custom_value_print_test/1, + trace_plugin_tracker_test/1 + ]). + + + +%%-------------------------------------------------------------------- +%% Suite Configuration +%%-------------------------------------------------------------------- + +%% @doc Returns list of test cases and/or groups to be executed. +all() -> + [{group, use_dbg_test}, {group, doc_based_test}]. + +%% @doc Defines the test groups. +groups() -> + [ + {doc_based_test, [sequence], [ + trace_full_module_test, + trace_one_function_test, + trace_rate_limit_test, + trace_even_arg_test, + trace_iolist_to_binary_with_binary_test, + trace_specific_pid_test, + trace_multi_pid_test, + trace_arity_test, + trace_spec_list_new_procs_only_test, + trace_handle_call_new_and_custom_registry_test, + trace_return_shellfun_test, + trace_return_matchspec_test, + trace_return_shorthand_test + ] + }, + {use_dbg_test, [sequence], [ + dummy_basic_trace_test, + trace_map_match_test, + trace_binary_patterns_test, + trace_binary_all_pattern_test, + dummy_basic_test, + trace_timestamp_test, + trace_return_to_test, + trace_no_return_to_test, + trace_suppress_print_test, + trace_custom_value_print_test, + trace_plugin_tracker_test + + ] + } + ]. + +%%-------------------------------------------------------------------- +%% Init and Teardown Functions +%%-------------------------------------------------------------------- + +init_per_suite(Config) -> + {ok, Pid} = test_statem:start(), + ct:log("Starting test_statem process with PID: ~p", [Pid]), + State = test_statem:get_state(), + ct:log("Init per suite state: ~p", [State]), + ct:log("Init per suite config: ~p", [Config]), + Config. + + +end_per_suite(_Config) -> + %% Cleanup after all tests run + test_statem:stop(). + + +init_per_group(_GroupName, Config) -> + Config. + +end_per_group(_GroupName, Config) -> + Config. + +init_per_testcase(TestName, Config) -> + LogFileName = "test_statem_"++atom_to_list(TestName)++".log", + {ok, FH} = file:open(LogFileName, [write]), + [{file, {FH, LogFileName}} | Config]. + +end_per_testcase(_TestName, Config) -> + {FH, _FileName} = proplists:get_value(file, Config), + file:close(FH), + recon_trace:clear(), % Ensure traces are cleared between tests + proplists:delete(file, Config). + +%%-------------------------------------------------------------------- +%% Helper Functions +%%-------------------------------------------------------------------- + +assert_trace_match(RegexString, TraceOutput) -> + ct:log("Asserting match for ~p in output:~n~p", [RegexString, TraceOutput]), + case re:run(TraceOutput, RegexString, [{capture, none}]) of + match -> ok; + nomatch -> ct:fail({regex_did_not_match, RegexString}) + end. +count_trace_match(RegexString, TraceOutput, ExpCnt) -> + ct:log("Counting if ~p matches for ~p in output:~n~p", [ExpCnt, RegexString, TraceOutput]), + + case re:run(TraceOutput, RegexString, [global]) of + {match, List} when length(List) == ExpCnt -> ok; + {match, List} -> ct:fail({wrong_match_count, RegexString, length(List), ExpCnt}); + nomatch -> ct:fail({regex_did_not_match, RegexString}); + _ -> ct:fail({unexpected, RegexString, ExpCnt}) + + end. + +assert_trace_no_match(RegexString, TraceOutput) -> + ct:log("Asserting match for ~p in output:~n~p", [RegexString, TraceOutput]), + case re:run(TraceOutput, RegexString, [{capture, none}]) of + match -> ct:fail({regex_unexpectedly_matched, RegexString}); + nomatch -> ok + end. + +%%-------------------------------------------------------------------- +%% Test Cases +%%-------------------------------------------------------------------- + +dummy_basic_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + case test_statem:get_state() of + {ok,light_state,_} -> ok; + {ok,heavy_state,_} -> test_statem:switch_state() + end, + + Num = recon_trace:calls({test_statem, light_state, fun([cast, switch_state, _]) -> print end}, 10, + [{io_server, FH}, {use_dbg, true}, {scope,local}]), + + ct:log("Number of traces: ~p", [Num]), + + test_statem:switch_state(), + S = test_statem:get_state(), + ct:log("State: ~p", [S]), + timer:sleep(100), + {ok, TraceOutput} = file:read_file(FileName), + assert_trace_match("test_statem:light_state\\(cast, switch_state, #{iterator=>", TraceOutput), + ok. + +dummy_basic_trace_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + case test_statem:get_state() of + {ok,light_state,_} -> ok; + {ok,heavy_state,_} -> test_statem:switch_state() + end, + + MatchSpec = dbg:fun2ms(fun(_) -> return_trace() end), + recon_trace:calls({test_statem, light_state, MatchSpec}, 10, + [{io_server, FH}, {use_dbg, true}, {scope,local}]), + + test_statem:switch_state(), + S = test_statem:get_state(), + ct:log("State: ~p", [S]), + timer:sleep(100), + {ok, TraceOutput} = file:read_file(FileName), + assert_trace_match("test_statem:light_state\\(cast, switch_state, #{iterator=>0", TraceOutput), + ok. + +%%====================================================================== +%% Documentation: All calls from the queue module, with 10 calls printed at most: +%% recon_trace:calls({queue, '_', '_'}, 10) +%%--- +%% Test: All calls from the test_statem module, with 10 calls printed at most. +%%--- +%%====================================================================== +trace_full_module_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + recon_trace:calls({test_statem, '_', '_'}, 100, + [{io_server, FH}, {use_dbg, true}, {scope,local}]), + + timer:sleep(100), + ok = test_statem:switch_state(), + _ = test_statem:get_state(), + timer:sleep(100), + ok = test_statem:switch_state(), + timer:sleep(100), + lists:foreach(fun(_)->test_statem:get_state(), timer:sleep(50) end, lists:seq(1, 7)), % Call get_state multiple times + + {ok, TraceOutput} = file:read_file(FileName), + %% there are race conditions when test ends, so + count_trace_match("test_statem:get_state\\(\\)", TraceOutput,8), + count_trace_match("test_statem:light_state\\(cast, switch_state, #{iterator=>", TraceOutput,1), + count_trace_match("test_statem:heavy_state\\(cast, switch_state, #{iterator=>", TraceOutput,1), + ok. +%%====================================================================== +%% Documentation: All calls to lists:seq(A,B), with 100 calls printed at most: recon_trace:calls({lists, seq, 2}, 100) +%%--- +%% Test: All calls from the test_statem:get_state module, with 10 calls printed at most. +%%--- +%%====================================================================== +trace_one_function_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + recon_trace:calls({test_statem, get_state, 0}, 100, + [{io_server, FH}, {use_dbg, true}, {scope,local}]), + + timer:sleep(100), + ok = test_statem:switch_state(), + _ = test_statem:get_state(), + timer:sleep(100), + ok = test_statem:switch_state(), + timer:sleep(100), + lists:foreach(fun(_)->test_statem:get_state(), timer:sleep(50) end, lists:seq(1, 7)), % Call get_state multiple times + + {ok, TraceOutput} = file:read_file(FileName), + + count_trace_match("test_statem:get_state\\(\\)", TraceOutput,8), + ok. + +%%====================================================================== +%% Documentation: All calls to lists:seq(A,B), with 100 calls per second at most: recon_trace:calls({lists, seq, 2}, {100, 1000}) +%%--- +%% Test: All calls to test_statem:heavy_state(A,B), with 1 call per second printed at most: +%%--- +%%====================================================================== + +trace_rate_limit_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + case test_statem:get_state() of + {ok,light_state,_} -> test_statem:switch_state(); + {ok,heavy_state,_} -> ok + end, + + recon_trace:calls({test_statem, heavy_state, 3}, {1, 1000}, + [{io_server, FH}, {use_dbg, true}, {scope,local}]), + + timer:sleep(4000), % Allow more time for potential rate limiting delays + recon_trace:clear(), + + {ok, TraceOutput} = file:read_file(FileName), + + count_trace_match("test_statem:heavy_state", TraceOutput, 2), + ok. + +%%====================================================================== +%% Documentation: All calls to lists:seq(A,B,2) (all sequences increasing by two) with 100 calls at most: +%% recon_trace:calls({lists, seq, fun([_,_,2]) -> ok end}, 100) +%%--- +%% Test: All calls to test_statem:heavy_state(A,B) where B is even, with 10 calls at most: +%%--- +%%====================================================================== + +trace_even_arg_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + case test_statem:get_state() of + {ok,light_state,_} -> test_statem:switch_state(); + {ok,heavy_state,_} -> ok + + end, + MatchSpec = fun([_,_,#{iterator:=N}]) when N rem 2 == 0 -> print end, + + recon_trace:calls({test_statem, heavy_state, MatchSpec}, 10, + [{io_server, FH}, {use_dbg, true}, {scope,local}]), + timer:sleep(1900), + recon_trace:clear(), + {ok, TraceOutput} = file:read_file(FileName), + + count_trace_match("test_statem:heavy_state\\(timeout", TraceOutput, 3), + ok. +%%%====================================================================== +%% Documentation: Test matching maps with a specific pattern. +%%--- +%% Test: Use dbg flag to pattern match maps with a specific pattern. +%%--- +%% NOTE: Possible only with the use_dbg flag. +%%====================================================================== + +trace_map_match_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + MatchSpec = fun([#{a:=b}]) -> print end, + recon_trace:calls({maps, to_list, MatchSpec}, 10, + [{io_server, FH}, {use_dbg, true}, {scope,local}]), + + _ = maps:to_list(#{}), % Should NOT trace + _ = maps:to_list(#{a=>b}), % Should trace + _ = maps:to_list(#{a=>c}), % Should NOT trace + _ = maps:to_list(#{a=>b, c=>d}), % Should trace + + timer:sleep(100), + {ok, TraceOutput} = file:read_file(FileName), + + recon_trace:clear(), + + assert_trace_match("maps:to_list\\(#{a=>b}\\)", TraceOutput), + assert_trace_match("maps:to_list\\(#{.*c=>d", TraceOutput), + assert_trace_no_match("maps:to_list\\(#{a=>c}\\)", TraceOutput), + assert_trace_no_match("maps:to_list\\(#{}\\)", TraceOutput), + ok. + +%====================================================================== +%% Documentation: Test matching binaries with binary guard. +%%--- +%% Test: Use dbg flag to pattern match binaries with guard. +%%--- +%%====================================================================== + +trace_iolist_to_binary_with_binary_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + MatchSpec = fun([X]) when is_binary(X) -> print end, + recon_trace:calls({erlang, iolist_to_binary, MatchSpec}, 10, + [{io_server, FH}, {use_dbg, true}, {scope,local}]), + + _ = erlang:iolist_to_binary(<<"already binary">>), % Should trace + _ = erlang:iolist_to_binary(["not binary"]), % Should NOT trace + _ = erlang:iolist_to_binary([<<"mix">>, "ed"]), % Should NOT trace + _ = erlang:iolist_to_binary(<<"another binary">>), % Should trace + + timer:sleep(100), + {ok, TraceOutput} = file:read_file(FileName), + + recon_trace:clear(), + + assert_trace_match("erlang:iolist_to_binary\\(<<\"already binary\">>\\)", TraceOutput), + assert_trace_match("erlang:iolist_to_binary\\(<<\"another binary\">>\\)", TraceOutput), + assert_trace_no_match("erlang:iolist_to_binary\\(\\[\"not binary\"\\]\\)", TraceOutput), + assert_trace_no_match("erlang:iolist_to_binary\\(\\[<<\"mix\">>,\"ed\"\\]\\)", TraceOutput), + ok. + +%%====================================================================== +%% Documentation: Test matching binaries. +%%--- +%% Test: Use dbg flag to pattern match binaries. +%%--- +%% NOTE: Possible only with the use_dbg flag. +%%=========================================== + +trace_binary_all_pattern_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + MatchSpec = fun([<<_X/binary>>]) -> print end, + recon_trace:calls({erlang, iolist_to_binary, MatchSpec}, 10, + [{io_server, FH}, {use_dbg, true}, {scope,local}]), + + _ = erlang:iolist_to_binary(<<"already binary">>), % Should trace + _ = erlang:iolist_to_binary(["not binary"]), % Should NOT trace + _ = erlang:iolist_to_binary([<<"mix">>, "ed"]), % Should NOT trace + _ = erlang:iolist_to_binary(<<"another binary">>), % Should trace + + timer:sleep(100), + {ok, TraceOutput} = file:read_file(FileName), + + recon_trace:clear(), + + assert_trace_match("erlang:iolist_to_binary\\(<<\"already binary\">>\\)", TraceOutput), + assert_trace_match("erlang:iolist_to_binary\\(<<\"another binary\">>\\)", TraceOutput), + assert_trace_no_match("erlang:iolist_to_binary\\(\\[\"not binary\"\\]\\)", TraceOutput), + assert_trace_no_match("erlang:iolist_to_binary\\(\\[<<\"mix\">>,\"ed\"\\]\\)", TraceOutput), + ok. + + +%%====================================================================== +%% Documentation: Test matching binaries with a specific pattern. +%% +%% recon_trace:calls({erlang, iolist_to_binary, fun([X]) when is_binary(X) -> ok end}, 10) +%%--- +%% Test: Use dbg flag to pattern match parts of binaries. +%%--- +%% NOTE: Possible only with the use_dbg flag. +%%=========================================== + +trace_binary_patterns_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + MatchSpec = fun([<<"already",_/binary>>]) -> print end, + recon_trace:calls({erlang, iolist_to_binary, MatchSpec}, 10, + [{io_server, FH}, {use_dbg, true}, {scope,local}]), + + _ = erlang:iolist_to_binary(<<"already binary">>), % Should trace + _ = erlang:iolist_to_binary(["not binary"]), % Should NOT trace + _ = erlang:iolist_to_binary([<<"mix">>, "ed"]), % Should NOT trace + _ = erlang:iolist_to_binary(<<"another binary">>), % Should NOT trace + + timer:sleep(100), + {ok, TraceOutput} = file:read_file(FileName), + + recon_trace:clear(), + + assert_trace_match("erlang:iolist_to_binary\\(<<\"already binary\">>\\)", TraceOutput), + assert_trace_no_match("erlang:iolist_to_binary\\(<<\"another binary\">>\\)", TraceOutput), + assert_trace_no_match("erlang:iolist_to_binary\\(\\[\"not binary\"\\]\\)", TraceOutput), + assert_trace_no_match("erlang:iolist_to_binary\\(\\[<<\"mix\">>,\"ed\"\\]\\)", TraceOutput), + ok. + + +%%====================================================================== +%% Documentation: Calls to the queue module only in a given process Pid, +%% at a rate of 50 per second at most: recon_trace:calls({queue, '_', '_'}, {50,1000}, [{pid, Pid}]) +%%--- +%% Test: Calls to the test_statem module only in the test_statem process Pid, at a rate of 10 per second at most. +%%--- +%%====================================================================== +trace_specific_pid_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + %%default statem state is heavy_state + case test_statem:get_state() of + {ok,light_state,_} -> test_statem:switch_state(); + {ok,heavy_state,_} -> ok + end, + %% new statem in light state + {ok, Pid} = gen_statem:start(test_statem, [], []), + + recon_trace:calls({test_statem, '_', '_'}, {10,1000}, + [{pid, Pid}, {io_server, FH}, {use_dbg, true}, {scope,local}]), + + gen_statem:call(Pid, get_value), + gen_statem:call(Pid, get_value), + %% Call from another process - should NOT trace + test_statem:get_state(), + test_statem:get_state(), + test_statem:get_state(), + timer:sleep(100), + recon_trace:clear(), + + {ok, TraceOutput} = file:read_file(FileName), + %% Check calls originating from are traced (e.g., handle_event) + count_trace_match(".*test_statem:light_state", TraceOutput,2), + %% Check calls from the other process are NOT traced + assert_trace_no_match(".*test_statem:heavy_state", TraceOutput), + is_process_alive(Pid) andalso exit(Pid, kill), % Cleanup spawned proc + ok. + +%%====================================================================== +%% Documentation: Calls to the queue module only in given 2 processes Pid, +%% at a rate of 50 per second at most: recon_trace:calls({queue, '_', '_'}, {50,1000}, [{pid, Pid}]) +%%--- +%% Test: Calls to the test_statem module only in the test_statem 2 processes Pids, at a rate of 10 per second at most. +%%--- +%%====================================================================== +trace_multi_pid_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + %% new statem in light state + {ok, Pid} = gen_statem:start(test_statem, [], []), + {ok, Pid2} = gen_statem:start(test_statem, [], []), + + %% the second statem state is heavy_state + gen_statem:cast(Pid2, switch_state), + + recon_trace:calls({test_statem, '_', '_'}, {10,1000}, + [{pid, [Pid, Pid2]}, {io_server, FH}, {use_dbg, true}, {scope,local}]), + + gen_statem:call(Pid, get_value), + gen_statem:call(Pid, get_value), + gen_statem:call(Pid2, get_value), + gen_statem:call(Pid2, get_value), + gen_statem:call(Pid2, get_value), + timer:sleep(100), + recon_trace:clear(), + + {ok, TraceOutput} = file:read_file(FileName), + %% Check calls originating from are traced (e.g., handle_event) + count_trace_match(".*test_statem:light_state", TraceOutput,2), + %% Check calls from the other process are NOT traced + count_trace_match(".*test_statem:heavy_state", TraceOutput,3), + is_process_alive(Pid) andalso exit(Pid, kill), % Cleanup spawned proc + is_process_alive(Pid2) andalso exit(Pid2, kill), % Cleanup spawned proc + ok. + + +%%====================================================================== +%% Documentation: Print the traces with the function arity instead of literal arguments: +%% recon_trace:calls(TSpec, Max, [{args, arity}]) +%%--- +%% Test: Print traces for test_statem calls with arity instead of arguments. +%%--- +%%====================================================================== +trace_arity_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + recon_trace:calls({test_statem, '_', '_'}, 10, + [{args, arity}, {io_server, FH}, {use_dbg, true}, {scope,local}]), + + test_statem:get_state(), + ok = test_statem:switch_state(), + ok = test_statem:switch_state(), + timer:sleep(100), + recon_trace:clear(), + {ok, TraceOutput} = file:read_file(FileName), + %% Check for arity format, e.g., module:function/arity + assert_trace_match("test_statem:get_state/0", TraceOutput), % gen_statem callback arity + assert_trace_match("test_statem:light_state/3", TraceOutput), % gen_statem callback arity + %% Ensure literal args are not present + assert_trace_no_match("switch_state\\(", TraceOutput), + assert_trace_no_match("iterator", TraceOutput), + ok. + +%%====================================================================== +%% Documentation: Matching the filter/2 functions of both dict and lists modules, across new processes only: +%% recon_trace:calls([{dict,filter,2},{lists,filter,2}], 10, [{pid, new}]) +%%--- +%% Test: Matching light_state/2 and heavy_state/2 calls in test_statem across new processes only. +%%--- +%%====================================================================== +trace_spec_list_new_procs_only_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + case test_statem:get_state() of + {ok,light_state,_} -> test_statem:switch_state(); + {ok,heavy_state,_} -> ok + end, + + recon_trace:calls([{test_statem, light_state, fun(_) -> print end}, {test_statem, heavy_state, '_'}], 10, + [{pid, new}, {io_server, FH}, {use_dbg, true}, {scope,local}]), + + {ok, heavy_state,_} = test_statem:get_state(), + %% Call from a *new* process - should trace + {ok, NewPid} = gen_statem:start(test_statem, [], []), + + gen_statem:call(NewPid, get_value), + gen_statem:call(NewPid, get_value), + + %% Call from old process - should NOT trace + test_statem:get_state(), + test_statem:get_state(), + test_statem:get_state(), + timer:sleep(1000), + recon_trace:clear(), + + {ok, TraceOutput} = file:read_file(FileName), + %% Check calls from the new process ARE traced + count_trace_match("test_statem:light_state", TraceOutput, 2), + assert_trace_no_match("test_statem:heavy_state", TraceOutput), + is_process_alive(NewPid) andalso exit(NewPid, kill), % Cleanup spawned proc + ok. +%%====================================================================== +%% Documentation: Tracing the handle_call/3 functions of a given module for all new processes, and those of an existing one registered with gproc: +%% recon_trace:calls({Mod,handle_call,3}, {10,100}, [{pid, [{via, gproc, Name}, new]}]) +%%--- +%% Test: Tracing test_statem for new processes and one via custom process register. +%%--- +%%====================================================================== +trace_handle_call_new_and_custom_registry_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + try + case test_statem:get_state() of + {ok,light_state,_} -> test_statem:switch_state(); + {ok,heavy_state,_} -> ok + end, + fake_reg:start(), + {ok, NewPid} = gen_statem:start({via, fake_reg, ts_test}, test_statem, [], []), + + recon_trace:calls([{test_statem, light_state, '_'}, {test_statem, heavy_state, '_'}], 10, + [{pid, [{via, fake_reg, ts_test}, new]}, {io_server, FH}, {use_dbg, true}, {scope,local}]), + + gen_statem:call({via, fake_reg, ts_test}, get_value), + gen_statem:call(NewPid, get_value), + + %% Call from old process - should NOT trace + test_statem:get_state(), + test_statem:get_state(), + test_statem:get_state(), + timer:sleep(100), + recon_trace:clear(), + + {ok, TraceOutput} = file:read_file(FileName), + %% Check calls from the new process ARE traced + count_trace_match("test_statem:light_state", TraceOutput, 2), + assert_trace_no_match("test_statem:heavy_state", TraceOutput) + after + gen_statem:stop({via, fake_reg, ts_test}), + fake_reg:stop() + end. +%%====================================================================== +%% Documentation: Show the result of a given function call: recon_trace:calls({Mod,Fun,fun(_) -> return_trace() end}, Max, Opts) +%%--- +%% Test: Show the result of test_statem:get_state/0 calls. +%% The recon_trace:calls calls back default implementation. +%%--- +%%====================================================================== +trace_return_shellfun_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + case test_statem:get_state() of + {ok,light_state,_} -> ok; + {ok,heavy_state,_} -> test_statem:switch_state() + end, + + MatchSpec = dbg:fun2ms(fun(_) -> return_trace() end), + + recon_trace:calls({test_statem, get_state, MatchSpec}, 10, + [{io_server, FH}, use_dbg, {scope,local}]), + + {ok,light_state, N} = test_statem:get_state(), + + timer:sleep(100), + recon_trace:clear(), + + {ok, TraceOutput} = file:read_file(FileName), + %% Check for the call and its return value + assert_trace_match("test_statem:get_state/0 --> {ok,light_state,"++integer_to_list(N)++"}", TraceOutput), + ok. +%%====================================================================== +%% Documentation: Show the result of a given function call: +%% recon_trace:calls({Mod,Fun,[{'_', [], [{return_trace}]}]}, Max, Opts), +%%--- +%% Test: Show the result of test_statem:get_state/0 calls (using match spec). +%% The recon_trace:calls calls back default implementation. +%%--- +%%====================================================================== +trace_return_matchspec_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + case test_statem:get_state() of + {ok,heavy_state,_} -> ok; + {ok,light_state,_} -> test_statem:switch_state() + end, + %% Trace the API function test_statem:get_state/1 using match spec + recon_trace:calls({test_statem, get_state, + [{'_', [], [{return_trace}]}]}, 10, [ {io_server, FH}, {use_dbg, true}, {scope,local}]), + + {ok,heavy_state, N} = test_statem:get_state(), + timer:sleep(100), + recon_trace:clear(), + {ok, TraceOutput} = file:read_file(FileName), + + %% Check for the call and its return value + assert_trace_match("test_statem:get_state/0 --> {ok,heavy_state,"++integer_to_list(N)++"}", TraceOutput), + ok. +%%====================================================================== +%% Documentation: A short-hand version for this pattern of 'match anything, trace everything' +%% for a function is recon_trace:calls({Mod, Fun, return_trace}). +%%--- +%% Test: Show the result of test_statem:get_state/0 calls (shorthand). +%%--- +%%====================================================================== +trace_return_shorthand_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + case test_statem:get_state() of + {ok,light_state,_} -> ok; + {ok,heavy_state,_} -> test_statem:switch_state() + end, + %% Trace the API function test_statem:get_state/1 using shorthand + recon_trace:calls({test_statem, get_state, return_trace}, 10, + [{io_server, FH}, {use_dbg, true}, {scope,local}]), + {ok,light_state, N} = test_statem:get_state(), + timer:sleep(100), + recon_trace:clear(), + + {ok, TraceOutput} = file:read_file(FileName), + + %% Check for the call and its return value + assert_trace_match("test_statem:get_state/0 --> {ok,light_state,"++integer_to_list(N)++"}", TraceOutput), + ok. + +%%====================================================================== +%% Documentation: The timestamp option adds a timestamp to the trace output. +%% recon_trace:calls({Mod, Fun, return_trace}, 10, [{timestamp, true}]). +%%--- +%% Test: Show the result of test_statem:get_state/0 calls, timestamp has different source +%% but same format. +%%--- +%%====================================================================== +trace_timestamp_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + case test_statem:get_state() of + {ok,light_state,_} -> ok; + {ok,heavy_state,_} -> test_statem:switch_state() + end, + %% Trace the API function test_statem:get_state/1 using shorthand + recon_trace:calls({test_statem, get_state, '_'}, 10, + [ {io_server, FH},{scope,local}, {timestamp, trace}, {use_dbg, true}]), + {ok,light_state, _} = test_statem:get_state(), + timer:sleep(100), + recon_trace:clear(), + + {ok, TraceOutput} = file:read_file(FileName), + + %% Check for the call and its return value + assert_trace_match("test_statem:get_state\\(", TraceOutput), + ok. + +%%====================================================================== +%% Documentation: The return_to option adds a traces for calls pointing where +%% local functions return result to. +%% recon_trace:calls({Mod, Fun, return_trace}, 10, [{return_to, true}]). +%%--- +%% Test: Show the result of test_statem:get_state/0 calls and the return to trace. +%%--- +%% Function: recon_trace:calls({test_statem, get_state, '_'}, 10). +%%====================================================================== +trace_return_to_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + case test_statem:get_state() of + {ok,light_state,_} -> ok; + {ok,heavy_state,_} -> test_statem:switch_state() + end, + %% Trace the API function test_statem:get_state/1 using shorthand + recon_trace:calls({test_statem, get_state, '_'}, 10, + [{use_dbg, true}, {io_server, FH},{scope,local}, {return_to, true}]), + {ok,light_state, _} = test_statem:get_state(), + timer:sleep(100), + recon_trace:clear(), + + {ok, TraceOutput} = file:read_file(FileName), + + %% Check for the call and its return value + assert_trace_match("test_statem:get_state\\(", TraceOutput), + assert_trace_match("--> "++atom_to_list(?MODULE)++":trace_return_to_test/1", TraceOutput), + ok. + +%%====================================================================== +%% Documentation: The return_to option adds a traces for calls, ensure it do not send +%% return to traces for not matching calls. +%% recon_trace:calls({Mod, Fun, return_trace}, 10, [{return_to, true}]). +%%--- +%% Test: Show no result of test_statem:get_state/0 calls and the return to trace. +%%--- +%%====================================================================== +trace_no_return_to_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + case test_statem:get_state() of + {ok,light_state,_} -> ok; + {ok,heavy_state,_} -> test_statem:switch_state() + end, + %% Trace the API function test_statem:get_state/1 using shorthand + recon_trace:calls({test_statem, not_get_state, '_'}, 10, + [{use_dbg, true}, {io_server, FH},{scope,local}, {return_to, true}]), + {ok,light_state, _} = test_statem:get_state(), + timer:sleep(100), + recon_trace:clear(), + + {ok, TraceOutput} = file:read_file(FileName), + + %% Check for the call and its return value + assert_trace_no_match("test_statem:get_state\\(", TraceOutput), + assert_trace_no_match("--> "++atom_to_list(?MODULE)++":trace_return_to_test/1", TraceOutput), + ok. +%%====================================================================== +%% Documentation: The clauses of the match spec can be used to suppress the trace output. +%%--- +%% Test: Show no result of calls that return suppress. +%%--- +%%====================================================================== +trace_suppress_print_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + MatchSpec = fun([enter_heavy_state,_]) -> suppress; + ([enter_light_state,_]) -> print end, + recon_trace:calls({test_statem, traced_function, MatchSpec}, 100, + [{io_server, FH}, {use_dbg, true}, {scope,local}]), + + timer:sleep(100), + ok = test_statem:switch_state(), + _ = test_statem:get_state(), + timer:sleep(100), + ok = test_statem:switch_state(), + timer:sleep(100), + + {ok, TraceOutput} = file:read_file(FileName), + %% there are race conditions when test ends, so + assert_trace_no_match("test_statem:traced_function\\(enter_heavy_state", TraceOutput), + assert_trace_match("test_statem:traced_function\\(enter_light_state", TraceOutput), + ok. + +%%====================================================================== +%% Documentation: The clauses of the match spec can be used to write custom value +%% the trace output. +%%--- +%% Test: Show custom value result of calls that return {print, custom_value}. +%%--- +%%====================================================================== +trace_custom_value_print_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + MatchSpec = fun([enter_heavy_state,_]) -> suppress; + ([enter_light_state,_]) -> + {print, {"printed", [custom_value]}} end, + recon_trace:calls({test_statem, traced_function, MatchSpec}, 100, + [{io_server, FH}, {use_dbg, true}, {scope,local}]), + + timer:sleep(100), + ok = test_statem:switch_state(), + _ = test_statem:get_state(), + timer:sleep(100), + ok = test_statem:switch_state(), + timer:sleep(100), + + {ok, TraceOutput} = file:read_file(FileName), + %% there are race conditions when test ends, so + assert_trace_no_match("test_statem:traced_function\\(enter_heavy_state", TraceOutput), + assert_trace_no_match("test_statem:traced_function\\(enter_light_state", TraceOutput), + assert_trace_match("{\"printed\",\\[custom_value\\]}", TraceOutput), + ok. + +%%====================================================================== +%% Documentation: Test matching binaries with a specific pattern. +%% +%% recon_trace:calls({erlang, iolist_to_binary, fun([X]) when is_binary(X) -> ok end}, 10) +%%--- +%% Test: Use dbg flag to pattern match parts of binaries. +%%--- +%% NOTE: Possible only with the use_dbg flag. +%%=========================================== + +trace_plugin_tracker_test(Config) -> + {FH, FileName} = proplists:get_value(file, Config), + + MatchSpec = {erlang, iolist_to_binary, + fun([ <<"request",A/binary>>], #{}) -> {print_session, #{session => A}} end}, + MatchSpec2 = {maps, to_list, + fun([#{response := A, value := V }], #{session := A}) -> {print_session, V, #{}} end}, + recon_trace:calls([MatchSpec, MatchSpec2], 10, + [{io_server, FH}, {use_dbg, true}, {scope, local}, {plugin, plugin_tracker}]), + + _ = erlang:iolist_to_binary(<<"request right">>), % Should trace + _ = erlang:iolist_to_binary(<<"already wrong">>), % Should NOT trace + _ = maps:to_list(#{ response => <<" wrong">>, value => bad }), % Should NOT trace + _ = maps:to_list(#{ response => <<" right">>, value => good }), % Should trace + timer:sleep(100), + {ok, TraceOutput} = file:read_file(FileName), + + recon_trace:clear(), + + assert_trace_match("erlang:iolist_to_binary\\(<<\"request right\">>\\)", TraceOutput), + assert_trace_no_match("wrong", TraceOutput), + assert_trace_match("good", TraceOutput), + ok. + diff --git a/test/test_statem.erl b/test/test_statem.erl new file mode 100644 index 0000000..caa7254 --- /dev/null +++ b/test/test_statem.erl @@ -0,0 +1,89 @@ +%%% @author +%%% [https://flmath.github.io] +%%% @doc +%%% Basic statem for testing purposes +%%% @end +%%%------------------------------------------------------------------- +-module(test_statem). +-behaviour(gen_statem). + +-include_lib("eunit/include/eunit.hrl"). + + +-define(HeavyStateWindowLength, 300). + +%% API +-export([start/0, stop/0]). +-export([get_state/0, switch_state/0]). +%% gen_statem callbacks +-export([init/1, callback_mode/0, light_state/3, heavy_state/3, + terminate/3, code_change/4]). +-define(NAME, ?MODULE). + +%%%=================================================================== +%%% API +%%%=================================================================== + +%%-------------------------------------------------------------------- +start() -> + gen_statem:start({local, ?NAME}, ?MODULE, [], []). + +switch_state()-> + gen_statem:cast(?NAME, switch_state). + +get_state()-> + gen_statem:call(?NAME, get_value). + +stop() -> + gen_statem:stop(?NAME). + +%%%=================================================================== +%%% gen_statem callbacks +%%%=================================================================== + +%%-------------------------------------------------------------------- +init([]) -> + ct:pal("Starting ~p~n", [?MODULE]), + {ok, light_state, #{iterator=>0}}. + +callback_mode() -> + state_functions. + +%%-------------------------------------------------------------------- +light_state(cast, switch_state, State) -> + #{iterator:=Number}=State, + traced_function(enter_heavy_state, Number), + {next_state, heavy_state, State#{iterator:=Number+1}, ?HeavyStateWindowLength}; +light_state({call, From}, get_value, State) -> + #{iterator:=Number} = State, + {next_state, light_state, State, [{reply, From, {ok, light_state, Number}}]}. + +heavy_state(cast, switch_state, State) -> + #{iterator:=Number} = State, + traced_function(enter_light_state, Number), + {next_state, light_state, State#{iterator:=Number+1}}; +heavy_state(timeout, _Event, State) -> + #{iterator:=Number} = State, + traced_function(keep_heavy_state, Number), + {next_state, heavy_state, State#{iterator:=Number+1}, ?HeavyStateWindowLength}; +heavy_state({call, From}, get_value, State) -> + #{iterator:=Number} = State, + {next_state, heavy_state, State, + [{reply, From, {ok, heavy_state, Number}}, + {timeout, ?HeavyStateWindowLength, back_to_heavy_state}]}. + + +%%-------------------------------------------------------------------- +terminate(Reason, _StateName, _State) -> + ct:pal("Terminate ~p ~p ~n", [?MODULE, Reason]), + ok. + +code_change(_OldVsn, StateName, State, _Extra) -> + {ok, StateName, State}. + +%%%=================================================================== +%%% Internal functions +%%%=================================================================== + +traced_function(_StateName, _Number)-> + ct:pal("log called from state ~p number ~p~n", [_StateName, _Number]). \ No newline at end of file