diff options
Diffstat (limited to 'lib/kernel/src')
38 files changed, 5598 insertions, 489 deletions
diff --git a/lib/kernel/src/Makefile b/lib/kernel/src/Makefile index 0bc9f121a0..f265fdd272 100644 --- a/lib/kernel/src/Makefile +++ b/lib/kernel/src/Makefile @@ -109,6 +109,17 @@ MODULES = \ kernel_refc \ local_udp \ local_tcp \ + logger \ + logger_backend \ + logger_config \ + logger_std_h \ + logger_disk_log_h \ + logger_h_common \ + logger_filters \ + logger_formatter \ + logger_server \ + logger_simple_h \ + logger_sup \ net \ net_adm \ net_kernel \ @@ -132,13 +143,14 @@ MODULES = \ HRL_FILES= ../include/file.hrl ../include/inet.hrl ../include/inet_sctp.hrl \ ../include/dist.hrl ../include/dist_util.hrl \ - ../include/net_address.hrl + ../include/net_address.hrl ../include/logger.hrl INTERNAL_HRL_FILES= application_master.hrl disk_log.hrl \ - erl_epmd.hrl hipe_ext_format.hrl \ + erl_epmd.hrl file_int.hrl hipe_ext_format.hrl \ inet_dns.hrl inet_res.hrl \ inet_boot.hrl inet_config.hrl inet_int.hrl \ - inet_dns_record_adts.hrl + inet_dns_record_adts.hrl \ + logger_internal.hrl logger_h_common.hrl ERL_FILES= $(MODULES:%=%.erl) @@ -223,7 +235,7 @@ release_docs_spec: # Include dependencies -- list below added by Kostis Sagonas -$(EBIN)/application_controller.beam: application_master.hrl +$(EBIN)/application_controller.beam: application_master.hrl ../include/logger.hrl $(EBIN)/application_master.beam: application_master.hrl $(EBIN)/auth.beam: ../include/file.hrl $(EBIN)/code.beam: ../include/file.hrl @@ -234,6 +246,7 @@ $(EBIN)/disk_log_server.beam: disk_log.hrl $(EBIN)/dist_util.beam: ../include/dist_util.hrl ../include/dist.hrl $(EBIN)/erl_boot_server.beam: inet_boot.hrl $(EBIN)/erl_epmd.beam: inet_int.hrl erl_epmd.hrl +$(EBIN)/error_logger.beam: logger_internal.hrl ../include/logger.hrl $(EBIN)/file.beam: ../include/file.hrl file_int.hrl $(EBIN)/file_io_server.beam: ../include/file.hrl file_int.hrl $(EBIN)/gen_tcp.beam: inet_int.hrl @@ -259,6 +272,16 @@ $(EBIN)/inet_udp.beam: inet_int.hrl $(EBIN)/inet_sctp.beam: inet_int.hrl ../include/inet_sctp.hrl $(EBIN)/local_udp.beam: inet_int.hrl $(EBIN)/local_tcp.beam: inet_int.hrl +$(EBIN)/logger.beam: logger_internal.hrl ../include/logger.hrl +$(EBIN)/logger_backend.beam: logger_internal.hrl ../include/logger.hrl +$(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_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 +$(EBIN)/logger_h_common.beam: logger_h_common.hrl logger_internal.hrl ../include/logger.hrl $(EBIN)/net_kernel.beam: ../include/net_address.hrl $(EBIN)/os.beam: ../include/file.hrl $(EBIN)/ram_file.beam: ../include/file.hrl diff --git a/lib/kernel/src/application_controller.erl b/lib/kernel/src/application_controller.erl index 3b642f5873..0dad6ae935 100644 --- a/lib/kernel/src/application_controller.erl +++ b/lib/kernel/src/application_controller.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1996-2017. All Rights Reserved. +%% Copyright Ericsson AB 1996-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. @@ -44,6 +44,7 @@ keyfind/3, keydelete/3, keyreplace/4]). -include("application_master.hrl"). +-include("logger.hrl"). -define(AC, ?MODULE). % Name of process @@ -1271,9 +1272,7 @@ load(S, {ApplData, ApplEnv, IncApps, Descr, Id, Vsn, Apps}) -> NewEnv = merge_app_env(ApplEnv, ConfEnv), CmdLineEnv = get_cmd_env(Name), NewEnv2 = merge_app_env(NewEnv, CmdLineEnv), - NewEnv3 = keyreplaceadd(included_applications, 1, NewEnv2, - {included_applications, IncApps}), - add_env(Name, NewEnv3), + add_env(Name, NewEnv2), Appl = #appl{name = Name, descr = Descr, id = Id, vsn = Vsn, appl_data = ApplData, inc_apps = IncApps, apps = Apps}, ets:insert(ac_tab, {{loaded, Name}, Appl}), @@ -1291,7 +1290,7 @@ load(S, {ApplData, ApplEnv, IncApps, Descr, Id, Vsn, Apps}) -> {ok, NewS}. unload(AppName, S) -> - {ok, IncApps} = get_env(AppName, included_applications), + {ok, IncApps} = get_key(AppName, included_applications), del_env(AppName), ets:delete(ac_tab, {loaded, AppName}), foldl(fun(App, S1) -> @@ -1546,9 +1545,8 @@ do_change_apps(Applications, Config, OldAppls) -> %% Report errors, but do not terminate %% (backwards compatible behaviour) lists:foreach(fun({error, {SysFName, Line, Str}}) -> - Str2 = lists:flatten(io_lib:format("~tp: ~w: ~ts~n", - [SysFName, Line, Str])), - error_logger:format(Str2, []) + ?LOG_ERROR("~tp: ~w: ~ts~n",[SysFName, Line, Str], + #{error_logger=>#{tag=>error}}) end, Errors), @@ -1583,13 +1581,9 @@ do_change_appl({ok, {ApplData, Env, IncApps, Descr, Id, Vsn, Apps}}, CmdLineEnv = get_cmd_env(AppName), NewEnv2 = merge_app_env(NewEnv1, CmdLineEnv), - %% included_apps is made into an env parameter as well - NewEnv3 = keyreplaceadd(included_applications, 1, NewEnv2, - {included_applications, IncApps}), - %% Update ets table with new application env del_env(AppName), - add_env(AppName, NewEnv3), + add_env(AppName, NewEnv2), OldAppl#appl{appl_data=ApplData, descr=Descr, @@ -1631,8 +1625,9 @@ make_term(Str) -> end. handle_make_term_error(Mod, Reason, Str) -> - error_logger:format("application_controller: ~ts: ~ts~n", - [Mod:format_error(Reason), Str]), + ?LOG_ERROR("application_controller: ~ts: ~ts~n", + [Mod:format_error(Reason), Str], + #{error_logger=>#{tag=>error}}), throw({error, {bad_environment_value, Str}}). get_env_i(Name, #state{conf_data = ConfData}) when is_list(ConfData) -> @@ -1913,19 +1908,25 @@ config_error() -> "configuration file must contain ONE list ended by <dot>"}}. %%----------------------------------------------------------------- -%% Info messages sent to error_logger +%% Info messages sent to logger %%----------------------------------------------------------------- info_started(Name, Node) -> - Rep = [{application, Name}, - {started_at, Node}], - error_logger:info_report(progress, Rep). + ?LOG_INFO(#{label=>{application_controller,progress}, + report=>[{application, Name}, + {started_at, Node}]}, + #{domain=>[otp,sasl], + report_cb=>fun logger:format_otp_report/1, + logger_formatter=>#{title=>"PROGRESS REPORT"}, + error_logger=>#{tag=>info_report,type=>progress}}). info_exited(Name, Reason, Type) -> - Rep = [{application, Name}, - {exited, Reason}, - {type, Type}], - error_logger:info_report(Rep). - + ?LOG_NOTICE(#{label=>{application_controller,exit}, + report=>[{application, Name}, + {exited, Reason}, + {type, Type}]}, + #{domain=>[otp], + report_cb=>fun logger:format_otp_report/1, + error_logger=>#{tag=>info_report,type=>std_info}}). %%----------------------------------------------------------------- %% Reply to all processes waiting this application to be started. @@ -2012,5 +2013,5 @@ to_string(Term) -> true -> Term; false -> - lists:flatten(io_lib:format("~134217728p", [Term])) + lists:flatten(io_lib:format("~0p", [Term])) end. diff --git a/lib/kernel/src/auth.erl b/lib/kernel/src/auth.erl index 40feee6bf0..a2116d8e8a 100644 --- a/lib/kernel/src/auth.erl +++ b/lib/kernel/src/auth.erl @@ -107,7 +107,7 @@ get_cookie() -> get_cookie(_Node) when node() =:= nonode@nohost -> nocookie; get_cookie(Node) -> - gen_server:call(auth, {get_cookie, Node}). + gen_server:call(auth, {get_cookie, Node}, infinity). -spec set_cookie(Cookie :: cookie()) -> 'true'. @@ -119,12 +119,12 @@ set_cookie(Cookie) -> set_cookie(_Node, _Cookie) when node() =:= nonode@nohost -> erlang:error(distribution_not_started); set_cookie(Node, Cookie) -> - gen_server:call(auth, {set_cookie, Node, Cookie}). + gen_server:call(auth, {set_cookie, Node, Cookie}, infinity). -spec sync_cookie() -> any(). sync_cookie() -> - gen_server:call(auth, sync_cookie). + gen_server:call(auth, sync_cookie, infinity). -spec print(Node :: node(), Format :: string(), Args :: [_]) -> 'ok'. diff --git a/lib/kernel/src/code.erl b/lib/kernel/src/code.erl index f143a49d2f..7faef93609 100644 --- a/lib/kernel/src/code.erl +++ b/lib/kernel/src/code.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1996-2017. All Rights Reserved. +%% Copyright Ericsson AB 1996-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. @@ -630,7 +630,7 @@ do_par_recv(N, Good, Bad) -> call(Req) -> code_server:call(Req). --spec start_link() -> {'ok', pid()} | {'error', 'crash'}. +-spec start_link() -> {'ok', pid()}. start_link() -> do_start(). diff --git a/lib/kernel/src/code_server.erl b/lib/kernel/src/code_server.erl index f5a890cb95..1a7677295b 100644 --- a/lib/kernel/src/code_server.erl +++ b/lib/kernel/src/code_server.erl @@ -1434,14 +1434,20 @@ all_loaded(Db) -> -spec error_msg(io:format(), [term()]) -> 'ok'. error_msg(Format, Args) -> - Msg = {notify,{error, group_leader(), {self(), Format, Args}}}, - error_logger ! Msg, + logger ! {log,error,Format,Args, + #{pid=>self(), + gl=>group_leader(), + time=>erlang:system_time(microsecond), + error_logger=>#{tag=>error}}}, ok. -spec info_msg(io:format(), [term()]) -> 'ok'. info_msg(Format, Args) -> - Msg = {notify,{info_msg, group_leader(), {self(), Format, Args}}}, - error_logger ! Msg, + logger ! {log,info,Format,Args, + #{pid=>self(), + gl=>group_leader(), + time=>erlang:system_time(microsecond), + error_logger=>#{tag=>info_msg}}}, ok. objfile_extension() -> diff --git a/lib/kernel/src/dist_util.erl b/lib/kernel/src/dist_util.erl index f7a84c14b4..ecc022b28d 100644 --- a/lib/kernel/src/dist_util.erl +++ b/lib/kernel/src/dist_util.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1999-2017. All Rights Reserved. +%% Copyright Ericsson AB 1999-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. @@ -30,6 +30,7 @@ strict_order_flags/0, start_timer/1, setup_timer/2, reset_timer/1, cancel_timer/1, + is_node_name/1, split_node/1, is_allowed/2, shutdown/3, shutdown/4]). -import(error_logger,[error_msg/2]). @@ -113,6 +114,8 @@ dflag2str(?DFLAG_BIG_CREATION) -> "BIG_CREATION"; dflag2str(?DFLAG_SEND_SENDER) -> "SEND_SENDER"; +dflag2str(?DFLAG_BIG_SEQTRACE_LABELS) -> + "BIG_SEQTRACE_LABELS"; dflag2str(_) -> "UNKNOWN". @@ -180,7 +183,6 @@ handshake_other_started(#hs_data{request_type=ReqType, reject_flags=RejFlgs, require_flags=ReqFlgs}, check_dflags(HSData, EDF), - is_allowed(HSData), ?debug({"MD5 connection from ~p (V~p)~n", [Node, HSData#hs_data.other_version]}), mark_pending(HSData), @@ -198,21 +200,6 @@ handshake_other_started(OldHsData) when element(1,OldHsData) =:= hs_data -> %% -%% check if connecting node is allowed to connect -%% with allow-node-scheme -%% -is_allowed(#hs_data{other_node = Node, - allowed = Allowed} = HSData) -> - case lists:member(Node, Allowed) of - false when Allowed =/= [] -> - send_status(HSData, not_allowed), - error_msg("** Connection attempt from " - "disallowed node ~w ** ~n", [Node]), - ?shutdown2(Node, {is_allowed, not_allowed}); - _ -> true - end. - -%% %% Check mandatory flags... %% check_dflags(#hs_data{other_node = Node, @@ -640,33 +627,130 @@ send_challenge_ack(#hs_data{socket = Socket, f_send = FSend}, %% tcp_drv.c which used it to detect simultaneous connection %% attempts). %% -recv_name(#hs_data{socket = Socket, f_recv = Recv}) -> +recv_name(#hs_data{socket = Socket, f_recv = Recv} = HSData) -> case Recv(Socket, 0, infinity) of - {ok,Data} -> - get_name(Data); + {ok, + [$n,VersionA, VersionB, Flag1, Flag2, Flag3, Flag4 + | OtherNode] = Data} -> + case is_node_name(OtherNode) of + true -> + Flags = ?u32(Flag1, Flag2, Flag3, Flag4), + Version = ?u16(VersionA,VersionB), + is_allowed(HSData, Flags, OtherNode, Version); + false -> + ?shutdown(Data) + end; _ -> ?shutdown(no_node) end. -get_name([$n,VersionA, VersionB, Flag1, Flag2, Flag3, Flag4 | OtherNode] = Data) -> - case is_valid_name(OtherNode) of +is_node_name(OtherNodeName) -> + case string:split(OtherNodeName, "@", all) of + [Name,Host] -> + (not string:is_empty(Name)) + andalso (not string:is_empty(Host)); + _ -> + false + end. + +split_node(Node) -> + Split = string:split(listify(Node), "@", all), + case Split of + [Name,Host] -> + case string:is_empty(Name) of + true -> + Split; + false -> + case string:is_empty(Host) of + true -> + {name,Name}; + false -> + {node,Name,Host} + end + end; + [Host] -> + case string:is_empty(Host) of + true -> + Split; + false -> + {host,Host} + end + end. + +%% Check if connecting node is allowed to connect +%% with allow-node-scheme. An empty allowed list +%% allows all nodes. +%% +is_allowed(#hs_data{allowed = []}, Flags, Node, Version) -> + {Flags,list_to_atom(Node),Version}; +is_allowed(#hs_data{allowed = Allowed} = HSData, Flags, Node, Version) -> + case is_allowed(Node, Allowed) of true -> - {?u32(Flag1, Flag2, Flag3, Flag4), list_to_atom(OtherNode), - ?u16(VersionA,VersionB)}; + {Flags,list_to_atom(Node),Version}; false -> - ?shutdown(Data) - end; -get_name(Data) -> - ?shutdown(Data). - -is_valid_name(OtherNodeName) -> - case string:lexemes(OtherNodeName,"@") of - [_OtherNodeName,_OtherNodeHost] -> - true; - _else -> - false + send_status(HSData#hs_data{other_node = Node}, not_allowed), + error_msg("** Connection attempt from " + "disallowed node ~s ** ~n", [Node]), + ?shutdown2(Node, {is_allowed, not_allowed}) + end. + +%% The allowed list can contain node names, host names +%% or names before '@', in atom or list form: +%% [[email protected], "host.example.org", "node@"]. +%% An empty allowed list allows no nodes. +%% +%% Allow a node that matches any entry in the allowed list. +%% Also allow allowed entries as node to match, not from +%% this module; here the node has to be a valid name. +%% +is_allowed(_Node, []) -> + false; +is_allowed(Node, [Node|_Allowed]) -> + %% Just an optimization + true; +is_allowed(Node, [AllowedNode|Allowed]) -> + case split_node(AllowedNode) of + {node,AllowedName,AllowedHost} -> + %% Allowed node name + case split_node(Node) of + {node,AllowedName,AllowedHost} -> + true; + _ -> + is_allowed(Node, Allowed) + end; + {host,AllowedHost} -> + %% Allowed host name + case split_node(Node) of + {node,_,AllowedHost} -> + %% Matching Host part + true; + {host,AllowedHost} -> + %% Host matches Host + true; + _ -> + is_allowed(Node, Allowed) + end; + {name,AllowedName} -> + %% Allowed name before '@' + case split_node(Node) of + {node,AllowedName,_} -> + %% Matching Name part + true; + {name,AllowedName} -> + %% Name matches Name + true; + _ -> + is_allowed(Node, Allowed) + end; + _ -> + is_allowed(Node, Allowed) end. +listify(Atom) when is_atom(Atom) -> + atom_to_list(Atom); +listify(Node) when is_list(Node) -> + Node. + publish_type(Flags) -> case Flags band ?DFLAG_PUBLISHED of 0 -> diff --git a/lib/kernel/src/erl_epmd.erl b/lib/kernel/src/erl_epmd.erl index f96bc88913..9a0939972d 100644 --- a/lib/kernel/src/erl_epmd.erl +++ b/lib/kernel/src/erl_epmd.erl @@ -29,10 +29,20 @@ -define(port_please_failure2(Term), noop). -endif. +-ifndef(erlang_daemon_port). +-define(erlang_daemon_port, 4369). +-endif. +-ifndef(epmd_dist_high). +-define(epmd_dist_high, 4370). +-endif. +-ifndef(epmd_dist_low). +-define(epmd_dist_low, 4370). +-endif. + %% External exports -export([start/0, start_link/0, stop/0, port_please/2, port_please/3, names/0, names/1, - register_node/2, register_node/3, open/0, open/1, open/2]). + register_node/2, register_node/3, address_please/3, open/0, open/1, open/2]). %% gen_server callbacks -export([init/1, handle_call/3, handle_cast/2, handle_info/2, @@ -53,7 +63,7 @@ start() -> gen_server:start({local, erl_epmd}, ?MODULE, [], []). - +-spec start_link() -> {ok, pid()} | ignore | {error,term()}. start_link() -> gen_server:start_link({local, erl_epmd}, ?MODULE, [], []). @@ -66,9 +76,22 @@ stop() -> %% return {port, P, Version} | noport %% +-spec port_please(Name, Host) -> {ok, Port, Version} | noport when + Name :: string(), + Host :: inet:ip_address(), + Port :: non_neg_integer(), + Version :: non_neg_integer(). + 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(), + Timeout :: non_neg_integer() | infinity, + Port :: non_neg_integer(), + Version :: non_neg_integer(). + port_please(Node,HostName, Timeout) when is_atom(HostName) -> port_please1(Node,atom_to_list(HostName), Timeout); port_please(Node,HostName, Timeout) when is_list(HostName) -> @@ -92,10 +115,21 @@ port_please1(Node,HostName, Timeout) -> Else end. +-spec names() -> {ok, [{Name, Port}]} | {error, Reason} when + Name :: string(), + Port :: non_neg_integer(), + Reason :: address | file:posix(). + names() -> {ok, H} = inet:gethostname(), names(H). +-spec names(Host) -> {ok, [{Name, Port}]} | {error, Reason} when + Host :: atom() | string() | inet:ip_address(), + Name :: string(), + Port :: non_neg_integer(), + Reason :: address | file:posix(). + names(HostName) when is_atom(HostName); is_list(HostName) -> case inet:gethostbyname(HostName) of {ok,{hostent, _Name, _ , _Af, _Size, [EpmdAddr | _]}} -> @@ -106,9 +140,22 @@ names(HostName) when is_atom(HostName); is_list(HostName) -> names(EpmdAddr) -> get_names(EpmdAddr). +-spec register_node(Name, Port) -> Result when + Name :: string(), + Port :: non_neg_integer(), + Creation :: non_neg_integer(), + Result :: {ok, Creation} | {error, already_registered} | term(). register_node(Name, PortNo) -> - register_node(Name, PortNo, inet). + register_node(Name, PortNo, inet). + +-spec register_node(Name, Port, Driver) -> Result when + Name :: string(), + Port :: non_neg_integer(), + Driver :: inet_tcp | inet6_tcp | inet | inet6, + Creation :: non_neg_integer(), + Result :: {ok, Creation} | {error, already_registered} | term(). + register_node(Name, PortNo, inet_tcp) -> register_node(Name, PortNo, inet); register_node(Name, PortNo, inet6_tcp) -> @@ -116,6 +163,17 @@ register_node(Name, PortNo, inet6_tcp) -> register_node(Name, PortNo, Family) -> gen_server:call(erl_epmd, {register, Name, PortNo, Family}, infinity). +-spec address_please(Name, Host, AddressFamily) -> Success | {error, term()} when + Name :: string(), + Host :: string() | inet:ip_address(), + AddressFamily :: inet | inet6, + Port :: non_neg_integer(), + Version :: non_neg_integer(), + Success :: {ok, inet:ip_address()} | {ok, inet:ip_address(), Port, Version}. + +address_please(_Name, Host, AddressFamily) -> + inet:getaddr(Host, AddressFamily). + %%%---------------------------------------------------------------------- %%% Callback functions from gen_server %%%---------------------------------------------------------------------- diff --git a/lib/kernel/src/erl_signal_handler.erl b/lib/kernel/src/erl_signal_handler.erl index 22f235d4e4..b76c2a217a 100644 --- a/lib/kernel/src/erl_signal_handler.erl +++ b/lib/kernel/src/erl_signal_handler.erl @@ -19,12 +19,21 @@ -module(erl_signal_handler). -behaviour(gen_event). --export([init/1, format_status/2, +-export([start/0, init/1, format_status/2, handle_event/2, handle_call/2, handle_info/2, terminate/2, code_change/3]). -record(state,{}). +start() -> + %% add signal handler + case whereis(erl_signal_server) of + %% in case of minimal mode + undefined -> ok; + _ -> + gen_event:add_handler(erl_signal_server, erl_signal_handler, []) + end. + init(_Args) -> {ok, #state{}}. diff --git a/lib/kernel/src/error_logger.erl b/lib/kernel/src/error_logger.erl index 585507c545..918a915729 100644 --- a/lib/kernel/src/error_logger.erl +++ b/lib/kernel/src/error_logger.erl @@ -19,22 +19,23 @@ %% -module(error_logger). --export([start/0,start_link/0,format/2,error_msg/1,error_msg/2,error_report/1, +-include("logger_internal.hrl"). + +-export([start/0,start_link/0,stop/0, + format/2,error_msg/1,error_msg/2,error_report/1, error_report/2,info_report/1,info_report/2,warning_report/1, warning_report/2,error_info/1, info_msg/1,info_msg/2,warning_msg/1,warning_msg/2, - logfile/1,tty/1,swap_handler/1, + logfile/1,tty/1, add_report_handler/1,add_report_handler/2, - delete_report_handler/1]). + delete_report_handler/1, + which_report_handlers/0]). --export([init/1, - handle_event/2, handle_call/2, handle_info/2, - terminate/2]). +%% logger callbacks +-export([adding_handler/1, removing_handler/1, log/2]). -export([get_format_depth/0, limit_term/1]). --define(buffer_size, 10). - %%----------------------------------------------------------------- %% Types used in this file %%----------------------------------------------------------------- @@ -43,8 +44,6 @@ | 'info' | 'info_msg' | 'info_report' | 'warning_msg' | 'warning_report'. --type state() :: {non_neg_integer(), non_neg_integer(), [term()]}. - %%% BIF -export([warning_map/0]). @@ -59,26 +58,146 @@ warning_map() -> %%----------------------------------------------------------------- --spec start() -> {'ok', pid()} | {'error', any()}. +%%%----------------------------------------------------------------- +%%% Start the event manager process under logger_sup, which is part of +%%% the kernel application's supervision tree. +-spec start() -> 'ok' | {'error', any()}. start() -> - case gen_event:start({local, error_logger}) of - {ok, Pid} -> - simple_logger(?buffer_size), - {ok, Pid}; - Error -> Error + case whereis(?MODULE) of + undefined -> + ErrorLogger = + #{id => ?MODULE, + start => {?MODULE, start_link, []}, + restart => transient, + shutdown => 2000, + type => worker, + modules => dynamic}, + case supervisor:start_child(logger_sup, ErrorLogger) of + {ok,_} -> + ok; + Error -> + Error + end; + _ -> + ok end. +%%%----------------------------------------------------------------- +%%% Start callback specified in child specification to supervisor, see start/0 -spec start_link() -> {'ok', pid()} | {'error', any()}. start_link() -> - case gen_event:start_link({local, error_logger}) of - {ok, Pid} -> - simple_logger(?buffer_size), - {ok, Pid}; - Error -> Error + gen_event:start_link({local, ?MODULE}, + [{spawn_opt,[{message_queue_data, off_heap}]}]). + +%%%----------------------------------------------------------------- +%%% Stop the event manager +-spec stop() -> ok. +stop() -> + _ = supervisor:terminate_child(logger_sup,?MODULE), + _ = supervisor:delete_child(logger_sup,?MODULE), + ok. + +%%%----------------------------------------------------------------- +%%% Callbacks for logger +-spec adding_handler(logger:handler_config()) -> + {ok,logger:handler_config()} | {error,term()}. +adding_handler(#{id:=?MODULE}=Config) -> + case start() of + ok -> + {ok,Config}; + Error -> + Error end. +-spec removing_handler(logger:handler_config()) -> ok. +removing_handler(#{id:=?MODULE}) -> + stop(), + ok. + +-spec log(logger:log_event(),logger:handler_config()) -> ok. +log(#{level:=Level,msg:=Msg,meta:=Meta},_Config) -> + do_log(Level,Msg,Meta). + +do_log(Level,{report,Msg},#{?MODULE:=#{tag:=Tag,type:=Type}}=Meta) -> + %% From error_logger:*_report/1,2, or logger call which added + %% error_logger data to obtain backwards compatibility with + %% error_logger:*_report/1,2 + Report = + case Msg of + #{label:=_,report:=R} -> R; + _ -> Msg + end, + notify(Level,Tag,Type,Report,Meta); +do_log(Level,{report,Msg},#{?MODULE:=#{tag:=Tag}}=Meta) -> + {Format,Args} = + case Msg of + #{label:=_,format:=F,args:=A} -> + %% From error_logger:*_msg/1,2. + %% In order to be backwards compatible with handling + %% of faulty parameters to error_logger:*_msg/1,2, + %% don't use report_cb here. + {F,A}; + _ -> + %% 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}]} + end + end, + notify(Level,Tag,Format,Args,Meta); +do_log(Level,{Format,Args},#{?MODULE:=#{tag:=Tag}}=Meta) + when is_list(Format), is_list(Args) -> + %% From logger call which added error_logger data to obtain + %% backwards compatibility with error_logger:*_msg/1,2 + notify(Level,Tag,Format,Args,Meta); +do_log(_Level,_Msg,_Meta) -> + %% Ignore the rest - i.e. to get backwards compatibility with + %% error_logger, you must use the error_logger API for logging. + %% Some modules within OTP go around this by adding an + %% error_logger field to its metadata. This is done only to allow + %% complete backwards compatibility for log events originating + %% from within OTP, while still using the new logger interface. + ok. + +-spec notify(logger:level(), msg_tag(), any(), any(), map()) -> 'ok'. +notify(Level,Tag0,FormatOrType0,ArgsOrReport,#{pid:=Pid0,gl:=GL,?MODULE:=My}) -> + {Tag,FormatOrType} = maybe_map_warnings(Level,Tag0,FormatOrType0), + Pid = case maps:get(emulator,My,false) of + true -> emulator; + _ -> Pid0 + end, + gen_event:notify(?MODULE,{Tag,GL,{Pid,FormatOrType,ArgsOrReport}}). + +%% For backwards compatibility with really old even handlers, check +%% the warning map and update tag and type. +maybe_map_warnings(warning,Tag,FormatOrType) -> + case error_logger:warning_map() of + warning -> + {Tag,FormatOrType}; + Level -> + {fix_warning_tag(Level,Tag),fix_warning_type(Level,FormatOrType)} + end; +maybe_map_warnings(_,Tag,FormatOrType) -> + {Tag,FormatOrType}. + +fix_warning_tag(error,warning_msg) -> error; +fix_warning_tag(error,warning_report) -> error_report; +fix_warning_tag(info,warning_msg) -> info_msg; +fix_warning_tag(info,warning_report) -> info_report; +fix_warning_tag(_,Tag) -> Tag. + +fix_warning_type(error,std_warning) -> std_error; +fix_warning_type(info,std_warning) -> std_info; +fix_warning_type(_,Type) -> Type. + %%----------------------------------------------------------------- %% These two simple old functions generate events tagged 'error' %% Used for simple messages; error or information. @@ -95,14 +214,18 @@ error_msg(Format) -> Data :: list(). error_msg(Format, Args) -> - notify({error, group_leader(), {self(), Format, Args}}). + logger:log(error, + #{label=>{?MODULE,error_msg}, + format=>Format, + args=>Args}, + meta(error)). -spec format(Format, Data) -> 'ok' when Format :: string(), Data :: list(). format(Format, Args) -> - notify({error, group_leader(), {self(), Format, Args}}). + error_msg(Format, Args). %%----------------------------------------------------------------- %% This functions should be used for error reports. Events @@ -124,7 +247,10 @@ error_report(Report) -> Report :: report(). error_report(Type, Report) -> - notify({error_report, group_leader(), {self(), Type, Report}}). + logger:log(error, + #{label=>{?MODULE,error_report}, + report=>Report}, + meta(error_report,Type)). %%----------------------------------------------------------------- %% This function should be used for warning reports. @@ -146,25 +272,10 @@ warning_report(Report) -> Report :: report(). warning_report(Type, Report) -> - {Tag, NType} = case error_logger:warning_map() of - info -> - if - Type =:= std_warning -> - {info_report, std_info}; - true -> - {info_report, Type} - end; - warning -> - {warning_report, Type}; - error -> - if - Type =:= std_warning -> - {error_report, std_error}; - true -> - {error_report, Type} - end - end, - notify({Tag, group_leader(), {self(), NType, Report}}). + logger:log(warning, + #{label=>{?MODULE,warning_report}, + report=>Report}, + meta(warning_report,Type)). %%----------------------------------------------------------------- %% This function provides similar functions as error_msg for @@ -183,15 +294,11 @@ warning_msg(Format) -> Data :: list(). warning_msg(Format, Args) -> - Tag = case error_logger:warning_map() of - warning -> - warning_msg; - info -> - info_msg; - error -> - error - end, - notify({Tag, group_leader(), {self(), Format, Args}}). + logger:log(warning, + #{label=>{?MODULE,warning_msg}, + format=>Format, + args=>Args}, + meta(warning_msg)). %%----------------------------------------------------------------- %% This function should be used for information reports. Events @@ -210,7 +317,10 @@ info_report(Report) -> Report :: report(). info_report(Type, Report) -> - notify({info_report, group_leader(), {self(), Type, Report}}). + logger:log(notice, + #{label=>{?MODULE,info_report}, + report=>Report}, + meta(info_report,Type)). %%----------------------------------------------------------------- %% This function provides similar functions as error_msg for @@ -228,7 +338,11 @@ info_msg(Format) -> Data :: list(). info_msg(Format, Args) -> - notify({info_msg, group_leader(), {self(), Format, Args}}). + logger:log(notice, + #{label=>{?MODULE,info_msg}, + format=>Format, + args=>Args}, + meta(info_msg)). %%----------------------------------------------------------------- %% Used by the init process. Events are tagged 'info'. @@ -236,38 +350,75 @@ info_msg(Format, Args) -> -spec error_info(Error :: any()) -> 'ok'. +%% unused? error_info(Error) -> - notify({info, group_leader(), {self(), Error, []}}). - --spec notify({msg_tag(), pid(), {pid(), any(), any()}}) -> 'ok'. - -notify(Msg) -> - gen_event:notify(error_logger, Msg). - --type swap_handler_type() :: 'false' | 'silent' | 'tty' | {'logfile', string()}. --spec swap_handler(Type :: swap_handler_type()) -> any(). - -swap_handler(tty) -> - R = gen_event:swap_handler(error_logger, {error_logger, swap}, - {error_logger_tty_h, []}), - ok = simple_logger(), - R; -swap_handler({logfile, File}) -> - R = gen_event:swap_handler(error_logger, {error_logger, swap}, - {error_logger_file_h, File}), - ok = simple_logger(), - R; -swap_handler(silent) -> - _ = gen_event:delete_handler(error_logger, error_logger, delete), - ok = simple_logger(); -swap_handler(false) -> - ok. % keep primitive event handler as-is + {Format,Args} = + case string_p(Error) of + true -> {Error,[]}; + false -> {"~p",[Error]} + end, + MyMeta = #{tag=>info,type=>Error}, + logger:log(notice, Format, Args, #{?MODULE=>MyMeta,domain=>[Error]}). + +%%----------------------------------------------------------------- +%% Create metadata +meta(Tag) -> + meta(Tag,undefined). +meta(Tag,Type) -> + meta(Tag,Type,#{report_cb=>fun report_to_format/1}). +meta(Tag,undefined,Meta0) -> + Meta0#{?MODULE=>#{tag=>Tag}}; +meta(Tag,Type,Meta0) -> + maybe_add_domain(Tag,Type,Meta0#{?MODULE=>#{tag=>Tag,type=>Type}}). + +%% This is to prevent events of non standard type from being printed +%% with the standard logger. Similar to how error_logger_tty_h +%% discards events of non standard type. +maybe_add_domain(error_report,std_error,Meta) -> Meta; +maybe_add_domain(info_report,std_info,Meta) -> Meta; +maybe_add_domain(warning_report,std_warning,Meta) -> Meta; +maybe_add_domain(_,Type,Meta) -> Meta#{domain=>[Type]}. + +%% ----------------------------------------------------------------- +%% Report formatting - i.e. Term => {Format,Args} +%% This was earlier done in the event handler (error_logger_tty_h, etc) +%% ----------------------------------------------------------------- +report_to_format(#{label:={?MODULE,_}, + report:=Report}) when is_map(Report) -> + %% logger:format_otp_report does maps:to_list, and for backwards + %% compatibility reasons we don't want that. + {"~tp\n",[Report]}; +report_to_format(#{label:={?MODULE,_}, + format:=Format, + args:=Args}) -> + %% This is not efficient, but needed for backwards compatibility + %% in giving faulty arguments to the *_msg functions. + try io_lib:scan_format(Format,Args) of + _ -> {Format,Args} + catch _:_ -> + {"ERROR: ~tp - ~tp",[Format,Args]} + end; +report_to_format(Term) -> + logger:format_otp_report(Term). + +string_p(List) when is_list(List) -> + string_p1(lists:flatten(List)); +string_p(_) -> + false. +string_p1([]) -> + false; +string_p1(FlatList) -> + io_lib:printable_list(FlatList). + +%% ----------------------------------------------------------------- +%% Stuff directly related to the event manager +%% ----------------------------------------------------------------- -spec add_report_handler(Handler) -> any() when Handler :: module(). add_report_handler(Module) when is_atom(Module) -> - gen_event:add_handler(error_logger, Module, []). + add_report_handler(Module, []). -spec add_report_handler(Handler, Args) -> Result when Handler :: module(), @@ -275,24 +426,37 @@ add_report_handler(Module) when is_atom(Module) -> Result :: gen_event:add_handler_ret(). add_report_handler(Module, Args) when is_atom(Module) -> - gen_event:add_handler(error_logger, Module, Args). + _ = logger:add_handler(?MODULE,?MODULE,#{level=>info,filter_default=>log}), + gen_event:add_handler(?MODULE, Module, Args). -spec delete_report_handler(Handler) -> Result when Handler :: module(), Result :: gen_event:del_handler_ret(). delete_report_handler(Module) when is_atom(Module) -> - gen_event:delete_handler(error_logger, Module, []). - -%% Start the lowest level error_logger handler with Buffer. - -simple_logger(Buffer_size) when is_integer(Buffer_size) -> - gen_event:add_handler(error_logger, error_logger, Buffer_size). - -%% Start the lowest level error_logger handler without Buffer. + case whereis(?MODULE) of + Pid when is_pid(Pid) -> + Return = gen_event:delete_handler(?MODULE, Module, []), + case gen_event:which_handlers(?MODULE) of + [] -> + %% Don't want a lot of logs here if it's not needed + _ = logger:remove_handler(?MODULE), + ok; + _ -> + ok + end, + Return; + _ -> + ok + end. -simple_logger() -> - gen_event:add_handler(error_logger, error_logger, []). +which_report_handlers() -> + case whereis(?MODULE) of + Pid when is_pid(Pid) -> + gen_event:which_handlers(?MODULE); + undefined -> + [] + end. %% Log all errors to File for all eternity @@ -308,26 +472,35 @@ simple_logger() -> FilenameReason :: no_log_file. logfile({open, File}) -> - case lists:member(error_logger_file_h, - gen_event:which_handlers(error_logger)) of + case lists:member(error_logger_file_h,which_report_handlers()) of true -> {error, allready_have_logfile}; _ -> - gen_event:add_handler(error_logger, error_logger_file_h, File) + add_report_handler(error_logger_file_h, File) end; logfile(close) -> - case gen_event:delete_handler(error_logger, error_logger_file_h, normal) of - {error,Reason} -> - {error,Reason}; - _ -> - ok + case whereis(?MODULE) of + Pid when is_pid(Pid) -> + case gen_event:delete_handler(?MODULE, error_logger_file_h, normal) of + {error,Reason} -> + {error,Reason}; + _ -> + ok + end; + _ -> + {error,module_not_found} end; logfile(filename) -> - case gen_event:call(error_logger, error_logger_file_h, filename) of - {error,_} -> - {error, no_log_file}; - Val -> - Val + case whereis(?MODULE) of + Pid when is_pid(Pid) -> + case gen_event:call(?MODULE, error_logger_file_h, filename) of + {error,_} -> + {error, no_log_file}; + Val -> + Val + end; + _ -> + {error, no_log_file} end. %% Possibly turn off all tty printouts, maybe we only want the errors @@ -337,194 +510,38 @@ logfile(filename) -> Flag :: boolean(). tty(true) -> - Hs = gen_event:which_handlers(error_logger), - case lists:member(error_logger_tty_h, Hs) of - false -> - gen_event:add_handler(error_logger, error_logger_tty_h, []); - true -> - ignore - end, + _ = case lists:member(error_logger_tty_h, which_report_handlers()) of + false -> + case logger:get_handler_config(default) of + {ok,#{module:=logger_std_h,config:=#{type:=standard_io}}} -> + logger:remove_handler_filter(default, + error_logger_tty_false); + _ -> + logger:add_handler(error_logger_tty_true,logger_std_h, + #{filter_default=>stop, + filters=>?DEFAULT_HANDLER_FILTERS( + [otp]), + formatter=>{?DEFAULT_FORMATTER, + ?DEFAULT_FORMAT_CONFIG}, + config=>#{type=>standard_io}}) + end; + true -> + ok + end, ok; tty(false) -> - gen_event:delete_handler(error_logger, error_logger_tty_h, []), + delete_report_handler(error_logger_tty_h), + _ = logger:remove_handler(error_logger_tty_true), + _ = case logger:get_handler_config(default) of + {ok,#{module:=logger_std_h,config:=#{type:=standard_io}}} -> + logger:add_handler_filter(default,error_logger_tty_false, + {fun(_,_) -> stop end, ok}); + _ -> + ok + end, ok. - -%%% --------------------------------------------------- -%%% This is the default error_logger handler. -%%% --------------------------------------------------- - --spec init(term()) -> {'ok', state() | []}. - -init(Max) when is_integer(Max) -> - {ok, {Max, 0, []}}; -%% This one is called if someone took over from us, and now wants to -%% go back. -init({go_back, _PostState}) -> - {ok, {?buffer_size, 0, []}}; -init(_) -> - %% The error logger process may receive a huge amount of - %% messages. Make sure that they are stored off heap to - %% avoid exessive GCs. - process_flag(message_queue_data, off_heap), - {ok, []}. - --spec handle_event(term(), state()) -> {'ok', state()}. - -handle_event({Type, GL, Msg}, State) when node(GL) =/= node() -> - gen_event:notify({error_logger, node(GL)},{Type, GL, Msg}), - %% handle_event2({Type, GL, Msg}, State); %% Shall we do something - {ok, State}; %% at this node too ??? -handle_event({info_report, _, {_, Type, _}}, State) when Type =/= std_info -> - {ok, State}; %% Ignore other info reports here -handle_event(Event, State) -> - handle_event2(Event, State). - --spec handle_info(term(), state()) -> {'ok', state()}. - -handle_info({emulator, GL, Chars}, State) when node(GL) =/= node() -> - {error_logger, node(GL)} ! {emulator, GL, add_node(Chars,self())}, - {ok, State}; -handle_info({emulator, GL, Chars}, State) -> - handle_event2({emulator, GL, Chars}, State); -handle_info(_, State) -> - {ok, State}. - --spec handle_call(term(), state()) -> {'ok', {'error', 'bad_query'}, state()}. - -handle_call(_Query, State) -> {ok, {error, bad_query}, State}. - --spec terminate(term(), state()) -> {'error_logger', [term()]}. - -terminate(swap, {_, 0, Buff}) -> - {error_logger, Buff}; -terminate(swap, {_, Lost, Buff}) -> - Myevent = {info, group_leader(), {self(), {lost_messages, Lost}, []}}, - {error_logger, [tag_event(Myevent)|Buff]}; -terminate(_, _) -> - {error_logger, []}. - -handle_event2(Event, {1, Lost, Buff}) -> - display(tag_event(Event)), - {ok, {1, Lost+1, Buff}}; -handle_event2(Event, {N, Lost, Buff}) -> - Tagged = tag_event(Event), - display(Tagged), - {ok, {N-1, Lost, [Tagged|Buff]}}; -handle_event2(_, State) -> - {ok, State}. - -tag_event(Event) -> - {erlang:localtime(), Event}. - -display({Tag,{error,_,{_,Format,Args}}}) -> - display2(Tag,Format,Args); -display({Tag,{error_report,_,{_,Type,Report}}}) -> - display2(Tag,Type,Report); -display({Tag,{info_report,_,{_,Type,Report}}}) -> - display2(Tag,Type,Report); -display({Tag,{info,_,{_,Error,_}}}) -> - display2(Tag,Error,[]); -display({Tag,{info_msg,_,{_,Format,Args}}}) -> - display2(Tag,Format,Args); -display({Tag,{warning_report,_,{_,Type,Report}}}) -> - display2(Tag,Type,Report); -display({Tag,{warning_msg,_,{_,Format,Args}}}) -> - display2(Tag,Format,Args); -display({Tag,{emulator,_,Chars}}) -> - display2(Tag,Chars,[]). - -add_node(X, Pid) when is_atom(X) -> - add_node(atom_to_list(X), Pid); -add_node(X, Pid) -> - lists:concat([X,"** at node ",node(Pid)," **~n"]). - -%% Can't do io_lib:format - -display2({{_Y,_Mo,_D},{_H,_Mi,_S}} = Date, F, A) -> - display_date(Date), - display3(string_p(F), F, A). - -display_date({{Y,Mo,D},{H,Mi,S}}) -> - erlang:display_string( - integer_to_list(Y) ++ "-" ++ - two_digits(Mo) ++ "-" ++ - two_digits(D) ++ " " ++ - two_digits(H) ++ ":" ++ - two_digits(Mi) ++ ":" ++ - two_digits(S) ++ " "). - -two_digits(N) when 0 =< N, N =< 9 -> - [$0, $0 + N]; -two_digits(N) -> - integer_to_list(N). - -display3(true, F, A) -> - %% Format string with arguments - erlang:display_string(F ++ "\n"), - [begin - erlang:display_string("\t"), - erlang:display(Arg) - end || Arg <- A], - ok; -display3(false, Atom, A) when is_atom(Atom) -> - %% The widest atom seems to be 'supervisor_report' at 17. - ColumnWidth = 20, - AtomString = atom_to_list(Atom), - AtomLength = length(AtomString), - Padding = lists:duplicate(ColumnWidth - AtomLength, $\s), - erlang:display_string(AtomString ++ Padding), - display4(A); -display3(_, F, A) -> - erlang:display({F, A}). - -display4([A, []]) -> - %% Not sure why crash reports look like this. - display4(A); -display4(A = [_|_]) -> - case lists:all(fun({Key,_Value}) -> is_atom(Key); (_) -> false end, A) of - true -> - erlang:display_string("\n"), - lists:foreach( - fun({Key, Value}) -> - erlang:display_string( - " " ++ - atom_to_list(Key) ++ - ": "), - erlang:display(Value) - end, A); - false -> - erlang:display(A) - end; -display4(A) -> - erlang:display(A). - -string_p([]) -> - false; -string_p(Term) -> - string_p1(Term). - -string_p1([H|T]) when is_integer(H), H >= $\040, H =< $\176 -> - string_p1(T); -string_p1([H|T]) when is_integer(H), H >= 16#A0, H < 16#D800; - is_integer(H), H > 16#DFFF, H < 16#FFFE; - is_integer(H), H > 16#FFFF, H =< 16#10FFFF -> - string_p1(T); -string_p1([$\n|T]) -> string_p1(T); -string_p1([$\r|T]) -> string_p1(T); -string_p1([$\t|T]) -> string_p1(T); -string_p1([$\v|T]) -> string_p1(T); -string_p1([$\b|T]) -> string_p1(T); -string_p1([$\f|T]) -> string_p1(T); -string_p1([$\e|T]) -> string_p1(T); -string_p1([H|T]) when is_list(H) -> - case string_p1(H) of - true -> string_p1(T); - _ -> false - end; -string_p1([]) -> true; -string_p1(_) -> false. - +%%%----------------------------------------------------------------- -spec limit_term(term()) -> term(). limit_term(Term) -> @@ -539,6 +556,8 @@ get_format_depth() -> case application:get_env(kernel, error_logger_format_depth) of {ok, Depth} when is_integer(Depth) -> max(10, Depth); + {ok, unlimited} -> + unlimited; undefined -> unlimited end. diff --git a/lib/kernel/src/erts_debug.erl b/lib/kernel/src/erts_debug.erl index 6f248626ca..1270de4144 100644 --- a/lib/kernel/src/erts_debug.erl +++ b/lib/kernel/src/erts_debug.erl @@ -35,7 +35,8 @@ flat_size/1, get_internal_state/1, instructions/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]). + lcnt_control/1, lcnt_control/2, lcnt_collect/0, lcnt_clear/0, + lc_graph/0, lc_graph_to_dot/2, lc_graph_merge/2]). -spec breakpoint(MFA, Flag) -> non_neg_integer() when MFA :: {Module :: module(), @@ -407,3 +408,90 @@ cont_dis(_, {_,_,_}, _) -> ok. map_info(_) -> erlang:nif_error(undef). + +%% Create file "lc_graph.<pid>" with all actual lock dependencies +%% recorded so far by the VM. +%% Needs debug VM or --enable-lock-checking config, returns 'notsup' otherwise. +lc_graph() -> + erts_debug:set_internal_state(available_internal_state, true), + erts_debug:get_internal_state(lc_graph). + +%% Convert "lc_graph.<pid>" file to https://www.graphviz.org dot format. +lc_graph_to_dot(OutFile, InFile) -> + {ok, [LL0]} = file:consult(InFile), + + [{"NO LOCK",0} | LL] = LL0, + Map = maps:from_list([{Id, Name} || {Name, Id, _, _} <- LL]), + + case file:open(OutFile, [exclusive]) of + {ok, Out} -> + ok = file:write(Out, "digraph G {\n"), + + [dot_print_lock(Out, Lck, Map) || Lck <- LL], + + ok = file:write(Out, "}\n"), + ok = file:close(Out); + + {error,eexist} -> + {"File already exists", OutFile} + end. + +dot_print_lock(Out, {_Name, Id, Lst, _}, Map) -> + [dot_print_edge(Out, From, Id, Map) || From <- Lst], + ok. + +dot_print_edge(_, 0, _, _) -> + ignore; % "NO LOCK" +dot_print_edge(Out, From, To, Map) -> + io:format(Out, "~p -> ~p;\n", [maps:get(From,Map), maps:get(To,Map)]). + + +%% Merge several "lc_graph" files into one file. +lc_graph_merge(OutFile, InFiles) -> + LLs = lists:map(fun(InFile) -> + {ok, [LL]} = file:consult(InFile), + LL + end, + InFiles), + + Res = lists:foldl(fun(A, B) -> lcg_merge(A, B) end, + hd(LLs), + tl(LLs)), + case file:open(OutFile, [exclusive]) of + {ok, Out} -> + try + lcg_print(Out, Res) + after + file:close(Out) + end, + ok; + {error, eexist} -> + {"File already exists", OutFile} + end. + +lcg_merge(A, B) -> + lists:zipwith(fun(LA, LB) -> lcg_merge_locks(LA, LB) end, + A, B). + +lcg_merge_locks(L, L) -> + L; +lcg_merge_locks({Name, Id, DA, IA}, {Name, Id, DB, IB}) -> + Direct = lists:umerge(DA, DB), + Indirect = lists:umerge(IA, IB), + {Name, Id, Direct, Indirect -- Direct}. + + +lcg_print(Out, LL) -> + io:format(Out, "[", []), + lcg_print_locks(Out, LL), + io:format(Out, "].\n", []), + ok. + +lcg_print_locks(Out, [{_,_}=NoLock | Rest]) -> + io:format(Out, "~p,\n", [NoLock]), + lcg_print_locks(Out, Rest); +lcg_print_locks(Out, [LastLock]) -> + io:format(Out, "~w", [LastLock]); +lcg_print_locks(Out, [Lock | Rest]) -> + io:format(Out, "~w,\n", [Lock]), + lcg_print_locks(Out, Rest). diff --git a/lib/kernel/src/file.erl b/lib/kernel/src/file.erl index c2df1ee288..1d4e37196c 100644 --- a/lib/kernel/src/file.erl +++ b/lib/kernel/src/file.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1996-2017. All Rights Reserved. +%% Copyright Ericsson AB 1996-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. @@ -69,7 +69,7 @@ %% Types that can be used from other modules -- alphabetically ordered. -export_type([date_time/0, fd/0, file_info/0, filename/0, filename_all/0, - io_device/0, name/0, name_all/0, posix/0]). + io_device/0, mode/0, name/0, name_all/0, posix/0]). %%% Includes and defines -include("file_int.hrl"). @@ -101,14 +101,25 @@ -type deep_list() :: [char() | atom() | deep_list()]. -type name() :: string() | atom() | deep_list(). -type name_all() :: string() | atom() | deep_list() | (RawFilename :: binary()). --type posix() :: 'eacces' | 'eagain' | 'ebadf' | 'ebusy' | 'edquot' - | 'eexist' | 'efault' | 'efbig' | 'eintr' | 'einval' - | 'eio' | 'eisdir' | 'eloop' | 'emfile' | 'emlink' - | 'enametoolong' - | 'enfile' | 'enodev' | 'enoent' | 'enomem' | 'enospc' - | 'enotblk' | 'enotdir' | 'enotsup' | 'enxio' | 'eperm' - | 'epipe' | 'erofs' | 'espipe' | 'esrch' | 'estale' - | 'exdev'. +-type posix() :: + 'eacces' | 'eagain' | + 'ebadf' | 'ebadmsg' | 'ebusy' | + 'edeadlk' | 'edeadlock' | 'edquot' | + 'eexist' | + 'efault' | 'efbig' | 'eftype' | + 'eintr' | 'einval' | 'eio' | 'eisdir' | + 'eloop' | + 'emfile' | 'emlink' | 'emultihop' | + 'enametoolong' | 'enfile' | + 'enobufs' | 'enodev' | 'enolck' | 'enolink' | 'enoent' | + 'enomem' | 'enospc' | 'enosr' | 'enostr' | 'enosys' | + 'enotblk' | 'enotdir' | 'enotsup' | 'enxio' | + 'eopnotsupp' | 'eoverflow' | + 'eperm' | 'epipe' | + 'erange' | 'erofs' | + 'espipe' | 'esrch' | 'estale' | + 'etxtbsy' | + 'exdev'. -type date_time() :: calendar:datetime(). -type posix_file_advise() :: 'normal' | 'sequential' | 'random' | 'no_reuse' | 'will_need' | 'dont_need'. diff --git a/lib/kernel/src/file_server.erl b/lib/kernel/src/file_server.erl index ecc1ffbdd6..29eaa23375 100644 --- a/lib/kernel/src/file_server.erl +++ b/lib/kernel/src/file_server.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2000-2017. All Rights Reserved. +%% Copyright Ericsson AB 2000-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. @@ -73,7 +73,7 @@ stop() -> %% {stop, Reason} %%---------------------------------------------------------------------- --spec init([]) -> {'ok', state()} | {'stop', term()}. +-spec init([]) -> {'ok', state()}. init([]) -> process_flag(trap_exit, true), @@ -225,7 +225,7 @@ handle_cast(Msg, State) -> %%---------------------------------------------------------------------- -spec handle_info(term(), state()) -> - {'noreply', state()} | {'stop', 'normal', state()}. + {'noreply', state()}. handle_info({'EXIT', Pid, _Reason}, State) when is_pid(Pid) -> ets:delete(?FILE_IO_SERVER_TABLE, Pid), diff --git a/lib/kernel/src/gen_sctp.erl b/lib/kernel/src/gen_sctp.erl index a6aa0edd15..3526df3600 100644 --- a/lib/kernel/src/gen_sctp.erl +++ b/lib/kernel/src/gen_sctp.erl @@ -118,6 +118,8 @@ open() -> | inet:address_family() | {port,Port} | {type,SockType} + | {netns, file:filename_all()} + | {bind_to_device, binary()} | option(), IP :: inet:ip_address() | any | loopback, Port :: inet:port_number(), diff --git a/lib/kernel/src/gen_tcp.erl b/lib/kernel/src/gen_tcp.erl index ac61dbc792..253c63528f 100644 --- a/lib/kernel/src/gen_tcp.erl +++ b/lib/kernel/src/gen_tcp.erl @@ -102,6 +102,8 @@ inet:address_family() | {port, inet:port_number()} | {tcp_module, module()} | + {netns, file:filename_all()} | + {bind_to_device, binary()} | option(). -type listen_option() :: {ip, inet:socket_address()} | @@ -111,6 +113,8 @@ {port, inet:port_number()} | {backlog, B :: non_neg_integer()} | {tcp_module, module()} | + {netns, file:filename_all()} | + {bind_to_device, binary()} | option(). -type socket() :: port(). diff --git a/lib/kernel/src/gen_udp.erl b/lib/kernel/src/gen_udp.erl index 3121544719..9ab58011ec 100644 --- a/lib/kernel/src/gen_udp.erl +++ b/lib/kernel/src/gen_udp.erl @@ -97,6 +97,8 @@ open(Port) -> | {ifaddr, inet:socket_address()} | inet:address_family() | {port, inet:port_number()} + | {netns, file:filename_all()} + | {bind_to_device, binary()} | option(), Socket :: socket(), Reason :: inet:posix(). diff --git a/lib/kernel/src/hipe_unified_loader.erl b/lib/kernel/src/hipe_unified_loader.erl index fd06f0f7d8..5704cc79c2 100644 --- a/lib/kernel/src/hipe_unified_loader.erl +++ b/lib/kernel/src/hipe_unified_loader.erl @@ -453,7 +453,7 @@ make_beam_stub(Mod, LoaderState, MD5, Beam, FunDefs, ClosuresToPatch) -> %%======================================================================== %% Patching %% @spec patch(refs(), BaseAddress::integer(), ConstAndZone::term(), -%% FunDefs::term(), TrampolineMap::term()) -> 'ok'. +%% FunDefs::term(), TrampolineMap::term()) -> 'ok' %% @type refs()=[{RefType::integer(), Reflist::reflist()} | refs()] %% %% @type reflist()= [{Data::term(), Offsets::offests()}|reflist()] diff --git a/lib/kernel/src/inet.erl b/lib/kernel/src/inet.erl index 4bad523dff..73c53b9011 100644 --- a/lib/kernel/src/inet.erl +++ b/lib/kernel/src/inet.erl @@ -105,7 +105,20 @@ {local, binary()} | {unspec, <<>>} | {undefined, any()}. --type posix() :: exbadport | exbadseq | file:posix(). +-type posix() :: + 'eaddrinuse' | 'eaddrnotavail' | 'eafnosupport' | 'ealready' | + 'econnaborted' | 'econnrefused' | 'econnreset' | + 'edestaddrreq' | + 'ehostdown' | 'ehostunreach' | + 'einprogress' | 'eisconn' | + 'emsgsize' | + 'enetdown' | 'enetunreach' | + 'enopkg' | 'enoprotoopt' | 'enotconn' | 'enotty' | 'enotsock' | + 'eproto' | 'eprotonosupport' | 'eprototype' | + 'esocktnosupport' | + 'etimedout' | + 'ewouldblock' | + 'exbadport' | 'exbadseq' | file:posix(). -type socket() :: port(). -type socket_setopt() :: diff --git a/lib/kernel/src/inet_tcp_dist.erl b/lib/kernel/src/inet_tcp_dist.erl index e3fdb1bb22..b4b50899f7 100644 --- a/lib/kernel/src/inet_tcp_dist.erl +++ b/lib/kernel/src/inet_tcp_dist.erl @@ -283,73 +283,22 @@ do_setup(Driver, Kernel, Node, Type, MyNode, LongOrShortNames, SetupTime) -> ?trace("~p~n",[{inet_tcp_dist,self(),setup,Node}]), [Name, Address] = splitnode(Driver, Node, LongOrShortNames), AddressFamily = Driver:family(), - case inet:getaddr(Address, AddressFamily) of + ErlEpmd = net_kernel:epmd_module(), + {ARMod, ARFun} = get_address_resolver(ErlEpmd), + Timer = dist_util:start_timer(SetupTime), + case ARMod:ARFun(Name, Address, AddressFamily) of + {ok, Ip, TcpPort, Version} -> + ?trace("address_please(~p) -> version ~p~n", + [Node,Version]), + do_setup_connect(Driver, Kernel, Node, Address, AddressFamily, + Ip, TcpPort, Version, Type, MyNode, Timer); {ok, Ip} -> - Timer = dist_util:start_timer(SetupTime), - ErlEpmd = net_kernel:epmd_module(), case ErlEpmd:port_please(Name, Ip) of {port, TcpPort, Version} -> ?trace("port_please(~p) -> version ~p~n", [Node,Version]), - dist_util:reset_timer(Timer), - case - Driver:connect( - Ip, TcpPort, - connect_options([{active, false}, {packet, 2}])) - of - {ok, Socket} -> - HSData = #hs_data{ - kernel_pid = Kernel, - other_node = Node, - this_node = MyNode, - socket = Socket, - timer = Timer, - this_flags = 0, - other_version = Version, - f_send = fun Driver:send/2, - f_recv = fun Driver:recv/3, - f_setopts_pre_nodeup = - fun(S) -> - inet:setopts - (S, - [{active, false}, - {packet, 4}, - nodelay()]) - end, - f_setopts_post_nodeup = - fun(S) -> - inet:setopts - (S, - [{active, true}, - {deliver, port}, - {packet, 4}, - nodelay()]) - end, - - f_getll = fun inet:getll/1, - f_address = - fun(_,_) -> - #net_address{ - address = {Ip,TcpPort}, - host = Address, - protocol = tcp, - family = AddressFamily} - end, - mf_tick = fun(S) -> ?MODULE:tick(Driver, S) end, - mf_getstat = fun ?MODULE:getstat/1, - request_type = Type, - mf_setopts = fun ?MODULE:setopts/2, - mf_getopts = fun ?MODULE:getopts/2 - }, - dist_util:handshake_we_started(HSData); - _ -> - %% Other Node may have closed since - %% port_please ! - ?trace("other node (~p) " - "closed since port_please.~n", - [Node]), - ?shutdown(Node) - end; + do_setup_connect(Driver, Kernel, Node, Address, AddressFamily, + Ip, TcpPort, Version, Type, MyNode, Timer); _ -> ?trace("port_please (~p) " "failed.~n", [Node]), @@ -361,6 +310,71 @@ do_setup(Driver, Kernel, Node, Type, MyNode, LongOrShortNames, SetupTime) -> ?shutdown(Node) end. +%% +%% Actual setup of connection +%% +do_setup_connect(Driver, Kernel, Node, Address, AddressFamily, + Ip, TcpPort, Version, Type, MyNode, Timer) -> + dist_util:reset_timer(Timer), + case + Driver:connect( + Ip, TcpPort, + connect_options([{active, false}, {packet, 2}])) + of + {ok, Socket} -> + HSData = #hs_data{ + kernel_pid = Kernel, + other_node = Node, + this_node = MyNode, + socket = Socket, + timer = Timer, + this_flags = 0, + other_version = Version, + f_send = fun Driver:send/2, + f_recv = fun Driver:recv/3, + f_setopts_pre_nodeup = + fun(S) -> + inet:setopts + (S, + [{active, false}, + {packet, 4}, + nodelay()]) + end, + f_setopts_post_nodeup = + fun(S) -> + inet:setopts + (S, + [{active, true}, + {deliver, port}, + {packet, 4}, + nodelay()]) + end, + + f_getll = fun inet:getll/1, + f_address = + fun(_,_) -> + #net_address{ + address = {Ip,TcpPort}, + host = Address, + protocol = tcp, + family = AddressFamily} + end, + mf_tick = fun(S) -> ?MODULE:tick(Driver, S) end, + mf_getstat = fun ?MODULE:getstat/1, + request_type = Type, + mf_setopts = fun ?MODULE:setopts/2, + mf_getopts = fun ?MODULE:getopts/2 + }, + dist_util:handshake_we_started(HSData); + _ -> + %% Other Node may have closed since + %% discovery ! + ?trace("other node (~p) " + "closed since discovery (port_please).~n", + [Node]), + ?shutdown(Node) + end. + connect_options(Opts) -> case application:get_env(kernel, inet_dist_connect_options) of {ok,ConnectOpts} -> @@ -430,6 +444,16 @@ get_tcp_address(Driver, Socket) -> }. %% ------------------------------------------------------------ +%% Determine if EPMD module supports address resolving. Default +%% is to use inet:getaddr/2. +%% ------------------------------------------------------------ +get_address_resolver(EpmdModule) -> + case erlang:function_exported(EpmdModule, address_please, 3) of + true -> {EpmdModule, address_please}; + _ -> {inet, getaddr} + end. + +%% ------------------------------------------------------------ %% Do only accept new connection attempts from nodes at our %% own LAN, if the check_ip environment parameter is true. %% ------------------------------------------------------------ diff --git a/lib/kernel/src/kernel.app.src b/lib/kernel/src/kernel.app.src index 82a3571da9..390f1fa42a 100644 --- a/lib/kernel/src/kernel.app.src +++ b/lib/kernel/src/kernel.app.src @@ -60,6 +60,17 @@ kernel_refc, local_tcp, local_udp, + logger, + logger_backend, + logger_config, + logger_disk_log_h, + logger_filters, + logger_formatter, + logger_h_common, + logger_server, + logger_simple_h, + logger_std_h, + logger_sup, net, net_adm, net_kernel, @@ -117,6 +128,8 @@ kernel_config, kernel_refc, kernel_sup, + logger, + logger_sup, net_kernel, net_sup, rex, @@ -127,7 +140,9 @@ inet_db, pg2]}, {applications, []}, - {env, [{error_logger, tty}]}, + {env, [{logger_level, notice}, + {logger_sasl_compatible, false} + ]}, {mod, {kernel, []}}, {runtime_dependencies, ["erts-10.0", "stdlib-3.5", "sasl-3.0"]} ] diff --git a/lib/kernel/src/kernel.appup.src b/lib/kernel/src/kernel.appup.src index 4ee497bbbd..305a1c788c 100644 --- a/lib/kernel/src/kernel.appup.src +++ b/lib/kernel/src/kernel.appup.src @@ -18,9 +18,11 @@ %% %CopyrightEnd% {"%VSN%", %% Up from - max one major revision back - [{<<"5\\.[0-3](\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-19.*, OTP-20.0 - {<<"5\\.4(\\.[0-9]+)*">>,[restart_new_emulator]}], % OTP-20.1+ + [{<<"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\\.[0-3](\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-19.*, OTP-20.0 - {<<"5\\.4(\\.[0-9]+)*">>,[restart_new_emulator]}] % OTP-20.1+ + [{<<"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 }. diff --git a/lib/kernel/src/kernel.erl b/lib/kernel/src/kernel.erl index 0382764b39..b0e8c00bbf 100644 --- a/lib/kernel/src/kernel.erl +++ b/lib/kernel/src/kernel.erl @@ -30,24 +30,13 @@ %%% Callback functions for the kernel application. %%%----------------------------------------------------------------- start(_, []) -> + %% Setup the logger and configure the kernel logger environment + ok = logger:internal_init_logger(), case supervisor:start_link({local, kernel_sup}, kernel, []) of {ok, Pid} -> - %% add signal handler - case whereis(erl_signal_server) of - %% in case of minimal mode - undefined -> ok; - _ -> - ok = gen_event:add_handler(erl_signal_server, erl_signal_handler, []) - end, - %% add error handler - Type = get_error_logger_type(), - case error_logger:swap_handler(Type) of - ok -> {ok, Pid, []}; - Error -> - %% Not necessary since the node will crash anyway: - exit(Pid, shutdown), - Error - end; + ok = erl_signal_handler:start(), + ok = logger:add_handlers(kernel), + {ok, Pid, []}; Error -> Error end. @@ -62,16 +51,6 @@ config_change(Changed, New, Removed) -> do_global_groups_change(Changed, New, Removed), ok. -get_error_logger_type() -> - case application:get_env(kernel, error_logger) of - {ok, tty} -> tty; - {ok, {file, File}} when is_list(File) -> {logfile, File}; - {ok, false} -> false; - {ok, silent} -> silent; - undefined -> tty; % default value - {ok, Bad} -> exit({bad_config, {kernel, {error_logger, Bad}}}) - end. - %%%----------------------------------------------------------------- %%% The process structure in kernel is as shown in the figure. %%% @@ -153,9 +132,18 @@ init([]) -> type => supervisor, modules => [?MODULE]}, + + LoggerSup = #{id => logger_sup, + start => {logger_sup, start_link, []}, + restart => permanent, + shutdown => infinity, + type => supervisor, + modules => [logger_sup]}, + case init:get_argument(mode) of {ok, [["minimal"]]} -> - {ok, {SupFlags, [Code, File, StdError, User, Config, RefC, SafeSup]}}; + {ok, {SupFlags, + [Code, File, StdError, User, LoggerSup, Config, RefC, SafeSup]}}; _ -> Rpc = #{id => rex, start => {rpc, start_link, []}, @@ -206,7 +194,7 @@ init([]) -> {ok, {SupFlags, [Code, Rpc, Global, InetDb | DistAC] ++ [NetSup, GlGroup, File, SigSrv, - StdError, User, Config, RefC, SafeSup] ++ Timer}} + StdError, User, Config, RefC, SafeSup, LoggerSup] ++ Timer}} end; init(safe) -> SupFlags = #{strategy => one_for_one, diff --git a/lib/kernel/src/kernel_config.erl b/lib/kernel/src/kernel_config.erl index 535083ef27..c5ff1887c2 100644 --- a/lib/kernel/src/kernel_config.erl +++ b/lib/kernel/src/kernel_config.erl @@ -30,11 +30,8 @@ %%%----------------------------------------------------------------- %%% This module implements a process that configures the kernel %%% application. -%%% Its purpose is that in the init phase add an error_logger -%%% and when it dies (when the kernel application dies) deleting the -%%% previously installed error_logger. -%%% Also, this process waits for other nodes at startup, if -%%% specified. +%%% Its purpose is that in the init phase waits for other nodes at startup, +%%% if specified. %%%----------------------------------------------------------------- start_link() -> gen_server:start_link(kernel_config, [], []). diff --git a/lib/kernel/src/kernel_refc.erl b/lib/kernel/src/kernel_refc.erl index 05076dc885..8e04ff99d8 100644 --- a/lib/kernel/src/kernel_refc.erl +++ b/lib/kernel/src/kernel_refc.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2017. All Rights Reserved. +%% 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. @@ -44,7 +44,7 @@ scheduler_wall_time(Bool) -> %% Callback functions from gen_server %%----------------------------------------------------------------- --spec init([]) -> {'ok', map()} | {'stop', term()}. +-spec init([]) -> {'ok', map()}. init([]) -> resource(scheduler_wall_time, false), diff --git a/lib/kernel/src/logger.erl b/lib/kernel/src/logger.erl new file mode 100644 index 0000000000..7d121f22fe --- /dev/null +++ b/lib/kernel/src/logger.erl @@ -0,0 +1,841 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2017. 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). + +%% Log interface +-export([emergency/1,emergency/2,emergency/3, + alert/1,alert/2,alert/3, + critical/1,critical/2,critical/3, + error/1,error/2,error/3, + warning/1,warning/2,warning/3, + notice/1,notice/2,notice/3, + info/1,info/2,info/3, + debug/1,debug/2,debug/3]). +-export([log/2,log/3,log/4]). + +%% Called by macro +-export([allow/2,macro_log/3,macro_log/4,macro_log/5,add_default_metadata/1]). + +%% Configuration +-export([add_handler/3, remove_handler/1, + add_primary_filter/2, add_handler_filter/3, + remove_primary_filter/1, remove_handler_filter/2, + set_module_level/2, + unset_module_level/1, unset_module_level/0, + 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, + 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, + add_handlers/1]). + +%% Private configuration +-export([internal_init_logger/0]). + +%% Misc +-export([compare_levels/2]). +-export([set_process_metadata/1, update_process_metadata/1, + unset_process_metadata/0, get_process_metadata/0]). + +%% Basic report formatting +-export([format_report/1, format_otp_report/1]). + +-export([internal_log/2,filter_stacktrace/2]). + +-include("logger_internal.hrl"). +-include("logger.hrl"). + +%%%----------------------------------------------------------------- +%%% Types +-type log_event() :: #{level:=level(), + msg:={io:format(),[term()]} | + {report,report()} | + {string,unicode:chardata()}, + meta:=metadata()}. +-type level() :: emergency | alert | critical | error | + warning | notice | info | debug. +-type report() :: map() | [{atom(),term()}]. +-type msg_fun() :: fun((term()) -> {io:format(),[term()]} | + report() | + unicode:chardata()). +-type metadata() :: #{pid => pid(), + gl => pid(), + time => timestamp(), + mfa => {module(),atom(),non_neg_integer()}, + file => file:filename(), + line => non_neg_integer(), + domain => [atom()], + report_cb => fun((report()) -> {io:format(),[term()]}), + atom() => term()}. +-type location() :: #{mfa := {module(),atom(),non_neg_integer()}, + file := file:filename(), + line := non_neg_integer()}. +-type handler_id() :: atom(). +-type filter_id() :: atom(). +-type filter() :: {fun((log_event(),filter_arg()) -> + filter_return()),filter_arg()}. +-type filter_arg() :: term(). +-type filter_return() :: stop | ignore | log_event(). +-type primary_config() :: #{level => level() | all | none, + filter_default => log | stop, + filters => [{filter_id(),filter()}]}. +-type handler_config() :: #{id => handler_id(), + config => term(), + level => level() | all | none, + module => module(), + filter_default => log | stop, + filters => [{filter_id(),filter()}], + formatter => {module(),formatter_config()}}. +-type timestamp() :: integer(). +-type formatter_config() :: #{atom() => term()}. + +-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]). + +%%%----------------------------------------------------------------- +%%% API +emergency(X) -> + log(emergency,X). +emergency(X,Y) -> + log(emergency,X,Y). +emergency(X,Y,Z) -> + log(emergency,X,Y,Z). + +alert(X) -> + log(alert,X). +alert(X,Y) -> + log(alert,X,Y). +alert(X,Y,Z) -> + log(alert,X,Y,Z). + +critical(X) -> + log(critical,X). +critical(X,Y) -> + log(critical,X,Y). +critical(X,Y,Z) -> + log(critical,X,Y,Z). + +error(X) -> + log(error,X). +error(X,Y) -> + log(error,X,Y). +error(X,Y,Z) -> + log(error,X,Y,Z). + +warning(X) -> + log(warning,X). +warning(X,Y) -> + log(warning,X,Y). +warning(X,Y,Z) -> + log(warning,X,Y,Z). + +notice(X) -> + log(notice,X). +notice(X,Y) -> + log(notice,X,Y). +notice(X,Y,Z) -> + log(notice,X,Y,Z). + +info(X) -> + log(info,X). +info(X,Y) -> + log(info,X,Y). +info(X,Y,Z) -> + log(info,X,Y,Z). + +debug(X) -> + log(debug,X). +debug(X,Y) -> + log(debug,X,Y). +debug(X,Y,Z) -> + log(debug,X,Y,Z). + +-spec log(Level,StringOrReport) -> ok when + Level :: level(), + StringOrReport :: unicode:chardata() | report(). +log(Level, StringOrReport) -> + do_log(Level,StringOrReport,#{}). + +-spec log(Level,StringOrReport,Metadata) -> ok when + Level :: level(), + StringOrReport :: unicode:chardata() | report(), + Metadata :: metadata(); + (Level,Format,Args) -> ok when + Level :: level(), + Format :: io:format(), + Args ::[term()]; + (Level,Fun,FunArgs) -> ok when + Level :: level(), + Fun :: msg_fun(), + FunArgs :: term(). +log(Level, StringOrReport, Metadata) + when is_map(Metadata), not is_function(StringOrReport) -> + do_log(Level,StringOrReport,Metadata); +log(Level, FunOrFormat, Args) -> + do_log(Level,{FunOrFormat,Args},#{}). + +-spec log(Level,Format, Args, Metadata) -> ok when + Level :: level(), + Format :: io:format(), + Args :: [term()], + Metadata :: metadata(); + (Level,Fun,FunArgs,Metadata) -> ok when + Level :: level(), + Fun :: msg_fun(), + FunArgs :: term(), + Metadata :: metadata(). +log(Level, FunOrFormat, Args, Metadata) -> + do_log(Level,{FunOrFormat,Args},Metadata). + +-spec allow(Level,Module) -> boolean() when + Level :: level(), + Module :: module(). +allow(Level,Module) when ?IS_LEVEL(Level), is_atom(Module) -> + logger_config:allow(?LOGGER_TABLE,Level,Module). + + +-spec macro_log(Location,Level,StringOrReport) -> ok when + Location :: location(), + Level :: level(), + StringOrReport :: unicode:chardata() | report(). +macro_log(Location,Level,StringOrReport) -> + log_allowed(Location,Level,StringOrReport,#{}). + +-spec macro_log(Location,Level,StringOrReport,Meta) -> ok when + Location :: location(), + Level :: level(), + StringOrReport :: unicode:chardata() | report(), + Meta :: metadata(); + (Location,Level,Format,Args) -> ok when + Location :: location(), + Level :: level(), + Format :: io:format(), + Args ::[term()]; + (Location,Level,Fun,FunArgs) -> ok when + Location :: location(), + Level :: level(), + Fun :: msg_fun(), + FunArgs :: term(). +macro_log(Location,Level,StringOrReport,Meta) + when is_map(Meta), not is_function(StringOrReport) -> + log_allowed(Location,Level,StringOrReport,Meta); +macro_log(Location,Level,FunOrFormat,Args) -> + log_allowed(Location,Level,{FunOrFormat,Args},#{}). + +-spec macro_log(Location,Level,Format,Args,Meta) -> ok when + Location :: location(), + Level :: level(), + Format :: io:format(), + Args ::[term()], + Meta :: metadata(); + (Location,Level,Fun,FunArgs,Meta) -> ok when + Location :: location(), + Level :: level(), + Fun :: msg_fun(), + FunArgs :: term(), + Meta :: metadata(). +macro_log(Location,Level,FunOrFormat,Args,Meta) -> + log_allowed(Location,Level,{FunOrFormat,Args},Meta). + +-spec format_otp_report(Report) -> FormatArgs when + Report :: report(), + FormatArgs :: {io:format(),[term()]}. +format_otp_report(#{label:=_,report:=Report}) -> + format_report(Report); +format_otp_report(Report) -> + format_report(Report). + +-spec format_report(Report) -> FormatArgs when + Report :: report(), + FormatArgs :: {io:format(),[term()]}. +format_report(Report) when is_map(Report) -> + format_report(maps:to_list(Report)); +format_report(Report) when is_list(Report) -> + case lists:flatten(Report) of + [] -> + {"~tp",[[]]}; + FlatList -> + case string_p1(FlatList) of + true -> + {"~ts",[FlatList]}; + false -> + format_term_list(Report,[],[]) + end + end; +format_report(Report) -> + {"~tp",[Report]}. + +format_term_list([{Tag,Data}|T],Format,Args) -> + PorS = case string_p(Data) of + true -> "s"; + false -> "p" + end, + format_term_list(T,[" ~tp: ~t"++PorS|Format],[Data,Tag|Args]); +format_term_list([Data|T],Format,Args) -> + format_term_list(T,[" ~tp"|Format],[Data|Args]); +format_term_list([],Format,Args) -> + {lists:flatten(lists:join($\n,lists:reverse(Format))),lists:reverse(Args)}. + +string_p(List) when is_list(List) -> + string_p1(lists:flatten(List)); +string_p(_) -> + false. + +string_p1([]) -> + false; +string_p1(FlatList) -> + io_lib:printable_unicode_list(FlatList). + +internal_log(Level,Term) when is_atom(Level) -> + erlang:display_string("Logger - "++ atom_to_list(Level) ++ ": "), + erlang:display(Term). + +%%%----------------------------------------------------------------- +%%% Configuration +-spec add_primary_filter(FilterId,Filter) -> ok | {error,term()} when + FilterId :: filter_id(), + Filter :: filter(). +add_primary_filter(FilterId,Filter) -> + logger_server:add_filter(primary,{FilterId,Filter}). + +-spec add_handler_filter(HandlerId,FilterId,Filter) -> ok | {error,term()} when + HandlerId :: handler_id(), + FilterId :: filter_id(), + Filter :: filter(). +add_handler_filter(HandlerId,FilterId,Filter) -> + logger_server:add_filter(HandlerId,{FilterId,Filter}). + + +-spec remove_primary_filter(FilterId) -> ok | {error,term()} when + FilterId :: filter_id(). +remove_primary_filter(FilterId) -> + logger_server:remove_filter(primary,FilterId). + +-spec remove_handler_filter(HandlerId,FilterId) -> ok | {error,term()} when + HandlerId :: handler_id(), + FilterId :: filter_id(). +remove_handler_filter(HandlerId,FilterId) -> + logger_server:remove_filter(HandlerId,FilterId). + +-spec add_handler(HandlerId,Module,Config) -> ok | {error,term()} when + HandlerId :: handler_id(), + Module :: module(), + Config :: handler_config(). +add_handler(HandlerId,Module,Config) -> + logger_server:add_handler(HandlerId,Module,Config). + +-spec remove_handler(HandlerId) -> ok | {error,term()} when + HandlerId :: handler_id(). +remove_handler(HandlerId) -> + logger_server:remove_handler(HandlerId). + +-spec set_primary_config(Key,Value) -> ok | {error,term()} when + Key :: atom(), + Value :: term(). +set_primary_config(Key,Value) -> + logger_server:set_config(primary,Key,Value). + +-spec set_primary_config(Config) -> ok | {error,term()} when + Config :: primary_config(). +set_primary_config(Config) -> + logger_server:set_config(primary,Config). + +-spec set_handler_config(HandlerId,Key,Value) -> ok | {error,term()} when + HandlerId :: handler_id(), + Key :: atom(), + Value :: term(). +set_handler_config(HandlerId,Key,Value) -> + logger_server:set_config(HandlerId,Key,Value). + +-spec set_handler_config(HandlerId,Config) -> ok | {error,term()} when + HandlerId :: handler_id(), + Config :: handler_config(). +set_handler_config(HandlerId,Config) -> + logger_server:set_config(HandlerId,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,Config) -> ok | {error,term()} when + HandlerId :: handler_id(), + Config :: handler_config(). +update_handler_config(HandlerId,Config) -> + logger_server:update_config(HandlerId,Config). + +-spec get_primary_config() -> Config when + Config :: primary_config(). +get_primary_config() -> + {ok,Config} = logger_config:get(?LOGGER_TABLE,primary), + maps:remove(handlers,Config). + +-spec get_handler_config(HandlerId) -> {ok,Config} | {error,term()} when + HandlerId :: handler_id(), + Config :: handler_config(). +get_handler_config(HandlerId) -> + case logger_config:get(?LOGGER_TABLE,HandlerId) of + {ok,{_,Config}} -> + {ok,Config}; + Error -> + Error + end. + +-spec get_handler_config() -> [Config] when + Config :: handler_config(). +get_handler_config() -> + [begin + {ok,Config} = get_handler_config(HandlerId), + Config + end || HandlerId <- get_handler_ids()]. + +-spec get_handler_ids() -> [HandlerId] when + HandlerId :: handler_id(). +get_handler_ids() -> + {ok,#{handlers:=HandlerIds}} = logger_config:get(?LOGGER_TABLE,primary), + HandlerIds. + +-spec update_formatter_config(HandlerId,FormatterConfig) -> + ok | {error,term()} when + HandlerId :: handler_id(), + FormatterConfig :: formatter_config(). +update_formatter_config(HandlerId,FormatterConfig) -> + logger_server:update_formatter_config(HandlerId,FormatterConfig). + +-spec update_formatter_config(HandlerId,Key,Value) -> + ok | {error,term()} when + HandlerId :: handler_id(), + Key :: atom(), + Value :: term(). +update_formatter_config(HandlerId,Key,Value) -> + logger_server:update_formatter_config(HandlerId,#{Key=>Value}). + +-spec set_module_level(Modules,Level) -> ok | {error,term()} when + Modules :: [module()] | module(), + Level :: level() | all | none. +set_module_level(Module,Level) when is_atom(Module) -> + set_module_level([Module],Level); +set_module_level(Modules,Level) -> + logger_server:set_module_level(Modules,Level). + +-spec unset_module_level(Modules) -> ok when + Modules :: [module()] | module(). +unset_module_level(Module) when is_atom(Module) -> + unset_module_level([Module]); +unset_module_level(Modules) -> + logger_server:unset_module_level(Modules). + +-spec unset_module_level() -> ok. +unset_module_level() -> + logger_server:unset_module_level(). + +-spec get_module_level(Modules) -> [{Module,Level}] when + Modules :: [Module] | Module, + Module :: module(), + Level :: level() | all | none. +get_module_level(Module) when is_atom(Module) -> + get_module_level([Module]); +get_module_level(Modules) when is_list(Modules) -> + [{M,L} || {M,L} <- get_module_level(), + lists:member(M,Modules)]. + +-spec get_module_level() -> [{Module,Level}] when + Module :: module(), + Level :: level() | all | none. +get_module_level() -> + logger_config:get_module_level(?LOGGER_TABLE). + +%%%----------------------------------------------------------------- +%%% Misc +-spec compare_levels(Level1,Level2) -> eq | gt | lt when + Level1 :: level(), + Level2 :: level(). +compare_levels(Level,Level) when ?IS_LEVEL(Level) -> + eq; +compare_levels(Level1,Level2) when ?IS_LEVEL(Level1), ?IS_LEVEL(Level2) -> + Int1 = logger_config:level_to_int(Level1), + Int2 = logger_config:level_to_int(Level2), + if Int1 < Int2 -> gt; + true -> lt + end; +compare_levels(Level1,Level2) -> + erlang:error(badarg,[Level1,Level2]). + +-spec set_process_metadata(Meta) -> ok when + Meta :: metadata(). +set_process_metadata(Meta) when is_map(Meta) -> + _ = put(?LOGGER_META_KEY,Meta), + ok; +set_process_metadata(Meta) -> + erlang:error(badarg,[Meta]). + +-spec update_process_metadata(Meta) -> ok when + Meta :: metadata(). +update_process_metadata(Meta) when is_map(Meta) -> + case get_process_metadata() of + undefined -> + set_process_metadata(Meta); + Meta0 when is_map(Meta0) -> + set_process_metadata(maps:merge(Meta0,Meta)), + ok + end; +update_process_metadata(Meta) -> + erlang:error(badarg,[Meta]). + +-spec get_process_metadata() -> Meta | undefined when + Meta :: metadata(). +get_process_metadata() -> + get(?LOGGER_META_KEY). + +-spec unset_process_metadata() -> ok. +unset_process_metadata() -> + _ = erase(?LOGGER_META_KEY), + ok. + +-spec get_config() -> #{primary=>primary_config(), + handlers=>[handler_config()], + module_levels=>[{module(),level() | all | none}]}. +get_config() -> + #{primary=>get_primary_config(), + handlers=>get_handler_config(), + module_levels=>lists:keysort(1,get_module_level())}. + +-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 +%% logger settings to take effect before the kernel supervisor +%% tree is started. +internal_init_logger() -> + try + ok = logger:set_primary_config(level, get_logger_level()), + ok = logger:set_primary_config(filter_default, get_primary_filter_default()), + + [case logger:add_primary_filter(Id, Filter) of + ok -> ok; + {error, Reason} -> throw(Reason) + end || {Id, Filter} <- get_primary_filters()], + + _ = [[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_handler_config(simple,filters, + get_default_handler_filters()) of + ok -> ok; + {error,{not_found,simple}} -> ok + end, + + init_kernel_handlers() + catch throw:Reason -> + ?LOG_ERROR("Invalid logger config: ~p", [Reason]), + {error, {bad_config, {kernel, Reason}}} + end. + +-spec init_kernel_handlers() -> 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() -> + try + case get_logger_type() of + {ok,silent} -> + ok = logger:remove_handler(simple); + {ok,false} -> + ok; + {ok,Type} -> + init_default_config(Type) + end + catch throw:Reason -> + ?LOG_ERROR("Invalid default handler config: ~p", [Reason]), + {error, {bad_config, {kernel, Reason}}} + end. + +-spec add_handlers(Application) -> ok | {error,term()} when + Application :: atom(); + (HandlerConfig) -> ok | {error,term()} when + HandlerConfig :: [config_handler()]. +%% 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(App) when is_atom(App) -> + add_handlers(application:get_env(App, logger, [])); +add_handlers(HandlerConfig) -> + try + check_logger_config(HandlerConfig), + DefaultAdded = + lists:foldl( + fun({handler, default = Id, Module, Config}, _) + when not is_map_key(filters, Config) -> + %% The default handler should have a couple of extra filters + %% set on it by default. + DefConfig = #{ filter_default => stop, + filters => get_default_handler_filters()}, + setup_handler(Id, Module, maps:merge(DefConfig,Config)), + true; + ({handler, Id, Module, Config}, Default) -> + setup_handler(Id, Module, Config), + Default orelse Id == 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], + ok + catch throw:Reason -> + ?LOG_ERROR("Invalid logger handler config: ~p", [Reason]), + {error, {bad_config, {handler, Reason}}} + end. + +setup_handler(Id, Module, Config) -> + case logger:add_handler(Id, Module, Config) of + ok -> ok; + {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() -> + 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 + true -> + {ok, false}; + false -> + {ok, standard_io} % default value + end; + {ok, Bad} -> + throw({error_logger, Bad}) + end. + +get_logger_level() -> + case application:get_env(kernel,logger_level,info) of + Level when ?IS_LEVEL(Level) -> + Level; + Level -> + throw({logger_level, Level}) + end. + +get_primary_filter_default() -> + case lists:keyfind(filters,1,get_logger_env()) of + {filters,Default,_} -> + Default; + false -> + log + end. + +get_primary_filters() -> + lists:foldl( + fun({filters, _, Filters}, _Acc) -> + Filters; + (_, Acc) -> + Acc + end, [], get_logger_env()). + +%% 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(), + 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); + _ -> + %% 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}). + +get_default_handler_filters() -> + case application:get_env(kernel, logger_sasl_compatible, false) of + true -> + ?DEFAULT_HANDLER_FILTERS([otp]); + false -> + ?DEFAULT_HANDLER_FILTERS([otp,sasl]) + end. + +get_logger_env() -> + application:get_env(kernel, logger, []). + +%%%----------------------------------------------------------------- +%%% Internal +do_log(Level,Msg,#{mfa:={Module,_,_}}=Meta) -> + case logger_config:allow(?LOGGER_TABLE,Level,Module) of + true -> + log_allowed(#{},Level,Msg,Meta); + false -> + ok + end; +do_log(Level,Msg,Meta) -> + case logger_config:allow(?LOGGER_TABLE,Level) of + true -> + log_allowed(#{},Level,Msg,Meta); + false -> + ok + end. + +-spec log_allowed(Location,Level,Msg,Meta) -> ok when + Location :: location() | #{}, + Level :: level(), + Msg :: {msg_fun(),term()} | + {io:format(),[term()]} | + report() | + unicode:chardata(), + Meta :: metadata(). +log_allowed(Location,Level,{Fun,FunArgs},Meta) when is_function(Fun,1) -> + try Fun(FunArgs) of + Msg={Format,Args} when is_list(Format), is_list(Args) -> + log_allowed(Location,Level,Msg,Meta); + Report when ?IS_REPORT(Report) -> + log_allowed(Location,Level,Report,Meta); + String when ?IS_STRING(String) -> + log_allowed(Location,Level,String,Meta); + Other -> + log_allowed(Location,Level, + {"LAZY_FUN ERROR: ~tp; Returned: ~tp", + [{Fun,FunArgs},Other]}, + Meta) + catch C:R -> + log_allowed(Location,Level, + {"LAZY_FUN CRASH: ~tp; Reason: ~tp", + [{Fun,FunArgs},{C,R}]}, + Meta) + end; +log_allowed(Location,Level,Msg,Meta0) when is_map(Meta0) -> + %% Metadata priorities are: + %% Location (added in API macros) - will be overwritten by process + %% metadata (set by set_process_metadata/1), which in turn will be + %% overwritten by the metadata given as argument in the log call + %% (function or macro). + Meta = add_default_metadata( + 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); + _ -> + do_log_allowed(Level,Msg,Meta) + end. + +do_log_allowed(Level,{Format,Args}=Msg,Meta) + 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) + 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) + when ?IS_LEVEL(Level), + ?IS_STRING(String), + is_map(Meta) -> + logger_backend:log_allowed(#{level=>Level,msg=>{string,String},meta=>Meta}, + tid()). +tid() -> + ets:whereis(?LOGGER_TABLE). + +log_remote(Node,Level,{Format,Args},Meta) -> + log_remote(Node,{log,Level,Format,Args,Meta}); +log_remote(Node,Level,Msg,Meta) -> + log_remote(Node,{log,Level,Msg,Meta}). + +log_remote(Node,Request) -> + {logger,Node} ! Request, + ok. + +add_default_metadata(Meta) -> + add_default_metadata([pid,gl,time],Meta). + +add_default_metadata([Key|Keys],Meta) -> + case maps:is_key(Key,Meta) of + true -> + add_default_metadata(Keys,Meta); + false -> + add_default_metadata(Keys,Meta#{Key=>default(Key)}) + end; +add_default_metadata([],Meta) -> + Meta. + +proc_meta() -> + case get_process_metadata() of + ProcMeta when is_map(ProcMeta) -> ProcMeta; + _ -> #{} + end. + +default(pid) -> self(); +default(gl) -> group_leader(); +default(time) -> erlang:system_time(microsecond). + +%% Remove everything upto and including this module from the stacktrace +filter_stacktrace(Module,[{Module,_,_,_}|_]) -> + []; +filter_stacktrace(Module,[H|T]) -> + [H|filter_stacktrace(Module,T)]; +filter_stacktrace(_,[]) -> + []. diff --git a/lib/kernel/src/logger_backend.erl b/lib/kernel/src/logger_backend.erl new file mode 100644 index 0000000000..a73b681e0d --- /dev/null +++ b/lib/kernel/src/logger_backend.erl @@ -0,0 +1,133 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2017. 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_backend). + +-export([log_allowed/2]). + +-include("logger_internal.hrl"). + +-define(OWN_KEYS,[level,filters,filter_default,handlers]). + +%%%----------------------------------------------------------------- +%%% The default logger backend +log_allowed(Log, Tid) -> + {ok,Config} = logger_config:get(Tid,primary), + Filters = maps:get(filters,Config,[]), + case apply_filters(primary,Log,Filters,Config) of + stop -> + ok; + Log1 -> + Handlers = maps:get(handlers,Config,[]), + call_handlers(Log1,Handlers,Tid) + end, + ok. + +call_handlers(#{level:=Level}=Log,[Id|Handlers],Tid) -> + case logger_config:get(Tid,Id,Level) of + {ok,{Module,Config}} -> + Filters = maps:get(filters,Config,[]), + case apply_filters(Id,Log,Filters,Config) of + stop -> + ok; + Log1 -> + Config1 = maps:without(?OWN_KEYS,Config), + try Module:log(Log1,Config1) + catch C:R:S -> + case logger:remove_handler(Id) of + ok -> + logger:internal_log( + error,{removed_failing_handler,Id}), + ?LOG_INTERNAL( + debug, + [{logger,removed_failing_handler}, + {handler,{Id,Module}}, + {log_event,Log1}, + {config,Config1}, + {reason,{C,R,filter_stacktrace(S)}}]); + {error,{not_found,_}} -> + %% Probably already removed by other client + %% Don't report again + ok; + {error,Reason} -> + ?LOG_INTERNAL( + debug, + [{logger,remove_handler_failed}, + {reason,Reason}]) + end + end + end; + _ -> + ok + end, + call_handlers(Log,Handlers,Tid); +call_handlers(_Log,[],_Tid) -> + ok. + +apply_filters(Owner,Log,Filters,Config) -> + case do_apply_filters(Owner,Log,Filters,ignore) of + stop -> + stop; + ignore -> + case maps:get(filter_default,Config) of + log -> + Log; + stop -> + stop + end; + Log1 -> + Log1 + end. + +do_apply_filters(Owner,Log,[{_Id,{FilterFun,FilterArgs}}=Filter|Filters],State) -> + try FilterFun(Log,FilterArgs) of + stop -> + stop; + ignore -> + do_apply_filters(Owner,Log,Filters,State); + Log1=#{level:=Level,msg:=Msg,meta:=Meta} + when is_atom(Level), ?IS_MSG(Msg), is_map(Meta) -> + do_apply_filters(Owner,Log1,Filters,log); + Bad -> + handle_filter_failed(Filter,Owner,Log,{bad_return_value,Bad}) + catch C:R:S -> + handle_filter_failed(Filter,Owner,Log,{C,R,filter_stacktrace(S)}) + end; +do_apply_filters(_Owner,_Log,[],ignore) -> + ignore; +do_apply_filters(_Owner,Log,[],log) -> + Log. + +handle_filter_failed({Id,_}=Filter,Owner,Log,Reason) -> + case logger_server:remove_filter(Owner,Id) of + ok -> + logger:internal_log(error,{removed_failing_filter,Id}), + ?LOG_INTERNAL(debug, + [{logger,removed_failing_filter}, + {filter,Filter}, + {owner,Owner}, + {log_event,Log}, + {reason,Reason}]); + _ -> + ok + end, + ignore. + +filter_stacktrace(Stacktrace) -> + logger:filter_stacktrace(?MODULE,Stacktrace). diff --git a/lib/kernel/src/logger_config.erl b/lib/kernel/src/logger_config.erl new file mode 100644 index 0000000000..7b2148d034 --- /dev/null +++ b/lib/kernel/src/logger_config.erl @@ -0,0 +1,165 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2017. 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_config). + +-export([new/1,delete/2, + exist/2, + allow/2,allow/3, + get/2, get/3, get/1, + create/3, create/4, set/3, + set_module_level/3,unset_module_level/2, + get_module_level/1,cache_module_level/2, + level_to_int/1]). + +-include("logger_internal.hrl"). + +new(Name) -> + _ = ets:new(Name,[set,protected,named_table,{write_concurrency,true}]), + ets:whereis(Name). + +delete(Tid,Id) -> + ets:delete(Tid,table_key(Id)). + +allow(Tid,Level,Module) -> + LevelInt = level_to_int(Level), + case ets:lookup(Tid,Module) of + [{Module,{ModLevel,cached}}] when is_integer(ModLevel), + LevelInt =< ModLevel -> + true; + [{Module,ModLevel}] when is_integer(ModLevel), + LevelInt =< ModLevel -> + true; + [] -> + logger_server:cache_module_level(Module), + allow(Tid,Level); + _ -> + false + end. + +allow(Tid,Level) -> + GlobalLevelInt = ets:lookup_element(Tid,?PRIMARY_KEY,2), + level_to_int(Level) =< GlobalLevelInt. + +exist(Tid,What) -> + ets:member(Tid,table_key(What)). + +get(Tid,What) -> + case ets:lookup(Tid,table_key(What)) of + [{_,_,Config}] -> + {ok,Config}; + [{_,_,Config,Module}] -> + {ok,{Module,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 + [{'>=','$1',level_to_int(Level)}], + [{{'$3','$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,What,Config) -> + LevelInt = level_to_int(maps:get(level,Config)), + ets:insert(Tid,{table_key(What),LevelInt,Config}). + +set(Tid,What,Config) -> + LevelInt = level_to_int(maps:get(level,Config)), + %% Should do this only if the level has actually changed. Possibly + %% overwrite instead of delete? + case What of + primary -> + _ = ets:select_delete(Tid,[{{'_',{'$1',cached}}, + [{'=/=','$1',LevelInt}], + [true]}]), + ok; + _ -> + ok + end, + ets:update_element(Tid,table_key(What),[{2,LevelInt},{3,Config}]), + ok. + +set_module_level(Tid,Modules,Level) -> + LevelInt = level_to_int(Level), + [ets:insert(Tid,{Module,LevelInt}) || Module <- Modules], + ok. + +%% should possibly overwrite instead of delete? +unset_module_level(Tid,all) -> + MS = [{{'$1','$2'},[{is_atom,'$1'},{is_integer,'$2'}],[true]}], + _ = ets:select_delete(Tid,MS), + ok; +unset_module_level(Tid,Modules) -> + [ets:delete(Tid,Module) || Module <- Modules], + ok. + +get_module_level(Tid) -> + MS = [{{'$1','$2'},[{is_atom,'$1'},{is_integer,'$2'}],[{{'$1','$2'}}]}], + Modules = ets:select(Tid,MS), + lists:sort([{M,int_to_level(L)} || {M,L} <- Modules]). + +cache_module_level(Tid,Module) -> + GlobalLevelInt = ets:lookup_element(Tid,?PRIMARY_KEY,2), + 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; +level_to_int(critical) -> ?CRITICAL; +level_to_int(error) -> ?ERROR; +level_to_int(warning) -> ?WARNING; +level_to_int(notice) -> ?NOTICE; +level_to_int(info) -> ?INFO; +level_to_int(debug) -> ?DEBUG; +level_to_int(all) -> ?LOG_ALL. + +int_to_level(?LOG_NONE) -> none; +int_to_level(?EMERGENCY) -> emergency; +int_to_level(?ALERT) -> alert; +int_to_level(?CRITICAL) -> critical; +int_to_level(?ERROR) -> error; +int_to_level(?WARNING) -> warning; +int_to_level(?NOTICE) -> notice; +int_to_level(?INFO) -> info; +int_to_level(?DEBUG) -> debug; +int_to_level(?LOG_ALL) -> all. + +%%%----------------------------------------------------------------- +%%% Internal + +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 new file mode 100644 index 0000000000..a074d0210e --- /dev/null +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -0,0 +1,717 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2017. 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_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, sync/1, reset/1]). + +%% gen_server callbacks +-export([init/1, handle_call/3, handle_cast/2, handle_info/2, + terminate/2, code_change/3]). + +%% logger callbacks +-export([log/2, adding_handler/1, removing_handler/1, changing_config/2]). + +%% handler internal +-export([log_handler_info/4]). + +%%%=================================================================== +%%% 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 sync(Name) -> ok | {error,Reason} when + Name :: atom(), + Reason :: handler_busy | {badarg,term()}. + +sync(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; +sync(Name) -> + {error,{badarg,{sync,[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 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; + 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 + end. + +check_config(adding, #{id:=Name}=Config) -> + %% merge handler specific config data + HConfig = merge_default_logopts(Name, maps:get(config, Config, #{})), + 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. + +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]) -> + check_h_config(Config); +check_h_config([{max_no_files,N}|Config]) when is_integer(N), N>0 -> + check_h_config(Config); +check_h_config([{max_no_bytes,infinity}|Config]) -> + check_h_config(Config); +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([]) -> + ok. + +%%%----------------------------------------------------------------- +%%% Handler being removed +removing_handler(#{id:=Name}) -> + stop(Name). + +%%%----------------------------------------------------------------- +%%% Log a string or report +-spec log(LogEvent, Config) -> ok | dropped 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). + +%%%=================================================================== +%%% gen_server callbacks +%%%=================================================================== + +init([Name, + Config = #{config := HConfig = #{file:=File, + type:=Type, + max_no_bytes:=MNB, + max_no_files:=MNF}}, + State = #{dl_sync_int := DLSyncInt}]) -> + + register(?name_to_reg_name(?MODULE,Name), 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 -> + logger_h_common:error_notify({open_disk_log,Name,Error}), + proc_lib:init_ack(Error) + end; + Error -> + 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}. + +%% 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)), + _ = close_disk_log(Name, normal), + logger_h_common:stop_or_restart(Name, Reason, State). + +code_change(_OldVsn, State, _Extra) -> + {ok, State}. + +%%%----------------------------------------------------------------- +%%% 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 -> + Size = + if Type == halt -> MaxNoBytes; + Type == wrap -> {MaxNoBytes,MaxNoFiles} + end, + Opts = [{name, Name}, + {file, File}, + {size, Size}, + {type, Type}, + {linkto, self()}, + {repair, false}, + {format, external}, + {notify, true}, + {quiet, true}, + {mode, read_write}], + case disk_log:open(Opts) of + {ok,Name} -> + ok; + Error = {error,_Reason} -> + Error + end; + Error -> + Error + end. + +close_disk_log(Name, _) -> + _ = ?disk_log_sync(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,sync, + LogOpts, + SyncError}) + end, + State#{prev_sync_result => SyncError} + end. + +error_notify_new(Info,Info, _Term) -> + ok; +error_notify_new(_Info0,_Info1, Term) -> + logger_h_common:error_notify(Term). diff --git a/lib/kernel/src/logger_filters.erl b/lib/kernel/src/logger_filters.erl new file mode 100644 index 0000000000..7359b3b4b7 --- /dev/null +++ b/lib/kernel/src/logger_filters.erl @@ -0,0 +1,127 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2017. 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_filters). + +-export([domain/2, + level/2, + progress/2, + remote_gl/2]). + +-include("logger_internal.hrl"). +-define(IS_ACTION(A), (A==log orelse A==stop)). + +-spec domain(LogEvent,Extra) -> logger:filter_return() when + LogEvent :: logger:log_event(), + Extra :: {Action,Compare,MatchDomain}, + Action :: log | stop, + Compare :: super | sub | equal | not_equal | undefined, + MatchDomain :: list(atom()). +domain(#{meta:=Meta}=LogEvent,{Action,Compare,MatchDomain}) + when ?IS_ACTION(Action) andalso + (Compare==super orelse + Compare==sub orelse + Compare==equal orelse + Compare==not_equal orelse + Compare==undefined) andalso + is_list(MatchDomain) -> + filter_domain(Compare,Meta,MatchDomain,on_match(Action,LogEvent)); +domain(LogEvent,Extra) -> + erlang:error(badarg,[LogEvent,Extra]). + +-spec level(LogEvent,Extra) -> logger:filter_return() when + LogEvent :: logger:log_event(), + Extra :: {Action,Operator,MatchLevel}, + Action :: log | stop, + Operator :: neq | eq | lt | gt | lteq | gteq, + MatchLevel :: logger:level(). +level(#{level:=L1}=LogEvent,{Action,Op,L2}) + when ?IS_ACTION(Action) andalso + (Op==neq orelse + Op==eq orelse + Op==lt orelse + Op==gt orelse + Op==lteq orelse + Op==gteq) andalso + ?IS_LEVEL(L2) -> + filter_level(Op,L1,L2,on_match(Action,LogEvent)); +level(LogEvent,Extra) -> + erlang:error(badarg,[LogEvent,Extra]). + +-spec progress(LogEvent,Extra) -> logger:filter_return() when + LogEvent :: logger:log_event(), + Extra :: log | stop. +progress(LogEvent,Action) when ?IS_ACTION(Action) -> + filter_progress(LogEvent,on_match(Action,LogEvent)); +progress(LogEvent,Action) -> + erlang:error(badarg,[LogEvent,Action]). + +-spec remote_gl(LogEvent,Extra) -> logger:filter_return() when + LogEvent :: logger:log_event(), + Extra :: log | stop. +remote_gl(LogEvent,Action) when ?IS_ACTION(Action) -> + filter_remote_gl(LogEvent,on_match(Action,LogEvent)); +remote_gl(LogEvent,Action) -> + erlang:error(badarg,[LogEvent,Action]). + +%%%----------------------------------------------------------------- +%%% Internal +filter_domain(super,#{domain:=Domain},MatchDomain,OnMatch) -> + is_prefix(Domain,MatchDomain,OnMatch); +filter_domain(sub,#{domain:=Domain},MatchDomain,OnMatch) -> + is_prefix(MatchDomain,Domain,OnMatch); +filter_domain(equal,#{domain:=Domain},Domain,OnMatch) -> + OnMatch; +filter_domain(not_equal,#{domain:=Domain},MatchDomain,OnMatch) + when Domain=/=MatchDomain -> + OnMatch; +filter_domain(Compare,Meta,_,OnMatch) -> + case maps:is_key(domain,Meta) of + false when Compare==undefined; Compare==not_equal -> OnMatch; + _ -> ignore + end. + +is_prefix(D1,D2,OnMatch) when is_list(D1), is_list(D2) -> + case lists:prefix(D1,D2) of + true -> OnMatch; + false -> ignore + end; +is_prefix(_,_,_) -> + ignore. + +filter_level(Op,L1,L2,OnMatch) -> + case logger:compare_levels(L1,L2) of + eq when Op==eq; Op==lteq; Op==gteq -> OnMatch; + lt when Op==lt; Op==lteq; Op==neq -> OnMatch; + gt when Op==gt; Op==gteq; Op==neq -> OnMatch; + _ -> ignore + end. + +filter_progress(#{msg:={report,#{label:={_,progress}}}},OnMatch) -> + OnMatch; +filter_progress(_,_) -> + ignore. + +filter_remote_gl(#{meta:=#{gl:=GL}},OnMatch) when node(GL)=/=node() -> + OnMatch; +filter_remote_gl(_,_) -> + ignore. + +on_match(log,LogEvent) -> LogEvent; +on_match(stop,_) -> stop. diff --git a/lib/kernel/src/logger_formatter.erl b/lib/kernel/src/logger_formatter.erl new file mode 100644 index 0000000000..33b250eef6 --- /dev/null +++ b/lib/kernel/src/logger_formatter.erl @@ -0,0 +1,458 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2017. 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_formatter). + +-export([format/2]). +-export([check_config/1]). + +-include("logger_internal.hrl"). + +%%%----------------------------------------------------------------- +%%% 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 metakey() :: atom() | [atom()]. + +%%%----------------------------------------------------------------- +%%% API +-spec format(LogEvent,Config) -> unicode:chardata() when + LogEvent :: logger:log_event(), + Config :: config(). +format(#{level:=Level,msg:=Msg0,meta:=Meta},Config0) + when is_map(Config0) -> + Config = add_default_config(Config0), + Meta1 = maybe_add_legacy_header(Level,Meta,Config), + Template = maps:get(template,Config), + {BT,AT0} = lists:splitwith(fun(msg) -> false; (_) -> true end, Template), + {DoMsg,AT} = + case AT0 of + [msg|Rest] -> {true,Rest}; + _ ->{false,AT0} + end, + B = do_format(Level,Meta1,BT,Config), + A = do_format(Level,Meta1,AT,Config), + MsgStr = + if DoMsg -> + Config1 = + case maps:get(chars_limit,Config) of + unlimited -> + Config; + Size0 -> + Size = + case Size0 - string:length([B,A]) of + S when S>=0 -> S; + _ -> 0 + end, + Config#{chars_limit=>Size} + end, + MsgStr0 = format_msg(Msg0,Meta1,Config1), + case maps:get(single_line,Config) of + true -> + %% Trim leading and trailing whitespaces, and replace + %% newlines with ", " + re:replace(string:trim(MsgStr0),",?\r?\n\s*",", ", + [{return,list},global]); + _false -> + MsgStr0 + end; + true -> + "" + end, + truncate(B ++ MsgStr ++ A,maps:get(max_size,Config)). + +do_format(Level,Data,[level|Format],Config) -> + [to_string(level,Level,Config)|do_format(Level,Data,Format,Config)]; +do_format(Level,Data,[{Key,IfExist,Else}|Format],Config) -> + String = + case value(Key,Data) of + {ok,Value} -> do_format(Level,Data#{Key=>Value},IfExist,Config); + error -> do_format(Level,Data,Else,Config) + end, + [String|do_format(Level,Data,Format,Config)]; +do_format(Level,Data,[Key|Format],Config) + when is_atom(Key) orelse + (is_list(Key) andalso is_atom(hd(Key))) -> + String = + case value(Key,Data) of + {ok,Value} -> to_string(Key,Value,Config); + error -> "" + end, + [String|do_format(Level,Data,Format,Config)]; +do_format(Level,Data,[Str|Format],Config) -> + [Str|do_format(Level,Data,Format,Config)]; +do_format(_Level,_Data,[],_Config) -> + []. + +value(Key,Meta) when is_map_key(Key,Meta) -> + {ok,maps:get(Key,Meta)}; +value([Key|Keys],Meta) when is_map_key(Key,Meta) -> + value(Keys,maps:get(Key,Meta)); +value([],Value) -> + {ok,Value}; +value(_,_) -> + error. + +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(X) when is_atom(X) -> + atom_to_list(X); +to_string(X) when is_integer(X) -> + integer_to_list(X); +to_string(X) when is_pid(X) -> + pid_to_list(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 + true -> X; + _ -> io_lib:format("~tp",[X]) + end; +to_string(X) -> + io_lib:format("~tp",[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(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", + [Report,Other]},Meta,Config) + catch C:R -> + format_msg({"REPORT_CB CRASH: ~tp; Reason: ~tp", + [Report,{C,R}]},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) -> + try + Format1 = io_lib:scan_format(Format0, Args), + Format = limit_format(Format1, Depth), + io_lib:build_text(Format,Opts) + catch _:_ -> + limit_size({"FORMAT ERROR: ~tp - ~tp",[Format0,Args]},Depth,Opts) + 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([], _) -> + []. + +truncate(String,unlimited) -> + String; +truncate(String,Size) -> + Length = string:length(String), + if Length>Size -> + case lists:reverse(lists:flatten(String)) of + [$\n|_] -> + string:slice(String,0,Size-4)++"...\n"; + _ -> + string:slice(String,0,Size-3)++"..." + end; + true -> + String + end. + +%% SysTime is the system time in microseconds +format_time(SysTime,#{time_offset:=Offset,time_designator:=Des}) + when is_integer(SysTime) -> + calendar:system_time_to_rfc3339(SysTime,[{unit,microsecond}, + {offset,Offset}, + {time_designator,Des}]). + +%% SysTime is the system time in microseconds +timestamp_to_datetimemicro(SysTime,Config) when is_integer(SysTime) -> + Micro = SysTime rem 1000000, + Sec = SysTime div 1000000, + UniversalTime = erlang:posixtime_to_universaltime(Sec), + {{Date,Time},UtcStr} = + case offset_to_utc(maps:get(time_offset,Config)) of + true -> {UniversalTime,"UTC "}; + _ -> {erlang:universaltime_to_localtime(UniversalTime),""} + end, + {Date,Time,Micro,UtcStr}. + +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). + +maybe_add_legacy_header(Level, + #{time:=Timestamp}=Meta, + #{legacy_header:=true}=Config) -> + #{title:=Title}=MyMeta = add_legacy_title(Level,Meta,Config), + {{Y,Mo,D},{H,Mi,S},Micro,UtcStr} = + timestamp_to_datetimemicro(Timestamp,Config), + Header = + io_lib:format("=~ts==== ~w-~s-~4w::~2..0w:~2..0w:~2..0w.~6..0w ~s===", + [Title,D,month(Mo),Y,H,Mi,S,Micro,UtcStr]), + Meta#{?MODULE=>MyMeta#{header=>Header}}; +maybe_add_legacy_header(_,Meta,_) -> + Meta. + +add_legacy_title(_Level,#{?MODULE:=#{title:=_}=MyMeta},_) -> + MyMeta; +add_legacy_title(Level,Meta,Config) -> + case maps:get(?MODULE,Meta,#{}) of + #{title:=_}=MyMeta -> + MyMeta; + MyMeta -> + TitleLevel = + case (Level=:=notice andalso maps:find(error_logger,Meta)) of + {ok,_} -> + maps:get(error_logger_notice_header,Config); + _ -> + Level + end, + Title = string:uppercase(atom_to_list(TitleLevel)) ++ " REPORT", + MyMeta#{title=>Title} + end. + +month(1) -> "Jan"; +month(2) -> "Feb"; +month(3) -> "Mar"; +month(4) -> "Apr"; +month(5) -> "May"; +month(6) -> "Jun"; +month(7) -> "Jul"; +month(8) -> "Aug"; +month(9) -> "Sep"; +month(10) -> "Oct"; +month(11) -> "Nov"; +month(12) -> "Dec". + +%% Ensure that all valid configuration parameters exist in the final +%% configuration map +add_default_config(Config0) -> + Default = + #{legacy_header=>false, + error_logger_notice_header=>info, + 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)), + Offset = get_offset(maps:get(time_offset,Config0,undefined)), + add_default_template(maps:merge(Default,Config0#{max_size=>MaxSize, + depth=>Depth, + time_offset=>Offset})). + +add_default_template(#{template:=_}=Config) -> + Config; +add_default_template(Config) -> + Config#{template=>default_template(Config)}. + +default_template(#{legacy_header:=true}) -> + ?DEFAULT_FORMAT_TEMPLATE_HEADER; +default_template(#{single_line:=true}) -> + ?DEFAULT_FORMAT_TEMPLATE_SINGLE; +default_template(_) -> + ?DEFAULT_FORMAT_TEMPLATE. + +get_max_size(undefined) -> + unlimited; +get_max_size(S) -> + max(10,S). + +get_depth(undefined) -> + error_logger:get_format_depth(); +get_depth(S) -> + max(5,S). + +get_offset(undefined) -> + utc_to_offset(get_utc_config()); +get_offset(Offset) -> + Offset. + +utc_to_offset(true) -> + "Z"; +utc_to_offset(false) -> + "". + +get_utc_config() -> + %% SASL utc_log overrides stdlib config - in order to have uniform + %% timestamps in log messages + case application:get_env(sasl, utc_log) of + {ok, Val} when is_boolean(Val) -> Val; + _ -> + case application:get_env(stdlib, utc_log) of + {ok, Val} when is_boolean(Val) -> Val; + _ -> false + end + end. + +offset_to_utc(Z) when Z=:=0; Z=:="z"; Z=:="Z" -> + true; +offset_to_utc([$+|Tz]) -> + case io_lib:fread("~d:~d", Tz) of + {ok, [0, 0], []} -> + true; + _ -> + false + end; +offset_to_utc(_) -> + false. + +-spec check_config(Config) -> ok | {error,term()} when + Config :: config(). +check_config(Config) when is_map(Config) -> + do_check_config(maps:to_list(Config)); +check_config(Config) -> + {error,{invalid_formatter_config,?MODULE,Config}}. + +do_check_config([{Type,L}|Config]) when Type == chars_limit; + Type == depth; + Type == max_size -> + case check_limit(L) of + ok -> do_check_config(Config); + error -> {error,{invalid_formatter_config,?MODULE,{Type,L}}} + end; +do_check_config([{single_line,SL}|Config]) when is_boolean(SL) -> + do_check_config(Config); +do_check_config([{legacy_header,LH}|Config]) when is_boolean(LH) -> + do_check_config(Config); +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(Config); +do_check_config([{template,T}|Config]) -> + case check_template(T) of + ok -> do_check_config(Config); + error -> {error,{invalid_formatter_template,?MODULE,T}} + end; +do_check_config([{time_offset,Offset}|Config]) -> + case check_offset(Offset) of + ok -> + do_check_config(Config); + error -> + {error,{invalid_formatter_config,?MODULE,{time_offset,Offset}}} + end; +do_check_config([{time_designator,Char}|Config]) when Char>=0, Char=<255 -> + case io_lib:printable_latin1_list([Char]) of + true -> + do_check_config(Config); + false -> + {error,{invalid_formatter_config,?MODULE,{time_designator,Char}}} + end; +do_check_config([C|_]) -> + {error,{invalid_formatter_config,?MODULE,C}}; +do_check_config([]) -> + ok. + +check_limit(L) when is_integer(L), L>0 -> + ok; +check_limit(unlimited) -> + ok; +check_limit(_) -> + error. + +check_template([Key|T]) when is_atom(Key) -> + check_template(T); +check_template([Key|T]) when is_list(Key), is_atom(hd(Key)) -> + case lists:all(fun(X) when is_atom(X) -> true; + (_) -> false + end, + Key) of + true -> + check_template(T); + false -> + error + end; +check_template([{Key,IfExist,Else}|T]) + when is_atom(Key) orelse + (is_list(Key) andalso is_atom(hd(Key))) -> + case check_template(IfExist) of + ok -> + case check_template(Else) of + ok -> + check_template(T); + error -> + error + end; + error -> + error + end; +check_template([Str|T]) when is_list(Str) -> + case io_lib:printable_unicode_list(Str) of + true -> check_template(T); + false -> error + end; +check_template([]) -> + ok; +check_template(_) -> + error. + +check_offset(I) when is_integer(I) -> + ok; +check_offset(Tz) when Tz=:=""; Tz=:="Z"; Tz=:="z" -> + ok; +check_offset([Sign|Tz]) when Sign=:=$+; Sign=:=$- -> + check_timezone(Tz); +check_offset(_) -> + error. + +check_timezone(Tz) -> + try io_lib:fread("~d:~d", Tz) of + {ok, [_, _], []} -> + ok; + _ -> + error + catch _:_ -> + error + end. diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl new file mode 100644 index 0000000000..d556938f02 --- /dev/null +++ b/lib/kernel/src/logger_h_common.erl @@ -0,0 +1,338 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2017. 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_h_common). + +-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]). + +%%%----------------------------------------------------------------- +%%% Covert log data on any form to binary +-spec log_to_binary(LogEvent,Config) -> LogString when + LogEvent :: logger:log_event(), + Config :: logger:handler_config(), + LogString :: binary(). +log_to_binary(#{msg:={report,_},meta:=#{report_cb:=_}}=Log,Config) -> + do_log_to_binary(Log,Config); +log_to_binary(#{msg:={report,_},meta:=Meta}=Log,Config) -> + DefaultReportCb = fun logger:format_otp_report/1, + do_log_to_binary(Log#{meta=>Meta#{report_cb=>DefaultReportCb}},Config); +log_to_binary(Log,Config) -> + do_log_to_binary(Log,Config). + +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 _:_ -> + ?LOG_INTERNAL(debug,[{formatter_error,Formatter}, + {config,FormatterConfig}, + {log_event,Log}, + {bad_return_value,String}]), + <<"FORMATTER ERROR: bad_return_value">> + end. + +try_format(Log,Formatter,FormatterConfig) -> + try Formatter:format(Log,FormatterConfig) + catch + C:R:S -> + ?LOG_INTERNAL(debug,[{formatter_crashed,Formatter}, + {config,FormatterConfig}, + {log_event,Log}, + {reason, + {C,R,logger:filter_stacktrace(?MODULE,S)}}]), + case {?DEFAULT_FORMATTER,#{}} of + {Formatter,FormatterConfig} -> + "DEFAULT FORMATTER CRASHED"; + {DefaultFormatter,DefaultConfig} -> + try_format(Log#{msg=>{"FORMATTER CRASH: ~tp", + [maps:get(msg,Log)]}}, + DefaultFormatter,DefaultConfig) + 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 == never -> + valid; + +check_common_config({filesync_repeat_interval,NorA}) when is_integer(NorA); + NorA == no_repeat -> + valid; +check_common_config(_) -> + invalid. + + +%%%----------------------------------------------------------------- +%%% 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). + +set_restart_flag(Name, Module) -> + Flag = list_to_atom(lists:concat([Module,"_",Name,"_restarting"])), + spawn(fun() -> + register(Flag, self()), + timer:sleep(infinity) + end), + 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. + +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. + +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 + %% file/disk_log_sync, 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 + 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 new file mode 100644 index 0000000000..ad80b51109 --- /dev/null +++ b/lib/kernel/src/logger_h_common.hrl @@ -0,0 +1,263 @@ + +%%%----------------------------------------------------------------- +%%% 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 'never' +%% disables restarts. +-define(OVERLOAD_KILL_RESTART_AFTER, 5000). +%%-define(OVERLOAD_KILL_RESTART_AFTER, never). + +%% The handler sends asynchronous write requests to the process +%% controlling the i/o device, but every once in this interval +%% will the write request be synchronous, so that the i/o device +%% process doesn't get overloaded. This gives the handler time +%% to keep up with its mailbox in overload situations, even if +%% the i/o is slow. +-define(CONTROLLER_SYNC_INTERVAL, 20). +%% The handler will not perform a file sync operation if the +%% mailbox size is greater than this number. This is to ensure +%% the handler process doesn't get overloaded while waiting for +%% an expensive file sync operation to finish. +-define(FILESYNC_OK_QLEN, 2). +%% Do a file/disk_log sync operation every integer() millisec +%% (if necessary) or set to 'no_repeat' to only do file sync when +%% the handler is idle. Note that file sync is not guaranteed to +%% happen automatically if this operation is disabled. +-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). +-define(DISK_LOG_MAX_NO_BYTES, 1048576). + +%%%----------------------------------------------------------------- +%%% Utility macros + +-define(name_to_reg_name(MODULE,Name), + 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 +%%% to be officially released. + +%%-define(TEST_HOOKS, true). +-ifdef(TEST_HOOKS). + -define(TEST_HOOKS_TAB, logger_h_test_hooks). + + -define(init_test_hooks(), + _ = case ets:whereis(?TEST_HOOKS_TAB) of + undefined -> ets:new(?TEST_HOOKS_TAB, [named_table,public]); + _ -> ok + end, + 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_sync,ok})). + + -define(set_internal_log(MOD_FUNC), + ets:insert(?TEST_HOOKS_TAB, {internal_log,MOD_FUNC})). + + -define(set_result(OPERATION, RESULT), + ets:insert(?TEST_HOOKS_TAB, {OPERATION,RESULT})). + + -define(set_defaults(), + 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_sync,ok})). + + -define(internal_log(TYPE, TERM), + try ets:lookup(?TEST_HOOKS_TAB, internal_log) of + [{_,{LMOD,LFUNC}}] -> apply(LMOD, LFUNC, [TYPE,TERM]); + _ -> logger:internal_log(TYPE, TERM) + catch _:_ -> logger:internal_log(TYPE, TERM) end). + + -define(file_write(DEVICE, DATA), + try ets:lookup(?TEST_HOOKS_TAB, file_write) of + [{_,ok}] -> file:write(DEVICE, DATA); + [{_,ERROR}] -> ERROR + catch _:_ -> file:write(DEVICE, DATA) end). + + -define(file_datasync(DEVICE), + try ets:lookup(?TEST_HOOKS_TAB, file_datasync) of + [{_,ok}] -> file:datasync(DEVICE); + [{_,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); + [{_,ERROR}] -> ERROR + catch _:_ -> disk_log:blog(LOG, DATA) end). + + -define(disk_log_sync(LOG), + try ets:lookup(?TEST_HOOKS_TAB, disk_log_sync) of + [{_,ok}] -> disk_log:sync(LOG); + [{_,ERROR}] -> ERROR + catch _:_ -> disk_log:sync(LOG) end). + + -define(DEFAULT_CALL_TIMEOUT, 5000). + +-else. % DEFAULTS! + -define(TEST_HOOKS_TAB, undefined). + -define(init_test_hooks(), ok). + -define(set_internal_log(_MOD_FUNC), ok). + -define(set_result(_OPERATION, _RESULT), ok). + -define(set_defaults(), ok). + -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_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_internal.hrl b/lib/kernel/src/logger_internal.hrl new file mode 100644 index 0000000000..8941409a25 --- /dev/null +++ b/lib/kernel/src/logger_internal.hrl @@ -0,0 +1,101 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2017. 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% +%% +-include_lib("kernel/include/logger.hrl"). +-define(LOGGER_TABLE,logger). +-define(PRIMARY_KEY,'$primary_config$'). +-define(HANDLER_KEY,'$handler_config$'). +-define(LOGGER_META_KEY,'$logger_metadata$'). +-define(STANDARD_HANDLER, default). +-define(DEFAULT_HANDLER_FILTERS,?DEFAULT_HANDLER_FILTERS([otp])). +-define(DEFAULT_HANDLER_FILTERS(Domain), + [{remote_gl,{fun logger_filters:remote_gl/2,stop}}, + {domain,{fun logger_filters:domain/2,{log,super,Domain}}}, + {no_domain,{fun logger_filters:domain/2,{log,undefined,[]}}}]). +-define(DEFAULT_FORMATTER,logger_formatter). +-define(DEFAULT_FORMAT_CONFIG,#{legacy_header=>true, + single_line=>false}). +-define(DEFAULT_FORMAT_TEMPLATE_HEADER, + [[logger_formatter,header],"\n",msg,"\n"]). +-define(DEFAULT_FORMAT_TEMPLATE_SINGLE, + [time," ",level,": ",msg,"\n"]). +-define(DEFAULT_FORMAT_TEMPLATE, + [time," ",level,":\n",msg,"\n"]). + +-define(DEFAULT_LOGGER_CALL_TIMEOUT, infinity). + +-define(LOG_INTERNAL(Level,Report), + case logger:allow(Level,?MODULE) of + true -> + %% Spawn this to avoid deadlocks + _ = spawn(logger,macro_log,[?LOCATION,Level,Report, + logger:add_default_metadata(#{})]), + ok; + false -> + ok + end). + +%%%----------------------------------------------------------------- +%%% Levels +%%% Using same as syslog +-define(LEVELS,[none, + emergency, + alert, + critical, + error, + warning, + notice, + info, + debug, + all]). +-define(LOG_NONE,-1). +-define(EMERGENCY,0). +-define(ALERT,1). +-define(CRITICAL,2). +-define(ERROR,3). +-define(WARNING,4). +-define(NOTICE,5). +-define(INFO,6). +-define(DEBUG,7). +-define(LOG_ALL,10). + +-define(IS_LEVEL(L), + (L=:=emergency orelse + L=:=alert orelse + L=:=critical orelse + L=:=error orelse + L=:=warning orelse + L=:=notice orelse + L=:=info orelse + L=:=debug)). + +-define(IS_MSG(Msg), + ((is_tuple(Msg) andalso tuple_size(Msg)==2) + andalso + (is_list(element(1,Msg)) andalso is_list(element(2,Msg))) + orelse + (element(1,Msg)==report andalso ?IS_REPORT(element(2,Msg))) + orelse + (element(1,Msg)==string andalso ?IS_STRING(element(2,Msg))))). + +-define(IS_REPORT(Report), + (is_map(Report) orelse (is_list(Report) andalso is_tuple(hd(Report))))). + +-define(IS_STRING(String), + (is_list(String) orelse is_binary(String))). diff --git a/lib/kernel/src/logger_server.erl b/lib/kernel/src/logger_server.erl new file mode 100644 index 0000000000..e50954fc40 --- /dev/null +++ b/lib/kernel/src/logger_server.erl @@ -0,0 +1,532 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2017. 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_server). + +-behaviour(gen_server). + +%% API +-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, + update_formatter_config/2]). + +%% gen_server callbacks +-export([init/1, handle_call/3, handle_cast/2, handle_info/2, + terminate/2]). + +-include("logger_internal.hrl"). + +-define(SERVER, logger). +-define(LOGGER_SERVER_TAG, '$logger_cb_process'). + +-record(state, {tid, async_req, async_req_queue}). + +%%%=================================================================== +%%% API +%%%=================================================================== + +start_link() -> + gen_server:start_link({local, ?SERVER}, ?MODULE, [], []). + +add_handler(Id,Module,Config0) -> + try {check_id(Id),check_mod(Module)} of + {ok,ok} -> + case sanity_check(Id,Config0) of + ok -> + Default = default_config(Id,Module), + Config = maps:merge(Default,Config0), + call({add_handler,Id,Module,Config}); + Error -> + Error + end + catch throw:Error -> + {error,Error} + end. + +remove_handler(HandlerId) -> + call({remove_handler,HandlerId}). + +add_filter(Owner,Filter) -> + case sanity_check(Owner,filters,[Filter]) of + ok -> call({add_filter,Owner,Filter}); + Error -> Error + end. + +remove_filter(Owner,FilterId) -> + call({remove_filter,Owner,FilterId}). + +set_module_level(Modules,Level) when is_list(Modules) -> + case lists:all(fun(M) -> is_atom(M) end,Modules) of + true -> + case sanity_check(primary,level,Level) of + ok -> call({set_module_level,Modules,Level}); + Error -> Error + end; + false -> + {error,{not_a_list_of_modles,Modules}} + end; +set_module_level(Modules,_) -> + {error,{not_a_list_of_modules,Modules}}. + +unset_module_level() -> + call({unset_module_level,all}). + +unset_module_level(Modules) when is_list(Modules) -> + case lists:all(fun(M) -> is_atom(M) end,Modules) of + true -> + call({unset_module_level,Modules}); + false -> + {error,{not_a_list_of_modles,Modules}} + end; +unset_module_level(Modules) -> + {error,{not_a_list_of_modules,Modules}}. + +cache_module_level(Module) -> + gen_server:cast(?SERVER,{cache_module_level,Module}). + +set_config(Owner,Key,Value) -> + update_config(Owner,#{Key=>Value}). + +set_config(Owner,Config) -> + case sanity_check(Owner,Config) of + ok -> + call({set_config,Owner,Config}); + Error -> + Error + end. + +update_config(Owner, Config) -> + case sanity_check(Owner,Config) of + ok -> + call({update_config,Owner,Config}); + Error -> + Error + end. + +update_formatter_config(HandlerId, FormatterConfig) + when is_map(FormatterConfig) -> + call({update_formatter_config,HandlerId,FormatterConfig}); +update_formatter_config(_HandlerId, FormatterConfig) -> + {error,{invalid_formatter_config,FormatterConfig}}. + + +%%%=================================================================== +%%% gen_server callbacks +%%%=================================================================== + +init([]) -> + process_flag(trap_exit, true), + put(?LOGGER_SERVER_TAG,true), + Tid = logger_config:new(?LOGGER_TABLE), + PrimaryConfig = maps:merge(default_config(primary), + #{handlers=>[simple]}), + logger_config:create(Tid,primary,PrimaryConfig), + SimpleConfig0 = maps:merge(default_config(simple,logger_simple_h), + #{filter_default=>stop, + 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), + {ok, #state{tid=Tid, async_req_queue = queue:new()}}. + +handle_call({add_handler,Id,Module,HConfig}, From, #state{tid=Tid}=State) -> + case logger_config:exist(Tid,Id) of + true -> + {reply,{error,{already_exist,Id}},State}; + false -> + call_h_async( + fun() -> + %% inform the handler + call_h(Module,adding_handler,[HConfig],{ok,HConfig}) + end, + fun({ok,HConfig1}) -> + %% We know that the call_h would have loaded the module + %% if it existed, so it is safe here to call function_exported + %% to find out if this is a valid handler + case erlang:function_exported(Module, log, 2) of + true -> + logger_config:create(Tid,Id,Module,HConfig1), + {ok,Config} = do_get_config(Tid,primary), + Handlers = maps:get(handlers,Config,[]), + do_set_config(Tid,primary, + Config#{handlers=>[Id|Handlers]}); + false -> + {error,{invalid_handler, + {function_not_exported, + {Module,log,2}}}} + end; + ({error,HReason}) -> + {error,{handler_not_added,HReason}} + end,From,State) + end; +handle_call({remove_handler,HandlerId}, From, #state{tid=Tid}=State) -> + case logger_config:get(Tid,HandlerId) of + {ok,{Module,HConfig}} -> + {ok,Config} = do_get_config(Tid,primary), + Handlers0 = maps:get(handlers,Config,[]), + Handlers = lists:delete(HandlerId,Handlers0), + call_h_async( + fun() -> + %% inform the handler + call_h(Module,removing_handler,[HConfig],ok) + end, + fun(_Res) -> + do_set_config(Tid,primary,Config#{handlers=>Handlers}), + logger_config:delete(Tid,HandlerId), + ok + end,From,State); + _ -> + {reply,{error,{not_found,HandlerId}},State} + end; +handle_call({add_filter,Id,Filter}, _From,#state{tid=Tid}=State) -> + Reply = do_add_filter(Tid,Id,Filter), + {reply,Reply,State}; +handle_call({remove_filter,Id,FilterId}, _From, #state{tid=Tid}=State) -> + Reply = do_remove_filter(Tid,Id,FilterId), + {reply,Reply,State}; +handle_call({update_config,Id,NewConfig}, From, #state{tid=Tid}=State) -> + 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}), + {reply,Reply,State}; +handle_call({set_config,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); + _ -> + {reply,{error,{not_found,HandlerId}},State} + end; +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}} -> + try + FConfig = maps:merge(OldFConfig,NewFConfig), + check_formatter({FMod,FConfig}), + do_set_config(Tid,HandlerId, + Config#{formatter=>{FMod,FConfig}}) + catch throw:Reason -> {error,Reason} + end; + _ -> + {error,{not_found,HandlerId}} + end, + {reply,Reply,State}; +handle_call({set_module_level,Modules,Level}, _From, #state{tid=Tid}=State) -> + Reply = logger_config:set_module_level(Tid,Modules,Level), + {reply,Reply,State}; +handle_call({unset_module_level,Modules}, _From, #state{tid=Tid}=State) -> + Reply = logger_config:unset_module_level(Tid,Modules), + {reply,Reply,State}. + +handle_cast({async_req_reply,_Ref,_Reply} = Reply,State) -> + call_h_reply(Reply,State); +handle_cast({cache_module_level,Module}, #state{tid=Tid}=State) -> + logger_config:cache_module_level(Tid,Module), + {noreply, State}. + +%% Interface for those who can't call the API - e.g. the emulator, or +%% places related to code loading. +%% +%% This can also be log events from remote nodes which are sent from +%% logger.erl when the group leader of the client process is on a +%% same node as the client process itself. +handle_info({log,Level,Format,Args,Meta}, State) -> + logger:log(Level,Format,Args,Meta), + {noreply, State}; +handle_info({log,Level,Report,Meta}, State) -> + logger:log(Level,Report,Meta), + {noreply, State}; +handle_info({Ref,_Reply},State) when is_reference(Ref) -> + %% Assuming this is a timed-out gen_server reply - ignoring + {noreply, State}; +handle_info({'DOWN',_Ref,_Proc,_Pid,_Reason} = Down,State) -> + call_h_reply(Down,State); +handle_info(Unexpected,State) when element(1,Unexpected) == 'EXIT' -> + %% The simple handler will send an 'EXIT' message when it is replaced + %% We may as well ignore all 'EXIT' messages that we get + ?LOG_INTERNAL(debug, + [{logger,got_unexpected_message}, + {process,?SERVER}, + {message,Unexpected}]), + {noreply,State}; +handle_info(Unexpected,State) -> + ?LOG_INTERNAL(info, + [{logger,got_unexpected_message}, + {process,?SERVER}, + {message,Unexpected}]), + {noreply,State}. + +terminate(_Reason, _State) -> + ok. + +%%%=================================================================== +%%% Internal functions +%%%=================================================================== +call(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 -> + {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 + {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]}) + end; + Error -> + Error + end. + +do_remove_filter(Tid,Id,FilterId) -> + case do_get_config(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}); + false -> + {error,{not_found,FilterId}} + end; + Error -> + 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=>[], + filter_default=>log}; +default_config(Id) -> + #{id=>Id, + level=>all, + filters=>[], + filter_default=>log, + formatter=>{?DEFAULT_FORMATTER,#{}}}. +default_config(Id,Module) -> + (default_config(Id))#{module=>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(_,Config) -> + {error,{invalid_handler_config,Config}}. + +sanity_check_1(Owner,Config) when is_list(Config) -> + try + Type = get_type(Owner), + check_config(Type,Config) + catch throw:Error -> {error,Error} + end. + +get_type(primary) -> + primary; +get_type(Id) -> + check_id(Id), + handler. + +check_config(Owner,[{level,Level}|Config]) -> + check_level(Level), + check_config(Owner,Config); +check_config(Owner,[{filters,Filters}|Config]) -> + check_filters(Filters), + check_config(Owner,Config); +check_config(Owner,[{filter_default,FD}|Config]) -> + check_filter_default(FD), + check_config(Owner,Config); +check_config(handler,[{formatter,Formatter}|Config]) -> + check_formatter(Formatter), + check_config(handler,Config); +check_config(primary,[C|_]) -> + throw({invalid_primary_config,C}); +check_config(handler,[{_,_}|Config]) -> + %% Arbitrary config elements are allowed for handlers + check_config(handler,Config); +check_config(_,[]) -> + ok. + +check_id(Id) when is_atom(Id) -> + ok; +check_id(Id) -> + throw({invalid_id,Id}). + +check_mod(Mod) when is_atom(Mod) -> + ok; +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 -> + ok; + false -> + throw({invalid_level,Level}) + end. + +check_filters([{Id,{Fun,_Args}}|Filters]) when is_atom(Id), is_function(Fun,2) -> + check_filters(Filters); +check_filters([Filter|_]) -> + throw({invalid_filter,Filter}); +check_filters([]) -> + ok; +check_filters(Filters) -> + throw({invalid_filters,Filters}). + +check_filter_default(FD) when FD==stop; FD==log -> + ok; +check_filter_default(FD) -> + throw({invalid_filter_default,FD}). + +check_formatter({Mod,Config}) -> + check_mod(Mod), + try Mod:check_config(Config) of + ok -> ok; + {error,Error} -> throw(Error) + catch + C:R:S -> + case {C,R,S} of + {error,undef,[{Mod,check_config,[Config],_}|_]} -> + ok; + _ -> + throw({callback_crashed, + {C,R,logger:filter_stacktrace(?MODULE,S)}}) + end + end; +check_formatter(Formatter) -> + throw({invalid_formatter,Formatter}). + +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 + %% exist and we'll get a deadlock in removing the handler. + try apply(Module, Function, Args) + catch + C:R:S -> + case {C,R,S} of + {error,undef,[{Module,Function,Args,_}|_]} -> + DefRet; + _ -> + ST = logger:filter_stacktrace(?MODULE,S), + ?LOG_INTERNAL(error, + [{logger,callback_crashed}, + {process,?SERVER}, + {reason,{C,R,ST}}]), + {error,{callback_crashed,{C,R,ST}}} + end + end. + +%% There are all sort of API functions that can cause deadlocks if called +%% from the handler callbacks. So we spawn a process that does the request +%% for the logger_server. There are still APIs that will cause problems, +%% namely logger:add_handler +call_h_async(AsyncFun,PostFun,From,#state{ async_req = undefined } = State) -> + Parent = self(), + {Pid, Ref} = spawn_monitor( + fun() -> + put(?LOGGER_SERVER_TAG,true), + receive Ref -> Ref end, + gen_server:cast(Parent, {async_req_reply, Ref, AsyncFun()}) + end), + Pid ! Ref, + {noreply,State#state{ async_req = {Ref,PostFun,From} }}; +call_h_async(AsyncFun,PostFun,From,#state{ async_req_queue = Q } = State) -> + {noreply,State#state{ async_req_queue = queue:in({AsyncFun,PostFun,From},Q) }}. + +call_h_reply({async_req_reply,Ref,Reply}, + #state{ async_req = {Ref,PostFun,From}, async_req_queue = Q} = State) -> + erlang:demonitor(Ref,[flush]), + _ = gen_server:reply(From, PostFun(Reply)), + {Value,NewQ} = queue:out(Q), + NewState = State#state{ async_req = undefined, + async_req_queue = NewQ }, + case Value of + {value,{AsyncFun,NPostFun,NFrom}} -> + call_h_async(AsyncFun,NPostFun,NFrom,NewState); + empty -> + {noreply,NewState} + end; +call_h_reply({'DOWN',Ref,_Proc,Pid,Reason}, #state{ async_req = {Ref,_PostFun,_From}} = State) -> + %% This clause should only be triggered if someone explicitly sends an exit signal + %% to the spawned process. It is only here to make sure that the logger_server does + %% not deadlock if that happens. + ?LOG_INTERNAL(error, + [{logger,process_exited}, + {process,Pid}, + {reason,Reason}]), + call_h_reply( + {async_req_reply,Ref,{error,{logger_process_exited,Pid,Reason}}}, + State); +call_h_reply(Unexpected,State) -> + ?LOG_INTERNAL(info, + [{logger,got_unexpected_message}, + {process,?SERVER}, + {message,Unexpected}]), + {noreply,State}. diff --git a/lib/kernel/src/logger_simple_h.erl b/lib/kernel/src/logger_simple_h.erl new file mode 100644 index 0000000000..19fb3b54ba --- /dev/null +++ b/lib/kernel/src/logger_simple_h.erl @@ -0,0 +1,212 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2017. 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_simple_h). + +-export([adding_handler/1, removing_handler/1, log/2]). + +%% This module implements a simple handler for logger. It is the +%% default used during system start. + +%%%----------------------------------------------------------------- +%%% Logger callback + +adding_handler(#{id:=simple}=Config) -> + Me = self(), + case whereis(?MODULE) of + undefined -> + {Pid,Ref} = spawn_opt(fun() -> init(Me) end, + [link,monitor,{message_queue_data,off_heap}]), + receive + {'DOWN',Ref,process,Pid,Reason} -> + {error,Reason}; + {Pid,started} -> + erlang:demonitor(Ref), + {ok,Config} + end; + _ -> + {error,{handler_process_name_already_exists,?MODULE}} + end. + +removing_handler(#{id:=simple}) -> + case whereis(?MODULE) of + undefined -> + ok; + Pid -> + Ref = erlang:monitor(process,Pid), + unlink(Pid), + Pid ! stop, + receive {'DOWN',Ref,process,Pid,_} -> + ok + end + end. + +log(#{meta:=#{error_logger:=#{tag:=info_report,type:=Type}}},_Config) + when Type=/=std_info -> + %% Skip info reports that are not 'std_info' (ref simple logger in + %% error_logger) + ok; +log(#{msg:=_,meta:=#{time:=_}}=Log,_Config) -> + _ = case whereis(?MODULE) of + undefined -> + %% Is the node on the way down? Real emergency? + %% Log directly from client just to get it out + do_log( + #{level=>error, + msg=>{report,{error,simple_handler_process_dead}}, + meta=>#{time=>erlang:system_time(microsecond)}}), + do_log(Log); + _ -> + ?MODULE ! {log,Log} + end, + ok; +log(_,_) -> + %% Unexpected log. + %% We don't want to crash the simple logger, so ignore this. + ok. + +%%%----------------------------------------------------------------- +%%% Process +init(Starter) -> + register(?MODULE,self()), + Starter ! {self(),started}, + loop(#{buffer_size=>10,dropped=>0,buffer=>[]}). + +loop(Buffer) -> + receive + stop -> + %% We replay the logger messages of there is + %% a default handler when the simple handler + %% is removed. + case logger:get_handler_config(default) of + {ok, _} -> + replay_buffer(Buffer); + _ -> + ok + end; + {log,#{msg:=_,meta:=#{time:=_}}=Log} -> + do_log(Log), + loop(update_buffer(Buffer,Log)); + _ -> + %% Unexpected message - flush it! + loop(Buffer) + end. + +update_buffer(#{buffer_size:=0,dropped:=D}=Buffer,_Log) -> + Buffer#{dropped=>D+1}; +update_buffer(#{buffer_size:=S,buffer:=B}=Buffer,Log) -> + Buffer#{buffer_size=>S-1,buffer=>[Log|B]}. + +replay_buffer(#{ dropped := D, buffer := Buffer }) -> + lists:foreach( + fun F(#{msg := {Tag, Msg}} = L) when Tag =:= string; Tag =:= report -> + F(L#{ msg := Msg }); + F(#{ level := Level, msg := Msg, meta := MD}) -> + logger:log(Level, Msg, MD) + end, lists:reverse(Buffer, drop_msg(D))). + +drop_msg(0) -> + []; +drop_msg(N) -> + [#{level=>info, + msg=>{"Simple handler buffer full, dropped ~w messages",[N]}, + meta=>#{time=>erlang:system_time(microsecond)}}]. + +%%%----------------------------------------------------------------- +%%% Internal + +%% Can't do io_lib:format + +do_log(#{msg:={report,Report}, + meta:=#{time:=T,error_logger:=#{type:=Type}}}) -> + display_date(T), + display_report(Type,Report); +do_log(#{msg:=Msg,meta:=#{time:=T}}) -> + display_date(T), + display(Msg). + +display_date(Timestamp) when is_integer(Timestamp) -> + Micro = Timestamp rem 1000000, + Sec = Timestamp div 1000000, + {{Y,Mo,D},{H,Mi,S}} = erlang:universaltime_to_localtime( + erlang:posixtime_to_universaltime(Sec)), + erlang:display_string( + integer_to_list(Y) ++ "-" ++ + pad(Mo,2) ++ "-" ++ + pad(D,2) ++ " " ++ + pad(H,2) ++ ":" ++ + pad(Mi,2) ++ ":" ++ + pad(S,2) ++ "." ++ + pad(Micro,6) ++ " "). + +pad(Int,Size) when is_integer(Int) -> + pad(integer_to_list(Int),Size); +pad(Str,Size) when length(Str)==Size -> + Str; +pad(Str,Size) -> + pad([$0|Str],Size). + +display({string,Chardata}) -> + try unicode:characters_to_list(Chardata) of + String -> erlang:display_string(String), erlang:display_string("\n") + catch _:_ -> erlang:display(Chardata) + end; +display({report,Report}) when is_map(Report) -> + display_report(maps:to_list(Report)); +display({report,Report}) -> + display_report(Report); +display({F, A}) when is_list(F), is_list(A) -> + erlang:display_string(F ++ "\n"), + [begin + erlang:display_string("\t"), + erlang:display(Arg) + end || Arg <- A], + ok. + +display_report(Atom, A) when is_atom(Atom) -> + %% The widest atom seems to be 'supervisor_report' at 17. + ColumnWidth = 20, + AtomString = atom_to_list(Atom), + AtomLength = length(AtomString), + Padding = lists:duplicate(ColumnWidth - AtomLength, $\s), + erlang:display_string(AtomString ++ Padding), + display_report(A); +display_report(F, A) -> + erlang:display({F, A}). + +display_report([A, []]) -> + %% Special case for crash reports when process has no links + display_report(A); +display_report(A = [_|_]) -> + case lists:all(fun({Key,_Value}) -> is_atom(Key); (_) -> false end, A) of + true -> + erlang:display_string("\n"), + lists:foreach( + fun({Key, Value}) -> + erlang:display_string( + " " ++ + atom_to_list(Key) ++ + ": "), + erlang:display(Value) + end, A); + false -> + erlang:display(A) + end; +display_report(A) -> + erlang:display(A). diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl new file mode 100644 index 0000000000..ce9daa50ab --- /dev/null +++ b/lib/kernel/src/logger_std_h.erl @@ -0,0 +1,822 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2017. 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_std_h). + +-behaviour(gen_server). + +-include("logger.hrl"). +-include("logger_internal.hrl"). +-include("logger_h_common.hrl"). + +-include_lib("kernel/include/file.hrl"). + +%% API +-export([start_link/3, info/1, sync/1, reset/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 callbacks +-export([log/2, adding_handler/1, removing_handler/1, changing_config/2]). + +%% handler internal +-export([log_handler_info/4]). + +%%%=================================================================== +%%% 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 sync(Name) -> ok | {error,Reason} when + Name :: atom(), + Reason :: handler_busy | {badarg,term()}. + +sync(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; +sync(Name) -> + {error,{badarg,{sync,[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 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; + Error -> + Error + end. + +%%%----------------------------------------------------------------- +%%% 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. + + +%%%----------------------------------------------------------------- +%%% Handler being removed +removing_handler(#{id:=Name}) -> + stop(Name). + +%%%----------------------------------------------------------------- +%%% Log a string or report +-spec log(LogEvent, Config) -> ok | dropped 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). + +%%%=================================================================== +%%% gen_server callbacks +%%%=================================================================== + +init([Name, Config = #{config := HConfig}, + State0 = #{type := Type, file_ctrl_sync_int := FileCtrlSyncInt}]) -> + register(?name_to_reg_name(?MODULE,Name), self()), + process_flag(trap_exit, true), + process_flag(message_queue_data, off_heap), + + ?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 -> + logger_h_common:error_notify({init_handler,Name,Error}), + proc_lib:init_ack(Error) + end; + Error -> + logger_h_common:error_notify({init_handler,Name,Error}), + proc_lib:init_ack(Error) + end. + +do_init(Name, Type) -> + case open_log_file(Name, Type) 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}}; + Error -> + 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(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; + +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; + +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}; + +handle_info(_Info, State) -> + {noreply, State}. + +terminate(Reason, State = #{id:=Name, file_ctrl_pid:=FWPid, + type:=_FileInfo}) -> + _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, State, + undefined)), + case is_process_alive(FWPid) of + true -> + unlink(FWPid), + _ = file_ctrl_stop(FWPid), + MRef = erlang:monitor(process, FWPid), + receive + {'DOWN',MRef,_,_,_} -> + ok + after + ?DEFAULT_CALL_TIMEOUT -> + exit(FWPid, kill) + end; + false -> + ok + end, + logger_h_common:stop_or_restart(Name, Reason, State). + +code_change(_OldVsn, State, _Extra) -> + {ok, State}. + +%%%=================================================================== +%%% 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, + 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}) -> + try + case filelib:ensure_dir(File) of + ok -> + file:open(File, Modes); + Error -> + Error + end + catch + _:Reason -> {error,Reason} + end. + +close_log_file(Std) when Std == standard_io; Std == standard_error -> + ok; +close_log_file(Fd) -> + _ = file:datasync(Fd), + _ = file:close(Fd). + + +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) -> + Starter = self(), + FileCtrlPid = + spawn_link(fun() -> + file_ctrl_init(HandlerName, FileInfo, Starter) + end), + receive + {FileCtrlPid,ok} -> + {ok,FileCtrlPid}; + {FileCtrlPid,Error} -> + Error + after + ?DEFAULT_CALL_TIMEOUT -> + {error,file_ctrl_process_not_started} + end. + +file_ctrl_stop(Pid) -> + Pid ! stop. + +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. + +file_ctrl_filesync_async(Pid) -> + Pid ! filesync, + ok. + +file_ctrl_filesync_sync(Pid) -> + file_ctrl_call(Pid, {filesync,self()}). + +file_ctrl_call(Pid, Msg) -> + MRef = monitor(process, Pid), + Pid ! {Msg,MRef}, + receive + {MRef,Result} -> + demonitor(MRef, [flush]), + Result; + {'DOWN',MRef,_Type,_Object,Reason} -> + {error,Reason} + after + ?DEFAULT_CALL_TIMEOUT -> + {error,{no_response,Pid}} + end. + +file_ctrl_init(HandlerName, FileInfo, Starter) when is_tuple(FileInfo) -> + process_flag(message_queue_data, off_heap), + FileName = element(2, FileInfo), + case do_open_log_file(FileInfo) of + {ok,Fd} -> + Starter ! {self(),ok}, + file_ctrl_loop(Fd, file, FileName, false, ok, ok, HandlerName); + {error,Reason} -> + Starter ! {self(),{error,{open_failed,FileName,Reason}}} + end; +file_ctrl_init(HandlerName, StdDev, Starter) -> + Starter ! {self(),ok}, + file_ctrl_loop(StdDev, standard_io, StdDev, false, ok, ok, HandlerName). + +file_ctrl_loop(Fd, Type, DevName, Synced, + PrevWriteResult, PrevSyncResult, HandlerName) -> + 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); + + %% 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); + + 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, + From ! {MRef,ok}, + file_ctrl_loop(Fd, Type, DevName, true, + PrevWriteResult, Result, HandlerName); + + stop -> + _ = close_log_file(Fd), + stopped + end. + +write_to_dev(Fd, Bin, FileName, PrevWriteResult, HandlerName) -> + case ?file_write(Fd, Bin) of + ok -> + ok; + PrevWriteResult -> + %% don't report same error twice + PrevWriteResult; + Error -> + logger_h_common:error_notify({HandlerName,write,FileName,Error}), + Error + end. + +sync_dev(Fd, DevName, PrevSyncResult, HandlerName) -> + case ?file_datasync(Fd) of + ok -> + ok; + PrevSyncResult -> + %% don't report same error twice + PrevSyncResult; + Error -> + logger_h_common:error_notify({HandlerName,sync,DevName,Error}), + Error + end. + diff --git a/lib/kernel/src/logger_sup.erl b/lib/kernel/src/logger_sup.erl new file mode 100644 index 0000000000..4e4de94d5c --- /dev/null +++ b/lib/kernel/src/logger_sup.erl @@ -0,0 +1,53 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2017. 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_sup). + +-behaviour(supervisor). + +%% API +-export([start_link/0]). + +%% Supervisor callbacks +-export([init/1]). + +-define(SERVER, ?MODULE). + +%%%=================================================================== +%%% API functions +%%%=================================================================== + +start_link() -> + supervisor:start_link({local, ?SERVER}, ?MODULE, []). + +%%%=================================================================== +%%% Supervisor callbacks +%%%=================================================================== + +init([]) -> + + SupFlags = #{strategy => one_for_one, + intensity => 1, + period => 5}, + + {ok, {SupFlags, []}}. + +%%%=================================================================== +%%% Internal functions +%%%=================================================================== diff --git a/lib/kernel/src/net_kernel.erl b/lib/kernel/src/net_kernel.erl index 669adefdf8..c4e1a0ce1e 100644 --- a/lib/kernel/src/net_kernel.erl +++ b/lib/kernel/src/net_kernel.erl @@ -53,7 +53,7 @@ %% Documented API functions. --export([allow/1, +-export([allow/1, allowed/0, connect_node/1, monitor_nodes/1, monitor_nodes/2, @@ -171,6 +171,8 @@ kernel_apply(M,F,A) -> request({apply,M,F,A}). Nodes :: [node()]. allow(Nodes) -> request({allow, Nodes}). +allowed() -> request(allowed). + longnames() -> request(longnames). -spec stop() -> ok | {error, Reason} when @@ -528,6 +530,9 @@ handle_call({allow, Nodes}, From, State) -> async_reply({reply,error,State}, From) end; +handle_call(allowed, From, #state{allowed = Allowed} = State) -> + async_reply({reply,{ok,Allowed},State}, From); + %% %% authentication, used by auth. Simply works as this: %% if the message comes through, the other node IS authorized. diff --git a/lib/kernel/src/seq_trace.erl b/lib/kernel/src/seq_trace.erl index cc0c10909b..8d7aba0f27 100644 --- a/lib/kernel/src/seq_trace.erl +++ b/lib/kernel/src/seq_trace.erl @@ -41,7 +41,7 @@ -type flag() :: 'send' | 'receive' | 'print' | 'timestamp' | 'monotonic_timestamp' | 'strict_monotonic_timestamp'. -type component() :: 'label' | 'serial' | flag(). --type value() :: (Integer :: non_neg_integer()) +-type value() :: (Label :: term()) | {Previous :: non_neg_integer(), Current :: non_neg_integer()} | (Bool :: boolean()). @@ -59,10 +59,6 @@ set_token({Flags,Label,Serial,_From,Lastcnt}) -> F = decode_flags(Flags), set_token2([{label,Label},{serial,{Lastcnt, Serial}} | F]). -%% We limit the label type to always be a small integer because erl_interface -%% expects that, the BIF can however "unofficially" handle atoms as well, and -%% atoms can be used if only Erlang nodes are involved - -spec set_token(Component, Val) -> {Component, OldVal} when Component :: component(), Val :: value(), |