diff options
Diffstat (limited to 'lib/kernel/src')
47 files changed, 3444 insertions, 2324 deletions
diff --git a/lib/kernel/src/Makefile b/lib/kernel/src/Makefile index c595c25341..fcb599859b 100644 --- a/lib/kernel/src/Makefile +++ b/lib/kernel/src/Makefile @@ -112,15 +112,17 @@ MODULES = \ logger \ logger_backend \ logger_config \ - logger_std_h \ + logger_handler_watcher \ + logger_std_h \ logger_disk_log_h \ logger_h_common \ logger_filters \ logger_formatter \ + logger_olp \ + logger_proxy \ logger_server \ logger_simple_h \ logger_sup \ - net \ net_adm \ net_kernel \ os \ @@ -150,7 +152,7 @@ INTERNAL_HRL_FILES= application_master.hrl disk_log.hrl \ inet_dns.hrl inet_res.hrl \ inet_boot.hrl inet_config.hrl inet_int.hrl \ inet_dns_record_adts.hrl \ - logger_internal.hrl logger_h_common.hrl + logger_internal.hrl logger_olp.hrl logger_h_common.hrl ERL_FILES= $(MODULES:%=%.erl) @@ -173,8 +175,10 @@ APPUP_TARGET= $(EBIN)/$(APPUP_FILE) ifeq ($(NATIVE_LIBS_ENABLED),yes) ERL_COMPILE_FLAGS += +native +else +ERL_COMPILE_FLAGS += -Werror endif -ERL_COMPILE_FLAGS += -I../include -Werror +ERL_COMPILE_FLAGS += -I../include # ---------------------------------------------------- # Targets @@ -278,6 +282,8 @@ $(EBIN)/logger_config.beam: logger_internal.hrl ../include/logger.hrl $(EBIN)/logger_disk_log_h.beam: logger_h_common.hrl logger_internal.hrl ../include/logger.hrl ../include/file.hrl $(EBIN)/logger_filters.beam: logger_internal.hrl ../include/logger.hrl $(EBIN)/logger_formatter.beam: logger_internal.hrl ../include/logger.hrl +$(EBIN)/logger_olp.beam: logger_olp.hrl logger_internal.hrl +$(EBIN)/logger_proxy.beam: logger_internal.hrl $(EBIN)/logger_server.beam: logger_internal.hrl ../include/logger.hrl $(EBIN)/logger_simple_h.beam: logger_internal.hrl ../include/logger.hrl $(EBIN)/logger_std_h.beam: logger_h_common.hrl logger_internal.hrl ../include/logger.hrl ../include/file.hrl diff --git a/lib/kernel/src/application.erl b/lib/kernel/src/application.erl index bc6be2f8f5..5c2e981e4b 100644 --- a/lib/kernel/src/application.erl +++ b/lib/kernel/src/application.erl @@ -25,7 +25,7 @@ which_applications/0, which_applications/1, loaded_applications/0, permit/2]). -export([ensure_started/1, ensure_started/2]). --export([set_env/3, set_env/4, unset_env/2, unset_env/3]). +-export([set_env/1, set_env/2, set_env/3, set_env/4, unset_env/2, unset_env/3]). -export([get_env/1, get_env/2, get_env/3, get_all_env/0, get_all_env/1]). -export([get_key/1, get_key/2, get_all_key/0, get_all_key/1]). -export([get_application/0, get_application/1, info/0]). @@ -279,6 +279,26 @@ loaded_applications() -> info() -> application_controller:info(). +-spec set_env(Config) -> 'ok' when + Config :: [{Application, Env}], + Application :: atom(), + Env :: [{Par :: atom(), Val :: term()}]. + +set_env(Config) when is_list(Config) -> + set_env(Config, []). + +-spec set_env(Config, Opts) -> 'ok' when + Config :: [{Application, Env}], + Application :: atom(), + Env :: [{Par :: atom(), Val :: term()}], + Opts :: [{timeout, timeout()} | {persistent, boolean()}]. + +set_env(Config, Opts) when is_list(Config), is_list(Opts) -> + case application_controller:set_env(Config, Opts) of + ok -> ok; + {error, Msg} -> erlang:error({badarg, Msg}, [Config, Opts]) + end. + -spec set_env(Application, Par, Val) -> 'ok' when Application :: atom(), Par :: atom(), diff --git a/lib/kernel/src/application_controller.erl b/lib/kernel/src/application_controller.erl index a074d2e74b..7715dca7c6 100644 --- a/lib/kernel/src/application_controller.erl +++ b/lib/kernel/src/application_controller.erl @@ -26,7 +26,7 @@ control_application/1, change_application_data/2, prep_config_change/0, config_change/1, which_applications/0, which_applications/1, - loaded_applications/0, info/0, + loaded_applications/0, info/0, set_env/2, get_pid_env/2, get_env/2, get_pid_all_env/1, get_all_env/1, get_pid_key/2, get_key/2, get_pid_all_key/1, get_all_key/1, get_master/1, get_application/1, get_application_module/1, @@ -345,9 +345,6 @@ get_all_env(AppName) -> map(fun([Key, Val]) -> {Key, Val} end, ets:match(ac_tab, {{env, AppName, '$1'}, '$2'})). - - - get_pid_key(Master, Key) -> case ets:match(ac_tab, {{application_master, '$1'}, Master}) of [[AppName]] -> get_key(AppName, Key); @@ -461,6 +458,15 @@ permit_application(ApplName, Flag) -> {permit_application, ApplName, Flag}, infinity). +set_env(Config, Opts) -> + case check_conf_data(Config) of + ok -> + Timeout = proplists:get_value(timeout, Opts, 5000), + gen_server:call(?AC, {set_env, Config, Opts}, Timeout); + + {error, _} = Error -> + Error + end. set_env(AppName, Key, Val) -> gen_server:call(?AC, {set_env, AppName, Key, Val, []}). @@ -528,19 +534,15 @@ check_conf_data([]) -> check_conf_data(ConfData) when is_list(ConfData) -> [Application | ConfDataRem] = ConfData, case Application of - {kernel, List} when is_list(List) -> - case check_para_kernel(List) of - ok -> - check_conf_data(ConfDataRem); - Error1 -> - Error1 - end; {AppName, List} when is_atom(AppName), is_list(List) -> - case check_para(List, atom_to_list(AppName)) of - ok -> - check_conf_data(ConfDataRem); - Error2 -> - Error2 + case lists:keymember(AppName, 1, ConfDataRem) of + true -> + {error, "duplicate application config: " ++ atom_to_list(AppName)}; + false -> + case check_para(List, AppName) of + ok -> check_conf_data(ConfDataRem); + Error -> Error + end end; {AppName, List} when is_list(List) -> ErrMsg = "application: " @@ -553,36 +555,39 @@ check_conf_data(ConfData) when is_list(ConfData) -> ++ "; parameters must be a list", {error, ErrMsg}; Else -> - ErrMsg = "invalid application name: " ++ - lists:flatten(io_lib:format(" ~tp",[Else])), + ErrMsg = "invalid application config: " + ++ lists:flatten(io_lib:format("~tp",[Else])), {error, ErrMsg} end; check_conf_data(_ConfData) -> - {error, 'configuration must be a list ended by <dot><whitespace>'}. - + {error, "configuration must be a list ended by <dot><whitespace>"}. -%% Special check of distributed parameter for kernel -check_para_kernel([]) -> + +check_para([], _AppName) -> ok; -check_para_kernel([{distributed, Apps} | ParaList]) when is_list(Apps) -> - case check_distributed(Apps) of - {error, _ErrorMsg} = Error -> - Error; - _ -> - check_para_kernel(ParaList) +check_para([{Para, Val} | ParaList], AppName) when is_atom(Para) -> + case lists:keymember(Para, 1, ParaList) of + true -> + ErrMsg = "application: " ++ atom_to_list(AppName) + ++ "; duplicate parameter: " ++ atom_to_list(Para), + {error, ErrMsg}; + false -> + case check_para_value(Para, Val, AppName) of + ok -> check_para(ParaList, AppName); + {error, _} = Error -> Error + end end; -check_para_kernel([{distributed, _Apps} | _ParaList]) -> - {error, "application: kernel; erroneous parameter: distributed"}; -check_para_kernel([{Para, _Val} | ParaList]) when is_atom(Para) -> - check_para_kernel(ParaList); -check_para_kernel([{Para, _Val} | _ParaList]) -> - {error, "application: kernel; invalid parameter: " ++ +check_para([{Para, _Val} | _ParaList], AppName) -> + {error, "application: " ++ atom_to_list(AppName) ++ "; invalid parameter name: " ++ lists:flatten(io_lib:format("~tp",[Para]))}; -check_para_kernel(Else) -> - {error, "application: kernel; invalid parameter list: " ++ +check_para([Else | _ParaList], AppName) -> + {error, "application: " ++ atom_to_list(AppName) ++ "; invalid parameter: " ++ lists:flatten(io_lib:format("~tp",[Else]))}. - +check_para_value(distributed, Apps, kernel) -> check_distributed(Apps); +check_para_value(_Para, _Val, _AppName) -> ok. + +%% Special check of distributed parameter for kernel check_distributed([]) -> ok; check_distributed([{App, List} | Apps]) when is_atom(App), is_list(List) -> @@ -595,18 +600,6 @@ check_distributed(_Else) -> {error, "application: kernel; erroneous parameter: distributed"}. -check_para([], _AppName) -> - ok; -check_para([{Para, _Val} | ParaList], AppName) when is_atom(Para) -> - check_para(ParaList, AppName); -check_para([{Para, _Val} | _ParaList], AppName) -> - {error, "application: " ++ AppName ++ "; invalid parameter: " ++ - lists:flatten(io_lib:format("~tp",[Para]))}; -check_para([Else | _ParaList], AppName) -> - {error, "application: " ++ AppName ++ "; invalid parameter: " ++ - lists:flatten(io_lib:format("~tp",[Else]))}. - - -type calls() :: 'info' | 'prep_config_change' | 'which_applications' | {'config_change' | 'control_application' | 'load_application' | 'start_type' | 'stop_application' | @@ -863,6 +856,16 @@ handle_call(which_applications, _From, S) -> end, S#state.running), {reply, Reply, S}; +handle_call({set_env, Config, Opts}, _From, S) -> + _ = [add_env(AppName, Env) || {AppName, Env} <- Config], + + case proplists:get_value(persistent, Opts, false) of + true -> + {reply, ok, S#state{conf_data = merge_env(S#state.conf_data, Config)}}; + false -> + {reply, ok, S} + end; + handle_call({set_env, AppName, Key, Val, Opts}, _From, S) -> ets:insert(ac_tab, {{env, AppName, Key}, Val}), case proplists:get_value(persistent, Opts, false) of diff --git a/lib/kernel/src/code_server.erl b/lib/kernel/src/code_server.erl index 1b4a67ecb7..68e1205301 100644 --- a/lib/kernel/src/code_server.erl +++ b/lib/kernel/src/code_server.erl @@ -1434,19 +1434,25 @@ all_loaded(Db) -> -spec error_msg(io:format(), [term()]) -> 'ok'. error_msg(Format, Args) -> + %% This is equal to calling logger:error/3 which we don't want to + %% do from code_server. We don't want to call logger:timestamp() + %% either. logger ! {log,error,Format,Args, #{pid=>self(), gl=>group_leader(), - time=>erlang:system_time(microsecond), + time=>os:system_time(microsecond), error_logger=>#{tag=>error}}}, ok. -spec info_msg(io:format(), [term()]) -> 'ok'. info_msg(Format, Args) -> + %% This is equal to calling logger:info/3 which we don't want to + %% do from code_server. We don't want to call logger:timestamp() + %% either. logger ! {log,info,Format,Args, #{pid=>self(), gl=>group_leader(), - time=>erlang:system_time(microsecond), + time=>os:system_time(microsecond), error_logger=>#{tag=>info_msg}}}, ok. diff --git a/lib/kernel/src/dist_util.erl b/lib/kernel/src/dist_util.erl index ecc022b28d..09ed31f10c 100644 --- a/lib/kernel/src/dist_util.erl +++ b/lib/kernel/src/dist_util.erl @@ -116,6 +116,10 @@ dflag2str(?DFLAG_SEND_SENDER) -> "SEND_SENDER"; dflag2str(?DFLAG_BIG_SEQTRACE_LABELS) -> "BIG_SEQTRACE_LABELS"; +dflag2str(?DFLAG_EXIT_PAYLOAD) -> + "EXIT_PAYLOAD"; +dflag2str(?DFLAG_FRAGMENTS) -> + "FRAGMENTS"; dflag2str(_) -> "UNKNOWN". diff --git a/lib/kernel/src/erl_distribution.erl b/lib/kernel/src/erl_distribution.erl index 0bec78e938..cdb2d2f1f6 100644 --- a/lib/kernel/src/erl_distribution.erl +++ b/lib/kernel/src/erl_distribution.erl @@ -21,6 +21,8 @@ -behaviour(supervisor). +-include_lib("kernel/include/logger.hrl"). + -export([start_link/0,start_link/2,init/1,start/1,stop/0]). -define(DBG,erlang:display([?MODULE,?LINE])). @@ -83,6 +85,10 @@ do_start_link([{Arg,Flag}|T]) -> case init:get_argument(Arg) of {ok,[[Name]]} -> start_link([list_to_atom(Name),Flag|ticktime()], true); + {ok,[[Name]|_Rest]} -> + ?LOG_WARNING("Multiple -~p given to erl, using the first, ~p", + [Arg, Name]), + start_link([list_to_atom(Name),Flag|ticktime()], true); _ -> do_start_link(T) end; diff --git a/lib/kernel/src/erl_epmd.erl b/lib/kernel/src/erl_epmd.erl index b7e8868911..7a14e2635c 100644 --- a/lib/kernel/src/erl_epmd.erl +++ b/lib/kernel/src/erl_epmd.erl @@ -77,8 +77,8 @@ stop() -> %% -spec port_please(Name, Host) -> {ok, Port, Version} | noport when - Name :: string(), - Host :: inet:ip_address(), + Name :: atom() | string(), + Host :: atom() | string() | inet:ip_address(), Port :: non_neg_integer(), Version :: non_neg_integer(). @@ -86,8 +86,8 @@ port_please(Node, Host) -> port_please(Node, Host, infinity). -spec port_please(Name, Host, Timeout) -> {ok, Port, Version} | noport when - Name :: string(), - Host :: inet:ip_address(), + Name :: atom() | string(), + Host :: atom() | string() | inet:ip_address(), Timeout :: non_neg_integer() | infinity, Port :: non_neg_integer(), Version :: non_neg_integer(). diff --git a/lib/kernel/src/error_logger.erl b/lib/kernel/src/error_logger.erl index a7e7f19167..e324be5290 100644 --- a/lib/kernel/src/error_logger.erl +++ b/lib/kernel/src/error_logger.erl @@ -74,8 +74,8 @@ start() -> type => worker, modules => dynamic}, case supervisor:start_child(logger_sup, ErrorLogger) of - {ok,_} -> - ok; + {ok,Pid} -> + ok = logger_handler_watcher:register_handler(?MODULE,Pid); Error -> Error end; @@ -95,9 +95,14 @@ start_link() -> %%% Stop the event manager -spec stop() -> ok. stop() -> - _ = supervisor:terminate_child(logger_sup,?MODULE), - _ = supervisor:delete_child(logger_sup,?MODULE), - ok. + case whereis(?MODULE) of + undefined -> + ok; + _Pid -> + _ = gen_event:stop(?MODULE,{shutdown,stopped},infinity), + _ = supervisor:delete_child(logger_sup,?MODULE), + ok + end. %%%----------------------------------------------------------------- %%% Callbacks for logger @@ -142,14 +147,27 @@ do_log(Level,{report,Msg},#{?MODULE:=#{tag:=Tag}}=Meta) -> _ -> %% From logger call which added error_logger data to %% obtain backwards compatibility with error_logger:*_msg/1,2 - RCBFun=maps:get(report_cb,Meta,fun logger:format_report/1), - try RCBFun(Msg) of - {F,A} when is_list(F), is_list(A) -> - {F,A}; - Other -> - {"REPORT_CB ERROR: ~tp; Returned: ~tp",[Msg,Other]} - catch C:R -> - {"REPORT_CB CRASH: ~tp; Reason: ~tp",[Msg,{C,R}]} + case maps:get(report_cb,Meta,fun logger:format_report/1) of + RCBFun when is_function(RCBFun,1) -> + try RCBFun(Msg) of + {F,A} when is_list(F), is_list(A) -> + {F,A}; + Other -> + {"REPORT_CB ERROR: ~tp; Returned: ~tp",[Msg,Other]} + catch C:R -> + {"REPORT_CB CRASH: ~tp; Reason: ~tp",[Msg,{C,R}]} + end; + RCBFun when is_function(RCBFun,2) -> + try RCBFun(Msg,#{depth=>get_format_depth(), + chars_limit=>unlimited, + single_line=>false}) of + Chardata when ?IS_STRING(Chardata) -> + {"~ts",[Chardata]}; + Other -> + {"REPORT_CB ERROR: ~tp; Returned: ~tp",[Msg,Other]} + catch C:R -> + {"REPORT_CB CRASH: ~tp; Reason: ~tp",[Msg,{C,R}]} + end end end, notify(Level,Tag,Format,Args,Meta); diff --git a/lib/kernel/src/erts_debug.erl b/lib/kernel/src/erts_debug.erl index 1270de4144..e6a30d0b92 100644 --- a/lib/kernel/src/erts_debug.erl +++ b/lib/kernel/src/erts_debug.erl @@ -33,10 +33,12 @@ -export([breakpoint/2, disassemble/1, display/1, dist_ext_to_term/2, flat_size/1, get_internal_state/1, instructions/0, + interpreter_size/0, map_info/1, same/2, set_internal_state/2, size_shared/1, copy_shared/1, dirty_cpu/2, dirty_io/2, dirty/3, lcnt_control/1, lcnt_control/2, lcnt_collect/0, lcnt_clear/0, - lc_graph/0, lc_graph_to_dot/2, lc_graph_merge/2]). + lc_graph/0, lc_graph_to_dot/2, lc_graph_merge/2, + alloc_blocks_size/1]). -spec breakpoint(MFA, Flag) -> non_neg_integer() when MFA :: {Module :: module(), @@ -117,6 +119,11 @@ get_internal_state(_) -> instructions() -> erlang:nif_error(undef). +-spec interpreter_size() -> pos_integer(). + +interpreter_size() -> + erlang:nif_error(undef). + -spec ic(F) -> Result when F :: function(), Result :: term(). @@ -495,3 +502,58 @@ lcg_print_locks(Out, [LastLock]) -> lcg_print_locks(Out, [Lock | Rest]) -> io:format(Out, "~w,\n", [Lock]), lcg_print_locks(Out, Rest). + + +%% Returns the amount of memory allocated by the given allocator type. +-spec alloc_blocks_size(Type) -> non_neg_integer() | undefined when + Type :: atom(). + +alloc_blocks_size(Type) -> + Allocs = erlang:system_info(alloc_util_allocators), + Sizes = erlang:system_info({allocator_sizes, Allocs}), + alloc_blocks_size_1(Sizes, Type, 0). + +alloc_blocks_size_1([], _Type, 0) -> + undefined; +alloc_blocks_size_1([{_Type, false} | Rest], Type, Acc) -> + alloc_blocks_size_1(Rest, Type, Acc); +alloc_blocks_size_1([{Type, Instances} | Rest], Type, Acc0) -> + F = fun ({instance, _, L}, Acc) -> + MBCSPool = case lists:keyfind(mbcs_pool, 1, L) of + {_, Pool} -> Pool; + false -> [] + end, + {_,MBCS} = lists:keyfind(mbcs, 1, L), + {_,SBCS} = lists:keyfind(sbcs, 1, L), + Acc + + sum_block_sizes(MBCSPool) + + sum_block_sizes(MBCS) + + sum_block_sizes(SBCS) + end, + alloc_blocks_size_1(Rest, Type, lists:foldl(F, Acc0, Instances)); +alloc_blocks_size_1([{_Type, Instances} | Rest], Type, Acc0) -> + F = fun ({instance, _, L}, Acc) -> + Acc + sum_foreign_sizes(Type, L) + end, + alloc_blocks_size_1(Rest, Type, lists:foldl(F, Acc0, Instances)); +alloc_blocks_size_1([], _Type, Acc) -> + Acc. + +sum_foreign_sizes(Type, L) -> + case lists:keyfind(mbcs_pool, 1, L) of + {_,Pool} -> + {_,ForeignBlocks} = lists:keyfind(foreign_blocks, 1, Pool), + case lists:keyfind(Type, 1, ForeignBlocks) of + {_,TypeSizes} -> sum_block_sizes(TypeSizes); + false -> 0 + end; + _ -> + 0 + end. + +sum_block_sizes(Blocks) -> + lists:foldl( + fun({blocks_size, Sz,_,_}, Sz0) -> Sz0+Sz; + ({blocks_size, Sz}, Sz0) -> Sz0+Sz; + (_, Sz) -> Sz + end, 0, Blocks). diff --git a/lib/kernel/src/gen_sctp.erl b/lib/kernel/src/gen_sctp.erl index bf795ee9c6..d893d44079 100644 --- a/lib/kernel/src/gen_sctp.erl +++ b/lib/kernel/src/gen_sctp.erl @@ -66,7 +66,12 @@ {sctp_set_peer_primary_addr, #sctp_setpeerprim{}} | {sctp_status, #sctp_status{}} | {sndbuf, non_neg_integer()} | - {tos, non_neg_integer()}. + {tos, non_neg_integer()} | + {tclass, non_neg_integer()} | + {ttl, non_neg_integer()} | + {recvtos, boolean()} | + {recvtclass, boolean()} | + {recvttl, boolean()}. -type option_name() :: active | buffer | @@ -97,7 +102,12 @@ sctp_set_peer_primary_addr | sctp_status | sndbuf | - tos. + tos | + tclass | + ttl | + recvtos | + recvtclass | + recvttl. -type sctp_socket() :: port(). -export_type([assoc_id/0, option/0, option_name/0, sctp_socket/0]). @@ -365,7 +375,7 @@ send(S, AssocChange, Stream, Data) -> Socket :: sctp_socket(), FromIP :: inet:ip_address(), FromPort :: inet:port_number(), - AncData :: [#sctp_sndrcvinfo{}], + AncData :: [#sctp_sndrcvinfo{} | inet:ancillary_data()], Data :: binary() | string() | #sctp_sndrcvinfo{} | #sctp_assoc_change{} | #sctp_paddr_change{} | #sctp_adaptation_event{}, @@ -382,7 +392,7 @@ recv(S) -> Timeout :: timeout(), FromIP :: inet:ip_address(), FromPort :: inet:port_number(), - AncData :: [#sctp_sndrcvinfo{}], + AncData :: [#sctp_sndrcvinfo{} | inet:ancillary_data()], Data :: binary() | string() | #sctp_sndrcvinfo{} | #sctp_assoc_change{} | #sctp_paddr_change{} | #sctp_adaptation_event{}, diff --git a/lib/kernel/src/gen_tcp.erl b/lib/kernel/src/gen_tcp.erl index c61411e814..5d4764f8ff 100644 --- a/lib/kernel/src/gen_tcp.erl +++ b/lib/kernel/src/gen_tcp.erl @@ -62,7 +62,14 @@ {show_econnreset, boolean()} | {sndbuf, non_neg_integer()} | {tos, non_neg_integer()} | + {tclass, non_neg_integer()} | + {ttl, non_neg_integer()} | + {recvtos, boolean()} | + {recvtclass, boolean()} | + {recvttl, boolean()} | {ipv6_v6only, boolean()}. +-type pktoptions_value() :: + {pktoptions, inet:ancillary_data()}. -type option_name() :: active | buffer | @@ -81,6 +88,7 @@ nodelay | packet | packet_size | + pktoptions | priority | {raw, Protocol :: non_neg_integer(), @@ -94,6 +102,12 @@ show_econnreset | sndbuf | tos | + tclass | + ttl | + recvtos | + recvtclass | + recvttl | + pktoptions | ipv6_v6only. -type connect_option() :: {ip, inet:socket_address()} | @@ -119,7 +133,7 @@ -type socket() :: port(). -export_type([option/0, option_name/0, connect_option/0, listen_option/0, - socket/0]). + socket/0, pktoptions_value/0]). %% %% Connect a socket @@ -142,7 +156,7 @@ connect(Address, Port, Opts) -> Options :: [connect_option()], Timeout :: timeout(), Socket :: socket(), - Reason :: inet:posix(). + Reason :: timeout | inet:posix(). connect(Address, Port, Opts, Time) -> Timer = inet:start_timer(Time), @@ -206,7 +220,7 @@ listen(Port, Opts0) -> -spec accept(ListenSocket) -> {ok, Socket} | {error, Reason} when ListenSocket :: socket(), Socket :: socket(), - Reason :: closed | timeout | system_limit | inet:posix(). + Reason :: closed | system_limit | inet:posix(). accept(S) -> case inet_db:lookup_socket(S) of @@ -298,7 +312,7 @@ recv(S, Length) when is_port(S) -> Length :: non_neg_integer(), Timeout :: timeout(), Packet :: string() | binary() | HttpPacket, - Reason :: closed | inet:posix(), + Reason :: closed | timeout | inet:posix(), HttpPacket :: term(). recv(S, Length, Time) when is_port(S) -> diff --git a/lib/kernel/src/gen_udp.erl b/lib/kernel/src/gen_udp.erl index 44eef9f3c5..fad7b2f887 100644 --- a/lib/kernel/src/gen_udp.erl +++ b/lib/kernel/src/gen_udp.erl @@ -51,6 +51,11 @@ {reuseaddr, boolean()} | {sndbuf, non_neg_integer()} | {tos, non_neg_integer()} | + {tclass, non_neg_integer()} | + {ttl, non_neg_integer()} | + {recvtos, boolean()} | + {recvtclass, boolean()} | + {recvttl, boolean()} | {ipv6_v6only, boolean()}. -type option_name() :: active | @@ -76,6 +81,12 @@ reuseaddr | sndbuf | tos | + tclass | + ttl | + recvtos | + recvtclass | + recvttl | + pktoptions | ipv6_v6only. -type socket() :: port(). @@ -84,7 +95,7 @@ -spec open(Port) -> {ok, Socket} | {error, Reason} when Port :: inet:port_number(), Socket :: socket(), - Reason :: inet:posix(). + Reason :: system_limit | inet:posix(). open(Port) -> open(Port, []). @@ -101,7 +112,7 @@ open(Port) -> | {bind_to_device, binary()} | option(), Socket :: socket(), - Reason :: inet:posix(). + Reason :: system_limit | inet:posix(). open(Port, Opts0) -> {Mod, Opts} = inet:udp_module(Opts0), @@ -147,11 +158,13 @@ send(S, Packet) when is_port(S) -> end. -spec recv(Socket, Length) -> - {ok, {Address, Port, Packet}} | {error, Reason} when + {ok, RecvData} | {error, Reason} when Socket :: socket(), Length :: non_neg_integer(), + RecvData :: {Address, Port, Packet} | {Address, Port, AncData, Packet}, Address :: inet:ip_address() | inet:returned_non_ip_address(), Port :: inet:port_number(), + AncData :: inet:ancillary_data(), Packet :: string() | binary(), Reason :: not_owner | inet:posix(). @@ -164,14 +177,16 @@ recv(S,Len) when is_port(S), is_integer(Len) -> end. -spec recv(Socket, Length, Timeout) -> - {ok, {Address, Port, Packet}} | {error, Reason} when + {ok, RecvData} | {error, Reason} when Socket :: socket(), Length :: non_neg_integer(), Timeout :: timeout(), + RecvData :: {Address, Port, Packet} | {Address, Port, AncData, Packet}, Address :: inet:ip_address() | inet:returned_non_ip_address(), Port :: inet:port_number(), + AncData :: inet:ancillary_data(), Packet :: string() | binary(), - Reason :: not_owner | inet:posix(). + Reason :: not_owner | timeout | inet:posix(). recv(S,Len,Time) when is_port(S) -> case inet_db:lookup_socket(S) of diff --git a/lib/kernel/src/global.erl b/lib/kernel/src/global.erl index a38522eb5c..3875074d74 100644 --- a/lib/kernel/src/global.erl +++ b/lib/kernel/src/global.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1996-2017. All Rights Reserved. +%% Copyright Ericsson AB 1996-2019. 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. @@ -50,10 +50,9 @@ %% This is for backward compatibility only; the functionality is broken. -define(WARN_DUPLICATED_NAME, global_multi_name_action). -%% Undocumented Kernel variable. Set this to 0 (zero) to get the old -%% behaviour. +%% Undocumented Kernel variable. -define(N_CONNECT_RETRIES, global_connect_retries). --define(DEFAULT_N_CONNECT_RETRIES, 5). +-define(DEFAULT_N_CONNECT_RETRIES, 0). %%% In certain places in the server, calling io:format hangs everything, %%% so we'd better use erlang:display/1. @@ -125,16 +124,12 @@ %%% There are also ETS tables used for bookkeeping of locks and names %%% (the first position is the key): %%% -%%% global_locks (set): {ResourceId, LockRequesterId, [{Pid,RPid,ref()]} +%%% global_locks (set): {ResourceId, LockRequesterId, [{Pid,ref()]} %%% Pid is locking ResourceId, ref() is the monitor ref. -%%% RPid =/= Pid if there is an extra process calling erlang:monitor(). -%%% global_names (set): {Name, Pid, Method, RPid, ref()} +%%% global_names (set): {Name, Pid, Method, ref()} %%% Registered names. ref() is the monitor ref. -%%% RPid =/= Pid if there is an extra process calling erlang:monitor(). %%% global_names_ext (set): {Name, Pid, RegNode} %%% External registered names (C-nodes). -%%% (The RPid:s can be removed when/if erlang:monitor() returns before -%%% trying to connect to the other node.) %%% %%% Helper tables: %%% global_pid_names (bag): {Pid, Name} | {ref(), Name} @@ -310,7 +305,7 @@ re_register_name(Name, Pid, Method0) when is_pid(Pid) -> -spec registered_names() -> [Name] when Name :: term(). registered_names() -> - MS = ets:fun2ms(fun({Name,_Pid,_M,_RP,_R}) -> Name end), + MS = ets:fun2ms(fun({Name,_Pid,_M,_R}) -> Name end), ets:select(global_names, MS). %%----------------------------------------------------------------- @@ -1235,7 +1230,7 @@ ins_name_ext(Name, Pid, Method, RegNode, FromPidOrNode, ExtraInfo, S0) -> where(Name) -> case ets:lookup(global_names, Name) of - [{_Name, Pid, _Method, _RPid, _Ref}] -> + [{_Name, Pid, _Method, _Ref}] -> if node(Pid) == node() -> case is_process_alive(Pid) of true -> Pid; @@ -1272,10 +1267,10 @@ can_set_lock({ResourceId, LockRequesterId}) -> end. insert_lock({ResourceId, LockRequesterId}=Id, Pid, PidRefs, S) -> - {RPid, Ref} = do_monitor(Pid), + Ref = erlang:monitor(process, Pid), true = ets:insert(global_pid_ids, {Pid, ResourceId}), true = ets:insert(global_pid_ids, {Ref, ResourceId}), - Lock = {ResourceId, LockRequesterId, [{Pid,RPid,Ref} | PidRefs]}, + Lock = {ResourceId, LockRequesterId, [{Pid,Ref} | PidRefs]}, true = ets:insert(global_locks, Lock), trace_message(S, {ins_lock, node(Pid)}, [Id, Pid]). @@ -1293,10 +1288,9 @@ handle_del_lock({ResourceId, LockReqId}, Pid, S0) -> _ -> S0 end. -remove_lock(ResourceId, LockRequesterId, Pid, [{Pid,RPid,Ref}], Down, S0) -> +remove_lock(ResourceId, LockRequesterId, Pid, [{Pid,Ref}], Down, S0) -> ?trace({remove_lock_1, {id,ResourceId},{pid,Pid}}), true = erlang:demonitor(Ref, [flush]), - kill_monitor_proc(RPid, Pid), true = ets:delete(global_locks, ResourceId), true = ets:delete_object(global_pid_ids, {Pid, ResourceId}), true = ets:delete_object(global_pid_ids, {Ref, ResourceId}), @@ -1309,9 +1303,8 @@ remove_lock(ResourceId, LockRequesterId, Pid, [{Pid,RPid,Ref}], Down, S0) -> remove_lock(ResourceId, LockRequesterId, Pid, PidRefs0, _Down, S) -> ?trace({remove_lock_2, {id,ResourceId},{pid,Pid}}), PidRefs = case lists:keyfind(Pid, 1, PidRefs0) of - {Pid, RPid, Ref} -> + {Pid, Ref} -> true = erlang:demonitor(Ref, [flush]), - kill_monitor_proc(RPid, Pid), true = ets:delete_object(global_pid_ids, {Ref, ResourceId}), lists:keydelete(Pid, 1, PidRefs0); @@ -1324,11 +1317,6 @@ remove_lock(ResourceId, LockRequesterId, Pid, PidRefs0, _Down, S) -> trace_message(S, {rem_lock, node(Pid)}, [{ResourceId, LockRequesterId}, Pid]). -kill_monitor_proc(Pid, Pid) -> - ok; -kill_monitor_proc(RPid, _Pid) -> - exit(RPid, kill). - do_ops(Ops, ConnNode, Names_ext, ExtraInfo, S0) -> ?trace({do_ops, {ops,Ops}}), @@ -1394,8 +1382,8 @@ sync_other(Node, N) -> % exit(normal). insert_global_name(Name, Pid, Method, FromPidOrNode, ExtraInfo, S) -> - {RPid, Ref} = do_monitor(Pid), - true = ets:insert(global_names, {Name, Pid, Method, RPid, Ref}), + Ref = erlang:monitor(process, Pid), + true = ets:insert(global_names, {Name, Pid, Method, Ref}), true = ets:insert(global_pid_names, {Pid, Name}), true = ets:insert(global_pid_names, {Ref, Name}), case lock_still_set(FromPidOrNode, ExtraInfo, S) of @@ -1437,7 +1425,7 @@ extra_info(Tag, ExtraInfo) -> del_name(Ref, S) -> NameL = [Name || {_, Name} <- ets:lookup(global_pid_names, Ref), - {_, _Pid, _Method, _RPid, Ref1} <- + {_, _Pid, _Method, Ref1} <- ets:lookup(global_names, Name), Ref1 =:= Ref], case NameL of @@ -1450,24 +1438,23 @@ del_name(Ref, S) -> %% Keeps the entry in global_names for whereis_name/1. delete_global_name_keep_pid(Name, S) -> case ets:lookup(global_names, Name) of - [{Name, Pid, _Method, RPid, Ref}] -> - delete_global_name2(Name, Pid, RPid, Ref, S); + [{Name, Pid, _Method, Ref}] -> + delete_global_name2(Name, Pid, Ref, S); [] -> S end. delete_global_name2(Name, S) -> case ets:lookup(global_names, Name) of - [{Name, Pid, _Method, RPid, Ref}] -> + [{Name, Pid, _Method, Ref}] -> true = ets:delete(global_names, Name), - delete_global_name2(Name, Pid, RPid, Ref, S); + delete_global_name2(Name, Pid, Ref, S); [] -> S end. -delete_global_name2(Name, Pid, RPid, Ref, S) -> +delete_global_name2(Name, Pid, Ref, S) -> true = erlang:demonitor(Ref, [flush]), - kill_monitor_proc(RPid, Pid), delete_global_name(Name, Pid), ?trace({delete_global_name,{item,Name},{pid,Pid}}), true = ets:delete_object(global_pid_names, {Pid, Name}), @@ -1929,9 +1916,9 @@ reset_node_state(Node) -> %% from the same partition. exchange_names([{Name, Pid, Method} | Tail], Node, Ops, Res) -> case ets:lookup(global_names, Name) of - [{Name, Pid, _Method, _RPid2, _Ref2}] -> + [{Name, Pid, _Method, _Ref2}] -> exchange_names(Tail, Node, Ops, Res); - [{Name, Pid2, Method2, _RPid2, _Ref2}] when node() < Node -> + [{Name, Pid2, Method2, _Ref2}] when node() < Node -> %% Name clash! Add the result of resolving to Res(olved). %% We know that node(Pid) =/= node(), so we don't %% need to link/unlink to Pid. @@ -1960,7 +1947,7 @@ exchange_names([{Name, Pid, Method} | Tail], Node, Ops, Res) -> Op = {delete, Name}, exchange_names(Tail, Node, [Op | Ops], [Op | Res]) end; - [{Name, _Pid2, _Method, _RPid, _Ref}] -> + [{Name, _Pid2, _Method, _Ref}] -> %% The other node will solve the conflict. exchange_names(Tail, Node, Ops, Res); _ -> @@ -2036,7 +2023,7 @@ pid_is_locking(Pid, PidRefs) -> delete_lock(Ref, S0) -> Locks = pid_locks(Ref), F = fun({ResourceId, LockRequesterId, PidRefs}, S) -> - {Pid, _RPid, Ref} = lists:keyfind(Ref, 3, PidRefs), + {Pid, Ref} = lists:keyfind(Ref, 2, PidRefs), remove_lock(ResourceId, LockRequesterId, Pid, PidRefs, true, S) end, lists:foldl(F, S0, Locks). @@ -2046,10 +2033,10 @@ pid_locks(Ref) -> ets:lookup(global_locks, ResourceId) end, ets:lookup(global_pid_ids, Ref)), [Lock || Lock = {_Id, _Req, PidRefs} <- L, - rpid_is_locking(Ref, PidRefs)]. + ref_is_locking(Ref, PidRefs)]. -rpid_is_locking(Ref, PidRefs) -> - lists:keyfind(Ref, 3, PidRefs) =/= false. +ref_is_locking(Ref, PidRefs) -> + lists:keyfind(Ref, 2, PidRefs) =/= false. handle_nodedown(Node, S) -> %% DOWN signals from monitors have removed locks and registered names. @@ -2062,7 +2049,7 @@ handle_nodedown(Node, S) -> get_names() -> ets:select(global_names, - ets:fun2ms(fun({Name, Pid, Method, _RPid, _Ref}) -> + ets:fun2ms(fun({Name, Pid, Method, _Ref}) -> {Name, Pid, Method} end)). @@ -2205,24 +2192,6 @@ unexpected_message(Message, What) -> %%% Utilities -%% When/if erlang:monitor() returns before trying to connect to the -%% other node this function can be removed. -do_monitor(Pid) -> - case (node(Pid) =:= node()) orelse lists:member(node(Pid), nodes()) of - true -> - %% Assume the node is still up - {Pid, erlang:monitor(process, Pid)}; - false -> - F = fun() -> - Ref = erlang:monitor(process, Pid), - receive - {'DOWN', Ref, process, Pid, _Info} -> - exit(normal) - end - end, - erlang:spawn_monitor(F) - end. - intersection(_, []) -> []; intersection(L1, L2) -> diff --git a/lib/kernel/src/inet.erl b/lib/kernel/src/inet.erl index 73c53b9011..9f22eb6aaa 100644 --- a/lib/kernel/src/inet.erl +++ b/lib/kernel/src/inet.erl @@ -76,7 +76,7 @@ -export_type([address_family/0, socket_protocol/0, hostent/0, hostname/0, ip4_address/0, ip6_address/0, ip_address/0, port_number/0, local_address/0, socket_address/0, returned_non_ip_address/0, - socket_setopt/0, socket_getopt/0, + socket_setopt/0, socket_getopt/0, ancillary_data/0, posix/0, socket/0, stat_option/0]). %% imports -import(lists, [append/1, duplicate/2, filter/2, foldl/3]). @@ -154,6 +154,15 @@ 'running' | 'multicast' | 'loopback']} | {'hwaddr', ether_address()}. +-type getifaddrs_ifopts() :: + [Ifopt :: {flags, Flags :: [up | broadcast | loopback | + pointtopoint | running | multicast]} | + {addr, Addr :: ip_address()} | + {netmask, Netmask :: ip_address()} | + {broadaddr, Broadaddr :: ip_address()} | + {dstaddr, Dstaddr :: ip_address()} | + {hwaddr, Hwaddr :: [byte()]}]. + -type address_family() :: 'inet' | 'inet6' | 'local'. -type socket_protocol() :: 'tcp' | 'udp' | 'sctp'. -type socket_type() :: 'stream' | 'dgram' | 'seqpacket'. @@ -163,6 +172,9 @@ 'recv_cnt' | 'recv_max' | 'recv_avg' | 'recv_oct' | 'recv_dvi' | 'send_cnt' | 'send_max' | 'send_avg' | 'send_oct' | 'send_pend'. +-type ancillary_data() :: + [ {'tos', byte()} | {'tclass', byte()} | {'ttl', byte()} ]. + %%% --------------------------------- -spec get_rc() -> [{Par :: atom(), Val :: any()} | @@ -302,7 +314,7 @@ setopts(Socket, Opts) -> {'ok', OptionValues} | {'error', posix()} when Socket :: socket(), Options :: [socket_getopt()], - OptionValues :: [socket_setopt()]. + OptionValues :: [socket_setopt() | gen_tcp:pktoptions_value()]. getopts(Socket, Opts) -> case prim_inet:getopts(Socket, Opts) of @@ -318,32 +330,32 @@ getopts(Socket, Opts) -> Other end. --spec getifaddrs(Socket :: socket()) -> - {'ok', [string()]} | {'error', posix()}. - +-spec getifaddrs( + [Option :: {netns, Namespace :: file:filename_all()}] + | socket()) -> + {'ok', [{Ifname :: string(), + Ifopts :: getifaddrs_ifopts()}]} + | {'error', posix()}. +getifaddrs(Opts) when is_list(Opts) -> + withsocket(fun(S) -> prim_inet:getifaddrs(S) end, Opts); getifaddrs(Socket) -> prim_inet:getifaddrs(Socket). --spec getifaddrs() -> {ok, Iflist} | {error, posix()} when - Iflist :: [{Ifname,[Ifopt]}], - Ifname :: string(), - Ifopt :: {flags,[Flag]} | {addr,Addr} | {netmask,Netmask} - | {broadaddr,Broadaddr} | {dstaddr,Dstaddr} - | {hwaddr,Hwaddr}, - Flag :: up | broadcast | loopback | pointtopoint - | running | multicast, - Addr :: ip_address(), - Netmask :: ip_address(), - Broadaddr :: ip_address(), - Dstaddr :: ip_address(), - Hwaddr :: [byte()]. - +-spec getifaddrs() -> + {'ok', [{Ifname :: string(), + Ifopts :: getifaddrs_ifopts()}]} + | {'error', posix()}. getifaddrs() -> withsocket(fun(S) -> prim_inet:getifaddrs(S) end). --spec getiflist(Socket :: socket()) -> - {'ok', [string()]} | {'error', posix()}. +-spec getiflist( + [Option :: {netns, Namespace :: file:filename_all()}] + | socket()) -> + {'ok', [string()]} | {'error', posix()}. + +getiflist(Opts) when is_list(Opts) -> + withsocket(fun(S) -> prim_inet:getiflist(S) end, Opts); getiflist(Socket) -> prim_inet:getiflist(Socket). @@ -360,11 +372,19 @@ getiflist() -> ifget(Socket, Name, Opts) -> prim_inet:ifget(Socket, Name, Opts). --spec ifget(Name :: string() | atom(), Opts :: [if_getopt()]) -> +-spec ifget( + Name :: string() | atom(), + Opts :: [if_getopt() | + {netns, Namespace :: file:filename_all()}]) -> {'ok', [if_getopt_result()]} | {'error', posix()}. ifget(Name, Opts) -> - withsocket(fun(S) -> prim_inet:ifget(S, Name, Opts) end). + {NSOpts,IFOpts} = + lists:partition( + fun ({netns,_}) -> true; + (_) -> false + end, Opts), + withsocket(fun(S) -> prim_inet:ifget(S, Name, IFOpts) end, NSOpts). -spec ifset(Socket :: socket(), Name :: string() | atom(), @@ -374,11 +394,19 @@ ifget(Name, Opts) -> ifset(Socket, Name, Opts) -> prim_inet:ifset(Socket, Name, Opts). --spec ifset(Name :: string() | atom(), Opts :: [if_setopt()]) -> +-spec ifset( + Name :: string() | atom(), + Opts :: [if_setopt() | + {netns, Namespace :: file:filename_all()}]) -> 'ok' | {'error', posix()}. ifset(Name, Opts) -> - withsocket(fun(S) -> prim_inet:ifset(S, Name, Opts) end). + {NSOpts,IFOpts} = + lists:partition( + fun ({netns,_}) -> true; + (_) -> false + end, Opts), + withsocket(fun(S) -> prim_inet:ifset(S, Name, IFOpts) end, NSOpts). -spec getif() -> {'ok', [{ip_address(), ip_address() | 'undefined', ip_address()}]} | @@ -388,10 +416,14 @@ getif() -> withsocket(fun(S) -> getif(S) end). %% backwards compatible getif --spec getif(Socket :: socket()) -> +-spec getif( + [Option :: {netns, Namespace :: file:filename_all()}] + | socket()) -> {'ok', [{ip_address(), ip_address() | 'undefined', ip_address()}]} | {'error', posix()}. +getif(Opts) when is_list(Opts) -> + withsocket(fun(S) -> getif(S) end, Opts); getif(Socket) -> case prim_inet:getiflist(Socket) of {ok, IfList} -> @@ -412,7 +444,10 @@ getif(Socket) -> end. withsocket(Fun) -> - case inet_udp:open(0,[]) of + withsocket(Fun, []). +%% +withsocket(Fun, Opts) -> + case inet_udp:open(0, Opts) of {ok,Socket} -> Res = Fun(Socket), inet_udp:close(Socket), @@ -722,6 +757,7 @@ stats() -> %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% connect_options() -> [tos, tclass, priority, reuseaddr, keepalive, linger, sndbuf, recbuf, nodelay, + recvtos, recvtclass, ttl, recvttl, header, active, packet, packet_size, buffer, mode, deliver, line_delimiter, exit_on_close, high_watermark, low_watermark, high_msgq_watermark, low_msgq_watermark, send_timeout, send_timeout_close, delay_send, raw, @@ -790,6 +826,7 @@ con_add(Name, Val, #connect_opts{} = R, Opts, AllOpts) -> %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% listen_options() -> [tos, tclass, priority, reuseaddr, keepalive, linger, sndbuf, recbuf, nodelay, + recvtos, recvtclass, ttl, recvttl, header, active, packet, buffer, mode, deliver, backlog, ipv6_v6only, exit_on_close, high_watermark, low_watermark, high_msgq_watermark, low_msgq_watermark, send_timeout, send_timeout_close, delay_send, @@ -870,7 +907,7 @@ tcp_module_1(Opts, Address) -> %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% udp_options() -> [tos, tclass, priority, reuseaddr, sndbuf, recbuf, header, active, buffer, mode, - deliver, ipv6_v6only, + recvtos, recvtclass, ttl, recvttl, deliver, ipv6_v6only, broadcast, dontroute, multicast_if, multicast_ttl, multicast_loop, add_membership, drop_membership, read_packets,raw, high_msgq_watermark, low_msgq_watermark, bind_to_device]. @@ -940,8 +977,10 @@ udp_module(Opts) -> % (*) passing of open FDs ("fdopen") is not supported. sctp_options() -> [ % The following are generic inet options supported for SCTP sockets: - mode, active, buffer, tos, tclass, priority, dontroute, reuseaddr, linger, sndbuf, - recbuf, ipv6_v6only, high_msgq_watermark, low_msgq_watermark, + mode, active, buffer, tos, tclass, ttl, + priority, dontroute, reuseaddr, linger, + recvtos, recvtclass, recvttl, + sndbuf, recbuf, ipv6_v6only, high_msgq_watermark, low_msgq_watermark, bind_to_device, % Other options are SCTP-specific (though they may be similar to their diff --git a/lib/kernel/src/inet6_tcp.erl b/lib/kernel/src/inet6_tcp.erl index a0d5d3df70..347b8b9a1b 100644 --- a/lib/kernel/src/inet6_tcp.erl +++ b/lib/kernel/src/inet6_tcp.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1997-2016. All Rights Reserved. +%% Copyright Ericsson AB 1997-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. @@ -167,7 +167,7 @@ listen(Port, Opts) -> %% Accept %% accept(L) -> - case prim_inet:accept(L) of + case prim_inet:accept(L, accept_family_opts()) of {ok, S} -> inet_db:register_socket(S, ?MODULE), {ok,S}; @@ -175,13 +175,15 @@ accept(L) -> end. accept(L, Timeout) -> - case prim_inet:accept(L, Timeout) of + case prim_inet:accept(L, Timeout, accept_family_opts()) of {ok, S} -> inet_db:register_socket(S, ?MODULE), {ok,S}; Error -> Error end. +accept_family_opts() -> [tclass, recvtclass]. + %% %% Create a port/socket from a file descriptor %% diff --git a/lib/kernel/src/inet_config.erl b/lib/kernel/src/inet_config.erl index 9f76360b8b..e771461b65 100644 --- a/lib/kernel/src/inet_config.erl +++ b/lib/kernel/src/inet_config.erl @@ -98,7 +98,7 @@ init() -> {win32,WinType} -> win32_load_from_registry(WinType); _ -> - error("can not read win32 system registry~n", []) + error("cannot read win32 system registry~n", []) end end, CfgFiles), diff --git a/lib/kernel/src/inet_db.erl b/lib/kernel/src/inet_db.erl index 6cbb6ac2da..630ef5d2f7 100644 --- a/lib/kernel/src/inet_db.erl +++ b/lib/kernel/src/inet_db.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1997-2016. All Rights Reserved. +%% Copyright Ericsson AB 1997-2019. 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. @@ -1223,7 +1223,11 @@ handle_set_file(Option, Fname, TagTm, TagInfo, ParseFun, From, {ok, B, _} -> B; _ -> <<>> end; - _ -> <<>> + _ -> + ets:insert(Db, {TagInfo, undefined}), + TimeZero = - (?RES_FILE_UPDATE_TM + 1), % Early enough + ets:insert(Db, {TagTm, TimeZero}), + <<>> end, handle_set_file(ParseFun, Bin, From, State); false -> {reply,error,State} diff --git a/lib/kernel/src/inet_dns.erl b/lib/kernel/src/inet_dns.erl index f1f58bc872..6c98d2aab7 100644 --- a/lib/kernel/src/inet_dns.erl +++ b/lib/kernel/src/inet_dns.erl @@ -699,7 +699,7 @@ encode_labels(Bin, Comp0, Pos, [L|Ls]=Labels) none -> Comp = if Pos < (3 bsl 14) -> %% Just in case - compression - %% pointers can not reach further + %% pointers cannot reach further gb_trees:insert(Labels, Pos, Comp0); true -> Comp0 end, diff --git a/lib/kernel/src/inet_int.hrl b/lib/kernel/src/inet_int.hrl index 357e27826c..f6525d7261 100644 --- a/lib/kernel/src/inet_int.hrl +++ b/lib/kernel/src/inet_int.hrl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1997-2017. All Rights Reserved. +%% Copyright Ericsson AB 1997-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. @@ -157,6 +157,12 @@ -define(INET_LOPT_LINE_DELIM, 40). -define(INET_OPT_TCLASS, 41). -define(INET_OPT_BIND_TO_DEVICE, 42). +-define(INET_OPT_RECVTOS, 43). +-define(INET_OPT_RECVTCLASS, 44). +-define(INET_OPT_PKTOPTIONS, 45). +-define(INET_OPT_TTL, 46). +-define(INET_OPT_RECVTTL, 47). +-define(TCP_OPT_NOPUSH, 48). % Specific SCTP options: separate range: -define(SCTP_OPT_RTOINFO, 100). -define(SCTP_OPT_ASSOCINFO, 101). diff --git a/lib/kernel/src/inet_tcp.erl b/lib/kernel/src/inet_tcp.erl index dac6b3119d..f1e3116856 100644 --- a/lib/kernel/src/inet_tcp.erl +++ b/lib/kernel/src/inet_tcp.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1997-2016. All Rights Reserved. +%% Copyright Ericsson AB 1997-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. @@ -164,7 +164,7 @@ listen(Port, Opts) -> %% Accept %% accept(L) -> - case prim_inet:accept(L) of + case prim_inet:accept(L, accept_family_opts()) of {ok, S} -> inet_db:register_socket(S, ?MODULE), {ok,S}; @@ -172,13 +172,15 @@ accept(L) -> end. accept(L, Timeout) -> - case prim_inet:accept(L, Timeout) of + case prim_inet:accept(L, Timeout, accept_family_opts()) of {ok, S} -> inet_db:register_socket(S, ?MODULE), {ok,S}; Error -> Error end. +accept_family_opts() -> [tos, ttl, recvtos, recvttl]. + %% %% Create a port/socket from a file descriptor %% diff --git a/lib/kernel/src/inet_tcp_dist.erl b/lib/kernel/src/inet_tcp_dist.erl index d1701afdaa..c5a114a9ef 100644 --- a/lib/kernel/src/inet_tcp_dist.erl +++ b/lib/kernel/src/inet_tcp_dist.erl @@ -212,6 +212,7 @@ do_accept(Driver, Kernel, AcceptPid, Socket, MyNode, Allowed, SetupTime) -> [{active, true}, {deliver, port}, {packet, 4}, + binary, nodelay()]) end, f_getll = fun(S) -> @@ -450,7 +451,7 @@ get_tcp_address(Driver, Socket) -> get_address_resolver(EpmdModule) -> case erlang:function_exported(EpmdModule, address_please, 3) of true -> {EpmdModule, address_please}; - _ -> {inet, getaddr} + _ -> {erl_epmd, address_please} end. %% ------------------------------------------------------------ diff --git a/lib/kernel/src/kernel.app.src b/lib/kernel/src/kernel.app.src index 47dd7c03d5..8fe6bdd1ca 100644 --- a/lib/kernel/src/kernel.app.src +++ b/lib/kernel/src/kernel.app.src @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1996-2018. All Rights Reserved. +%% Copyright Ericsson AB 1996-2019. 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. @@ -67,11 +67,13 @@ logger_filters, logger_formatter, logger_h_common, + logger_handler_watcher, + logger_olp, + logger_proxy, logger_server, logger_simple_h, logger_std_h, logger_sup, - net, net_adm, net_kernel, os, @@ -129,6 +131,7 @@ kernel_refc, kernel_sup, logger, + logger_handler_watcher, logger_sup, net_kernel, net_sup, @@ -144,6 +147,6 @@ {logger_sasl_compatible, false} ]}, {mod, {kernel, []}}, - {runtime_dependencies, ["erts-10.0", "stdlib-3.5", "sasl-3.0"]} + {runtime_dependencies, ["erts-10.2.5", "stdlib-3.5", "sasl-3.0"]} ] }. diff --git a/lib/kernel/src/kernel.appup.src b/lib/kernel/src/kernel.appup.src index 305a1c788c..95853a7a8f 100644 --- a/lib/kernel/src/kernel.appup.src +++ b/lib/kernel/src/kernel.appup.src @@ -16,13 +16,42 @@ %% limitations under the License. %% %% %CopyrightEnd% +%% +%% We allow upgrade from, and downgrade to all previous +%% versions from the following OTP releases: +%% - OTP 21 +%% - OTP 22 +%% +%% We also allow upgrade from, and downgrade to all +%% versions that have branched off from the above +%% stated previous versions. +%% {"%VSN%", - %% Up from - max one major revision back - [{<<"5\\.3(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-20.0 - {<<"5\\.4(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-20.1+ - {<<"6\\.0(\\.[0-9]+)*">>,[restart_new_emulator]}], % OTP-21 - %% Down to - max one major revision back - [{<<"5\\.3(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-20.0 - {<<"5\\.4(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-20.1+ - {<<"6\\.0(\\.[0-9]+)*">>,[restart_new_emulator]}] % OTP-21 -}. + [{<<"^6\\.0$">>,[restart_new_emulator]}, + {<<"^6\\.0\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^6\\.0\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.1$">>,[restart_new_emulator]}, + {<<"^6\\.1\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^6\\.1\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.2$">>,[restart_new_emulator]}, + {<<"^6\\.2\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^6\\.2\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.3$">>,[restart_new_emulator]}, + {<<"^6\\.3\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^6\\.3\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.4$">>,[restart_new_emulator]}, + {<<"^6\\.4\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}], + [{<<"^6\\.0$">>,[restart_new_emulator]}, + {<<"^6\\.0\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^6\\.0\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.1$">>,[restart_new_emulator]}, + {<<"^6\\.1\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^6\\.1\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.2$">>,[restart_new_emulator]}, + {<<"^6\\.2\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^6\\.2\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.3$">>,[restart_new_emulator]}, + {<<"^6\\.3\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^6\\.3\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.4$">>,[restart_new_emulator]}, + {<<"^6\\.4\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}]}. diff --git a/lib/kernel/src/kernel.erl b/lib/kernel/src/kernel.erl index c68d04e279..bfa091a036 100644 --- a/lib/kernel/src/kernel.erl +++ b/lib/kernel/src/kernel.erl @@ -68,7 +68,7 @@ config_change(Changed, New, Removed) -> %%% auth, ...) ...) %%% %%% The rectangular boxes are supervisors. All supervisors except -%%% for kernel_safe_sup terminates the enitre erlang node if any of +%%% for kernel_safe_sup terminates the entire erlang node if any of %%% their children dies. Any child that can't be restarted in case %%% of failure must be placed under one of these supervisors. Any %%% other child must be placed under safe_sup. These children may @@ -145,26 +145,11 @@ init([]) -> {ok, {SupFlags, [Code, File, StdError, User, LoggerSup, Config, RefC, SafeSup]}}; _ -> - Rpc = #{id => rex, - start => {rpc, start_link, []}, - restart => permanent, - shutdown => 2000, - type => worker, - modules => [rpc]}, - - Global = #{id => global_name_server, - start => {global, start_link, []}, - restart => permanent, - shutdown => 2000, - type => worker, - modules => [global]}, - - GlGroup = #{id => global_group, - start => {global_group,start_link,[]}, - restart => permanent, - shutdown => 2000, - type => worker, - modules => [global_group]}, + DistChildren = + case application:get_env(kernel, start_distribution) of + {ok, false} -> []; + _ -> start_distribution() + end, InetDb = #{id => inet_db, start => {inet_db, start_link, []}, @@ -173,13 +158,6 @@ init([]) -> type => worker, modules => [inet_db]}, - NetSup = #{id => net_sup, - start => {erl_distribution, start_link, []}, - restart => permanent, - shutdown => infinity, - type => supervisor, - modules => [erl_distribution]}, - SigSrv = #{id => erl_signal_server, start => {gen_event, start_link, [{local, erl_signal_server}]}, restart => permanent, @@ -187,14 +165,11 @@ init([]) -> type => worker, modules => dynamic}, - DistAC = start_dist_ac(), - Timer = start_timer(), {ok, {SupFlags, - [Code, Rpc, Global, InetDb | DistAC] ++ - [NetSup, GlGroup, File, SigSrv, - StdError, User, Config, RefC, SafeSup, LoggerSup] ++ Timer}} + [Code, InetDb | DistChildren] ++ + [File, SigSrv, StdError, User, Config, RefC, SafeSup, LoggerSup] ++ Timer}} end; init(safe) -> SupFlags = #{strategy => one_for_one, @@ -213,6 +188,39 @@ init(safe) -> {ok, {SupFlags, Boot ++ DiskLog ++ Pg2}}. +start_distribution() -> + Rpc = #{id => rex, + start => {rpc, start_link, []}, + restart => permanent, + shutdown => 2000, + type => worker, + modules => [rpc]}, + + Global = #{id => global_name_server, + start => {global, start_link, []}, + restart => permanent, + shutdown => 2000, + type => worker, + modules => [global]}, + + DistAC = start_dist_ac(), + + NetSup = #{id => net_sup, + start => {erl_distribution, start_link, []}, + restart => permanent, + shutdown => infinity, + type => supervisor, + modules => [erl_distribution]}, + + GlGroup = #{id => global_group, + start => {global_group,start_link,[]}, + restart => permanent, + shutdown => 2000, + type => worker, + modules => [global_group]}, + + [Rpc, Global | DistAC] ++ [NetSup, GlGroup]. + start_dist_ac() -> Spec = [#{id => dist_ac, start => {dist_ac,start_link,[]}, diff --git a/lib/kernel/src/logger.erl b/lib/kernel/src/logger.erl index 0a9b1672ec..38bd2f481c 100644 --- a/lib/kernel/src/logger.erl +++ b/lib/kernel/src/logger.erl @@ -39,13 +39,18 @@ remove_primary_filter/1, remove_handler_filter/2, set_module_level/2, unset_module_level/1, unset_module_level/0, + set_application_level/2, unset_application_level/1, get_module_level/0, get_module_level/1, set_primary_config/1, set_primary_config/2, set_handler_config/2, set_handler_config/3, - update_primary_config/1, update_handler_config/2, + set_proxy_config/1, + update_primary_config/1, + update_handler_config/2, update_handler_config/3, + update_proxy_config/1, update_formatter_config/2, update_formatter_config/3, get_primary_config/0, get_handler_config/1, get_handler_config/0, get_handler_ids/0, get_config/0, + get_proxy_config/0, add_handlers/1]). %% Private configuration @@ -55,6 +60,8 @@ -export([compare_levels/2]). -export([set_process_metadata/1, update_process_metadata/1, unset_process_metadata/0, get_process_metadata/0]). +-export([i/0, i/1]). +-export([timestamp/0]). %% Basic report formatting -export([format_report/1, format_otp_report/1]). @@ -74,6 +81,11 @@ -type level() :: emergency | alert | critical | error | warning | notice | info | debug. -type report() :: map() | [{atom(),term()}]. +-type report_cb() :: fun((report()) -> {io:format(),[term()]}) | + fun((report(),report_cb_config()) -> unicode:chardata()). +-type report_cb_config() :: #{depth := pos_integer() | unlimited, + chars_limit := pos_integer() | unlimited, + single_line := boolean()}. -type msg_fun() :: fun((term()) -> {io:format(),[term()]} | report() | unicode:chardata()). @@ -84,7 +96,7 @@ file => file:filename(), line => non_neg_integer(), domain => [atom()], - report_cb => fun((report()) -> {io:format(),[term()]}), + report_cb => report_cb(), atom() => term()}. -type location() :: #{mfa := {module(),atom(),non_neg_integer()}, file := file:filename(), @@ -110,10 +122,41 @@ -type config_handler() :: {handler, handler_id(), module(), handler_config()}. --export_type([log_event/0,level/0,report/0,msg_fun/0,metadata/0, - primary_config/0,handler_config/0,handler_id/0, - filter_id/0,filter/0,filter_arg/0,filter_return/0, - config_handler/0,formatter_config/0]). +-type config_logger() :: [{handler,default,undefined} | + config_handler() | + {filters,log | stop,[{filter_id(),filter()}]} | + {module_level,level(),[module()]}]. + +-type olp_config() :: #{sync_mode_qlen => non_neg_integer(), + drop_mode_qlen => pos_integer(), + flush_qlen => pos_integer(), + burst_limit_enable => boolean(), + burst_limit_max_count => pos_integer(), + burst_limit_window_time => pos_integer(), + overload_kill_enable => boolean(), + overload_kill_qlen => pos_integer(), + overload_kill_mem_size => pos_integer(), + overload_kill_restart_after => + non_neg_integer() | infinity}. + +-export_type([log_event/0, + level/0, + report/0, + report_cb/0, + report_cb_config/0, + msg_fun/0, + metadata/0, + primary_config/0, + handler_config/0, + handler_id/0, + filter_id/0, + filter/0, + filter_arg/0, + filter_return/0, + config_handler/0, + formatter_config/0, + olp_config/0, + timestamp/0]). %%%----------------------------------------------------------------- %%% API @@ -313,6 +356,10 @@ internal_log(Level,Term) when is_atom(Level) -> erlang:display_string("Logger - "++ atom_to_list(Level) ++ ": "), erlang:display(Term). +-spec timestamp() -> timestamp(). +timestamp() -> + os:system_time(microsecond). + %%%----------------------------------------------------------------- %%% Configuration -spec add_primary_filter(FilterId,Filter) -> ok | {error,term()} when @@ -352,9 +399,12 @@ add_handler(HandlerId,Module,Config) -> remove_handler(HandlerId) -> logger_server:remove_handler(HandlerId). --spec set_primary_config(Key,Value) -> ok | {error,term()} when - Key :: atom(), - Value :: term(). +-spec set_primary_config(level,Level) -> ok | {error,term()} when + Level :: level() | all | none; + (filter_default,FilterDefault) -> ok | {error,term()} when + FilterDefault :: log | stop; + (filters,Filters) -> ok | {error,term()} when + Filters :: [{filter_id(),filter()}]. set_primary_config(Key,Value) -> logger_server:set_config(primary,Key,Value). @@ -363,10 +413,27 @@ set_primary_config(Key,Value) -> set_primary_config(Config) -> logger_server:set_config(primary,Config). --spec set_handler_config(HandlerId,Key,Value) -> ok | {error,term()} when + +-spec set_handler_config(HandlerId,level,Level) -> Return when HandlerId :: handler_id(), - Key :: atom(), - Value :: term(). + Level :: level() | all | none, + Return :: ok | {error,term()}; + (HandlerId,filter_default,FilterDefault) -> Return when + HandlerId :: handler_id(), + FilterDefault :: log | stop, + Return :: ok | {error,term()}; + (HandlerId,filters,Filters) -> Return when + HandlerId :: handler_id(), + Filters :: [{filter_id(),filter()}], + Return :: ok | {error,term()}; + (HandlerId,formatter,Formatter) -> Return when + HandlerId :: handler_id(), + Formatter :: {module(), formatter_config()}, + Return :: ok | {error,term()}; + (HandlerId,config,Config) -> Return when + HandlerId :: handler_id(), + Config :: term(), + Return :: ok | {error,term()}. set_handler_config(HandlerId,Key,Value) -> logger_server:set_config(HandlerId,Key,Value). @@ -376,17 +443,50 @@ set_handler_config(HandlerId,Key,Value) -> set_handler_config(HandlerId,Config) -> logger_server:set_config(HandlerId,Config). +-spec set_proxy_config(Config) -> ok | {error,term()} when + Config :: olp_config(). +set_proxy_config(Config) -> + logger_server:set_config(proxy,Config). + -spec update_primary_config(Config) -> ok | {error,term()} when Config :: primary_config(). update_primary_config(Config) -> logger_server:update_config(primary,Config). +-spec update_handler_config(HandlerId,level,Level) -> Return when + HandlerId :: handler_id(), + Level :: level() | all | none, + Return :: ok | {error,term()}; + (HandlerId,filter_default,FilterDefault) -> Return when + HandlerId :: handler_id(), + FilterDefault :: log | stop, + Return :: ok | {error,term()}; + (HandlerId,filters,Filters) -> Return when + HandlerId :: handler_id(), + Filters :: [{filter_id(),filter()}], + Return :: ok | {error,term()}; + (HandlerId,formatter,Formatter) -> Return when + HandlerId :: handler_id(), + Formatter :: {module(), formatter_config()}, + Return :: ok | {error,term()}; + (HandlerId,config,Config) -> Return when + HandlerId :: handler_id(), + Config :: term(), + Return :: ok | {error,term()}. +update_handler_config(HandlerId,Key,Value) -> + logger_server:update_config(HandlerId,Key,Value). + -spec update_handler_config(HandlerId,Config) -> ok | {error,term()} when HandlerId :: handler_id(), Config :: handler_config(). update_handler_config(HandlerId,Config) -> logger_server:update_config(HandlerId,Config). +-spec update_proxy_config(Config) -> ok | {error,term()} when + Config :: olp_config(). +update_proxy_config(Config) -> + logger_server:update_config(proxy,Config). + -spec get_primary_config() -> Config when Config :: primary_config(). get_primary_config() -> @@ -398,8 +498,10 @@ get_primary_config() -> Config :: handler_config(). get_handler_config(HandlerId) -> case logger_config:get(?LOGGER_TABLE,HandlerId) of - {ok,{_,Config}} -> - {ok,Config}; + {ok,#{module:=Module}=Config} -> + {ok,try Module:filter_config(Config) + catch _:_ -> Config + end}; Error -> Error end. @@ -418,6 +520,12 @@ get_handler_ids() -> {ok,#{handlers:=HandlerIds}} = logger_config:get(?LOGGER_TABLE,primary), HandlerIds. +-spec get_proxy_config() -> Config when + Config :: olp_config(). +get_proxy_config() -> + {ok,Config} = logger_config:get(?LOGGER_TABLE,proxy), + Config. + -spec update_formatter_config(HandlerId,FormatterConfig) -> ok | {error,term()} when HandlerId :: handler_id(), @@ -452,6 +560,27 @@ unset_module_level(Modules) -> unset_module_level() -> logger_server:unset_module_level(). +-spec set_application_level(Application,Level) -> ok | {error, not_loaded} when + Application :: atom(), + Level :: level() | all | none. +set_application_level(App,Level) -> + case application:get_key(App, modules) of + {ok, Modules} -> + set_module_level(Modules, Level); + undefined -> + {error, {not_loaded, App}} + end. + +-spec unset_application_level(Application) -> ok | {error, not_loaded} when + Application :: atom(). +unset_application_level(App) -> + case application:get_key(App, modules) of + {ok, Modules} -> + unset_module_level(Modules); + undefined -> + {error, {not_loaded, App}} + end. + -spec get_module_level(Modules) -> [{Module,Level}] when Modules :: [Module] | Module, Module :: module(), @@ -517,12 +646,150 @@ unset_process_metadata() -> -spec get_config() -> #{primary=>primary_config(), handlers=>[handler_config()], + proxy=>olp_config(), module_levels=>[{module(),level() | all | none}]}. get_config() -> #{primary=>get_primary_config(), handlers=>get_handler_config(), + proxy=>get_proxy_config(), module_levels=>lists:keysort(1,get_module_level())}. +-spec i() -> ok. +i() -> + #{primary := Primary, + handlers := HandlerConfigs, + proxy := Proxy, + module_levels := Modules} = get_config(), + M = modifier(), + i_primary(Primary,M), + i_handlers(HandlerConfigs,M), + i_proxy(Proxy,M), + i_modules(Modules,M). + +-spec i(What) -> ok when + What :: primary | handlers | proxy | modules | handler_id(). +i(primary) -> + i_primary(get_primary_config(),modifier()); +i(handlers) -> + i_handlers(get_handler_config(),modifier()); +i(proxy) -> + i_proxy(get_proxy_config(),modifier()); +i(modules) -> + i_modules(get_module_level(),modifier()); +i(HandlerId) when is_atom(HandlerId) -> + case get_handler_config(HandlerId) of + {ok,HandlerConfig} -> + i_handlers([HandlerConfig],modifier()); + Error -> + Error + end; +i(What) -> + erlang:error(badarg,[What]). + + +i_primary(#{level := Level, + filters := Filters, + filter_default := FilterDefault}, + M) -> + io:format("Primary configuration: ~n",[]), + io:format(" Level: ~p~n",[Level]), + io:format(" Filter Default: ~p~n", [FilterDefault]), + io:format(" Filters: ~n", []), + print_filters(" ",Filters,M). + +i_handlers(HandlerConfigs,M) -> + io:format("Handler configuration: ~n", []), + print_handlers(HandlerConfigs,M). + +i_proxy(Proxy,M) -> + io:format("Proxy configuration: ~n", []), + print_custom(" ",Proxy,M). + +i_modules(Modules,M) -> + io:format("Level set per module: ~n", []), + print_module_levels(Modules,M). + +encoding() -> + case lists:keyfind(encoding, 1, io:getopts()) of + false -> latin1; + {encoding, Enc} -> Enc + end. + +modifier() -> + modifier(encoding()). + +modifier(latin1) -> ""; +modifier(_) -> "t". + +print_filters(Indent, {Id, {Fun, Arg}}, M) -> + io:format("~sId: ~"++M++"p~n" + "~s Fun: ~"++M++"p~n" + "~s Arg: ~"++M++"p~n", + [Indent, Id, Indent, Fun, Indent, Arg]); +print_filters(Indent,[],_M) -> + io:format("~s(none)~n",[Indent]); +print_filters(Indent,Filters,M) -> + [print_filters(Indent,Filter,M) || Filter <- Filters], + ok. + +print_handlers(#{id := Id, + module := Module, + level := Level, + filters := Filters, filter_default := FilterDefault, + formatter := {FormatterModule,FormatterConfig}} = Config, M) -> + io:format(" Id: ~"++M++"p~n" + " Module: ~p~n" + " Level: ~p~n" + " Formatter:~n" + " Module: ~p~n" + " Config:~n", + [Id, Module, Level, FormatterModule]), + print_custom(" ",FormatterConfig,M), + io:format(" Filter Default: ~p~n" + " Filters:~n", + [FilterDefault]), + print_filters(" ",Filters,M), + case maps:find(config,Config) of + {ok,HandlerConfig} -> + io:format(" Handler Config:~n"), + print_custom(" ",HandlerConfig,M); + error -> + ok + end, + MyKeys = [filter_default, filters, formatter, level, module, id, config], + case maps:without(MyKeys,Config) of + Empty when Empty==#{} -> + ok; + Unhandled -> + io:format(" Custom Config:~n"), + print_custom(" ",Unhandled,M) + end; +print_handlers([], _M) -> + io:format(" (none)~n"); +print_handlers(HandlerConfigs, M) -> + [print_handlers(HandlerConfig, M) || HandlerConfig <- HandlerConfigs], + ok. + +print_custom(Indent, {Key, Value}, M) -> + io:format("~s~"++M++"p: ~"++M++"p~n",[Indent,Key,Value]); +print_custom(Indent, Map, M) when is_map(Map) -> + print_custom(Indent,lists:keysort(1,maps:to_list(Map)), M); +print_custom(Indent, List, M) when is_list(List), is_tuple(hd(List)) -> + [print_custom(Indent, X, M) || X <- List], + ok; +print_custom(Indent, Value, M) -> + io:format("~s~"++M++"p~n",[Indent,Value]). + +print_module_levels({Module,Level},M) -> + io:format(" Module: ~"++M++"p~n" + " Level: ~p~n", + [Module,Level]); +print_module_levels([],_M) -> + io:format(" (none)~n"); +print_module_levels(Modules,M) -> + [print_module_levels(Module,M) || Module <- Modules], + ok. + -spec internal_init_logger() -> ok | {error,term()}. %% This function is responsible for config of the logger %% This is done before add_handlers because we want the @@ -530,19 +797,21 @@ get_config() -> %% tree is started. internal_init_logger() -> try + Env = get_logger_env(kernel), + check_logger_config(kernel,Env), ok = logger:set_primary_config(level, get_logger_level()), - ok = logger:set_primary_config(filter_default, get_primary_filter_default()), + ok = logger:set_primary_config(filter_default, + get_primary_filter_default(Env)), [case logger:add_primary_filter(Id, Filter) of ok -> ok; {error, Reason} -> throw(Reason) - end || {Id, Filter} <- get_primary_filters()], + end || {Id, Filter} <- get_primary_filters(Env)], - _ = [[case logger:set_module_level(Module, Level) of - ok -> ok; - {error, Reason} -> throw(Reason) - end || Module <- Modules] - || {module_level, Level, Modules} <- get_logger_env()], + [case logger:set_module_level(Modules, Level) of + ok -> ok; + {error, Reason} -> throw(Reason) + end || {module_level, Level, Modules} <- Env], case logger:set_handler_config(simple,filters, get_default_handler_filters()) of @@ -550,24 +819,24 @@ internal_init_logger() -> {error,{not_found,simple}} -> ok end, - init_kernel_handlers() + init_kernel_handlers(Env) catch throw:Reason -> ?LOG_ERROR("Invalid logger config: ~p", [Reason]), {error, {bad_config, {kernel, Reason}}} end. --spec init_kernel_handlers() -> ok | {error,term()}. +-spec init_kernel_handlers(config_logger()) -> ok | {error,term()}. %% Setup the kernel environment variables to be correct %% The actual handlers are started by a call to add_handlers. -init_kernel_handlers() -> +init_kernel_handlers(Env) -> try - case get_logger_type() of + case get_logger_type(Env) of {ok,silent} -> ok = logger:remove_handler(simple); {ok,false} -> ok; {ok,Type} -> - init_default_config(Type) + init_default_config(Type,Env) end catch throw:Reason -> ?LOG_ERROR("Invalid default handler config: ~p", [Reason]), @@ -581,11 +850,25 @@ init_kernel_handlers() -> %% This function is responsible for resolving the handler config %% and then starting the correct handlers. This is done after the %% kernel supervisor tree has been started as it needs the logger_sup. +add_handlers(kernel) -> + Env = get_logger_env(kernel), + case get_proxy_opts(Env) of + undefined -> + add_handlers(kernel,Env); + Opts -> + case set_proxy_config(Opts) of + ok -> add_handlers(kernel,Env); + {error, Reason} -> {error,{bad_proxy_config,Reason}} + end + end; add_handlers(App) when is_atom(App) -> - add_handlers(application:get_env(App, logger, [])); + add_handlers(App,get_logger_env(App)); add_handlers(HandlerConfig) -> + add_handlers(application:get_application(),HandlerConfig). + +add_handlers(App,HandlerConfig) -> try - check_logger_config(HandlerConfig), + check_logger_config(App,HandlerConfig), DefaultAdded = lists:foldl( fun({handler, default = Id, Module, Config}, _) @@ -599,17 +882,22 @@ add_handlers(HandlerConfig) -> ({handler, Id, Module, Config}, Default) -> setup_handler(Id, Module, Config), Default orelse Id == default; - (_, Default) -> Default + (_,Default) -> Default end, false, HandlerConfig), %% If a default handler was added we try to remove the simple_logger %% If the simple logger exists it will replay its log events %% to the handler(s) added in the fold above. - _ = [case logger:remove_handler(simple) of - ok -> ok; - {error,{not_found,simple}} -> ok - end || DefaultAdded], + [case logger:remove_handler(simple) of + ok -> ok; + {error,{not_found,simple}} -> ok + end || DefaultAdded], ok - catch throw:Reason -> + catch throw:Reason0 -> + Reason = + case App of + undefined -> Reason0; + _ -> {App,Reason0} + end, ?LOG_ERROR("Invalid logger handler config: ~p", [Reason]), {error, {bad_config, {handler, Reason}}} end. @@ -620,26 +908,37 @@ setup_handler(Id, Module, Config) -> {error, Reason} -> throw(Reason) end. -check_logger_config(_) -> - ok. - --spec get_logger_type() -> {ok, standard_io | false | silent | - {file, file:name_all()} | - {file, file:name_all(), [file:mode()]}}. -get_logger_type() -> +check_logger_config(_,[]) -> + ok; +check_logger_config(App,[{handler,_,_,_}|Env]) -> + check_logger_config(App,Env); +check_logger_config(kernel,[{handler,default,undefined}|Env]) -> + check_logger_config(kernel,Env); +check_logger_config(kernel,[{filters,_,_}|Env]) -> + check_logger_config(kernel,Env); +check_logger_config(kernel,[{module_level,_,_}|Env]) -> + check_logger_config(kernel,Env); +check_logger_config(kernel,[{proxy,_}|Env]) -> + check_logger_config(kernel,Env); +check_logger_config(_,Bad) -> + throw(Bad). + +-spec get_logger_type(config_logger()) -> + {ok, standard_io | false | silent | + {file, file:name_all()} | + {file, file:name_all(), [file:mode()]}}. +get_logger_type(Env) -> case application:get_env(kernel, error_logger) of {ok, tty} -> {ok, standard_io}; {ok, {file, File}} when is_list(File) -> {ok, {file, File}}; - {ok, {file, File, Modes}} when is_list(File), is_list(Modes) -> - {ok, {file, File, Modes}}; {ok, false} -> {ok, false}; {ok, silent} -> {ok, silent}; undefined -> - case lists:member({handler,default,undefined}, get_logger_env()) of + case lists:member({handler,default,undefined}, Env) of true -> {ok, false}; false -> @@ -651,62 +950,68 @@ get_logger_type() -> get_logger_level() -> case application:get_env(kernel,logger_level,info) of - Level when ?IS_LEVEL(Level) -> + Level when ?IS_LEVEL(Level); Level=:=all; Level=:=none -> Level; Level -> throw({logger_level, Level}) end. -get_primary_filter_default() -> - case lists:keyfind(filters,1,get_logger_env()) of +get_primary_filter_default(Env) -> + case lists:keyfind(filters,1,Env) of {filters,Default,_} -> Default; false -> log end. -get_primary_filters() -> - lists:foldl( - fun({filters, _, Filters}, _Acc) -> - Filters; - (_, Acc) -> - Acc - end, [], get_logger_env()). +get_primary_filters(Env) -> + case [F || F={filters,_,_} <- Env] of + [{filters,_,Filters}] -> + case lists:all(fun({_,_}) -> true; (_) -> false end,Filters) of + true -> Filters; + false -> throw({invalid_filters,Filters}) + end; + [] -> []; + _ -> throw({multiple_filters,Env}) + end. + +get_proxy_opts(Env) -> + case [P || P={proxy,_} <- Env] of + [{proxy,Opts}] -> Opts; + [] -> undefined; + _ -> throw({multiple_proxies,Env}) + end. %% This function looks at the kernel logger environment %% and updates it so that the correct logger is configured -init_default_config(Type) when Type==standard_io; - Type==standard_error; - element(1,Type)==file -> - Env = get_logger_env(), +init_default_config(Type,Env) when Type==standard_io; + Type==standard_error; + element(1,Type)==file -> DefaultFormatter = #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}}, DefaultConfig = DefaultFormatter#{config=>#{type=>Type}}, NewLoggerEnv = case lists:keyfind(default, 2, Env) of - {handler, default, Module, Config} -> - lists:map( - fun({handler, default, logger_std_h, _}) -> - %% Only want to add the logger_std_h config - %% if not configured by user AND the default - %% handler is still the logger_std_h. - {handler, default, Module, maps:merge(DefaultConfig,Config)}; - ({handler, default, logger_disk_log_h, _}) -> - %% Add default formatter. The point of this - %% is to get the expected formatter config - %% for the default handler, since this - %% differs from the default values that - %% logger_formatter itself adds. - {handler, default, logger_disk_log_h, maps:merge(DefaultFormatter,Config)}; - (Other) -> - Other - end, Env); + {handler, default, logger_std_h, Config} -> + %% Only want to add the logger_std_h config + %% if not configured by user AND the default + %% handler is still the logger_std_h. + lists:keyreplace(default, 2, Env, + {handler, default, logger_std_h, + maps:merge(DefaultConfig,Config)}); + {handler, default, Module,Config} -> + %% Add default formatter. The point of this + %% is to get the expected formatter config + %% for the default handler, since this + %% differs from the default values that + %% logger_formatter itself adds. + lists:keyreplace(default, 2, Env, + {handler, default, Module, + maps:merge(DefaultFormatter,Config)}); _ -> %% Nothing has been configured, use default [{handler, default, logger_std_h, DefaultConfig} | Env] end, - application:set_env(kernel, logger, NewLoggerEnv, [{timeout,infinity}]); -init_default_config(Type) -> - throw({illegal_logger_type,Type}). + application:set_env(kernel, logger, NewLoggerEnv, [{timeout,infinity}]). get_default_handler_filters() -> case application:get_env(kernel, logger_sasl_compatible, false) of @@ -716,8 +1021,8 @@ get_default_handler_filters() -> ?DEFAULT_HANDLER_FILTERS([otp,sasl]) end. -get_logger_env() -> - application:get_env(kernel, logger, []). +get_logger_env(App) -> + application:get_env(App, logger, []). %%%----------------------------------------------------------------- %%% Internal @@ -773,30 +1078,30 @@ log_allowed(Location,Level,Msg,Meta0) when is_map(Meta0) -> maps:merge(Location,maps:merge(proc_meta(),Meta0))), case node(maps:get(gl,Meta)) of Node when Node=/=node() -> - log_remote(Node,Level,Msg,Meta), - do_log_allowed(Level,Msg,Meta); + log_remote(Node,Level,Msg,Meta); _ -> - do_log_allowed(Level,Msg,Meta) - end. + ok + end, + do_log_allowed(Level,Msg,Meta,tid()). -do_log_allowed(Level,{Format,Args}=Msg,Meta) +do_log_allowed(Level,{Format,Args}=Msg,Meta,Tid) when ?IS_LEVEL(Level), is_list(Format), is_list(Args), is_map(Meta) -> - logger_backend:log_allowed(#{level=>Level,msg=>Msg,meta=>Meta},tid()); -do_log_allowed(Level,Report,Meta) + logger_backend:log_allowed(#{level=>Level,msg=>Msg,meta=>Meta},Tid); +do_log_allowed(Level,Report,Meta,Tid) when ?IS_LEVEL(Level), ?IS_REPORT(Report), is_map(Meta) -> logger_backend:log_allowed(#{level=>Level,msg=>{report,Report},meta=>Meta}, - tid()); -do_log_allowed(Level,String,Meta) + Tid); +do_log_allowed(Level,String,Meta,Tid) when ?IS_LEVEL(Level), ?IS_STRING(String), is_map(Meta) -> logger_backend:log_allowed(#{level=>Level,msg=>{string,String},meta=>Meta}, - tid()). + Tid). tid() -> ets:whereis(?LOGGER_TABLE). @@ -806,7 +1111,7 @@ log_remote(Node,Level,Msg,Meta) -> log_remote(Node,{log,Level,Msg,Meta}). log_remote(Node,Request) -> - {logger,Node} ! Request, + logger_proxy:log({remote,Node,Request}), ok. add_default_metadata(Meta) -> @@ -830,7 +1135,7 @@ proc_meta() -> default(pid) -> self(); default(gl) -> group_leader(); -default(time) -> erlang:system_time(microsecond). +default(time) -> timestamp(). %% Remove everything upto and including this module from the stacktrace filter_stacktrace(Module,[{Module,_,_,_}|_]) -> diff --git a/lib/kernel/src/logger_backend.erl b/lib/kernel/src/logger_backend.erl index 4d7bd6b2a0..432c671afd 100644 --- a/lib/kernel/src/logger_backend.erl +++ b/lib/kernel/src/logger_backend.erl @@ -41,7 +41,7 @@ log_allowed(Log, Tid) -> call_handlers(#{level:=Level}=Log,[Id|Handlers],Tid) -> case logger_config:get(Tid,Id,Level) of - {ok,{Module,Config}} -> + {ok,#{module:=Module}=Config} -> Filters = maps:get(filters,Config,[]), case apply_filters(Id,Log,Filters,Config) of stop -> diff --git a/lib/kernel/src/logger_config.erl b/lib/kernel/src/logger_config.erl index 55427dce5a..5024d20cfe 100644 --- a/lib/kernel/src/logger_config.erl +++ b/lib/kernel/src/logger_config.erl @@ -22,8 +22,8 @@ -export([new/1,delete/2, exist/2, allow/2,allow/3, - get/2, get/3, get/1, - create/3, create/4, set/3, + get/2, get/3, + create/3, set/3, set_module_level/3,unset_module_level/2, get_module_level/1,cache_module_level/2, level_to_int/1]). @@ -31,7 +31,9 @@ -include("logger_internal.hrl"). new(Name) -> - _ = ets:new(Name,[set,protected,named_table,{write_concurrency,true}]), + _ = ets:new(Name,[set,protected,named_table, + {read_concurrency,true}, + {write_concurrency,true}]), ets:whereis(Name). delete(Tid,Id) -> @@ -64,31 +66,30 @@ get(Tid,What) -> case ets:lookup(Tid,table_key(What)) of [{_,_,Config}] -> {ok,Config}; - [{_,_,Config,Module}] -> - {ok,{Module,Config}}; + [{_,Config}] when What=:=proxy -> + {ok,Config}; [] -> {error,{not_found,What}} end. get(Tid,What,Level) -> - MS = [{{table_key(What),'$1','$2'}, % primary config - [{'>=','$1',level_to_int(Level)}], - ['$2']}, - {{table_key(What),'$1','$2','$3'}, % handler config + MS = [{{table_key(What),'$1','$2'}, [{'>=','$1',level_to_int(Level)}], - [{{'$3','$2'}}]}], + ['$2']}], case ets:select(Tid,MS) of [] -> error; [Data] -> {ok,Data} end. -create(Tid,What,Module,Config) -> - LevelInt = level_to_int(maps:get(level,Config)), - ets:insert(Tid,{table_key(What),LevelInt,Config,Module}). +create(Tid,proxy,Config) -> + ets:insert(Tid,{table_key(proxy),Config}); create(Tid,What,Config) -> LevelInt = level_to_int(maps:get(level,Config)), ets:insert(Tid,{table_key(What),LevelInt,Config}). +set(Tid,proxy,Config) -> + ets:insert(Tid,{table_key(proxy),Config}), + ok; set(Tid,What,Config) -> LevelInt = level_to_int(maps:get(level,Config)), %% Should do this only if the level has actually changed. Possibly @@ -129,13 +130,6 @@ cache_module_level(Tid,Module) -> ets:insert_new(Tid,{Module,{GlobalLevelInt,cached}}), ok. -get(Tid) -> - {ok,Primary} = get(Tid,primary), - HMS = [{{table_key('$1'),'_','$2','$3'},[],[{{'$1','$3','$2'}}]}], - Handlers = ets:select(Tid,HMS), - Modules = get_module_level(Tid), - {Primary,Handlers,Modules}. - level_to_int(none) -> ?LOG_NONE; level_to_int(emergency) -> ?EMERGENCY; level_to_int(alert) -> ?ALERT; @@ -161,5 +155,6 @@ int_to_level(?LOG_ALL) -> all. %%%----------------------------------------------------------------- %%% Internal +table_key(proxy) -> ?PROXY_KEY; table_key(primary) -> ?PRIMARY_KEY; table_key(HandlerId) -> {?HANDLER_KEY,HandlerId}. diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index 0a72654e11..47b39da900 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -19,183 +19,117 @@ %% -module(logger_disk_log_h). --behaviour(gen_server). - -include("logger.hrl"). -include("logger_internal.hrl"). -include("logger_h_common.hrl"). %%% API --export([start_link/3, info/1, filesync/1, reset/1]). +-export([filesync/1]). -%% gen_server callbacks --export([init/1, handle_call/3, handle_cast/2, handle_info/2, - terminate/2, code_change/3]). +%% logger_h_common callbacks +-export([init/2, check_config/4, reset_state/2, + filesync/3, write/4, handle_info/3, terminate/3]). %% logger callbacks --export([log/2, adding_handler/1, removing_handler/1, changing_config/2]). - -%% handler internal --export([log_handler_info/4]). +-export([log/2, adding_handler/1, removing_handler/1, changing_config/3, + filter_config/1]). %%%=================================================================== %%% API %%%=================================================================== %%%----------------------------------------------------------------- -%%% Start a disk_log handler process and link to caller. -%%% This function is called by the kernel supervisor when this -%%% handler process gets added (as a result of calling add/3). --spec start_link(Name, Config, HandlerState) -> {ok,Pid} | {error,Reason} when - Name :: atom(), - Config :: logger:handler_config(), - HandlerState :: map(), - Pid :: pid(), - Reason :: term(). - -start_link(Name, Config, HandlerState) -> - proc_lib:start_link(?MODULE,init,[[Name,Config,HandlerState]]). - -%%%----------------------------------------------------------------- %%% -spec filesync(Name) -> ok | {error,Reason} when Name :: atom(), Reason :: handler_busy | {badarg,term()}. -filesync(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - disk_log_sync, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; filesync(Name) -> - {error,{badarg,{filesync,[Name]}}}. + logger_h_common:filesync(?MODULE,Name). + +%%%=================================================================== +%%% logger callbacks +%%%=================================================================== %%%----------------------------------------------------------------- -%%% --spec info(Name) -> Info | {error,Reason} when - Name :: atom(), - Info :: term(), - Reason :: handler_busy | {badarg,term()}. +%%% Handler being added +adding_handler(Config) -> + logger_h_common:adding_handler(Config). + +%%%----------------------------------------------------------------- +%%% Updating handler config +changing_config(SetOrUpdate, OldConfig, NewConfig) -> + logger_h_common:changing_config(SetOrUpdate, OldConfig, NewConfig). -info(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - info, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; -info(Name) -> - {error,{badarg,{info,[Name]}}}. +%%%----------------------------------------------------------------- +%%% Handler being removed +removing_handler(Config) -> + logger_h_common:removing_handler(Config). %%%----------------------------------------------------------------- -%%% --spec reset(Name) -> ok | {error,Reason} when - Name :: atom(), - Reason :: handler_busy | {badarg,term()}. +%%% Log a string or report +-spec log(LogEvent, Config) -> ok when + LogEvent :: logger:log_event(), + Config :: logger:handler_config(). -reset(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - reset, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; -reset(Name) -> - {error,{badarg,{reset,[Name]}}}. +log(LogEvent, Config) -> + logger_h_common:log(LogEvent, Config). +%%%----------------------------------------------------------------- +%%% Remove internal fields from configuration +filter_config(Config) -> + logger_h_common:filter_config(Config). %%%=================================================================== -%%% logger callbacks +%%% logger_h_common callbacks %%%=================================================================== - -%%%----------------------------------------------------------------- -%%% Handler being added -adding_handler(#{id:=Name}=Config) -> - case check_config(adding, Config) of - {ok, Config1} -> - %% create initial handler state by merging defaults with config - HConfig = maps:get(config, Config1, #{}), - HState = maps:merge(get_init_state(), HConfig), - case logger_h_common:overload_levels_ok(HState) of - true -> - start(Name, Config1, HState); - false -> - #{sync_mode_qlen := SMQL, - drop_mode_qlen := DMQL, - flush_qlen := FQL} = HState, - {error,{invalid_levels,{SMQL,DMQL,FQL}}} - end; +init(Name, #{file:=File,type:=Type,max_no_bytes:=MNB,max_no_files:=MNF}) -> + case open_disk_log(Name, File, Type, MNB, MNF) of + ok -> + {ok,#{log_opts => #{file => File, + type => Type, + max_no_bytes => MNB, + max_no_files => MNF}, + prev_log_result => ok, + prev_sync_result => ok, + prev_disk_log_info => undefined}}; Error -> Error end. -%%%----------------------------------------------------------------- -%%% Updating handler config -changing_config(OldConfig = #{id:=Name, config:=OldHConfig}, - NewConfig = #{id:=Name, config:=NewHConfig}) -> - #{type:=Type, file:=File, max_no_files:=MaxFs, - max_no_bytes:=MaxBytes} = OldHConfig, - case NewHConfig of - #{type:=Type, file:=File, max_no_files:=MaxFs, - max_no_bytes:=MaxBytes} -> - changing_config1(OldConfig, NewConfig); - _ -> - {error,{illegal_config_change,OldConfig,NewConfig}} - end; -changing_config(OldConfig, NewConfig) -> - {error,{illegal_config_change,OldConfig,NewConfig}}. - -changing_config1(OldConfig=#{config:=OldHConfig}, NewConfig) -> - case check_config(changing, NewConfig) of - {ok,NewConfig1 = #{config:=NewHConfig}} -> - #{handler_pid:=HPid, - mode_tab:=ModeTab} = OldHConfig, - NewHConfig1 = NewHConfig#{handler_pid=>HPid, - mode_tab=>ModeTab}, - NewConfig2 = NewConfig1#{config=>NewHConfig1}, - try gen_server:call(HPid, {change_config,OldConfig,NewConfig2}, - ?DEFAULT_CALL_TIMEOUT) of - ok -> {ok,NewConfig2}; - HError -> HError - catch - _:{timeout,_} -> {error,handler_busy} - end; - Error -> - Error +check_config(Name,set,undefined,HConfig0) -> + HConfig=merge_default_logopts(Name,maps:merge(get_default_config(),HConfig0)), + check_config(HConfig); +check_config(_Name,SetOrUpdate,OldHConfig,NewHConfig0) -> + WriteOnce = maps:with([type,file,max_no_files,max_no_bytes],OldHConfig), + Default = + case SetOrUpdate of + set -> + %% Do not reset write-once fields to defaults + maps:merge(get_default_config(),WriteOnce); + update -> + OldHConfig + end, + + NewHConfig = maps:merge(Default,NewHConfig0), + + %% Fail if write-once fields are changed + case maps:with([type,file,max_no_files,max_no_bytes],NewHConfig) of + WriteOnce -> + check_config(NewHConfig); + Other -> + {Old,New} = logger_server:diff_maps(WriteOnce,Other), + {error,{illegal_config_change,?MODULE,Old,New}} end. -check_config(adding, #{id:=Name}=Config) -> - %% merge handler specific config data - HConfig = merge_default_logopts(Name, maps:get(config, Config, #{})), +check_config(HConfig) -> case check_h_config(maps:to_list(HConfig)) of ok -> - {ok,Config#{config=>HConfig}}; - Error -> - Error - end; -check_config(changing, Config) -> - HConfig = maps:get(config, Config, #{}), - case check_h_config(maps:to_list(HConfig)) of - ok -> {ok,Config}; - Error -> Error + {ok,HConfig}; + {error,{Key,Value}} -> + {error,{invalid_config,?MODULE,#{Key=>Value}}} end. -merge_default_logopts(Name, HConfig) -> - Type = maps:get(type, HConfig, wrap), - {DefaultNoFiles,DefaultNoBytes} = - case Type of - halt -> {undefined,infinity}; - _wrap -> {10,1048576} - end, - {ok,Dir} = file:get_cwd(), - Defaults = #{file => filename:join(Dir,Name), - max_no_files => DefaultNoFiles, - max_no_bytes => DefaultNoBytes, - type => Type}, - maps:merge(Defaults, HConfig). - check_h_config([{file,File}|Config]) when is_list(File) -> check_h_config(Config); check_h_config([{max_no_files,undefined}|Config]) -> @@ -208,445 +142,59 @@ check_h_config([{max_no_bytes,N}|Config]) when is_integer(N), N>0 -> check_h_config(Config); check_h_config([{type,Type}|Config]) when Type==wrap; Type==halt -> check_h_config(Config); -check_h_config([Other | Config]) -> - case logger_h_common:check_common_config(Other) of - valid -> - check_h_config(Config); - invalid -> - {error,{invalid_config,?MODULE,Other}} - end; +check_h_config([Other | _]) -> + {error,Other}; check_h_config([]) -> ok. -%%%----------------------------------------------------------------- -%%% Handler being removed -removing_handler(#{id:=Name}) -> - stop(Name). +get_default_config() -> + #{}. -%%%----------------------------------------------------------------- -%%% Log a string or report --spec log(LogEvent, Config) -> ok | dropped when - LogEvent :: logger:log_event(), - Config :: logger:handler_config(). +merge_default_logopts(Name, HConfig) -> + Type = maps:get(type, HConfig, wrap), + {DefaultNoFiles,DefaultNoBytes} = + case Type of + halt -> {undefined,infinity}; + _wrap -> {10,1048576} + end, + {ok,Dir} = file:get_cwd(), + Defaults = #{file => filename:join(Dir,Name), + max_no_files => DefaultNoFiles, + max_no_bytes => DefaultNoBytes, + type => Type}, + maps:merge(Defaults, HConfig). -log(LogEvent, Config = #{id := Name, - config := #{handler_pid := HPid, - mode_tab := ModeTab}}) -> - %% if the handler has crashed, we must drop this event - %% and hope the handler restarts so we can try again - true = is_process_alive(HPid), - Bin = logger_h_common:log_to_binary(LogEvent, Config), - logger_h_common:call_cast_or_drop(Name, HPid, ModeTab, Bin). +filesync(Name,_Mode,State) -> + Result = ?disk_log_sync(Name), + maybe_notify_error(Name, filesync, Result, prev_sync_result, State). -%%%=================================================================== -%%% gen_server callbacks -%%%=================================================================== +write(Name, Mode, Bin, State) -> + Result = ?disk_log_write(Name, Mode, Bin), + maybe_notify_error(Name, log, Result, prev_log_result, State). -init([Name, - Config = #{config := HConfig = #{file:=File, - type:=Type, - max_no_bytes:=MNB, - max_no_files:=MNF}}, - State = #{dl_sync_int := DLSyncInt}]) -> - - RegName = ?name_to_reg_name(?MODULE,Name), - register(RegName, self()), - process_flag(trap_exit, true), - process_flag(message_queue_data, off_heap), - - ?init_test_hooks(), - ?start_observation(Name), - - LogOpts = #{file=>File, type=>Type, max_no_bytes=>MNB, max_no_files=>MNF}, - case open_disk_log(Name, File, Type, MNB, MNF) of - ok -> - try ets:new(Name, [public]) of - ModeTab -> - ?set_mode(ModeTab, async), - T0 = ?timestamp(), - State1 = - ?merge_with_stats(State#{ - id => Name, - mode_tab => ModeTab, - mode => async, - dl_sync => DLSyncInt, - log_opts => LogOpts, - last_qlen => 0, - 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}), - Config1 = - Config#{config => HConfig#{handler_pid => self(), - mode_tab => ModeTab}}, - proc_lib:init_ack({ok,self(),Config1}), - gen_server:cast(self(), repeated_disk_log_sync), - case logger_h_common:unset_restart_flag(Name, ?MODULE) of - true -> - %% inform about restart - gen_server:cast(self(), {log_handler_info, - "Handler ~p restarted", - [Name]}); - false -> - %% initial start - ok - end, - enter_loop(Config1, State1) - catch - _:Error -> - unregister(RegName), - logger_h_common:error_notify({open_disk_log,Name,Error}), - proc_lib:init_ack(Error) - end; - Error -> - unregister(RegName), - logger_h_common:error_notify({open_disk_log,Name,Error}), - proc_lib:init_ack(Error) - end. - -enter_loop(_Config,State) -> - gen_server:enter_loop(?MODULE,[],State). - -%% This is the synchronous log event. -handle_call({log, Bin}, _From, State) -> - {Result,State1} = do_log(Bin, call, State), - %% Result == ok | dropped - {reply, Result, State1}; - -handle_call(disk_log_sync, _From, State = #{id := Name}) -> - State1 = #{prev_sync_result := Result} = disk_log_sync(Name, State), - {reply, Result, State1}; - -handle_call({change_config,_OldConfig,NewConfig}, _From, - State = #{filesync_repeat_interval := FSyncInt0}) -> - HConfig = maps:get(config, NewConfig, #{}), - State1 = #{sync_mode_qlen := SMQL, - drop_mode_qlen := DMQL, - flush_qlen := FQL} = maps:merge(State, HConfig), - case logger_h_common:overload_levels_ok(State1) of - true -> - _ = - case maps:get(filesync_repeat_interval, HConfig, undefined) of - undefined -> - ok; - no_repeat -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, - State, - undefined)); - FSyncInt0 -> - ok; - _FSyncInt1 -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, - State, - undefined)), - _ = gen_server:cast(self(), repeated_disk_log_sync) - end, - {reply, ok, State1}; - false -> - {reply, {error,{invalid_levels,{SMQL,DMQL,FQL}}}, State} - end; - -handle_call(info, _From, State) -> - {reply, State, State}; - -handle_call(reset, _From, State) -> - State1 = ?merge_with_stats(State), - {reply, ok, State1#{last_qlen => 0, - last_log_ts => ?timestamp(), - prev_log_result => ok, - prev_sync_result => ok, - prev_disk_log_info => undefined}}; - -handle_call(stop, _From, State) -> - {stop, {shutdown,stopped}, ok, State}. - - -%% This is the asynchronous log event. -handle_cast({log, Bin}, State) -> - {_,State1} = do_log(Bin, cast, State), - {noreply, State1}; - -handle_cast({log_handler_info, Format, Args}, State = #{id:=Name}) -> - log_handler_info(Name, Format, Args, State), - {noreply, State}; - -%% If FILESYNC_REPEAT_INTERVAL is set to a millisec value, this -%% clause gets called repeatedly by the handler. In order to -%% guarantee that a filesync *always* happens after the last log -%% event, the repeat operation must be active! -handle_cast(repeated_disk_log_sync, - State = #{id := Name, - filesync_repeat_interval := FSyncInt, - last_op := LastOp}) -> - State1 = - if is_integer(FSyncInt) -> - %% only do filesync if something has been - %% written since last time we checked - 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]), - NewState#{rep_sync_tref => TRef, last_op => sync}; - true -> - State - end, - {noreply,State1}. +reset_state(_Name, State) -> + State#{prev_log_result => ok, + prev_sync_result => ok, + prev_disk_log_info => undefined}. %% The disk log owner must handle status messages from disk_log. -handle_info({disk_log, _Node, _Log, {wrap,_NoLostItems}}, State) -> - {noreply, State}; -handle_info({disk_log, _Node, Log, Info = {truncated,_NoLostItems}}, - State = #{id := Name, prev_disk_log_info := PrevInfo}) -> - error_notify_new(Info, PrevInfo, {disk_log,Name,Log,Info}), - {noreply, State#{prev_disk_log_info => Info}}; -handle_info({disk_log, _Node, Log, Info = {blocked_log,_Items}}, - State = #{id := Name, prev_disk_log_info := PrevInfo}) -> - error_notify_new(Info, PrevInfo, {disk_log,Name,Log,Info}), - {noreply, State#{prev_disk_log_info => Info}}; -handle_info({disk_log, _Node, Log, full}, - State = #{id := Name, prev_disk_log_info := PrevInfo}) -> - error_notify_new(full, PrevInfo, {disk_log,Name,Log,full}), - {noreply, State#{prev_disk_log_info => full}}; -handle_info({disk_log, _Node, Log, Info = {error_status,_Status}}, - State = #{id := Name, prev_disk_log_info := PrevInfo}) -> - error_notify_new(Info, PrevInfo, {disk_log,Name,Log,Info}), - {noreply, State#{prev_disk_log_info => Info}}; - -handle_info({'EXIT',_Pid,_Why}, State = #{id := _Name}) -> - {noreply, State}; - -handle_info(_, State) -> - {noreply, State}. - -terminate(Reason, State = #{id := Name}) -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, State, - undefined)), +handle_info(Name, {disk_log, _Node, Log, Info={truncated,_NoLostItems}}, State) -> + maybe_notify_status(Name, Log, Info, prev_disk_log_info, State); +handle_info(Name, {disk_log, _Node, Log, Info = {blocked_log,_Items}}, State) -> + maybe_notify_status(Name, Log, Info, prev_disk_log_info, State); +handle_info(Name, {disk_log, _Node, Log, Info = full}, State) -> + maybe_notify_status(Name, Log, Info, prev_disk_log_info, State); +handle_info(Name, {disk_log, _Node, Log, Info = {error_status,_Status}}, State) -> + maybe_notify_status(Name, Log, Info, prev_disk_log_info, State); +handle_info(_, _, State) -> + State. + +terminate(Name, _Reason, _State) -> _ = close_disk_log(Name, normal), - unregister(?name_to_reg_name(?MODULE, Name)), - logger_h_common:stop_or_restart(Name, Reason, State). - -code_change(_OldVsn, State, _Extra) -> - {ok, State}. + ok. %%%----------------------------------------------------------------- %%% Internal functions - -%%%----------------------------------------------------------------- -%%% -get_init_state() -> - #{sync_mode_qlen => ?SYNC_MODE_QLEN, - drop_mode_qlen => ?DROP_MODE_QLEN, - flush_qlen => ?FLUSH_QLEN, - burst_limit_enable => ?BURST_LIMIT_ENABLE, - burst_limit_max_count => ?BURST_LIMIT_MAX_COUNT, - burst_limit_window_time => ?BURST_LIMIT_WINDOW_TIME, - overload_kill_enable => ?OVERLOAD_KILL_ENABLE, - overload_kill_qlen => ?OVERLOAD_KILL_QLEN, - overload_kill_mem_size => ?OVERLOAD_KILL_MEM_SIZE, - overload_kill_restart_after => ?OVERLOAD_KILL_RESTART_AFTER, - dl_sync_int => ?CONTROLLER_SYNC_INTERVAL, - filesync_ok_qlen => ?FILESYNC_OK_QLEN, - filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}. - -%%%----------------------------------------------------------------- -%%% Add a disk_log handler to the logger. -%%% This starts a dedicated handler process which should always -%%% exist if the handler is registered with logger (and should not -%%% exist if the handler is not registered). -%%% -%%% Config is the logger:handler_config() map. Handler specific parameters -%%% should be provided with a sub map associated with a key named -%%% 'config', e.g: -%%% -%%% Config = #{config => #{sync_mode_qlen => 50} -%%% -%%% The 'config' sub map will also contain parameters for configuring -%%% the disk_log: -%%% -%%% Config = #{config => #{file => file:filename(), -%%% max_no_bytes => integer(), -%%% max_no_files => integer(), -%%% type => wrap | halt}}. -%%% -%%% If type == halt, then max_no_files is ignored. -%%% -%%% The disk_log handler process is linked to logger_sup, which is -%%% part of the kernel application's supervision tree. -start(Name, Config, HandlerState) -> - LoggerDLH = - #{id => Name, - start => {?MODULE, start_link, [Name,Config,HandlerState]}, - restart => temporary, - shutdown => 2000, - type => worker, - modules => [?MODULE]}, - case supervisor:start_child(logger_sup, LoggerDLH) of - {ok,_Pid,Config1} -> - {ok,Config1}; - Error -> - Error - end. - -%%%----------------------------------------------------------------- -%%% Stop and remove the handler. -stop(Name) -> - case whereis(?name_to_reg_name(?MODULE,Name)) of - undefined -> - ok; - Pid -> - %% We don't want to do supervisor:terminate_child here - %% since we need to distinguish this explicit stop from a - %% system termination in order to avoid circular attempts - %% at removing the handler (implying deadlocks and - %% timeouts). - _ = gen_server:call(Pid, stop), - _ = supervisor:delete_child(logger_sup, Name), - ok - end. - -%%%----------------------------------------------------------------- -%%% Logging and overload control. --define(update_dl_sync(C, Interval), - if C == 0 -> Interval; - true -> C-1 end). - -%% check for overload between every event (and set Mode to async, -%% sync or drop accordingly), but never flush the whole mailbox -%% before LogWindowSize events have been handled -do_log(Bin, CallOrCast, State = #{id:=Name, mode := Mode0}) -> - T1 = ?timestamp(), - - %% check if the handler is getting overloaded, or if it's - %% recovering from overload (the check must be done for each - %% event to react quickly to large bursts of events and - %% to ensure that the handler can never end up in drop mode - %% with an empty mailbox, which would stop operation) - {Mode1,QLen,Mem,State1} = logger_h_common:check_load(State), - - if (Mode1 == drop) andalso (Mode0 =/= drop) -> - log_handler_info(Name, "Handler ~p switched to drop mode", - [Name], State); - (Mode0 == drop) andalso ((Mode1 == async) orelse (Mode1 == sync)) -> - log_handler_info(Name, "Handler ~p switched to ~w mode", - [Name,Mode1], State); - true -> - ok - end, - - %% kill the handler if it can't keep up with the load - logger_h_common:kill_if_choked(Name, QLen, Mem, ?MODULE, State), - - if Mode1 == flush -> - flush(Name, QLen, T1, State1); - true -> - write(Name, Mode1, T1, Bin, CallOrCast, State1) - end. - -%% this function is called by do_log/3 after an overload check -%% has been performed, where QLen > FlushQLen -flush(Name, _QLen0, T1, State=#{last_log_ts := _T0, mode_tab := ModeTab}) -> - %% flush messages in the mailbox (a limited number in - %% order to not cause long delays) - NewFlushed = logger_h_common:flush_log_events(?FLUSH_MAX_N), - - %% write info in log about flushed messages - log_handler_info(Name, "Handler ~p flushed ~w log events", - [Name,NewFlushed], State), - - %% because of the receive loop when flushing messages, the - %% handler will be scheduled out often and the mailbox could - %% grow very large, so we'd better check the queue again here - {_,_QLen1} = process_info(self(), message_queue_len), - ?observe(Name,{max_qlen,_QLen1}), - - %% Add 1 for the current log event - ?observe(Name,{flushed,NewFlushed+1}), - - State1 = ?update_max_time(?diff_time(T1,_T0),State), - {dropped,?update_other(flushed,FLUSHED,NewFlushed, - State1#{mode => ?set_mode(ModeTab,async), - last_qlen => 0, - last_log_ts => T1})}. - -%% this function is called to write to disk_log -write(Name, Mode, T1, Bin, _CallOrCast, - State = #{mode_tab := ModeTab, - dl_sync := DLSync, - dl_sync_int := DLSyncInt, - last_qlen := LastQLen, - last_log_ts := T0}) -> - %% check if we need to limit the number of writes - %% during a burst of log events - {DoWrite,BurstWinT,BurstMsgCount} = logger_h_common:limit_burst(State), - - %% only send a synhrounous event to the disk_log process - %% every DLSyncInt time, to give the handler time between - %% writes so it can keep up with incoming messages - {Status,LastQLen1,State1} = - if DoWrite, DLSync == 0 -> - ?observe(Name,{_CallOrCast,1}), - NewState = disk_log_write(Name, Bin, State), - {ok, element(2,process_info(self(),message_queue_len)), - NewState}; - DoWrite -> - ?observe(Name,{_CallOrCast,1}), - NewState = disk_log_write(Name, Bin, State), - {ok, LastQLen, NewState}; - not DoWrite -> - ?observe(Name,{flushed,1}), - {dropped, LastQLen, State} - end, - - %% Check if the time since the previous log event is long enough - - %% and the queue length small enough - to assume the mailbox has - %% been emptied, and if so, do filesync operation and reset mode to - %% async. Note that this is the best we can do to detect an idle - %% handler without setting a timer after each log call/cast. If the - %% time between two consecutive log events is fast and no new - %% event comes in after the last one, idle state won't be detected! - Time = ?diff_time(T1,T0), - {Mode1,BurstMsgCount1,State2} = - if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso - (Time > ?IDLE_DETECT_TIME_USEC) -> - {?change_mode(ModeTab,Mode,async), 0, disk_log_sync(Name,State1)}; - true -> - {Mode, BurstMsgCount,State1} - end, - - State3 = - ?update_calls_or_casts(_CallOrCast,1,State2), - State4 = - ?update_max_time(Time, - State3#{mode => Mode1, - last_qlen := LastQLen1, - last_log_ts => T1, - burst_win_ts => BurstWinT, - burst_msg_count => BurstMsgCount1, - dl_sync => ?update_dl_sync(DLSync,DLSyncInt)}), - {Status,State4}. - - -log_handler_info(Name, Format, Args, State) -> - Config = - case logger:get_handler_config(Name) of - {ok,Conf} -> Conf; - _ -> #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}} - end, - Meta = #{time=>erlang:system_time(microsecond)}, - Bin = logger_h_common:log_to_binary(#{level => notice, - msg => {Format,Args}, - meta => Meta}, Config), - _ = disk_log_write(Name, Bin, State), - ok. - - open_disk_log(Name, File, Type, MaxNoBytes, MaxNoFiles) -> case filelib:ensure_dir(File) of ok -> @@ -679,43 +227,26 @@ close_disk_log(Name, _) -> _ = disk_log:lclose(Name), ok. -disk_log_write(Name, Bin, State) -> - case ?disk_log_blog(Name, Bin) of - ok -> - State#{prev_log_result => ok, last_op => write}; - LogError -> - _ = case maps:get(prev_log_result, State) of - LogError -> - %% don't report same error twice - ok; - _ -> - LogOpts = maps:get(log_opts, State), - logger_h_common:error_notify({Name,log, - LogOpts, - LogError}) - end, - State#{prev_log_result => LogError} - end. - -disk_log_sync(Name, State) -> - 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,filesync, - LogOpts, - SyncError}) - end, - State#{prev_sync_result => SyncError} - end. +disk_log_write(Name, sync, Bin) -> + disk_log:blog(Name, Bin); +disk_log_write(Name, async, Bin) -> + disk_log:balog(Name, Bin). + +%%%----------------------------------------------------------------- +%%% Print error messages, but don't repeat the same message +maybe_notify_error(Name, Op, Result, Key, #{log_opts:=LogOpts}=State) -> + {Result,error_notify_new({Name, Op, LogOpts, Result}, Result, Key, State)}. -error_notify_new(Info,Info, _Term) -> +maybe_notify_status(Name, Log, Info, Key, State) -> + error_notify_new({disk_log, Name, Log, Info}, Info, Key, State). + +error_notify_new(Term, What, Key, State) -> + error_notify_new(What, maps:get(Key,State), Term), + State#{Key => What}. + +error_notify_new(ok,_Prev,_Term) -> + ok; +error_notify_new(Same,Same,_Term) -> ok; -error_notify_new(_Info0,_Info1, Term) -> +error_notify_new(_New,_Prev,Term) -> logger_h_common:error_notify(Term). diff --git a/lib/kernel/src/logger_formatter.erl b/lib/kernel/src/logger_formatter.erl index 456b0c9e8d..8696adbd72 100644 --- a/lib/kernel/src/logger_formatter.erl +++ b/lib/kernel/src/logger_formatter.erl @@ -26,16 +26,16 @@ %%%----------------------------------------------------------------- %%% Types --type config() :: #{chars_limit=>pos_integer()| unlimited, - depth=>pos_integer() | unlimited, - legacy_header=>boolean(), - max_size=>pos_integer() | unlimited, - report_cb=>fun((logger:report()) -> {io:format(),[term()]}), - single_line=>boolean(), - template=>template(), - time_designator=>byte(), - time_offset=>integer()|[byte()]}. --type template() :: [metakey()|{metakey(),template(),template()}|string()]. +-type config() :: #{chars_limit => pos_integer() | unlimited, + depth => pos_integer() | unlimited, + legacy_header => boolean(), + max_size => pos_integer() | unlimited, + report_cb => logger:report_cb(), + single_line => boolean(), + template => template(), + time_designator => byte(), + time_offset => integer() | [byte()]}. +-type template() :: [metakey() | {metakey(),template(),template()} | string()]. -type metakey() :: atom() | [atom()]. %%%----------------------------------------------------------------- @@ -64,7 +64,7 @@ format(#{level:=Level,msg:=Msg0,meta:=Meta},Config0) Config; Size0 -> Size = - case Size0 - string:length([B,A]) of + case Size0 - io_lib:chars_length([B,A]) of S when S>=0 -> S; _ -> 0 end, @@ -75,15 +75,38 @@ format(#{level:=Level,msg:=Msg0,meta:=Meta},Config0) true -> %% Trim leading and trailing whitespaces, and replace %% newlines with ", " - re:replace(string:trim(MsgStr0),",?\r?\n\s*",", ", - [{return,list},global]); + T = lists:reverse( + trim( + lists:reverse( + trim(MsgStr0,false)),true)), + re:replace(T,",?\r?\n\s*",", ", + [{return,list},global,unicode]); _false -> MsgStr0 end; true -> "" end, - truncate(B ++ MsgStr ++ A,maps:get(max_size,Config)). + truncate(B,MsgStr,A,maps:get(max_size,Config)). + +trim([H|T],Rev) when H==$\s; H==$\r; H==$\n -> + trim(T,Rev); +trim([H|T],false) when is_list(H) -> + case trim(H,false) of + [] -> + trim(T,false); + TrimmedH -> + [TrimmedH|T] + end; +trim([H|T],true) when is_list(H) -> + case trim(lists:reverse(H),true) of + [] -> + trim(T,true); + TrimmedH -> + [lists:reverse(TrimmedH)|T] + end; +trim(String,_) -> + String. do_format(Level,Data,[level|Format],Config) -> [to_string(level,Level,Config)|do_format(Level,Data,Format,Config)]; @@ -119,93 +142,167 @@ value(_,_) -> to_string(time,Time,Config) -> format_time(Time,Config); -to_string(mfa,MFA,_Config) -> - format_mfa(MFA); -to_string(_,Value,_Config) -> - to_string(Value). +to_string(mfa,MFA,Config) -> + format_mfa(MFA,Config); +to_string(_,Value,Config) -> + to_string(Value,Config). -to_string(X) when is_atom(X) -> +to_string(X,_) when is_atom(X) -> atom_to_list(X); -to_string(X) when is_integer(X) -> +to_string(X,_) when is_integer(X) -> integer_to_list(X); -to_string(X) when is_pid(X) -> +to_string(X,_) when is_pid(X) -> pid_to_list(X); -to_string(X) when is_reference(X) -> +to_string(X,_) when is_reference(X) -> ref_to_list(X); -to_string(X) when is_list(X) -> - case io_lib:printable_unicode_list(lists:flatten(X)) of +to_string(X,Config) when is_list(X) -> + case printable_list(lists:flatten(X)) of true -> X; - _ -> io_lib:format("~tp",[X]) + _ -> io_lib:format(p(Config),[X]) end; -to_string(X) -> - io_lib:format("~tp",[X]). +to_string(X,Config) -> + io_lib:format(p(Config),[X]). + +printable_list([]) -> + false; +printable_list(X) -> + io_lib:printable_list(X). format_msg({string,Chardata},Meta,Config) -> format_msg({"~ts",[Chardata]},Meta,Config); -format_msg({report,_}=Msg,Meta,#{report_cb:=Fun}=Config) when is_function(Fun,1) -> +format_msg({report,_}=Msg,Meta,#{report_cb:=Fun}=Config) + when is_function(Fun,1); is_function(Fun,2) -> format_msg(Msg,Meta#{report_cb=>Fun},maps:remove(report_cb,Config)); format_msg({report,Report},#{report_cb:=Fun}=Meta,Config) when is_function(Fun,1) -> try Fun(Report) of {Format,Args} when is_list(Format), is_list(Args) -> format_msg({Format,Args},maps:remove(report_cb,Meta),Config); Other -> - format_msg({"REPORT_CB ERROR: ~tp; Returned: ~tp", + P = p(Config), + format_msg({"REPORT_CB/1 ERROR: "++P++"; Returned: "++P, + [Report,Other]},Meta,Config) + catch C:R:S -> + P = p(Config), + format_msg({"REPORT_CB/1 CRASH: "++P++"; Reason: "++P, + [Report,{C,R,logger:filter_stacktrace(?MODULE,S)}]}, + Meta,Config) + end; +format_msg({report,Report},#{report_cb:=Fun}=Meta,Config) when is_function(Fun,2) -> + try Fun(Report,maps:with([depth,chars_limit,single_line],Config)) of + Chardata when ?IS_STRING(Chardata) -> + try chardata_to_list(Chardata) % already size limited by report_cb + catch _:_ -> + P = p(Config), + format_msg({"REPORT_CB/2 ERROR: "++P++"; Returned: "++P, + [Report,Chardata]},Meta,Config) + end; + Other -> + P = p(Config), + format_msg({"REPORT_CB/2 ERROR: "++P++"; Returned: "++P, [Report,Other]},Meta,Config) - catch C:R -> - format_msg({"REPORT_CB CRASH: ~tp; Reason: ~tp", - [Report,{C,R}]},Meta,Config) + catch C:R:S -> + P = p(Config), + format_msg({"REPORT_CB/2 CRASH: "++P++"; Reason: "++P, + [Report,{C,R,logger:filter_stacktrace(?MODULE,S)}]}, + Meta,Config) end; format_msg({report,Report},Meta,Config) -> format_msg({report,Report}, Meta#{report_cb=>fun logger:format_report/1}, Config); -format_msg(Msg,_Meta,#{depth:=Depth,chars_limit:=CharsLimit}) -> - limit_size(Msg, Depth, CharsLimit). - -limit_size(Msg,Depth,unlimited) -> - limit_size(Msg,Depth,[]); -limit_size(Msg,Depth,CharsLimit) when is_integer(CharsLimit) -> - limit_size(Msg,Depth,[{chars_limit,CharsLimit}]); -limit_size({Format,Args},unlimited,Opts) when is_list(Opts) -> - try io_lib:format(Format,Args,Opts) - catch _:_ -> - io_lib:format("FORMAT ERROR: ~tp - ~tp",[Format,Args],Opts) - end; -limit_size({Format0,Args},Depth,Opts) when is_integer(Depth) -> +format_msg(Msg,_Meta,#{depth:=Depth,chars_limit:=CharsLimit, + single_line:=Single}) -> + Opts = chars_limit_to_opts(CharsLimit), + format_msg(Msg, Depth, Opts, Single). + +chars_limit_to_opts(unlimited) -> []; +chars_limit_to_opts(CharsLimit) -> [{chars_limit,CharsLimit}]. + +format_msg({Format0,Args},Depth,Opts,Single) -> try Format1 = io_lib:scan_format(Format0, Args), - Format = limit_format(Format1, Depth), + Format = reformat(Format1, Depth, Single), io_lib:build_text(Format,Opts) - catch _:_ -> - limit_size({"FORMAT ERROR: ~tp - ~tp",[Format0,Args]},Depth,Opts) + catch C:R:S -> + P = p(Single), + FormatError = "FORMAT ERROR: "++P++" - "++P, + case Format0 of + FormatError -> + %% already been here - avoid failing cyclically + erlang:raise(C,R,S); + _ -> + format_msg({FormatError,[Format0,Args]},Depth,Opts,Single) + end end. -limit_format([#{control_char:=C0}=M0|T], Depth) when C0 =:= $p; - C0 =:= $w -> - C = C0 - ($a - $A), %To uppercase. - #{args:=Args} = M0, - M = M0#{control_char:=C,args:=Args++[Depth]}, - [M|limit_format(T, Depth)]; -limit_format([H|T], Depth) -> - [H|limit_format(T, Depth)]; -limit_format([], _) -> +reformat(Format,unlimited,false) -> + Format; +reformat([#{control_char:=C}=M|T], Depth, true) when C =:= $p -> + [limit_depth(M#{width => 0}, Depth)|reformat(T, Depth, true)]; +reformat([#{control_char:=C}=M|T], Depth, true) when C =:= $P -> + [M#{width => 0}|reformat(T, Depth, true)]; +reformat([#{control_char:=C}=M|T], Depth, Single) when C =:= $p; C =:= $w -> + [limit_depth(M, Depth)|reformat(T, Depth, Single)]; +reformat([H|T], Depth, Single) -> + [H|reformat(T, Depth, Single)]; +reformat([], _, _) -> []. -truncate(String,unlimited) -> - String; -truncate(String,Size) -> - Length = string:length(String), +limit_depth(M0, unlimited) -> + M0; +limit_depth(#{control_char:=C0, args:=Args}=M0, Depth) -> + C = C0 - ($a - $A), %To uppercase. + M0#{control_char:=C,args:=Args++[Depth]}. + +chardata_to_list(Chardata) -> + case unicode:characters_to_list(Chardata,unicode) of + List when is_list(List) -> + List; + Error -> + throw(Error) + end. + +truncate(B,Msg,A,unlimited) -> + [B,Msg,A]; +truncate(B,Msg,A,Size) -> + String = [B,Msg,A], + Length = io_lib:chars_length(String), if Length>Size -> - case lists:reverse(lists:flatten(String)) of - [$\n|_] -> - string:slice(String,0,Size-4)++"...\n"; + {Last,FlatString} = + case A of + [] -> + case Msg of + [] -> + {get_last(B),lists:flatten(B)}; + _ -> + {get_last(Msg),lists:flatten([B,Msg])} + end; + _ -> + {get_last(A),lists:flatten(String)} + end, + case Last of + $\n-> + lists:sublist(FlatString,1,Size-4)++"...\n"; _ -> - string:slice(String,0,Size-3)++"..." + lists:sublist(FlatString,1,Size-3)++"..." end; true -> String end. +get_last(L) -> + get_first(lists:reverse(L)). + +get_first([]) -> + error; +get_first([C|_]) when is_integer(C) -> + C; +get_first([L|Rest]) when is_list(L) -> + case get_last(L) of + error -> get_first(Rest); + First -> First + end. + %% SysTime is the system time in microseconds format_time(SysTime,#{time_offset:=Offset,time_designator:=Des}) when is_integer(SysTime) -> @@ -225,12 +322,12 @@ timestamp_to_datetimemicro(SysTime,Config) when is_integer(SysTime) -> end, {Date,Time,Micro,UtcStr}. -format_mfa({M,F,A}) when is_atom(M), is_atom(F), is_integer(A) -> +format_mfa({M,F,A},_) when is_atom(M), is_atom(F), is_integer(A) -> atom_to_list(M)++":"++atom_to_list(F)++"/"++integer_to_list(A); -format_mfa({M,F,A}) when is_atom(M), is_atom(F), is_list(A) -> - format_mfa({M,F,length(A)}); -format_mfa(MFA) -> - to_string(MFA). +format_mfa({M,F,A},Config) when is_atom(M), is_atom(F), is_list(A) -> + format_mfa({M,F,length(A)},Config); +format_mfa(MFA,Config) -> + to_string(MFA,Config). maybe_add_legacy_header(Level, #{time:=Timestamp}=Meta, @@ -280,10 +377,10 @@ month(12) -> "Dec". %% configuration map add_default_config(Config0) -> Default = - #{legacy_header=>false, + #{chars_limit=>unlimited, error_logger_notice_header=>info, + legacy_header=>false, single_line=>true, - chars_limit=>unlimited, time_designator=>$T}, MaxSize = get_max_size(maps:get(max_size,Config0,undefined)), Depth = get_depth(maps:get(depth,Config0,undefined)), @@ -369,7 +466,8 @@ do_check_config([{legacy_header,LH}|Config]) when is_boolean(LH) -> do_check_config([{error_logger_notice_header,ELNH}|Config]) when ELNH == info; ELNH == notice -> do_check_config(Config); -do_check_config([{report_cb,RCB}|Config]) when is_function(RCB,1) -> +do_check_config([{report_cb,RCB}|Config]) when is_function(RCB,1); + is_function(RCB,2) -> do_check_config(Config); do_check_config([{template,T}|Config]) -> case check_template(T) of @@ -456,3 +554,10 @@ check_timezone(Tz) -> catch _:_ -> error end. + +p(#{single_line:=Single}) -> + p(Single); +p(true) -> + "~0tp"; +p(false) -> + "~tp". diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl index a40345dddc..16946ff97c 100644 --- a/lib/kernel/src/logger_h_common.erl +++ b/lib/kernel/src/logger_h_common.erl @@ -18,29 +18,362 @@ %% %CopyrightEnd% %% -module(logger_h_common). +-behaviour(gen_server). -include("logger_h_common.hrl"). -include("logger_internal.hrl"). --export([log_to_binary/2, - check_common_config/1, - call_cast_or_drop/4, - check_load/1, - limit_burst/1, - kill_if_choked/5, - flush_log_events/0, - flush_log_events/1, - handler_exit/2, - set_restart_flag/2, - unset_restart_flag/2, - cancel_timer/1, - stop_or_restart/3, - overload_levels_ok/1, - error_notify/1, - info_notify/1]). +%% API +-export([filesync/2]). + +%% logger_olp callbacks +-export([init/1, handle_load/2, handle_call/3, handle_cast/2, handle_info/2, + terminate/2, code_change/3, notify/2, reset_state/1]). + +%% logger callbacks +-export([log/2, adding_handler/1, removing_handler/1, changing_config/3, + filter_config/1]). + +%% Library functions for handlers +-export([error_notify/1]). + +-define(OLP_KEYS,[sync_mode_qlen, + drop_mode_qlen, + flush_qlen, + burst_limit_enable, + burst_limit_max_count, + burst_limit_window_time, + overload_kill_enable, + overload_kill_qlen, + overload_kill_mem_size, + overload_kill_restart_after]). + +-define(COMMON_KEYS,[filesync_repeat_interval]). + +-define(READ_ONLY_KEYS,[olp]). + +%%%----------------------------------------------------------------- +%%% API + +%% This function is called by the logger_sup supervisor +filesync(Module, Name) -> + call(Module, Name, filesync). + +%%%----------------------------------------------------------------- +%%% Handler being added +adding_handler(#{id:=Name,module:=Module}=Config) -> + HConfig0 = maps:get(config, Config, #{}), + HandlerConfig0 = maps:without(?OLP_KEYS++?COMMON_KEYS,HConfig0), + case Module:check_config(Name,set,undefined,HandlerConfig0) of + {ok,HandlerConfig} -> + ModifiedCommon = maps:with(?COMMON_KEYS,HandlerConfig), + CommonConfig0 = maps:with(?COMMON_KEYS,HConfig0), + CommonConfig = maps:merge( + maps:merge(get_default_config(), CommonConfig0), + ModifiedCommon), + case check_config(CommonConfig) of + ok -> + HConfig = maps:merge(CommonConfig,HandlerConfig), + OlpOpts = maps:with(?OLP_KEYS,HConfig0), + start(OlpOpts, Config#{config => HConfig}); + {error,Faulty} -> + {error,{invalid_config,Module,Faulty}} + end; + Error -> + Error + end. + +%%%----------------------------------------------------------------- +%%% Handler being removed +removing_handler(#{id:=Name, module:=Module, config:=#{olp:=Olp}}) -> + case whereis(?name_to_reg_name(Module,Name)) of + undefined -> + ok; + _Pid -> + %% We don't want to do supervisor:terminate_child here + %% since we need to distinguish this explicit stop from a + %% system termination in order to avoid circular attempts + %% at removing the handler (implying deadlocks and + %% timeouts). + %% And we don't need to do supervisor:delete_child, since + %% the restart type is temporary, which means that the + %% child specification is automatically removed from the + %% supervisor when the process dies. + _ = logger_olp:stop(Olp), + ok + end. + +%%%----------------------------------------------------------------- +%%% Updating handler config +changing_config(SetOrUpdate, + #{id:=Name,config:=OldHConfig,module:=Module}, + NewConfig0) -> + NewHConfig0 = maps:get(config, NewConfig0, #{}), + NoHandlerKeys = ?OLP_KEYS++?COMMON_KEYS++?READ_ONLY_KEYS, + OldHandlerConfig = maps:without(NoHandlerKeys,OldHConfig), + NewHandlerConfig0 = maps:without(NoHandlerKeys,NewHConfig0), + case Module:check_config(Name, SetOrUpdate, + OldHandlerConfig,NewHandlerConfig0) of + {ok, NewHandlerConfig} -> + ModifiedCommon = maps:with(?COMMON_KEYS,NewHandlerConfig), + NewCommonConfig0 = maps:with(?COMMON_KEYS,NewHConfig0), + OldCommonConfig = maps:with(?COMMON_KEYS,OldHConfig), + CommonDefault = + case SetOrUpdate of + set -> + get_default_config(); + update -> + OldCommonConfig + end, + NewCommonConfig = maps:merge( + maps:merge(CommonDefault,NewCommonConfig0), + ModifiedCommon), + case check_config(NewCommonConfig) of + ok -> + OlpDefault = + case SetOrUpdate of + set -> + logger_olp:get_default_opts(); + update -> + maps:with(?OLP_KEYS,OldHConfig) + end, + Olp = maps:get(olp,OldHConfig), + NewOlpOpts = maps:merge(OlpDefault, + maps:with(?OLP_KEYS,NewHConfig0)), + case logger_olp:set_opts(Olp,NewOlpOpts) of + ok -> + logger_olp:cast(Olp, {config_changed, + NewCommonConfig, + NewHandlerConfig}), + ReadOnly = maps:with(?READ_ONLY_KEYS,OldHConfig), + NewHConfig = + maps:merge( + maps:merge( + maps:merge(NewCommonConfig,NewHandlerConfig), + ReadOnly), + NewOlpOpts), + NewConfig = NewConfig0#{config=>NewHConfig}, + {ok,NewConfig}; + Error -> + Error + end; + {error,Faulty} -> + {error,{invalid_config,Module,Faulty}} + end; + Error -> + Error + end. + +%%%----------------------------------------------------------------- +%%% Log a string or report +-spec log(LogEvent, Config) -> ok when + LogEvent :: logger:log_event(), + Config :: logger:handler_config(). + +log(LogEvent, Config = #{config := #{olp:=Olp}}) -> + %% if the handler has crashed, we must drop this event + %% and hope the handler restarts so we can try again + true = is_process_alive(logger_olp:get_pid(Olp)), + Bin = log_to_binary(LogEvent, Config), + logger_olp:load(Olp,Bin). %%%----------------------------------------------------------------- -%%% Covert log data on any form to binary +%%% Remove internal fields from configuration +filter_config(#{config:=HConfig}=Config) -> + Config#{config=>maps:without(?READ_ONLY_KEYS,HConfig)}. + +%%%----------------------------------------------------------------- +%%% Start the handler process +%%% +%%% The process must always exist if the handler is registered with +%%% logger (and must not exist if the handler is not registered). +%%% +%%% The handler process is linked to logger_sup, which is part of the +%%% kernel application's supervision tree. +start(OlpOpts0, #{id := Name, module:=Module, config:=HConfig} = Config0) -> + RegName = ?name_to_reg_name(Module,Name), + ChildSpec = + #{id => Name, + start => {logger_olp, start_link, [RegName,?MODULE, + Config0, OlpOpts0]}, + restart => temporary, + shutdown => 2000, + type => worker, + modules => [?MODULE]}, + case supervisor:start_child(logger_sup, ChildSpec) of + {ok,Pid,Olp} -> + ok = logger_handler_watcher:register_handler(Name,Pid), + OlpOpts = logger_olp:get_opts(Olp), + {ok,Config0#{config=>(maps:merge(HConfig,OlpOpts))#{olp=>Olp}}}; + {error,{Reason,Ch}} when is_tuple(Ch), element(1,Ch)==child -> + {error,Reason}; + Error -> + Error + end. + +%%%=================================================================== +%%% gen_server callbacks +%%%=================================================================== + +init(#{id := Name, module := Module, config := HConfig}) -> + process_flag(trap_exit, true), + + ?init_test_hooks(), + + case Module:init(Name, HConfig) of + {ok,HState} -> + %% Storing common config in state to avoid copying + %% (sending) the config data for each log message + CommonConfig = maps:with(?COMMON_KEYS,HConfig), + State = CommonConfig#{id => Name, + module => Module, + ctrl_sync_count => + ?CONTROLLER_SYNC_INTERVAL, + last_op => sync, + handler_state => HState}, + State1 = set_repeated_filesync(State), + {ok,State1}; + Error -> + Error + end. + +%% This is the log event. +handle_load(Bin, #{id:=Name, + module:=Module, + handler_state:=HandlerState, + ctrl_sync_count := CtrlSync}=State) -> + if CtrlSync==0 -> + {_,HS1} = Module:write(Name, sync, Bin, HandlerState), + State#{handler_state => HS1, + ctrl_sync_count => ?CONTROLLER_SYNC_INTERVAL, + last_op=>write}; + true -> + {_,HS1} = Module:write(Name, async, Bin, HandlerState), + State#{handler_state => HS1, + ctrl_sync_count => CtrlSync-1, + last_op=>write} + end. + +handle_call(filesync, _From, State = #{id := Name, + module := Module, + handler_state := HandlerState}) -> + {Result,HandlerState1} = Module:filesync(Name,sync,HandlerState), + {reply, Result, State#{handler_state=>HandlerState1, last_op=>sync}}. + +%% If FILESYNC_REPEAT_INTERVAL is set to a millisec value, this +%% clause gets called repeatedly by the handler. In order to +%% guarantee that a filesync *always* happens after the last log +%% event, the repeat operation must be active! +handle_cast(repeated_filesync,State = #{filesync_repeat_interval := no_repeat}) -> + %% This clause handles a race condition which may occur when + %% config changes filesync_repeat_interval from an integer value + %% to no_repeat. + {noreply,State}; +handle_cast(repeated_filesync, + State = #{id := Name, + module := Module, + handler_state := HandlerState, + last_op := LastOp}) -> + State1 = + if LastOp == sync -> + State; + true -> + {_,HS} = Module:filesync(Name, async, HandlerState), + State#{handler_state => HS, last_op => sync} + end, + {noreply,set_repeated_filesync(State1)}; +handle_cast({config_changed, CommonConfig, HConfig}, + State = #{id := Name, + module := Module, + handler_state := HandlerState, + filesync_repeat_interval := OldFSyncInt}) -> + State1 = + case maps:get(filesync_repeat_interval,CommonConfig) of + OldFSyncInt -> + State; + FSyncInt -> + set_repeated_filesync( + cancel_repeated_filesync( + State#{filesync_repeat_interval=>FSyncInt})) + end, + HS = try Module:config_changed(Name, HConfig, HandlerState) + catch error:undef -> HandlerState + end, + {noreply, State1#{handler_state => HS}}. + +handle_info(Info, #{id := Name, module := Module, + handler_state := HandlerState} = State) -> + {noreply,State#{handler_state => Module:handle_info(Name,Info,HandlerState)}}. + +terminate(overloaded=Reason, #{id:=Name}=State) -> + _ = log_handler_info(Name,"Handler ~p overloaded and stopping",[Name],State), + do_terminate(Reason,State), + ConfigResult = logger:get_handler_config(Name), + case ConfigResult of + {ok,#{module:=Module}=HConfig0} -> + spawn(fun() -> logger:remove_handler(Name) end), + HConfig = try Module:filter_config(HConfig0) + catch _:_ -> HConfig0 + end, + {ok,fun() -> logger:add_handler(Name,Module,HConfig) end}; + Error -> + error_notify({Name,restart_impossible,Error}), + Error + end; +terminate(Reason, State) -> + do_terminate(Reason, State). + +do_terminate(Reason, State = #{id := Name, + module := Module, + handler_state := HandlerState}) -> + _ = cancel_repeated_filesync(State), + _ = Module:terminate(Name, Reason, HandlerState), + ok. + +code_change(_OldVsn, State, _Extra) -> + {ok, State}. + +reset_state(#{id:=Name, module:=Module, handler_state:=HandlerState} = State) -> + State#{handler_state=>Module:reset_state(Name, HandlerState)}. + +%%%----------------------------------------------------------------- +%%% Internal functions +call(Module, Name, Op) when is_atom(Name) -> + case logger_olp:call(?name_to_reg_name(Module,Name), Op) of + {error,busy} -> {error,handler_busy}; + Other -> Other + end; +call(_, Name, Op) -> + {error,{badarg,{Op,[Name]}}}. + +notify({mode_change,Mode0,Mode1},#{id:=Name}=State) -> + log_handler_info(Name,"Handler ~p switched from ~p to ~p mode", + [Name,Mode0,Mode1], State); +notify({flushed,Flushed},#{id:=Name}=State) -> + log_handler_info(Name, "Handler ~p flushed ~w log events", + [Name,Flushed], State); +notify(restart,#{id:=Name}=State) -> + log_handler_info(Name, "Handler ~p restarted", [Name], State); +notify(idle,#{id:=Name,module:=Module,handler_state:=HandlerState}=State) -> + {_,HS} = Module:filesync(Name,async,HandlerState), + State#{handler_state=>HS, last_op=>sync}. + +log_handler_info(Name, Format, Args, #{module:=Module, + handler_state:=HandlerState}=State) -> + Config = + case logger:get_handler_config(Name) of + {ok,Conf} -> Conf; + _ -> #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}} + end, + Meta = #{time=>logger:timestamp()}, + Bin = log_to_binary(#{level => notice, + msg => {Format,Args}, + meta => Meta}, Config), + {_,HS} = Module:write(Name, async, Bin, HandlerState), + State#{handler_state=>HS, last_op=>write}. + +%%%----------------------------------------------------------------- +%%% Convert log data on any form to binary -spec log_to_binary(LogEvent,Config) -> LogString when LogEvent :: logger:log_event(), Config :: logger:handler_config(), @@ -57,13 +390,14 @@ do_log_to_binary(Log,Config) -> {Formatter,FormatterConfig} = maps:get(formatter,Config,{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}), String = try_format(Log,Formatter,FormatterConfig), - try unicode:characters_to_binary(String) - catch _:_ -> + try string_to_binary(String) + catch C2:R2:S2 -> ?LOG_INTERNAL(debug,[{formatter_error,Formatter}, {config,FormatterConfig}, {log_event,Log}, - {bad_return_value,String}]), - <<"FORMATTER ERROR: bad_return_value">> + {bad_return_value,String}, + {catched,{C2,R2,S2}}]), + <<"FORMATTER ERROR: bad return value">> end. try_format(Log,Formatter,FormatterConfig) -> @@ -85,254 +419,45 @@ try_format(Log,Formatter,FormatterConfig) -> end end. -%%%----------------------------------------------------------------- -%%% Check that the configuration term is valid -check_common_config({mode_tab,_Tid}) -> - valid; -check_common_config({handler_pid,Pid}) when is_pid(Pid) -> - valid; - -check_common_config({sync_mode_qlen,N}) when is_integer(N) -> - valid; -check_common_config({drop_mode_qlen,N}) when is_integer(N) -> - valid; -check_common_config({flush_qlen,N}) when is_integer(N) -> - valid; - -check_common_config({burst_limit_enable,Bool}) when Bool == true; - Bool == false -> - valid; -check_common_config({burst_limit_max_count,N}) when is_integer(N) -> - valid; -check_common_config({burst_limit_window_time,N}) when is_integer(N) -> - valid; - -check_common_config({overload_kill_enable,Bool}) when Bool == true; - Bool == false -> - valid; -check_common_config({overload_kill_qlen,N}) when is_integer(N) -> - valid; -check_common_config({overload_kill_mem_size,N}) when is_integer(N) -> - valid; -check_common_config({overload_kill_restart_after,NorA}) when is_integer(NorA); - NorA == infinity -> - valid; - -check_common_config({filesync_repeat_interval,NorA}) when is_integer(NorA); - NorA == no_repeat -> - valid; -check_common_config(_) -> - invalid. - +string_to_binary(String) -> + case unicode:characters_to_binary(String) of + Binary when is_binary(Binary) -> + Binary; + Error -> + throw(Error) + end. %%%----------------------------------------------------------------- -%%% Overload Protection -call_cast_or_drop(_Name, HandlerPid, ModeTab, Bin) -> - %% If the handler process is getting overloaded, the log event - %% will be synchronous instead of asynchronous (slows down the - %% logging tempo of a process doing lots of logging. If the - %% handler is choked, drop mode is set and no event will be sent. - try ?get_mode(ModeTab) of - async -> - gen_server:cast(HandlerPid, {log,Bin}); - sync -> - try gen_server:call(HandlerPid, {log,Bin}, ?DEFAULT_CALL_TIMEOUT) of - %% if return value from call == dropped, the - %% message has been flushed by handler and should - %% therefore not be counted as dropped in stats - ok -> ok; - dropped -> ok - catch - _:{timeout,_} -> - ?observe(_Name,{dropped,1}) - end; - drop -> - ?observe(_Name,{dropped,1}) - catch - %% if the ETS table doesn't exist (maybe because of a - %% handler restart), we can only drop the event - _:_ -> ?observe(_Name,{dropped,1}) - end, - ok. - -handler_exit(_Name, Reason) -> - exit(Reason). +%%% Check that the configuration term is valid +check_config(Config) when is_map(Config) -> + check_common_config(maps:to_list(Config)). -set_restart_flag(Name, Module) -> - Flag = list_to_atom(lists:concat([Module,"_",Name,"_restarting"])), - spawn(fun() -> - register(Flag, self()), - timer:sleep(infinity) - end), +check_common_config([{filesync_repeat_interval,NorA}|Config]) + when is_integer(NorA); NorA == no_repeat -> + check_common_config(Config); +check_common_config([{Key,Value}|_]) -> + {error,#{Key=>Value}}; +check_common_config([]) -> ok. -unset_restart_flag(Name, Module) -> - Flag = list_to_atom(lists:concat([Module,"_",Name,"_restarting"])), - case whereis(Flag) of - undefined -> - false; - Pid -> - exit(Pid, kill), - true - end. - -check_load(State = #{id:=_Name, mode_tab := ModeTab, mode := Mode, - sync_mode_qlen := SyncModeQLen, - drop_mode_qlen := DropModeQLen, - flush_qlen := FlushQLen}) -> - {_,Mem} = process_info(self(), memory), - ?observe(_Name,{max_mem,Mem}), - {_,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 events (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 -> - {flush, 0,1}; - QLen >= DropModeQLen -> - %% Note that drop mode will force log events to - %% be dropped on the client side (never sent get to - %% the handler). - IncDrops = if Mode == drop -> 0; true -> 1 end, - {?change_mode(ModeTab, Mode, drop), IncDrops,0}; - QLen >= SyncModeQLen -> - {?change_mode(ModeTab, Mode, sync), 0,0}; - true -> - {?change_mode(ModeTab, Mode, async), 0,0} - end, - State1 = ?update_other(drops,DROPS,_NewDrops,State), - {Mode1, QLen, Mem, - ?update_other(flushes,FLUSHES,_NewFlushes, - State1#{last_qlen => QLen})}. - -limit_burst(#{burst_limit_enable := false}) -> - {true,0,0}; -limit_burst(#{burst_win_ts := BurstWinT0, - burst_msg_count := BurstMsgCount, - burst_limit_window_time := BurstLimitWinTime, - burst_limit_max_count := BurstLimitMaxCnt}) -> - if (BurstMsgCount >= BurstLimitMaxCnt) -> - %% the limit for allowed messages has been reached - BurstWinT1 = ?timestamp(), - case ?diff_time(BurstWinT1,BurstWinT0) of - BurstCheckTime when BurstCheckTime < (BurstLimitWinTime*1000) -> - %% we're still within the burst time frame - {false,BurstWinT0,BurstMsgCount}; - _BurstCheckTime -> - %% burst time frame passed, reset counters - {true,BurstWinT1,0} - end; - true -> - %% the limit for allowed messages not yet reached - {true,BurstWinT0,BurstMsgCount+1} - end. +get_default_config() -> + #{filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}. -kill_if_choked(Name, QLen, Mem, HandlerMod, - State = #{overload_kill_enable := KillIfOL, - overload_kill_qlen := OLKillQLen, - overload_kill_mem_size := OLKillMem}) -> - if KillIfOL andalso - ((QLen > OLKillQLen) orelse (Mem > OLKillMem)) -> - HandlerMod:log_handler_info(Name, - "Handler ~p overloaded and stopping", - [Name], State), - set_restart_flag(Name, HandlerMod), - handler_exit(Name, {shutdown,{overloaded,Name,QLen,Mem}}); - true -> - ok - end. +set_repeated_filesync(#{filesync_repeat_interval:=FSyncInt} = State) + when is_integer(FSyncInt) -> + {ok,TRef} = timer:apply_after(FSyncInt, gen_server, cast, + [self(),repeated_filesync]), + State#{rep_sync_tref=>TRef}; +set_repeated_filesync(State) -> + State. -flush_log_events() -> - flush_log_events(-1). - -flush_log_events(Limit) -> - process_flag(priority, high), - Flushed = flush_log_events(0, Limit), - process_flag(priority, normal), - Flushed. - -flush_log_events(Limit, Limit) -> - Limit; -flush_log_events(N, Limit) -> - %% flush log events but leave other events, such as - %% filesync, info and change_config, so that these - %% have a chance to be processed even under heavy load - receive - {'$gen_cast',{log,_}} -> - flush_log_events(N+1, Limit); - {'$gen_call',{Pid,MRef},{log,_}} -> - Pid ! {MRef, dropped}, - flush_log_events(N+1, Limit) - after - 0 -> N +cancel_repeated_filesync(State) -> + case maps:take(rep_sync_tref,State) of + {TRef,State1} -> + _ = timer:cancel(TRef), + State1; + error -> + State end. - -cancel_timer(TRef) when is_atom(TRef) -> ok; -cancel_timer(TRef) -> timer:cancel(TRef). - - -stop_or_restart(Name, {shutdown,Reason={overloaded,_Name,_QLen,_Mem}}, - #{overload_kill_restart_after := RestartAfter}) -> - %% If we're terminating because of an overload situation (see - %% logger_h_common:kill_if_choked/4), we need to remove the handler - %% and set a restart timer. A separate process must perform this - %% in order to avoid deadlock. - HandlerPid = self(), - RemoveAndRestart = - fun() -> - MRef = erlang:monitor(process, HandlerPid), - receive - {'DOWN',MRef,_,_,_} -> - ok - after 30000 -> - error_notify(Reason), - exit(HandlerPid, kill) - end, - case logger:get_handler_config(Name) of - {ok,#{module:=HMod}=HConfig} when is_integer(RestartAfter) -> - _ = logger:remove_handler(Name), - _ = timer:apply_after(RestartAfter, logger, add_handler, - [Name,HMod,HConfig]); - {ok,_} -> - _ = logger:remove_handler(Name); - {error,CfgReason} when is_integer(RestartAfter) -> - error_notify({Name,restart_impossible,CfgReason}); - {error,_} -> - ok - end - end, - spawn(RemoveAndRestart), - ok; - -stop_or_restart(Name, shutdown, _State) -> - %% Probably terminated by supervisor. Remove the handler to avoid - %% error printouts due to failing handler. - _ = case logger:get_handler_config(Name) of - {ok,_} -> - %% Spawning to avoid deadlock - spawn(logger,remove_handler,[Name]); - _ -> - ok - end, - ok; - -stop_or_restart(_Name, _Reason, _State) -> - ok. - -overload_levels_ok(HandlerConfig) -> - SMQL = maps:get(sync_mode_qlen, HandlerConfig, ?SYNC_MODE_QLEN), - DMQL = maps:get(drop_mode_qlen, HandlerConfig, ?DROP_MODE_QLEN), - FQL = maps:get(flush_qlen, HandlerConfig, ?FLUSH_QLEN), - (DMQL > 1) andalso (SMQL =< DMQL) andalso (DMQL =< FQL). - error_notify(Term) -> ?internal_log(error, Term). - -info_notify(Term) -> - ?internal_log(info, Term). diff --git a/lib/kernel/src/logger_h_common.hrl b/lib/kernel/src/logger_h_common.hrl index e0a7b6e3ca..004a61d9d9 100644 --- a/lib/kernel/src/logger_h_common.hrl +++ b/lib/kernel/src/logger_h_common.hrl @@ -1,50 +1,22 @@ - -%%%----------------------------------------------------------------- -%%% Overload protection configuration - -%%! *** NOTE *** -%%! It's important that: -%%! SYNC_MODE_QLEN =< DROP_MODE_QLEN =< FLUSH_QLEN -%%! and that DROP_MODE_QLEN >= 2. -%%! Otherwise the handler could end up in drop mode with no new -%%! log requests to process. This would cause all future requests -%%! to be dropped (no switch to async mode would ever take place). - -%% This specifies the message_queue_len value where the log -%% requests switch from asynchronous casts to synchronous calls. --define(SYNC_MODE_QLEN, 10). -%% Above this message_queue_len, log requests will be dropped, -%% i.e. no log requests get sent to the handler process. --define(DROP_MODE_QLEN, 200). -%% Above this message_queue_len, the handler process will flush -%% its mailbox and only leave this number of messages in it. --define(FLUSH_QLEN, 1000). - -%% Never flush more than this number of messages in one go, -%% or the handler will be unresponsive for seconds (keep this -%% number as large as possible or the mailbox could grow large). --define(FLUSH_MAX_N, 5000). - -%% BURST_LIMIT_MAX_COUNT is the max number of log requests allowed -%% to be written within a BURST_LIMIT_WINDOW_TIME time frame. --define(BURST_LIMIT_ENABLE, true). --define(BURST_LIMIT_MAX_COUNT, 500). --define(BURST_LIMIT_WINDOW_TIME, 1000). - -%% This enables/disables the feature to automatically get the -%% handler terminated if it gets too loaded (and can't keep up). --define(OVERLOAD_KILL_ENABLE, false). -%% If the message_queue_len goes above this size even after -%% flushing has been performed, the handler is terminated. --define(OVERLOAD_KILL_QLEN, 20000). -%% If the memory usage exceeds this level --define(OVERLOAD_KILL_MEM_SIZE, 3000000). - -%% This is the default time that the handler will wait before -%% restarting and accepting new requests. The value 'infinity' -%% disables restarts. --define(OVERLOAD_KILL_RESTART_AFTER, 5000). -%%-define(OVERLOAD_KILL_RESTART_AFTER, infinity). +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 1997-2015. 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% +%% %% The handler sends asynchronous write requests to the process %% controlling the i/o device, but every once in this interval @@ -65,12 +37,6 @@ -define(FILESYNC_REPEAT_INTERVAL, 5000). %%-define(FILESYNC_REPEAT_INTERVAL, no_repeat). -%% This is the time after last message received that we think/hope -%% that the handler has an empty mailbox (no new log request has -%% come in). --define(IDLE_DETECT_TIME_MSEC, 100). --define(IDLE_DETECT_TIME_USEC, 100000). - %% Default disk log option values -define(DISK_LOG_TYPE, wrap). -define(DISK_LOG_MAX_NO_FILES, 10). @@ -83,43 +49,6 @@ list_to_atom(lists:concat([MODULE,"_",Name]))). %%%----------------------------------------------------------------- -%%% Overload protection macros - --define(timestamp(), erlang:monotonic_time(microsecond)). - --define(get_mode(Tid), - case ets:lookup(Tid, mode) of - [{mode,M}] -> M; - _ -> async - end). - --define(set_mode(Tid, M), - begin ets:insert(Tid, {mode,M}), M end). - --define(change_mode(Tid, M0, M1), - if M0 == M1 -> - M0; - true -> - ets:insert(Tid, {mode,M1}), - M1 - end). - --define(min(X1, X2), - if X2 == undefined -> X1; - X2 < X1 -> X2; - true -> X1 - end). - --define(max(X1, X2), - if - X2 == undefined -> X1; - X2 > X1 -> X2; - true -> X1 - end). - --define(diff_time(OS_T1, OS_T0), OS_T1-OS_T0). - -%%%----------------------------------------------------------------- %%% The test hook macros make it possible to observe and manipulate %%% internal handler functionality. When enabled, these macros will %%% slow down execution and therefore should not be include in code @@ -137,7 +66,7 @@ ets:insert(?TEST_HOOKS_TAB, {internal_log,{logger,internal_log}}), ets:insert(?TEST_HOOKS_TAB, {file_write,ok}), ets:insert(?TEST_HOOKS_TAB, {file_datasync,ok}), - ets:insert(?TEST_HOOKS_TAB, {disk_log_blog,ok}), + ets:insert(?TEST_HOOKS_TAB, {disk_log_write,ok}), ets:insert(?TEST_HOOKS_TAB, {disk_log_sync,ok})). -define(set_internal_log(MOD_FUNC), @@ -150,7 +79,7 @@ ets:insert(?TEST_HOOKS_TAB, {internal_log,{logger,internal_log}}), ets:insert(?TEST_HOOKS_TAB, {file_write,ok}), ets:insert(?TEST_HOOKS_TAB, {file_datasync,ok}), - ets:insert(?TEST_HOOKS_TAB, {disk_log_blog,ok}), + ets:insert(?TEST_HOOKS_TAB, {disk_log_write,ok}), ets:insert(?TEST_HOOKS_TAB, {disk_log_sync,ok})). -define(internal_log(TYPE, TERM), @@ -171,11 +100,11 @@ [{_,ERROR}] -> ERROR catch _:_ -> file:datasync(DEVICE) end). - -define(disk_log_blog(LOG, DATA), - try ets:lookup(?TEST_HOOKS_TAB, disk_log_blog) of - [{_,ok}] -> disk_log:blog(LOG, DATA); + -define(disk_log_write(LOG, MODE, DATA), + try ets:lookup(?TEST_HOOKS_TAB, disk_log_write) of + [{_,ok}] -> disk_log_write(LOG, MODE, DATA); [{_,ERROR}] -> ERROR - catch _:_ -> disk_log:blog(LOG, DATA) end). + catch _:_ -> disk_log_write(LOG, MODE, DATA) end). -define(disk_log_sync(LOG), try ets:lookup(?TEST_HOOKS_TAB, disk_log_sync) of @@ -183,7 +112,6 @@ [{_,ERROR}] -> ERROR catch _:_ -> disk_log:sync(LOG) end). - -define(DEFAULT_CALL_TIMEOUT, 5000). -else. % DEFAULTS! -define(TEST_HOOKS_TAB, undefined). @@ -194,70 +122,6 @@ -define(internal_log(TYPE, TERM), logger:internal_log(TYPE, TERM)). -define(file_write(DEVICE, DATA), file:write(DEVICE, DATA)). -define(file_datasync(DEVICE), file:datasync(DEVICE)). - -define(disk_log_blog(LOG, DATA), disk_log:blog(LOG, DATA)). + -define(disk_log_write(LOG, MODE, DATA), disk_log_write(LOG, MODE, DATA)). -define(disk_log_sync(LOG), disk_log:sync(LOG)). - -define(DEFAULT_CALL_TIMEOUT, 10000). --endif. - -%%%----------------------------------------------------------------- -%%% These macros enable statistics counters in the state of the -%%% handler which is useful for analysing the overload protection -%%% behaviour. These counters should not be included in code to be -%%% officially released (as some counters will grow very large -%%% over time). - -%%-define(SAVE_STATS, true). --ifdef(SAVE_STATS). - -define(merge_with_stats(STATE), - STATE#{flushes => 0, flushed => 0, drops => 0, - casts => 0, calls => 0, - max_qlen => 0, max_time => 0}). - - -define(update_max_qlen(QLEN, STATE), - begin #{max_qlen := QLEN0} = STATE, - STATE#{max_qlen => ?max(QLEN0,QLEN)} end). - - -define(update_calls_or_casts(CALL_OR_CAST, INC, STATE), - case CALL_OR_CAST of - cast -> - #{casts := CASTS0} = STATE, - STATE#{casts => CASTS0+INC}; - call -> - #{calls := CALLS0} = STATE, - STATE#{calls => CALLS0+INC} - end). - - -define(update_max_time(TIME, STATE), - begin #{max_time := TIME0} = STATE, - STATE#{max_time => ?max(TIME0,TIME)} end). - - -define(update_other(OTHER, VAR, INCVAL, STATE), - begin #{OTHER := VAR} = STATE, - STATE#{OTHER => VAR+INCVAL} end). - --else. % DEFAULT! - -define(merge_with_stats(STATE), STATE). - -define(update_max_qlen(_QLEN, STATE), STATE). - -define(update_calls_or_casts(_CALL_OR_CAST, _INC, STATE), STATE). - -define(update_max_time(_TIME, STATE), STATE). - -define(update_other(_OTHER, _VAR, _INCVAL, STATE), STATE). --endif. - -%%%----------------------------------------------------------------- -%%% These macros enable callbacks that make it possible to analyse -%%% the overload protection behaviour from outside the handler -%%% process (including dropped requests on the client side). -%%% An external callback module (?OBSERVER_MOD) is required which -%%% is not part of the kernel application. For this reason, these -%%% callbacks should not be included in code to be officially released. - -%%-define(OBSERVER_MOD, logger_test). --ifdef(OBSERVER_MOD). - -define(start_observation(NAME), ?OBSERVER:start_observation(NAME)). - -define(observe(NAME,EVENT), ?OBSERVER:observe(NAME,EVENT)). - --else. % DEFAULT! - -define(start_observation(_NAME), ok). - -define(observe(_NAME,_EVENT), ok). -endif. -%%! <--- diff --git a/lib/kernel/src/logger_handler_watcher.erl b/lib/kernel/src/logger_handler_watcher.erl new file mode 100644 index 0000000000..b75c74c643 --- /dev/null +++ b/lib/kernel/src/logger_handler_watcher.erl @@ -0,0 +1,113 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 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% +%% +-module(logger_handler_watcher). + +-behaviour(gen_server). + +%% API +-export([start_link/0]). +-export([register_handler/2]). + +%% gen_server callbacks +-export([init/1, handle_call/3, handle_cast/2, handle_info/2, terminate/2]). + +-define(SERVER, ?MODULE). + +-record(state, {handlers}). + +%%%=================================================================== +%%% API +%%%=================================================================== + +-spec start_link() -> {ok, Pid :: pid()} | + {error, Error :: {already_started, pid()}} | + {error, Error :: term()} | + ignore. +start_link() -> + gen_server:start_link({local, ?SERVER}, ?MODULE, [], []). + +-spec register_handler(Id::logger:handler_id(),Pid::pid()) -> ok. +register_handler(Id,Pid) -> + gen_server:call(?SERVER,{register,Id,Pid}). + +%%%=================================================================== +%%% gen_server callbacks +%%%=================================================================== + +-spec init(Args :: term()) -> {ok, State :: term()} | + {ok, State :: term(), Timeout :: timeout()} | + {ok, State :: term(), hibernate} | + {stop, Reason :: term()} | + ignore. +init([]) -> + process_flag(trap_exit, true), + {ok, #state{handlers=[]}}. + +-spec handle_call(Request :: term(), From :: {pid(), term()}, State :: term()) -> + {reply, Reply :: term(), NewState :: term()} | + {reply, Reply :: term(), NewState :: term(), Timeout :: timeout()} | + {reply, Reply :: term(), NewState :: term(), hibernate} | + {noreply, NewState :: term()} | + {noreply, NewState :: term(), Timeout :: timeout()} | + {noreply, NewState :: term(), hibernate} | + {stop, Reason :: term(), Reply :: term(), NewState :: term()} | + {stop, Reason :: term(), NewState :: term()}. +handle_call({register,Id,Pid}, _From, #state{handlers=Hs}=State) -> + Ref = erlang:monitor(process,Pid), + Hs1 = lists:keystore(Id,1,Hs,{Id,Ref}), + {reply, ok, State#state{handlers=Hs1}}. + +-spec handle_cast(Request :: term(), State :: term()) -> + {noreply, NewState :: term()} | + {noreply, NewState :: term(), Timeout :: timeout()} | + {noreply, NewState :: term(), hibernate} | + {stop, Reason :: term(), NewState :: term()}. +handle_cast(_Request, State) -> + {noreply, State}. + +-spec handle_info(Info :: timeout() | term(), State :: term()) -> + {noreply, NewState :: term()} | + {noreply, NewState :: term(), Timeout :: timeout()} | + {noreply, NewState :: term(), hibernate} | + {stop, Reason :: normal | term(), NewState :: term()}. +handle_info({'DOWN',Ref,process,_,shutdown}, #state{handlers=Hs}=State) -> + case lists:keytake(Ref,2,Hs) of + {value,{Id,Ref},Hs1} -> + %% Probably terminated by supervisor. Remove the handler to avoid + %% error printouts due to failing handler. + _ = case logger:get_handler_config(Id) of + {ok,_} -> + logger:remove_handler(Id); + _ -> + ok + end, + {noreply,State#state{handlers=Hs1}}; + false -> + {noreply, State} + end; +handle_info({'DOWN',Ref,process,_,_OtherReason}, #state{handlers=Hs}=State) -> + {noreply,State#state{handlers=lists:keydelete(Ref,2,Hs)}}; +handle_info(_Other,State) -> + {noreply,State}. + +-spec terminate(Reason :: normal | shutdown | {shutdown, term()} | term(), + State :: term()) -> any(). +terminate(_Reason, _State) -> + ok. diff --git a/lib/kernel/src/logger_internal.hrl b/lib/kernel/src/logger_internal.hrl index d96a4ac78b..e53922e5d3 100644 --- a/lib/kernel/src/logger_internal.hrl +++ b/lib/kernel/src/logger_internal.hrl @@ -19,6 +19,7 @@ %% -include_lib("kernel/include/logger.hrl"). -define(LOGGER_TABLE,logger). +-define(PROXY_KEY,'$proxy_config$'). -define(PRIMARY_KEY,'$primary_config$'). -define(HANDLER_KEY,'$handler_config$'). -define(LOGGER_META_KEY,'$logger_metadata$'). @@ -40,12 +41,14 @@ -define(DEFAULT_LOGGER_CALL_TIMEOUT, infinity). --define(LOG_INTERNAL(Level,Report), +-define(LOG_INTERNAL(Level,Report),?DO_LOG_INTERNAL(Level,[Report])). +-define(LOG_INTERNAL(Level,Format,Args),?DO_LOG_INTERNAL(Level,[Format,Args])). +-define(DO_LOG_INTERNAL(Level,Data), case logger:allow(Level,?MODULE) of true -> %% Spawn this to avoid deadlocks - _ = spawn(logger,macro_log,[?LOCATION,Level,Report, - logger:add_default_metadata(#{})]), + _ = spawn(logger,macro_log,[?LOCATION,Level|Data]++ + [logger:add_default_metadata(#{})]), ok; false -> ok diff --git a/lib/kernel/src/logger_olp.erl b/lib/kernel/src/logger_olp.erl new file mode 100644 index 0000000000..8365383fe2 --- /dev/null +++ b/lib/kernel/src/logger_olp.erl @@ -0,0 +1,627 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2017-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% +%% +-module(logger_olp). +-behaviour(gen_server). + +-include("logger_olp.hrl"). +-include("logger_internal.hrl"). + +%% API +-export([start_link/4, load/2, info/1, reset/1, stop/1, restart/1, + set_opts/2, get_opts/1, get_default_opts/0, get_pid/1, + call/2, cast/2, get_ref/0, get_ref/1]). + +%% gen_server and proc_lib callbacks +-export([init/1, handle_call/3, handle_cast/2, handle_info/2, + terminate/2, code_change/3]). + +-define(OPT_KEYS,[sync_mode_qlen, + drop_mode_qlen, + flush_qlen, + burst_limit_enable, + burst_limit_max_count, + burst_limit_window_time, + overload_kill_enable, + overload_kill_qlen, + overload_kill_mem_size, + overload_kill_restart_after]). + +-export_type([olp_ref/0, options/0]). + +-opaque olp_ref() :: {atom(),pid(),ets:tid()}. + +-type options() :: logger:olp_config(). + +%%%----------------------------------------------------------------- +%%% API + +-spec start_link(Name,Module,Args,Options) -> {ok,Pid,Olp} | {error,Reason} when + Name :: atom(), + Module :: module(), + Args :: term(), + Options :: options(), + Pid :: pid(), + Olp :: olp_ref(), + Reason :: term(). +start_link(Name,Module,Args,Options0) when is_map(Options0) -> + Options = maps:merge(get_default_opts(),Options0), + case check_opts(Options) of + ok -> + proc_lib:start_link(?MODULE,init,[[Name,Module,Args,Options]]); + Error -> + Error + end. + +-spec load(Olp, Msg) -> ok when + Olp :: olp_ref(), + Msg :: term(). +load({_Name,Pid,ModeRef},Msg) -> + %% If the process is getting overloaded, the message will be + %% synchronous instead of asynchronous (slows down the tempo of a + %% process causing much load). If the process is choked, drop mode + %% is set and no message is sent. + try ?get_mode(ModeRef) of + async -> + gen_server:cast(Pid, {'$olp_load',Msg}); + sync -> + case call(Pid, {'$olp_load',Msg}) of + ok -> + ok; + _Other -> + %% dropped or {error,busy} + ?observe(_Name,{dropped,1}), + ok + end; + drop -> + ?observe(_Name,{dropped,1}) + catch + %% if the ETS table doesn't exist (maybe because of a + %% process restart), we can only drop the event + _:_ -> ?observe(_Name,{dropped,1}) + end, + ok. + +-spec info(Olp) -> map() | {error, busy} when + Olp :: atom() | pid() | olp_ref(). +info(Olp) -> + call(Olp, info). + +-spec reset(Olp) -> ok | {error, busy} when + Olp :: atom() | pid() | olp_ref(). +reset(Olp) -> + call(Olp, reset). + +-spec stop(Olp) -> ok when + Olp :: atom() | pid() | olp_ref(). +stop({_Name,Pid,_ModRef}) -> + stop(Pid); +stop(Pid) -> + _ = gen_server:call(Pid, stop), + ok. + +-spec set_opts(Olp, Opts) -> ok | {error,term()} | {error, busy} when + Olp :: atom() | pid() | olp_ref(), + Opts :: options(). +set_opts(Olp, Opts) -> + call(Olp, {set_opts,Opts}). + +-spec get_opts(Olp) -> options() | {error, busy} when + Olp :: atom() | pid() | olp_ref(). +get_opts(Olp) -> + call(Olp, get_opts). + +-spec get_default_opts() -> options(). +get_default_opts() -> + #{sync_mode_qlen => ?SYNC_MODE_QLEN, + drop_mode_qlen => ?DROP_MODE_QLEN, + flush_qlen => ?FLUSH_QLEN, + burst_limit_enable => ?BURST_LIMIT_ENABLE, + burst_limit_max_count => ?BURST_LIMIT_MAX_COUNT, + burst_limit_window_time => ?BURST_LIMIT_WINDOW_TIME, + overload_kill_enable => ?OVERLOAD_KILL_ENABLE, + overload_kill_qlen => ?OVERLOAD_KILL_QLEN, + overload_kill_mem_size => ?OVERLOAD_KILL_MEM_SIZE, + overload_kill_restart_after => ?OVERLOAD_KILL_RESTART_AFTER}. + +-spec restart(fun(() -> any())) -> ok. +restart(Fun) -> + Result = + try Fun() + catch C:R:S -> + {error,{restart_failed,Fun,C,R,S}} + end, + ?LOG_INTERNAL(debug,[{logger_olp,restart}, + {result,Result}]), + ok. + +-spec get_ref() -> olp_ref(). +get_ref() -> + get(olp_ref). + +-spec get_ref(PidOrName) -> olp_ref() | {error, busy} when + PidOrName :: pid() | atom(). +get_ref(PidOrName) -> + call(PidOrName,get_ref). + +-spec get_pid(olp_ref()) -> pid(). +get_pid({_Name,Pid,_ModeRef}) -> + Pid. + +%%%=================================================================== +%%% gen_server callbacks +%%%=================================================================== + +init([Name,Module,Args,Options]) -> + register(Name, self()), + process_flag(message_queue_data, off_heap), + + ?start_observation(Name), + + try ets:new(Name, [public]) of + ModeRef -> + OlpRef = {Name,self(),ModeRef}, + put(olp_ref,OlpRef), + try Module:init(Args) of + {ok,CBState} -> + ?set_mode(ModeRef, async), + T0 = ?timestamp(), + proc_lib:init_ack({ok,self(),OlpRef}), + %% Storing options in state to avoid copying + %% (sending) the option data with each message + State0 = ?merge_with_stats( + Options#{id => Name, + idle=> true, + module => Module, + mode_ref => ModeRef, + mode => async, + last_qlen => 0, + last_load_ts => T0, + burst_win_ts => T0, + burst_msg_count => 0, + cb_state => CBState}), + State = reset_restart_flag(State0), + gen_server:enter_loop(?MODULE, [], State); + Error -> + _ = ets:delete(ModeRef), + unregister(Name), + proc_lib:init_ack(Error) + catch + _:Error -> + _ = ets:delete(ModeRef), + unregister(Name), + proc_lib:init_ack(Error) + end + catch + _:Error -> + unregister(Name), + proc_lib:init_ack(Error) + end. + +%% This is the synchronous load event. +handle_call({'$olp_load', Msg}, _From, State) -> + {Result,State1} = do_load(Msg, call, State#{idle=>false}), + %% Result == ok | dropped + reply_return(Result,State1); + +handle_call(get_ref,_From,#{id:=Name,mode_ref:=ModeRef}=State) -> + reply_return({Name,self(),ModeRef},State); + +handle_call({set_opts,Opts0},_From,State) -> + Opts = maps:merge(maps:with(?OPT_KEYS,State),Opts0), + case check_opts(Opts) of + ok -> + reply_return(ok, maps:merge(State,Opts)); + Error -> + reply_return(Error, State) + end; + +handle_call(get_opts,_From,State) -> + reply_return(maps:with(?OPT_KEYS,State), State); + +handle_call(info, _From, State) -> + reply_return(State, State); + +handle_call(reset, _From, #{module:=Module,cb_state:=CBState}=State) -> + State1 = ?merge_with_stats(State), + CBState1 = try_callback_call(Module,reset_state,[CBState],CBState), + reply_return(ok, State1#{idle => true, + last_qlen => 0, + last_load_ts => ?timestamp(), + cb_state => CBState1}); + +handle_call(stop, _From, State) -> + {stop, {shutdown,stopped}, ok, State}; + +handle_call(Msg, From, #{module:=Module,cb_state:=CBState}=State) -> + case try_callback_call(Module,handle_call,[Msg, From, CBState]) of + {reply,Reply,CBState1} -> + reply_return(Reply,State#{cb_state=>CBState1}); + {noreply,CBState1} -> + noreply_return(State#{cb_state=>CBState1}); + {stop, Reason, Reply, CBState1} -> + {stop, Reason, Reply, State#{cb_state=>CBState1}}; + {stop, Reason, CBState1} -> + {stop, Reason, State#{cb_state=>CBState1}} + end. + +%% This is the asynchronous load event. +handle_cast({'$olp_load', Msg}, State) -> + {_Result,State1} = do_load(Msg, cast, State#{idle=>false}), + noreply_return(State1); + +handle_cast(Msg, #{module:=Module, cb_state:=CBState} = State) -> + case try_callback_call(Module,handle_cast,[Msg, CBState]) of + {noreply,CBState1} -> + noreply_return(State#{cb_state=>CBState1}); + {stop, Reason, CBState1} -> + {stop, Reason, State#{cb_state=>CBState1}} + end. + +handle_info(timeout, #{mode_ref:=_ModeRef, mode:=Mode} = State) -> + State1 = notify(idle,State), + State2 = maybe_notify_mode_change(async,State1), + {noreply, State2#{idle => true, + mode => ?change_mode(_ModeRef, Mode, async), + burst_msg_count => 0}}; +handle_info(Msg, #{module := Module, cb_state := CBState} = State) -> + case try_callback_call(Module,handle_info,[Msg, CBState]) of + {noreply,CBState1} -> + noreply_return(State#{cb_state=>CBState1}); + {stop, Reason, CBState1} -> + {stop, Reason, State#{cb_state=>CBState1}}; + {load,CBState1} -> + {_,State1} = do_load(Msg, cast, State#{idle=>false, + cb_state=>CBState1}), + noreply_return(State1) + end. + +terminate({shutdown,{overloaded,_QLen,_Mem}}, + #{id:=Name, module := Module, cb_state := CBState, + overload_kill_restart_after := RestartAfter} = State) -> + %% We're terminating because of an overload situation (see + %% kill_if_choked/3). + unregister(Name), %%!!!! to avoid error printout of callback crashed on stop + case try_callback_call(Module,terminate,[overloaded,CBState],ok) of + {ok,Fun} when is_function(Fun,0), is_integer(RestartAfter) -> + set_restart_flag(State), + _ = timer:apply_after(RestartAfter,?MODULE,restart,[Fun]), + ok; + _ -> + ok + end; +terminate(Reason, #{id:=Name, module:=Module, cb_state:=CBState}) -> + _ = try_callback_call(Module,terminate,[Reason,CBState],ok), + unregister(Name), + ok. + +code_change(_OldVsn, State, _Extra) -> + {ok, State}. + + +%%%----------------------------------------------------------------- +%%% Internal functions +-spec call(Olp, term()) -> term() | {error,busy} when + Olp :: atom() | pid() | olp_ref(). +call({_Name, Pid, _ModeRef},Msg) -> + call(Pid, Msg); +call(Server, Msg) -> + try + gen_server:call(Server, Msg) + catch + _:{timeout,_} -> {error,busy} + end. + +-spec cast(olp_ref(),term()) -> ok. +cast({_Name, Pid, _ModeRef},Msg) -> + gen_server:cast(Pid, Msg). + +%% check for overload between every event (and set Mode to async, +%% sync or drop accordingly), but never flush the whole mailbox +%% before LogWindowSize events have been handled +do_load(Msg, CallOrCast, State) -> + T1 = ?timestamp(), + State1 = ?update_time(T1,State), + + %% check if the process is getting overloaded, or if it's + %% recovering from overload (the check must be done for each + %% event to react quickly to large bursts of events and + %% to ensure that the handler can never end up in drop mode + %% with an empty mailbox, which would stop operation) + {Mode1,QLen,Mem,State2} = check_load(State1), + + %% kill the handler if it can't keep up with the load + kill_if_choked(QLen, Mem, State2), + + if Mode1 == flush -> + flush(T1, State2); + true -> + handle_load(Mode1, T1, Msg, CallOrCast, State2) + end. + +%% this function is called by do_load/3 after an overload check +%% has been performed, where QLen > FlushQLen +flush(T1, State=#{id := _Name, mode := Mode, last_load_ts := _T0, mode_ref := ModeRef}) -> + %% flush load messages in the mailbox (a limited number in order + %% to not cause long delays) + NewFlushed = flush_load(?FLUSH_MAX_N), + + %% write info in log about flushed messages + State1=notify({flushed,NewFlushed},State), + + %% because of the receive loop when flushing messages, the + %% handler will be scheduled out often and the mailbox could + %% grow very large, so we'd better check the queue again here + {_,QLen1} = process_info(self(), message_queue_len), + ?observe(_Name,{max_qlen,QLen1}), + + %% Add 1 for the current log event + ?observe(_Name,{flushed,NewFlushed+1}), + + State2 = ?update_max_time(?diff_time(T1,_T0),State1), + State3 = ?update_max_qlen(QLen1,State2), + State4 = maybe_notify_mode_change(async,State3), + {dropped,?update_other(flushed,FLUSHED,NewFlushed, + State4#{mode => ?change_mode(ModeRef,Mode,async), + last_qlen => QLen1, + last_load_ts => T1})}. + +%% this function is called to actually handle the message +handle_load(Mode, T1, Msg, _CallOrCast, + State = #{id := _Name, + module := Module, + cb_state := CBState, + last_qlen := LastQLen, + last_load_ts := _T0}) -> + %% check if we need to limit the number of writes + %% during a burst of log events + {DoWrite,State1} = limit_burst(State), + + {Result,LastQLen1,CBState1} = + if DoWrite -> + ?observe(_Name,{_CallOrCast,1}), + CBS = try_callback_call(Module,handle_load,[Msg,CBState]), + {ok,element(2, process_info(self(), message_queue_len)),CBS}; + true -> + ?observe(_Name,{flushed,1}), + {dropped,LastQLen,CBState} + end, + State2 = State1#{cb_state=>CBState1}, + + State3 = State2#{mode => Mode}, + State4 = ?update_calls_or_casts(_CallOrCast,1,State3), + State5 = ?update_max_qlen(LastQLen1,State4), + State6 = + ?update_max_time(?diff_time(T1,_T0), + State5#{last_qlen := LastQLen1, + last_load_ts => T1}), + State7 = case Result of + ok -> + S = ?update_freq(T1,State6), + ?update_other(writes,WRITES,1,S); + _ -> + State6 + end, + {Result,State7}. + + +%%%----------------------------------------------------------------- +%%% Check that the options are valid +check_opts(Options) when is_map(Options) -> + case do_check_opts(maps:to_list(Options)) of + ok -> + case overload_levels_ok(Options) of + true -> + ok; + false -> + Faulty = maps:with([sync_mode_qlen, + drop_mode_qlen, + flush_qlen],Options), + {error,{invalid_olp_levels,Faulty}} + end; + {error,Key,Value} -> + {error,{invalid_olp_config,#{Key=>Value}}} + end. + +do_check_opts([{sync_mode_qlen,N}|Options]) when is_integer(N) -> + do_check_opts(Options); +do_check_opts([{drop_mode_qlen,N}|Options]) when is_integer(N) -> + do_check_opts(Options); +do_check_opts([{flush_qlen,N}|Options]) when is_integer(N) -> + do_check_opts(Options); +do_check_opts([{burst_limit_enable,Bool}|Options]) when is_boolean(Bool) -> + do_check_opts(Options); +do_check_opts([{burst_limit_max_count,N}|Options]) when is_integer(N) -> + do_check_opts(Options); +do_check_opts([{burst_limit_window_time,N}|Options]) when is_integer(N) -> + do_check_opts(Options); +do_check_opts([{overload_kill_enable,Bool}|Options]) when is_boolean(Bool) -> + do_check_opts(Options); +do_check_opts([{overload_kill_qlen,N}|Options]) when is_integer(N) -> + do_check_opts(Options); +do_check_opts([{overload_kill_mem_size,N}|Options]) when is_integer(N) -> + do_check_opts(Options); +do_check_opts([{overload_kill_restart_after,NorA}|Options]) + when is_integer(NorA); NorA == infinity -> + do_check_opts(Options); +do_check_opts([{Key,Value}|_]) -> + {error,Key,Value}; +do_check_opts([]) -> + ok. + +set_restart_flag(#{id := Name, module := Module}) -> + Flag = list_to_atom(lists:concat([Module,"_",Name,"_restarting"])), + spawn(fun() -> + register(Flag, self()), + timer:sleep(infinity) + end), + ok. + +reset_restart_flag(#{id := Name, module := Module} = State) -> + Flag = list_to_atom(lists:concat([Module,"_",Name,"_restarting"])), + case whereis(Flag) of + undefined -> + State; + Pid -> + exit(Pid, kill), + notify(restart,State) + end. + +check_load(State = #{id:=_Name, mode_ref := ModeRef, mode := Mode, + sync_mode_qlen := SyncModeQLen, + drop_mode_qlen := DropModeQLen, + flush_qlen := FlushQLen}) -> + {_,Mem} = process_info(self(), memory), + ?observe(_Name,{max_mem,Mem}), + {_,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 events (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 -> + {flush, 0,1}; + QLen >= DropModeQLen -> + %% Note that drop mode will force load messages to + %% be dropped on the client side (never sent to + %% the olp process). + IncDrops = if Mode == drop -> 0; true -> 1 end, + {?change_mode(ModeRef, Mode, drop), IncDrops,0}; + QLen >= SyncModeQLen -> + {?change_mode(ModeRef, Mode, sync), 0,0}; + true -> + {?change_mode(ModeRef, Mode, async), 0,0} + end, + State1 = ?update_other(drops,DROPS,_NewDrops,State), + State2 = ?update_max_qlen(QLen,State1), + State3 = ?update_max_mem(Mem,State2), + State4 = maybe_notify_mode_change(Mode1,State3), + {Mode1, QLen, Mem, + ?update_other(flushes,FLUSHES,_NewFlushes, + State4#{last_qlen => QLen})}. + +limit_burst(#{burst_limit_enable := false}=State) -> + {true,State}; +limit_burst(#{burst_win_ts := BurstWinT0, + burst_msg_count := BurstMsgCount, + burst_limit_window_time := BurstLimitWinTime, + burst_limit_max_count := BurstLimitMaxCnt} = State) -> + if (BurstMsgCount >= BurstLimitMaxCnt) -> + %% the limit for allowed messages has been reached + BurstWinT1 = ?timestamp(), + case ?diff_time(BurstWinT1,BurstWinT0) of + BurstCheckTime when BurstCheckTime < (BurstLimitWinTime*1000) -> + %% we're still within the burst time frame + {false,?update_other(burst_drops,BURSTS,1,State)}; + _BurstCheckTime -> + %% burst time frame passed, reset counters + {true,State#{burst_win_ts => BurstWinT1, + burst_msg_count => 0}} + end; + true -> + %% the limit for allowed messages not yet reached + {true,State#{burst_win_ts => BurstWinT0, + burst_msg_count => BurstMsgCount+1}} + end. + +kill_if_choked(QLen, Mem, #{overload_kill_enable := KillIfOL, + overload_kill_qlen := OLKillQLen, + overload_kill_mem_size := OLKillMem}) -> + if KillIfOL andalso + ((QLen > OLKillQLen) orelse (Mem > OLKillMem)) -> + exit({shutdown,{overloaded,QLen,Mem}}); + true -> + ok + end. + +flush_load(Limit) -> + process_flag(priority, high), + Flushed = flush_load(0, Limit), + process_flag(priority, normal), + Flushed. + +flush_load(Limit, Limit) -> + Limit; +flush_load(N, Limit) -> + %% flush log events but leave other events, such as info, reset + %% and stop, so that these have a chance to be processed even + %% under heavy load + receive + {'$gen_cast',{'$olp_load',_}} -> + flush_load(N+1, Limit); + {'$gen_call',{Pid,MRef},{'$olp_load',_}} -> + Pid ! {MRef, dropped}, + flush_load(N+1, Limit); + {log,_,_,_,_} -> + flush_load(N+1, Limit); + {log,_,_,_} -> + flush_load(N+1, Limit) + after + 0 -> N + end. + +overload_levels_ok(Options) -> + SMQL = maps:get(sync_mode_qlen, Options, ?SYNC_MODE_QLEN), + DMQL = maps:get(drop_mode_qlen, Options, ?DROP_MODE_QLEN), + FQL = maps:get(flush_qlen, Options, ?FLUSH_QLEN), + (DMQL > 1) andalso (SMQL =< DMQL) andalso (DMQL =< FQL). + +maybe_notify_mode_change(drop,#{mode:=Mode0}=State) + when Mode0=/=drop -> + notify({mode_change,Mode0,drop},State); +maybe_notify_mode_change(Mode1,#{mode:=drop}=State) + when Mode1==async; Mode1==sync -> + notify({mode_change,drop,Mode1},State); +maybe_notify_mode_change(_,State) -> + State. + +notify(Note,#{module:=Module,cb_state:=CBState}=State) -> + CBState1 = try_callback_call(Module,notify,[Note,CBState],CBState), + State#{cb_state=>CBState1}. + +try_callback_call(Module, Function, Args) -> + try_callback_call(Module, Function, Args, '$no_default_return'). + +try_callback_call(Module, Function, Args, DefRet) -> + try apply(Module, Function, Args) + catch + throw:R -> R; + error:undef:S when DefRet=/='$no_default_return' -> + case S of + [{Module,Function,Args,_}|_] -> + DefRet; + _ -> + erlang:raise(error,undef,S) + end + end. + +noreply_return(#{idle:=true}=State) -> + {noreply,State}; +noreply_return(#{idle:=false}=State) -> + {noreply,State,?IDLE_DETECT_TIME}. + +reply_return(Reply,#{idle:=true}=State) -> + {reply,Reply,State}; +reply_return(Reply,#{idle:=false}=State) -> + {reply,Reply,State,?IDLE_DETECT_TIME}. diff --git a/lib/kernel/src/logger_olp.hrl b/lib/kernel/src/logger_olp.hrl new file mode 100644 index 0000000000..d68b5c048d --- /dev/null +++ b/lib/kernel/src/logger_olp.hrl @@ -0,0 +1,185 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 1997-2015. 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% +%% + +%%%----------------------------------------------------------------- +%%% Overload protection configuration + +%%! *** NOTE *** +%%! It's important that: +%%! SYNC_MODE_QLEN =< DROP_MODE_QLEN =< FLUSH_QLEN +%%! and that DROP_MODE_QLEN >= 2. +%%! Otherwise the process could end up in drop mode with no new +%%! log requests to process. This would cause all future requests +%%! to be dropped (no switch to async mode would ever take place). + +%% This specifies the message_queue_len value where the log +%% requests switch from asynchronous casts to synchronous calls. +-define(SYNC_MODE_QLEN, 10). +%% Above this message_queue_len, log requests will be dropped, +%% i.e. no log requests get sent to the process. +-define(DROP_MODE_QLEN, 200). +%% Above this message_queue_len, the process will flush its mailbox +%% and only leave this number of messages in it. +-define(FLUSH_QLEN, 1000). + +%% Never flush more than this number of messages in one go, or the +%% process will be unresponsive for seconds (keep this number as large +%% as possible or the mailbox could grow large). +-define(FLUSH_MAX_N, 5000). + +%% BURST_LIMIT_MAX_COUNT is the max number of log requests allowed +%% to be written within a BURST_LIMIT_WINDOW_TIME time frame. +-define(BURST_LIMIT_ENABLE, true). +-define(BURST_LIMIT_MAX_COUNT, 500). +-define(BURST_LIMIT_WINDOW_TIME, 1000). + +%% This enables/disables the feature to automatically terminate the +%% process if it gets too loaded (and can't keep up). +-define(OVERLOAD_KILL_ENABLE, false). +%% If the message_queue_len goes above this size even after +%% flushing has been performed, the process is terminated. +-define(OVERLOAD_KILL_QLEN, 20000). +%% If the memory usage exceeds this level, the process is terminated. +-define(OVERLOAD_KILL_MEM_SIZE, 3000000). + +%% This is the default time to wait before restarting and accepting +%% new requests. The value 'infinity' disables restarts. +-define(OVERLOAD_KILL_RESTART_AFTER, 5000). + +%% This is the time in milliseconds after last load message received +%% that we notify the callback about being idle. +-define(IDLE_DETECT_TIME, 100). + +%%%----------------------------------------------------------------- +%%% Overload protection macros + +-define(timestamp(), erlang:monotonic_time(microsecond)). + +-define(get_mode(Tid), + case ets:lookup(Tid, mode) of + [{mode,M}] -> M; + _ -> async + end). + +-define(set_mode(Tid, M), + begin ets:insert(Tid, {mode,M}), M end). + +-define(change_mode(Tid, M0, M1), + if M0 == M1 -> + M0; + true -> + ets:insert(Tid, {mode,M1}), + M1 + end). + +-define(max(X1, X2), + if + X2 == undefined -> X1; + X2 > X1 -> X2; + true -> X1 + end). + +-define(diff_time(OS_T1, OS_T0), OS_T1-OS_T0). + +%%%----------------------------------------------------------------- +%%% These macros enable statistics counters in the state of the +%%% process, which is useful for analysing the overload protection +%%% behaviour. These counters should not be included in code to be +%%% officially released (as some counters will grow very large over +%%% time). + +%% -define(SAVE_STATS, true). +-ifdef(SAVE_STATS). + -define(merge_with_stats(STATE), + begin + TIME = ?timestamp(), + STATE#{start => TIME, time => {TIME,0}, + flushes => 0, flushed => 0, drops => 0, + burst_drops => 0, casts => 0, calls => 0, + writes => 0, max_qlen => 0, max_time => 0, + max_mem => 0, freq => {TIME,0,0}} end). + + -define(update_max_qlen(QLEN, STATE), + begin #{max_qlen := QLEN0} = STATE, + STATE#{max_qlen => ?max(QLEN0,QLEN)} end). + + -define(update_max_mem(MEM, STATE), + begin #{max_mem := MEM0} = STATE, + STATE#{max_mem => ?max(MEM0,MEM)} end). + + -define(update_calls_or_casts(CALL_OR_CAST, INC, STATE), + case CALL_OR_CAST of + cast -> + #{casts := CASTS0} = STATE, + STATE#{casts => CASTS0+INC}; + call -> + #{calls := CALLS0} = STATE, + STATE#{calls => CALLS0+INC} + end). + + -define(update_max_time(TIME, STATE), + begin #{max_time := TIME0} = STATE, + STATE#{max_time => ?max(TIME0,TIME)} end). + + -define(update_other(OTHER, VAR, INCVAL, STATE), + begin #{OTHER := VAR} = STATE, + STATE#{OTHER => VAR+INCVAL} end). + + -define(update_freq(TIME,STATE), + begin + case STATE of + #{freq := {START, 49, _}} -> + STATE#{freq => {TIME, 0, trunc(1000000*50/(?diff_time(TIME,START)))}}; + #{freq := {START, N, FREQ}} -> + STATE#{freq => {START, N+1, FREQ}} + end end). + + -define(update_time(TIME,STATE), + begin #{start := START} = STATE, + STATE#{time => {TIME,trunc((?diff_time(TIME,START))/1000000)}} end). + +-else. % DEFAULT! + -define(merge_with_stats(STATE), STATE). + -define(update_max_qlen(_QLEN, STATE), STATE). + -define(update_max_mem(_MEM, STATE), STATE). + -define(update_calls_or_casts(_CALL_OR_CAST, _INC, STATE), STATE). + -define(update_max_time(_TIME, STATE), STATE). + -define(update_other(_OTHER, _VAR, _INCVAL, STATE), STATE). + -define(update_freq(_TIME, STATE), STATE). + -define(update_time(_TIME, STATE), STATE). +-endif. + +%%%----------------------------------------------------------------- +%%% These macros enable callbacks that make it possible to analyse the +%%% overload protection behaviour from outside the process (including +%%% dropped requests on the client side). An external callback module +%%% (?OBSERVER_MOD) is required which is not part of the kernel +%%% application. For this reason, these callbacks should not be +%%% included in code to be officially released. + +%%-define(OBSERVER_MOD, logger_test). +-ifdef(OBSERVER_MOD). + -define(start_observation(NAME), ?OBSERVER:start_observation(NAME)). + -define(observe(NAME,EVENT), ?OBSERVER:observe(NAME,EVENT)). + +-else. % DEFAULT! + -define(start_observation(_NAME), ok). + -define(observe(_NAME,_EVENT), ok). +-endif. diff --git a/lib/kernel/src/logger_proxy.erl b/lib/kernel/src/logger_proxy.erl new file mode 100644 index 0000000000..24b293805c --- /dev/null +++ b/lib/kernel/src/logger_proxy.erl @@ -0,0 +1,165 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2017-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% +%% +-module(logger_proxy). + +%% API +-export([start_link/0, restart/0, log/1, child_spec/0, get_default_config/0]). + +%% logger_olp callbacks +-export([init/1, handle_load/2, handle_info/2, terminate/2, + notify/2]). + +-include("logger_internal.hrl"). + +-define(SERVER,?MODULE). + +%%%----------------------------------------------------------------- +%%% API +-spec log(RemoteLog) -> ok when + RemoteLog :: {remote,node(),LogEvent}, + LogEvent :: {log,Level,Format,Args,Meta} | + {log,Level,StringOrReport,Meta}, + Level :: logger:level(), + Format :: io:format(), + Args :: list(term()), + StringOrReport :: unicode:chardata() | logger:report(), + Meta :: logger:metadata(). +log(RemoteLog) -> + Olp = persistent_term:get(?MODULE), + case logger_olp:get_pid(Olp) =:= self() of + true -> + %% This happens when the log event comes from the + %% emulator, and the group leader is on a remote node. + _ = handle_load(RemoteLog, no_state), + ok; + false -> + logger_olp:load(Olp, RemoteLog) + end. + +%% Called by supervisor +-spec start_link() -> {ok,pid(),logger_olp:olp_ref()} | {error,term()}. +start_link() -> + %% Notice that sync_mode is only used when logging to remote node, + %% i.e. when the log/2 API function is called. + %% + %% When receiving log events from the emulator or from a remote + %% node, the log event is sent as a message to this process, and + %% thus received directly in handle_info/2. This means that the + %% mode (async/sync/drop) is not read before the message is + %% sent. Thus sync mode is never entered, and drop mode is + %% implemented by setting the system_logger flag to undefined (see + %% notify/2) + %% + %% Burst limit is disabled, since this is only a proxy and we + %% don't want to limit bursts twice (here and in the handler). + logger_olp:start_link(?SERVER,?MODULE,[],logger:get_proxy_config()). + +%% Fun used for restarting this process after it has been killed due +%% to overload (must set overload_kill_enable=>true in opts) +restart() -> + case supervisor:start_child(logger_sup, child_spec()) of + {ok,_Pid,Olp} -> + {ok,Olp}; + {error,{Reason,Ch}} when is_tuple(Ch), element(1,Ch)==child -> + {error,Reason}; + Error -> + Error + end. + +%% Called internally and by logger_sup +child_spec() -> + Name = ?SERVER, + #{id => Name, + start => {?MODULE, start_link, []}, + restart => temporary, + shutdown => 2000, + type => worker, + modules => [?MODULE]}. + +get_default_config() -> + OlpDefault = logger_olp:get_default_opts(), + OlpDefault#{sync_mode_qlen=>500, + drop_mode_qlen=>1000, + flush_qlen=>5000, + burst_limit_enable=>false}. + +%%%=================================================================== +%%% gen_server callbacks +%%%=================================================================== + +init([]) -> + process_flag(trap_exit, true), + _ = erlang:system_flag(system_logger,self()), + persistent_term:put(?MODULE,logger_olp:get_ref()), + {ok,no_state}. + +%% Log event to send to the node where the group leader of it's client resides +handle_load({remote,Node,Log},State) -> + %% If the connection is overloaded (send_nosuspend returns false), + %% we drop the message. + _ = erlang:send_nosuspend({?SERVER,Node},Log), + State; +%% Log event to log on this node +handle_load({log,Level,Format,Args,Meta},State) -> + try_log([Level,Format,Args,Meta]), + State; +handle_load({log,Level,Report,Meta},State) -> + try_log([Level,Report,Meta]), + State. + +%% Log event sent to this process e.g. from the emulator - it is really load +handle_info(Log,State) when is_tuple(Log), element(1,Log)==log -> + {load,State}. + +terminate(overloaded, _State) -> + _ = erlang:system_flag(system_logger,undefined), + {ok,fun ?MODULE:restart/0}; +terminate(_Reason, _State) -> + _ = erlang:system_flag(system_logger,whereis(logger)), + ok. + +notify({mode_change,Mode0,Mode1},State) -> + _ = if Mode1=:=drop -> % entering drop mode + erlang:system_flag(system_logger,undefined); + Mode0=:=drop -> % leaving drop mode + erlang:system_flag(system_logger,self()); + true -> + ok + end, + ?LOG_INTERNAL(notice,"~w switched from ~w to ~w mode",[?MODULE,Mode0,Mode1]), + State; +notify({flushed,Flushed},State) -> + ?LOG_INTERNAL(notice, "~w flushed ~w log events",[?MODULE,Flushed]), + State; +notify(restart,State) -> + ?LOG_INTERNAL(notice, "~w restarted", [?MODULE]), + State; +notify(_Note,State) -> + State. + +%%%----------------------------------------------------------------- +%%% Internal functions +try_log(Args) -> + try apply(logger,log,Args) + catch C:R:S -> + ?LOG_INTERNAL(debug,[{?MODULE,log_failed}, + {log,Args}, + {reason,{C,R,S}}]) + end. diff --git a/lib/kernel/src/logger_server.erl b/lib/kernel/src/logger_server.erl index 28e31d46ea..722246e82c 100644 --- a/lib/kernel/src/logger_server.erl +++ b/lib/kernel/src/logger_server.erl @@ -22,14 +22,17 @@ -behaviour(gen_server). %% API --export([start_link/0, - add_handler/3, remove_handler/1, +-export([start_link/0, add_handler/3, remove_handler/1, add_filter/2, remove_filter/2, set_module_level/2, unset_module_level/0, unset_module_level/1, cache_module_level/1, - set_config/2, set_config/3, update_config/2, + set_config/2, set_config/3, + update_config/2, update_config/3, update_formatter_config/2]). +%% Helper +-export([diff_maps/2]). + %% gen_server callbacks -export([init/1, handle_call/3, handle_cast/2, handle_info/2, terminate/2]). @@ -39,7 +42,7 @@ -define(SERVER, logger). -define(LOGGER_SERVER_TAG, '$logger_cb_process'). --record(state, {tid, async_req, async_req_queue}). +-record(state, {tid, async_req, async_req_queue, remote_logger}). %%%=================================================================== %%% API @@ -83,7 +86,7 @@ set_module_level(Modules,Level) when is_list(Modules) -> Error -> Error end; false -> - {error,{not_a_list_of_modles,Modules}} + {error,{not_a_list_of_modules,Modules}} end; set_module_level(Modules,_) -> {error,{not_a_list_of_modules,Modules}}. @@ -96,7 +99,7 @@ unset_module_level(Modules) when is_list(Modules) -> true -> call({unset_module_level,Modules}); false -> - {error,{not_a_list_of_modles,Modules}} + {error,{not_a_list_of_modules,Modules}} end; unset_module_level(Modules) -> {error,{not_a_list_of_modules,Modules}}. @@ -105,12 +108,25 @@ cache_module_level(Module) -> gen_server:cast(?SERVER,{cache_module_level,Module}). set_config(Owner,Key,Value) -> - update_config(Owner,#{Key=>Value}). + case sanity_check(Owner,Key,Value) of + ok -> + call({change_config,set,Owner,Key,Value}); + Error -> + Error + end. set_config(Owner,Config) -> case sanity_check(Owner,Config) of ok -> - call({set_config,Owner,Config}); + call({change_config,set,Owner,Config}); + Error -> + Error + end. + +update_config(Owner,Key,Value) -> + case sanity_check(Owner,Key,Value) of + ok -> + call({change_config,update,Owner,Key,Value}); Error -> Error end. @@ -118,7 +134,7 @@ set_config(Owner,Config) -> update_config(Owner, Config) -> case sanity_check(Owner,Config) of ok -> - call({update_config,Owner,Config}); + call({change_config,update,Owner,Config}); Error -> Error end. @@ -138,6 +154,8 @@ init([]) -> process_flag(trap_exit, true), put(?LOGGER_SERVER_TAG,true), Tid = logger_config:new(?LOGGER_TABLE), + %% Store initial proxy config. logger_proxy reads config from here at startup. + logger_config:create(Tid,proxy,logger_proxy:get_default_config()), PrimaryConfig = maps:merge(default_config(primary), #{handlers=>[simple]}), logger_config:create(Tid,primary,PrimaryConfig), @@ -146,7 +164,7 @@ init([]) -> filters=>?DEFAULT_HANDLER_FILTERS}), %% If this fails, then the node should crash {ok,SimpleConfig} = logger_simple_h:adding_handler(SimpleConfig0), - logger_config:create(Tid,simple,logger_simple_h,SimpleConfig), + logger_config:create(Tid,simple,SimpleConfig), {ok, #state{tid=Tid, async_req_queue = queue:new()}}. handle_call({add_handler,Id,Module,HConfig}, From, #state{tid=Tid}=State) -> @@ -165,11 +183,11 @@ handle_call({add_handler,Id,Module,HConfig}, From, #state{tid=Tid}=State) -> %% 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,primary), + logger_config:create(Tid,Id,HConfig1), + {ok,Config} = logger_config:get(Tid,primary), Handlers = maps:get(handlers,Config,[]), - do_set_config(Tid,primary, - Config#{handlers=>[Id|Handlers]}); + logger_config:set(Tid,primary, + Config#{handlers=>[Id|Handlers]}); false -> {error,{invalid_handler, {function_not_exported, @@ -181,8 +199,8 @@ handle_call({add_handler,Id,Module,HConfig}, From, #state{tid=Tid}=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,primary), + {ok,#{module:=Module}=HConfig} -> + {ok,Config} = logger_config:get(Tid,primary), Handlers0 = maps:get(handlers,Config,[]), Handlers = lists:delete(HandlerId,Handlers0), call_h_async( @@ -191,7 +209,7 @@ handle_call({remove_handler,HandlerId}, From, #state{tid=Tid}=State) -> call_h(Module,removing_handler,[HConfig],ok) end, fun(_Res) -> - do_set_config(Tid,primary,Config#{handlers=>Handlers}), + logger_config:set(Tid,primary,Config#{handlers=>Handlers}), logger_config:delete(Tid,HandlerId), ok end,From,State); @@ -204,36 +222,90 @@ handle_call({add_filter,Id,Filter}, _From,#state{tid=Tid}=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) -> - 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,primary,Config0}, _From, #state{tid=Tid}=State) -> - Config = maps:merge(default_config(primary),Config0), - {ok,#{handlers:=Handlers}} = logger_config:get(Tid,primary), - Reply = do_set_config(Tid,primary,Config#{handlers=>Handlers}), +handle_call({change_config,SetOrUpd,proxy,Config0},_From,#state{tid=Tid}=State) -> + Default = + case SetOrUpd of + set -> + logger_proxy:get_default_config(); + update -> + {ok,OldConfig} = logger_config:get(Tid,proxy), + OldConfig + end, + Config = maps:merge(Default,Config0), + Reply = + case logger_olp:set_opts(logger_proxy,Config) of + ok -> + logger_config:set(Tid,proxy,Config); + Error -> + Error + end, + {reply,Reply,State}; +handle_call({change_config,SetOrUpd,primary,Config0}, _From, + #state{tid=Tid}=State) -> + {ok,#{handlers:=Handlers}=OldConfig} = logger_config:get(Tid,primary), + Default = + case SetOrUpd of + set -> default_config(primary); + update -> OldConfig + end, + Config = maps:merge(Default,Config0), + Reply = logger_config:set(Tid,primary,Config#{handlers=>Handlers}), + {reply,Reply,State}; +handle_call({change_config,_SetOrUpd,primary,Key,Value}, _From, + #state{tid=Tid}=State) -> + {ok,OldConfig} = logger_config:get(Tid,primary), + Reply = logger_config:set(Tid,primary,OldConfig#{Key=>Value}), {reply,Reply,State}; -handle_call({set_config,HandlerId,Config0}, From, #state{tid=Tid}=State) -> +handle_call({change_config,SetOrUpd,HandlerId,Config0}, From, + #state{tid=Tid}=State) -> case logger_config:get(Tid,HandlerId) of - {ok,{Module,OldConfig}} -> - Config = maps:merge(default_config(HandlerId,Module),Config0), - call_h_async( - fun() -> - call_h(Module,changing_config,[OldConfig,Config], - {ok,Config}) - end, - fun({ok,Config1}) -> - do_set_config(Tid,HandlerId,Config1); - (Error) -> - Error - end,From,State); + {ok,#{module:=Module}=OldConfig} -> + Default = + case SetOrUpd of + set -> default_config(HandlerId,Module); + update -> OldConfig + end, + Config = maps:merge(Default,Config0), + case check_config_change(OldConfig,Config) of + ok -> + call_h_async( + fun() -> + call_h(Module,changing_config, + [SetOrUpd,OldConfig,Config], + {ok,Config}) + end, + fun({ok,Config1}) -> + logger_config:set(Tid,HandlerId,Config1); + (Error) -> + Error + end,From,State); + Error -> + {reply,Error,State} + end; + _ -> + {reply,{error,{not_found,HandlerId}},State} + end; +handle_call({change_config,SetOrUpd,HandlerId,Key,Value}, From, + #state{tid=Tid}=State) -> + case logger_config:get(Tid,HandlerId) of + {ok,#{module:=Module}=OldConfig} -> + Config = OldConfig#{Key=>Value}, + case check_config_change(OldConfig,Config) of + ok -> + call_h_async( + fun() -> + call_h(Module,changing_config, + [SetOrUpd,OldConfig,Config], + {ok,Config}) + end, + fun({ok,Config1}) -> + logger_config:set(Tid,HandlerId,Config1); + (Error) -> + Error + end,From,State); + Error -> + {reply,Error,State} + end; _ -> {reply,{error,{not_found,HandlerId}},State} end; @@ -241,12 +313,12 @@ handle_call({update_formatter_config,HandlerId,NewFConfig},_From, #state{tid=Tid}=State) -> Reply = case logger_config:get(Tid,HandlerId) of - {ok,{_Mod,#{formatter:={FMod,OldFConfig}}=Config}} -> + {ok,#{formatter:={FMod,OldFConfig}}=Config} -> try FConfig = maps:merge(OldFConfig,NewFConfig), check_formatter({FMod,FConfig}), - do_set_config(Tid,HandlerId, - Config#{formatter=>{FMod,FConfig}}) + logger_config:set(Tid,HandlerId, + Config#{formatter=>{FMod,FConfig}}) catch throw:Reason -> {error,Reason} end; _ -> @@ -304,38 +376,40 @@ terminate(_Reason, _State) -> %%%=================================================================== %%% Internal functions %%%=================================================================== -call(Request) -> +call(Request) when is_tuple(Request) -> Action = element(1,Request), case get(?LOGGER_SERVER_TAG) of true when Action == add_handler; Action == remove_handler; - Action == update_config; Action == set_config -> + Action == add_filter; Action == remove_filter; + Action == change_config -> {error,{attempting_syncronous_call_to_self,Request}}; _ -> gen_server:call(?SERVER,Request,?DEFAULT_LOGGER_CALL_TIMEOUT) end. + do_add_filter(Tid,Id,{FId,_} = Filter) -> - case do_get_config(Tid,Id) of + case logger_config:get(Tid,Id) of {ok,Config} -> Filters = maps:get(filters,Config,[]), case lists:keymember(FId,1,Filters) of true -> {error,{already_exist,FId}}; false -> - do_set_config(Tid,Id,Config#{filters=>[Filter|Filters]}) + logger_config:set(Tid,Id,Config#{filters=>[Filter|Filters]}) end; Error -> Error end. do_remove_filter(Tid,Id,FilterId) -> - case do_get_config(Tid,Id) of + case logger_config:get(Tid,Id) of {ok,Config} -> Filters0 = maps:get(filters,Config,[]), case lists:keytake(FilterId,1,Filters0) of {value,_,Filters} -> - do_set_config(Tid,Id,Config#{filters=>Filters}); + logger_config:set(Tid,Id,Config#{filters=>Filters}); false -> {error,{not_found,FilterId}} end; @@ -343,20 +417,6 @@ do_remove_filter(Tid,Id,FilterId) -> Error end. -do_get_config(Tid,Id) -> - case logger_config:get(Tid,Id) of - {ok,{_,Config}} -> - {ok,Config}; - {ok,Config} -> - {ok,Config}; - Error -> - Error - end. - -do_set_config(Tid,Id,Config) -> - logger_config:set(Tid,Id,Config), - ok. - default_config(primary) -> #{level=>notice, filters=>[], @@ -373,11 +433,13 @@ default_config(Id,Module) -> sanity_check(Owner,Key,Value) -> sanity_check_1(Owner,[{Key,Value}]). -sanity_check(HandlerId,Config) when is_map(Config) -> - sanity_check_1(HandlerId,maps:to_list(Config)); +sanity_check(Owner,Config) when is_map(Config) -> + sanity_check_1(Owner,maps:to_list(Config)); sanity_check(_,Config) -> - {error,{invalid_handler_config,Config}}. + {error,{invalid_config,Config}}. +sanity_check_1(proxy,_Config) -> + ok; % Details are checked by logger_olp:set_opts/2 sanity_check_1(Owner,Config) when is_list(Config) -> try Type = get_type(Owner), @@ -421,8 +483,6 @@ check_mod(Mod) when is_atom(Mod) -> check_mod(Mod) -> throw({invalid_module,Mod}). -check_level({LevelInt,cached}) when LevelInt>=?EMERGENCY, LevelInt=<?DEBUG -> - ok; check_level(Level) -> case lists:member(Level,?LEVELS) of true -> @@ -463,6 +523,15 @@ check_formatter({Mod,Config}) -> check_formatter(Formatter) -> throw({invalid_formatter,Formatter}). +%% When changing configuration for a handler, the id and module fields +%% can not be changed. +check_config_change(#{id:=Id,module:=Module},#{id:=Id,module:=Module}) -> + ok; +check_config_change(OldConfig,NewConfig) -> + {Old,New} = logger_server:diff_maps(maps:with([id,module],OldConfig), + maps:with([id,module],NewConfig)), + {error,{illegal_config_change,Old,New}}. + call_h(Module, Function, Args, DefRet) -> %% Not calling code:ensure_loaded + erlang:function_exported here, %% since in some rare terminal cases, the code_server might not @@ -471,6 +540,11 @@ call_h(Module, Function, Args, DefRet) -> catch C:R:S -> case {C,R,S} of + {error,undef,[{Module,Function=changing_config,Args,_}|_]} + when length(Args)=:=3 -> + %% Backwards compatible call, if changing_config/3 + %% did not exist. + call_h(Module, Function, tl(Args), DefRet); {error,undef,[{Module,Function,Args,_}|_]} -> DefRet; _ -> @@ -530,3 +604,14 @@ call_h_reply(Unexpected,State) -> {process,?SERVER}, {message,Unexpected}]), {noreply,State}. + +%% Return two maps containing only the fields that differ. +diff_maps(M1,M2) -> + diffs(lists:sort(maps:to_list(M1)),lists:sort(maps:to_list(M2)),#{},#{}). + +diffs([H|T1],[H|T2],D1,D2) -> + diffs(T1,T2,D1,D2); +diffs([{K,V1}|T1],[{K,V2}|T2],D1,D2) -> + diffs(T1,T2,D1#{K=>V1},D2#{K=>V2}); +diffs([],[],D1,D2) -> + {D1,D2}. diff --git a/lib/kernel/src/logger_simple_h.erl b/lib/kernel/src/logger_simple_h.erl index 8b51dd8569..a0d51dba25 100644 --- a/lib/kernel/src/logger_simple_h.erl +++ b/lib/kernel/src/logger_simple_h.erl @@ -50,7 +50,6 @@ removing_handler(#{id:=simple}) -> ok; Pid -> Ref = erlang:monitor(process,Pid), - unlink(Pid), Pid ! stop, receive {'DOWN',Ref,process,Pid,_} -> ok @@ -70,7 +69,7 @@ log(#{msg:=_,meta:=#{time:=_}}=Log,_Config) -> do_log( #{level=>error, msg=>{report,{error,simple_handler_process_dead}}, - meta=>#{time=>erlang:system_time(microsecond)}}), + meta=>#{time=>logger:timestamp()}}), do_log(Log); _ -> ?MODULE ! {log,Log} @@ -99,7 +98,11 @@ loop(Buffer) -> replay_buffer(Buffer); _ -> ok - end; + end, + %% Before stopping, we unlink the logger process to avoid + %% an unexpected EXIT message + unlink(whereis(logger)), + ok; {log,#{msg:=_,meta:=#{time:=_}}=Log} -> do_log(Log), loop(update_buffer(Buffer,Log)); @@ -126,7 +129,7 @@ drop_msg(0) -> drop_msg(N) -> [#{level=>info, msg=>{"Simple handler buffer full, dropped ~w messages",[N]}, - meta=>#{time=>erlang:system_time(microsecond)}}]. + meta=>#{time=>logger:timestamp()}}]. %%%----------------------------------------------------------------- %%% Internal diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index 480fafd6d8..c8f1acfca4 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -19,8 +19,6 @@ %% -module(logger_std_h). --behaviour(gen_server). - -include("logger.hrl"). -include("logger_internal.hrl"). -include("logger_h_common.hrl"). @@ -28,381 +26,252 @@ -include_lib("kernel/include/file.hrl"). %% API --export([start_link/3, info/1, filesync/1, reset/1]). +-export([filesync/1]). -%% gen_server and proc_lib callbacks --export([init/1, handle_call/3, handle_cast/2, handle_info/2, - terminate/2, code_change/3]). +%% logger_h_common callbacks +-export([init/2, check_config/4, config_changed/3, reset_state/2, + filesync/3, write/4, handle_info/3, terminate/3]). %% logger callbacks --export([log/2, adding_handler/1, removing_handler/1, changing_config/2]). +-export([log/2, adding_handler/1, removing_handler/1, changing_config/3, + filter_config/1]). -%% handler internal --export([log_handler_info/4]). +-define(DEFAULT_CALL_TIMEOUT, 5000). %%%=================================================================== %%% API %%%=================================================================== %%%----------------------------------------------------------------- -%%% Start a standard handler process and link to caller. -%%% This function is called by the kernel supervisor when this -%%% handler process gets added --spec start_link(Name, Config, HandlerState) -> {ok,Pid} | {error,Reason} when - Name :: atom(), - Config :: logger:handler_config(), - HandlerState :: map(), - Pid :: pid(), - Reason :: term(). - -start_link(Name, Config, HandlerState) -> - proc_lib:start_link(?MODULE,init,[[Name,Config,HandlerState]]). - -%%%----------------------------------------------------------------- %%% -spec filesync(Name) -> ok | {error,Reason} when Name :: atom(), Reason :: handler_busy | {badarg,term()}. -filesync(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - filesync, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; filesync(Name) -> - {error,{badarg,{filesync,[Name]}}}. - -%%%----------------------------------------------------------------- -%%% --spec info(Name) -> Info | {error,Reason} when - Name :: atom(), - Info :: term(), - Reason :: handler_busy | {badarg,term()}. - -info(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - info, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; -info(Name) -> - {error,{badarg,{info,[Name]}}}. - -%%%----------------------------------------------------------------- -%%% --spec reset(Name) -> ok | {error,Reason} when - Name :: atom(), - Reason :: handler_busy | {badarg,term()}. - -reset(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - reset, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; -reset(Name) -> - {error,{badarg,{reset,[Name]}}}. - + logger_h_common:filesync(?MODULE,Name). %%%=================================================================== -%%% logger callbacks +%%% logger callbacks - just forward to logger_h_common %%%=================================================================== %%%----------------------------------------------------------------- %%% Handler being added -adding_handler(#{id:=Name}=Config) -> - case check_config(adding, Config) of - {ok, Config1} -> - %% create initial handler state by merging defaults with config - HConfig = maps:get(config, Config1, #{}), - HState = maps:merge(get_init_state(), HConfig), - case logger_h_common:overload_levels_ok(HState) of - true -> - start(Name, Config1, HState); - false -> - #{sync_mode_qlen := SMQL, - drop_mode_qlen := DMQL, - flush_qlen := FQL} = HState, - {error,{invalid_levels,{SMQL,DMQL,FQL}}} - end; - Error -> - Error - end. +-spec adding_handler(Config) -> {ok,Config} | {error,Reason} when + Config :: logger:handler_config(), + Reason :: term(). + +adding_handler(Config) -> + logger_h_common:adding_handler(Config). %%%----------------------------------------------------------------- %%% Updating handler config -changing_config(OldConfig=#{id:=Name, config:=OldHConfig}, - NewConfig=#{id:=Name}) -> - #{type:=Type, handler_pid:=HPid, mode_tab:=ModeTab} = OldHConfig, - NewHConfig = maps:get(config, NewConfig, #{}), - case maps:get(type, NewHConfig, Type) of - Type -> - NewHConfig1 = NewHConfig#{type=>Type, - handler_pid=>HPid, - mode_tab=>ModeTab}, - changing_config1(HPid, OldConfig, - NewConfig#{config=>NewHConfig1}); - _ -> - {error,{illegal_config_change,OldConfig,NewConfig}} - end; -changing_config(OldConfig, NewConfig) -> - {error,{illegal_config_change,OldConfig,NewConfig}}. - -changing_config1(HPid, OldConfig, NewConfig) -> - case check_config(changing, NewConfig) of - Result = {ok,NewConfig1} -> - try gen_server:call(HPid, {change_config,OldConfig,NewConfig1}, - ?DEFAULT_CALL_TIMEOUT) of - ok -> Result; - HError -> HError - catch - _:{timeout,_} -> {error,handler_busy} - end; - Error -> - Error - end. - -check_config(adding, Config) -> - %% Merge in defaults on handler level - HConfig0 = maps:get(config, Config, #{}), - HConfig = maps:merge(#{type => standard_io}, - HConfig0), - case check_h_config(maps:to_list(HConfig)) of - ok -> - {ok,Config#{config=>HConfig}}; - Error -> - Error - end; -check_config(changing, Config) -> - HConfig = maps:get(config, Config, #{}), - case check_h_config(maps:to_list(HConfig)) of - ok -> {ok,Config}; - Error -> Error - end. - -check_h_config([{type,Type} | Config]) when Type == standard_io; - Type == standard_error -> - check_h_config(Config); -check_h_config([{type,{file,File}} | Config]) when is_list(File) -> - check_h_config(Config); -check_h_config([{type,{file,File,Modes}} | Config]) when is_list(File), - is_list(Modes) -> - check_h_config(Config); -check_h_config([Other | Config]) -> - case logger_h_common:check_common_config(Other) of - valid -> - check_h_config(Config); - invalid -> - {error,{invalid_config,?MODULE,Other}} - end; -check_h_config([]) -> - ok. +-spec changing_config(SetOrUpdate, OldConfig, NewConfig) -> + {ok,Config} | {error,Reason} when + SetOrUpdate :: set | update, + OldConfig :: logger:handler_config(), + NewConfig :: logger:handler_config(), + Config :: logger:handler_config(), + Reason :: term(). +changing_config(SetOrUpdate, OldConfig, NewConfig) -> + logger_h_common:changing_config(SetOrUpdate, OldConfig, NewConfig). %%%----------------------------------------------------------------- %%% Handler being removed -removing_handler(#{id:=Name}) -> - stop(Name). +-spec removing_handler(Config) -> ok when + Config :: logger:handler_config(). + +removing_handler(Config) -> + logger_h_common:removing_handler(Config). %%%----------------------------------------------------------------- %%% Log a string or report --spec log(LogEvent, Config) -> ok | dropped when +-spec log(LogEvent, Config) -> ok when LogEvent :: logger:log_event(), Config :: logger:handler_config(). -log(LogEvent, Config = #{id := Name, - config := #{handler_pid := HPid, - mode_tab := ModeTab}}) -> - %% if the handler has crashed, we must drop this event - %% and hope the handler restarts so we can try again - true = is_process_alive(HPid), - Bin = logger_h_common:log_to_binary(LogEvent, Config), - logger_h_common:call_cast_or_drop(Name, HPid, ModeTab, Bin). +log(LogEvent, Config) -> + logger_h_common:log(LogEvent, Config). -%%%=================================================================== -%%% gen_server callbacks -%%%=================================================================== - -init([Name, Config = #{config := HConfig}, - State0 = #{type := Type, file_ctrl_sync_int := FileCtrlSyncInt}]) -> - RegName = ?name_to_reg_name(?MODULE,Name), - register(RegName, self()), - process_flag(trap_exit, true), - process_flag(message_queue_data, off_heap), +%%%----------------------------------------------------------------- +%%% Remove internal fields from configuration +-spec filter_config(Config) -> Config when + Config :: logger:handler_config(). - ?init_test_hooks(), - ?start_observation(Name), - - case do_init(Name, Type) of - {ok,InitState} -> - try ets:new(Name, [public]) of - ModeTab -> - ?set_mode(ModeTab, async), - State = maps:merge(State0, InitState), - T0 = ?timestamp(), - State1 = - ?merge_with_stats(State#{ - mode_tab => ModeTab, - mode => async, - file_ctrl_sync => FileCtrlSyncInt, - last_qlen => 0, - last_log_ts => T0, - last_op => sync, - burst_win_ts => T0, - burst_msg_count => 0}), - Config1 = - Config#{config => HConfig#{handler_pid => self(), - mode_tab => ModeTab}}, - proc_lib:init_ack({ok,self(),Config1}), - gen_server:cast(self(), repeated_filesync), - enter_loop(Config1, State1) - catch - _:Error -> - unregister(RegName), - logger_h_common:error_notify({init_handler,Name,Error}), - proc_lib:init_ack(Error) - end; - Error -> - unregister(RegName), - logger_h_common:error_notify({init_handler,Name,Error}), - proc_lib:init_ack(Error) - end. +filter_config(Config) -> + logger_h_common:filter_config(Config). -do_init(Name, Type) -> - case open_log_file(Name, Type) of +%%%=================================================================== +%%% logger_h_common callbacks +%%%=================================================================== +init(Name, Config) -> + MyConfig = maps:with([type,file,modes,file_check,max_no_bytes, + max_no_files,compress_on_rotate],Config), + case file_ctrl_start(Name, MyConfig) of {ok,FileCtrlPid} -> - case logger_h_common:unset_restart_flag(Name, ?MODULE) of - true -> - %% inform about restart - gen_server:cast(self(), {log_handler_info, - "Handler ~p restarted", - [Name]}); - false -> - %% initial start - ok - end, - {ok,#{id=>Name,type=>Type,file_ctrl_pid=>FileCtrlPid}}; + {ok,MyConfig#{file_ctrl_pid=>FileCtrlPid}}; Error -> Error end. -enter_loop(_Config,State) -> - gen_server:enter_loop(?MODULE,[],State). +check_config(Name,set,undefined,NewHConfig) -> + check_h_config(merge_default_config(Name,normalize_config(NewHConfig))); +check_config(Name,SetOrUpdate,OldHConfig,NewHConfig0) -> + WriteOnce = maps:with([type,file,modes],OldHConfig), + Default = + case SetOrUpdate of + set -> + %% Do not reset write-once fields to defaults + merge_default_config(Name,WriteOnce); + update -> + OldHConfig + end, -%% This is the synchronous log event. -handle_call({log, Bin}, _From, State) -> - {Result,State1} = do_log(Bin, call, State), - %% Result == ok | dropped - {reply,Result, State1}; + NewHConfig = maps:merge(Default, normalize_config(NewHConfig0)), -handle_call(filesync, _From, State = #{type := Type, - file_ctrl_pid := FileCtrlPid}) -> - if is_atom(Type) -> - {reply, ok, State}; - true -> - {reply, file_ctrl_filesync_sync(FileCtrlPid), State#{last_op=>sync}} - end; + %% Fail if write-once fields are changed + case maps:with([type,file,modes],NewHConfig) of + WriteOnce -> + check_h_config(NewHConfig); + Other -> + {error,{illegal_config_change,?MODULE,WriteOnce,Other}} + end. -handle_call({change_config,_OldConfig,NewConfig}, _From, - State = #{filesync_repeat_interval := FSyncInt0}) -> - HConfig = maps:get(config, NewConfig, #{}), - State1 = maps:merge(State, HConfig), - case logger_h_common:overload_levels_ok(State1) of - true -> - _ = - case maps:get(filesync_repeat_interval, HConfig, undefined) of - undefined -> - ok; - no_repeat -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, - State, - undefined)); - FSyncInt0 -> - ok; - _FSyncInt1 -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, - State, - undefined)), - gen_server:cast(self(), repeated_filesync) - end, - {reply, ok, State1}; - false -> - #{sync_mode_qlen := SMQL, - drop_mode_qlen := DMQL, - flush_qlen := FQL} = State1, - {reply, {error,{invalid_levels,{SMQL,DMQL,FQL}}}, State} - end; +check_h_config(HConfig) -> + case check_h_config(maps:get(type,HConfig),maps:to_list(HConfig)) of + ok -> + {ok,fix_file_opts(HConfig)}; + {error,{Key,Value}} -> + {error,{invalid_config,?MODULE,#{Key=>Value}}} + end. -handle_call(info, _From, State) -> - {reply, State, State}; - -handle_call(reset, _From, State) -> - State1 = ?merge_with_stats(State), - {reply, ok, State1#{last_qlen => 0, - last_log_ts => ?timestamp()}}; - -handle_call(stop, _From, State) -> - {stop, {shutdown,stopped}, ok, State}. - -%% This is the asynchronous log event. -handle_cast({log, Bin}, State) -> - {_,State1} = do_log(Bin, cast, State), - {noreply, State1}; - -handle_cast({log_handler_info, Format, Args}, State = #{id:=Name}) -> - log_handler_info(Name, Format, Args, State), - {noreply, State}; - -%% If FILESYNC_REPEAT_INTERVAL is set to a millisec value, this -%% clause gets called repeatedly by the handler. In order to -%% guarantee that a filesync *always* happens after the last log -%% event, the repeat operation must be active! -handle_cast(repeated_filesync, - State = #{type := Type, - file_ctrl_pid := FileCtrlPid, - filesync_repeat_interval := FSyncInt, - 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 LastOp == sync -> - ok; - true -> - file_ctrl_filesync_async(FileCtrlPid) - end, - {ok,TRef} = - timer:apply_after(FSyncInt, gen_server,cast, - [self(),repeated_filesync]), - State#{rep_sync_tref => TRef, last_op => sync}; - true -> - State - end, - {noreply,State1}. - -handle_info({'EXIT',Pid,Why}, State = #{id := Name, type := FileInfo}) -> - case maps:get(file_ctrl_pid, State, undefined) of - Pid -> - %% file error, terminate handler - logger_h_common:handler_exit(Name, - {error,{write_failed,FileInfo,Why}}); - _Other -> - %% ignore EXIT - ok - end, - {noreply, State}; +check_h_config(Type,[{type,Type} | Config]) when Type =:= standard_io; + Type =:= standard_error; + Type =:= file -> + check_h_config(Type,Config); +check_h_config(file,[{file,File} | Config]) when is_list(File) -> + check_h_config(file,Config); +check_h_config(file,[{modes,Modes} | Config]) when is_list(Modes) -> + check_h_config(file,Config); +check_h_config(file,[{max_no_bytes,Size} | Config]) + when (is_integer(Size) andalso Size>0) orelse Size=:=infinity -> + check_h_config(file,Config); +check_h_config(file,[{max_no_files,Num} | Config]) when is_integer(Num), Num>=0 -> + check_h_config(file,Config); +check_h_config(file,[{compress_on_rotate,Bool} | Config]) when is_boolean(Bool) -> + check_h_config(file,Config); +check_h_config(file,[{file_check,FileCheck} | Config]) + when is_integer(FileCheck), FileCheck>=0 -> + check_h_config(file,Config); +check_h_config(_Type,[Other | _]) -> + {error,Other}; +check_h_config(_Type,[]) -> + ok. -handle_info(_Info, State) -> - {noreply, State}. +normalize_config(#{type:={file,File}}=HConfig) -> + HConfig#{type=>file,file=>File}; +normalize_config(#{type:={file,File,Modes}}=HConfig) -> + HConfig#{type=>file,file=>File,modes=>Modes}; +normalize_config(HConfig) -> + HConfig. + +merge_default_config(Name,#{type:=Type}=HConfig) -> + merge_default_config(Name,Type,HConfig); +merge_default_config(Name,#{file:=_}=HConfig) -> + merge_default_config(Name,file,HConfig); +merge_default_config(Name,HConfig) -> + merge_default_config(Name,standard_io,HConfig). + +merge_default_config(Name,Type,HConfig) -> + maps:merge(get_default_config(Name,Type),HConfig). + +get_default_config(Name,file) -> + #{type => file, + file => atom_to_list(Name), + modes => [raw,append], + file_check => 0, + max_no_bytes => infinity, + max_no_files => 0, + compress_on_rotate => false}; +get_default_config(_Name,Type) -> + #{type => Type}. + +fix_file_opts(#{modes:=Modes}=HConfig) -> + HConfig#{modes=>fix_modes(Modes)}; +fix_file_opts(HConfig) -> + HConfig#{filesync_repeat_interval=>no_repeat}. + +fix_modes(Modes) -> + %% Ensure write|append|exclusive + Modes1 = + case [M || M <- Modes, + lists:member(M,[write,append,exclusive])] of + [] -> [append|Modes]; + _ -> Modes + end, + %% Ensure raw + Modes2 = + case lists:member(raw,Modes) of + false -> [raw|Modes1]; + true -> Modes1 + end, + %% Ensure delayed_write + case lists:partition(fun(delayed_write) -> true; + ({delayed_write,_,_}) -> true; + (_) -> false + end, Modes2) of + {[],_} -> + [delayed_write|Modes2]; + _ -> + Modes2 + end. -terminate(Reason, State = #{id:=Name, file_ctrl_pid:=FWPid, - type:=_FileInfo}) -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, State, - undefined)), +config_changed(_Name, + #{file_check:=FileCheck, + max_no_bytes:=Size, + max_no_files:=Count, + compress_on_rotate:=Compress}, + #{file_check:=FileCheck, + max_no_bytes:=Size, + max_no_files:=Count, + compress_on_rotate:=Compress}=State) -> + State; +config_changed(_Name, + #{file_check:=FileCheck, + max_no_bytes:=Size, + max_no_files:=Count, + compress_on_rotate:=Compress}, + #{file_ctrl_pid := FileCtrlPid} = State) -> + FileCtrlPid ! {update_config,#{file_check=>FileCheck, + max_no_bytes=>Size, + max_no_files=>Count, + compress_on_rotate=>Compress}}, + State#{file_check:=FileCheck, + max_no_bytes:=Size, + max_no_files:=Count, + compress_on_rotate:=Compress}; +config_changed(_Name,_NewHConfig,State) -> + State. + +filesync(_Name, SyncAsync, #{file_ctrl_pid := FileCtrlPid} = State) -> + Result = file_ctrl_filesync(SyncAsync, FileCtrlPid), + {Result,State}. + +write(_Name, SyncAsync, Bin, #{file_ctrl_pid:=FileCtrlPid} = State) -> + Result = file_write(SyncAsync, FileCtrlPid, Bin), + {Result,State}. + +reset_state(_Name, State) -> + State. + +handle_info(_Name, {'EXIT',Pid,Why}, #{file_ctrl_pid := Pid}=State) -> + %% file_ctrl_pid died, file error, terminate handler + exit({error,{write_failed,maps:with([type,file,modes],State),Why}}); +handle_info(_, _, State) -> + State. + +terminate(_Name, _Reason, #{file_ctrl_pid:=FWPid}) -> case is_process_alive(FWPid) of true -> unlink(FWPid), @@ -413,16 +282,12 @@ terminate(Reason, State = #{id:=Name, file_ctrl_pid:=FWPid, ok after ?DEFAULT_CALL_TIMEOUT -> - exit(FWPid, kill) + exit(FWPid, kill), + ok end; false -> ok - end, - unregister(?name_to_reg_name(?MODULE, Name)), - logger_h_common:stop_or_restart(Name, Reason, State). - -code_change(_OldVsn, State, _Extra) -> - {ok, State}. + end. %%%=================================================================== %%% Internal functions @@ -430,213 +295,36 @@ code_change(_OldVsn, State, _Extra) -> %%%----------------------------------------------------------------- %%% -get_init_state() -> - #{sync_mode_qlen => ?SYNC_MODE_QLEN, - drop_mode_qlen => ?DROP_MODE_QLEN, - flush_qlen => ?FLUSH_QLEN, - burst_limit_enable => ?BURST_LIMIT_ENABLE, - burst_limit_max_count => ?BURST_LIMIT_MAX_COUNT, - burst_limit_window_time => ?BURST_LIMIT_WINDOW_TIME, - overload_kill_enable => ?OVERLOAD_KILL_ENABLE, - overload_kill_qlen => ?OVERLOAD_KILL_QLEN, - overload_kill_mem_size => ?OVERLOAD_KILL_MEM_SIZE, - overload_kill_restart_after => ?OVERLOAD_KILL_RESTART_AFTER, - file_ctrl_sync_int => ?CONTROLLER_SYNC_INTERVAL, - filesync_ok_qlen => ?FILESYNC_OK_QLEN, - filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}. - -%%%----------------------------------------------------------------- -%%% Add a standard handler to the logger. -%%% This starts a dedicated handler process which should always -%%% exist if the handler is registered with logger (and should not -%%% exist if the handler is not registered). -%%% -%%% Handler specific config should be provided with a sub map associated -%%% with a key named 'config', e.g: -%%% -%%% Config = #{config => #{sync_mode_qlen => 50} -%%% -%%% The standard handler process is linked to logger_sup, which is -%%% part of the kernel application's supervision tree. -start(Name, Config, HandlerState) -> - LoggerStdH = - #{id => Name, - start => {?MODULE, start_link, [Name,Config,HandlerState]}, - restart => temporary, - shutdown => 2000, - type => worker, - modules => [?MODULE]}, - case supervisor:start_child(logger_sup, LoggerStdH) of - {ok,_Pid,Config1} -> - {ok,Config1}; - Error -> - Error - end. - -%%%----------------------------------------------------------------- -%%% Stop and remove the handler. -stop(Name) -> - case whereis(?name_to_reg_name(?MODULE,Name)) of - undefined -> - ok; - Pid -> - %% We don't want to do supervisor:terminate_child here - %% since we need to distinguish this explicit stop from a - %% system termination in order to avoid circular attempts - %% at removing the handler (implying deadlocks and - %% timeouts). - _ = gen_server:call(Pid, stop), - _ = supervisor:delete_child(logger_sup, Name), - ok - end. - -%%%----------------------------------------------------------------- -%%% Logging and overload control. --define(update_file_ctrl_sync(C, Interval), - if C == 0 -> Interval; - true -> C-1 end). - -%% check for overload between every event (and set Mode to async, -%% sync or drop accordingly), but never flush the whole mailbox -%% before LogWindowSize events have been handled -do_log(Bin, CallOrCast, State = #{id:=Name, mode:=Mode0}) -> - T1 = ?timestamp(), - - %% check if the handler is getting overloaded, or if it's - %% recovering from overload (the check must be done for each - %% event to react quickly to large bursts of events and - %% to ensure that the handler can never end up in drop mode - %% with an empty mailbox, which would stop operation) - {Mode1,QLen,Mem,State1} = logger_h_common:check_load(State), - - if (Mode1 == drop) andalso (Mode0 =/= drop) -> - log_handler_info(Name, "Handler ~p switched to drop mode", - [Name], State); - (Mode0 == drop) andalso ((Mode1 == async) orelse (Mode1 == sync)) -> - log_handler_info(Name, "Handler ~p switched to ~w mode", - [Name,Mode1], State); - true -> - ok - end, - - %% kill the handler if it can't keep up with the load - logger_h_common:kill_if_choked(Name, QLen, Mem, ?MODULE, State), - - if Mode1 == flush -> - flush(Name, QLen, T1, State1); - true -> - write(Name, Mode1, T1, Bin, CallOrCast, State1) - end. - -%% this clause is called by do_log/3 after an overload check -%% has been performed, where QLen > FlushQLen -flush(Name, _QLen0, T1, State=#{last_log_ts := _T0, mode_tab := ModeTab}) -> - %% flush messages in the mailbox (a limited number in - %% order to not cause long delays) - NewFlushed = logger_h_common:flush_log_events(?FLUSH_MAX_N), - - %% write info in log about flushed messages - log_handler_info(Name, "Handler ~p flushed ~w log events", - [Name,NewFlushed], State), - - %% because of the receive loop when flushing messages, the - %% handler will be scheduled out often and the mailbox could - %% grow very large, so we'd better check the queue again here - {_,_QLen1} = process_info(self(), message_queue_len), - ?observe(Name,{max_qlen,_QLen1}), - - %% Add 1 for the current log event - ?observe(Name,{flushed,NewFlushed+1}), - - State1 = ?update_max_time(?diff_time(T1,_T0),State), - {dropped,?update_other(flushed,FLUSHED,NewFlushed, - State1#{mode => ?set_mode(ModeTab,async), - last_qlen => 0, - last_log_ts => T1})}. - -%% this clause is called to write to file -write(_Name, Mode, T1, Bin, _CallOrCast, - State = #{mode_tab := ModeTab, - file_ctrl_pid := FileCtrlPid, - file_ctrl_sync := FileCtrlSync, - last_qlen := LastQLen, - last_log_ts := T0, - file_ctrl_sync_int := FileCtrlSyncInt}) -> - %% check if we need to limit the number of writes - %% during a burst of log events - {DoWrite,BurstWinT,BurstMsgCount} = logger_h_common:limit_burst(State), - - %% only send a synhrounous event to the file controller process - %% every FileCtrlSyncInt time, to give the handler time between - %% file writes so it can keep up with incoming messages - {Result,LastQLen1} = - if DoWrite, FileCtrlSync == 0 -> - ?observe(_Name,{_CallOrCast,1}), - file_write_sync(FileCtrlPid, Bin, false), - {ok,element(2, process_info(self(), message_queue_len))}; - DoWrite -> - ?observe(_Name,{_CallOrCast,1}), - file_write_async(FileCtrlPid, Bin), - {ok,LastQLen}; - not DoWrite -> - ?observe(_Name,{flushed,1}), - {dropped,LastQLen} - end, - - %% Check if the time since the previous log event is long enough - - %% and the queue length small enough - to assume the mailbox has - %% been emptied, and if so, do filesync operation and reset mode to - %% async. Note that this is the best we can do to detect an idle - %% handler without setting a timer after each log call/cast. If the - %% time between two consecutive log events is fast and no new - %% event comes in after the last one, idle state won't be detected! - Time = ?diff_time(T1,T0), - {Mode1,BurstMsgCount1} = - if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso - (Time > ?IDLE_DETECT_TIME_USEC) -> - %% do filesync if necessary - case maps:get(type, State) of - Std when is_atom(Std) -> - ok; - _File -> - file_ctrl_filesync_async(FileCtrlPid) - end, - {?change_mode(ModeTab, Mode, async),0}; - true -> - {Mode,BurstMsgCount} - end, - State1 = - ?update_calls_or_casts(_CallOrCast,1,State), - State2 = - ?update_max_time(Time, - State1#{mode => Mode1, - last_qlen := LastQLen1, - last_log_ts => T1, - last_op => write, - burst_win_ts => BurstWinT, - burst_msg_count => BurstMsgCount1, - file_ctrl_sync => - ?update_file_ctrl_sync(FileCtrlSync, - FileCtrlSyncInt)}), - {Result,State2}. - -open_log_file(HandlerName, FileInfo) -> - case file_ctrl_start(HandlerName, FileInfo) of - OK = {ok,_FileCtrlPid} -> OK; - Error -> Error - end. - -do_open_log_file({file,File}) -> - do_open_log_file({file,File,[raw,append,delayed_write]}); - -do_open_log_file({file,File,[]}) -> - do_open_log_file({file,File,[raw,append,delayed_write]}); - -do_open_log_file({file,File,Modes}) -> +open_log_file(HandlerName,#{type:=file, + file:=FileName, + modes:=Modes, + file_check:=FileCheck, + max_no_bytes:=Size, + max_no_files:=Count, + compress_on_rotate:=Compress}) -> try - case filelib:ensure_dir(File) of + case filelib:ensure_dir(FileName) of ok -> - file:open(File, Modes); + case file:open(FileName, Modes) of + {ok, Fd} -> + {ok,#file_info{inode=INode}} = + file:read_file_info(FileName,[raw]), + UpdateModes = [append | Modes--[write,append,exclusive]], + State0 = #{handler_name=>HandlerName, + file_name=>FileName, + modes=>UpdateModes, + file_check=>FileCheck, + fd=>Fd, + inode=>INode, + last_check=>timestamp(), + synced=>false, + write_res=>ok, + sync_res=>ok}, + State = update_rotation({Size,Count,Compress},State0), + {ok,State}; + Error -> + Error + end; Error -> Error end @@ -644,34 +332,23 @@ do_open_log_file({file,File,Modes}) -> _:Reason -> {error,Reason} end. -close_log_file(Std) when Std == standard_io; Std == standard_error -> - ok; -close_log_file(Fd) -> +close_log_file(#{fd:=Fd}) -> _ = file:datasync(Fd), - _ = file:close(Fd). + _ = file:close(Fd), + ok; +close_log_file(_) -> + ok. -log_handler_info(Name, Format, Args, #{file_ctrl_pid := FileCtrlPid}) -> - Config = - case logger:get_handler_config(Name) of - {ok,Conf} -> Conf; - _ -> #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}} - end, - Meta = #{time=>erlang:system_time(microsecond)}, - Bin = logger_h_common:log_to_binary(#{level => notice, - msg => {Format,Args}, - meta => Meta}, Config), - _ = file_write_async(FileCtrlPid, Bin), - ok. %%%----------------------------------------------------------------- %%% File control process -file_ctrl_start(HandlerName, FileInfo) -> +file_ctrl_start(HandlerName, HConfig) -> Starter = self(), FileCtrlPid = spawn_link(fun() -> - file_ctrl_init(HandlerName, FileInfo, Starter) + file_ctrl_init(HandlerName, HConfig, Starter) end), receive {FileCtrlPid,ok} -> @@ -686,28 +363,21 @@ file_ctrl_start(HandlerName, FileInfo) -> file_ctrl_stop(Pid) -> Pid ! stop. -file_write_async(Pid, Bin) -> +file_write(async, Pid, Bin) -> Pid ! {log,Bin}, - ok. - -file_write_sync(Pid, Bin, FileSync) -> - case file_ctrl_call(Pid, {log,self(),Bin,FileSync}) of - {error,Reason} -> - {error,{write_failed,Bin,Reason}}; - Result -> - Result - end. + ok; +file_write(sync, Pid, Bin) -> + file_ctrl_call(Pid, {log,Bin}). -file_ctrl_filesync_async(Pid) -> +file_ctrl_filesync(async, Pid) -> Pid ! filesync, - ok. - -file_ctrl_filesync_sync(Pid) -> - file_ctrl_call(Pid, {filesync,self()}). + ok; +file_ctrl_filesync(sync, Pid) -> + file_ctrl_call(Pid, filesync). file_ctrl_call(Pid, Msg) -> MRef = monitor(process, Pid), - Pid ! {Msg,MRef}, + Pid ! {Msg,{self(),MRef}}, receive {MRef,Result} -> demonitor(MRef, [flush]), @@ -719,108 +389,255 @@ file_ctrl_call(Pid, Msg) -> {error,{no_response,Pid}} end. -file_ctrl_init(HandlerName, FileInfo, Starter) when is_tuple(FileInfo) -> +file_ctrl_init(HandlerName, + #{type:=file, + file:=FileName} = HConfig, + Starter) -> process_flag(message_queue_data, off_heap), - FileName = element(2, FileInfo), - case do_open_log_file(FileInfo) of - {ok,Fd} -> + case open_log_file(HandlerName,HConfig) of + {ok,State} -> Starter ! {self(),ok}, - file_ctrl_loop(Fd, file, FileName, false, ok, ok, HandlerName); + file_ctrl_loop(State); {error,Reason} -> Starter ! {self(),{error,{open_failed,FileName,Reason}}} end; -file_ctrl_init(HandlerName, StdDev, Starter) -> +file_ctrl_init(HandlerName, #{type:=StdDev}, Starter) -> Starter ! {self(),ok}, - file_ctrl_loop(StdDev, standard_io, StdDev, false, ok, ok, HandlerName). + file_ctrl_loop(#{handler_name=>HandlerName,dev=>StdDev}). -file_ctrl_loop(Fd, Type, DevName, Synced, - PrevWriteResult, PrevSyncResult, HandlerName) -> +file_ctrl_loop(State) -> receive %% asynchronous event {log,Bin} -> - Result = if Type == file -> - write_to_dev(Fd, Bin, DevName, - PrevWriteResult, HandlerName); - true -> - io:put_chars(Fd, Bin) - end, - file_ctrl_loop(Fd, Type, DevName, false, - Result, PrevSyncResult, HandlerName); + State1 = write_to_dev(Bin,State), + file_ctrl_loop(State1); %% synchronous event - {{log,From,Bin,FileSync},MRef} -> - if Type == file -> - %% check that file hasn't been deleted - CheckFile = - fun() -> {ok,_} = file:read_file_info(DevName) end, - spawn_link(CheckFile), - WResult = write_to_dev(Fd, Bin, DevName, - PrevWriteResult, HandlerName), - {Synced1,SResult} = - if not FileSync -> - {false,PrevSyncResult}; - true -> - case sync_dev(Fd, DevName, - PrevSyncResult, HandlerName) of - ok -> {true,ok}; - Error -> {false,Error} - end - end, - From ! {MRef,ok}, - file_ctrl_loop(Fd, Type, DevName, Synced1, - WResult, SResult, HandlerName); - true -> - _ = io:put_chars(Fd, Bin), - From ! {MRef,ok}, - file_ctrl_loop(Fd, Type, DevName, false, - ok, PrevSyncResult, HandlerName) - end; - - filesync when not Synced -> - Result = sync_dev(Fd, DevName, PrevSyncResult, HandlerName), - file_ctrl_loop(Fd, Type, DevName, true, - PrevWriteResult, Result, HandlerName); + {{log,Bin},{From,MRef}} -> + State1 = ensure_file(State), + State2 = write_to_dev(Bin,State1), + From ! {MRef,ok}, + file_ctrl_loop(State2); filesync -> - file_ctrl_loop(Fd, Type, DevName, true, - PrevWriteResult, PrevSyncResult, HandlerName); - - {{filesync,From},MRef} -> - Result = if not Synced -> - sync_dev(Fd, DevName, PrevSyncResult, HandlerName); - true -> - ok - end, + State1 = sync_dev(State), + file_ctrl_loop(State1); + + {filesync,{From,MRef}} -> + State1 = ensure_file(State), + State2 = sync_dev(State1), From ! {MRef,ok}, - file_ctrl_loop(Fd, Type, DevName, true, - PrevWriteResult, Result, HandlerName); + file_ctrl_loop(State2); + + {update_config,#{file_check:=FileCheck, + max_no_bytes:=Size, + max_no_files:=Count, + compress_on_rotate:=Compress}} -> + State1 = update_rotation({Size,Count,Compress},State), + file_ctrl_loop(State1#{file_check=>FileCheck}); stop -> - _ = close_log_file(Fd), + close_log_file(State), stopped end. -write_to_dev(Fd, Bin, FileName, PrevWriteResult, HandlerName) -> - case ?file_write(Fd, Bin) of - ok -> +maybe_ensure_file(#{file_check:=0}=State) -> + ensure_file(State); +maybe_ensure_file(#{last_check:=T0,file_check:=CheckInt}=State) + when is_integer(CheckInt) -> + T = timestamp(), + if T-T0 > CheckInt -> ensure_file(State); + true -> State + end; +maybe_ensure_file(State) -> + State. + +%% In order to play well with tools like logrotate, we need to be able +%% to re-create the file if it has disappeared (e.g. if rotated by +%% logrotate) +ensure_file(#{fd:=Fd0,inode:=INode0,file_name:=FileName,modes:=Modes}=State) -> + case file:read_file_info(FileName,[raw]) of + {ok,#file_info{inode=INode0}} -> + State#{last_check=>timestamp()}; + _ -> + close_log_file(Fd0), + case file:open(FileName,Modes) of + {ok,Fd} -> + {ok,#file_info{inode=INode}} = + file:read_file_info(FileName,[raw]), + State#{fd=>Fd,inode=>INode, + last_check=>timestamp(), + synced=>true,sync_res=>ok}; + Error -> + exit({could_not_reopen_file,Error}) + end + end; +ensure_file(State) -> + State. + +write_to_dev(Bin,#{dev:=DevName}=State) -> + io:put_chars(DevName, Bin), + State; +write_to_dev(Bin, State) -> + State1 = #{fd:=Fd} = maybe_ensure_file(State), + Result = ?file_write(Fd, Bin), + State2 = maybe_rotate_file(Bin,State1), + maybe_notify_error(write,Result,State2), + State2#{synced=>false,write_res=>Result}. + +sync_dev(#{synced:=false}=State) -> + State1 = #{fd:=Fd} = maybe_ensure_file(State), + Result = ?file_datasync(Fd), + maybe_notify_error(filesync,Result,State1), + State1#{synced=>true,sync_res=>Result}; +sync_dev(State) -> + State. + +update_rotation({infinity,_,_},State) -> + maybe_remove_archives(0,State), + maps:remove(rotation,State); +update_rotation({Size,Count,Compress},#{file_name:=FileName} = State) -> + maybe_remove_archives(Count,State), + {ok,#file_info{size=CurrSize}} = file:read_file_info(FileName,[raw]), + State1 = State#{rotation=>#{size=>Size, + count=>Count, + compress=>Compress, + curr_size=>CurrSize}}, + maybe_update_compress(0,State1), + maybe_rotate_file(0,State1). + +maybe_remove_archives(Count,#{file_name:=FileName}=State) -> + Archive = rot_file_name(FileName,Count,false), + CompressedArchive = rot_file_name(FileName,Count,true), + case {file:read_file_info(Archive,[raw]), + file:read_file_info(CompressedArchive,[raw])} of + {{error,enoent},{error,enoent}} -> ok; - PrevWriteResult -> - %% don't report same error twice - PrevWriteResult; - Error -> - logger_h_common:error_notify({HandlerName,write,FileName,Error}), - Error + _ -> + _ = file:delete(Archive), + _ = file:delete(CompressedArchive), + maybe_remove_archives(Count+1,State) end. -sync_dev(Fd, DevName, PrevSyncResult, HandlerName) -> - case ?file_datasync(Fd) of - ok -> - ok; - PrevSyncResult -> - %% don't report same error twice - PrevSyncResult; +maybe_update_compress(Count,#{rotation:=#{count:=Count}}) -> + ok; +maybe_update_compress(N,#{file_name:=FileName, + rotation:=#{compress:=Compress}}=State) -> + Archive = rot_file_name(FileName,N,not Compress), + case file:read_file_info(Archive,[raw]) of + {ok,_} when Compress -> + compress_file(Archive); + {ok,_} -> + decompress_file(Archive); + _ -> + ok + end, + maybe_update_compress(N+1,State). + +maybe_rotate_file(Bin,#{rotation:=_}=State) when is_binary(Bin) -> + maybe_rotate_file(byte_size(Bin),State); +maybe_rotate_file(AddSize,#{rotation:=#{size:=RotSize, + curr_size:=CurrSize}=Rotation}=State) -> + NewSize = CurrSize + AddSize, + if NewSize>RotSize -> + rotate_file(State#{rotation=>Rotation#{curr_size=>NewSize}}); + true -> + State#{rotation=>Rotation#{curr_size=>NewSize}} + end; +maybe_rotate_file(_Bin,State) -> + State. + +rotate_file(#{fd:=Fd0,file_name:=FileName,modes:=Modes,rotation:=Rotation}=State) -> + State1 = sync_dev(State), + _ = file:close(Fd0), + _ = file:close(Fd0), + rotate_files(FileName,maps:get(count,Rotation),maps:get(compress,Rotation)), + case file:open(FileName,Modes) of + {ok,Fd} -> + {ok,#file_info{inode=INode}} = file:read_file_info(FileName,[raw]), + State1#{fd=>Fd,inode=>INode,rotation=>Rotation#{curr_size=>0}}; Error -> - logger_h_common:error_notify({HandlerName,filesync,DevName,Error}), - Error + exit({could_not_reopen_file,Error}) end. +rotate_files(FileName,0,_Compress) -> + _ = file:delete(FileName), + ok; +rotate_files(FileName,1,Compress) -> + FileName0 = FileName++".0", + _ = file:rename(FileName,FileName0), + if Compress -> compress_file(FileName0); + true -> ok + end, + ok; +rotate_files(FileName,Count,Compress) -> + _ = file:rename(rot_file_name(FileName,Count-2,Compress), + rot_file_name(FileName,Count-1,Compress)), + rotate_files(FileName,Count-1,Compress). + +rot_file_name(FileName,Count,false) -> + FileName ++ "." ++ integer_to_list(Count); +rot_file_name(FileName,Count,true) -> + rot_file_name(FileName,Count,false) ++ ".gz". + +compress_file(FileName) -> + {ok,In} = file:open(FileName,[read,binary]), + {ok,Out} = file:open(FileName++".gz",[write]), + Z = zlib:open(), + zlib:deflateInit(Z, default, deflated, 31, 8, default), + compress_data(Z,In,Out), + zlib:deflateEnd(Z), + zlib:close(Z), + _ = file:close(In), + _ = file:close(Out), + _ = file:delete(FileName), + ok. + +compress_data(Z,In,Out) -> + case file:read(In,100000) of + {ok,Data} -> + Compressed = zlib:deflate(Z, Data), + _ = file:write(Out,Compressed), + compress_data(Z,In,Out); + eof -> + Compressed = zlib:deflate(Z, <<>>, finish), + _ = file:write(Out,Compressed), + ok + end. + +decompress_file(FileName) -> + {ok,In} = file:open(FileName,[read,binary]), + {ok,Out} = file:open(filename:rootname(FileName,".gz"),[write]), + Z = zlib:open(), + zlib:inflateInit(Z, 31), + decompress_data(Z,In,Out), + zlib:inflateEnd(Z), + zlib:close(Z), + _ = file:close(In), + _ = file:close(Out), + _ = file:delete(FileName), + ok. + +decompress_data(Z,In,Out) -> + case file:read(In,1000) of + {ok,Data} -> + Decompressed = zlib:inflate(Z, Data), + _ = file:write(Out,Decompressed), + decompress_data(Z,In,Out); + eof -> + ok + end. + +maybe_notify_error(_Op, ok, _State) -> + ok; +maybe_notify_error(Op, Result, #{write_res:=WR,sync_res:=SR}) + when (Op==write andalso Result==WR) orelse + (Op==filesync andalso Result==SR) -> + %% don't report same error twice + ok; +maybe_notify_error(Op, Error, #{handler_name:=HandlerName,file_name:=FileName}) -> + logger_h_common:error_notify({HandlerName,Op,FileName,Error}), + ok. + +timestamp() -> + erlang:monotonic_time(millisecond). diff --git a/lib/kernel/src/logger_sup.erl b/lib/kernel/src/logger_sup.erl index dcdcdad0bd..9ea8558a16 100644 --- a/lib/kernel/src/logger_sup.erl +++ b/lib/kernel/src/logger_sup.erl @@ -46,7 +46,13 @@ init([]) -> intensity => 1, period => 5}, - {ok, {SupFlags, []}}. + Watcher = #{id => logger_handler_watcher, + start => {logger_handler_watcher, start_link, []}, + shutdown => brutal_kill}, + + Proxy = logger_proxy:child_spec(), + + {ok, {SupFlags, [Watcher,Proxy]}}. %%%=================================================================== %%% Internal functions diff --git a/lib/kernel/src/net.erl b/lib/kernel/src/net.erl deleted file mode 100644 index 2d0ae2ed0c..0000000000 --- a/lib/kernel/src/net.erl +++ /dev/null @@ -1,40 +0,0 @@ -%% -%% %CopyrightBegin% -%% -%% Copyright Ericsson AB 1996-2016. 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% -%% --module(net). - -%% Various network functions, kept here for compatibility - --export([call/4, - cast/4, - broadcast/3, - ping/1, - relay/1, - sleep/1]). - --deprecated(module). - -call(N,M,F,A) -> rpc:call(N,M,F,A). -cast(N,M,F,A) -> rpc:cast(N,M,F,A). -broadcast(M,F,A) -> rpc:eval_everywhere(M,F,A). -ping(Node) -> net_adm:ping(Node). -sleep(T) -> receive after T -> ok end. -relay(X) -> slave:relay(X). - - diff --git a/lib/kernel/src/net_kernel.erl b/lib/kernel/src/net_kernel.erl index c4e1a0ce1e..83d3b4b5e1 100644 --- a/lib/kernel/src/net_kernel.erl +++ b/lib/kernel/src/net_kernel.erl @@ -279,24 +279,18 @@ passive_connect_monitor(From, Node) -> ok = monitor_nodes(true,[{node_type,all}]), Reply = case lists:member(Node,nodes([connected])) of true -> - io:format("~p: passive_connect_monitor ~p\n", [self(), ?LINE]), true; _ -> receive {nodeup,Node,_} -> - io:format("~p: passive_connect_monitor ~p\n", [self(), ?LINE]), true after connecttime() -> - io:format("~p: passive_connect_monitor ~p\n", [self(), ?LINE]), false end end, ok = monitor_nodes(false,[{node_type,all}]), - io:format("~p: passive_connect_monitor ~p\n", [self(), ?LINE]), {Pid, Tag} = From, - io:format("~p: passive_connect_monitor ~p\n", [self(), ?LINE]), - erlang:send(Pid, {Tag, Reply}), - io:format("~p: passive_connect_monitor ~p\n", [self(), ?LINE]). + erlang:send(Pid, {Tag, Reply}). %% If the net_kernel isn't running we ignore all requests to the @@ -358,20 +352,34 @@ init({Name, LongOrShortNames, TickT, CleanHalt}) -> {stop, Error} end. - -do_auto_connect(Type, Node, ConnId, WaitForBarred, From, State) -> - ConnLookup = ets:lookup(sys_dist, Node), - - case ConnLookup of +do_auto_connect_1(Node, ConnId, From, State) -> + case ets:lookup(sys_dist, Node) of [#barred_connection{}] -> - case WaitForBarred of - false -> - {reply, false, State}; - true -> + case ConnId of + passive_cnct -> spawn(?MODULE,passive_connect_monitor,[From,Node]), - {noreply, State} + {noreply, State}; + _ -> + erts_internal:abort_connection(Node, ConnId), + {reply, false, State} end; + ConnLookup -> + do_auto_connect_2(Node, ConnId, From, State, ConnLookup) + end. + +do_auto_connect_2(Node, passive_cnct, From, State, ConnLookup) -> + try erts_internal:new_connection(Node) of + ConnId -> + do_auto_connect_2(Node, ConnId, From, State, ConnLookup) + catch + _:_ -> + error_logger:error_msg("~n** Cannot get connection id for node ~w~n", + [Node]), + {reply, false, State} + end; +do_auto_connect_2(Node, ConnId, From, State, ConnLookup) -> + case ConnLookup of [#connection{conn_id=ConnId, state = up}] -> {reply, true, State}; [#connection{conn_id=ConnId, waiting=Waiting}=Conn] -> @@ -385,6 +393,7 @@ do_auto_connect(Type, Node, ConnId, WaitForBarred, From, State) -> case application:get_env(kernel, dist_auto_connect) of {ok, never} -> ?connect_failure(Node,{dist_auto_connect,never}), + erts_internal:abort_connection(Node, ConnId), {reply, false, State}; %% This might happen due to connection close @@ -394,14 +403,16 @@ do_auto_connect(Type, Node, ConnId, WaitForBarred, From, State) -> (hd(ConnLookup))#connection.state =:= up -> ?connect_failure(Node,{barred_connection, ets:lookup(sys_dist, Node)}), + erts_internal:abort_connection(Node, ConnId), {reply, false, State}; _ -> - case setup(ConnLookup, Node,ConnId,Type,From,State) of + case setup(Node, ConnId, normal, From, State) of {ok, SetupPid} -> Owners = [{SetupPid, Node} | State#state.conn_owners], {noreply,State#state{conn_owners=Owners}}; _Error -> ?connect_failure(Node, {setup_call, failed, _Error}), + erts_internal:abort_connection(Node, ConnId), {reply, false, State} end end @@ -419,8 +430,8 @@ do_explicit_connect([#connection{conn_id = ConnId}=Conn], _, _, ConnId, From, St do_explicit_connect([#barred_connection{}], Type, Node, ConnId, From , State) -> %% Barred connection only affects auto_connect, ignore it. do_explicit_connect([], Type, Node, ConnId, From , State); -do_explicit_connect(ConnLookup, Type, Node, ConnId, From , State) -> - case setup(ConnLookup, Node,ConnId,Type,From,State) of +do_explicit_connect(_ConnLookup, Type, Node, ConnId, From , State) -> + case setup(Node,ConnId,Type,From,State) of {ok, SetupPid} -> Owners = [{SetupPid, Node} | State#state.conn_owners], {noreply,State#state{conn_owners=Owners}}; @@ -429,18 +440,6 @@ do_explicit_connect(ConnLookup, Type, Node, ConnId, From , State) -> {reply, false, State} end. --define(ERTS_DIST_CON_ID_MASK, 16#ffffff). % also in external.h - -verify_new_conn_id([], {Nr,_DHandle}) - when (Nr band (bnot ?ERTS_DIST_CON_ID_MASK)) =:= 0 -> - true; -verify_new_conn_id([#connection{conn_id = {Old,_}}], {New,_}) - when New =:= ((Old+1) band ?ERTS_DIST_CON_ID_MASK) -> - true; -verify_new_conn_id(_, _) -> - false. - - %% ------------------------------------------------------------ %% handle_call. @@ -454,34 +453,33 @@ handle_call({passive_cnct, Node}, From, State) when Node =:= node() -> async_reply({reply, true, State}, From); handle_call({passive_cnct, Node}, From, State) -> verbose({passive_cnct, Node}, 1, State), - Type = normal, - WaitForBarred = true, - R = case (catch erts_internal:new_connection(Node)) of - {Nr,_DHandle}=ConnId when is_integer(Nr) -> - do_auto_connect(Type, Node, ConnId, WaitForBarred, From, State); - - _Error -> - error_logger:error_msg("~n** Cannot get connection id for node ~w~n", - [Node]), - {reply, false, State} - end, - + R = do_auto_connect_1(Node, passive_cnct, From, State), return_call(R, From); %% %% Explicit connect %% The response is delayed until the connection is up and running. %% -handle_call({connect, _, Node, _, _}, From, State) when Node =:= node() -> +handle_call({connect, _, Node}, From, State) when Node =:= node() -> async_reply({reply, true, State}, From); handle_call({connect, Type, Node}, From, State) -> verbose({connect, Type, Node}, 1, State), ConnLookup = ets:lookup(sys_dist, Node), - R = case (catch erts_internal:new_connection(Node)) of - {Nr,_DHandle}=ConnId when is_integer(Nr) -> - do_explicit_connect(ConnLookup, Type, Node, ConnId, From, State); + R = try erts_internal:new_connection(Node) of + ConnId -> + R1 = do_explicit_connect(ConnLookup, Type, Node, ConnId, From, State), + case R1 of + {reply, true, _S} -> %% already connected + ok; + {noreply, _S} -> %% connection pending + ok; + {reply, false, _S} -> %% connection refused + erts_internal:abort_connection(Node, ConnId) + end, + R1 - _Error -> + catch + _:_ -> error_logger:error_msg("~n** Cannot get connection id for node ~w~n", [Node]), {reply, false, State} @@ -699,11 +697,11 @@ terminate(_Reason, State) -> %% %% Asynchronous auto connect request %% -handle_info({auto_connect,Node, Nr, DHandle}, State) -> - verbose({auto_connect, Node, Nr, DHandle}, 1, State), - ConnId = {Nr, DHandle}, +handle_info({auto_connect,Node, DHandle}, State) -> + verbose({auto_connect, Node, DHandle}, 1, State), + ConnId = DHandle, NewState = - case do_auto_connect(normal, Node, ConnId, false, noreply, State) of + case do_auto_connect_1(Node, ConnId, noreply, State) of {noreply, S} -> %% Pending connection S; @@ -711,7 +709,6 @@ handle_info({auto_connect,Node, Nr, DHandle}, State) -> S; {reply, false, S} -> %% Connection refused - erts_internal:abort_connection(Node, ConnId), S end, {noreply, NewState}; @@ -796,8 +793,8 @@ handle_info({AcceptPid, {accept_pending,MyNode,Node,Address,Type}}, State) -> AcceptPid ! {self(), {accept_pending, already_pending}}, {noreply, State}; _ -> - case (catch erts_internal:new_connection(Node)) of - {Nr,_DHandle}=ConnId when is_integer(Nr) -> + try erts_internal:new_connection(Node) of + ConnId -> ets:insert(sys_dist, #connection{node = Node, conn_id = ConnId, state = pending, @@ -806,12 +803,13 @@ handle_info({AcceptPid, {accept_pending,MyNode,Node,Address,Type}}, State) -> type = Type}), AcceptPid ! {self(),{accept_pending,ok}}, Owners = [{AcceptPid,Node} | State#state.conn_owners], - {noreply, State#state{conn_owners = Owners}}; - - _ -> + {noreply, State#state{conn_owners = Owners}} + catch + _:_ -> error_logger:error_msg("~n** Cannot get connection id for node ~w~n", [Node]), - AcceptPid ! {self(),{accept_pending,nok_pending}} + AcceptPid ! {self(),{accept_pending,nok_pending}}, + {noreply, State} end end; @@ -1128,14 +1126,22 @@ do_disconnect(Node, State) -> {false, State} end. - disconnect_pid(Pid, State) -> exit(Pid, disconnect), + + %% This code used to only use exit + recv 'EXIT' to sync, + %% but since OTP-22 links are no longer broken atomically + %% so the exit message below can arrive before any remaining + %% exit messages have killed the distribution port + Ref = erlang:monitor(process, Pid), %% Sync wait for connection to die!!! receive - {'EXIT',Pid,Reason} -> - {_,State1} = handle_exit(Pid, Reason, State), - {true, State1} + {'DOWN',Ref,_,_,_} -> + receive + {'EXIT',Pid,Reason} -> + {_,State1} = handle_exit(Pid, Reason, State), + {true, State1} + end end. %% @@ -1275,8 +1281,8 @@ spawn_func(_,{From,Tag},M,F,A,Gleader) -> %% Set up connection to a new node. %% ----------------------------------------------------------- -setup(ConnLookup, Node,ConnId,Type,From,State) -> - case setup_check(ConnLookup, Node, ConnId, State) of +setup(Node, ConnId, Type, From, State) -> + case setup_check(Node, State) of {ok, L} -> Mod = L#listen.module, LAddr = L#listen.address, @@ -1305,7 +1311,7 @@ setup(ConnLookup, Node,ConnId,Type,From,State) -> Error end. -setup_check(ConnLookup, Node, ConnId, State) -> +setup_check(Node, State) -> Allowed = State#state.allowed, case lists:member(Node, Allowed) of false when Allowed =/= [] -> @@ -1313,16 +1319,9 @@ setup_check(ConnLookup, Node, ConnId, State) -> "disallowed node ~w ** ~n", [Node]), {error, bad_node}; _ -> - case verify_new_conn_id(ConnLookup, ConnId) of - false -> - error_msg("** Connection attempt to ~w with " - "bad connection id ~w ** ~n", [Node, ConnId]), - {error, bad_conn_id}; - true -> - case select_mod(Node, State#state.listen) of - {ok, _L}=OK -> OK; - Error -> Error - end + case select_mod(Node, State#state.listen) of + {ok, _L}=OK -> OK; + Error -> Error end end. @@ -1442,7 +1441,7 @@ validate_hostname([$@|HostPart] = Host) -> end. valid_name_head(Head) -> - {ok, MP} = re:compile("^[0-9A-Za-z_\\-]*$", [unicode]), + {ok, MP} = re:compile("^[0-9A-Za-z_\\-]+$", [unicode]), case re:run(Head, MP) of {match, _} -> true; diff --git a/lib/kernel/src/raw_file_io_inflate.erl b/lib/kernel/src/raw_file_io_inflate.erl index 7e9780310c..d3ed02dd03 100644 --- a/lib/kernel/src/raw_file_io_inflate.erl +++ b/lib/kernel/src/raw_file_io_inflate.erl @@ -26,7 +26,7 @@ -include("file_int.hrl"). --define(INFLATE_CHUNK_SIZE, (1 bsl 10)). +-define(INFLATE_CHUNK_SIZE, (8 bsl 10)). -define(GZIP_WBITS, (16 + 15)). callback_mode() -> state_functions. diff --git a/lib/kernel/src/seq_trace.erl b/lib/kernel/src/seq_trace.erl index 14fe21e9de..4f9d7b3e5c 100644 --- a/lib/kernel/src/seq_trace.erl +++ b/lib/kernel/src/seq_trace.erl @@ -98,7 +98,7 @@ print(Label, Term) -> -spec reset_trace() -> 'true'. reset_trace() -> - erlang:system_flag(1, 0). + erlang:system_flag(reset_seq_trace, true). %% reset_trace(Pid) -> % this might be a useful function too diff --git a/lib/kernel/src/standard_error.erl b/lib/kernel/src/standard_error.erl index 5d649e5f94..ef5b532960 100644 --- a/lib/kernel/src/standard_error.erl +++ b/lib/kernel/src/standard_error.erl @@ -27,7 +27,8 @@ -define(PROCNAME_SUP, standard_error_sup). %% Defines for control ops --define(CTRL_OP_GET_WINSIZE,100). +-define(ERTS_TTYSL_DRV_CONTROL_MAGIC_NUMBER, 16#018b0900). +-define(CTRL_OP_GET_WINSIZE, (100 + ?ERTS_TTYSL_DRV_CONTROL_MAGIC_NUMBER)). %% %% The basic server and start-up. diff --git a/lib/kernel/src/user.erl b/lib/kernel/src/user.erl index 872e63ab53..5a3487a9ba 100644 --- a/lib/kernel/src/user.erl +++ b/lib/kernel/src/user.erl @@ -28,7 +28,8 @@ -define(NAME, user). %% Defines for control ops --define(CTRL_OP_GET_WINSIZE,100). +-define(ERTS_TTYSL_DRV_CONTROL_MAGIC_NUMBER, 16#018b0900). +-define(CTRL_OP_GET_WINSIZE, (100 + ?ERTS_TTYSL_DRV_CONTROL_MAGIC_NUMBER)). %% %% The basic server and start-up. @@ -295,7 +296,8 @@ io_requests([], Stat, _) -> %% port. put_port(List, Port) -> - send_port(Port, {command, List}). + true = port_command(Port, List), + ok. %% send_port(Port, Command) diff --git a/lib/kernel/src/user_drv.erl b/lib/kernel/src/user_drv.erl index 9f914aa222..644aa752b6 100644 --- a/lib/kernel/src/user_drv.erl +++ b/lib/kernel/src/user_drv.erl @@ -32,9 +32,10 @@ -define(OP_BEEP,4). -define(OP_PUTC_SYNC,5). % Control op --define(CTRL_OP_GET_WINSIZE,100). --define(CTRL_OP_GET_UNICODE_STATE,101). --define(CTRL_OP_SET_UNICODE_STATE,102). +-define(ERTS_TTYSL_DRV_CONTROL_MAGIC_NUMBER, 16#018b0900). +-define(CTRL_OP_GET_WINSIZE, (100 + ?ERTS_TTYSL_DRV_CONTROL_MAGIC_NUMBER)). +-define(CTRL_OP_GET_UNICODE_STATE, (101 + ?ERTS_TTYSL_DRV_CONTROL_MAGIC_NUMBER)). +-define(CTRL_OP_SET_UNICODE_STATE, (102 + ?ERTS_TTYSL_DRV_CONTROL_MAGIC_NUMBER)). %% start() %% start(ArgumentList) @@ -119,7 +120,7 @@ server1(Iport, Oport, Shell) -> {Curr,Shell1} = case init:get_argument(remsh) of {ok,[[Node]]} -> - ANode = list_to_atom(Node), + ANode = list_to_atom(append_hostname(Node)), RShell = {ANode,shell,start,[]}, RGr = group:start(self(), RShell, rem_sh_opts(ANode)), {RGr,RShell}; @@ -138,6 +139,12 @@ server1(Iport, Oport, Shell) -> %% Enter the server loop. server_loop(Iport, Oport, Curr, User, Gr, {false, queue:new()}). +append_hostname(Node) -> + case string:find(Node, "@") of + nomatch -> Node ++ string:find(atom_to_list(node()), "@"); + _ -> Node + end. + rem_sh_opts(Node) -> [{expand_fun,fun(B)-> rpc:call(Node,edlin_expand,expand,[B]) end}]. @@ -536,19 +543,14 @@ set_unicode_state(Iport, Bool) -> %% io_request(Request, InPort, OutPort) %% io_requests(Requests, InPort, OutPort) %% Note: InPort is unused. - -io_request(Request, Iport, Oport) -> - try io_command(Request) of - {command,_} = Command -> - Oport ! {self(),Command}, - ok; - {Command,Reply} -> - Oport ! {self(),Command}, - Reply - catch - {requests,Rs} -> - io_requests(Rs, Iport, Oport); - _ -> +io_request({requests,Rs}, Iport, Oport) -> + io_requests(Rs, Iport, Oport); +io_request(Request, _Iport, Oport) -> + case io_command(Request) of + {Data, Reply} -> + true = port_command(Oport, Data), + Reply; + unhandled -> ok end. @@ -568,19 +570,19 @@ put_int16(N, Tail) -> %% to the console before the vm stops when calling erlang:halt(integer()). -dialyzer({no_improper_lists, io_command/1}). io_command({put_chars_sync, unicode,Cs,Reply}) -> - {{command,[?OP_PUTC_SYNC|unicode:characters_to_binary(Cs,utf8)]},Reply}; + {[?OP_PUTC_SYNC|unicode:characters_to_binary(Cs,utf8)], Reply}; io_command({put_chars, unicode,Cs}) -> - {command,[?OP_PUTC|unicode:characters_to_binary(Cs,utf8)]}; + {[?OP_PUTC|unicode:characters_to_binary(Cs,utf8)], ok}; io_command({move_rel,N}) -> - {command,[?OP_MOVE|put_int16(N, [])]}; + {[?OP_MOVE|put_int16(N, [])], ok}; io_command({insert_chars,unicode,Cs}) -> - {command,[?OP_INSC|unicode:characters_to_binary(Cs,utf8)]}; + {[?OP_INSC|unicode:characters_to_binary(Cs,utf8)], ok}; io_command({delete_chars,N}) -> - {command,[?OP_DELC|put_int16(N, [])]}; + {[?OP_DELC|put_int16(N, [])], ok}; io_command(beep) -> - {command,[?OP_BEEP]}; -io_command(Else) -> - throw(Else). + {[?OP_BEEP], ok}; +io_command(_) -> + unhandled. %% gr_new() %% gr_get_num(Group, Index) |