diff options
Diffstat (limited to 'lib/common_test/src')
| -rw-r--r-- | lib/common_test/src/common_test.appup.src | 22 | ||||
| -rw-r--r-- | lib/common_test/src/ct_conn_log_h.erl | 105 | ||||
| -rw-r--r-- | lib/common_test/src/ct_framework.erl | 283 | ||||
| -rw-r--r-- | lib/common_test/src/ct_gen_conn.erl | 19 | ||||
| -rw-r--r-- | lib/common_test/src/ct_hooks.erl | 7 | ||||
| -rw-r--r-- | lib/common_test/src/ct_logs.erl | 90 | ||||
| -rw-r--r-- | lib/common_test/src/ct_netconfc.erl | 129 | ||||
| -rw-r--r-- | lib/common_test/src/ct_run.erl | 2 | ||||
| -rw-r--r-- | lib/common_test/src/ct_telnet.erl | 655 | ||||
| -rw-r--r-- | lib/common_test/src/ct_util.erl | 89 | ||||
| -rw-r--r-- | lib/common_test/src/ct_util.hrl | 8 | ||||
| -rw-r--r-- | lib/common_test/src/cth_conn_log.erl | 68 | ||||
| -rw-r--r-- | lib/common_test/src/cth_log_redirect.erl | 175 | ||||
| -rw-r--r-- | lib/common_test/src/cth_surefire.erl | 5 | ||||
| -rw-r--r-- | lib/common_test/src/unix_telnet.erl | 57 |
15 files changed, 1179 insertions, 535 deletions
diff --git a/lib/common_test/src/common_test.appup.src b/lib/common_test/src/common_test.appup.src index 0fbe5f23f7..4dfd9f1b0d 100644 --- a/lib/common_test/src/common_test.appup.src +++ b/lib/common_test/src/common_test.appup.src @@ -1 +1,21 @@ -{"%VSN%",[],[]}.
\ No newline at end of file +%% -*- erlang -*- +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2014. All Rights Reserved. +%% +%% The contents of this file are subject to the Erlang Public License, +%% Version 1.1, (the "License"); you may not use this file except in +%% compliance with the License. You should have received a copy of the +%% Erlang Public License along with this software. If not, it can be +%% retrieved online at http://www.erlang.org/. +%% +%% Software distributed under the License is distributed on an "AS IS" +%% basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See +%% the License for the specific language governing rights and limitations +%% under the License. +%% +%% %CopyrightEnd% +{"%VSN%", + [{<<".*">>,[{restart_application, common_test}]}], + [{<<".*">>,[{restart_application, common_test}]}] +}. diff --git a/lib/common_test/src/ct_conn_log_h.erl b/lib/common_test/src/ct_conn_log_h.erl index ac08a3e0ad..d733df27dc 100644 --- a/lib/common_test/src/ct_conn_log_h.erl +++ b/lib/common_test/src/ct_conn_log_h.erl @@ -30,80 +30,88 @@ handle_event/2, handle_call/2, handle_info/2, terminate/2]). --record(state, {group_leader,logs=[]}). +-record(state, {logs=[], default_gl}). -define(WIDTH,80). %%%----------------------------------------------------------------- %%% Callbacks -init({GL,Logs}) -> - open_files(Logs,#state{group_leader=GL}). +init({GL,ConnLogs}) -> + open_files(GL,ConnLogs,#state{default_gl=GL}). -open_files([{ConnMod,{LogType,Logs}}|T],State) -> - case do_open_files(Logs,[]) of +open_files(GL,[{ConnMod,{LogType,LogFiles}}|T],State=#state{logs=Logs}) -> + case do_open_files(LogFiles,[]) of {ok,Fds} -> - open_files(T,State#state{logs=[{ConnMod,{LogType,Fds}} | - State#state.logs]}); + ConnInfo = proplists:get_value(GL,Logs,[]), + Logs1 = [{GL,[{ConnMod,{LogType,Fds}}|ConnInfo]} | + proplists:delete(GL,Logs)], + open_files(GL,T,State#state{logs=Logs1}); Error -> Error end; -open_files([],State) -> +open_files(_GL,[],State) -> {ok,State}. - -do_open_files([{Tag,File}|Logs],Acc) -> - case file:open(File, [write,{encoding,utf8}]) of +do_open_files([{Tag,File}|LogFiles],Acc) -> + case file:open(File, [write,append,{encoding,utf8}]) of {ok,Fd} -> - do_open_files(Logs,[{Tag,Fd}|Acc]); + do_open_files(LogFiles,[{Tag,Fd}|Acc]); {error,Reason} -> {error,{could_not_open_log,File,Reason}} end; do_open_files([],Acc) -> {ok,lists:reverse(Acc)}. +handle_event({info_report,_,{From,update,{GL,ConnLogs}}}, + State) when node(GL) == node() -> + Result = open_files(GL,ConnLogs,State), + From ! {updated,GL}, + Result; handle_event({_Type, GL, _Msg}, State) when node(GL) /= node() -> {ok, State}; -handle_event({_Type,_GL,{Pid,{ct_connection,Action,ConnName},Report}},State) -> - %% NOTE: if the format of this event is changed - %% ({ct_connection,Action,ConnName}) then remember to change - %% test_server_h:report_receiver as well!!! - Info = conn_info(Pid,#conn_log{name=ConnName,action=Action}), - write_report(now(),Info,Report,State), +handle_event({_Type,GL,{Pid,{ct_connection,Mod,Action,ConnName},Report}}, + State) -> + Info = conn_info(Pid,#conn_log{name=ConnName,action=Action,module=Mod}), + write_report(now(),Info,Report,GL,State), {ok, State}; -handle_event({_Type,_GL,{Pid,Info=#conn_log{},Report}},State) -> - %% NOTE: if the format of this event is changed - %% (Info=#conn_log{}) then remember to change - %% test_server_h:report_receiver as well!!! - write_report(now(),conn_info(Pid,Info),Report,State), +handle_event({_Type,GL,{Pid,Info=#conn_log{},Report}}, State) -> + write_report(now(),conn_info(Pid,Info),Report,GL,State), {ok, State}; -handle_event({error_report,_,{Pid,_,[{ct_connection,ConnName}|R]}},State) -> +handle_event({error_report,GL,{Pid,_,[{ct_connection,ConnName}|R]}}, State) -> %% Error reports from connection - write_error(now(),conn_info(Pid,#conn_log{name=ConnName}),R,State), + write_error(now(),conn_info(Pid,#conn_log{name=ConnName}),R,GL,State), {ok, State}; -handle_event(_, State) -> +handle_event(_What, State) -> {ok, State}. -handle_info(_, State) -> +handle_info(_What, State) -> {ok, State}. handle_call(_Query, State) -> {ok, {error, bad_query}, State}. terminate(_,#state{logs=Logs}) -> - [file:close(Fd) || {_,{_,Fds}} <- Logs, {_,Fd} <- Fds], + lists:foreach( + fun({_GL,ConnLogs}) -> + [file:close(Fd) || {_,{_,Fds}} <- ConnLogs, {_,Fd} <- Fds] + end, Logs), ok. %%%----------------------------------------------------------------- %%% Writing reports -write_report(Time,#conn_log{module=ConnMod}=Info,Data,State) -> - {LogType,Fd} = get_log(Info,State), +write_report(_Time,#conn_log{header=false,module=ConnMod}=Info,Data,GL,State) -> + {LogType,Fd} = get_log(Info,GL,State), + io:format(Fd,"~n~ts",[format_data(ConnMod,LogType,Data)]); + +write_report(Time,#conn_log{module=ConnMod}=Info,Data,GL,State) -> + {LogType,Fd} = get_log(Info,GL,State), io:format(Fd,"~n~ts~ts~ts",[format_head(ConnMod,LogType,Time), format_title(LogType,Info), format_data(ConnMod,LogType,Data)]). -write_error(Time,#conn_log{module=ConnMod}=Info,Report,State) -> - case get_log(Info,State) of +write_error(Time,#conn_log{module=ConnMod}=Info,Report,GL,State) -> + case get_log(Info,GL,State) of {html,_} -> %% The error will anyway be written in the html log by the %% sasl error handler, so don't write it again. @@ -115,14 +123,19 @@ write_error(Time,#conn_log{module=ConnMod}=Info,Report,State) -> format_error(LogType,Report)]) end. -get_log(Info,State) -> - case proplists:get_value(Info#conn_log.module,State#state.logs) of - {html,_} -> - {html,State#state.group_leader}; - {LogType,Fds} -> - {LogType,get_fd(Info,Fds)}; +get_log(Info,GL,State) -> + case proplists:get_value(GL,State#state.logs) of undefined -> - {html,State#state.group_leader} + {html,State#state.default_gl}; + ConnLogs -> + case proplists:get_value(Info#conn_log.module,ConnLogs) of + {html,_} -> + {html,GL}; + {LogType,Fds} -> + {LogType,get_fd(Info,Fds)}; + undefined -> + {html,GL} + end end. get_fd(#conn_log{name=undefined},Fds) -> @@ -191,17 +204,27 @@ pretty_head({{{Y,Mo,D},{H,Mi,S}},MicroS},ConnMod,Text0) -> micro2milli(MicroS)]). pretty_title(#conn_log{client=Client}=Info) -> - io_lib:format("= Client ~w ~s Server ~ts ", - [Client,actionstr(Info),serverstr(Info)]). + case actionstr(Info) of + {no_server,Action} -> + io_lib:format("= Client ~w ~s ",[Client,Action]); + Action -> + io_lib:format("= Client ~w ~s ~ts ",[Client,Action, + serverstr(Info)]) + end. actionstr(#conn_log{action=send}) -> "----->"; +actionstr(#conn_log{action=cmd}) -> "----->"; actionstr(#conn_log{action=recv}) -> "<-----"; actionstr(#conn_log{action=open}) -> "opened session to"; actionstr(#conn_log{action=close}) -> "closed session to"; actionstr(_) -> "<---->". +serverstr(#conn_log{name=undefined,address={undefined,_}}) -> + io_lib:format("server",[]); serverstr(#conn_log{name=undefined,address=Address}) -> io_lib:format("~p",[Address]); +serverstr(#conn_log{name=Alias,address={undefined,_}}) -> + io_lib:format("~w",[Alias]); serverstr(#conn_log{name=Alias,address=Address}) -> io_lib:format("~w(~p)",[Alias,Address]). diff --git a/lib/common_test/src/ct_framework.erl b/lib/common_test/src/ct_framework.erl index 276f902b05..580588fbd2 100644 --- a/lib/common_test/src/ct_framework.erl +++ b/lib/common_test/src/ct_framework.erl @@ -69,13 +69,13 @@ init_tc(Mod,Func,Config) -> andalso Func=/=end_per_group andalso ct_util:get_testdata(skip_rest) of true -> - {skip,"Repeated test stopped by force_stop option"}; + {auto_skip,"Repeated test stopped by force_stop option"}; _ -> case ct_util:get_testdata(curr_tc) of {Suite,{suite0_failed,{require,Reason}}} -> - {skip,{require_failed_in_suite0,Reason}}; + {auto_skip,{require_failed_in_suite0,Reason}}; {Suite,{suite0_failed,_}=Failure} -> - {skip,Failure}; + {fail,Failure}; _ -> ct_util:update_testdata(curr_tc, fun(undefined) -> @@ -103,7 +103,7 @@ init_tc(Mod,Func,Config) -> end, init_tc1(Mod,Suite,Func,Config); {failed,Seq,BadFunc} -> - {skip,{sequence_failed,Seq,BadFunc}} + {auto_skip,{sequence_failed,Seq,BadFunc}} end end end. @@ -115,9 +115,9 @@ init_tc1(?MODULE,_,error_in_suite,[Config0]) when is_list(Config0) -> data={?MODULE,error_in_suite}}), case ?val(error, Config0) of undefined -> - {skip,"unknown_error_in_suite"}; + {fail,"unknown_error_in_suite"}; Reason -> - {skip,Reason} + {fail,Reason} end; init_tc1(Mod,Suite,Func,[Config0]) when is_list(Config0) -> @@ -159,22 +159,28 @@ init_tc1(Mod,Suite,Func,[Config0]) when is_list(Config0) -> true -> ct_config:delete_default_config(testcase) end, + Initialize = fun() -> + ct_logs:init_tc(false), + ct_event:notify(#event{name=tc_start, + node=node(), + data={Mod,FuncSpec}}) + end, case add_defaults(Mod,Func,AllGroups) of Error = {suite0_failed,_} -> - ct_logs:init_tc(false), - ct_event:notify(#event{name=tc_start, - node=node(), - data={Mod,FuncSpec}}), + Initialize(), ct_util:set_testdata({curr_tc,{Suite,Error}}), {error,Error}; + Error = {group0_failed,_} -> + Initialize(), + {auto_skip,Error}; + Error = {testcase0_failed,_} -> + Initialize(), + {auto_skip,Error}; {SuiteInfo,MergeResult} -> case MergeResult of {error,Reason} -> - ct_logs:init_tc(false), - ct_event:notify(#event{name=tc_start, - node=node(), - data={Mod,FuncSpec}}), - {skip,Reason}; + Initialize(), + {fail,Reason}; _ -> init_tc2(Mod,Suite,Func,SuiteInfo,MergeResult,Config) end @@ -222,11 +228,11 @@ init_tc2(Mod,Suite,Func,SuiteInfo,MergeResult,Config) -> {suite0_failed,Reason} -> ct_util:set_testdata({curr_tc,{Mod,{suite0_failed, {require,Reason}}}}), - {skip,{require_failed_in_suite0,Reason}}; + {auto_skip,{require_failed_in_suite0,Reason}}; {error,Reason} -> {auto_skip,{require_failed,Reason}}; {'EXIT',Reason} -> - {auto_skip,Reason}; + {fail,Reason}; {ok,PostInitHook,Config1} -> case get('$test_server_framework_test') of undefined -> @@ -272,6 +278,8 @@ add_defaults(Mod,Func, GroupPath) -> SuiteInfo = merge_with_suite_defaults(Suite,[]), SuiteInfoNoCTH = [I || I <- SuiteInfo, element(1,I) =/= ct_hooks], case add_defaults1(Mod,Func, GroupPath, SuiteInfoNoCTH) of + Error = {group0_failed,_} -> Error; + Error = {testcase0_failed,_} -> Error; Error = {error,_} -> {SuiteInfo,Error}; MergedInfo -> {SuiteInfo,MergedInfo} end; @@ -292,13 +300,16 @@ add_defaults(Mod,Func, GroupPath) -> element(1,I) =/= ct_hooks], case add_defaults1(Mod,Func, GroupPath, SuiteInfoNoCTH) of + Error = {group0_failed,_} -> Error; + Error = {testcase0_failed,_} -> Error; Error = {error,_} -> {SuiteInfo1,Error}; MergedInfo -> {SuiteInfo1,MergedInfo} end; false -> ErrStr = io_lib:format("~n*** ERROR *** " "Invalid return value from " - "~w:suite/0: ~p~n", [Suite,SuiteInfo]), + "~w:suite/0: ~p~n", + [Suite,SuiteInfo]), io:format(ErrStr, []), io:format(user, ErrStr, []), {suite0_failed,bad_return_value} @@ -318,36 +329,69 @@ add_defaults1(Mod,Func, GroupPath, SuiteInfo) -> %% [LevelXGroupInfo, LevelX-1GroupInfo, ..., TopLevelGroupInfo] GroupPathInfo = lists:map(fun(GroupProps) -> - Name = ?val(name, GroupProps), - case catch Suite:group(Name) of - GrInfo when is_list(GrInfo) -> GrInfo; - _ -> [] + case ?val(name, GroupProps) of + undefined -> + []; + Name -> + case catch Suite:group(Name) of + GrInfo when is_list(GrInfo) -> GrInfo; + {'EXIT',{undef,_}} -> []; + BadGr0 -> {error,BadGr0,Name} + end end end, GroupPath), - Args = if Func == init_per_group ; Func == end_per_group -> - [?val(name, hd(GroupPath))]; - true -> - [] - end, - TestCaseInfo = - case catch apply(Mod,Func,Args) of - TCInfo when is_list(TCInfo) -> TCInfo; - _ -> [] - end, - %% let test case info (also for all config funcs) override group info, - %% and lower level group info override higher level info - TCAndGroupInfo = [TestCaseInfo | remove_info_in_prev(TestCaseInfo, - GroupPathInfo)], - %% find and save require terms found in suite info - SuiteReqs = - [SDDef || SDDef <- SuiteInfo, - ((require == element(1,SDDef)) or - (default_config == element(1,SDDef)))], - case check_for_clashes(TestCaseInfo, GroupPathInfo, SuiteReqs) of - [] -> - add_defaults2(Mod,Func, TCAndGroupInfo,SuiteInfo,SuiteReqs); - Clashes -> - {error,{config_name_already_in_use,Clashes}} + case lists:keysearch(error, 1, GroupPathInfo) of + {value,{error,BadGr0Val,GrName}} -> + Gr0ErrStr = io_lib:format("~n*** ERROR *** " + "Invalid return value from " + "~w:group(~w): ~p~n", + [Mod,GrName,BadGr0Val]), + io:format(Gr0ErrStr, []), + io:format(user, Gr0ErrStr, []), + {group0_failed,bad_return_value}; + _ -> + Args = if Func == init_per_group ; Func == end_per_group -> + [?val(name, hd(GroupPath))]; + true -> + [] + end, + TestCaseInfo = + case catch apply(Mod,Func,Args) of + TCInfo when is_list(TCInfo) -> TCInfo; + {'EXIT',{undef,_}} -> []; + BadTC0 -> {error,BadTC0} + end, + + case TestCaseInfo of + {error,BadTC0Val} -> + TC0ErrStr = io_lib:format("~n*** ERROR *** " + "Invalid return value from " + "~w:~w/0: ~p~n", + [Mod,Func,BadTC0Val]), + io:format(TC0ErrStr, []), + io:format(user, TC0ErrStr, []), + {testcase0_failed,bad_return_value}; + _ -> + %% let test case info (also for all config funcs) override + %% group info, and lower level group info override higher + %% level info + TCAndGroupInfo = + [TestCaseInfo | remove_info_in_prev(TestCaseInfo, + GroupPathInfo)], + %% find and save require terms found in suite info + SuiteReqs = + [SDDef || SDDef <- SuiteInfo, + ((require == element(1,SDDef)) + or (default_config == element(1,SDDef)))], + case check_for_clashes(TestCaseInfo, GroupPathInfo, + SuiteReqs) of + [] -> + add_defaults2(Mod,Func, TCAndGroupInfo, + SuiteInfo,SuiteReqs); + Clashes -> + {error,{config_name_already_in_use,Clashes}} + end + end end. get_suite_name(?MODULE, [Cfg|_]) when is_list(Cfg), Cfg /= [] -> @@ -621,31 +665,34 @@ end_tc(Mod,Func,TCPid,Result,Args,Return) -> _ -> Func end, - case get('$test_server_framework_test') of - undefined -> - {FinalResult,FinalNotify} = - case ct_hooks:end_tc( - Suite, FuncSpec, Args, Result, Return) of - '$ct_no_change' -> - {ok,Result}; - FinalResult1 -> - {FinalResult1,FinalResult1} - end, - %% send sync notification so that event handlers may print - %% in the log file before it gets closed - ct_event:sync_notify(#event{name=tc_done, - node=node(), - data={Mod,FuncSpec, - tag_cth(FinalNotify)}}); - Fun -> - %% send sync notification so that event handlers may print - %% in the log file before it gets closed - ct_event:sync_notify(#event{name=tc_done, - node=node(), - data={Mod,FuncSpec,tag(Result)}}), - FinalResult = Fun(end_tc, Return) - end, - + {Result1,FinalNotify} = + case ct_hooks:end_tc( + Suite, FuncSpec, Args, Result, Return) of + '$ct_no_change' -> + {ok,Result}; + HookResult -> + {HookResult,HookResult} + end, + FinalResult = + case get('$test_server_framework_test') of + undefined -> + %% send sync notification so that event handlers may print + %% in the log file before it gets closed + ct_event:sync_notify(#event{name=tc_done, + node=node(), + data={Mod,FuncSpec, + tag_cth(FinalNotify)}}), + Result1; + Fun -> + %% send sync notification so that event handlers may print + %% in the log file before it gets closed + ct_event:sync_notify(#event{name=tc_done, + node=node(), + data={Mod,FuncSpec, + tag(FinalNotify)}}), + Fun(end_tc, Return) + end, + case FuncSpec of {_,GroupName,_Props} -> if Func == end_per_group -> @@ -683,12 +730,17 @@ end_tc(Mod,Func,TCPid,Result,Args,Return) -> (undefined) -> undefined; (Unexpected) -> - exit({error,{reset_curr_tc,{Mod,Func},Unexpected}}) + {error,{reset_curr_tc,{Mod,Func},Unexpected}} end, - ct_util:update_testdata(curr_tc,ClearCurrTC), + case ct_util:update_testdata(curr_tc, ClearCurrTC) of + {error,_} = ClearError -> + exit(ClearError); + _ -> + ok + end, case FinalResult of - {skip,{sequence_failed,_,_}} -> + {auto_skip,{sequence_failed,_,_}} -> %% ct_logs:init_tc is never called for a skipped test case %% in a failing sequence, so neither should end_tc ok; @@ -711,8 +763,13 @@ end_tc(Mod,Func,TCPid,Result,Args,Return) -> %% {error,Reason} | {skip,Reason} | {timetrap_timeout,TVal} | %% {testcase_aborted,Reason} | testcase_aborted_or_killed | %% {'EXIT',Reason} | Other (ignored return value, e.g. 'ok') -tag({STag,Reason}) when STag == skip; STag == skipped -> - {skipped,Reason}; +tag({STag,Reason}) when STag == skip; STag == skipped -> + case Reason of + {failed,{_,init_per_testcase,_}} -> {auto_skipped,Reason}; + _ -> {skipped,Reason} + end; +tag({auto_skip,Reason}) -> + {auto_skipped,Reason}; tag(E = {ETag,_}) when ETag == error; ETag == 'EXIT'; ETag == timetrap_timeout; ETag == testcase_aborted -> @@ -722,13 +779,20 @@ tag(E = testcase_aborted_or_killed) -> tag(Other) -> Other. +tag_cth({skipped,Reason={failed,{_,init_per_testcase,_}}}) -> + {auto_skipped,Reason}; tag_cth({STag,Reason}) when STag == skip; STag == skipped -> - {skipped,Reason}; -tag_cth({fail, Reason}) -> - {failed, {error,Reason}}; + case Reason of + {failed,{_,init_per_testcase,_}} -> {auto_skipped,Reason}; + _ -> {skipped,Reason} + end; +tag_cth({auto_skip,Reason}) -> + {auto_skipped,Reason}; +tag_cth({fail,Reason}) -> + {failed,{error,Reason}}; tag_cth(E = {ETag,_}) when ETag == error; ETag == 'EXIT'; - ETag == timetrap_timeout; - ETag == testcase_aborted -> + ETag == timetrap_timeout; + ETag == testcase_aborted -> {failed,E}; tag_cth(E = testcase_aborted_or_killed) -> {failed,E}; @@ -1229,6 +1293,8 @@ report(What,Data) -> ct_hooks:on_tc_skip(tc_auto_skip, Data); {skipped,_} -> ct_hooks:on_tc_skip(tc_user_skip, Data); + {auto_skipped,_} -> + ct_hooks:on_tc_skip(tc_auto_skip, Data); _Else -> ok end, @@ -1253,31 +1319,54 @@ report(What,Data) -> add_to_stats(auto_skipped); {_,{skipped,_}} -> add_to_stats(user_skipped); + {_,{auto_skipped,_}} -> + add_to_stats(auto_skipped); {_,{SkipOrFail,_Reason}} -> add_to_stats(SkipOrFail) end; - tc_user_skip -> - %% test case specified as skipped in testspec - %% Data = {Suite,Case,Comment} + tc_user_skip -> + %% test case or config function specified as skipped in testspec, + %% or init config func for suite/group has returned {skip,Reason} + %% Data = {Suite,Case,Comment} | + %% {Suite,{GroupConfigFunc,GroupName},Comment} + {Func,Data1} = case Data of + {Suite,{ConfigFunc,undefined},Cmt} -> + {ConfigFunc,{Suite,ConfigFunc,Cmt}}; + {_,{ConfigFunc,_},_} -> {ConfigFunc,Data}; + {_,Case,_} -> {Case,Data} + end, + ct_event:sync_notify(#event{name=tc_user_skip, node=node(), - data=Data}), - ct_hooks:on_tc_skip(What, Data), - add_to_stats(user_skipped); - tc_auto_skip -> - %% test case skipped because of error in init_per_suite - %% Data = {Suite,Case,Comment} - - {_Suite,Case,_Result} = Data, + data=Data1}), + ct_hooks:on_tc_skip(What, Data1), + if Func /= init_per_suite, Func /= init_per_group, + Func /= end_per_suite, Func /= end_per_group -> + add_to_stats(user_skipped); + true -> + ok + end; + tc_auto_skip -> + %% test case skipped because of error in config function, or + %% config function skipped because of error in info function + %% Data = {Suite,Case,Comment} | + %% {Suite,{GroupConfigFunc,GroupName},Comment} + {Func,Data1} = case Data of + {Suite,{ConfigFunc,undefined},Cmt} -> + {ConfigFunc,{Suite,ConfigFunc,Cmt}}; + {_,{ConfigFunc,_},_} -> {ConfigFunc,Data}; + {_,Case,_} -> {Case,Data} + end, %% this test case does not have a log, so printouts %% from event handlers should end up in the main log ct_event:sync_notify(#event{name=tc_auto_skip, node=node(), - data=Data}), - ct_hooks:on_tc_skip(What, Data), - if Case /= end_per_suite, - Case /= end_per_group -> + data=Data1}), + ct_hooks:on_tc_skip(What, Data1), + + if Func /= end_per_suite, + Func /= end_per_group -> add_to_stats(auto_skipped); true -> ok @@ -1328,7 +1417,7 @@ warn(_What) -> true. %%%----------------------------------------------------------------- -%%% @spec add_data_dir(File0) -> File1 +%%% @spec add_data_dir(File0, Config) -> File1 add_data_dir(File,Config) when is_atom(File) -> add_data_dir(atom_to_list(File),Config); diff --git a/lib/common_test/src/ct_gen_conn.erl b/lib/common_test/src/ct_gen_conn.erl index a5b736136f..078d6b1a44 100644 --- a/lib/common_test/src/ct_gen_conn.erl +++ b/lib/common_test/src/ct_gen_conn.erl @@ -29,6 +29,13 @@ -export([start/4, stop/1, get_conn_pid/1]). -export([call/2, call/3, return/2, do_within_time/2]). +%%---------------------------------------------------------------------- +%% Exported types +%%---------------------------------------------------------------------- +-export_type([server_id/0, + target_name/0, + key_or_name/0]). + -ifdef(debug). -define(dbg,true). -else. @@ -47,6 +54,18 @@ cb_state, ct_util_server}). +%%------------------------------------------------------------------ +%% Type declarations +%%------------------------------------------------------------------ +-type server_id() :: atom(). +%% A `ServerId' which exists in a configuration file. +-type target_name() :: atom(). +%% A name which is associated to a `server_id()' via a +%% `require' statement or a call to {@link ct:require/2} in the +%% test suite. +-type key_or_name() :: server_id() | target_name(). + + %%%----------------------------------------------------------------- %%% @spec start(Address,InitData,CallbackMod,Opts) -> %%% {ok,Handle} | {error,Reason} diff --git a/lib/common_test/src/ct_hooks.erl b/lib/common_test/src/ct_hooks.erl index 3d87a82e24..e845e9e908 100644 --- a/lib/common_test/src/ct_hooks.erl +++ b/lib/common_test/src/ct_hooks.erl @@ -50,9 +50,8 @@ -spec init(State :: term()) -> ok | {fail, Reason :: term()}. init(Opts) -> - call(get_new_hooks(Opts, undefined) ++ get_builtin_hooks(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 f5355bfefe..a4ad65c0a4 100644 --- a/lib/common_test/src/ct_logs.erl +++ b/lib/common_test/src/ct_logs.erl @@ -61,6 +61,7 @@ -define(index_name, "index.html"). -define(totals_name, "totals.info"). -define(log_cache_name, "ct_log_cache"). +-define(misc_io_log, "misc_io.log.html"). -define(table_color1,"#ADD8E6"). -define(table_color2,"#E4F0FE"). @@ -75,7 +76,7 @@ tests = []}). %%%----------------------------------------------------------------- -%%% @spec init(Mode) -> Result +%%% @spec init(Mode, Verbosity) -> Result %%% Mode = normal | interactive %%% Result = {StartTime,LogDir} %%% StartTime = term() @@ -446,6 +447,8 @@ tc_print(Category,Importance,Format,Args) -> ct_util:get_verbosity('$unspecified'); {error,bad_invocation} -> ?MAX_VERBOSITY; + {error,_Failure} -> + ?MAX_VERBOSITY; Val -> Val end, @@ -521,7 +524,7 @@ int_footer() -> div_header(Class) -> div_header(Class,"User"). div_header(Class,Printer) -> - "<div class=\"" ++ atom_to_list(Class) ++ "\"><b>*** " ++ Printer ++ + "\n<div class=\"" ++ atom_to_list(Class) ++ "\"><b>*** " ++ Printer ++ " " ++ log_timestamp(now()) ++ " ***</b>". div_footer() -> "</div>". @@ -615,6 +618,34 @@ logger(Parent, Mode, Verbosity) -> end end end, + + test_server_io:start_link(), + MiscIoName = filename:join(Dir, ?misc_io_log), + {ok,MiscIoFd} = file:open(MiscIoName, + [write,{encoding,utf8}]), + test_server_io:set_fd(unexpected_io, MiscIoFd), + + {MiscIoHeader,MiscIoFooter} = + case get_ts_html_wrapper("Pre/post-test I/O log", Dir, false, + Dir, undefined, utf8) of + {basic_html,UH,UF} -> + {UH,UF}; + {xhtml,UH,UF} -> + {UH,UF} + end, + io:put_chars(MiscIoFd, + [MiscIoHeader, + "<a name=\"pretest\"></a>\n", + xhtml("<br>\n<h2>Pre-test Log</h2>", + "<br />\n<h3>PRE-TEST LOG</h3>"), + "\n<pre>\n"]), + MiscIoDivider = + "\n<a name=\"posttest\"></a>\n"++ + xhtml("</pre>\n<br><h2>Post-test Log</h2>\n<pre>\n", + "</pre>\n<br />\n<h3>POST-TEST LOG</h3>\n<pre>\n"), + ct_util:set_testdata_async({misc_io_log,{filename:absname(MiscIoName), + MiscIoDivider,MiscIoFooter}}), + ct_event:notify(#event{name=start_logging,node=node(), data=AbsDir}), make_all_runs_index(start), @@ -625,7 +656,7 @@ logger(Parent, Mode, Verbosity) -> end, file:set_cwd(Dir), make_last_run_index(Time), - CtLogFd = open_ctlog(), + CtLogFd = open_ctlog(?misc_io_log), io:format(CtLogFd,int_header()++int_footer(), [log_timestamp(now()),"Common Test Logger started"]), Parent ! {started,self(),{Time,filename:absname("")}}, @@ -690,14 +721,15 @@ logger_loop(State) -> false -> %% Group leader is dead, so write to the %% CtLog or unexpected_io log instead - unexpected_io(Pid,Category,List,State), + unexpected_io(Pid,Category,Importance, + List,State), logger_loop(State) end; {ct_log,_Fd,TCGLs} -> %% If category is ct_internal then write %% to ct_log, else write to unexpected_io %% log - unexpected_io(Pid,Category,List,State), + unexpected_io(Pid,Category,Importance,List,State), logger_loop(State#logger_state{ tc_groupleaders = TCGLs}) end; @@ -798,7 +830,7 @@ print_to_log(sync, FromPid, Category, TCGL, List, State) -> IoFun = create_io_fun(FromPid, State), io:format(TCGL,"~ts", [lists:foldl(IoFun, [], List)]); true -> - unexpected_io(FromPid,Category,List,State) + unexpected_io(FromPid,Category,?MAX_IMPORTANCE,List,State) end, State; @@ -814,7 +846,8 @@ print_to_log(async, FromPid, Category, TCGL, List, State) -> end; true -> fun() -> - unexpected_io(FromPid,Category,List,State) + unexpected_io(FromPid,Category,?MAX_IMPORTANCE, + List,State) end end, case State#logger_state.async_print_jobs of @@ -918,7 +951,7 @@ set_evmgr_gl(GL) -> EvMgrPid -> group_leader(GL,EvMgrPid) end. -open_ctlog() -> +open_ctlog(MiscIoName) -> {ok,Fd} = file:open(?ct_log_name,[write,{encoding,utf8}]), io:format(Fd, header("Common Test Framework Log", {[],[1,2],[]}), []), case file:consult(ct_run:variables_file_name("../")) of @@ -933,10 +966,21 @@ open_ctlog() -> "No configuration found for test!!\n", [Variables,Reason]) end, + io:format(Fd, + xhtml("<br><br><h2>Pre/post-test I/O Log</h2>\n", + "<br /><br />\n<h4>PRE/POST TEST I/O LOG</h4>\n"), []), + io:format(Fd, + "\n<ul>\n" + "<li><a href=\"~ts#pretest\">" + "View I/O logged before the test run</a></li>\n" + "<li><a href=\"~ts#posttest\">" + "View I/O logged after the test run</a></li>\n</ul>\n", + [MiscIoName,MiscIoName]), + print_style(Fd,undefined), io:format(Fd, - xhtml("<br><br><h2>Progress Log</h2>\n<pre>\n", - "<br /><br /><h4>PROGRESS LOG</h4>\n<pre>\n"), []), + xhtml("<br><h2>Progress Log</h2>\n<pre>\n", + "<br />\n<h4>PROGRESS LOG</h4>\n<pre>\n"), []), Fd. print_style(Fd,undefined) -> @@ -1205,7 +1249,8 @@ make_one_index_entry1(SuiteName, Link, Label, Success, Fail, UserSkip, AutoSkip, integer_to_list(NotBuilt),"</a></td>\n"] end, FailStr = - if Fail > 0 -> + if (Fail > 0) or (NotBuilt > 0) or + ((Success+Fail+UserSkip+AutoSkip) == 0) -> ["<font color=\"red\">", integer_to_list(Fail),"</font>"]; true -> @@ -1860,7 +1905,8 @@ runentry(Dir, undefined, _) -> runentry(Dir, Totals={Node,Label,Logs, {TotSucc,TotFail,UserSkip,AutoSkip,NotBuilt}}, Index) -> TotFailStr = - if TotFail > 0 -> + if (TotFail > 0) or (NotBuilt > 0) or + ((TotSucc+TotFail+UserSkip+AutoSkip) == 0) -> ["<font color=\"red\">", integer_to_list(TotFail),"</font>"]; true -> @@ -2852,6 +2898,9 @@ make_relative1(DirTs, CwdTs) -> %%% @doc %%% get_ts_html_wrapper(TestName, PrintLabel, Cwd, TableCols, Encoding) -> + get_ts_html_wrapper(TestName, undefined, PrintLabel, Cwd, TableCols, Encoding). + +get_ts_html_wrapper(TestName, Logdir, PrintLabel, Cwd, TableCols, Encoding) -> TestName1 = if is_list(TestName) -> lists:flatten(TestName); true -> @@ -2872,7 +2921,12 @@ get_ts_html_wrapper(TestName, PrintLabel, Cwd, TableCols, Encoding) -> end end, CTPath = code:lib_dir(common_test), - {ok,CtLogdir} = get_log_dir(true), + + {ok,CtLogdir} = + if Logdir == undefined -> get_log_dir(true); + true -> {ok,Logdir} + end, + AllRuns = make_relative(filename:join(filename:dirname(CtLogdir), ?all_runs_name), Cwd), TestIndex = make_relative(filename:join(filename:dirname(CtLogdir), @@ -3066,10 +3120,12 @@ html_encoding(latin1) -> html_encoding(utf8) -> "utf-8". -unexpected_io(Pid,ct_internal,List,#logger_state{ct_log_fd=Fd}=State) -> +unexpected_io(Pid,ct_internal,_Importance,List,State) -> IoFun = create_io_fun(Pid,State), - io:format(Fd, "~ts", [lists:foldl(IoFun, [], List)]); -unexpected_io(Pid,_Category,List,State) -> + io:format(State#logger_state.ct_log_fd, "~ts", + [lists:foldl(IoFun, [], List)]); +unexpected_io(Pid,_Category,_Importance,List,State) -> IoFun = create_io_fun(Pid,State), Data = io_lib:format("~ts", [lists:foldl(IoFun, [], List)]), - test_server_io:print_unexpected(Data). + test_server_io:print_unexpected(Data), + ok. diff --git a/lib/common_test/src/ct_netconfc.erl b/lib/common_test/src/ct_netconfc.erl index e094ee877a..35920ec1dc 100644 --- a/lib/common_test/src/ct_netconfc.erl +++ b/lib/common_test/src/ct_netconfc.erl @@ -212,11 +212,7 @@ %%---------------------------------------------------------------------- %% Exported types %%---------------------------------------------------------------------- --export_type([hook_options/0, - conn_mod/0, - log_type/0, - key_or_name/0, - notification/0]). +-export_type([notification/0]). %%---------------------------------------------------------------------- %% Internal exports @@ -247,7 +243,11 @@ -define(is_timeout(T), (is_integer(T) orelse T==infinity)). -define(is_filter(F), - (is_atom(F) orelse (is_tuple(F) andalso is_atom(element(1,F))))). + (?is_simple_xml(F) + orelse (F==[]) + orelse (is_list(F) andalso ?is_simple_xml(hd(F))))). +-define(is_simple_xml(Xml), + (is_atom(Xml) orelse (is_tuple(Xml) andalso is_atom(element(1,Xml))))). -define(is_string(S), (is_list(S) andalso is_integer(hd(S)))). %%---------------------------------------------------------------------- @@ -288,19 +288,11 @@ %%---------------------------------------------------------------------- %% Type declarations %%---------------------------------------------------------------------- --type client() :: handle() | server_id() | target_name(). +-type client() :: handle() | ct_gen_conn:server_id() | ct_gen_conn:target_name(). -type handle() :: term(). %% An opaque reference for a connection (netconf session). See {@link %% ct} for more information. --type server_id() :: atom(). -%% A `ServerId' which exists in a configuration file. --type target_name() :: atom(). -%% A name which is associated to a `server_id()' via a -%% `require' statement or a call to {@link ct:require/2} in the -%% test suite. --type key_or_name() :: server_id() | target_name(). - -type options() :: [option()]. %% Options used for setting up ssh connection to a netconf server. @@ -322,14 +314,7 @@ %% See XML Schema for Event Notifications found in RFC5277 for further %% detail about the data format for the string values. --type hook_options() :: [hook_option()]. -%% Options that can be given to `cth_conn_log' in the `ct_hook' statement. --type hook_option() :: {log_type,log_type()} | - {hosts,[key_or_name()]}. --type log_type() :: raw | pretty | html | silent. %-type error_handler() :: module(). --type conn_mod() :: ct_netconfc. - -type error_reason() :: term(). -type simple_xml() :: {xml_tag(), xml_attributes(), xml_content()} | @@ -380,7 +365,7 @@ open(Options) -> %%---------------------------------------------------------------------- -spec open(KeyOrName, ExtraOptions) -> Result when - KeyOrName :: key_or_name(), + KeyOrName :: ct_gen_conn:key_or_name(), ExtraOptions :: options(), Result :: {ok,handle()} | {error,error_reason()}. %% @doc Open a named netconf session and exchange `hello' messages. @@ -457,7 +442,7 @@ only_open(Options) -> %%---------------------------------------------------------------------- -spec only_open(KeyOrName,ExtraOptions) -> Result when - KeyOrName :: key_or_name(), + KeyOrName :: ct_gen_conn:key_or_name(), ExtraOptions :: options(), Result :: {ok,handle()} | {error,error_reason()}. %% @doc Open a name netconf session, but don't send `hello'. @@ -540,22 +525,51 @@ get_capabilities(Client) -> get_capabilities(Client, Timeout) -> call(Client, get_capabilities, Timeout). -%% @private +%%---------------------------------------------------------------------- +%% @spec send(Client, SimpleXml) -> Result +%% @equiv send(Client, SimpleXml, infinity) send(Client, SimpleXml) -> send(Client, SimpleXml, ?DEFAULT_TIMEOUT). -%% @private + +%%---------------------------------------------------------------------- +-spec send(Client, SimpleXml, Timeout) -> Result when + Client :: client(), + SimpleXml :: simple_xml(), + Timeout :: timeout(), + Result :: ok | {error,error_reason()}. +%% @doc Send an XML document to the server. +%% +%% The given XML document is sent as is to the server. This function +%% can be used for sending XML documents that can not be expressed by +%% other interface functions in this module. send(Client, SimpleXml, Timeout) -> call(Client,{send, Timeout, SimpleXml}). -%% @private +%%---------------------------------------------------------------------- +%% @spec send_rpc(Client, SimpleXml) -> Result +%% @equiv send_rpc(Client, SimpleXml, infinity) send_rpc(Client, SimpleXml) -> send_rpc(Client, SimpleXml, ?DEFAULT_TIMEOUT). -%% @private + +%%---------------------------------------------------------------------- +-spec send_rpc(Client, SimpleXml, Timeout) -> Result when + Client :: client(), + SimpleXml :: simple_xml(), + Timeout :: timeout(), + Result :: ok | {error,error_reason()}. +%% @doc Send a Netconf <code>rpc</code> request to the server. +%% +%% The given XML document is wrapped in a valid Netconf +%% <code>rpc</code> request and sent to the server. The +%% <code>message-id</code> and namespace attributes are added to the +%% <code>rpc</code> element. +%% +%% This function can be used for sending <code>rpc</code> requests +%% that can not be expressed by other interface functions in this +%% module. send_rpc(Client, SimpleXml, Timeout) -> call(Client,{send_rpc, SimpleXml, Timeout}). - - %%---------------------------------------------------------------------- %% @spec lock(Client, Target) -> Result %% @equiv lock(Client, Target, infinity) @@ -761,7 +775,7 @@ create_subscription(Client,Timeout) when ?is_timeout(Timeout) -> create_subscription(Client,?DEFAULT_STREAM,Timeout); create_subscription(Client,Stream) - when is_list(Stream) -> + when ?is_string(Stream) -> create_subscription(Client,Stream,?DEFAULT_TIMEOUT); create_subscription(Client,Filter) when ?is_filter(Filter) -> @@ -769,14 +783,14 @@ create_subscription(Client,Filter) ?DEFAULT_TIMEOUT). create_subscription(Client,Stream,Timeout) - when is_list(Stream) andalso + when ?is_string(Stream) andalso ?is_timeout(Timeout) -> call(Client,{send_rpc_op,{create_subscription,self()}, [Stream,undefined,undefined,undefined], Timeout}); create_subscription(Client,StartTime,StopTime) - when is_list(StartTime) andalso - is_list(StopTime) -> + when ?is_string(StartTime) andalso + ?is_string(StopTime) -> create_subscription(Client,?DEFAULT_STREAM,StartTime,StopTime, ?DEFAULT_TIMEOUT); create_subscription(Client,Filter,Timeout) @@ -784,28 +798,28 @@ create_subscription(Client,Filter,Timeout) ?is_timeout(Timeout) -> create_subscription(Client,?DEFAULT_STREAM,Filter,Timeout); create_subscription(Client,Stream,Filter) - when is_list(Stream) andalso + when ?is_string(Stream) andalso ?is_filter(Filter) -> create_subscription(Client,Stream,Filter,?DEFAULT_TIMEOUT). create_subscription(Client,StartTime,StopTime,Timeout) - when is_list(StartTime) andalso - is_list(StopTime) andalso + when ?is_string(StartTime) andalso + ?is_string(StopTime) andalso ?is_timeout(Timeout) -> create_subscription(Client,?DEFAULT_STREAM,StartTime,StopTime,Timeout); create_subscription(Client,Stream,StartTime,StopTime) - when is_list(Stream) andalso - is_list(StartTime) andalso - is_list(StopTime) -> + when ?is_string(Stream) andalso + ?is_string(StartTime) andalso + ?is_string(StopTime) -> create_subscription(Client,Stream,StartTime,StopTime,?DEFAULT_TIMEOUT); create_subscription(Client,Filter,StartTime,StopTime) when ?is_filter(Filter) andalso - is_list(StartTime) andalso - is_list(StopTime) -> + ?is_string(StartTime) andalso + ?is_string(StopTime) -> create_subscription(Client,?DEFAULT_STREAM,Filter, StartTime,StopTime,?DEFAULT_TIMEOUT); create_subscription(Client,Stream,Filter,Timeout) - when is_list(Stream) andalso + when ?is_string(Stream) andalso ?is_filter(Filter) andalso ?is_timeout(Timeout) -> call(Client,{send_rpc_op,{create_subscription,self()}, @@ -813,18 +827,18 @@ create_subscription(Client,Stream,Filter,Timeout) Timeout}). create_subscription(Client,Stream,StartTime,StopTime,Timeout) - when is_list(Stream) andalso - is_list(StartTime) andalso - is_list(StopTime) andalso + when ?is_string(Stream) andalso + ?is_string(StartTime) andalso + ?is_string(StopTime) andalso ?is_timeout(Timeout) -> call(Client,{send_rpc_op,{create_subscription,self()}, [Stream,undefined,StartTime,StopTime], Timeout}); create_subscription(Client,Stream,Filter,StartTime,StopTime) - when is_list(Stream) andalso + when ?is_string(Stream) andalso ?is_filter(Filter) andalso - is_list(StartTime) andalso - is_list(StopTime) -> + ?is_string(StartTime) andalso + ?is_string(StopTime) -> create_subscription(Client,Stream,Filter,StartTime,StopTime,?DEFAULT_TIMEOUT). %%---------------------------------------------------------------------- @@ -832,7 +846,7 @@ create_subscription(Client,Stream,Filter,StartTime,StopTime) Result when Client :: client(), Stream :: stream_name(), - Filter :: simple_xml(), + Filter :: simple_xml() | [simple_xml()], StartTime :: xs_datetime(), StopTime :: xs_datetime(), Timeout :: timeout(), @@ -855,8 +869,7 @@ create_subscription(Client,Stream,Filter,StartTime,StopTime) %% possible events is of interest. The format of this parameter is %% the same as that of the filter parameter in the NETCONF protocol %% operations. If not present, all events not precluded by other -%% parameters will be sent. See section 3.6 for more information on -%% filters.</dd> +%% parameters will be sent.</dd> %% %% <dt>StartTime:</dt> %% <dd>An optional parameter used to trigger the replay feature and @@ -1097,10 +1110,14 @@ handle_msg({Ref,timeout}, ct_gen_conn:return(Caller,{error,{hello_session_failed,timeout}}), {stop,State#state{hello_status={error,timeout}}}; handle_msg({Ref,timeout},#state{pending=Pending} = State) -> - {value,#pending{caller=Caller},Pending1} = + {value,#pending{op=Op,caller=Caller},Pending1} = lists:keytake(Ref,#pending.ref,Pending), ct_gen_conn:return(Caller,{error,timeout}), - {noreply,State#state{pending=Pending1}}. + R = case Op of + close_session -> stop; + _ -> noreply + end, + {R,State#state{pending=Pending1}}. %% @private %% Called by ct_util_server to close registered connections before terminate. @@ -1241,8 +1258,10 @@ filter(undefined) -> []; filter({xpath,Filter}) when ?is_string(Filter) -> [{filter,[{type,"xpath"},{select, Filter}],[]}]; +filter(Filter) when is_list(Filter) -> + [{filter,[{type,"subtree"}],Filter}]; filter(Filter) -> - [{filter,[{type,"subtree"}],[Filter]}]. + filter([Filter]). maybe_element(_,undefined) -> []; diff --git a/lib/common_test/src/ct_run.erl b/lib/common_test/src/ct_run.erl index 266ca73417..7c797be03e 100644 --- a/lib/common_test/src/ct_run.erl +++ b/lib/common_test/src/ct_run.erl @@ -1883,7 +1883,7 @@ verify_suites(TestSuites) -> atom_to_list( Suite)), io:format(user, - "Suite ~w not found" + "Suite ~w not found " "in directory ~ts~n", [Suite,TestDir]), {Found,[{DS,[Name]}|NotFound]} diff --git a/lib/common_test/src/ct_telnet.erl b/lib/common_test/src/ct_telnet.erl index 4092d33bc0..b4d82a53cf 100644 --- a/lib/common_test/src/ct_telnet.erl +++ b/lib/common_test/src/ct_telnet.erl @@ -17,51 +17,147 @@ %% %CopyrightEnd% %% -%%% @doc Common Test specific layer on top of telnet client ct_telnet_client.erl -%%% -%%% <p>Use this module to set up telnet connections, send commands and -%%% perform string matching on the result. -%%% See the <c>unix_telnet</c> manual page for information about how to use -%%% ct_telnet, and configure connections, specifically for unix hosts.</p> -%%% <p>The following default values are defined in ct_telnet:</p> -%%% <pre> -%%% Connection timeout = 10 sec (time to wait for connection) -%%% Command timeout = 10 sec (time to wait for a command to return) -%%% Max no of reconnection attempts = 3 -%%% Reconnection interval = 5 sek (time to wait in between reconnection attempts) -%%% Keep alive = true (will send NOP to the server every 10 sec if connection is idle)</pre> -%%% <p>These parameters can be altered by the user with the following -%%% configuration term:</p> -%%% <pre> -%%% {telnet_settings, [{connect_timeout,Millisec}, -%%% {command_timeout,Millisec}, -%%% {reconnection_attempts,N}, -%%% {reconnection_interval,Millisec}, -%%% {keep_alive,Bool}]}.</pre> -%%% <p><code>Millisec = integer(), N = integer()</code></p> -%%% <p>Enter the <code>telnet_settings</code> term in a configuration -%%% file included in the test and ct_telnet will retrieve the information -%%% automatically. Note that <c>keep_alive</c> may be specified per connection if -%%% required. See <c>unix_telnet</c> for details.</p></doc> - -%%% @type connection_type() = telnet | ts1 | ts2 - -%%% @type connection() = handle() | -%%% {ct:target_name(),connection_type()} | ct:target_name() - -%%% @type handle() = ct_gen_conn:handle(). Handle for a -%%% specific telnet connection. - -%%% @type prompt_regexp() = string(). A regular expression which -%%% matches all possible prompts for a specific type of target. The -%%% regexp must not have any groups i.e. when matching, re:run/3 shall -%%% return a list with one single element. -%%% -%%% @see unix_telnet +%% @doc Common Test specific layer on top of telnet client `ct_telnet_client.erl' +%% +%% <p>Use this module to set up telnet connections, send commands and +%% perform string matching on the result. +%% See the `unix_telnet' manual page for information about how to use +%% `ct_telnet', and configure connections, specifically for unix hosts.</p> +%% <p>The following default values are defined in `ct_telnet':</p> +%% <pre> +%% Connection timeout = 10 sec (time to wait for connection) +%% Command timeout = 10 sec (time to wait for a command to return) +%% Max no of reconnection attempts = 3 +%% Reconnection interval = 5 sek (time to wait in between reconnection attempts) +%% Keep alive = true (will send NOP to the server every 10 sec if connection is idle)</pre> +%% <p>These parameters can be altered by the user with the following +%% configuration term:</p> +%% <pre> +%% {telnet_settings, [{connect_timeout,Millisec}, +%% {command_timeout,Millisec}, +%% {reconnection_attempts,N}, +%% {reconnection_interval,Millisec}, +%% {keep_alive,Bool}]}.</pre> +%% <p><code>Millisec = integer(), N = integer()</code></p> +%% <p>Enter the <code>telnet_settings</code> term in a configuration +%% file included in the test and ct_telnet will retrieve the information +%% automatically. Note that `keep_alive' may be specified per connection if +%% required. See `unix_telnet' for details.</p> +%% +%% == Logging == +%% +%% `ct_telnet' can be configured to uses the `error_logger' for logging telnet +%% traffic. A special purpose error handler is implemented in +%% `ct_conn_log_h'. To use this error handler, add the `cth_conn_log' +%% hook in your test suite, e.g: +%% +%% +%% ``` +%% suite() -> +%% [{ct_hooks, [{cth_conn_log, [{conn_mod(),hook_options()}]}]}]. +%%''' +%% +%% `conn_mod()' is the name of the common_test module implementing +%% the connection protocol, i.e. `ct_telnet'. +%% +%% The hook option `log_type' specifies the type of logging: +%% +%% <dl> +%% <dt>`raw'</dt> +%% <dd>The sent and received telnet data is logged to a separate +%% text file as is, without any formatting. A link to the file is +%% added to the test case HTML log.</dd> +%% +%% <dt>`html (default)'</dt> +%% <dd>The sent and received telnet traffic is pretty printed +%% directly in the test case HTML log.</dd> +%% +%% <dt>`silent'</dt> +%% <dd>Telnet traffic is not logged.</dd> +%% </dl> +%% +%% By default, all telnet traffic is logged in one single log +%% file. However, it is possible to have different connections logged +%% in separate files. To do this, use the hook option `hosts' and +%% list the names of the servers/connections that will be used in the +%% suite. Note that the connections must be named for this to work +%% (see the `open' function below). +%% +%% The `hosts' option has no effect if `log_type' is set to `html' or +%% `silent'. +%% +%% The hook options can also be specified in a configuration file with +%% the configuration variable `ct_conn_log': +%% +%% ``` +%% {ct_conn_log,[{conn_mod(),hook_options()}]}. +%% ''' +%% +%% For example: +%% +%% ``` +%% {ct_conn_log,[{ct_telnet,[{log_type,raw}, +%% {hosts,[key_or_name()]}]}]} +%% ''' +%% +%% <b>Note</b> that hook options specified in a configuration file +%% will overwrite any hardcoded hook options in the test suite. +%% +%% === Logging example 1 === +%% +%% The following `ct_hooks' statement will cause raw printing of +%% telnet traffic to separate logs for the connections named +%% `server1' and `server2'. Any other connections will be logged +%% to default telnet log. +%% +%% ``` +%% suite() -> +%% [{ct_hooks, [{cth_conn_log, [{ct_telnet,[{log_type,raw}}, +%% {hosts,[server1,server2]}]} +%% ]}]}]. +%%''' +%% +%% === Logging example 2 === +%% +%% The following configuration file will cause raw logging of all +%% telnet traffic into one single text file. +%% +%% ``` +%% {ct_conn_log,[{ct_telnet,[{log_type,raw}]}]}. +%% ''' +%% +%% The `ct_hooks' statement must look like this: +%% +%% ``` +%% suite() -> +%% [{ct_hooks, [{cth_conn_log, []}]}]. +%% ''' +%% +%% The same `ct_hooks' statement without the configuration file would +%% cause HTML logging of all telnet connections into the test case +%% HTML log. +%% +%% <b>Note</b> that if the `cth_conn_log' hook is not added, telnet +%% traffic is still logged in the test case HTML log file (on the legacy +%% `ct_telnet' format). +%% @end --module(ct_telnet). +%% @type connection_type() = telnet | ts1 | ts2 + +%% @type connection() = handle() | +%% {ct:target_name(),connection_type()} | ct:target_name() --compile(export_all). +%% @type handle() = ct_gen_conn:handle(). Handle for a +%% specific telnet connection. + +%% @type prompt_regexp() = string(). A regular expression which +%% matches all possible prompts for a specific type of target. The +%% regexp must not have any groups i.e. when matching, re:run/3 shall +%% return a list with one single element. +%% +%% @see unix_telnet + +-module(ct_telnet). -export([open/1, open/2, open/3, open/4, close/1]). -export([cmd/2, cmd/3, cmdf/3, cmdf/4, get_data/1, @@ -71,10 +167,9 @@ -export([init/3,handle_msg/2,reconnect/2,terminate/2]). %% Tool internals --export([silent_teln_expect/5, teln_receive_until_prompt/3, - start_log/1, log/3, cont_log/2, end_log/0, - try_start_log/1, try_log/3, try_cont_log/2, try_end_log/0]). - +-export([silent_teln_expect/6, teln_receive_until_prompt/3, + format_data/2]). +-export([start_gen_log/1, end_gen_log/0, log/3, log/4]). -define(RECONNS,3). -define(RECONN_TIMEOUT,5000). @@ -83,12 +178,14 @@ -include("ct_util.hrl"). --record(state,{teln_pid, +-record(state,{host, + port, + teln_pid, prx, - type, buffer=[], prompt=false, name, + type, target_mod, keep_alive, extra, @@ -160,8 +257,7 @@ open(KeyOrName,ConnType,TargetMod) -> open(KeyOrName,ConnType,TargetMod,Extra) -> case ct:get_config({KeyOrName,ConnType}) of undefined -> - log(heading(open,{KeyOrName,ConnType}),"Failed: ~p", - [{not_available,KeyOrName}]), + log(undefined,open,"Failed: ~p",[{not_available,KeyOrName}]), {error,{not_available,KeyOrName,ConnType}}; Addr -> Addr1 = @@ -183,8 +279,8 @@ open(KeyOrName,ConnType,TargetMod,Extra) -> end; Bool -> Bool end, - log(heading(open,{KeyOrName,ConnType}), - "Opening connection to: ~p",[Addr1]), + log(undefined,open,"Connecting to ~p(~p)", + [KeyOrName,Addr1]), ct_gen_conn:start(KeyOrName,full_addr(Addr1,ConnType), {TargetMod,KeepAlive,Extra},?MODULE) end. @@ -202,7 +298,7 @@ open(KeyOrName,ConnType,TargetMod,Extra) -> close(Connection) -> case get_handle(Connection) of {ok,Pid} -> - log("ct_telnet:close","Handle: ~w",[Pid]), + log(undefined,close,"Connection closed, handle: ~w",[Pid]), case ct_gen_conn:stop(Pid) of {error,{process_down,Pid,noproc}} -> {error,already_closed}; @@ -408,9 +504,20 @@ init(Name,{Ip,Port,Type},{TargetMod,KeepAlive,Extra}) -> Settings -> set_telnet_defaults(Settings,#state{}) end, - case catch TargetMod:connect(Ip,Port,S0#state.conn_to,KeepAlive,Extra) of + case catch TargetMod:connect(Name,Ip,Port,S0#state.conn_to, + KeepAlive,Extra) of {ok,TelnPid} -> - log(heading(init,{Name,Type}), + put({ct_telnet_pid2name,TelnPid},Name), + S1 = S0#state{host=Ip, + port=Port, + teln_pid=TelnPid, + name=Name, + type=type(Type), + target_mod=TargetMod, + keep_alive=KeepAlive, + extra=Extra, + prx=TargetMod:get_prompt_regexp()}, + log(S1,open, "Opened telnet connection\n" "IP: ~p\n" "Port: ~p\n" @@ -419,15 +526,9 @@ init(Name,{Ip,Port,Type},{TargetMod,KeepAlive,Extra}) -> "Reconnection interval: ~p\n" "Connection timeout: ~p\n" "Keep alive: ~w", - [Ip,Port,S0#state.com_to,S0#state.reconns, - S0#state.reconn_int,S0#state.conn_to,KeepAlive]), - {ok,TelnPid,S0#state{teln_pid=TelnPid, - type=type(Type), - name={Name,Type}, - target_mod=TargetMod, - keep_alive=KeepAlive, - extra=Extra, - prx=TargetMod:get_prompt_regexp()}}; + [Ip,Port,S1#state.com_to,S1#state.reconns, + S1#state.reconn_int,S1#state.conn_to,KeepAlive]), + {ok,TelnPid,S1}; {'EXIT',Reason} -> {error,Reason}; Error -> @@ -448,27 +549,31 @@ set_telnet_defaults([{reconnection_interval,RInt}|Ss],S) -> set_telnet_defaults([{keep_alive,_}|Ss],S) -> set_telnet_defaults(Ss,S); set_telnet_defaults([Unknown|Ss],S) -> - log(heading(set_telnet_defaults,{telnet_settings,Unknown}), - "Bad element in telnet_settings: ~p",[Unknown]), + force_log(S,error, + "Bad element in telnet_settings: ~p",[Unknown]), set_telnet_defaults(Ss,S); set_telnet_defaults([],S) -> S. %% @hidden handle_msg({cmd,Cmd,Timeout},State) -> - try_start_log(heading(cmd,State#state.name)), - try_cont_log("Cmd: ~p", [Cmd]), - debug_cont_log("Throwing Buffer:",[]), + start_gen_log(heading(cmd,State#state.name)), + log(State,cmd,"Cmd: ~p",[Cmd]), + + debug_cont_gen_log("Throwing Buffer:",[]), debug_log_lines(State#state.buffer), + case {State#state.type,State#state.prompt} of {ts,_} -> - silent_teln_expect(State#state.teln_pid, + silent_teln_expect(State#state.name, + State#state.teln_pid, State#state.buffer, prompt, State#state.prx, [{timeout,2000}]); {ip,false} -> - silent_teln_expect(State#state.teln_pid, + silent_teln_expect(State#state.name, + State#state.teln_pid, State#state.buffer, prompt, State#state.prx, @@ -482,29 +587,36 @@ handle_msg({cmd,Cmd,Timeout},State) -> {Return,NewBuffer,Prompt} = case teln_cmd(State#state.teln_pid, Cmd, State#state.prx, TO) of {ok,Data,_PromptType,Rest} -> - try_cont_log("Return: ~p", [{ok,Data}]), + log(State,recv,"Return: ~p",[{ok,Data}]), {{ok,Data},Rest,true}; Error -> - Retry = {retry,{Error,State#state.name,State#state.teln_pid, + Retry = {retry,{Error, + {State#state.name, + State#state.type}, + State#state.teln_pid, {cmd,Cmd,TO}}}, - try_cont_log("Return: ~p", [Error]), + log(State,recv,"Return: ~p",[Error]), {Retry,[],false} end, - try_end_log(), + end_gen_log(), {Return,State#state{buffer=NewBuffer,prompt=Prompt}}; handle_msg({send,Cmd},State) -> - try_log(heading(send,State#state.name),"Cmd: ~p",[Cmd]), - debug_cont_log("Throwing Buffer:",[]), + log(State,send,"Cmd: ~p",[Cmd]), + + debug_cont_gen_log("Throwing Buffer:",[]), debug_log_lines(State#state.buffer), + case {State#state.type,State#state.prompt} of {ts,_} -> - silent_teln_expect(State#state.teln_pid, + silent_teln_expect(State#state.name, + State#state.teln_pid, State#state.buffer, prompt, State#state.prx, [{timeout,2000}]); {ip,false} -> - silent_teln_expect(State#state.teln_pid, + silent_teln_expect(State#state.name, + State#state.teln_pid, State#state.buffer, prompt, State#state.prx, @@ -515,19 +627,21 @@ handle_msg({send,Cmd},State) -> ct_telnet_client:send_data(State#state.teln_pid,Cmd), {ok,State#state{buffer=[],prompt=false}}; handle_msg(get_data,State) -> - try_start_log(heading(get_data,State#state.name)), + start_gen_log(heading(get_data,State#state.name)), + log(State,cmd,"Reading data...",[]), {ok,Data,Buffer} = teln_get_all_data(State#state.teln_pid, State#state.prx, State#state.buffer, [],[]), - try_cont_log("Return: ~p",[{ok,Data}]), - try_end_log(), + log(State,recv,"Return: ~p",[{ok,Data}]), + end_gen_log(), {{ok,Data},State#state{buffer=Buffer}}; handle_msg({expect,Pattern,Opts},State) -> - try_start_log(heading(expect,State#state.name)), - try_cont_log("Expect: ~p\nOpts=~p\n",[Pattern,Opts]), + start_gen_log(heading(expect,State#state.name)), + log(State,expect,"Expect: ~p\nOpts = ~p\n",[Pattern,Opts]), {Return,NewBuffer,Prompt} = - case teln_expect(State#state.teln_pid, + case teln_expect(State#state.name, + State#state.teln_pid, State#state.buffer, Pattern, State#state.prx, @@ -536,22 +650,23 @@ handle_msg({expect,Pattern,Opts},State) -> P = check_if_prompt_was_reached(Data,[]), {{ok,Data},Rest,P}; {ok,Data,HaltReason,Rest} -> - force_cont_log("HaltReason: ~p", - [HaltReason]), + force_log(State,expect,"HaltReason: ~p",[HaltReason]), P = check_if_prompt_was_reached(Data,HaltReason), {{ok,Data,HaltReason},Rest,P}; {error,Reason,Rest} -> - force_cont_log("Expect failed\n~p",[{error,Reason}]), + force_log(State,expect,"Expect failed\n~p",[{error,Reason}]), P = check_if_prompt_was_reached([],Reason), {{error,Reason},Rest,P}; {error,Reason} -> - force_cont_log("Expect failed\n~p",[{error,Reason}]), + force_log(State,expect,"Expect failed\n~p",[{error,Reason}]), P = check_if_prompt_was_reached([],Reason), {{error,Reason},[],P} end, - try_end_log(), + end_gen_log(), Return1 = case Return of - {error,_} -> {retry,{Return,State#state.name, + {error,_} -> {retry,{Return, + {State#state.name, + State#state.type}, State#state.teln_pid, {expect,Pattern,Opts}}}; _ -> Return @@ -562,18 +677,20 @@ handle_msg({expect,Pattern,Opts},State) -> %% @hidden reconnect({Ip,Port,_Type},State) -> reconnect(Ip,Port,State#state.reconns,State). -reconnect(Ip,Port,N,State=#state{target_mod=TargetMod, +reconnect(Ip,Port,N,State=#state{name=Name, + target_mod=TargetMod, keep_alive=KeepAlive, extra=Extra, conn_to=ConnTo, reconn_int=ReconnInt}) -> - case TargetMod:connect(Ip,Port,ConnTo,KeepAlive,Extra) of - {ok, NewPid} -> + case TargetMod:connect(Name,Ip,Port,ConnTo,KeepAlive,Extra) of + {ok,NewPid} -> + put({ct_telnet_pid2name,NewPid},Name), {ok, NewPid, State#state{teln_pid=NewPid}}; Error when N==0 -> Error; _Error -> - log("Reconnect failed!","Retries left: ~w",[N]), + log(State,reconnect,"Reconnect failed!","Retries left: ~w",[N]), timer:sleep(ReconnInt), reconnect(Ip,Port,N-1,State) end. @@ -581,11 +698,9 @@ reconnect(Ip,Port,N,State=#state{target_mod=TargetMod, %% @hidden terminate(TelnPid,State) -> - log(heading(terminate,State#state.name), - "Closing telnet connection.\nId: ~w", - [TelnPid]), - ct_telnet_client:close(TelnPid). - + Result = ct_telnet_client:close(TelnPid), + log(State,close,"Telnet connection for ~w closed.",[TelnPid]), + Result. %%%================================================================= %%% Internal function @@ -637,79 +752,109 @@ check_if_prompt_was_reached(Data,_) when is_list(Data) -> check_if_prompt_was_reached(_,_) -> false. -%tc(Fun) -> -% Before = erlang:now(), -% Val = Fun(), -% After = erlang:now(), -% {now_diff(After, Before), Val}. -%now_diff({A2, B2, C2}, {A1, B1, C1}) -> -% ((A2-A1)*1000000 + B2-B1)*1000000 + C2-C1. - -heading(Function,Name) -> - io_lib:format("~w:~w ~p",[?MODULE,Function,Name]). - -%%% @hidden -%% Functions for regular (unconditional) logging, to be -%% used during connect, reconnect, disconnect etc. -log(Heading,Str,Args) -> - ct_gen_conn:log(Heading,Str,Args). -%%% @hidden -start_log(Heading) -> - ct_gen_conn:start_log(Heading). -cont_log(Str,Args) -> - ct_gen_conn:cont_log(Str,Args). -end_log() -> - ct_gen_conn:end_log(). - -%%% @hidden -%% Functions for conditional logging, to be used by -%% cmd, send, receive, expect etc (this output may be -%% silenced by user). -try_start_log(Heading) -> - do_try_log(start_log,[Heading]). -%%% @hidden -try_end_log() -> - do_try_log(end_log,[]). - -%%% @hidden -try_log(Heading,Str,Args) -> - do_try_log(log,[Heading,Str,Args]). - -%%% @hidden -try_cont_log(Str,Args) -> - do_try_log(cont_log,[Str,Args]). - %%% @hidden -do_try_log(Func,Args) -> - %% check if output is suppressed - case ct_util:is_silenced(telnet) of - true -> +%% Functions for logging ct_telnet reports and telnet data + +heading(Action,undefined) -> + io_lib:format("~w ~w",[?MODULE,Action]); +heading(Action,Name) -> + io_lib:format("~w ~w for ~p",[?MODULE,Action,Name]). + +force_log(State,Action,String,Args) -> + log(State,Action,String,Args,true). + +log(State,Action,String,Args) when is_record(State, state) -> + log(State,Action,String,Args,false); +log(Name,Action,String,Args) when is_atom(Name) -> + log(#state{name=Name},Action,String,Args,false); +log(TelnPid,Action,String,Args) when is_pid(TelnPid) -> + log(#state{teln_pid=TelnPid},Action,String,Args,false). + +log(undefined,String,Args) -> + log(#state{},undefined,String,Args,false); +log(Name,String,Args) when is_atom(Name) -> + log(#state{name=Name},undefined,String,Args,false); +log(TelnPid,String,Args) when is_pid(TelnPid) -> + log(#state{teln_pid=TelnPid},undefined,String,Args). + +log(#state{name=Name,teln_pid=TelnPid,host=Host,port=Port}, + Action,String,Args,ForcePrint) -> + Name1 = if Name == undefined -> get({ct_telnet_pid2name,TelnPid}); + true -> Name + end, + Silent = get(silent), + case ct_util:get_testdata({cth_conn_log,?MODULE}) of + Result when Result /= undefined, Result /= silent, Silent /= true -> + {PrintHeader,PreBR} = if Action==undefined -> + {false,""}; + true -> + {true,"\n"} + end, + error_logger:info_report(#conn_log{header=PrintHeader, + client=self(), + conn_pid=TelnPid, + address={Host,Port}, + name=Name1, + action=Action, + module=?MODULE}, + {PreBR++String,Args}); + Result when Result /= undefined -> ok; - false -> - apply(ct_gen_conn,Func,Args) + _ when Action == open; Action == close; Action == reconnect; + Action == info; Action == error -> + ct_gen_conn:log(heading(Action,Name1),String,Args); + _ when ForcePrint == false -> + case ct_util:is_silenced(telnet) of + true -> + ok; + false -> + ct_gen_conn:cont_log(String,Args) + end; + _ when ForcePrint == true -> + case ct_util:is_silenced(telnet) of + true -> + %% call log/3 now instead of cont_log/2 since + %% start_gen_log/1 will not have been previously called + ct_gen_conn:log(heading(Action,Name1),String,Args); + false -> + ct_gen_conn:cont_log(String,Args) + end end. -%%% @hidden -%% Functions that will force printout even if ct_telnet -%% output has been silenced, to be used for error printouts. -force_cont_log(Str,Args) -> - case ct_util:is_silenced(telnet) of - true -> - %% call log/3 now instead of cont_log/2 since - %% start_log/1 will not have been previously called - log("ct_telnet info",Str,Args); - false -> - cont_log(Str,Args) +start_gen_log(Heading) -> + case ct_util:get_testdata({cth_conn_log,?MODULE}) of + undefined -> + %% check if output is suppressed + case ct_util:is_silenced(telnet) of + true -> ok; + false -> ct_gen_conn:start_log(Heading) + end; + _ -> + ok + end. + +end_gen_log() -> + case ct_util:get_testdata({cth_conn_log,?MODULE}) of + undefined -> + %% check if output is suppressed + case ct_util:is_silenced(telnet) of + true -> ok; + false -> ct_gen_conn:end_log() + end; + _ -> + ok end. %%% @hidden %% Debug printouts. -debug_cont_log(Str,Args) -> +debug_cont_gen_log(Str,Args) -> Old = put(silent,true), - cont_log(Str,Args), + ct_gen_conn:cont_log(Str,Args), put(silent,Old). - +%% Log callback - called from the error handler process +format_data(_How,{String,Args}) -> + io_lib:format(String,Args). %%%================================================================= %%% Abstraction layer on top of ct_telnet_client.erl @@ -717,7 +862,6 @@ teln_cmd(Pid,Cmd,Prx,Timeout) -> ct_telnet_client:send_data(Pid,Cmd), teln_receive_until_prompt(Pid,Prx,Timeout). - teln_get_all_data(Pid,Prx,Data,Acc,LastLine) -> case check_for_prompt(Prx,lists:reverse(LastLine) ++ Data) of {prompt,Lines,_PromptType,Rest} -> @@ -746,11 +890,9 @@ teln_get_all_data(Pid,Prx,Data,Acc,LastLine) -> %% @doc Externally the silent_teln_expect function shall only be used %% by the TargetModule, i.e. the target specific module which %% implements connect/2 and get_prompt_regexp/0. -silent_teln_expect(Pid,Data,Pattern,Prx,Opts) -> +silent_teln_expect(Name,Pid,Data,Pattern,Prx,Opts) -> Old = put(silent,true), - try_cont_log("silent_teln_expect/5, Pattern = ~p",[Pattern]), - Result = teln_expect(Pid,Data,Pattern,Prx,Opts), - try_cont_log("silent_teln_expect -> ~p\n",[Result]), + Result = teln_expect(Name,Pid,Data,Pattern,Prx,Opts), put(silent,Old), Result. @@ -766,7 +908,7 @@ silent_teln_expect(Pid,Data,Pattern,Prx,Opts) -> %% condition is fullfilled. %% 3b) Repeat (sequence): 2) is repeated either N times or until a %% halt condition is fullfilled. -teln_expect(Pid,Data,Pattern0,Prx,Opts) -> +teln_expect(Name,Pid,Data,Pattern0,Prx,Opts) -> HaltPatterns = case get_ignore_prompt(Opts) of true -> @@ -790,7 +932,7 @@ teln_expect(Pid,Data,Pattern0,Prx,Opts) -> case get_repeat(Opts) of false -> - case teln_expect1(Data,Pattern,[],EO) of + case teln_expect1(Name,Pid,Data,Pattern,[],EO) of {ok,Matched,Rest} -> {ok,Matched,Rest}; {halt,Why,Rest} -> @@ -800,7 +942,7 @@ teln_expect(Pid,Data,Pattern0,Prx,Opts) -> end; N -> EO1 = EO#eo{repeat=N}, - repeat_expect(Data,Pattern,[],EO1) + repeat_expect(Name,Pid,Data,Pattern,[],EO1) end. convert_pattern(Pattern,Seq) @@ -855,23 +997,27 @@ get_prompt_check(Opts) -> %% Repeat either single or sequence. All match results are accumulated %% and returned when a halt condition is fulllfilled. -repeat_expect(Rest,_Pattern,Acc,#eo{repeat=0}) -> +repeat_expect(_Name,_Pid,Rest,_Pattern,Acc,#eo{repeat=0}) -> {ok,lists:reverse(Acc),done,Rest}; -repeat_expect(Data,Pattern,Acc,EO) -> - case teln_expect1(Data,Pattern,[],EO) of +repeat_expect(Name,Pid,Data,Pattern,Acc,EO) -> + case teln_expect1(Name,Pid,Data,Pattern,[],EO) of {ok,Matched,Rest} -> EO1 = EO#eo{repeat=EO#eo.repeat-1}, - repeat_expect(Rest,Pattern,[Matched|Acc],EO1); + repeat_expect(Name,Pid,Rest,Pattern,[Matched|Acc],EO1); {halt,Why,Rest} -> {ok,lists:reverse(Acc),Why,Rest}; {error,Reason} -> {error,Reason} end. -teln_expect1(Data,Pattern,Acc,EO) -> +teln_expect1(Name,Pid,Data,Pattern,Acc,EO) -> ExpectFun = case EO#eo.seq of - true -> fun() -> seq_expect(Data,Pattern,Acc,EO) end; - false -> fun() -> one_expect(Data,Pattern,EO) end + true -> fun() -> + seq_expect(Name,Pid,Data,Pattern,Acc,EO) + end; + false -> fun() -> + one_expect(Name,Pid,Data,Pattern,EO) + end end, case ExpectFun() of {match,Match,Rest} -> @@ -890,10 +1036,10 @@ teln_expect1(Data,Pattern,Acc,EO) -> case NotFinished of {nomatch,Rest} -> %% One expect - teln_expect1(Rest++Data1,Pattern,[],EO); + teln_expect1(Name,Pid,Rest++Data1,Pattern,[],EO); {continue,Patterns1,Acc1,Rest} -> %% Sequence - teln_expect1(Rest++Data1,Patterns1,Acc1,EO) + teln_expect1(Name,Pid,Rest++Data1,Patterns1,Acc1,EO) end end end. @@ -913,47 +1059,45 @@ get_data1(Pid) -> %% lines and each line is matched against each pattern. %% one_expect: split data chunk at prompts -one_expect(Data,Pattern,EO) when EO#eo.prompt_check==false -> +one_expect(Name,Pid,Data,Pattern,EO) when EO#eo.prompt_check==false -> % io:format("Raw Data ~p Pattern ~p EO ~p ",[Data,Pattern,EO]), - one_expect1(Data,Pattern,[],EO#eo{found_prompt=false}); -one_expect(Data,Pattern,EO) -> + one_expect1(Name,Pid,Data,Pattern,[],EO#eo{found_prompt=false}); +one_expect(Name,Pid,Data,Pattern,EO) -> case match_prompt(Data,EO#eo.prx) of {prompt,UptoPrompt,PromptType,Rest} -> case Pattern of [Prompt] when Prompt==prompt; Prompt=={prompt,PromptType} -> %% Only searching for prompt - log_lines(UptoPrompt), - try_cont_log("<b>PROMPT:</b> ~ts", [PromptType]), + log_lines(Name,Pid,UptoPrompt), + log(name_or_pid(Name,Pid),"PROMPT: ~ts",[PromptType]), {match,{prompt,PromptType},Rest}; [{prompt,_OtherPromptType}] -> %% Only searching for one specific prompt, not thisone - log_lines(UptoPrompt), + log_lines(Name,Pid,UptoPrompt), {nomatch,Rest}; _ -> - one_expect1(UptoPrompt,Pattern,Rest, + one_expect1(Name,Pid,UptoPrompt,Pattern,Rest, EO#eo{found_prompt=PromptType}) end; noprompt -> case Pattern of [Prompt] when Prompt==prompt; element(1,Prompt)==prompt -> %% Only searching for prompt - LastLine = log_lines_not_last(Data), + LastLine = log_lines_not_last(Name,Pid,Data), {nomatch,LastLine}; _ -> - one_expect1(Data,Pattern,[],EO#eo{found_prompt=false}) + one_expect1(Name,Pid,Data,Pattern,[], + EO#eo{found_prompt=false}) end end. -remove_zero(List) -> - [Ch || Ch <- List, Ch=/=0, Ch=/=13]. - %% one_expect1: split data chunk at lines -one_expect1(Data,Pattern,Rest,EO) -> - case match_lines(Data,Pattern,EO) of +one_expect1(Name,Pid,Data,Pattern,Rest,EO) -> + case match_lines(Name,Pid,Data,Pattern,EO) of {match,Match,MatchRest} -> {match,Match,MatchRest++Rest}; {nomatch,prompt} -> - one_expect(Rest,Pattern,EO); + one_expect(Name,Pid,Rest,Pattern,EO); {nomatch,NoMatchRest} -> {nomatch,NoMatchRest++Rest}; {halt,Why,HaltRest} -> @@ -970,77 +1114,77 @@ one_expect1(Data,Pattern,Rest,EO) -> %% searching for the next pattern in the list. %% seq_expect: Split data chunk at prompts -seq_expect(Data,[],Acc,_EO) -> +seq_expect(_Name,_Pid,Data,[],Acc,_EO) -> {match,lists:reverse(Acc),Data}; -seq_expect([],Patterns,Acc,_EO) -> +seq_expect(_Name,_Pid,[],Patterns,Acc,_EO) -> {continue,Patterns,lists:reverse(Acc),[]}; -seq_expect(Data,Patterns,Acc,EO) when EO#eo.prompt_check==false -> - seq_expect1(Data,Patterns,Acc,[],EO#eo{found_prompt=false}); -seq_expect(Data,Patterns,Acc,EO) -> +seq_expect(Name,Pid,Data,Patterns,Acc,EO) when EO#eo.prompt_check==false -> + seq_expect1(Name,Pid,Data,Patterns,Acc,[],EO#eo{found_prompt=false}); +seq_expect(Name,Pid,Data,Patterns,Acc,EO) -> case match_prompt(Data,EO#eo.prx) of {prompt,UptoPrompt,PromptType,Rest} -> - seq_expect1(UptoPrompt,Patterns,Acc,Rest, + seq_expect1(Name,Pid,UptoPrompt,Patterns,Acc,Rest, EO#eo{found_prompt=PromptType}); noprompt -> - seq_expect1(Data,Patterns,Acc,[],EO#eo{found_prompt=false}) + seq_expect1(Name,Pid,Data,Patterns,Acc,[],EO#eo{found_prompt=false}) end. %% seq_expect1: For one prompt-chunk, match each pattern - line by %% line if it is other than the prompt we are seaching for. -seq_expect1(Data,[prompt|Patterns],Acc,Rest,EO) -> +seq_expect1(Name,Pid,Data,[prompt|Patterns],Acc,Rest,EO) -> case EO#eo.found_prompt of false -> - LastLine = log_lines_not_last(Data), + LastLine = log_lines_not_last(Name,Pid,Data), %% Rest==[] because no prompt is found {continue,[prompt|Patterns],Acc,LastLine}; PromptType -> - log_lines(Data), - try_cont_log("<b>PROMPT:</b> ~ts", [PromptType]), - seq_expect(Rest,Patterns,[{prompt,PromptType}|Acc],EO) + log_lines(Name,Pid,Data), + log(name_or_pid(Name,Pid),"PROMPT: ~ts",[PromptType]), + seq_expect(Name,Pid,Rest,Patterns,[{prompt,PromptType}|Acc],EO) end; -seq_expect1(Data,[{prompt,PromptType}|Patterns],Acc,Rest,EO) -> +seq_expect1(Name,Pid,Data,[{prompt,PromptType}|Patterns],Acc,Rest,EO) -> case EO#eo.found_prompt of false -> - LastLine = log_lines_not_last(Data), + LastLine = log_lines_not_last(Name,Pid,Data), %% Rest==[] because no prompt is found {continue,[{prompt,PromptType}|Patterns],Acc,LastLine}; PromptType -> - log_lines(Data), - try_cont_log("<b>PROMPT:</b> ~ts", [PromptType]), - seq_expect(Rest,Patterns,[{prompt,PromptType}|Acc],EO); + log_lines(Name,Pid,Data), + log(name_or_pid(Name,Pid),"PROMPT: ~ts", [PromptType]), + seq_expect(Name,Pid,Rest,Patterns,[{prompt,PromptType}|Acc],EO); _OtherPromptType -> - log_lines(Data), - seq_expect(Rest,[{prompt,PromptType}|Patterns],Acc,EO) + log_lines(Name,Pid,Data), + seq_expect(Name,Pid,Rest,[{prompt,PromptType}|Patterns],Acc,EO) end; -seq_expect1(Data,[Pattern|Patterns],Acc,Rest,EO) -> - case match_lines(Data,[Pattern],EO) of +seq_expect1(Name,Pid,Data,[Pattern|Patterns],Acc,Rest,EO) -> + case match_lines(Name,Pid,Data,[Pattern],EO) of {match,Match,MatchRest} -> - seq_expect1(MatchRest,Patterns,[Match|Acc],Rest,EO); + seq_expect1(Name,Pid,MatchRest,Patterns,[Match|Acc],Rest,EO); {nomatch,prompt} -> - seq_expect(Rest,[Pattern|Patterns],Acc,EO); + seq_expect(Name,Pid,Rest,[Pattern|Patterns],Acc,EO); {nomatch,NoMatchRest} when Rest==[] -> %% The data did not end with a prompt {continue,[Pattern|Patterns],Acc,NoMatchRest}; {halt,Why,HaltRest} -> {halt,Why,HaltRest++Rest} end; -seq_expect1(Data,[],Acc,Rest,_EO) -> +seq_expect1(_Name,_Pid,Data,[],Acc,Rest,_EO) -> {match,lists:reverse(Acc),Data++Rest}. %% Split prompt-chunk at lines -match_lines(Data,Patterns,EO) -> +match_lines(Name,Pid,Data,Patterns,EO) -> FoundPrompt = EO#eo.found_prompt, case one_line(Data,[]) of {noline,Rest} when FoundPrompt=/=false -> %% This is the line including the prompt - case match_line(Rest,Patterns,FoundPrompt,EO) of + case match_line(Name,Pid,Rest,Patterns,FoundPrompt,EO) of nomatch -> {nomatch,prompt}; {Tag,Match} -> {Tag,Match,[]} end; {noline,Rest} when EO#eo.prompt_check==false -> - case match_line(Rest,Patterns,false,EO) of + case match_line(Name,Pid,Rest,Patterns,false,EO) of nomatch -> {nomatch,Rest}; {Tag,Match} -> @@ -1049,9 +1193,9 @@ match_lines(Data,Patterns,EO) -> {noline,Rest} -> {nomatch,Rest}; {Line,Rest} -> - case match_line(Line,Patterns,false,EO) of + case match_line(Name,Pid,Line,Patterns,false,EO) of nomatch -> - match_lines(Rest,Patterns,EO); + match_lines(Name,Pid,Rest,Patterns,EO); {Tag,Match} -> {Tag,Match,Rest} end @@ -1059,43 +1203,43 @@ match_lines(Data,Patterns,EO) -> %% For one line, match each pattern -match_line(Line,Patterns,FoundPrompt,EO) -> - match_line(Line,Patterns,FoundPrompt,EO,match). - -match_line(Line,[prompt|Patterns],false,EO,RetTag) -> - match_line(Line,Patterns,false,EO,RetTag); -match_line(Line,[prompt|_Patterns],FoundPrompt,_EO,RetTag) -> - try_cont_log(" ~ts", [Line]), - try_cont_log("<b>PROMPT:</b> ~ts", [FoundPrompt]), +match_line(Name,Pid,Line,Patterns,FoundPrompt,EO) -> + match_line(Name,Pid,Line,Patterns,FoundPrompt,EO,match). + +match_line(Name,Pid,Line,[prompt|Patterns],false,EO,RetTag) -> + match_line(Name,Pid,Line,Patterns,false,EO,RetTag); +match_line(Name,Pid,Line,[prompt|_Patterns],FoundPrompt,_EO,RetTag) -> + log(name_or_pid(Name,Pid)," ~ts",[Line]), + log(name_or_pid(Name,Pid),"PROMPT: ~ts",[FoundPrompt]), {RetTag,{prompt,FoundPrompt}}; -match_line(Line,[{prompt,PromptType}|_Patterns],FoundPrompt,_EO,RetTag) +match_line(Name,Pid,Line,[{prompt,PromptType}|_Patterns],FoundPrompt,_EO,RetTag) when PromptType==FoundPrompt -> - try_cont_log(" ~ts", [Line]), - try_cont_log("<b>PROMPT:</b> ~ts", [FoundPrompt]), + log(name_or_pid(Name,Pid)," ~ts",[Line]), + log(name_or_pid(Name,Pid),"PROMPT: ~ts",[FoundPrompt]), {RetTag,{prompt,FoundPrompt}}; -match_line(Line,[{prompt,PromptType}|Patterns],FoundPrompt,EO,RetTag) +match_line(Name,Pid,Line,[{prompt,PromptType}|Patterns],FoundPrompt,EO,RetTag) when PromptType=/=FoundPrompt -> - match_line(Line,Patterns,FoundPrompt,EO,RetTag); -match_line(Line,[{Tag,Pattern}|Patterns],FoundPrompt,EO,RetTag) -> + match_line(Name,Pid,Line,Patterns,FoundPrompt,EO,RetTag); +match_line(Name,Pid,Line,[{Tag,Pattern}|Patterns],FoundPrompt,EO,RetTag) -> case re:run(Line,Pattern,[{capture,all,list}]) of nomatch -> - match_line(Line,Patterns,FoundPrompt,EO,RetTag); + match_line(Name,Pid,Line,Patterns,FoundPrompt,EO,RetTag); {match,Match} -> - try_cont_log("<b>MATCH:</b> ~ts", [Line]), + log(name_or_pid(Name,Pid),"MATCH: ~ts",[Line]), {RetTag,{Tag,Match}} end; -match_line(Line,[Pattern|Patterns],FoundPrompt,EO,RetTag) -> +match_line(Name,Pid,Line,[Pattern|Patterns],FoundPrompt,EO,RetTag) -> case re:run(Line,Pattern,[{capture,all,list}]) of nomatch -> - match_line(Line,Patterns,FoundPrompt,EO,RetTag); + match_line(Name,Pid,Line,Patterns,FoundPrompt,EO,RetTag); {match,Match} -> - try_cont_log("<b>MATCH:</b> ~ts", [Line]), + log(name_or_pid(Name,Pid),"MATCH: ~ts",[Line]), {RetTag,Match} end; -match_line(Line,[],FoundPrompt,EO,match) -> - match_line(Line,EO#eo.haltpatterns,FoundPrompt,EO,halt); -match_line(Line,[],_FoundPrompt,_EO,halt) -> - try_cont_log(" ~ts", [Line]), +match_line(Name,Pid,Line,[],FoundPrompt,EO,match) -> + match_line(Name,Pid,Line,EO#eo.haltpatterns,FoundPrompt,EO,halt); +match_line(Name,Pid,Line,[],_FoundPrompt,_EO,halt) -> + log(name_or_pid(Name,Pid)," ~ts",[Line]), nomatch. one_line([$\n|Rest],Line) -> @@ -1111,26 +1255,29 @@ one_line([],Line) -> debug_log_lines(String) -> Old = put(silent,true), - log_lines(String), + log_lines(undefined,undefined,String), put(silent,Old). -log_lines(String) -> - case log_lines_not_last(String) of +log_lines(Name,Pid,String) -> + case log_lines_not_last(Name,Pid,String) of [] -> ok; LastLine -> - try_cont_log(" ~ts", [LastLine]) + log(name_or_pid(Name,Pid)," ~ts",[LastLine]) end. -log_lines_not_last(String) -> +log_lines_not_last(Name,Pid,String) -> case add_tabs(String,[],[]) of {[],LastLine} -> LastLine; {String1,LastLine} -> - try_cont_log("~ts",[String1]), + log(name_or_pid(Name,Pid),"~ts",[String1]), LastLine end. +name_or_pid(undefined,Pid) -> Pid; +name_or_pid(Name,_) -> Name. + add_tabs([0|Rest],Acc,LastLine) -> add_tabs(Rest,Acc,LastLine); add_tabs([$\r|Rest],Acc,LastLine) -> @@ -1145,8 +1292,6 @@ add_tabs([],[],LastLine) -> {[],lists:reverse(LastLine)}. - - %%% @hidden teln_receive_until_prompt(Pid,Prx,Timeout) -> Fun = fun() -> teln_receive_until_prompt(Pid,Prx,[],[]) end, diff --git a/lib/common_test/src/ct_util.erl b/lib/common_test/src/ct_util.erl index 68e76c2396..f5eb3a72f0 100644 --- a/lib/common_test/src/ct_util.erl +++ b/lib/common_test/src/ct_util.erl @@ -77,6 +77,8 @@ -record(suite_data, {key,name,value}). %%%----------------------------------------------------------------- +start() -> + start(normal, ".", ?default_verbosity). %%% @spec start(Mode) -> Pid | exit(Error) %%% Mode = normal | interactive %%% Pid = pid() @@ -91,9 +93,6 @@ %%% <code>ct_util_server</code>.</p> %%% %%% @see ct -start() -> - start(normal, ".", ?default_verbosity). - start(LogDir) when is_list(LogDir) -> start(normal, LogDir, ?default_verbosity); start(Mode) -> @@ -187,6 +186,7 @@ do_start(Parent, Mode, LogDir, Verbosity) -> false -> ok end, + {StartTime,TestLogDir} = ct_logs:init(Mode, Verbosity), ct_event:notify(#event{name=test_start, @@ -198,12 +198,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, @@ -286,14 +300,23 @@ get_start_dir() -> %% handle verbosity outside ct_util_server (let the client read %% the verbosity table) to avoid possible deadlock situations set_verbosity(Elem = {_Category,_Level}) -> - ets:insert(?verbosity_table, Elem), - ok. + try ets:insert(?verbosity_table, Elem) of + _ -> + ok + catch + _:Reason -> + {error,Reason} + end. + get_verbosity(Category) -> - case ets:lookup(?verbosity_table, Category) of + try ets:lookup(?verbosity_table, Category) of [{Category,Level}] -> Level; _ -> undefined + catch + _:Reason -> + {error,Reason} end. loop(Mode,TestData,StartDir) -> @@ -358,9 +381,18 @@ loop(Mode,TestData,StartDir) -> TestData1 = case lists:keysearch(Key,1,TestData) of {value,{Key,Val}} -> - NewVal = Fun(Val), - return(From,NewVal), - [{Key,NewVal}|lists:keydelete(Key,1,TestData)]; + try Fun(Val) of + '$delete' -> + return(From,deleted), + lists:keydelete(Key,1,TestData); + NewVal -> + return(From,NewVal), + [{Key,NewVal}|lists:keydelete(Key,1,TestData)] + catch + _:Error -> + return(From,{error,Error}), + TestData + end; _ -> case lists:member(create,Opts) of true -> @@ -383,19 +415,38 @@ loop(Mode,TestData,StartDir) -> return(From,StartDir), loop(From,TestData,StartDir); {{stop,Info},From} -> + test_server_io:reset_state(), + {MiscIoName,MiscIoDivider,MiscIoFooter} = + proplists:get_value(misc_io_log,TestData), + {ok,MiscIoFd} = file:open(MiscIoName, + [append,{encoding,utf8}]), + io:put_chars(MiscIoFd, MiscIoDivider), + test_server_io:set_fd(unexpected_io, MiscIoFd), + Time = calendar:local_time(), 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), ets:delete(?board_table), ets:delete(?suite_table), ets:delete(?verbosity_table), + + io:put_chars(MiscIoFd, "\n</pre>\n"++MiscIoFooter), + test_server_io:stop([unexpected_io]), + test_server_io:finish(), + ct_logs:close(Info, StartDir), ct_event:stop(), ct_config:stop(), @@ -670,8 +721,14 @@ reset_silent_connections() -> %%% @see ct stop(Info) -> case whereis(ct_util_server) of - undefined -> ok; - _ -> call({stop,Info}) + undefined -> + ok; + CtUtilPid -> + Ref = monitor(process, CtUtilPid), + call({stop,Info}), + receive + {'DOWN',Ref,_,_,_} -> ok + end end. %%%----------------------------------------------------------------- diff --git a/lib/common_test/src/ct_util.hrl b/lib/common_test/src/ct_util.hrl index 7c01e17c36..a82d58cc42 100644 --- a/lib/common_test/src/ct_util.hrl +++ b/lib/common_test/src/ct_util.hrl @@ -79,4 +79,10 @@ -define(tablesorter_script, "jquery.tablesorter.min.js"). %% Logging information for error handler --record(conn_log, {client, name, address, action, module}). +-record(conn_log, {header=true, + client, + name, + address, + conn_pid, + action, + module}). diff --git a/lib/common_test/src/cth_conn_log.erl b/lib/common_test/src/cth_conn_log.erl index 644594e34d..a731c8054c 100644 --- a/lib/common_test/src/cth_conn_log.erl +++ b/lib/common_test/src/cth_conn_log.erl @@ -56,11 +56,29 @@ pre_init_per_testcase/3, post_end_per_testcase/4]). +%%---------------------------------------------------------------------- +%% Exported types +%%---------------------------------------------------------------------- +-export_type([hook_options/0, + log_type/0, + conn_mod/0]). + +%%---------------------------------------------------------------------- +%% Type declarations +%%---------------------------------------------------------------------- +-type hook_options() :: [hook_option()]. +%% Options that can be given to `cth_conn_log' in the `ct_hook' statement. +-type hook_option() :: {log_type,log_type()} | + {hosts,[ct_gen_conn:key_or_name()]}. +-type log_type() :: raw | pretty | html | silent. +-type conn_mod() :: ct_netconfc | ct_telnet. +%%---------------------------------------------------------------------- + -spec init(Id, HookOpts) -> Result when Id :: term(), - HookOpts :: ct_netconfc:hook_options(), - Result :: {ok,[{ct_netconfc:conn_mod(), - {ct_netconfc:log_type(),[ct_netconfc:key_or_name()]}}]}. + HookOpts :: hook_options(), + Result :: {ok,[{conn_mod(), + {log_type(),[ct_gen_conn:key_or_name()]}}]}. init(_Id, HookOpts) -> ConfOpts = ct:get_config(ct_conn_log,[]), {ok,merge_log_info(ConfOpts,HookOpts)}. @@ -86,7 +104,8 @@ get_log_opts(Opts) -> pre_init_per_testcase(TestCase,Config,CthState) -> Logs = lists:map( - fun({ConnMod,{LogType,Hosts}}) -> + fun({ConnMod,{LogType,Hosts}}) -> + ct_util:set_testdata({{?MODULE,ConnMod},LogType}), case LogType of LogType when LogType==raw; LogType==pretty -> Dir = ?config(priv_dir,Config), @@ -117,9 +136,44 @@ pre_init_per_testcase(TestCase,Config,CthState) -> end end, CthState), - error_logger:add_report_handler(ct_conn_log_h,{group_leader(),Logs}), + + GL = group_leader(), + Update = + fun(Init) when Init == undefined; Init == [] -> + error_logger:add_report_handler(ct_conn_log_h,{GL,Logs}), + [TestCase]; + (PrevUsers) -> + error_logger:info_report(update,{GL,Logs}), + receive + {updated,GL} -> + [TestCase|PrevUsers] + after + 5000 -> + {error,no_response} + end + end, + ct_util:update_testdata(?MODULE, Update, [create]), {Config,CthState}. -post_end_per_testcase(_TestCase,_Config,Return,CthState) -> - error_logger:delete_report_handler(ct_conn_log_h), +post_end_per_testcase(TestCase,_Config,Return,CthState) -> + Update = + fun(PrevUsers) -> + case lists:delete(TestCase, PrevUsers) of + [] -> + '$delete'; + PrevUsers1 -> + PrevUsers1 + end + end, + case ct_util:update_testdata(?MODULE, Update) of + deleted -> + [ct_util:delete_testdata({?MODULE,ConnMod}) || + {ConnMod,_} <- CthState], + error_logger:delete_report_handler(ct_conn_log_h); + {error,no_response} -> + exit({?MODULE,no_response_from_logger}); + _PrevUsers -> + ok + end, {Return,CthState}. + diff --git a/lib/common_test/src/cth_log_redirect.erl b/lib/common_test/src/cth_log_redirect.erl index 958b7a94c7..61700a2032 100644 --- a/lib/common_test/src/cth_log_redirect.erl +++ b/lib/common_test/src/cth_log_redirect.erl @@ -25,16 +25,31 @@ %% CTH Callbacks --export([id/1, init/2, post_init_per_group/4, pre_end_per_group/3, - post_end_per_testcase/4]). +-export([id/1, init/2, + pre_init_per_suite/3, pre_end_per_suite/3, post_end_per_suite/4, + pre_init_per_group/3, post_init_per_group/4, + pre_end_per_group/3, post_end_per_group/4, + pre_init_per_testcase/3, post_end_per_testcase/4]). %% Event handler Callbacks -export([init/1, handle_event/2, handle_call/2, handle_info/2, - terminate/1]). + terminate/1, terminate/2, code_change/3]). + +%% Other +-export([handle_remote_events/1]). -include("ct.hrl"). +-behaviour(gen_event). + +-record(eh_state, {log_func, + curr_suite, + curr_group, + curr_func, + parallel_tcs = false, + handle_remote_events = false}). + id(_Opts) -> ?MODULE. @@ -42,36 +57,62 @@ init(?MODULE, _Opts) -> error_logger:add_report_handler(?MODULE), tc_log_async. -post_init_per_group(Group, Config, Result, tc_log_async) -> +pre_init_per_suite(Suite, Config, State) -> + set_curr_func({Suite,init_per_suite}, Config), + {Config, State}. + +pre_end_per_suite(Suite, Config, State) -> + set_curr_func({Suite,end_per_suite}, Config), + {Config, State}. + +post_end_per_suite(_Suite, Config, Return, State) -> + set_curr_func(undefined, Config), + {Return, State}. + +pre_init_per_group(Group, Config, State) -> + set_curr_func({group,Group,init_per_group}, Config), + {Config, State}. + +post_init_per_group(Group, Config, Result, tc_log_async) when is_list(Config) -> case lists:member(parallel,proplists:get_value( tc_group_properties,Config,[])) of true -> - {Result, {set_log_func(ct_log),Group}}; + {Result, {set_log_func(tc_log),Group}}; false -> {Result, tc_log_async} end; post_init_per_group(_Group, _Config, Result, State) -> {Result, State}. +pre_init_per_testcase(TC, Config, State) -> + set_curr_func(TC, Config), + {Config, State}. + post_end_per_testcase(_TC, _Config, Result, State) -> %% Make sure that the event queue is flushed %% before ending this test case. gen_event:call(error_logger, ?MODULE, flush, 300000), {Result, State}. -pre_end_per_group(Group, Config, {ct_log, Group}) -> +pre_end_per_group(Group, Config, {tc_log, Group}) -> + set_curr_func({group,Group,end_per_group}, Config), {Config, set_log_func(tc_log_async)}; -pre_end_per_group(_Group, Config, State) -> +pre_end_per_group(Group, Config, State) -> + set_curr_func({group,Group,end_per_group}, Config), {Config, State}. +post_end_per_group(_Group, Config, Return, State) -> + set_curr_func({group,undefined}, Config), + {Return, State}. %% Copied and modified from sasl_report_tty_h.erl init(_Type) -> - {ok, tc_log_async}. + {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, LogFunc) -> +handle_event(Event, #eh_state{log_func = LogFunc} = State) -> case lists:keyfind(sasl, 1, application:which_applications()) of false -> sasl_not_started; @@ -80,7 +121,8 @@ handle_event(Event, LogFunc) -> SReport = sasl_report:format_report(group_leader(), ErrLogType, tag_event(Event)), if is_list(SReport) -> - ct_logs:LogFunc(sasl, ?STD_IMPORTANCE, "System", SReport, []); + SaslHeader = format_header(State), + ct_logs:LogFunc(sasl, ?STD_IMPORTANCE, SaslHeader, SReport, []); true -> %% Report is an atom if no logging is to be done ignore end @@ -88,27 +130,122 @@ handle_event(Event, LogFunc) -> EReport = error_logger_tty_h:write_event( tag_event(Event),io_lib), if is_list(EReport) -> - ct_logs:LogFunc(error_logger, ?STD_IMPORTANCE, "System", EReport, []); + ErrHeader = format_header(State), + ct_logs:LogFunc(error_logger, ?STD_IMPORTANCE, ErrHeader, EReport, []); true -> %% Report is an atom if no logging is to be done ignore end, - {ok, LogFunc}. - + {ok, State}. + +handle_info({'EXIT',User,killed}, State) -> + case whereis(user) of + %% init:stop/1/2 has been called, let's finish! + undefined -> + remove_handler; + User -> + remove_handler; + _ -> + {ok,State} + end; -handle_info(_,State) -> {ok, State}. +handle_info(_, State) -> + {ok,State}. handle_call(flush,State) -> {ok, ok, State}; -handle_call({set_logfunc,NewLogFunc},_) -> - {ok, NewLogFunc, NewLogFunc}; -handle_call(_Query, _State) -> {error, bad_query}. -terminate(_State) -> +handle_call({set_curr_func,{group,Group,Conf},Config}, + State) when is_list(Config) -> + Parallel = case proplists:get_value(tc_group_properties, Config) of + undefined -> false; + Props -> lists:member(parallel, Props) + end, + {ok, ok, State#eh_state{curr_group = Group, + curr_func = Conf, + parallel_tcs = Parallel}}; +handle_call({set_curr_func,{group,Group,Conf},_SkipOrFail}, State) -> + {ok, ok, State#eh_state{curr_group = Group, + curr_func = Conf, + parallel_tcs = false}}; +handle_call({set_curr_func,{group,undefined},_Config}, State) -> + {ok, ok, State#eh_state{curr_group = undefined, + curr_func = undefined, + parallel_tcs = false}}; +handle_call({set_curr_func,{Suite,Conf},_Config}, State) -> + {ok, ok, State#eh_state{curr_suite = Suite, + curr_func = Conf, + parallel_tcs = false}}; +handle_call({set_curr_func,undefined,_Config}, State) -> + {ok, ok, State#eh_state{curr_suite = undefined, + curr_func = undefined, + parallel_tcs = false}}; +handle_call({set_curr_func,TC,_Config}, State) -> + {ok, ok, State#eh_state{curr_func = TC}}; + +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}. + +terminate(_) -> error_logger:delete_report_handler(?MODULE), []. +terminate(_Arg, _State) -> + ok. + tag_event(Event) -> {calendar:local_time(), Event}. +set_curr_func(CurrFunc, Config) -> + gen_event:call(error_logger, ?MODULE, {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}) -> + io_lib:format("System report during ~w", [Suite]); + +format_header(#eh_state{curr_suite = Suite, + curr_group = undefined, + curr_func = TcOrConf}) -> + io_lib:format("System report during ~w:~w/1", + [Suite,TcOrConf]); + +format_header(#eh_state{curr_suite = Suite, + curr_group = Group, + curr_func = Conf}) when Conf == init_per_group; + Conf == end_per_group -> + io_lib:format("System report during ~w:~w/2 for ~w", + [Suite,Conf,Group]); + +format_header(#eh_state{curr_suite = Suite, + curr_group = Group, + parallel_tcs = true}) -> + io_lib:format("System report during ~w in ~w", + [Group,Suite]); + +format_header(#eh_state{curr_suite = Suite, + curr_group = Group, + curr_func = TC}) -> + io_lib:format("System report during ~w:~w/1 in ~w", + [Suite,TC,Group]). + +code_change(_OldVsn, State, _Extra) -> + {ok, State}. diff --git a/lib/common_test/src/cth_surefire.erl b/lib/common_test/src/cth_surefire.erl index 1a38b6584b..7ed2018bdf 100644 --- a/lib/common_test/src/cth_surefire.erl +++ b/lib/common_test/src/cth_surefire.erl @@ -138,6 +138,9 @@ on_tc_fail(_TC, Res, State) -> {fail,lists:flatten(io_lib:format("~p",[Res]))} }, State#state{ test_cases = [NewTC | tl(TCs)]}. +on_tc_skip({ConfigFunc,_GrName},{Type,_Reason} = Res, State0) + when Type == tc_auto_skip; Type == tc_user_skip -> + on_tc_skip(ConfigFunc, Res, State0); on_tc_skip(Tc,{Type,_Reason} = Res, State0) when Type == tc_auto_skip -> TcStr = atom_to_list(Tc), State = @@ -330,5 +333,7 @@ count_tcs([#testcase{result={fail,_}}|TCs],Ok,F,S) -> count_tcs(TCs,Ok,F+1,S); count_tcs([#testcase{result={skipped,_}}|TCs],Ok,F,S) -> count_tcs(TCs,Ok,F,S+1); +count_tcs([#testcase{result={auto_skipped,_}}|TCs],Ok,F,S) -> + count_tcs(TCs,Ok,F,S+1); count_tcs([],Ok,F,S) -> {Ok+F+S,F,S}. diff --git a/lib/common_test/src/unix_telnet.erl b/lib/common_test/src/unix_telnet.erl index 88199b07d0..e049c3bf39 100644 --- a/lib/common_test/src/unix_telnet.erl +++ b/lib/common_test/src/unix_telnet.erl @@ -54,8 +54,8 @@ -compile(export_all). %% Callbacks for ct_telnet.erl --export([connect/5,get_prompt_regexp/0]). --import(ct_telnet,[start_log/1,cont_log/2,end_log/0]). +-export([connect/6,get_prompt_regexp/0]). +-import(ct_telnet,[start_gen_log/1,log/4,end_gen_log/0]). -define(username,"login: "). -define(password,"Password: "). @@ -76,7 +76,9 @@ get_prompt_regexp() -> %%%----------------------------------------------------------------- %%% @hidden -%%% @spec connect(Ip,Port,Timeout,KeepAlive,Extra) -> {ok,Handle} | {error,Reason} +%%% @spec connect(ConnName,Ip,Port,Timeout,KeepAlive,Extra) -> +%%% {ok,Handle} | {error,Reason} +%%% ConnName = ct:target_name() %%% Ip = string() | {integer(),integer(),integer(),integer()} %%% Port = integer() %%% Timeout = integer() @@ -89,59 +91,70 @@ get_prompt_regexp() -> %%% @doc Callback for ct_telnet.erl. %%% %%% <p>Setup telnet connection to a UNIX host.</p> -connect(Ip,Port,Timeout,KeepAlive,Extra) -> +connect(ConnName,Ip,Port,Timeout,KeepAlive,Extra) -> case Extra of {Username,Password} -> - connect1(Ip,Port,Timeout,KeepAlive,Username,Password); - Name -> - case get_username_and_password(Name) of + connect1(ConnName,Ip,Port,Timeout,KeepAlive, + Username,Password); + KeyOrName -> + case get_username_and_password(KeyOrName) of {ok,{Username,Password}} -> - connect1(Ip,Port,Timeout,KeepAlive,Username,Password); + connect1(ConnName,Ip,Port,Timeout,KeepAlive, + Username,Password); Error -> Error end end. -connect1(Ip,Port,Timeout,KeepAlive,Username,Password) -> - start_log("unix_telnet:connect"), +connect1(Name,Ip,Port,Timeout,KeepAlive,Username,Password) -> + start_gen_log("unix_telnet connect"), Result = case ct_telnet_client:open(Ip,Port,Timeout,KeepAlive) of {ok,Pid} -> - case ct_telnet:silent_teln_expect(Pid,[],[prompt],?prx,[]) of + case ct_telnet:silent_teln_expect(Name,Pid,[], + [prompt],?prx,[]) of {ok,{prompt,?username},_} -> + log(Name,send,"Logging in to ~p:~p", [Ip,Port]), ok = ct_telnet_client:send_data(Pid,Username), - cont_log("Username: ~ts",[Username]), - case ct_telnet:silent_teln_expect(Pid,[],prompt,?prx,[]) of + log(Name,send,"Username: ~ts",[Username]), + case ct_telnet:silent_teln_expect(Name,Pid,[], + prompt,?prx,[]) of {ok,{prompt,?password},_} -> ok = ct_telnet_client:send_data(Pid,Password), Stars = lists:duplicate(length(Password),$*), - cont_log("Password: ~s",[Stars]), + log(Name,send,"Password: ~s",[Stars]), ok = ct_telnet_client:send_data(Pid,""), - case ct_telnet:silent_teln_expect(Pid,[],prompt, + case ct_telnet:silent_teln_expect(Name,Pid,[], + prompt, ?prx,[]) of {ok,{prompt,Prompt},_} - when Prompt=/=?username, Prompt=/=?password -> + when Prompt=/=?username, + Prompt=/=?password -> {ok,Pid}; Error -> - cont_log("Password failed\n~p\n", - [Error]), + log(Name,recv,"Password failed\n~p\n", + [Error]), {error,Error} end; Error -> - cont_log("Login failed\n~p\n",[Error]), + log(Name,recv,"Login to ~p:~p failed\n~p\n",[Ip,Port,Error]), {error,Error} end; {ok,[{prompt,_OtherPrompt1},{prompt,_OtherPrompt2}],_} -> {ok,Pid}; Error -> - cont_log("Did not get expected prompt\n~p\n",[Error]), + log(Name,error, + "Did not get expected prompt from ~p:~p\n~p\n", + [Ip,Port,Error]), {error,Error} end; Error -> - cont_log("Could not open telnet connection\n~p\n",[Error]), + log(Name,error, + "Could not open telnet connection to ~p:~p\n~p\n", + [Ip,Port,Error]), Error end, - end_log(), + end_gen_log(), Result. get_username_and_password(Name) -> |