Merge remote-tracking branch 'peppe/peppe/kernel/logger_handler_fixes'

* peppe/peppe/kernel/logger_handler_fixes:
  Various logger handler improvements and updated test cases
  Make it possible to disable sync and drop mode

Conflicts:
	lib/kernel/test/logger_disk_log_h_SUITE.erl
	lib/kernel/test/logger_std_h_SUITE.erl

4 files changed, 51 insertions, 53 deletions

diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl
index 0150fa781a..57c54ce27e 100644
--- a/lib/kernel/src/logger_disk_log_h.erl
+++ b/lib/kernel/src/logger_disk_log_h.erl
@@ -278,10 +278,11 @@ init([Name, Config = #{disk_log_opts := LogOpts},
                                          last_log_ts => T0,
                                          burst_win_ts => T0,
                                          burst_msg_count => 0,
+                                         last_op => sync,
                                          prev_log_result => ok,
                                          prev_sync_result => ok,
                                          prev_disk_log_info => undefined}),
-            gen_server:cast(self(), {repeated_disk_log_sync,T0}),
+            gen_server:cast(self(), repeated_disk_log_sync),
             enter_loop(Config, State1);
         Error ->
             logger_h_common:error_notify({open_disk_log,Name,Error}),
@@ -316,8 +317,7 @@ handle_call(disk_log_sync, _From, State = #{id := Name}) ->
     {reply, Result, State1};
 
 handle_call({change_config,_OldConfig,NewConfig}, _From,
-            State = #{filesync_repeat_interval := FSyncInt0,
-                      last_log_ts := LastLogTS}) ->
+            State = #{filesync_repeat_interval := FSyncInt0}) ->
     HConfig = maps:get(?MODULE, NewConfig, #{}),
     State1 = #{toggle_sync_qlen   := TSQL,
                drop_new_reqs_qlen := DNRQL,
@@ -338,9 +338,8 @@ handle_call({change_config,_OldConfig,NewConfig}, _From,
                         _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref,
                                                                   State,
                                                                   undefined)),
-                        _ = gen_server:cast(self(), {repeated_disk_log_sync,
-                                                     LastLogTS})
-                end,            
+                        _ = gen_server:cast(self(), repeated_disk_log_sync)
+                end,
             {reply, ok, State1};
         false ->
             {reply, {error,{invalid_levels,{TSQL,DNRQL,FRQL}}}, State}
@@ -370,24 +369,23 @@ handle_cast({log, Bin}, State) ->
 %% clause gets called repeatedly by the handler. In order to
 %% guarantee that a filesync *always* happens after the last log
 %% request, the repeat operation must be active!
-handle_cast({repeated_disk_log_sync,LastLogTS0},
+handle_cast(repeated_disk_log_sync,
             State = #{id := Name,
                       filesync_repeat_interval := FSyncInt,
-                      last_log_ts := LastLogTS1}) ->
+                      last_op := LastOp}) ->
     State1 =
         if is_integer(FSyncInt) ->
                 %% only do filesync if something has been
                 %% written since last time we checked
-                NewState = if LastLogTS1 == LastLogTS0 ->
+                NewState = if LastOp == sync ->
                                    State;
                               true ->
                                    disk_log_sync(Name, State)
                            end,
                 {ok,TRef} =
                     timer:apply_after(FSyncInt, gen_server,cast,
-                                      [self(),
-                                       {repeated_disk_log_sync,LastLogTS1}]),
-                NewState#{rep_sync_tref => TRef};
+                                      [self(),repeated_disk_log_sync]),
+                NewState#{rep_sync_tref => TRef, last_op => sync};
            true ->
                 State
         end,
@@ -649,10 +647,9 @@ close_disk_log(Name, _) ->
     ok.
 
 disk_log_write(Name, Bin, State) ->
-    Result =
         case ?disk_log_blog(Name, Bin) of
             ok ->
-                ok;
+                State#{prev_log_result => ok, last_op => write};
             LogError ->
                 _ = case maps:get(prev_log_result, State) of
                         LogError ->
@@ -664,29 +661,26 @@ disk_log_write(Name, Bin, State) ->
                                                           LogOpts,
                                                           LogError})
                     end,
-                LogError
-        end,
-    State#{prev_log_result => Result}.
+                State#{prev_log_result => LogError}
+        end.
 
 disk_log_sync(Name, State) ->
-    Result =
-        case ?disk_log_sync(Name) of
-            ok ->
-                ok;
-            SyncError ->
-                _ = case maps:get(prev_sync_result, State) of
-                        SyncError ->
-                            %% don't report same error twice
-                            ok;
-                        _ ->
-                            LogOpts = maps:get(log_opts, State),
-                            logger_h_common:error_notify({Name,sync,
-                                                          LogOpts,
-                                                          SyncError})
-                    end,
-                SyncError
-        end,
-    State#{prev_sync_result => Result}. 
+    case ?disk_log_sync(Name) of
+        ok ->
+            State#{prev_sync_result => ok, last_op => sync};
+        SyncError ->
+            _ = case maps:get(prev_sync_result, State) of
+                    SyncError ->
+                        %% don't report same error twice
+                        ok;
+                    _ ->
+                        LogOpts = maps:get(log_opts, State),
+                        logger_h_common:error_notify({Name,sync,
+                                                      LogOpts,
+                                                      SyncError})
+                end,
+            State#{prev_sync_result => SyncError}
+    end.
 
 error_notify_new(Info,Info, _Term) ->
     ok;
diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl
index 7caad366ae..901c4c0dad 100644
--- a/lib/kernel/src/logger_h_common.erl
+++ b/lib/kernel/src/logger_h_common.erl
@@ -135,7 +135,8 @@ call_cast_or_drop(Name, Bin) ->
                 _:{timeout,_} ->
                     ?observe(Name,{dropped,1})
             end;
-        drop -> ?observe(Name,{dropped,1})
+        drop ->
+            ?observe(Name,{dropped,1})
     catch
         %% if the ETS table doesn't exist (maybe because of a
         %% handler restart), we can only drop the request
@@ -152,12 +153,15 @@ check_load(State = #{id:=Name, mode := Mode,
                      flush_reqs_qlen := FlushQLen}) ->
     {_,Mem} = process_info(self(), memory),
     ?observe(Name,{max_mem,Mem}),
-    %% make sure the handler process doesn't get scheduled
-    %% out between the message_queue_len check below and the
-    %% action that follows (flush or write).
     {_,QLen} = process_info(self(), message_queue_len),
     ?observe(Name,{max_qlen,QLen}),
-
+    %% When the handler process gets scheduled in, it's impossible
+    %% to predict the QLen. We could jump "up" arbitrarily from say
+    %% async to sync, async to drop, sync to flush, etc. However, when
+    %% the handler process manages the log requests (without flushing),
+    %% one after the other, we will move "down" from drop to sync and
+    %% from sync to async. This way we don't risk getting stuck in
+    %% drop or sync mode with an empty mailbox.
     {Mode1,_NewDrops,_NewFlushes} =
         if
             QLen >= FlushQLen ->
@@ -292,7 +296,7 @@ overload_levels_ok(HandlerConfig) ->
     TSQL = maps:get(toggle_sync_qlen, HandlerConfig, ?TOGGLE_SYNC_QLEN),
     DNRQL = maps:get(drop_new_reqs_qlen, HandlerConfig, ?DROP_NEW_REQS_QLEN),
     FRQL = maps:get(flush_reqs_qlen, HandlerConfig, ?FLUSH_REQS_QLEN),
-    (TSQL < DNRQL) andalso (DNRQL < FRQL).
+    (DNRQL > 1) andalso (TSQL =< DNRQL) andalso (DNRQL =< FRQL).
 
 error_notify(Term) ->
     ?internal_log(error, Term).
diff --git a/lib/kernel/src/logger_h_common.hrl b/lib/kernel/src/logger_h_common.hrl
index 89378dbb10..ed365ce6eb 100644
--- a/lib/kernel/src/logger_h_common.hrl
+++ b/lib/kernel/src/logger_h_common.hrl
@@ -124,7 +124,7 @@
 %%% slow down execution and therefore should not be include in code
 %%% to be officially released.
 
-%% -define(TEST_HOOKS, true).
+-define(TEST_HOOKS, true).
 -ifdef(TEST_HOOKS).
   -define(TEST_HOOKS_TAB, logger_h_test_hooks).
 
diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl
index 31edcfea8b..e5e0febc88 100644
--- a/lib/kernel/src/logger_std_h.erl
+++ b/lib/kernel/src/logger_std_h.erl
@@ -257,10 +257,11 @@ init([Name, Config,
                                          file_ctrl_sync => FileCtrlSyncInt,
                                          last_qlen => 0,
                                          last_log_ts => T0,
+                                         last_op => sync,
                                          burst_win_ts => T0,
                                          burst_msg_count => 0}),
             proc_lib:init_ack({ok,self()}),
-            gen_server:cast(self(), {repeated_filesync,T0}),
+            gen_server:cast(self(), repeated_filesync),
             enter_loop(Config, State1);
         Error ->
             logger_h_common:error_notify({init_handler,Name,Error}),
@@ -310,12 +311,11 @@ handle_call(filesync, _From, State = #{type := Type,
     if is_atom(Type) ->
             {reply, ok, State};
        true ->
-            {reply, file_ctrl_filesync_sync(FileCtrlPid), State}
+            {reply, file_ctrl_filesync_sync(FileCtrlPid), State#{last_op=>sync}}
     end;
 
 handle_call({change_config,_OldConfig,NewConfig}, _From,
-            State = #{filesync_repeat_interval := FSyncInt0,
-                      last_log_ts := LastLogTS}) ->
+            State = #{filesync_repeat_interval := FSyncInt0}) ->
     HConfig = maps:get(?MODULE, NewConfig, #{}),
     State1 = maps:merge(State, HConfig),
     case logger_h_common:overload_levels_ok(State1) of
@@ -334,8 +334,7 @@ handle_call({change_config,_OldConfig,NewConfig}, _From,
                         _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref,
                                                                   State,
                                                                   undefined)),
-                        gen_server:cast(self(), {repeated_filesync,
-                                                 LastLogTS})
+                        gen_server:cast(self(), repeated_filesync)
                 end,
             {reply, ok, State1};
         false ->
@@ -365,24 +364,24 @@ handle_cast({log, Bin}, State) ->
 %% clause gets called repeatedly by the handler. In order to
 %% guarantee that a filesync *always* happens after the last log
 %% request, the repeat operation must be active!
-handle_cast({repeated_filesync,LastLogTS0},
+handle_cast(repeated_filesync,
             State = #{type := Type,
                       file_ctrl_pid := FileCtrlPid,
                       filesync_repeat_interval := FSyncInt,
-                      last_log_ts := LastLogTS1}) ->
+                      last_op := LastOp}) ->
     State1 =
         if not is_atom(Type), is_integer(FSyncInt) ->
                 %% only do filesync if something has been
                 %% written since last time we checked
-                if LastLogTS1 == LastLogTS0 ->
+                if LastOp == sync ->
                         ok;
                    true ->
                         file_ctrl_filesync_async(FileCtrlPid)
                 end,
                 {ok,TRef} =
                     timer:apply_after(FSyncInt, gen_server,cast,
-                                      [self(),{repeated_filesync,LastLogTS1}]),
-                State#{rep_sync_tref => TRef};
+                                      [self(),repeated_filesync]),
+                State#{rep_sync_tref => TRef, last_op => sync};
            true ->
                 State
         end,
@@ -600,6 +599,7 @@ write(Name, Mode, T1, Bin, _CallOrCast,
                          State1#{mode => Mode1,
                                  last_qlen := LastQLen1,
                                  last_log_ts => T1,
+                                 last_op => write,
                                  burst_win_ts => BurstWinT,
                                  burst_msg_count => BurstMsgCount1,
                                  file_ctrl_sync =>