aboutsummaryrefslogtreecommitdiffstats
path: root/lib/kernel
diff options
context:
space:
mode:
authorLukas Larsson <[email protected]>2018-05-14 11:39:58 +0200
committerLukas Larsson <[email protected]>2018-05-21 17:43:52 +0200
commit3ff770804a27da9add51178b99946ea93d74bd32 (patch)
tree9ceae2ef157b2792255df89467fe06bcdc4fb9d8 /lib/kernel
parent395dbad6bcc38c3384840674f40657273b05b14a (diff)
downloadotp-3ff770804a27da9add51178b99946ea93d74bd32.tar.gz
otp-3ff770804a27da9add51178b99946ea93d74bd32.tar.bz2
otp-3ff770804a27da9add51178b99946ea93d74bd32.zip
kernel: Make all handler callbacks not block logger
Diffstat (limited to 'lib/kernel')
-rw-r--r--lib/kernel/src/logger_server.erl239
-rw-r--r--lib/kernel/test/logger_SUITE.erl68
-rw-r--r--lib/kernel/test/logger_env_var_SUITE.erl27
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,