From 376da624578485aae6160d8ee327330d58613fae Mon Sep 17 00:00:00 2001 From: Peter Andersson Date: Sun, 1 Sep 2013 23:36:24 +0200 Subject: Find and fix minor bugs --- lib/common_test/src/ct_hooks.erl | 5 +- lib/common_test/src/ct_logs.erl | 2 +- lib/common_test/src/ct_util.erl | 30 +++- lib/common_test/src/cth_log_redirect.erl | 23 ++- lib/common_test/test/ct_pre_post_test_io_SUITE.erl | 158 +++++++++++++++++++-- .../ct_pre_post_test_io_SUITE_data/cth_ctrl.erl | 13 +- lib/common_test/test/ct_test_support.erl | 9 +- 7 files changed, 214 insertions(+), 26 deletions(-) (limited to 'lib/common_test') diff --git a/lib/common_test/src/ct_hooks.erl b/lib/common_test/src/ct_hooks.erl index b492663c57..e845e9e908 100644 --- a/lib/common_test/src/ct_hooks.erl +++ b/lib/common_test/src/ct_hooks.erl @@ -52,7 +52,6 @@ init(Opts) -> call(get_builtin_hooks(Opts) ++ get_new_hooks(Opts, undefined), ok, init, []). - %% @doc Called after all suites are done. -spec terminate(Hooks :: term()) -> @@ -276,8 +275,10 @@ get_new_hooks(Config, Fun) -> end, get_new_hooks(Config)). get_new_hooks(Config) when is_list(Config) -> - lists:flatmap(fun({?config_name, HookConfigs}) -> + lists:flatmap(fun({?config_name, HookConfigs}) when is_list(HookConfigs) -> HookConfigs; + ({?config_name, HookConfig}) when is_atom(HookConfig) -> + [HookConfig]; (_) -> [] end, Config); diff --git a/lib/common_test/src/ct_logs.erl b/lib/common_test/src/ct_logs.erl index 4cc1564570..1a6e4d31a8 100644 --- a/lib/common_test/src/ct_logs.erl +++ b/lib/common_test/src/ct_logs.erl @@ -524,7 +524,7 @@ int_footer() -> div_header(Class) -> div_header(Class,"User"). div_header(Class,Printer) -> - "
*** " ++ Printer ++ + "\n
*** " ++ Printer ++ " " ++ log_timestamp(now()) ++ " ***". div_footer() -> "
". diff --git a/lib/common_test/src/ct_util.erl b/lib/common_test/src/ct_util.erl index cbdf999cf8..bcc4caa62e 100644 --- a/lib/common_test/src/ct_util.erl +++ b/lib/common_test/src/ct_util.erl @@ -199,12 +199,26 @@ do_start(Parent, Mode, LogDir, Verbosity) -> ok -> Parent ! {self(),started}; {fail,CTHReason} -> - ct_logs:tc_print('Suite Callback',CTHReason,[]), + ErrorInfo = if is_atom(CTHReason) -> + io_lib:format("{~p,~p}", + [CTHReason, + erlang:get_stacktrace()]); + true -> + CTHReason + end, + ct_logs:tc_print('Suite Callback',ErrorInfo,[]), self() ! {{stop,{self(),{user_error,CTHReason}}}, {Parent,make_ref()}} catch _:CTHReason -> - ct_logs:tc_print('Suite Callback',CTHReason,[]), + ErrorInfo = if is_atom(CTHReason) -> + io_lib:format("{~p,~p}", + [CTHReason, + erlang:get_stacktrace()]); + true -> + CTHReason + end, + ct_logs:tc_print('Suite Callback',ErrorInfo,[]), self() ! {{stop,{self(),{user_error,CTHReason}}}, {Parent,make_ref()}} end, @@ -405,9 +419,15 @@ loop(Mode,TestData,StartDir) -> ct_event:sync_notify(#event{name=test_done, node=node(), data=Time}), - Callbacks = ets:lookup_element(?suite_table, - ct_hooks, - #suite_data.value), + Callbacks = + try ets:lookup_element(?suite_table, + ct_hooks, + #suite_data.value) of + CTHMods -> CTHMods + catch + %% this is because ct_util failed in init + error:badarg -> [] + end, ct_hooks:terminate(Callbacks), close_connections(ets:tab2list(?conn_table)), ets:delete(?conn_table), diff --git a/lib/common_test/src/cth_log_redirect.erl b/lib/common_test/src/cth_log_redirect.erl index a030701f19..11af1aa346 100644 --- a/lib/common_test/src/cth_log_redirect.erl +++ b/lib/common_test/src/cth_log_redirect.erl @@ -36,13 +36,17 @@ handle_event/2, handle_call/2, handle_info/2, terminate/1]). +%% Other +-export([handle_remote_events/1]). + -include("ct.hrl"). -record(eh_state, {log_func, curr_suite, curr_group, curr_func, - parallel_tcs = false}). + parallel_tcs = false, + handle_remote_events = false}). id(_Opts) -> ?MODULE. @@ -51,7 +55,6 @@ init(?MODULE, _Opts) -> error_logger:add_report_handler(?MODULE), tc_log_async. - pre_init_per_suite(Suite, Config, State) -> set_curr_func({Suite,init_per_suite}, Config), {Config, State}. @@ -104,7 +107,8 @@ post_end_per_group(_Group, Config, Return, State) -> init(_Type) -> {ok, #eh_state{log_func = tc_log_async}}. -handle_event({_Type, GL, _Msg}, State) when node(GL) /= node() -> +handle_event({_Type,GL,_Msg}, #eh_state{handle_remote_events = false} = State) + when node(GL) /= node() -> {ok, State}; handle_event(Event, #eh_state{log_func = LogFunc} = State) -> case lists:keyfind(sasl, 1, application:which_applications()) of @@ -160,9 +164,12 @@ handle_call({set_curr_func,undefined,_Config}, State) -> handle_call({set_curr_func,TC,_Config}, State) -> {ok, ok, State#eh_state{curr_func = TC}}; -handle_call({set_logfunc,NewLogFunc},State) -> +handle_call({set_logfunc,NewLogFunc}, State) -> {ok, NewLogFunc, State#eh_state{log_func = NewLogFunc}}; +handle_call({handle_remote_events,Bool}, State) -> + {ok, ok, State#eh_state{handle_remote_events = Bool}}; + handle_call(_Query, _State) -> {error, bad_query}. @@ -179,8 +186,16 @@ set_curr_func(CurrFunc, Config) -> set_log_func(Func) -> gen_event:call(error_logger, ?MODULE, {set_logfunc, Func}). +handle_remote_events(Bool) -> + gen_event:call(error_logger, ?MODULE, {handle_remote_events, Bool}). + %%%----------------------------------------------------------------- +format_header(#eh_state{curr_suite = undefined, + curr_group = undefined, + curr_func = undefined}) -> + io_lib:format("System report", []); + format_header(#eh_state{curr_suite = Suite, curr_group = undefined, curr_func = undefined}) -> diff --git a/lib/common_test/test/ct_pre_post_test_io_SUITE.erl b/lib/common_test/test/ct_pre_post_test_io_SUITE.erl index 8d94a60244..84341a0b99 100644 --- a/lib/common_test/test/ct_pre_post_test_io_SUITE.erl +++ b/lib/common_test/test/ct_pre_post_test_io_SUITE.erl @@ -48,7 +48,8 @@ init_per_suite(Config) -> CTH = filename:join(DataDir, "cth_ctrl.erl"), ct:pal("Compiling ~p: ~p", [CTH,compile:file(CTH,[{outdir,DataDir},debug_info])]), - ct_test_support:init_per_suite([{path_dirs,[DataDir]} | Config]). + ct_test_support:init_per_suite([{path_dirs,[DataDir]}, + {start_sasl,true} | Config]). end_per_suite(Config) -> ct_test_support:end_per_suite(Config). @@ -76,20 +77,117 @@ pre_post_io(Config) -> TC = pre_post_io, DataDir = ?config(data_dir, Config), Suite = filename:join(DataDir, "dummy_SUITE"), - {Opts,ERPid} = setup([{suite,Suite},{label,TC},{ct_hooks,cth_ctrl}], Config), + {Opts,ERPid} = setup([{suite,Suite},{label,TC},{ct_hooks,[cth_ctrl]}], + Config), + + %%!-------------------------------------------------------------------- + %%! Note that error reports will not start showing up in the pre-test + %%! io log until handle_remote_events has been set to true (see below). + %%! The reason is that the error logger has its group leader on the + %%! test_server node (not the ct node) and cth_log_redirect ignores + %%! events with remote destination until told otherwise. + %%!-------------------------------------------------------------------- + + spawn(fun() -> + %% --- test run 1 --- + ct:sleep(3000), + ct_test_support:ct_rpc({cth_log_redirect, + handle_remote_events, + [true]}, Config), + ct:sleep(2000), + io:format(user, "Starting test run!~n", []), + ct_test_support:ct_rpc({cth_ctrl,proceed,[]}, Config), + ct:sleep(6000), + io:format(user, "Finishing off!~n", []), + ct_test_support:ct_rpc({cth_ctrl,proceed,[]}, Config), + %% --- test run 2 --- + ct:sleep(3000), + ct_test_support:ct_rpc({cth_log_redirect, + handle_remote_events, + [true]}, Config), + ct:sleep(2000), + io:format(user, "Starting test run!~n", []), + ct_test_support:ct_rpc({cth_ctrl,proceed,[]}, Config), + ct:sleep(6000), + io:format(user, "Finishing off!~n", []), + ct_test_support:ct_rpc({cth_ctrl,proceed,[]}, Config) + end), ct_test_support:run(Opts, Config), - ct:sleep(2000), - ct_test_support:ct_rpc({cth_ctrl,proceed,[]}, Config), - ct:sleep(4000), - ct_test_support:ct_rpc({cth_ctrl,proceed,[]}, Config), - ct:sleep(2000), Events = ct_test_support:get_events(ERPid, Config), ct_test_support:log_events(TC, reformat(Events, ?eh), ?config(priv_dir, Config), Opts), TestEvents = events_to_check(TC), - ok = ct_test_support:verify_events(TestEvents, Events, Config). + ok = ct_test_support:verify_events(TestEvents, Events, Config), + + LogDirs = lists:flatmap(fun({_EH,#event{name=start_logging,data=Dir}}) -> + [Dir]; + (_) -> + [] + end, Events), + PrePostIoFiles = + [filename:join(LogDir, "misc_io.log.html") || LogDir <- LogDirs], + lists:foreach( + fun(PrePostIoFile) -> + ct:log("Reading Pre/Post Test IO Log file: ~ts", [PrePostIoFile]), + {ok,Bin} = file:read_file(PrePostIoFile), + Ts = string:tokens(binary_to_list(Bin),[$\n]), + PrePostIOEntries = + lists:foldl(fun([$L,$o,$g,$g,$e,$r|_], + {pre,PreLogN,PreErrN,0,0}) -> + {pre,PreLogN+1,PreErrN,0,0}; + ([$=,$E,$R,$R,$O,$R|_], + {pre,PreLogN,PreErrN,0,0}) -> + {pre,PreLogN,PreErrN+1,0,0}; + ([_,_,_,_,$P,$O,$S,$T,$-,$T,$E,$S,$T|_], + {pre,PreLogN,PreErrN,0,0}) -> + {post,PreLogN,PreErrN,0,0}; + ([$L,$o,$g,$g,$e,$r|_], + {post,PreLogN,PreErrN,PostLogN,PostErrN}) -> + {post,PreLogN,PreErrN,PostLogN+1,PostErrN}; + ([$=,$E,$R,$R,$O,$R|_], + {post,PreLogN,PreErrN,PostLogN,PostErrN}) -> + {post,PreLogN,PreErrN,PostLogN,PostErrN+1}; + (_, Counters) -> + Counters + end, {pre,0,0,0,0}, Ts), + [_|Counters] = tuple_to_list(PrePostIOEntries), + ct:log("Entries in the Pre/Post Test IO Log: ~p", [Counters]), + case [C || C <- Counters, C < 2] of + [] -> + ok; + _ -> + exit("Not enough entries in the Pre/Post Test IO Log!") + end + end, PrePostIoFiles), + + UnexpIoFiles = + [filelib:wildcard( + filename:join(LogDir, + "*dummy_SUITE.logs/run.*/" + "unexpected_io.log.html")) || LogDir <- LogDirs], + lists:foreach( + fun(UnexpIoFile) -> + ct:log("Reading Unexpected IO Log file: ~ts", [UnexpIoFile]), + {ok,Bin} = file:read_file(UnexpIoFile), + Ts = string:tokens(binary_to_list(Bin),[$\n]), + UnexpIOEntries = + lists:foldl(fun([$L,$o,$g,$g,$e,$r|_], [LogN,ErrN]) -> + [LogN+1,ErrN]; + ([$=,$E,$R,$R,$O,$R|_], [LogN,ErrN]) -> + [LogN,ErrN+1]; + (_, Counters) -> Counters + end, [0,0], Ts), + ct:log("Entries in the Unexpected IO Log: ~p", [UnexpIOEntries]), + case [N || N <- UnexpIOEntries, N < 2] of + [] -> + ok; + _ -> + exit("Not enough entries in the Unexpected IO Log!") + end + end, UnexpIoFiles), + ok. %%%----------------------------------------------------------------- %%% HELP FUNCTIONS @@ -110,5 +208,45 @@ reformat(Events, EH) -> %%% TEST EVENTS %%%----------------------------------------------------------------- -events_to_check(_Test) -> - []. +events_to_check(pre_post_io) -> + [ + {?eh,start_logging,{'DEF','RUNDIR'}}, + {?eh,test_start,{'DEF',{'START_TIME','LOGDIR'}}}, + {?eh,start_info,{1,1,7}}, + {?eh,tc_start,{dummy_SUITE,init_per_suite}}, + {?eh,tc_done,{dummy_SUITE,init_per_suite,ok}}, + {parallel, + [{?eh,tc_start,{dummy_SUITE,{init_per_group,g1,[parallel]}}}, + {?eh,tc_done, + {dummy_SUITE,{init_per_group,g1,[parallel]},ok}}, + {?eh,tc_start,{dummy_SUITE,tc1}}, + {?eh,tc_start,{dummy_SUITE,tc2}}, + {?eh,tc_start,{dummy_SUITE,tc3}}, + {?eh,tc_done,{dummy_SUITE,tc2,ok}}, + {?eh,tc_done,{dummy_SUITE,tc1,ok}}, + {?eh,tc_done,{dummy_SUITE,tc3,ok}}, + {?eh,test_stats,{1,0,{0,0}}}, + {?eh,test_stats,{2,0,{0,0}}}, + {?eh,test_stats,{3,0,{0,0}}}, + {?eh,tc_start,{dummy_SUITE,{end_per_group,g1,[parallel]}}}, + {?eh,tc_done,{dummy_SUITE,{end_per_group,g1,[parallel]},ok}}]}, + {?eh,tc_start,{dummy_SUITE,tc1}}, + {?eh,tc_done,{dummy_SUITE,tc1,ok}}, + {?eh,test_stats,{4,0,{0,0}}}, + {?eh,tc_start,{dummy_SUITE,tc2}}, + {?eh,tc_done,{dummy_SUITE,tc2,ok}}, + {?eh,test_stats,{5,0,{0,0}}}, + [{?eh,tc_start,{dummy_SUITE,{init_per_group,g2,[]}}}, + {?eh,tc_done,{dummy_SUITE,{init_per_group,g2,[]},ok}}, + {?eh,tc_start,{dummy_SUITE,tc4}}, + {?eh,tc_done,{dummy_SUITE,tc4,ok}}, + {?eh,test_stats,{6,0,{0,0}}}, + {?eh,tc_start,{dummy_SUITE,tc5}}, + {?eh,tc_done,{dummy_SUITE,tc5,ok}}, + {?eh,test_stats,{7,0,{0,0}}}, + {?eh,tc_start,{dummy_SUITE,{end_per_group,g2,[]}}}, + {?eh,tc_done,{dummy_SUITE,{end_per_group,g2,[]},ok}}], + {?eh,tc_start,{dummy_SUITE,end_per_suite}}, + {?eh,tc_done,{dummy_SUITE,end_per_suite,ok}}, + {?eh,test_done,{'DEF','STOP_TIME'}}, + {?eh,stop_logging,[]}]. diff --git a/lib/common_test/test/ct_pre_post_test_io_SUITE_data/cth_ctrl.erl b/lib/common_test/test/ct_pre_post_test_io_SUITE_data/cth_ctrl.erl index 89f1734491..a9ea7b14dd 100644 --- a/lib/common_test/test/ct_pre_post_test_io_SUITE_data/cth_ctrl.erl +++ b/lib/common_test/test/ct_pre_post_test_io_SUITE_data/cth_ctrl.erl @@ -32,12 +32,19 @@ proceed() -> %% Hook functions %%-------------------------------------------------------------------- init(_Id, _Opts) -> + case lists:keyfind(sasl, 1, application:which_applications()) of + false -> + exit(sasl_not_started); + _Else -> + ok + end, WhoAmI = self(), DispPid = spawn_link(fun() -> dispatcher(WhoAmI) end), register(?MODULE, DispPid), io:format(user, - "~n~n+++ Startup finished, call ~w:proceed() to run tests!~n~n", - [?MODULE]), + "~n~n+++ Startup of ~w on ~p finished, " + "call ~w:proceed() to run tests...~n", + [?MODULE,node(),?MODULE]), start_external_logger(cth_logger), receive {?MODULE,proceed} -> ok @@ -49,7 +56,7 @@ init(_Id, _Opts) -> terminate(_State) -> io:format(user, - "~n~n+++ Tests finished, call ~w:proceed() to shut down!~n~n", + "~n~n+++ Tests finished, call ~w:proceed() to shut down...~n", [?MODULE]), receive {?MODULE,proceed} -> ok diff --git a/lib/common_test/test/ct_test_support.erl b/lib/common_test/test/ct_test_support.erl index 5512b9c242..67e430f821 100644 --- a/lib/common_test/test/ct_test_support.erl +++ b/lib/common_test/test/ct_test_support.erl @@ -65,7 +65,6 @@ init_per_suite(Config, Level) -> _ -> ok end, - start_slave(Config, Level). start_slave(Config, Level) -> @@ -103,6 +102,14 @@ start_slave(NodeName, Config, Level) -> test_server:format(Level, "Dirs added to code path (on ~w):~n", [CTNode]), [io:format("~s~n", [D]) || D <- PathDirs], + + case proplists:get_value(start_sasl, Config) of + true -> + rpc:call(CTNode, application, start, [sasl]), + test_server:format(Level, "SASL started on ~w~n", [CTNode]); + _ -> + ok + end, TraceFile = filename:join(DataDir, "ct.trace"), case file:read_file_info(TraceFile) of -- cgit v1.2.3