%%
%% %CopyrightBegin%
%%
%% Copyright Ericsson AB 2012-2018. All Rights Reserved.
%%
%% Licensed under the Apache License, Version 2.0 (the "License");
%% you may not use this file except in compliance with the License.
%% You may obtain a copy of the License at
%%
%%     http://www.apache.org/licenses/LICENSE-2.0
%%
%% Unless required by applicable law or agreed to in writing, software
%% distributed under the License is distributed on an "AS IS" BASIS,
%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
%% See the License for the specific language governing permissions and
%% limitations under the License.
%%
%% %CopyrightEnd%
%%

%%%-------------------------------------------------------------------
%%% File: ct_pre_post_test_io_SUITE
%%%
%%% Description:
%%%
%%% Test that ct:log/2 printouts and error/progress reports that happen
%%% before or after the test run are saved in the pre/post test IO log.
%%%-------------------------------------------------------------------
-module(ct_pre_post_test_io_SUITE).

-compile(export_all).

-include_lib("common_test/include/ct.hrl").
-include_lib("common_test/include/ct_event.hrl").

-define(eh, ct_test_support_eh).

%%--------------------------------------------------------------------
%% TEST SERVER CALLBACK FUNCTIONS
%%--------------------------------------------------------------------

%%--------------------------------------------------------------------
%% Description: Since Common Test starts another Test Server
%% instance, the tests need to be performed on a separate node (or
%% there will be clashes with logging processes etc).
%%--------------------------------------------------------------------
suite() ->
    [{ct_hooks,[ts_install_cth]},
     {timetrap,{seconds,120}}].

all() ->
    [
     pre_post_io
    ].

init_per_suite(Config) ->
    TTInfo = {_T,{_Scaled,ScaleVal}} = ct:get_timetrap_info(),
    ct:pal("Timetrap info = ~w", [TTInfo]),
    if ScaleVal > 1 ->
	    {skip,"Skip on systems running e.g. cover or debug!"};
       ScaleVal =< 1 ->
	    DataDir = ?config(data_dir, Config),
	    CTH = filename:join(DataDir, "cth_ctrl.erl"),
	    ct:pal("Compiling ~p: ~p",
		   [CTH,compile:file(CTH,[{outdir,DataDir},
					  debug_info])]),
	    ct_test_support:init_per_suite([{path_dirs,[DataDir]},
					    {start_sasl,true} | Config])
    end.

end_per_suite(Config) ->
    ct_test_support:end_per_suite(Config).

init_per_testcase(TestCase, Config) ->
    ct_test_support:init_per_testcase(TestCase, Config).

end_per_testcase(TestCase, Config) ->
    ct_test_support:end_per_testcase(TestCase, Config).

%%--------------------------------------------------------------------
%% TEST CASES
%%--------------------------------------------------------------------

%%%-----------------------------------------------------------------
%%%
pre_post_io(Config) ->
    TC = pre_post_io,
    DataDir = ?config(data_dir, Config),
    Suite = filename:join(DataDir, "dummy_SUITE"),
    {Opts,ERPid} = setup([{suite,Suite},{label,TC},{ct_hooks,[cth_ctrl]}],
			 Config),
    
    %%!--------------------------------------------------------------------
    %%! Note that error reports will not start showing up in the pre-test
    %%! io log until handle_remote_events has been set to true (see below).
    %%! The reason is that the error logger has its group leader on the
    %%! test_server node (not the ct node) and cth_log_redirect ignores
    %%! events with remote destination until told otherwise.
    %%!--------------------------------------------------------------------

    spawn(fun() ->
		  ct:pal("CONTROLLER: Starting test run #1...", []),
		  %% --- test run 1 ---
		  try_loop(ct_test_support, ct_rpc, [{cth_log_redirect,
						      handle_remote_events,
						      [true]}, Config], 3000),
		  CTLoggerPid1 = ct_test_support:ct_rpc({erlang,whereis,
							[ct_logs]}, Config),
		  ct:pal("CONTROLLER: Logger = ~w~nHandle remote events = true",
			 [CTLoggerPid1]),
		  ct:sleep(5000),
		  ct:pal("CONTROLLER: Proceeding with test run #1...", []),
		  ok = ct_test_support:ct_rpc({cth_ctrl,proceed,[]}, Config),
		  ct:sleep(6000),
		  ct:pal("CONTROLLER: Proceeding with shutdown #1...", []),
		  ok = ct_test_support:ct_rpc({cth_ctrl,proceed,[]}, Config),
		  try_loop(fun() ->
				   false = ct_test_support:ct_rpc({erlang,
								    is_process_alive,
								    [CTLoggerPid1]},
								   Config)
			   end, 3000),
		  ct:pal("CONTROLLER: Shutdown #1 complete!", []),
		  ct:pal("CONTROLLER: Starting test run #2...", []),
		  %% --- test run 2 ---
		  try_loop(ct_test_support, ct_rpc, [{cth_log_redirect,
						      handle_remote_events,
						      [true]}, Config], 3000),
		  CTLoggerPid2 = ct_test_support:ct_rpc({erlang,whereis,
							[ct_logs]}, Config),
		  ct:pal("CONTROLLER: Logger = ~w~nHandle remote events = true",
			 [CTLoggerPid2]),
		  ct:sleep(5000),
		  ct:pal("CONTROLLER: Proceeding with test run #2...", []),
		  ok = ct_test_support:ct_rpc({cth_ctrl,proceed,[]}, Config),
		  ct:sleep(6000),
		  ct:pal("CONTROLLER: Proceeding with shutdown #2...", []),
		  ok = ct_test_support:ct_rpc({cth_ctrl,proceed,[]}, Config),
		  try_loop(fun() ->
				   false = ct_test_support:ct_rpc({erlang,
								   is_process_alive,
								   [CTLoggerPid2]},
								  Config)
			   end, 3000),
		  ct:pal("CONTROLLER: Shutdown #2 complete!", [])
	  end),
    ct_test_support:run(Opts, Config),
    Events = ct_test_support:get_events(ERPid, Config),
    ct_test_support:log_events(TC,
			       reformat(Events, ?eh),
			       ?config(priv_dir, Config),
			       Opts),
    TestEvents = events_to_check(TC),
    ok = ct_test_support:verify_events(TestEvents, Events, Config),
    
    LogDirs = lists:flatmap(fun({_EH,#event{name=start_logging,data=Dir}}) ->
				    [Dir];
			       (_) ->
				    []
			    end, Events),
    PrePostIoFiles =
	[filename:join(LogDir, "misc_io.log.html") || LogDir <- LogDirs],
    lists:foreach(
      fun(PrePostIoFile) ->
	      ct:log("Reading Pre/Post Test IO Log file: ~ts", [PrePostIoFile]),
	      {ok,Bin} = file:read_file(PrePostIoFile),
	      Ts = string:lexemes(binary_to_list(Bin),[$\n]),
	      PrePostIOEntries =
		  lists:foldl(fun([$L,$o,$g,$g,$e,$r|_],
				  {pre,PreLogN,PreErrN,0,0}) ->
				      {pre,PreLogN+1,PreErrN,0,0};
				 ([$=,$E,$R,$R,$O,$R|_],
				  {pre,PreLogN,PreErrN,0,0}) ->
				      {pre,PreLogN,PreErrN+1,0,0};
				 ([_,_,_,_,$P,$O,$S,$T,$-,$T,$E,$S,$T|_],
				  {pre,PreLogN,PreErrN,0,0}) ->
				      {post,PreLogN,PreErrN,0,0};
				 ([$L,$o,$g,$g,$e,$r|_],
				  {post,PreLogN,PreErrN,PostLogN,PostErrN}) ->
				      {post,PreLogN,PreErrN,PostLogN+1,PostErrN};
				 ([$=,$E,$R,$R,$O,$R|_],
				  {post,PreLogN,PreErrN,PostLogN,PostErrN}) ->
				      {post,PreLogN,PreErrN,PostLogN,PostErrN+1};
				 (_, Counters) ->
				      Counters
			      end, {pre,0,0,0,0}, Ts),
	      [_|Counters] = tuple_to_list(PrePostIOEntries),
	      ct:pal("Entries in the Pre/Post Test IO Log: ~w", [Counters]),
	      case [C || C <- Counters, C < 2] of
		  [] ->
		      ok;
		  _ ->
		      exit("Not enough entries in the Pre/Post Test IO Log!")
	      end
      end, PrePostIoFiles), 

    UnexpIoFiles =
	[filelib:wildcard(
	   filename:join(LogDir,
			 "*dummy_SUITE.logs/run.*/"
			 "unexpected_io.log.html")) || LogDir <- LogDirs],
    lists:foreach(
      fun(UnexpIoFile) ->
	      ct:log("Reading Unexpected IO Log file: ~ts", [UnexpIoFile]),
	      {ok,Bin} = file:read_file(UnexpIoFile),
	      Ts = string:lexemes(binary_to_list(Bin),[$\n]),
	      UnexpIOEntries =
		  lists:foldl(fun([$L,$o,$g,$g,$e,$r|_], [LogN,ErrN]) ->
				      [LogN+1,ErrN];
				 ([$=,$E,$R,$R,$O,$R|_], [LogN,ErrN]) ->
				      [LogN,ErrN+1];
				 (_, Counters) -> Counters
			      end, [0,0], Ts),
	      ct:log("Entries in the Unexpected IO Log: ~w", [UnexpIOEntries]),
	      case [N || N <- UnexpIOEntries, N < 2] of
		  [] ->
		      ok;
		  _ ->
		      exit("Not enough entries in the Unexpected IO Log!")
	      end
      end, UnexpIoFiles),
    ok.

%%%-----------------------------------------------------------------
%%% HELP FUNCTIONS
%%%-----------------------------------------------------------------

setup(Test, Config) ->
    Opts0 = ct_test_support:get_opts(Config),
    Level = ?config(trace_level, Config),
    EvHArgs = [{cbm,ct_test_support},{trace_level,Level}],
    Opts = Opts0 ++ [{event_handler,{?eh,EvHArgs}}|Test],
    ERPid = ct_test_support:start_event_receiver(Config),
    {Opts,ERPid}.

reformat(Events, EH) ->
    ct_test_support:reformat(Events, EH).

try_loop(_Fun, 0) ->
    ct:pal("WARNING! Fun never succeeded!", []),
    gave_up;
try_loop(Fun, N) ->
    try Fun() of
	{Error,_} when Error==error; Error==badrpc ->
	    timer:sleep(10),
	    try_loop(Fun, N-1);
	Result ->
	    Result
    catch
	_:_What ->
	    timer:sleep(10),
	    try_loop(Fun, N-1)
    end.

try_loop(M, F, _A, 0) ->
    ct:pal("WARNING! ~w:~w never succeeded!", [M,F]),
    gave_up;
try_loop(M, F, A, N) ->
    try apply(M, F, A) of
	{Error,_Reason} when Error==error; Error==badrpc ->
	    timer:sleep(10),
	    try_loop(M, F, A, N-1);
	Result ->
	    Result
    catch
	_:_ ->
	    timer:sleep(10),
	    try_loop(M, F, A, N-1)
    end.

%%%-----------------------------------------------------------------
%%% TEST EVENTS
%%%-----------------------------------------------------------------

events_to_check(pre_post_io) ->
    [
     {?eh,start_logging,{'DEF','RUNDIR'}},
     {?eh,test_start,{'DEF',{'START_TIME','LOGDIR'}}},
     {?eh,start_info,{1,1,7}},
     {?eh,tc_start,{dummy_SUITE,init_per_suite}},
     {?eh,tc_done,{dummy_SUITE,init_per_suite,ok}},
     {parallel,
      [{?eh,tc_start,{dummy_SUITE,{init_per_group,g1,[parallel]}}},
       {?eh,tc_done,
	{dummy_SUITE,{init_per_group,g1,[parallel]},ok}},
       {?eh,tc_start,{dummy_SUITE,tc1}},
       {?eh,tc_start,{dummy_SUITE,tc2}},
       {?eh,tc_start,{dummy_SUITE,tc3}},
       {?eh,tc_done,{dummy_SUITE,tc2,ok}},
       {?eh,tc_done,{dummy_SUITE,tc1,ok}},
       {?eh,tc_done,{dummy_SUITE,tc3,ok}},
       {?eh,test_stats,{1,0,{0,0}}},
       {?eh,test_stats,{2,0,{0,0}}},
       {?eh,test_stats,{3,0,{0,0}}},
       {?eh,tc_start,{dummy_SUITE,{end_per_group,g1,[parallel]}}},
       {?eh,tc_done,{dummy_SUITE,{end_per_group,g1,[parallel]},ok}}]},
     {?eh,tc_start,{dummy_SUITE,tc1}},
     {?eh,tc_done,{dummy_SUITE,tc1,ok}},
     {?eh,test_stats,{4,0,{0,0}}},
     {?eh,tc_start,{dummy_SUITE,tc2}},
     {?eh,tc_done,{dummy_SUITE,tc2,ok}},
     {?eh,test_stats,{5,0,{0,0}}},
     [{?eh,tc_start,{dummy_SUITE,{init_per_group,g2,[]}}},
      {?eh,tc_done,{dummy_SUITE,{init_per_group,g2,[]},ok}},
      {?eh,tc_start,{dummy_SUITE,tc4}},
      {?eh,tc_done,{dummy_SUITE,tc4,ok}},
      {?eh,test_stats,{6,0,{0,0}}},
      {?eh,tc_start,{dummy_SUITE,tc5}},
      {?eh,tc_done,{dummy_SUITE,tc5,ok}},
      {?eh,test_stats,{7,0,{0,0}}},
      {?eh,tc_start,{dummy_SUITE,{end_per_group,g2,[]}}},
      {?eh,tc_done,{dummy_SUITE,{end_per_group,g2,[]},ok}}],
     {?eh,tc_start,{dummy_SUITE,end_per_suite}},
     {?eh,tc_done,{dummy_SUITE,end_per_suite,ok}},
     {?eh,test_done,{'DEF','STOP_TIME'}},
     {?eh,stop_logging,[]}].