kernel: Make all handler callbacks not block logger

3 files changed, 236 insertions, 98 deletions

diff --git a/lib/kernel/src/logger_server.erl b/lib/kernel/src/logger_server.erl
index 268fd4f2f3..2a3723177f 100644
--- a/lib/kernel/src/logger_server.erl
+++ b/lib/kernel/src/logger_server.erl
@@ -36,8 +36,9 @@
 -include("logger_internal.hrl").
 
 -define(SERVER, logger).
+-define(LOGGER_SERVER_TAG, '$logger_cb_process').
 
--record(state, {tid}).
+-record(state, {tid, async_req, async_req_queue}).
 
 %%%===================================================================
 %%% API
@@ -127,96 +128,93 @@ init([]) ->
     {ok,SimpleConfig} =
         logger_simple:adding_handler(logger_simple,SimpleConfig0),
     logger_config:create(Tid,logger_simple,logger_simple,SimpleConfig),
-    {ok, #state{tid=Tid}}.
-
-handle_call({add_handler,Id,Module,HConfig}, _From, #state{tid=Tid}=State) ->
-    Reply =
-        case logger_config:exist(Tid,Id) of
-            true ->
-                {error,{already_exist,Id}};
-            false ->
-                %% inform the handler
-                case call_h(Module,adding_handler,[Id,HConfig],{ok,HConfig}) of
-                    {ok,HConfig1} ->
-                        %% We know that the call_h would have loaded the module
-                        %% if it existed, so it is safe here to call function_exported
-                        %% to find out if this is a valid handler
-                        case erlang:function_exported(Module, log, 2) of
-                            true ->
-                                logger_config:create(Tid,Id,Module,HConfig1),
-                                {ok,Config} = do_get_config(Tid,logger),
-                                Handlers = maps:get(handlers,Config,[]),
-                                do_set_config(Tid,logger,
-                                              Config#{handlers=>[Id|Handlers]});
-                            false ->
-                                {error,{invalid_handler,
-                                        {function_not_exported,
-                                         {Module,log,2}}}}
-                        end;
-                    {error,HReason} ->
-                        {error,{handler_not_added,HReason}}
-                end
-        end,
-    {reply,Reply,State};
-handle_call({remove_handler,HandlerId}, _From, #state{tid=Tid}=State) ->
-    Reply =
-        case logger_config:get(Tid,HandlerId) of
-            {ok,{Module,_}} ->
-                {ok,Config} = do_get_config(Tid,logger),
-                Handlers0 = maps:get(handlers,Config,[]),
-                Handlers = lists:delete(HandlerId,Handlers0),
-                %% inform the handler
-                _ = call_h(Module,removing_handler,[HandlerId,Config],ok),
-                do_set_config(Tid,logger,Config#{handlers=>Handlers}),
-                logger_config:delete(Tid,HandlerId),
-                ok;
-            _ ->
-                {error,{not_found,HandlerId}}
-        end,
-    {reply,Reply,State};
+    {ok, #state{tid=Tid, async_req_queue = queue:new()}}.
+
+handle_call({add_handler,Id,Module,HConfig}, From, #state{tid=Tid}=State) ->
+    case logger_config:exist(Tid,Id) of
+        true ->
+            {reply,{error,{already_exist,Id}},State};
+        false ->
+            call_h_async(
+              fun() ->
+                      %% inform the handler
+                      call_h(Module,adding_handler,[Id,HConfig],{ok,HConfig})
+              end,
+              fun({ok,HConfig1}) ->
+                      %% We know that the call_h would have loaded the module
+                      %% if it existed, so it is safe here to call function_exported
+                      %% to find out if this is a valid handler
+                      case erlang:function_exported(Module, log, 2) of
+                          true ->
+                              logger_config:create(Tid,Id,Module,HConfig1),
+                              {ok,Config} = do_get_config(Tid,logger),
+                              Handlers = maps:get(handlers,Config,[]),
+                              do_set_config(Tid,logger,
+                                            Config#{handlers=>[Id|Handlers]});
+                          false ->
+                              {error,{invalid_handler,
+                                      {function_not_exported,
+                                       {Module,log,2}}}}
+                      end;
+                 ({error,HReason}) ->
+                      {error,{handler_not_added,HReason}}
+              end,From,State)
+    end;
+handle_call({remove_handler,HandlerId}, From, #state{tid=Tid}=State) ->
+    case logger_config:get(Tid,HandlerId) of
+        {ok,{Module,HConfig}} ->
+            {ok,Config} = do_get_config(Tid,logger),
+            Handlers0 = maps:get(handlers,Config,[]),
+            Handlers = lists:delete(HandlerId,Handlers0),
+            call_h_async(
+              fun() ->
+                      %% inform the handler
+                      call_h(Module,removing_handler,[HandlerId,HConfig],ok)
+              end,
+              fun(_Res) ->
+                      do_set_config(Tid,logger,Config#{handlers=>Handlers}),
+                      logger_config:delete(Tid,HandlerId),
+                      ok
+              end,From,State);
+        _ ->
+            {reply,{error,{not_found,HandlerId}},State}
+    end;
 handle_call({add_filter,Id,Filter}, _From,#state{tid=Tid}=State) ->
     Reply = do_add_filter(Tid,Id,Filter),
     {reply,Reply,State};
 handle_call({remove_filter,Id,FilterId}, _From, #state{tid=Tid}=State) ->
     Reply = do_remove_filter(Tid,Id,FilterId),
     {reply,Reply,State};
-handle_call({update_config,Id,NewConfig}, _From, #state{tid=Tid}=State) ->
-    Reply =
-        case logger_config:get(Tid,Id) of
-            {ok,{Module,OldConfig}} ->
-                Config = maps:merge(OldConfig,NewConfig),
-                case call_h(Module,changing_config,[Id,OldConfig,Config],
-                            {ok,Config}) of
-                    {ok,Config1} ->
-                        do_set_config(Tid,Id,Config1);
-                    Error ->
-                        Error
-                end;
-            {ok,OldConfig} ->
-                Config = maps:merge(OldConfig,NewConfig),
-                do_set_config(Tid,Id,Config);
-            Error ->
-                Error
-        end,
-    {reply,Reply,State};
+handle_call({update_config,Id,NewConfig}, From, #state{tid=Tid}=State) ->
+    case logger_config:get(Tid,Id) of
+        {ok,{_Module,OldConfig}} ->
+            Config = maps:merge(OldConfig,NewConfig),
+            handle_call({set_config,Id,Config}, From, State);
+        {ok,OldConfig} ->
+            Config = maps:merge(OldConfig,NewConfig),
+            {reply,do_set_config(Tid,Id,Config),State};
+        Error ->
+            {reply,Error,State}
+    end;
 handle_call({set_config,logger,Config}, _From, #state{tid=Tid}=State) ->
     Reply = do_set_config(Tid,logger,Config),
     {reply,Reply,State};
-handle_call({set_config,HandlerId,Config}, _From, #state{tid=Tid}=State) ->
-    Reply =
-        case logger_config:get(Tid,HandlerId) of
-            {ok,{Module,OldConfig}} ->
-                case call_h(Module,changing_config,[HandlerId,OldConfig,Config],
-                            {ok,Config}) of
-                    {ok,Config1} ->
-                        do_set_config(Tid,HandlerId,Config1);
-                    Error ->
-                        Error
-                end;
-            _ ->
-                {error,{not_found,HandlerId}}
-        end,
-    {reply,Reply,State};
+handle_call({set_config,HandlerId,Config}, From, #state{tid=Tid}=State) ->
+    case logger_config:get(Tid,HandlerId) of
+        {ok,{Module,OldConfig}} ->
+            call_h_async(
+              fun() ->
+                      call_h(Module,changing_config,[HandlerId,OldConfig,Config],
+                             {ok,Config})
+              end,
+              fun({ok,Config1}) ->
+                      do_set_config(Tid,HandlerId,Config1);
+                 (Error) ->
+                      Error
+              end,From,State);
+        _ ->
+            {reply,{error,{not_found,HandlerId}},State}
+    end;
 handle_call({set_module_level,Module,Level}, _From, #state{tid=Tid}=State) ->
     Reply = logger_config:set_module_level(Tid,Module,Level),
     {reply,Reply,State};
@@ -224,6 +222,8 @@ handle_call({reset_module_level,Module}, _From, #state{tid=Tid}=State) ->
     Reply = logger_config:reset_module_level(Tid,Module),
     {reply,Reply,State}.
 
+handle_cast({async_req_reply,_Ref,_Reply} = Reply,State) ->
+    call_h_reply(Reply,State);
 handle_cast({cache_module_level,Module}, #state{tid=Tid}=State) ->
     logger_config:cache_module_level(Tid,Module),
     {noreply, State}.
@@ -243,11 +243,21 @@ handle_info({log,Level,Report,Meta}, State) ->
 handle_info({Ref,_Reply},State) when is_reference(Ref) ->
     %% Assuming this is a timed-out gen_server reply - ignoring
     {noreply, State};
-handle_info(Unexpected,State) ->
+handle_info({'DOWN',_Ref,_Proc,_Pid,_Reason} = Down,State) ->
+    call_h_reply(Down,State);
+handle_info(Unexpected,State) when element(1,Unexpected) == 'EXIT' ->
+    %% The simple logger will send an 'EXIT' message when it is replaced
+    %% We may as well ignore all 'EXIT' messages that we get
     ?LOG_INTERNAL(debug,
                   [{logger,got_unexpected_message},
                    {process,?SERVER},
                    {message,Unexpected}]),
+    {noreply,State};
+handle_info(Unexpected,State) ->
+    ?LOG_INTERNAL(info,
+                  [{logger,got_unexpected_message},
+                   {process,?SERVER},
+                   {message,Unexpected}]),
     {noreply,State}.
 
 terminate(_Reason, _State) ->
@@ -257,8 +267,11 @@ terminate(_Reason, _State) ->
 %%% Internal functions
 %%%===================================================================
 call(Request) ->
-    case whereis(?SERVER) of
-        Pid when Pid==self() ->
+    Action = element(1,Request),
+    case get(?LOGGER_SERVER_TAG) of
+        true when
+              Action == add_handler; Action == remove_handler;
+              Action == update_config; Action == set_config ->
             {error,{attempting_syncronous_call_to_self,Request}};
         _ ->
             gen_server:call(?SERVER,Request,?DEFAULT_LOGGER_CALL_TIMEOUT)
@@ -448,7 +461,59 @@ call_h(Module, Function, Args, DefRet) ->
                 {error,undef,[{Module,Function,Args,_}|_]} ->
                     DefRet;
                 _ ->
-                    {error,{callback_crashed,
-                            {C,R,logger:filter_stacktrace(?MODULE,S)}}}
+                    ST = logger:filter_stacktrace(?MODULE,S),
+                    ?LOG_INTERNAL(error,
+                                  [{logger,callback_crashed},
+                                   {process,?SERVER},
+                                   {reason,{C,R,ST}}]),
+                    {error,{callback_crashed,{C,R,ST}}}
             end
     end.
+
+%% There are all sort of API functions that can cause deadlocks if called
+%% from the handler callbacks. So we spawn a process that does the request
+%% for the logger_server. There are still APIs that will cause problems,
+%% namely logger:add_handler
+call_h_async(AsyncFun,PostFun,From,#state{ async_req = undefined } = State) ->
+    Parent = self(),
+    {Pid, Ref} = spawn_monitor(
+                    fun() ->
+                            put(?LOGGER_SERVER_TAG,true),
+                            receive Ref -> Ref end,
+                            gen_server:cast(Parent, {async_req_reply, Ref, AsyncFun()})
+                    end),
+    Pid ! Ref,
+    {noreply,State#state{ async_req = {Ref,PostFun,From} }};
+call_h_async(AsyncFun,PostFun,From,#state{ async_req_queue = Q } = State) ->
+    {noreply,State#state{ async_req_queue = queue:in({AsyncFun,PostFun,From},Q) }}.
+
+call_h_reply({async_req_reply,Ref,Reply},
+              #state{ async_req = {Ref,PostFun,From}, async_req_queue = Q} = State) ->
+    erlang:demonitor(Ref,[flush]),
+    _ = gen_server:reply(From, PostFun(Reply)),
+    {Value,NewQ} = queue:out(Q),
+    NewState = State#state{ async_req = undefined,
+                            async_req_queue = NewQ },
+    case Value of
+        {value,{AsyncFun,NPostFun,NFrom}} ->
+            call_h_async(AsyncFun,NPostFun,NFrom,NewState);
+        empty ->
+            {noreply,NewState}
+    end;
+call_h_reply({'DOWN',Ref,_Proc,Pid,Reason}, #state{ async_req = {Ref,_PostFun,_From}} = State) ->
+    %% This clause should only be triggered if someone explicitly sends an exit signal
+    %% to the spawned process. It is only here to make sure that the logger_server does
+    %% not deadlock if that happens.
+    ?LOG_INTERNAL(error,
+                  [{logger,process_exited},
+                   {process,Pid},
+                   {reason,Reason}]),
+    call_h_reply(
+      {async_req_reply,Ref,{error,{logger_process_exited,Pid,Reason}}},
+      State);
+call_h_reply(Unexpected,State) ->
+    ?LOG_INTERNAL(info,
+                  [{logger,got_unexpected_message},
+                   {process,?SERVER},
+                   {message,Unexpected}]),
+    {noreply,State}.
diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl
index 8a757f0078..8c5d4da70d 100644
--- a/lib/kernel/test/logger_SUITE.erl
+++ b/lib/kernel/test/logger_SUITE.erl
@@ -218,14 +218,17 @@ change_config(_Config) ->
     {ok,{?MODULE,#{level:=info,filter_default:=stop}=C2}} =
         logger:get_handler_config(h1),
     false = maps:is_key(custom,C2),
-    {error,fail} = logger:set_handler_config(h1,#{fail=>true}),
+    {error,fail} = logger:set_handler_config(h1,#{conf_call=>fun() -> {error,fail} end}),
     {error,{attempting_syncronous_call_to_self,_}} =
         logger:set_handler_config(
-          h1,#{call=>fun() -> logger:set_module_level(?MODULE,debug) end}),
+          h1,#{conf_call=>fun() -> logger:set_handler_config(?MODULE,#{}) end}),
+    ok =
+        logger:set_handler_config(
+          h1,#{conf_call=>fun() -> logger:set_module_level(?MODULE,debug) end}),
     {ok,{?MODULE,C2}} = logger:get_handler_config(h1),
 
     %% Change one key only
-    {error,fail} = logger:set_handler_config(h1,fail,true),
+    {error,fail} = logger:set_handler_config(h1,conf_call,fun() -> {error,fail} end),
     ok = logger:set_handler_config(h1,custom,custom),
     [changing_config] = test_server:messages_get(),
     {ok,{?MODULE,#{custom:=custom}=C3}} = logger:get_handler_config(h1),
@@ -425,6 +428,7 @@ filter_failed(cleanup,_Config) ->
     ok.
 
 handler_failed(_Config) ->
+    register(callback_receiver,self()),
     {error,{invalid_id,1}} = logger:add_handler(1,?MODULE,#{}),
     {error,{invalid_module,"nomodule"}} = logger:add_handler(h1,"nomodule",#{}),
     {error,{invalid_handler_config,bad}} = logger:add_handler(h1,?MODULE,bad),
@@ -443,17 +447,58 @@ handler_failed(_Config) ->
     false = lists:keymember(h1,1,H1),
     {error,{not_found,h1}} = logger:remove_handler(h1),
 
-    ok = logger:add_handler(h2,?MODULE,#{filter_default=>log,crash=>true}),
+    ok = logger:add_handler(h2,?MODULE,#{filter_default=>log,log_call=>fun() -> a = b end}),
     {error,{already_exist,h2}} = logger:add_handler(h2,othermodule,#{}),
+    [add] = test_server:messages_get(),
 
     logger:info(?map_rep),
-    check_no_log(),
+    [remove] = test_server:messages_get(),
+
     #{logger:=#{handlers:=Ids2},
       handlers:=H2} = logger:i(),
     false = lists:member(h2,Ids2),
     false = lists:keymember(h2,1,H2),
     {error,{not_found,h2}} = logger:remove_handler(h2),
 
+    CallAddHandler = fun() -> logger:add_handler(h2,?MODULE,#{}) end,
+    CrashHandler = fun() -> a = b end,
+    KillHandler = fun() -> exit(self(), die) end,
+
+    {error,{handler_not_added,{attempting_syncronous_call_to_self,_}}} =
+        logger:add_handler(h1,?MODULE,#{add_call=>CallAddHandler}),
+    {error,{handler_not_added,{callback_crashed,_}}} =
+        logger:add_handler(h1,?MODULE,#{add_call=>CrashHandler}),
+    {error,{handler_not_added,{logger_process_exited,_,die}}} =
+        logger:add_handler(h1,?MODULE,#{add_call=>KillHandler}),
+
+    check_no_log(),
+    ok = logger:add_handler(h1,?MODULE,#{}),
+    {error,{attempting_syncronous_call_to_self,_}} =
+        logger:set_handler_config(h1,#{conf_call=>CallAddHandler}),
+    {error,{callback_crashed,_}} =
+        logger:set_handler_config(h1,#{conf_call=>CrashHandler}),
+    {error,{logger_process_exited,_,die}} =
+        logger:set_handler_config(h1,#{conf_call=>KillHandler}),
+
+    {error,{attempting_syncronous_call_to_self,_}} =
+        logger:set_handler_config(h1,conf_call,CallAddHandler),
+    {error,{callback_crashed,_}} =
+        logger:set_handler_config(h1,conf_call,CrashHandler),
+    {error,{logger_process_exited,_,die}} =
+        logger:set_handler_config(h1,conf_call,KillHandler),
+
+    ok = logger:remove_handler(h1),
+    [add,remove] = test_server:messages_get(),
+
+    check_no_log(),
+    ok = logger:add_handler(h1,?MODULE,#{rem_call=>CallAddHandler}),
+    ok = logger:remove_handler(h1),
+    ok = logger:add_handler(h1,?MODULE,#{rem_call=>CrashHandler}),
+    ok = logger:remove_handler(h1),
+    ok = logger:add_handler(h1,?MODULE,#{rem_call=>KillHandler}),
+    ok = logger:remove_handler(h1),
+    [add,add,add] = test_server:messages_get(),
+
     ok.
 
 handler_failed(cleanup,_Config) ->
@@ -720,16 +765,19 @@ check_maps(Expected,Got,What) ->
     end.
 
 %% Handler
+adding_handler(_Id,#{add_call:=Fun}) ->
+    Fun();
 adding_handler(_Id,Config) ->
     maybe_send(add),
     {ok,Config}.
+
+removing_handler(_Id,#{rem_call:=Fun}) ->
+    Fun();
 removing_handler(_Id,_Config) ->
     maybe_send(remove),
     ok.
-changing_config(_Id,_Old,#{call:=Fun}) ->
+changing_config(_Id,_Old,#{conf_call:=Fun}) ->
     Fun();
-changing_config(_Id,_Old,#{fail:=true}) ->
-    {error,fail};
 changing_config(_Id,_Old,Config) ->
     maybe_send(changing_config),
     {ok,Config}.
@@ -740,8 +788,8 @@ maybe_send(Msg) ->
         Pid -> Pid ! Msg
     end.
 
-log(_Log,#{crash:=true}) ->
-    a=b;
+log(_Log,#{log_call:=Fun}) ->
+    Fun();
 log(Log,Config) ->
     TcProc  = maps:get(tc_proc,Config,self()),
     TcProc ! {Log,Config},
diff --git a/lib/kernel/test/logger_env_var_SUITE.erl b/lib/kernel/test/logger_env_var_SUITE.erl
index e976a10b21..764f443634 100644
--- a/lib/kernel/test/logger_env_var_SUITE.erl
+++ b/lib/kernel/test/logger_env_var_SUITE.erl
@@ -58,7 +58,8 @@ groups() ->
                  logger_disk_log_formatter,
                  logger_undefined,
                  logger_many_handlers_default_first,
-                 logger_many_handlers_default_last
+                 logger_many_handlers_default_last,
+                 logger_many_handlers_default_last_broken_filter
                 ]},
      {bad,[],[bad_error_logger,
               bad_level,
@@ -470,6 +471,8 @@ logger_undefined(Config) ->
     false = lists:keymember(sasl_h,1,Hs),
     ok.
 
+
+%% Test that we can add multiple handlers with the default first
 logger_many_handlers_default_first(Config) ->
     LogErr = file(Config,logger_many_handlers_default_first_error),
     LogInfo = file(Config,logger_many_handlers_default_first_info),
@@ -508,6 +511,28 @@ logger_many_handlers_default_last(Config) ->
                 }
                ]}], LogErr, LogInfo, 7).
 
+%% Check that we can handle that an added logger has a broken filter
+%% This used to cause a deadlock.
+logger_many_handlers_default_last_broken_filter(Config) ->
+    LogErr = file(Config,logger_many_handlers_default_first_broken_filter_error),
+    LogInfo = file(Config,logger_many_handlers_default_first_broken_filter_info),
+
+    logger_many_handlers(
+      Config,[{logger,
+               [{handler,info,logger_std_h,
+                 #{level=>info,
+                   filters=>[{broken,{fun logger_filters:level/2,broken_state}},
+                             {level,{fun logger_filters:level/2,{stop,gteq,error}}}],
+                   logger_std_h=>#{type=>{file,LogInfo}}}
+                },
+                {handler,?STANDARD_HANDLER,logger_std_h,
+                 #{level=>error,
+                   filters=>[],
+                   formatter=>{logger_formatter,#{}},
+                   logger_std_h=>#{type=>{file,LogErr}}}
+                }
+               ]}], LogErr, LogInfo, 7).
+
 logger_many_handlers(Config, Env, LogErr, LogInfo, NumProgress) ->
     {ok,#{handlers:=Hs},Node} = setup(Config,Env),
     check_single_log(Node,LogErr,