diff options
Diffstat (limited to 'lib/common_test/src/ct_logs.erl')
| -rw-r--r-- | lib/common_test/src/ct_logs.erl | 278 |
1 files changed, 180 insertions, 98 deletions
diff --git a/lib/common_test/src/ct_logs.erl b/lib/common_test/src/ct_logs.erl index 19ad7b26d8..0cd9b5f7cb 100644 --- a/lib/common_test/src/ct_logs.erl +++ b/lib/common_test/src/ct_logs.erl @@ -38,7 +38,7 @@ -export([get_ts_html_wrapper/3]). %% Logging stuff directly from testcase --export([tc_log/3,tc_print/3,tc_pal/3,ct_log/3, +-export([tc_log/3,tc_log/4,tc_log_async/3,tc_print/3,tc_pal/3,ct_log/3, basic_html/0]). %% Simulate logger process for use without ct environment running @@ -239,7 +239,7 @@ end_tc(TCPid) -> %%% activity it is. <code>Format</code> and <code>Args</code> is the %%% data to log (as in <code>io:format(Format,Args)</code>).</p> log(Heading,Format,Args) -> - cast({log,self(),group_leader(), + cast({log,sync,self(),group_leader(), [{int_header(),[log_timestamp(now()),Heading]}, {Format,Args}, {int_footer(),[]}]}), @@ -261,7 +261,7 @@ log(Heading,Format,Args) -> %%% @see cont_log/2 %%% @see end_log/0 start_log(Heading) -> - cast({log,self(),group_leader(), + cast({log,sync,self(),group_leader(), [{int_header(),[log_timestamp(now()),Heading]}]}), ok. @@ -276,7 +276,7 @@ cont_log([],[]) -> ok; cont_log(Format,Args) -> maybe_log_timestamp(), - cast({log,self(),group_leader(),[{Format,Args}]}), + cast({log,sync,self(),group_leader(),[{Format,Args}]}), ok. %%%----------------------------------------------------------------- @@ -287,7 +287,7 @@ cont_log(Format,Args) -> %%% @see start_log/1 %%% @see cont_log/2 end_log() -> - cast({log,self(),group_leader(),[{int_footer(), []}]}), + cast({log,sync,self(),group_leader(),[{int_footer(), []}]}), ok. @@ -333,9 +333,32 @@ add_link(Heading,File,Type) -> %%% stuff directly from a testcase (i.e. not from within the CT %%% framework).</p> tc_log(Category,Format,Args) -> - cast({log,self(),group_leader(),[{div_header(Category),[]}, - {Format,Args}, - {div_footer(),[]}]}), + tc_log(Category,"User",Format,Args). + +tc_log(Category,Printer,Format,Args) -> + cast({log,sync,self(),group_leader(),[{div_header(Category,Printer),[]}, + {Format,Args}, + {div_footer(),[]}]}), + ok. + + +%%%----------------------------------------------------------------- +%%% @spec tc_log_async(Category,Format,Args) -> ok +%%% Category = atom() +%%% Format = string() +%%% Args = list() +%%% +%%% @doc Internal use only. +%%% +%%% <p>This function is used to perform asynchronous printouts +%%% towards the test server IO handler. This is necessary in order +%%% to avoid deadlocks when e.g. the hook that handles SASL printouts +%%% prints to the test case log file at the same time test server +%%% asks ct_logs for an html wrapper.</p> +tc_log_async(Category,Format,Args) -> + cast({log,async,self(),group_leader(),[{div_header(Category),[]}, + {Format,Args}, + {div_footer(),[]}]}), ok. %%%----------------------------------------------------------------- @@ -349,19 +372,18 @@ tc_log(Category,Format,Args) -> %%% <p>This function is called by <code>ct</code> when printing %%% stuff a testcase on the user console.</p> tc_print(Category,Format,Args) -> - print_heading(Category), - io:format(user,Format,Args), - io:format(user,"\n\n",[]), + Head = get_heading(Category), + io:format(user, lists:concat([Head,Format,"\n\n"]), Args), ok. -print_heading(default) -> - io:format(user, - "----------------------------------------------------\n~s\n", - [log_timestamp(now())]); -print_heading(Category) -> - io:format(user, - "----------------------------------------------------\n~s ~w\n", - [log_timestamp(now()),Category]). +get_heading(default) -> + io_lib:format("-----------------------------" + "-----------------------\n~s\n", + [log_timestamp(now())]); +get_heading(Category) -> + io_lib:format("-----------------------------" + "-----------------------\n~s ~w\n", + [log_timestamp(now()),Category]). %%%----------------------------------------------------------------- @@ -377,9 +399,9 @@ print_heading(Category) -> %%% log and on the console.</p> tc_pal(Category,Format,Args) -> tc_print(Category,Format,Args), - cast({log,self(),group_leader(),[{div_header(Category),[]}, - {Format,Args}, - {div_footer(),[]}]}), + cast({log,sync,self(),group_leader(),[{div_header(Category),[]}, + {Format,Args}, + {div_footer(),[]}]}), ok. @@ -408,8 +430,10 @@ int_footer() -> "</div>". div_header(Class) -> - "<div class=\"" ++ atom_to_list(Class) ++ "\"><b>*** User " ++ - log_timestamp(now()) ++ " ***</b>". + div_header(Class,"User"). +div_header(Class,Printer) -> + "<div class=\"" ++ atom_to_list(Class) ++ "\"><b>*** " ++ Printer ++ + " " ++ log_timestamp(now()) ++ " ***</b>". div_footer() -> "</div>". @@ -420,7 +444,7 @@ maybe_log_timestamp() -> {MS,S,_} -> ok; _ -> - cast({log,self(),group_leader(), + cast({log,sync,self(),group_leader(), [{"<i>~s</i>",[log_timestamp({MS,S,US})]}]}) end. @@ -441,7 +465,8 @@ log_timestamp({MS,S,US}) -> orig_GL, ct_log_fd, tc_groupleaders, - stylesheet}). + stylesheet, + async_print_jobs}). logger(Parent,Mode) -> register(?MODULE,self()), @@ -520,50 +545,32 @@ logger(Parent,Mode) -> start_time=Time, orig_GL=group_leader(), ct_log_fd=CtLogFd, - tc_groupleaders=[]}). + tc_groupleaders=[], + async_print_jobs=[]}). logger_loop(State) -> receive - {log,Pid,GL,List} -> - case get_groupleader(Pid,GL,State) of + {log,SyncOrAsync,Pid,GL,List} -> + case get_groupleader(Pid, GL, State) of {tc_log,TCGL,TCGLs} -> case erlang:is_process_alive(TCGL) of true -> - %% we have to build one io-list of all strings - %% before printing, or other io printouts (made in - %% parallel) may get printed between this header - %% and footer - Fun = - fun({Str,Args},IoList) -> - case catch io_lib:format(Str,Args) of - {'EXIT',_Reason} -> - Fd = State#logger_state.ct_log_fd, - io:format(Fd, - "Logging fails! " - "Str: ~p, Args: ~p~n", - [Str,Args]), - %% stop the testcase, we need - %% to see the fault - exit(Pid,{log_printout_error,Str,Args}), - []; - IoStr when IoList == [] -> - [IoStr]; - IoStr -> - [IoList,"\n",IoStr] - end - end, - io:format(TCGL,"~s",[lists:foldl(Fun,[],List)]), - logger_loop(State#logger_state{tc_groupleaders=TCGLs}); + State1 = print_to_log(SyncOrAsync, Pid, TCGL, + List, State), + logger_loop(State1#logger_state{tc_groupleaders = + TCGLs}); false -> - %% Group leader is dead, so write to the CtLog instead + %% Group leader is dead, so write to the + %% CtLog instead Fd = State#logger_state.ct_log_fd, [begin io:format(Fd,Str,Args),io:nl(Fd) end || {Str,Args} <- List], logger_loop(State) end; {ct_log,Fd,TCGLs} -> - [begin io:format(Fd,Str,Args),io:nl(Fd) end || {Str,Args} <- List], - logger_loop(State#logger_state{tc_groupleaders=TCGLs}) + [begin io:format(Fd,Str,Args),io:nl(Fd) end || + {Str,Args} <- List], + logger_loop(State#logger_state{tc_groupleaders = TCGLs}) end; {{init_tc,TCPid,GL,RefreshLog},From} -> print_style(GL, State#logger_state.stylesheet), @@ -575,11 +582,12 @@ logger_loop(State) -> make_last_run_index(State#logger_state.start_time) end, return(From,ok), - logger_loop(State#logger_state{tc_groupleaders=TCGLs}); + logger_loop(State#logger_state{tc_groupleaders = TCGLs}); {{end_tc,TCPid},From} -> set_evmgr_gl(State#logger_state.ct_log_fd), return(From,ok), - logger_loop(State#logger_state{tc_groupleaders=rm_tc_gl(TCPid,State)}); + logger_loop(State#logger_state{tc_groupleaders = + rm_tc_gl(TCPid,State)}); {{get_log_dir,true},From} -> return(From,{ok,State#logger_state.log_dir}), logger_loop(State); @@ -590,21 +598,35 @@ logger_loop(State) -> make_last_run_index(State#logger_state.start_time), return(From,filename:basename(State#logger_state.log_dir)), logger_loop(State); - {set_stylesheet,_,SSFile} when State#logger_state.stylesheet == SSFile -> + {set_stylesheet,_,SSFile} when State#logger_state.stylesheet == + SSFile -> logger_loop(State); {set_stylesheet,TC,SSFile} -> Fd = State#logger_state.ct_log_fd, - io:format(Fd, "~p loading external style sheet: ~s~n", [TC,SSFile]), - logger_loop(State#logger_state{stylesheet=SSFile}); + io:format(Fd, "~p loading external style sheet: ~s~n", + [TC,SSFile]), + logger_loop(State#logger_state{stylesheet = SSFile}); {clear_stylesheet,_} when State#logger_state.stylesheet == undefined -> logger_loop(State); {clear_stylesheet,_} -> - logger_loop(State#logger_state{stylesheet=undefined}); + logger_loop(State#logger_state{stylesheet = undefined}); {ct_log, List} -> Fd = State#logger_state.ct_log_fd, [begin io:format(Fd,Str,Args),io:nl(Fd) end || {Str,Args} <- List], logger_loop(State); + {'DOWN',Ref,_,_Pid,_} -> + %% there might be print jobs executing in parallel with ct_logs + %% and whenever one is finished (indicated by 'DOWN'), the + %% next job should be spawned + case lists:delete(Ref, State#logger_state.async_print_jobs) of + [] -> + logger_loop(State#logger_state{async_print_jobs = []}); + Jobs -> + [Next|JobsRev] = lists:reverse(Jobs), + Jobs1 = [print_next(Next)|lists:reverse(JobsRev)], + logger_loop(State#logger_state{async_print_jobs = Jobs1}) + end; stop -> io:format(State#logger_state.ct_log_fd, int_header()++int_footer(), @@ -613,6 +635,49 @@ logger_loop(State) -> ok end. +create_io_fun(FromPid, State) -> + %% we have to build one io-list of all strings + %% before printing, or other io printouts (made in + %% parallel) may get printed between this header + %% and footer + Fd = State#logger_state.ct_log_fd, + fun({Str,Args}, IoList) -> + case catch io_lib:format(Str,Args) of + {'EXIT',_Reason} -> + io:format(Fd, "Logging fails! Str: ~p, Args: ~p~n", + [Str,Args]), + %% stop the testcase, we need to see the fault + exit(FromPid, {log_printout_error,Str,Args}), + []; + IoStr when IoList == [] -> + [IoStr]; + IoStr -> + [IoList,"\n",IoStr] + end + end. + +print_to_log(sync, FromPid, TCGL, List, State) -> + IoFun = create_io_fun(FromPid, State), + io:format(TCGL, "~s", [lists:foldl(IoFun, [], List)]), + State; + +print_to_log(async, FromPid, TCGL, List, State) -> + IoFun = create_io_fun(FromPid, State), + Printer = fun() -> + io:format(TCGL, "~s", [lists:foldl(IoFun, [], List)]) + end, + case State#logger_state.async_print_jobs of + [] -> + {_Pid,Ref} = spawn_monitor(Printer), + State#logger_state{async_print_jobs = [Ref]}; + Queue -> + State#logger_state{async_print_jobs = [Printer|Queue]} + end. + +print_next(PrintFun) -> + {_Pid,Ref} = spawn_monitor(PrintFun), + Ref. + %% #logger_state.tc_groupleaders == [{Pid,{Type,GLPid}},...] %% Type = tc | io %% @@ -855,33 +920,48 @@ insert_dir(D,[D1|Ds]) -> insert_dir(D,[]) -> [D]. -make_last_run_index([Name|Rest], Result, TotSucc, TotFail, UserSkip, AutoSkip, - TotNotBuilt, Missing) -> - case last_test(Name) of +make_last_run_index([Name|Rest], Result, TotSucc, TotFail, + UserSkip, AutoSkip, TotNotBuilt, Missing) -> + case get_run_dirs(Name) of false -> %% Silently skip. - make_last_run_index(Rest, Result, TotSucc, TotFail, UserSkip, AutoSkip, - TotNotBuilt, Missing); - LastLogDir -> + make_last_run_index(Rest, Result, TotSucc, TotFail, + UserSkip, AutoSkip, TotNotBuilt, Missing); + LogDirs -> SuiteName = filename:rootname(filename:basename(Name)), - case make_one_index_entry(SuiteName, LastLogDir, "-", false, Missing) of - {Result1,Succ,Fail,USkip,ASkip,NotBuilt} -> - %% for backwards compatibility - AutoSkip1 = case catch AutoSkip+ASkip of - {'EXIT',_} -> undefined; - Res -> Res - end, - make_last_run_index(Rest, [Result|Result1], TotSucc+Succ, - TotFail+Fail, UserSkip+USkip, AutoSkip1, - TotNotBuilt+NotBuilt, Missing); - error -> - make_last_run_index(Rest, Result, TotSucc, TotFail, UserSkip, AutoSkip, - TotNotBuilt, Missing) - end + {Result1,TotSucc1,TotFail1,UserSkip1,AutoSkip1,TotNotBuilt1} = + make_last_run_index1(SuiteName, LogDirs, Result, + TotSucc, TotFail, + UserSkip, AutoSkip, + TotNotBuilt, Missing), + make_last_run_index(Rest, Result1, TotSucc1, TotFail1, + UserSkip1, AutoSkip1, + TotNotBuilt1, Missing) end; + make_last_run_index([], Result, TotSucc, TotFail, UserSkip, AutoSkip, TotNotBuilt, _) -> {ok, [Result|total_row(TotSucc, TotFail, UserSkip, AutoSkip, TotNotBuilt, false)], {TotSucc,TotFail,UserSkip,AutoSkip,TotNotBuilt}}. + +make_last_run_index1(SuiteName, [LogDir | LogDirs], Result, TotSucc, TotFail, + UserSkip, AutoSkip, TotNotBuilt, Missing) -> + case make_one_index_entry(SuiteName, LogDir, "-", false, Missing) of + {Result1,Succ,Fail,USkip,ASkip,NotBuilt} -> + %% for backwards compatibility + AutoSkip1 = case catch AutoSkip+ASkip of + {'EXIT',_} -> undefined; + Res -> Res + end, + make_last_run_index1(SuiteName, LogDirs, [Result|Result1], TotSucc+Succ, + TotFail+Fail, UserSkip+USkip, AutoSkip1, + TotNotBuilt+NotBuilt, Missing); + error -> + make_last_run_index1(SuiteName, LogDirs, Result, TotSucc, TotFail, + UserSkip, AutoSkip, TotNotBuilt, Missing) + end; +make_last_run_index1(_, [], Result, TotSucc, TotFail, + UserSkip, AutoSkip, TotNotBuilt, _) -> + {Result,TotSucc,TotFail,UserSkip,AutoSkip,TotNotBuilt}. make_one_index_entry(SuiteName, LogDir, Label, All, Missing) -> case count_cases(LogDir) of @@ -1633,8 +1713,8 @@ make_all_suites_index(NewTestData = {_TestName,DirName}) -> sort_logdirs([Dir|Dirs],Groups) -> TestName = filename:rootname(filename:basename(Dir)), case filelib:wildcard(filename:join(Dir,"run.*")) of - [RunDir] -> - Groups1 = insert_test(TestName,{filename:basename(RunDir),RunDir},Groups), + RunDirs = [_|_] -> + Groups1 = sort_logdirs1(TestName,RunDirs,Groups), sort_logdirs(Dirs,Groups1); _ -> % ignore missing run directory sort_logdirs(Dirs,Groups) @@ -1642,6 +1722,12 @@ sort_logdirs([Dir|Dirs],Groups) -> sort_logdirs([],Groups) -> lists:keysort(1,sort_each_group(Groups)). +sort_logdirs1(TestName,[RunDir|RunDirs],Groups) -> + Groups1 = insert_test(TestName,{filename:basename(RunDir),RunDir},Groups), + sort_logdirs1(TestName,RunDirs,Groups1); +sort_logdirs1(_,[],Groups) -> + Groups. + insert_test(Test,IxDir,[{Test,IxDirs}|Groups]) -> [{Test,[IxDir|IxDirs]}|Groups]; insert_test(Test,IxDir,[]) -> @@ -1894,7 +1980,7 @@ simulate() -> simulate_logger_loop() -> receive - {log,_,_,List} -> + {log,_,_,_,List} -> S = [[io_lib:format(Str,Args),io_lib:nl()] || {Str,Args} <- List], io:format("~s",[S]), simulate_logger_loop(); @@ -1933,21 +2019,17 @@ notify_and_unlock_file(File) -> end. %%%----------------------------------------------------------------- -%%% @spec last_test(Dir) -> string() | false +%%% @spec get_run_dirs(Dir) -> [string()] | false %%% %%% @doc %%% -last_test(Dir) -> - last_test(filelib:wildcard(filename:join(Dir, "run.[1-2]*")), false). - -last_test([Run|Rest], false) -> - last_test(Rest, Run); -last_test([Run|Rest], Latest) when Run > Latest -> - last_test(Rest, Run); -last_test([_|Rest], Latest) -> - last_test(Rest, Latest); -last_test([], Latest) -> - Latest. +get_run_dirs(Dir) -> + case filelib:wildcard(filename:join(Dir, "run.[1-2]*")) of + [] -> + false; + RunDirs -> + lists:sort(RunDirs) + end. %%%----------------------------------------------------------------- %%% @spec xhtml(HTML, XHTML) -> HTML | XHTML |