[logger] Stress overload_kill tests in disk_log handler

2 files changed, 51 insertions, 21 deletions

diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl
index 7225d4b57c..492730bd89 100644
--- a/lib/kernel/test/logger_disk_log_h_SUITE.erl
+++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl
@@ -1063,7 +1063,7 @@ kill_disabled(cleanup, _Config) ->
     ok = stop_handler(?MODULE).
 
 qlen_kill_new(Config) ->
-    {_Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
+    {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
     Pid0 = whereis(h_proc_name()),
     {_,Mem0} = process_info(Pid0, memory),
     RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER,
@@ -1076,7 +1076,7 @@ qlen_kill_new(Config) ->
     ok = logger:set_handler_config(?MODULE, NewHConfig),
     MRef = erlang:monitor(process, Pid0),
     NumOfReqs = 100,
-    Procs = 2,
+    Procs = 4,
     send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice),
     %% send_burst({n,NumOfReqs}, seq, {chars,79}, notice),
     receive
@@ -1087,8 +1087,8 @@ qlen_kill_new(Config) ->
                 killed ->
                     ct:pal("Slow shutdown, handler process was killed!", [])
             end,
-            timer:sleep(RestartAfter + 2000),
-            true = is_pid(whereis(h_proc_name())),
+            file_delete(Log),
+            {ok,_} = wait_for_process_up(RestartAfter * 3),
             ok
     after
         5000 ->
@@ -1100,7 +1100,7 @@ qlen_kill_new(cleanup, _Config) ->
     ok = stop_handler(?MODULE).
 
 mem_kill_new(Config) ->
-    {_Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
+    {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
     Pid0 = whereis(h_proc_name()),
     {_,Mem0} = process_info(Pid0, memory),
     RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER,
@@ -1113,7 +1113,7 @@ mem_kill_new(Config) ->
     ok = logger:set_handler_config(?MODULE, NewHConfig),
     MRef = erlang:monitor(process, Pid0),
     NumOfReqs = 100,
-    Procs = 2,
+    Procs = 4,
     send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice),
     %% send_burst({n,NumOfReqs}, seq, {chars,79}, notice),
     receive
@@ -1124,8 +1124,8 @@ mem_kill_new(Config) ->
                 killed ->
                     ct:pal("Slow shutdown, handler process was killed!", [])
             end,
-            timer:sleep(RestartAfter + 2000),
-            true = is_pid(whereis(h_proc_name())),
+            file_delete(Log),
+            {ok,_} = wait_for_process_up(RestartAfter * 3),
             ok
     after
         5000 ->
@@ -1136,6 +1136,8 @@ mem_kill_new(Config) ->
 mem_kill_new(cleanup, _Config) ->
     ok = stop_handler(?MODULE).
 
+restart_after() ->
+    [{timetrap,{minutes,2}}].
 restart_after(Config) ->
     {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
     NewHConfig1 =
@@ -1145,14 +1147,16 @@ restart_after(Config) ->
     ok = logger:set_handler_config(?MODULE, NewHConfig1),
     MRef1 = erlang:monitor(process, whereis(h_proc_name())),
     %% kill handler
-    send_burst({n,100}, {spawn,2,0}, {chars,79}, notice),
+    send_burst({n,100}, {spawn,4,0}, {chars,79}, notice),
     receive
-        {'DOWN', MRef1, _, _, _Info1} ->
-            timer:sleep(?OVERLOAD_KILL_RESTART_AFTER + 1000),
-            undefined = whereis(h_proc_name()),
+        {'DOWN', MRef1, _, _, _Reason1} ->
+            file_delete(Log),
+            error = wait_for_process_up(?OVERLOAD_KILL_RESTART_AFTER * 3),
             ok
     after
         5000 ->
+            Info1 = logger_std_h:info(?MODULE),
+            ct:pal("Handler state = ~p", [Info1]),
             ct:fail("Handler not dead! It should not have survived this!")
     end,
     
@@ -1166,16 +1170,17 @@ restart_after(Config) ->
     Pid0 = whereis(h_proc_name()),
     MRef2 = erlang:monitor(process, Pid0),
     %% kill handler
-    send_burst({n,100}, {spawn,2,0}, {chars,79}, notice),
+    send_burst({n,100}, {spawn,4,0}, {chars,79}, notice),
     receive
-        {'DOWN', MRef2, _, _, _Info2} ->
-            timer:sleep(RestartAfter + 2000),
-            Pid1 = whereis(h_proc_name()),
-            true = is_pid(Pid1),
+        {'DOWN', MRef2, _, _, _Reason2} ->
+            file_delete(Log),
+            {ok,Pid1} = wait_for_process_up(RestartAfter * 3),
             false = (Pid1 == Pid0),
             ok
     after
         5000 ->
+            Info2 = logger_std_h:info(?MODULE),
+            ct:pal("Handler state = ~p", [Info2]),
             ct:fail("Handler not dead! It should not have survived this!")
     end,
     ok.
@@ -1539,3 +1544,23 @@ h_proc_name(Name) ->
 
 file_delete(Log) ->
    file:delete(Log).
+
+wait_for_process_up(T) ->
+    wait_for_process_up(h_proc_name(),T).
+
+wait_for_process_up(Name,T) ->
+    N = (T div 500) + 1,
+    wait_for_process_up1(Name,N).
+
+wait_for_process_up1(Name,0) ->
+    error;
+wait_for_process_up1(Name,N) ->
+    timer:sleep(500),
+    case whereis(Name) of
+        Pid when is_pid(Pid) ->
+            %% ct:pal("Process ~p up (~p tries left)",[Name,N]),
+            {ok,Pid};
+        undefined ->
+            %% ct:pal("Waiting for process ~p (~p tries left)",[Name,N]),
+            wait_for_process_up1(Name,N-1)
+    end.
diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl
index e0bc79012c..c2cc7653ea 100644
--- a/lib/kernel/test/logger_std_h_SUITE.erl
+++ b/lib/kernel/test/logger_std_h_SUITE.erl
@@ -995,7 +995,7 @@ qlen_kill_new(Config) ->
                     ct:pal("Slow shutdown, handler process was killed!", [])
             end,
             file_delete(Log),
-            {ok,_} = wait_for_process_up(h_proc_name(), RestartAfter * 3),
+            {ok,_} = wait_for_process_up(RestartAfter * 3),
             ok
     after
         5000 ->
@@ -1046,7 +1046,7 @@ mem_kill_new(Config) ->
                     ct:pal("Slow shutdown, handler process was killed!", [])
             end,
             file_delete(Log),
-            {ok,_} = wait_for_process_up(h_proc_name(), RestartAfter * 3),
+            {ok,_} = wait_for_process_up(RestartAfter * 3),
             ok
     after
         5000 ->
@@ -1077,7 +1077,7 @@ restart_after(Config) ->
     receive
         {'DOWN', MRef1, _, _, _Reason1} ->
             file_delete(Log),
-            error = wait_for_process_up(h_proc_name(),?OVERLOAD_KILL_RESTART_AFTER * 3),
+            error = wait_for_process_up(?OVERLOAD_KILL_RESTART_AFTER * 3),
             ok
     after
         5000 ->
@@ -1100,7 +1100,7 @@ restart_after(Config) ->
     receive
         {'DOWN', MRef2, _, _, _Reason2} ->
             file_delete(Log),
-            {ok,Pid1} = wait_for_process_up(h_proc_name(),RestartAfter * 3),
+            {ok,Pid1} = wait_for_process_up(RestartAfter * 3),
             false = (Pid1 == Pid0),
             ok
     after
@@ -1570,6 +1570,9 @@ h_proc_name(Name) ->
 file_delete(Log) ->
    file:delete(Log).
 
+wait_for_process_up(T) ->
+    wait_for_process_up(h_proc_name(),T).
+
 wait_for_process_up(Name,T) ->
     N = (T div 500) + 1,
     wait_for_process_up1(Name,N).
@@ -1580,7 +1583,9 @@ wait_for_process_up1(Name,N) ->
     timer:sleep(500),
     case whereis(Name) of
         Pid when is_pid(Pid) ->
+            %% ct:pal("Process ~p up (~p tries left)",[Name,N]),
             {ok,Pid};
         undefined ->
+            %% ct:pal("Waiting for process ~p (~p tries left)",[Name,N]),
             wait_for_process_up1(Name,N-1)
     end.