diff options
author | Peter Andersson <peppe@erlang.org> | 2013-08-14 23:38:12 +0200 |
---|---|---|
committer | Peter Andersson <peppe@erlang.org> | 2013-09-02 12:14:01 +0200 |
commit | 614ba49d9ff9c75466bc3bba5b25a2e583e09217 (patch) | |
tree | 4a8553c8460e43fb025468ec11f8e5bb0020b790 /lib | |
parent | b1b6087d7f52b4ac88c90b52be7b66f0e894e565 (diff) | |
download | otp-614ba49d9ff9c75466bc3bba5b25a2e583e09217.tar.gz otp-614ba49d9ff9c75466bc3bba5b25a2e583e09217.tar.bz2 otp-614ba49d9ff9c75466bc3bba5b25a2e583e09217.zip |
Introduce pre- and post-test i/o log
Diffstat (limited to 'lib')
-rw-r--r-- | lib/common_test/src/ct_logs.erl | 72 | ||||
-rw-r--r-- | lib/common_test/src/ct_util.erl | 14 | ||||
-rw-r--r-- | lib/test_server/src/test_server_ctrl.erl | 33 | ||||
-rw-r--r-- | lib/test_server/src/test_server_io.erl | 183 |
4 files changed, 238 insertions, 64 deletions
diff --git a/lib/common_test/src/ct_logs.erl b/lib/common_test/src/ct_logs.erl index bd37b690b6..08a7fcb831 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"). @@ -617,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><br><h2>Post-test Log</h2>\n<pre>\n", + "</pre>\n<br /><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), @@ -627,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("")}}, @@ -922,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 @@ -937,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) -> @@ -2856,6 +2896,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 -> @@ -2876,7 +2919,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), @@ -3074,16 +3122,8 @@ unexpected_io(Pid,ct_internal,_Importance,List,State) -> IoFun = create_io_fun(Pid,State), io:format(State#logger_state.ct_log_fd, "~ts", [lists:foldl(IoFun, [], List)]); -unexpected_io(Pid,Category,Importance,List,State) -> +unexpected_io(Pid,_Category,_Importance,List,State) -> IoFun = create_io_fun(Pid,State), Data = io_lib:format("~ts", [lists:foldl(IoFun, [], List)]), - %% if unexpected io comes in during startup or shutdown, test_server - %% might not be running - if so (noproc exit), simply print to - %% stdout instead (will result in double printouts when pal is used) - try test_server_io:print_unexpected(Data) of - _ -> - ok - catch - _:{noproc,_} -> tc_print(Category,Importance,Data,[]); - _:Reason -> exit(Reason) - end. + test_server_io:print_unexpected(Data), + ok. diff --git a/lib/common_test/src/ct_util.erl b/lib/common_test/src/ct_util.erl index abda87c2cd..e039f68121 100644 --- a/lib/common_test/src/ct_util.erl +++ b/lib/common_test/src/ct_util.erl @@ -187,6 +187,7 @@ do_start(Parent, Mode, LogDir, Verbosity) -> false -> ok end, + {StartTime,TestLogDir} = ct_logs:init(Mode, Verbosity), ct_event:notify(#event{name=test_start, @@ -392,6 +393,14 @@ 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(), @@ -405,6 +414,11 @@ loop(Mode,TestData,StartDir) -> 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(), diff --git a/lib/test_server/src/test_server_ctrl.erl b/lib/test_server/src/test_server_ctrl.erl index 4a10684ea5..d0f31af198 100644 --- a/lib/test_server/src/test_server_ctrl.erl +++ b/lib/test_server/src/test_server_ctrl.erl @@ -1171,7 +1171,13 @@ init_tester(Mod, Func, Args, Dir, Name, {_,_,MinLev}=Levels, "<td>~.3fs</td><td><b>~ts</b></td><td>~w Ok, ~w Failed~ts of ~w</td></tr>\n" "</tfoot>\n", [Time,SuccessStr,OkN,FailedN,SkipStr,OkN+FailedN+SkippedN]), - test_server_io:stop([major,html,unexpected_io]). + + test_server_io:stop([major,html,unexpected_io]), + {UnexpectedIoName,UnexpectedIoFooter} = get(test_server_unexpected_footer), + {ok,UnexpectedIoFd} = open_html_file(UnexpectedIoName, [append]), + io:put_chars(UnexpectedIoFd, "\n</pre>\n"++UnexpectedIoFooter), + file:close(UnexpectedIoFd), + ok. report_severe_error(Reason) -> test_server_sup:framework_call(report, [severe_error,Reason]). @@ -1630,15 +1636,13 @@ start_log_file() -> FilenameMode), ok = write_file(?last_file, TestDir1 ++ "\n", FilenameMode), put(test_server_log_dir_base,TestDir1), + MajorName = filename:join(TestDir1, ?suitelog_name), HtmlName = MajorName ++ ?html_ext, UnexpectedName = filename:join(TestDir1, ?unexpected_io_log), + {ok,Major} = open_utf8_file(MajorName), {ok,Html} = open_html_file(HtmlName), - {ok,Unexpected} = open_html_file(UnexpectedName), - test_server_io:set_fd(major, Major), - test_server_io:set_fd(html, Html), - test_server_io:set_fd(unexpected_io, Unexpected), {UnexpHeader,UnexpFooter} = case test_server_sup:framework_call(get_html_wrapper, @@ -1651,8 +1655,17 @@ start_log_file() -> {xhtml,UH,UF} -> {UH,UF} end, - io:put_chars(Unexpected, UnexpHeader++"\n<pre>\n"), - put(test_server_unexpected_footer,UnexpFooter), + + {ok,Unexpected} = open_html_file(UnexpectedName), + io:put_chars(Unexpected, [UnexpHeader, + xhtml("<br>\n<h2>Unexpected I/O</h2>", + "<br />\n<h3>Unexpected I/O</h3>"), + "\n<pre>\n"]), + put(test_server_unexpected_footer,{UnexpectedName,UnexpFooter}), + + test_server_io:set_fd(major, Major), + test_server_io:set_fd(html, Html), + test_server_io:set_fd(unexpected_io, Unexpected), make_html_link(filename:absname(?last_test ++ ?html_ext), HtmlName, filename:basename(Dir)), @@ -5287,6 +5300,9 @@ html_header(Title) -> open_html_file(File) -> open_utf8_file(File). +open_html_file(File,Opts) -> + open_utf8_file(File,Opts). + write_html_file(File,Content) -> write_file(File,Content,utf8). @@ -5295,6 +5311,9 @@ write_html_file(File,Content) -> open_utf8_file(File) -> file:open(File,[write,{encoding,utf8}]). +open_utf8_file(File,Opts) -> + file:open(File,[{encoding,utf8}|Opts]). + %% Write a file with specified encoding write_file(File,Content,latin1) -> file:write_file(File,Content); diff --git a/lib/test_server/src/test_server_io.erl b/lib/test_server/src/test_server_io.erl index 73d4468bda..a92dbf5887 100644 --- a/lib/test_server/src/test_server_io.erl +++ b/lib/test_server/src/test_server_io.erl @@ -32,27 +32,39 @@ -export([start_link/0,stop/1,get_gl/1,set_fd/2, start_transaction/0,end_transaction/0, print_buffered/1,print/3,print_unexpected/1, - set_footer/1,set_job_name/1,set_gl_props/1]). + set_footer/1,set_job_name/1,set_gl_props/1, + reset_state/0,finish/0]). -export([init/1,handle_call/3,handle_info/2,terminate/2]). --record(st, {fds, %Singleton fds (gb_tree) - shared_gl :: pid(), %Shared group leader - gls, %Group leaders (gb_set) - io_buffering=false, %I/O buffering - buffered, %Buffered I/O requests - html_footer, %HTML footer - job_name, %Name of current job. - gl_props, %Properties for GL. - stopping +-record(st, {fds, % Singleton fds (gb_tree) + tags=[], % Known tag types + shared_gl :: pid(), % Shared group leader + gls, % Group leaders (gb_set) + io_buffering=false, % I/O buffering + buffered, % Buffered I/O requests + html_footer, % HTML footer + job_name, % Name of current job. + gl_props, % Properties for GL + phase, % Indicates current mode + offline_buffer, % Buffer I/O during startup + stopping, % Reply to when process stopped + pending_ops % Perform when process idle }). start_link() -> - case gen_server:start_link({local,?MODULE}, ?MODULE, [], []) of - {ok,Pid} -> - {ok,Pid}; - Other -> - Other + case whereis(?MODULE) of + undefined -> + case gen_server:start_link({local,?MODULE}, ?MODULE, [], []) of + {ok,Pid} -> + {ok,Pid}; + Other -> + Other + end; + Pid -> + %% already running, reset the state + reset_state(), + {ok,Pid} end. stop(FilesToClose) -> @@ -62,6 +74,9 @@ stop(FilesToClose) -> group_leader(OldGL, self()), ok. +finish() -> + req(finish). + %% get_gl(Shared) -> Pid %% Shared = boolean() %% Pid = pid() @@ -142,19 +157,27 @@ set_footer(Footer) -> req({set_footer,Footer}). %% set_job_name(Name) +%% %% Set a name for the currently running job. The name will be used %% when printing to 'stdout'. %% + set_job_name(Name) -> req({set_job_name,Name}). %% set_gl_props(PropList) +%% %% Set properties for group leader processes. When a group_leader process %% is created, test_server_gl:set_props(PropList) will be called. set_gl_props(PropList) -> req({set_gl_props,PropList}). +%% reset_state +%% +%% Reset the initial state +reset_state() -> + req(reset_state). %%% Internal functions. @@ -167,7 +190,10 @@ init([]) -> buffered=Empty, html_footer="</body>\n</html>\n", job_name="<name not set>", - gl_props=[]}}. + gl_props=[], + phase=starting, + offline_buffer=[], + pending_ops=[]}}. req(Req) -> gen_server:call(?MODULE, Req, infinity). @@ -178,9 +204,24 @@ handle_call({get_gl,false}, _From, #st{gls=Gls,gl_props=Props}=St) -> {reply,Pid,St#st{gls=gb_sets:insert(Pid, Gls)}}; handle_call({get_gl,true}, _From, #st{shared_gl=Shared}=St) -> {reply,Shared,St}; -handle_call({set_fd,Tag,Fd}, _From, #st{fds=Fds0}=St) -> +handle_call({set_fd,Tag,Fd}, _From, #st{fds=Fds0,tags=Tags0, + offline_buffer=OfflineBuff}=St) -> Fds = gb_trees:enter(Tag, Fd, Fds0), - {reply,ok,St#st{fds=Fds}}; + St1 = St#st{fds=Fds,tags=[Tag|lists:delete(Tag, Tags0)]}, + OfflineBuff1 = + if OfflineBuff == [] -> + []; + true -> + %% Fd ready, print anything buffered for associated Tag + lists:filtermap(fun({T,From,Str}) when T == Tag -> + output(From, Tag, Str, St1), + false; + (_) -> + true + end, lists:reverse(OfflineBuff)) + end, + {reply,ok,St1#st{phase=started, + offline_buffer=lists:reverse(OfflineBuff1)}}; handle_call({start_transaction,Pid}, _From, #st{io_buffering=Buffer0, buffered=Buf0}=St) -> Buf = case gb_trees:is_defined(Pid, Buf0) of @@ -213,12 +254,15 @@ handle_call({set_job_name,Name}, _From, St) -> handle_call({set_gl_props,Props}, _From, #st{shared_gl=Shared}=St) -> test_server_gl:set_props(Shared, Props), {reply,ok,St#st{gl_props=Props}}; -handle_call({stop,FdTags}, From, #st{fds=Fds,shared_gl=SGL,gls=Gls0}=St0) -> - St = St0#st{gls=gb_sets:insert(SGL, Gls0),stopping=From}, - gc(St), - %% Give the users of the surviving group leaders some - %% time to finish. - erlang:send_after(2000, self(), stop_group_leaders), +handle_call(reset_state, From, #st{phase=stopping,pending_ops=Ops}=St) -> + %% can't reset during stopping phase, save op for later + Op = fun(NewSt) -> + {_,Result,NewSt1} = handle_call(reset_state, From, NewSt), + {Result,NewSt1} + end, + {noreply,St#st{pending_ops=[{From,Op}|Ops]}}; +handle_call(reset_state, _From, #st{fds=Fds,tags=Tags,gls=Gls, + offline_buffer=OfflineBuff}) -> %% close open log files lists:foreach(fun(Tag) -> case gb_trees:lookup(Tag, Fds) of @@ -227,8 +271,44 @@ handle_call({stop,FdTags}, From, #st{fds=Fds,shared_gl=SGL,gls=Gls0}=St0) -> {value,Fd} -> file:close(Fd) end - end, FdTags), - {noreply,St}. + end, Tags), + GlList = gb_sets:to_list(Gls), + [test_server_gl:stop(GL) || GL <- GlList], + timer:sleep(2000), + [exit(GL, kill) || GL <- GlList], + Empty = gb_trees:empty(), + {ok,Shared} = test_server_gl:start_link(), + {reply,ok,#st{fds=Empty,shared_gl=Shared,gls=gb_sets:empty(), + io_buffering=gb_sets:empty(), + buffered=Empty, + html_footer="</body>\n</html>\n", + job_name="<name not set>", + gl_props=[], + phase=starting, + offline_buffer=OfflineBuff, + pending_ops=[]}}; +handle_call({stop,FdTags}, From, #st{fds=Fds0,tags=Tags0, + shared_gl=SGL,gls=Gls0}=St0) -> + St = St0#st{gls=gb_sets:insert(SGL, Gls0),phase=stopping,stopping=From}, + gc(St), + %% close open log files + {Fds1,Tags1} = lists:foldl(fun(Tag, {Fds,Tags}) -> + case gb_trees:lookup(Tag, Fds) of + none -> + {Fds,Tags}; + {value,Fd} -> + file:close(Fd), + {gb_trees:delete(Tag, Fds), + lists:delete(Tag, Tags)} + end + end, {Fds0,Tags0}, FdTags), + %% Give the users of the surviving group leaders some + %% time to finish. + erlang:send_after(2000, self(), stop_group_leaders), + {noreply,St#st{fds=Fds1,tags=Tags1}}; +handle_call(finish, From, St) -> + gen_server:reply(From, ok), + {stop,normal,St}. handle_info({'EXIT',Pid,normal}, #st{gls=Gls0,stopping=From}=St) -> Gls = gb_sets:delete_any(Pid, Gls0), @@ -236,10 +316,10 @@ handle_info({'EXIT',Pid,normal}, #st{gls=Gls0,stopping=From}=St) -> true -> %% No more group leaders left. gen_server:reply(From, ok), - {stop,normal,St#st{gls=Gls,stopping=undefined}}; + {noreply,St#st{gls=Gls,phase=stopping,stopping=undefined}}; false -> %% Wait for more group leaders to finish. - {noreply,St#st{gls=Gls}} + {noreply,St#st{gls=Gls,phase=stopping}} end; handle_info({'EXIT',_Pid,Reason}, _St) -> exit(Reason); @@ -248,10 +328,21 @@ handle_info(stop_group_leaders, #st{gls=Gls}=St) -> [test_server_gl:stop(GL) || GL <- gb_sets:to_list(Gls)], erlang:send_after(2000, self(), kill_group_leaders), {noreply,St}; -handle_info(kill_group_leaders, #st{gls=Gls,stopping=From}=St) -> +handle_info(kill_group_leaders, #st{gls=Gls,stopping=From, + pending_ops=Ops}=St) -> [exit(GL, kill) || GL <- gb_sets:to_list(Gls)], - gen_server:reply(From, ok), - {stop,normal,St}; + if From /= undefined -> + gen_server:reply(From, ok); + true -> % reply has been sent already + ok + end, + %% we're idle, check if any ops are pending + St1 = lists:foldr(fun({ReplyTo,Op},NewSt) -> + {Result,NewSt1} = Op(NewSt), + gen_server:reply(ReplyTo, Result), + NewSt1 + end, St#st{phase=idle,pending_ops=[]}, Ops), + {noreply,St1}; handle_info(Other, St) -> io:format("Ignoring: ~p\n", [Other]), {noreply,St}. @@ -259,11 +350,19 @@ handle_info(Other, St) -> terminate(_, _) -> ok. -output(From, Tag, Str, #st{io_buffering=Buffered,buffered=Buf0}=St) -> +output(From, Tag, Str, #st{io_buffering=Buffered,buffered=Buf0, + phase=Phase,offline_buffer=OfflineBuff}=St) -> case gb_sets:is_member(From, Buffered) of false -> - do_output(Tag, Str, St), - St; + case do_output(Tag, Str, Phase, St) of + buffer when length(OfflineBuff)>500 -> + %% something's wrong, clear buffer + St#st{offline_buffer=[]}; + buffer -> + St#st{offline_buffer=[{Tag,From,Str}|OfflineBuff]}; + _ -> + St + end; true -> Q0 = gb_trees:get(From, Buf0), Q = queue:in({Tag,Str}, Q0), @@ -271,17 +370,19 @@ output(From, Tag, Str, #st{io_buffering=Buffered,buffered=Buf0}=St) -> St#st{buffered=Buf} end. -do_output(stdout, Str, #st{job_name=undefined}) -> +do_output(stdout, Str, _, #st{job_name=undefined}) -> io:put_chars(Str); -do_output(stdout, Str0, #st{job_name=Name}) -> +do_output(stdout, Str0, _, #st{job_name=Name}) -> Str = io_lib:format("Testing ~ts: ~ts\n", [Name,Str0]), io:put_chars(Str); -do_output(Tag, Str, #st{fds=Fds}=St) -> +do_output(Tag, Str, Phase, #st{fds=Fds}=St) -> case gb_trees:lookup(Tag, Fds) of + none when Phase /= started -> + buffer; none -> S = io_lib:format("\n*** ERROR: ~w, line ~w: No known '~p' log file\n", [?MODULE,?LINE,Tag]), - do_output(stdout, [S,Str], St); + do_output(stdout, [S,Str], Phase, St); {value,Fd} -> try io:put_chars(Fd, Str), @@ -293,14 +394,14 @@ do_output(Tag, Str, #st{fds=Fds}=St) -> S = io_lib:format("\n*** ERROR: ~w, line ~w: Error writing to " "log file '~p': ~p\n", [?MODULE,?LINE,Tag,Error]), - do_output(stdout, [S,Str], St) + do_output(stdout, [S,Str], Phase, St) end end. finalise_table(Fd, #st{html_footer=Footer}) -> case file:position(Fd, {cur,0}) of {ok,Pos} -> - %% We are writing to a seekable file. Finalise so + %% We are writing to a seekable file. Finalise so %% we get complete valid (and viewable) HTML code. %% Then rewind to overwrite the finalising code. io:put_chars(Fd, ["\n</table>\n",Footer]), @@ -319,7 +420,7 @@ do_print_buffered(Q0, St) -> eot -> Q; {Tag,Str} -> - do_output(Tag, Str, St), + do_output(Tag, Str, undefined, St), do_print_buffered(Q, St) end. |