diff options
24 files changed, 1940 insertions, 278 deletions
diff --git a/lib/diameter/doc/src/diameter.xml b/lib/diameter/doc/src/diameter.xml index 0a0194af2d..85522c99b2 100644 --- a/lib/diameter/doc/src/diameter.xml +++ b/lib/diameter/doc/src/diameter.xml @@ -1,7 +1,9 @@ <?xml version="1.0" encoding="utf-8" ?> <!DOCTYPE erlref SYSTEM "erlref.dtd" [ - <!ENTITY spawn_opt + <!ENTITY spawn_opt2 '<seealso marker="erts:erlang#spawn_opt-2">erlang:spawn_opt/2</seealso>'> + <!ENTITY spawn_opt5 + '<seealso marker="erts:erlang#spawn_opt-5">erlang:spawn_opt/5</seealso>'> <!ENTITY nodes '<seealso marker="erts:erlang#nodes-0">erlang:nodes/0</seealso>'> <!ENTITY make_ref @@ -21,7 +23,7 @@ <copyright> <year>2011</year> -<year>2017</year> +<year>2019</year> <holder>Ericsson AB. All Rights Reserved.</holder> </copyright> <legalnotice> @@ -1384,12 +1386,22 @@ the same peer.</p> </item> <tag> -<marker id="spawn_opt"/><c>{spawn_opt, [term()]}</c></tag> +<marker id="spawn_opt"/><c>{spawn_opt, [term()] | {M,F,A}}</c></tag> <item> <p> -Options passed to &spawn_opt; when spawning a process for an -incoming Diameter request. -Options <c>monitor</c> and <c>link</c> are ignored.</p> +An options list passed to &spawn_opt2; to spawn a handler process for an +incoming Diameter request on the local node, or an MFA that returns +the pid of a handler process.</p> + +<p> +Options <c>monitor</c> and <c>link</c> are ignored in the list-valued +case. +An MFA is applied with an additional term prepended to its argument +list, and should return either the pid of the handler process that +invokes <c>diameter_traffic:request/1</c> on the term in order to +process the request, or the atom <c>discard</c>. +The handler process need not be local, but diameter must be started on +the remote node.</p> <p> Defaults to the empty list.</p> diff --git a/lib/diameter/doc/src/diameter_transport.xml b/lib/diameter/doc/src/diameter_transport.xml index 67fd54bc56..0a8ef321c6 100644 --- a/lib/diameter/doc/src/diameter_transport.xml +++ b/lib/diameter/doc/src/diameter_transport.xml @@ -14,7 +14,8 @@ <erlref> <header> <copyright> -<year>2011</year><year>2016</year> +<year>2011</year> +<year>2019</year> <holder>Ericsson AB. All Rights Reserved.</holder> </copyright> <legalnotice> @@ -174,10 +175,13 @@ its parent.</p> <taglist> -<tag><c>{diameter, {send, &message;}}</c></tag> +<tag><c>{diameter, {send, &message; | false}}</c></tag> <item> <p> -An outbound Diameter message.</p> +An outbound Diameter message. +The atom <c>false</c> can only be received when request +acknowledgements have been requests: see the <c>ack</c> message +below.</p> </item> <tag><c>{diameter, {close, Pid}}</c></tag> @@ -246,6 +250,27 @@ A <c>LocalAddr</c> list has the same semantics as one returned from &start;.</p> </item> +<tag><c>{diameter, ack}</c></tag> +<item> +<p> +Request acknowledgements of unanswered requests. +A transport process should send this once before passing incoming +Diameter messages into diameter. +As a result, every Diameter request passed into diameter with a +<c>recv</c> message (below) will be answered with a +<c>send</c> message (above), either a &message; for the transport +process to send or the atom <c>false</c> if the request has been +discarded or otherwise not answered.</p> + +<p> +This is to allow a transport process to keep count of the number +of incoming request messages that have not yet been answered or +discarded, to allow it to regulate the amount of incoming traffic. +Both diameter_tcp and diameter_sctp request acknowledgements when a +<c>message_cb</c> is configured, turning send/recv message into +callbacks that can be used to regulate traffic.</p> +</item> + <tag><c>{diameter, {recv, &message;}}</c></tag> <item> <p> diff --git a/lib/diameter/src/base/diameter.erl b/lib/diameter/src/base/diameter.erl index b90b794611..7f172e1fa1 100644 --- a/lib/diameter/src/base/diameter.erl +++ b/lib/diameter/src/base/diameter.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2010-2017. All Rights Reserved. +%% Copyright Ericsson AB 2010-2019. All Rights Reserved. %% %% Licensed under the Apache License, Version 2.0 (the "License"); %% you may not use this file except in compliance with the License. @@ -365,7 +365,7 @@ call(SvcName, App, Message) -> | {connect_timer, 'Unsigned32'()} | {watchdog_timer, 'Unsigned32'() | {module(), atom(), list()}} | {watchdog_config, [{okay|suspect, non_neg_integer()}]} - | {spawn_opt, list()}. + | {spawn_opt, list() | mfa()}. %% Options passed to start_service/2 diff --git a/lib/diameter/src/base/diameter_callback.erl b/lib/diameter/src/base/diameter_callback.erl index d04a416bef..3bcf550cd8 100644 --- a/lib/diameter/src/base/diameter_callback.erl +++ b/lib/diameter/src/base/diameter_callback.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2010-2017. All Rights Reserved. +%% Copyright Ericsson AB 2010-2019. All Rights Reserved. %% %% Licensed under the Apache License, Version 2.0 (the "License"); %% you may not use this file except in compliance with the License. @@ -70,7 +70,7 @@ -module(diameter_callback). -%% Default callbacks when no aleternate is specified. +%% Default callbacks when no alternate is specified. -export([peer_up/3, peer_down/3, pick_peer/4, diff --git a/lib/diameter/src/base/diameter_dist.erl b/lib/diameter/src/base/diameter_dist.erl new file mode 100644 index 0000000000..5c29ea95a4 --- /dev/null +++ b/lib/diameter/src/base/diameter_dist.erl @@ -0,0 +1,525 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2019. All Rights Reserved. +%% +%% Licensed under the Apache License, Version 2.0 (the "License"); +%% you may not use this file except in compliance with the License. +%% 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(diameter_dist). + +-behaviour(gen_server). + +%% +%% Implements callbacks that can be configured as a spawn_opt +%% transport configuration, to be able to distribute incoming Diameter +%% requests to handler processes (local or remote) in various ways. +%% + +%% spawn_opt callbacks +-export([spawn_local/2, + spawn_local/1, + route_session/2, + route_session/1]). + +%% signal availability for handling incoming requests to route_sesssion/2 +-export([attach/1, + detach/1]). + +%% consistent hashing +-export([hash/3, %% for use as default MFA in route_session/2 options map + hash/2]). %% arbitrary key/values + +-include_lib("diameter/include/diameter.hrl"). + +%% server start +-export([start_link/0]). + +%% gen_server callbacks +-export([init/1, + handle_info/2, + handle_cast/2, + handle_call/3, + code_change/3, + terminate/2]). + +-type request() :: tuple(). %% callback argument from diameter_traffic + +-define(SERVER, ?MODULE). %% server monitoring node connections + +%% Maps a node name binary to the corresponding atom. Used by +%% route_session/2 to map the optional value of a Session-Id to +%% node(). +-define(NODE_TABLE, diameter_dist_node). + +%% Maps a diameter:service_name() to a node() that has called attach/1 +%% to declare its willingness to handle incoming requests for the +%% service. Use by route_session/2 in case the optional value mapping +%% has failed. +-define(SERVICE_TABLE, diameter_dist_service). + +-define(B(A), atom_to_binary(A, utf8)). +-define(ORCOND(List), list_to_tuple(['orelse', false | List])). +-define(HASH(T), erlang:phash2(T, 16#100000000)). + +%% spawn_local/2 +%% +%% Callback that is equivalent to an options list. That is, the +%% following are equivalent when passed as options to +%% diameter:add_transport/2. +%% +%% {spawn_opt, Opts} +%% {spawn_opt, {diameter_dist, spawn_local, [Opts]}} + +-spec spawn_local(ReqT :: request(), Opts :: list()) + -> pid(). + +spawn_local(ReqT, Opts) -> + spawn_opt(diameter_traffic, request, [ReqT], Opts). + +%% spawn_local/1 + +spawn_local(ReqT) -> + spawn_local(ReqT, []). + +%% route_session/2 +%% +%% Callback that maps the Session-Id of an incoming request to a +%% handler node. +%% +%% With an options list, maps an id whose optional value is the name +%% of a connected node to the same node, to handle the case that the +%% session id has been returned from diameter:session_id/1; otherwise +%% to a node that has called diameter_dist:attach/1 using the +%% consistent hashing provided by hash/3, or to the local node() if a +%% session id could not be extracted or there are no attached nodes. A +%% handler process is spawned on the selected node using +%% erlang:spawn_opt/4. +%% +%% Different behaviour can be configured by supplying an options map +%% of the following form: +%% +%% #{search => non_neg_integer(), +%% id => [binary()], +%% default => discard | local | mfa(), +%% dispatch => list() | mfa()} +%% +%% The search member limits the number of AVPs that are examined in +%% the message (from the front), to avoid searching entire message in +%% case it's known that peers follow RFC 6733's recommendation that +%% Session-Id be placed at the head of a message. The default is to +%% search the entire message. +%% +%% The id member restricts the optional value mapping to session ids +%% whose DiamterIdentity is one of those specified. Set this to the +%% list of Diameter identities advertised by the service in question +%% (typically one) to ensure that only locally generated session ids +%% are mapped; or to the empty list to disable the mapping. +%% +%% The default member determines where to handle a message whose +%% Session-Id isn't found or whose optional value isn't mapped to the +%% name of a connected node. The atom local says the local node, an +%% MFA is invoked on Session-Id | false, the name of the diameter +%% service, and the message binary, and should return either a node() +%% or false to discard the message. Defaults to {diameter_dist, hash, []}. +%% +%% The dispatch member determines how the pid() of the request handler +%% process is retrieved. An MFA is applied to a previously selected +%% node(), and the module, function, and arguments list to apply in +%% the handler process to handle the request, the MFA being supplied +%% by diameter, and returns pid() | discard. A list is equivalent to +%% {erlang, spawn_opt, []}. Defaults to []. +%% +%% This can be used with search = 0 to route on something other than +%% Session-Id, but this is probably no simpler than just implementing +%% an own spawn_opt callback. (Except with the default dispatch possibly.) +%% +%% Note that if the peer is also implemented with OTP diameter and +%% generating session ids with diameter:session_id/1 then +%% route_session/2 can map an optional value to a local node that +%% happens to have the same name as one of the peer's nodes. This +%% could lead to an uneven distribution; for example, if the peer +%% nodes are a subset of the local nodes. In practice, it's typically +%% known if it's peers or the local node originating sessions; if the +%% former then setting id = [] disables the optional value mapping, if +%% the latter then setting default = local disables the hashing. +-spec route_session(ReqT :: request(), Opts) + -> discard + | pid() + when Opts :: pos_integer() %% aka #{search => N} + | list() %% aka #{dispatch => Opts} + | #{search => non_neg_integer(), %% limit number of examined AVPs + id => [binary()], %% restrict optional value map on DiamIdent + default => local %% handle locally + | discard + | mfa(), %% return node() | false + dispatch => list() %% spawn options + | mfa()}. %% (Node, M, F, A) -> pid() | discard + +route_session(ReqT, Opts) -> + {_, Bin} = Info = diameter_traffic:request_info(ReqT), + Sid = session_id(avps(Bin), search(Opts)), + Node = default(node_of_session_id(Sid, Opts), Sid, Opts, Info), + dispatch(Node, ReqT, dispatch(Opts)). + +%% avps/1 + +avps(<<_:20/binary, Bin/binary>>) -> + Bin; + +avps(_) -> + false. + +%% dispatch/3 + +dispatch(false, _, _) -> + discard; + +dispatch(Node, ReqT, {M,F,A}) -> + apply(M, F, [Node, diameter_traffic, request, [ReqT] | A]); + +dispatch(Node, ReqT, Opts) -> + spawn_opt(Node, diameter_traffic, request, [ReqT], Opts). + +%% route_session/1 + +route_session(ReqT) -> + route_session(ReqT, []). + +%% node_of_session_id/2 +%% +%% Return the node name encoded as optional value in a Session-Id, +%% assuming the id has been created with diameter:session_id/0. Lookup +%% the node name to ensure we don't convert arbitrary binaries to +%% atom. + +node_of_session_id([Id, _, _, Bin], #{id := Ids}) -> + lists:member(Id, Ids) andalso nodemap(Bin); + +node_of_session_id([_, _, _, Bin], _) -> + nodemap(Bin); + +node_of_session_id(_, _) -> + false. + +%% nodemap/1 + +nodemap(Bin) -> + try + ets:lookup_element(?NODE_TABLE, Bin, 2) + catch + error: badarg -> false + end. + +%% session_id/2 + +session_id(_, 0) -> %% give up + false; + +%% Session-Id = Command Code 263, V-bit = 0. +session_id(<<263:32, 0:1, _:7, Len:24, _/binary>> = Bin, _) -> + case Bin of + <<Avp:Len/binary, _/binary>> -> + <<_:8/binary, Sid/binary>> = Avp, + split(Sid); + _ -> + false + end; + +%% Jump to the next AVP. This is potentially costly for a message with +%% many AVPs and no Session-Id, which an attacker is prone to send. +%% 8.8 or RFC 6733 says that Session-Id SHOULD (but not MUST) appear +%% immediately following the Diameter Header, so there is no +%% guarantee. +session_id(<<_:40, Len:24, _/binary>> = Bin, N) -> + Pad = (4 - (Len rem 4)) rem 4, + case Bin of + <<_:Len/binary, _:Pad/binary, Rest/binary>> -> + session_id(Rest, if N == infinity -> N; true -> N-1 end); + _ -> + false + end; + +session_id(_, _) -> + false. + +%% split/1 +%% +%% Split a Session-Id at no more than three semicolons: the optional +%% value (if any) follows the third. binary:split/2 does better than +%% matching character by character, especially when the pattern is +%% compiled. + +split(Bin) -> + split(3, Bin, pattern()). + +%% split/3 + +split(0, Bin, _) -> + [Bin]; + +split(N, Bin, Pattern) -> + [H|T] = binary:split(Bin, Pattern), + [H | case T of + [] -> + T; + [Rest] -> + split(N-1, Rest, Pattern) + end]. + +%% pattern/0 +%% +%% Since this is being called in a watchdog process, compile the +%% pattern once and maintain it in the process dictionary. + +pattern() -> + case get(?MODULE) of + undefined -> + CP = binary:compile_pattern(<<$;>>), %% tuple + put(?MODULE, CP), + CP; + CP -> + CP + end. + +%% dispatch/1 + +dispatch(#{} = Opts) -> + maps:get(dispatch, Opts, []); + +dispatch(Opts) + when is_list(Opts) -> + Opts; + +dispatch(_) -> + []. + +%% search/1 +%% +%% Bound number of AVPs examined when looking for Session-Id. + +search(#{search := N}) + when is_integer(N), 0 =< N -> + N; + +search(N) + when is_integer(N), 0 =< N -> + N; + +search(_) -> + infinity. + +%% default/3 +%% +%% Choose a node when Session-Id lookup has failed. + +default(false, _, #{default := discard}, _) -> + false; + +default(false, _, #{default := local}, _) -> + node(); + +default(false, Sid, #{default := {M,F,A}}, Info) -> + {ServiceName, Bin} = Info, + apply(M, F, [Sid, ServiceName, Bin | A]); %% node() | false + +default(false, Sid, _, Info) -> %% aka {?MODULE, hash, []} + {ServiceName, Bin} = Info, + hash(Sid, ServiceName, Bin); + +default(Node, _, _, _) -> + Node. + +%% =========================================================================== + +%% hash/3 +%% +%% Consistent hashing of Session-Id to an attached node, or the local +%% node if Session-Id = false or no attached nodes. + +hash(Sid, ServiceName, _) -> + case false /= Sid andalso attached(ServiceName) of + [_|_] = Nodes -> + hash(Sid, Nodes); + _ -> + node() + end. + +%% hash/2 +%% +%% Consistent hashing on arbitrary key/values. Returns false if the +%% list is empty. + +%% No key or no values. +hash(_, []) -> + false; + +%% Not much choice. +hash(_, [Value]) -> + Value; + +%% Hash on a circle and choose the closest predecessor. +hash(Key, Values) -> + Hash = ?HASH(Key), + tl(lists:foldl(fun(V,A) -> + choose(Hash, [?HASH({Key, V}) | V], A) + end, + false, %% < list() + Values)). + +%% choose/3 + +choose(Hash, [Hash1 | _] = T, [Hash2 | _]) + when Hash1 =< Hash, Hash < Hash2 -> + T; + +choose(Hash, [Hash1 | _], [Hash2 | _] = T) + when Hash2 =< Hash, Hash < Hash1 -> + T; + +choose(_, T1, T2) -> + max(T1, T2). + +%% =========================================================================== + +%% attach/1 +%% +%% Register the local node as a handler of incoming requests for the +%% specified services when using the route_session/2 spawn_opt +%% callback. + +attach(ServiceNames) -> + abcast({attach, node(), ServiceNames}). + +%% detach/1 +%% +%% Deregister the local node as a handler of incoming requests. + +detach(ServiceNames) -> + abcast({detach, node(), ServiceNames}). + +%% abcast/1 + +abcast(T) -> + gen_server:abcast([node() | nodes()], ?SERVER, T), + ok. + +%% attached/1 + +attached(ServiceName) -> + try + ets:lookup_element(?SERVICE_TABLE, ServiceName, 2) + catch + error: badarg -> [] + end. + +%% cast/2 + +cast(Node, T) -> + gen_server:cast({?SERVER, Node}, T). + +%% attach/2 + +attach(Node, S) -> + case sets:to_list(S) of + [] -> + ok; + Services -> + cast(Node, {attach, node(), Services}) + end. + +%% =========================================================================== + +start_link() -> + gen_server:start_link({local, ?SERVER}, ?MODULE, _Args = [], _Opts = []). + +%% init/1 +%% +%% Maintain [node() | nodes()] in a table that maps from binary-valued +%% names, so we can lookup the corresponding atoms rather than convert +%% binaries that aren't necessarily node names. + +init([]) -> + ets:new(?NODE_TABLE, [set, named_table]), + ets:new(?SERVICE_TABLE, [bag, named_table]), + ok = net_kernel:monitor_nodes(true, [{node_type, all}, nodedown_reason]), + ets:insert(?NODE_TABLE, [{?B(N), N} || N <- [node() | nodes()]]), + abcast({attach, node()}), + {ok, sets:new()}. + +%% handle_call/3 + +handle_call(_, _From, S) -> + {reply, nok, S}. + +%% handle_cast/2 + +%% Remote node is asking which services the local node wants to handle. +handle_cast({attach, Node}, S) + when Node /= node() -> + attach(Node, S), + {noreply, S}; + +%% Node wants to handle incoming requests ... +handle_cast({attach, Node, ServiceNames}, S) -> + ets:insert(?SERVICE_TABLE, [{N, Node} || N <- ServiceNames]), + {noreply, case node() of + Node -> + sets:union(S, sets:from_list(ServiceNames)); + _ -> + S + end}; + +%% ... or not. +handle_cast({detach, Node, ServiceNames}, S) -> + ets:select_delete(?SERVICE_TABLE, [{{'$1', Node}, + [?ORCOND([{'==', '$1', {const, N}} + || N <- ServiceNames])], + [true]}]), + {noreply, case node() of + Node -> + sets:subtract(S, sets:from_list(ServiceNames)); + _ -> + S + end}; + +handle_cast(_, S) -> + {noreply, S}. + +%% handle_info/2 + +handle_info({nodeup, Node, _}, S) -> + ets:insert(?NODE_TABLE, {?B(Node), Node}), + cast(Node, {attach, node()}), %% ask which services remote node handles + attach(Node, S), %% say which service local node handles + {noreply, S}; + +handle_info({nodedown, Node, _}, S) -> + ets:delete(?NODE_TABLE, ?B(Node)), + ets:select_delete(?SERVICE_TABLE, [{{'_', Node}, [], [true]}]), + {noreply, S}; + +handle_info(_, S) -> + {noreply, S}. + +%% terminate/2 + +terminate(_, _) -> + ok. + +%% code_change/3 + +code_change(_OldVsn, State, _Extra) -> + {ok, State}. diff --git a/lib/diameter/src/base/diameter_misc_sup.erl b/lib/diameter/src/base/diameter_misc_sup.erl index 343688be23..fec5a41b5c 100644 --- a/lib/diameter/src/base/diameter_misc_sup.erl +++ b/lib/diameter/src/base/diameter_misc_sup.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2010-2016. All Rights Reserved. +%% Copyright Ericsson AB 2010-2019. All Rights Reserved. %% %% Licensed under the Apache License, Version 2.0 (the "License"); %% you may not use this file except in compliance with the License. @@ -35,6 +35,7 @@ diameter_stats, %% statistics counter management diameter_reg, %% service/property publishing diameter_peer, %% remote peer manager + diameter_dist, %% request distribution diameter_config]). %% configuration/restart %% start_link/0 diff --git a/lib/diameter/src/base/diameter_traffic.erl b/lib/diameter/src/base/diameter_traffic.erl index 2d3e4a2ac9..8423e30269 100644 --- a/lib/diameter/src/base/diameter_traffic.erl +++ b/lib/diameter/src/base/diameter_traffic.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2013-2017. All Rights Reserved. +%% Copyright Ericsson AB 2013-2019. All Rights Reserved. %% %% Licensed under the Apache License, Version 2.0 (the "License"); %% you may not use this file except in compliance with the License. @@ -42,8 +42,12 @@ peer_up/1, peer_down/1]). +%% towards diameter_dist +-export([request_info/1]). + %% internal -export([send/1, %% send from remote node + request/1, %% process request in handler process init/1]). %% monitor process start -include_lib("diameter/include/diameter.hrl"). @@ -232,7 +236,7 @@ incr_rc(Dir, Pkt, TPid, MsgDict, AppDict, Dict0) -> -spec receive_message(pid(), Route, #diameter_packet{}, module(), RecvData) -> pid() %% request handler | boolean() %% answer, known request or not - | discard %% request discarded by MFA + | discard %% request discarded when Route :: {Handler, RequestRef, TPid} | Ack, RecvData :: {[SpawnOpt], #recvdata{}}, @@ -252,7 +256,8 @@ receive_message(TPid, Route, Pkt, Dict0, RecvData) -> recv(true, Ack, TPid, Pkt, Dict0, T) when is_boolean(Ack) -> {Opts, RecvData} = T, - spawn_request(Ack, TPid, Pkt, Dict0, RecvData, Opts); + AppT = find_app(TPid, Pkt, RecvData), + ack(Ack, TPid, spawn_request(AppT, Opts, Ack, TPid, Pkt, Dict0, RecvData)); %% ... answer to known request ... recv(false, {Pid, Ref, TPid}, _, Pkt, Dict0, _) -> @@ -274,58 +279,73 @@ recv(false, false, TPid, Pkt, _, _) -> incr(TPid, {{unknown, 0}, recv, discarded}), false. -%% spawn_request/6 +%% spawn_request/7 + +spawn_request(false, _, _, _, _, _, _) -> %% no transport + discard; -%% An MFA should return a pid() or the atom 'discard'. The latter -%% results in an acknowledgment back to the transport process when -%% appropriate, to ensure that send/recv callbacks can count -%% outstanding requests. Acknowledgement is implicit if the +%% An MFA should return the pid() of a process in which the argument +%% fun in applied, or the atom 'discard' if the fun is not applied. +%% The latter results in an acknowledgment back to the transport +%% process when appropriate, to ensure that send/recv callbacks can +%% count outstanding requests. Acknowledgement is implicit if the %% handler process dies (in a handle_request callback for example). -spawn_request(Ack, TPid, Pkt, Dict0, RecvData, {M,F,A}) -> - ReqF = fun() -> - ack(Ack, TPid, recv_request(Ack, TPid, Pkt, Dict0, RecvData)) - end, - ack(Ack, TPid, apply(M, F, [ReqF | A])); +spawn_request(AppT, {M,F,A}, Ack, TPid, Pkt, Dict0, RecvData) -> + %% Term to pass to request/1 in an appropriate process. Module + %% diameter_dist implements callbacks. + ReqT = {Pkt, AppT, Ack, TPid, Dict0, RecvData}, + apply(M, F, [ReqT | A]); %% A spawned process acks implicitly when it dies, so there's no need %% to handle 'discard'. -spawn_request(Ack, TPid, Pkt, Dict0, RecvData, Opts) -> +spawn_request(AppT, Opts, Ack, TPid, Pkt, Dict0, RecvData) -> spawn_opt(fun() -> - recv_request(Ack, TPid, Pkt, Dict0, RecvData) + recv_request(Ack, TPid, Pkt, Dict0, RecvData, AppT) end, Opts). +%% request_info/1 +%% +%% Limited request information for diameter_dist. + +request_info({Pkt, _AppT, _Ack, _TPid, _Dict0, RecvData} = _ReqT) -> + {RecvData#recvdata.service_name, Pkt#diameter_packet.bin}. + +%% request/1 +%% +%% Called from a handler process chosen by a transport spawn_opt MFA +%% to process an incoming request. + +request({Pkt, AppT, Ack, TPid, Dict0, RecvData} = _ReqT) -> + ack(Ack, TPid, recv_request(Ack, TPid, Pkt, Dict0, RecvData, AppT)). + %% ack/3 ack(Ack, TPid, RC) -> - RC == discard andalso Ack andalso (TPid ! {send, false}), + RC == discard + andalso Ack + andalso (TPid ! {send, false}), RC. %% --------------------------------------------------------------------------- -%% recv_request/5 +%% recv_request/6 %% --------------------------------------------------------------------------- -spec recv_request(Ack :: boolean(), TPid :: pid(), #diameter_packet{}, Dict0 :: module(), - #recvdata{}) + #recvdata{}, + AppT :: {#diameter_app{}, #diameter_caps{}} + | #diameter_caps{}) %% no suitable app -> ok %% answer was sent - | discard %% or not - | false. %% no transport - -recv_request(Ack, - TPid, - #diameter_packet{header = #diameter_header{application_id = Id}} - = Pkt, - Dict0, - #recvdata{peerT = PeerT, - apps = Apps, - counters = Count} - = RecvData) -> + | discard. %% or not + +recv_request(Ack, TPid, Pkt, Dict0, RecvData, AppT) -> Ack andalso (TPid ! {handler, self()}), - case diameter_service:find_incoming_app(PeerT, TPid, Id, Apps) of + case AppT of {#diameter_app{id = Aid, dictionary = AppDict} = App, Caps} -> + Count = RecvData#recvdata.counters, Count andalso incr(recv, Pkt, TPid, AppDict), DecPkt = decode(Aid, AppDict, RecvData, Pkt), Count andalso incr_error(recv, DecPkt, TPid, AppDict), @@ -349,11 +369,20 @@ recv_request(Ack, Dict0, RecvData, DecPkt, - [[]]); - false = No -> %% transport has gone down - No + [[]]) end. +%% find_app/3 +%% +%% Lookup the application of a received Diameter request on the node +%% on which it's received. + +find_app(TPid, + #diameter_packet{header = #diameter_header{application_id = Id}}, + #recvdata{peerT = PeerT, + apps = Apps}) -> + diameter_service:find_incoming_app(PeerT, TPid, Id, Apps). + %% decode/4 decode(Id, Dict, #recvdata{codec = Opts}, Pkt) -> diff --git a/lib/diameter/src/diameter.appup.src b/lib/diameter/src/diameter.appup.src index 4e6b983bac..52263633fb 100644 --- a/lib/diameter/src/diameter.appup.src +++ b/lib/diameter/src/diameter.appup.src @@ -60,7 +60,8 @@ {"2.1.3", [{restart_application, diameter}]}, %% 20.2 {"2.1.4", [{restart_application, diameter}]}, %% 20.3 {"2.1.4.1", [{restart_application, diameter}]}, %% 20.3.8.19 - {"2.1.5", [{update, diameter_peer_fsm}]} %% 21.0 + {"2.1.5", [{restart_application, diameter}]}, %% 21.0 + {"2.1.6", [{restart_application, diameter}]} %% 21.1 ], [ {"0.9", [{restart_application, diameter}]}, @@ -102,6 +103,7 @@ {"2.1.3", [{restart_application, diameter}]}, {"2.1.4", [{restart_application, diameter}]}, {"2.1.4.1", [{restart_application, diameter}]}, - {"2.1.5", [{update, diameter_peer_fsm}]} + {"2.1.5", [{restart_application, diameter}]}, + {"2.1.6", [{restart_application, diameter}]} ] }. diff --git a/lib/diameter/src/modules.mk b/lib/diameter/src/modules.mk index bb86de016a..d16292bb88 100644 --- a/lib/diameter/src/modules.mk +++ b/lib/diameter/src/modules.mk @@ -1,7 +1,7 @@ # %CopyrightBegin% # -# Copyright Ericsson AB 2010-2017. All Rights Reserved. +# Copyright Ericsson AB 2010-2019. All Rights Reserved. # # Licensed under the Apache License, Version 2.0 (the "License"); # you may not use this file except in compliance with the License. @@ -40,6 +40,7 @@ RT_MODULES = \ base/diameter_config \ base/diameter_config_sup \ base/diameter_codec \ + base/diameter_dist \ base/diameter_gen \ base/diameter_lib \ base/diameter_misc_sup \ diff --git a/lib/diameter/test/diameter_dist_SUITE.erl b/lib/diameter/test/diameter_dist_SUITE.erl new file mode 100644 index 0000000000..b2e4c35b9a --- /dev/null +++ b/lib/diameter/test/diameter_dist_SUITE.erl @@ -0,0 +1,332 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2019. All Rights Reserved. +%% +%% Licensed under the Apache License, Version 2.0 (the "License"); +%% you may not use this file except in compliance with the License. +%% 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% +%% + +%% +%% Tests of traffic between two Diameter nodes, the server being +%% spread across three Erlang nodes. +%% + +-module(diameter_dist_SUITE). + +-export([suite/0, + all/0]). + +%% testcases +-export([enslave/1, enslave/0, + ping/1, + start/1, + connect/1, + send/1, + stop/1, stop/0]). + +%% diameter callbacks +-export([peer_up/3, + peer_down/3, + pick_peer/4, + prepare_request/3, + prepare_retransmit/3, + handle_answer/4, + handle_error/4, + handle_request/3]). + +-export([call/1]). + +-include("diameter.hrl"). +-include("diameter_gen_base_rfc6733.hrl"). + +%% =========================================================================== + +-define(util, diameter_util). + +-define(CLIENT, 'CLIENT'). +-define(SERVER, 'SERVER'). +-define(REALM, "erlang.org"). +-define(DICT, diameter_gen_base_rfc6733). +-define(ADDR, {127,0,0,1}). + +%% Config for diameter:start_service/2. +-define(SERVICE(Host), + [{'Origin-Host', Host ++ [$.|?REALM]}, + {'Origin-Realm', ?REALM}, + {'Host-IP-Address', [?ADDR]}, + {'Vendor-Id', 12345}, + {'Product-Name', "OTP/diameter"}, + {'Auth-Application-Id', [?DICT:id()]}, + {'Origin-State-Id', origin()}, + {spawn_opt, {diameter_dist, route_session, [#{id => []}]}}, + {sequence, fun sequence/0}, + {string_decode, false}, + {application, [{dictionary, ?DICT}, + {module, ?MODULE}, + {request_errors, callback}, + {answer_errors, callback}]}]). + +-define(SUCCESS, 2001). +-define(BUSY, 3004). +-define(LOGOUT, ?'DIAMETER_BASE_TERMINATION-CAUSE_LOGOUT'). +-define(MOVED, ?'DIAMETER_BASE_TERMINATION-CAUSE_USER_MOVED'). +-define(TIMEOUT, ?'DIAMETER_BASE_TERMINATION-CAUSE_SESSION_TIMEOUT'). + +-define(L, atom_to_list). +-define(A, list_to_atom). + +%% The order here is significant and causes the server to listen +%% before the clients connect. The server listens on the first node, +%% and distributes requests to the other two. +-define(NODES, [{server0, ?SERVER}, + {server1, ?SERVER}, + {server2, ?SERVER}, + {client, ?CLIENT}]). + +%% Options to ct_slave:start/2. +-define(TIMEOUTS, [{T, 15000} || T <- [boot_timeout, + init_timeout, + start_timeout]]). + +%% =========================================================================== + +suite() -> + [{timetrap, {seconds, 60}}]. + +all() -> + [enslave, + ping, + start, + connect, + send, + stop]. + +%% =========================================================================== +%% start/stop testcases + +%% enslave/1 +%% +%% Start four slave nodes, three to implement a Diameter server, +%% one to implement a client. + +enslave() -> + [{timetrap, {seconds, 30*length(?NODES)}}]. + +enslave(Config) -> + Here = filename:dirname(code:which(?MODULE)), + Ebin = filename:join([Here, "..", "ebin"]), + Dirs = [Here, Ebin], + Nodes = [{N,S} || {M,S} <- ?NODES, N <- [slave(M, Dirs)]], + ?util:write_priv(Config, nodes, [{N,S} || {{N,ok},S} <- Nodes]), + [] = [{T,S} || {{_,E} = T, S} <- Nodes, E /= ok]. + +slave(Name, Dirs) -> + add_pathsa(Dirs, ct_slave:start(Name, ?TIMEOUTS)). + +add_pathsa(Dirs, {ok, Node}) -> + {Node, rpc:call(Node, code, add_pathsa, [Dirs])}; +add_pathsa(_, No) -> + {No, error}. + +%% ping/1 +%% +%% Ensure the server nodes are connected so that diameter_dist can attach. + +ping({S, Nodes}) -> + ?SERVER = S, + [N || {N,_} <- Nodes, + node() /= N, + pang <- [net_adm:ping(N)]]; + +ping(Config) -> + Nodes = lists:droplast(?util:read_priv(Config, nodes)), + [] = [{N,RC} || {N,S} <- Nodes, + RC <- [rpc:call(N, ?MODULE, ping, [{S,Nodes}])], + RC /= []]. + +%% start/1 +%% +%% Start diameter services. + +start(SvcName) + when is_atom(SvcName) -> + ok = diameter:start(), + ok = diameter:start_service(SvcName, ?SERVICE((?L(SvcName)))); + +start(Config) -> + Nodes = ?util:read_priv(Config, nodes), + [] = [{N,RC} || {N,S} <- Nodes, + RC <- [rpc:call(N, ?MODULE, start, [S])], + RC /= ok]. + +sequence() -> + sequence(sname()). + +sequence(client) -> + {0,32}; +sequence(Server) -> + "server" ++ N = ?L(Server), + {list_to_integer(N), 30}. + +origin() -> + origin(sname()). + +origin(client) -> + 99; +origin(Server) -> + "server" ++ N = ?L(Server), + list_to_integer(N). + +%% connect/1 +%% +%% Establish one connection from the client, terminated on the first +%% server node, the others handling requests. + +connect({?SERVER, Config, [{Node, _} | _]}) -> + if Node == node() -> %% server0 + ?util:write_priv(Config, lref, {Node, ?util:listen(?SERVER, tcp)}); + true -> + diameter_dist:attach([?SERVER]) + end, + ok; + +connect({?CLIENT, Config, _}) -> + ?util:connect(?CLIENT, tcp, ?util:read_priv(Config, lref)), + ok; + +connect(Config) -> + Nodes = ?util:read_priv(Config, nodes), + [] = [{N,RC} || {N,S} <- Nodes, + RC <- [rpc:call(N, ?MODULE, connect, [{S, Config, Nodes}])], + RC /= ok]. + +%% stop/1 +%% +%% Stop the slave nodes. + +stop() -> + [{timetrap, {seconds, 30*length(?NODES)}}]. + +stop(_Config) -> + [] = [{N,E} || {N,_} <- ?NODES, + {error, _, _} = E <- [ct_slave:stop(N)]]. + +%% =========================================================================== +%% traffic testcases + +%% send/1 +%% +%% Send 100 requests and ensure the node name sent as User-Name isn't +%% the node terminating transport. + +send(Config) -> + send(Config, 100, dict:new()). + +%% send/2 + +send(Config, 0, Dict) -> + [{Server0, _} | _] = ?util:read_priv(Config, nodes) , + Node = atom_to_binary(Server0, utf8), + {false, _} = {dict:is_key(Node, Dict), dict:to_list(Dict)}; + +send(Config, N, Dict) -> + #diameter_base_STA{'Result-Code' = ?SUCCESS, + 'User-Name' = [ServerNode]} + = send(Config, str(?LOGOUT)), + true = is_binary(ServerNode), + send(Config, N-1, dict:update_counter(ServerNode, 1, Dict)). + +%% =========================================================================== + +str(Cause) -> + #diameter_base_STR{'Destination-Realm' = ?REALM, + 'Auth-Application-Id' = ?DICT:id(), + 'Termination-Cause' = Cause}. + +%% send/2 + +send(Config, Req) -> + {Node, _} = lists:last(?util:read_priv(Config, nodes)), + rpc:call(Node, ?MODULE, call, [Req]). + +%% call/1 + +call(Req) -> + diameter:call(?CLIENT, ?DICT, Req, []). + +%% sname/0 + +sname() -> + ?A(hd(string:tokens(?L(node()), "@"))). + +%% =========================================================================== +%% diameter callbacks + +%% peer_up/3 + +peer_up(_SvcName, _Peer, State) -> + State. + +%% peer_down/3 + +peer_down(_SvcName, _Peer, State) -> + State. + +%% pick_peer/4 + +pick_peer([Peer], [], ?CLIENT, _State) -> + {ok, Peer}. + +%% prepare_request/3 + +prepare_request(Pkt, ?CLIENT, {_Ref, Caps}) -> + #diameter_packet{msg = Req} + = Pkt, + #diameter_caps{origin_host = {OH, _}, + origin_realm = {OR, _}} + = Caps, + {send, Req#diameter_base_STR{'Origin-Host' = OH, + 'Origin-Realm' = OR, + 'Session-Id' = diameter:session_id(OH)}}. + +%% prepare_retransmit/3 + +prepare_retransmit(_, ?CLIENT, _) -> + discard. + +%% handle_answer/5 + +handle_answer(Pkt, _Req, ?CLIENT, _Peer) -> + #diameter_packet{msg = Rec, errors = []} = Pkt, + Rec. + +%% handle_error/5 + +handle_error(Reason, _Req, ?CLIENT, _Peer) -> + {error, Reason}. + +%% handle_request/3 + +handle_request(Pkt, ?SERVER, {_, Caps}) -> + #diameter_packet{msg = #diameter_base_STR{'Session-Id' = SId}} + = Pkt, + #diameter_caps{origin_host = {OH, _}, + origin_realm = {OR, _}} + = Caps, + {reply, #diameter_base_STA{'Result-Code' = ?SUCCESS, + 'Session-Id' = SId, + 'Origin-Host' = OH, + 'Origin-Realm' = OR, + 'User-Name' = [atom_to_binary(node(), utf8)]}}. diff --git a/lib/diameter/test/diameter_distribution_SUITE.erl b/lib/diameter/test/diameter_distribution_SUITE.erl index 5146f68ff1..5fe02284ae 100644 --- a/lib/diameter/test/diameter_distribution_SUITE.erl +++ b/lib/diameter/test/diameter_distribution_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2013-2016. All Rights Reserved. +%% Copyright Ericsson AB 2013-2019. All Rights Reserved. %% %% Licensed under the Apache License, Version 2.0 (the "License"); %% you may not use this file except in compliance with the License. @@ -76,6 +76,7 @@ {share_peers, peers()}, {use_shared_peers, peers()}, {restrict_connections, false}, + {spawn_opt, {diameter_dist, spawn_local, []}}, {sequence, fun sequence/0}, {application, [{dictionary, ?DICT}, {module, ?MODULE}, @@ -125,7 +126,7 @@ all() -> %% enslave/1 %% %% Start four slave nodes, one to implement a Diameter server, -%% two three to implement a client. +%% three to implement a client. enslave() -> [{timetrap, {seconds, 30*length(?NODES)}}]. @@ -331,6 +332,8 @@ prepare_request(Pkt, ?CLIENT, {_Ref, Caps}, {_, client0}) -> 'Origin-Realm' = OR, 'Session-Id' = diameter:session_id(OH)}}. +%% prepare_retransmit/4 + prepare_retransmit(Pkt, ?CLIENT, _, {_, client0}) -> #diameter_packet{msg = #diameter_base_STR{'Termination-Cause' = ?MOVED}} = Pkt, %% assert diff --git a/lib/diameter/test/diameter_pool_SUITE.erl b/lib/diameter/test/diameter_pool_SUITE.erl index 97c16940ff..a36a4fa17a 100644 --- a/lib/diameter/test/diameter_pool_SUITE.erl +++ b/lib/diameter/test/diameter_pool_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2015-2017. All Rights Reserved. +%% Copyright Ericsson AB 2015-2019. All Rights Reserved. %% %% Licensed under the Apache License, Version 2.0 (the "License"); %% you may not use this file except in compliance with the License. @@ -51,6 +51,7 @@ {'Auth-Application-Id', [0]}, %% common {'Acct-Application-Id', [3]}, %% accounting {restrict_connections, false}, + {spawn_opt, {diameter_dist, route_session, []}}, {application, [{alias, common}, {dictionary, diameter_gen_base_rfc6733}, {module, diameter_callback}]}, diff --git a/lib/diameter/test/diameter_traffic_SUITE.erl b/lib/diameter/test/diameter_traffic_SUITE.erl index 434aef01dd..47b00c25a2 100644 --- a/lib/diameter/test/diameter_traffic_SUITE.erl +++ b/lib/diameter/test/diameter_traffic_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2010-2018. All Rights Reserved. +%% Copyright Ericsson AB 2010-2019. All Rights Reserved. %% %% Licensed under the Apache License, Version 2.0 (the "License"); %% you may not use this file except in compliance with the License. @@ -539,8 +539,7 @@ add_transports(Config) -> ++ [{unordered, unordered()} || T == sctp], [{capabilities_cb, fun capx/2}, {pool_size, 8} - | server_apps()] - ++ [{spawn_opt, {erlang, spawn, []}} || CS]), + | server_apps()]), Cs = [?util:connect(CN, [T, {sender, CS} | client_opts(T)], LRef, diff --git a/lib/diameter/test/modules.mk b/lib/diameter/test/modules.mk index 0c73adca12..90b0a25d5f 100644 --- a/lib/diameter/test/modules.mk +++ b/lib/diameter/test/modules.mk @@ -1,7 +1,7 @@ # %CopyrightBegin% # -# Copyright Ericsson AB 2010-2017. All Rights Reserved. +# Copyright Ericsson AB 2010-2019. All Rights Reserved. # # Licensed under the Apache License, Version 2.0 (the "License"); # you may not use this file except in compliance with the License. @@ -31,6 +31,7 @@ MODULES = \ diameter_codec_test \ diameter_config_SUITE \ diameter_compiler_SUITE \ + diameter_dist_SUITE \ diameter_distribution_SUITE \ diameter_dpr_SUITE \ diameter_event_SUITE \ diff --git a/lib/ftp/test/ftp_SUITE.erl b/lib/ftp/test/ftp_SUITE.erl index 81147b5821..0b070ee8cb 100644 --- a/lib/ftp/test/ftp_SUITE.erl +++ b/lib/ftp/test/ftp_SUITE.erl @@ -96,6 +96,7 @@ ftp_tests()-> recv_chunk, recv_chunk_twice, recv_chunk_three_times, + recv_chunk_delay, type, quote, error_elogin, @@ -732,21 +733,28 @@ recv_chunk(Pid, Acc) -> Error end. -%% Make new test case that uses this or new code -%% only test one thing at the time -%% delay_recv_chunk(Pid) -> -%% delay_recv_chunk(Pid, <<>>). -%% delay_recv_chunk(Pid, Acc) -> -%% ct:pal("FOO ~p", [byte_size(Acc)]), -%% case ftp:recv_chunk(Pid) of -%% ok -> -%% {ok, Acc}; -%% {ok, Bin} -> -%% ct:sleep(100), -%% delay_recv_chunk(Pid, <<Acc/binary, Bin/binary>>); -%% Error -> -%% Error -%% end. +recv_chunk_delay(Config0) when is_list(Config0) -> + File1 = "big_file1.txt", + Contents = list_to_binary(lists:duplicate(1000, lists:seq(0,255))), + Config = set_state([reset, {mkfile,File1,Contents}], Config0), + Pid = proplists:get_value(ftp, Config), + ok = ftp:recv_chunk_start(Pid, id2ftp(File1,Config)), + {ok, ReceivedContents} = delay_recv_chunk(Pid), + find_diff(ReceivedContents, Contents). + +delay_recv_chunk(Pid) -> + delay_recv_chunk(Pid, <<>>). +delay_recv_chunk(Pid, Acc) -> + ct:pal("Recived size ~p", [byte_size(Acc)]), + case ftp:recv_chunk(Pid) of + ok -> + {ok, Acc}; + {ok, Bin} -> + ct:sleep(100), + delay_recv_chunk(Pid, <<Acc/binary, Bin/binary>>); + Error -> + Error + end. %%------------------------------------------------------------------------- type() -> diff --git a/lib/kernel/doc/src/kernel_app.xml b/lib/kernel/doc/src/kernel_app.xml index 15dbdb47dc..dbd83e1a6e 100644 --- a/lib/kernel/doc/src/kernel_app.xml +++ b/lib/kernel/doc/src/kernel_app.xml @@ -510,11 +510,13 @@ MaxT = TickTime + TickTime / 4</code> parameters for Logger are not set.</p> <taglist> <tag><c>error_logger</c></tag> - <item>Replaced by setting the type of the default - <seealso marker="logger_std_h#type"><c>logger_std_h</c></seealso> - to the same value. Example: + <item>Replaced by setting the <seealso + marker="logger_std_h#type"><c>type</c></seealso>, and possibly + <seealso marker="logger_std_h#file"><c>file</c></seealso> and + <seealso marker="logger_std_h#modes"><c>modes</c></seealso> + parameters of the default <c>logger_std_h</c> handler. Example: <code type="none"> -erl -kernel logger '[{handler,default,logger_std_h,#{config=>#{type=>{file,"/tmp/erlang.log"}}}}]' +erl -kernel logger '[{handler,default,logger_std_h,#{config=>#{file=>"/tmp/erlang.log"}}}]' </code> </item> <tag><c>error_logger_format_depth</c></tag> diff --git a/lib/kernel/doc/src/logger.xml b/lib/kernel/doc/src/logger.xml index e6448e144e..ebebcaa1ae 100644 --- a/lib/kernel/doc/src/logger.xml +++ b/lib/kernel/doc/src/logger.xml @@ -66,7 +66,7 @@ logger:error("error happened because: ~p", [Reason]). % Without macro [{kernel, [{logger, [{handler, default, logger_std_h, - #{config => #{type => {file, "path/to/file.log"}}}}]}]}]. + #{config => #{file => "path/to/file.log"}}}]}]}]. </code> <p> For more information about: diff --git a/lib/kernel/doc/src/logger_chapter.xml b/lib/kernel/doc/src/logger_chapter.xml index 5ed7397135..bfd0acf634 100644 --- a/lib/kernel/doc/src/logger_chapter.xml +++ b/lib/kernel/doc/src/logger_chapter.xml @@ -801,7 +801,7 @@ logger:debug(#{got => connection_request, id => Id, state => State}, [{kernel, [{logger, [{handler, default, logger_std_h, % {handler, HandlerId, Module, - #{config => #{type => {file,"log/erlang.log"}}}} % Config} + #{config => #{file => "log/erlang.log"}}} % Config} ]}]}]. </code> <p>Modify the default handler to print each log event as a @@ -831,10 +831,10 @@ logger:debug(#{got => connection_request, id => Id, state => State}, [{logger, [{handler, default, logger_std_h, #{level => error, - config => #{type => {file, "log/erlang.log"}}}}, + config => #{file => "log/erlang.log"}}}, {handler, info, logger_std_h, #{level => debug, - config => #{type => {file, "log/debug.log"}}}} + config => #{file => "log/debug.log"}}} ]}]}]. </code> </section> @@ -1004,10 +1004,10 @@ ok</pre> <p>Then, add a new handler which prints to file. You can use the handler module <seealso marker="logger_std_h"><c>logger_std_h</c></seealso>, - and specify type <c>{file,File}</c>.:</p> + and configure it to log to file:</p> <pre> -4> <input>Config = #{config => #{type => {file,"./info.log"}}, level => info}.</input> -#{config => #{type => {file,"./info.log"}},level => info} +4> <input>Config = #{config => #{file => "./info.log"}, level => info}.</input> +#{config => #{file => "./info.log"},level => info} 5> <input>logger:add_handler(myhandler, logger_std_h, Config).</input> ok</pre> <p>Since <c>filter_default</c> defaults to <c>log</c>, this @@ -1246,7 +1246,7 @@ do_log(Fd, LogEvent, #{formatter := {FModule, FConfig}}) -> <p>A configuration example:</p> <code type="none"> logger:add_handler(my_standard_h, logger_std_h, - #{config => #{type => {file,"./system_info.log"}, + #{config => #{file => "./system_info.log", sync_mode_qlen => 100, drop_mode_qlen => 1000, flush_qlen => 2000}}). diff --git a/lib/kernel/doc/src/logger_std_h.xml b/lib/kernel/doc/src/logger_std_h.xml index fcd180abd6..5ed1a2f210 100644 --- a/lib/kernel/doc/src/logger_std_h.xml +++ b/lib/kernel/doc/src/logger_std_h.xml @@ -55,30 +55,105 @@ is stored in a sub map with the key <c>config</c>, and can contain the following parameters:</p> <taglist> - <tag><marker id="type"/><c>type</c></tag> + <tag><marker id="type"/><c>type = standard_io | standard_error | file</c></tag> <item> - <p>This has the value <c>standard_io</c>, <c>standard_error</c>, - <c>{file,LogFileName}</c>, or <c>{file,LogFileName,LogFileOpts}</c>.</p> - <p>If <c>LogFileOpts</c> is specified, it replaces the default - list of options used when opening the log file. The default - list is <c>[raw,append,delayed_write]</c>. One reason to do - so can be to change <c>append</c> to, for - example, <c>write</c>, ensuring that the old log is - truncated when a node is restarted. See the reference manual - for <seealso marker="file#open-2"><c>file:open/2</c></seealso> - for more information about file options.</p> + <p>Specifies the log destination.</p> + <p>The value is set when the handler is added, and it can not + be changed in runtime.</p> + <p>Defaults to <c>standard_io</c>, unless + parameter <seealso marker="#file"><c>file</c></seealso> is + given, in which case it defaults to <c>file</c>.</p> + </item> + <tag><marker id="file"/><c>file = </c><seealso marker="file#type-filename"><c>file:filename()</c></seealso></tag> + <item> + <p>This specifies the name of the log file when the handler is + of type <c>file</c>.</p> + <p>The value is set when the handler is added, and it can not + be changed in runtime.</p> + <p>Defaults to the same name as the handler identity, in the + current directory.</p> + </item> + <tag><marker id="modes"/><c>modes = [</c><seealso marker="file#type-mode"><c>file:mode()</c></seealso><c>]</c></tag> + <item> + <p>This specifies the file modes to use when opening the log + file, + see <seealso marker="file#open-2"><c>file:open/2</c></seealso>. + If <c>modes</c> are not specified, the default list used + is <c>[raw,append,delayed_write]</c>. If <c>modes</c> are + specified, the list replaces the default modes list with the + following adjustments:</p> + <list> + <item> + If <c>raw</c> is not found in the list, it is added. + </item> + <item> + If none of <c>write</c>, <c>append</c> or <c>exclusive</c> is + found in the list, <c>append</c> is added.</item> + <item>If none of <c>delayed_write</c> + or <c>{delayed_write,Size,Delay}</c> is found in the + list, <c>delayed_write</c> is added.</item> + </list> <p>Log files are always UTF-8 encoded. The encoding can not be - changed by setting the option <c>{encoding,Encoding}</c> - in <c>LogFileOpts</c>.</p> - <p>Notice that the standard handler does not have support for - circular logging. Use the disk_log handler, - <seealso marker="logger_disk_log_h"><c>logger_disk_log_h</c></seealso>, - for this.</p> + changed by setting the mode <c>{encoding,Encoding}</c>.</p> <p>The value is set when the handler is added, and it can not be changed in runtime.</p> - <p>Defaults to <c>standard_io</c>.</p> + <p>Defaults to <c>[raw,append,delayed_write]</c>.</p> + </item> + <tag><marker id="max_no_bytes"/><c>max_no_bytes = pos_integer() | infinity</c></tag> + <item> + <p>This parameter specifies if the log file should be rotated + or not. The value <c>infinity</c> means the log file will + grow indefinitely, while an integer value specifies at which + file size (bytes) the file is rotated.</p> + <p>Defaults to <c>infinity</c>.</p> + </item> + <tag><marker id="max_no_files"/><c>max_no_files = non_neg_integer()</c></tag> + <item> + <p>This parameter specifies the number of rotated log file + archives to keep. This has meaning only + if <seealso marker="#max_no_bytes"><c>max_no_bytes</c></seealso> + is set to an integer value.</p> + <p>The log archives are + named <c>FileName.0</c>, <c>FileName.1</c>, + ... <c>FileName.N</c>, where <c>FileName</c> is the name of + the current log file. <c>FileName.0</c> is the newest of the + archives. The maximum value for <c>N</c> is the value + of <c>max_no_files</c> minus 1.</p> + <p>Notice that setting this value to <c>0</c> does not turn of + rotation. It only specifies that no archives are kept.</p> + <p>Defaults to <c>0</c>.</p> + </item> + <tag><marker id="compress_on_rotate"/><c>compress_on_rotate = boolean()</c></tag> + <item> + <p>This parameter specifies if the rotated log file archives + shall be compressed or not. If set to <c>true</c>, all + archives are compressed with <c>gzip</c>, and renamed + to <c>FileName.N.gz</c></p> + <p><c>compress_on_rotate</c> has no meaning if <seealso + marker="#max_no_bytes"><c>max_no_bytes</c></seealso> has the + value <c>infinity</c>.</p> + <p>Defaults to <c>false</c>.</p> + </item> + <tag><marker id="file_check"/><c>file_check = non_neg_integer()</c></tag> + <item> + <p>When <c>logger_std_h</c> logs to a file, it reads the file + information of the log file prior to each write + operation. This is to make sure the file still exists and + has the same inode as when it was opened. This implies some + performance loss, but ensures that no log events are lost in + the case when the file has been removed or renamed by an + external actor.</p> + <p>In order to allow minimizing the performance loss, the + <c>file_check</c> parameter can be set to a positive integer + value, <c>N</c>. The handler will then skip reading the file + information prior to writing, as long as no more + than <c>N</c> milliseconds have passed since it was last + read.</p> + <p>Notice that the risk of loosing log events grows when + the <c>file_check</c> value grows.</p> + <p>Defaults to 0.</p> </item> - <tag><c>filesync_repeat_interval</c></tag> + <tag><c>filesync_repeat_interval = pos_integer() | no_repeat</c></tag> <item> <p>This value, in milliseconds, specifies how often the handler does a file sync operation to write buffered data to disk. The handler attempts @@ -97,12 +172,13 @@ standard handler and the disk_log handler, and are documented in the <seealso marker="logger_chapter#overload_protection"><c>User's Guide</c> </seealso>.</p> - <p>Notice that if changing the configuration of the handler in runtime, - the <c>type</c> parameter must not be modified.</p> + <p>Notice that if changing the configuration of the handler in + runtime, the <c>type</c>, <c>file</c>, or <c>modes</c> parameters + must not be modified.</p> <p>Example of adding a standard handler:</p> <code type="none"> logger:add_handler(my_standard_h, logger_std_h, - #{config => #{type => {file,"./system_info.log"}, + #{config => #{file => "./system_info.log", filesync_repeat_interval => 1000}}). </code> <p>To set the default handler, that starts initially with @@ -110,7 +186,7 @@ logger:add_handler(my_standard_h, logger_std_h, change the Kernel default logger configuration. Example:</p> <code type="none"> erl -kernel logger '[{handler,default,logger_std_h, - #{config => #{type => {file,"./log.log"}}}}]' + #{config => #{file => "./log.log"}}}]' </code> <p>An example of how to replace the standard handler with a disk_log handler at startup is found in the diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl index 4b5e0a7dd0..16946ff97c 100644 --- a/lib/kernel/src/logger_h_common.erl +++ b/lib/kernel/src/logger_h_common.erl @@ -142,8 +142,9 @@ changing_config(SetOrUpdate, maps:with(?OLP_KEYS,NewHConfig0)), case logger_olp:set_opts(Olp,NewOlpOpts) of ok -> - maybe_set_repeated_filesync(Olp,OldCommonConfig, - NewCommonConfig), + logger_olp:cast(Olp, {config_changed, + NewCommonConfig, + NewHandlerConfig}), ReadOnly = maps:with(?READ_ONLY_KEYS,OldHConfig), NewHConfig = maps:merge( @@ -281,11 +282,24 @@ handle_cast(repeated_filesync, State#{handler_state => HS, last_op => sync} end, {noreply,set_repeated_filesync(State1)}; - -handle_cast({set_repeated_filesync,FSyncInt},State) -> - State1 = State#{filesync_repeat_interval=>FSyncInt}, - State2 = set_repeated_filesync(cancel_repeated_filesync(State1)), - {noreply, State2}. +handle_cast({config_changed, CommonConfig, HConfig}, + State = #{id := Name, + module := Module, + handler_state := HandlerState, + filesync_repeat_interval := OldFSyncInt}) -> + State1 = + case maps:get(filesync_repeat_interval,CommonConfig) of + OldFSyncInt -> + State; + FSyncInt -> + set_repeated_filesync( + cancel_repeated_filesync( + State#{filesync_repeat_interval=>FSyncInt})) + end, + HS = try Module:config_changed(Name, HConfig, HandlerState) + catch error:undef -> HandlerState + end, + {noreply, State1#{handler_state => HS}}. handle_info(Info, #{id := Name, module := Module, handler_state := HandlerState} = State) -> @@ -447,10 +461,3 @@ cancel_repeated_filesync(State) -> end. error_notify(Term) -> ?internal_log(error, Term). - -maybe_set_repeated_filesync(_Olp, - #{filesync_repeat_interval:=FSyncInt}, - #{filesync_repeat_interval:=FSyncInt}) -> - ok; -maybe_set_repeated_filesync(Olp,_,#{filesync_repeat_interval:=FSyncInt}) -> - logger_olp:cast(Olp,{set_repeated_filesync,FSyncInt}). diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index 65f5b3876e..c8f1acfca4 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -29,7 +29,7 @@ -export([filesync/1]). %% logger_h_common callbacks --export([init/2, check_config/4, reset_state/2, +-export([init/2, check_config/4, config_changed/3, reset_state/2, filesync/3, write/4, handle_info/3, terminate/3]). %% logger callbacks @@ -105,85 +105,169 @@ filter_config(Config) -> %%%=================================================================== %%% logger_h_common callbacks %%%=================================================================== -init(Name, #{type := Type}) -> - case open_log_file(Name, Type) of +init(Name, Config) -> + MyConfig = maps:with([type,file,modes,file_check,max_no_bytes, + max_no_files,compress_on_rotate],Config), + case file_ctrl_start(Name, MyConfig) of {ok,FileCtrlPid} -> - {ok,#{type=>Type,file_ctrl_pid=>FileCtrlPid}}; + {ok,MyConfig#{file_ctrl_pid=>FileCtrlPid}}; Error -> Error end. -check_config(_Name,set,undefined,NewHConfig) -> - check_config(maps:merge(get_default_config(),NewHConfig)); -check_config(_Name,SetOrUpdate,OldHConfig,NewHConfig0) -> - WriteOnce = maps:with([type],OldHConfig), +check_config(Name,set,undefined,NewHConfig) -> + check_h_config(merge_default_config(Name,normalize_config(NewHConfig))); +check_config(Name,SetOrUpdate,OldHConfig,NewHConfig0) -> + WriteOnce = maps:with([type,file,modes],OldHConfig), Default = case SetOrUpdate of set -> %% Do not reset write-once fields to defaults - maps:merge(get_default_config(),WriteOnce); + merge_default_config(Name,WriteOnce); update -> OldHConfig end, - NewHConfig = maps:merge(Default, NewHConfig0), + NewHConfig = maps:merge(Default, normalize_config(NewHConfig0)), %% Fail if write-once fields are changed - case maps:with([type],NewHConfig) of + case maps:with([type,file,modes],NewHConfig) of WriteOnce -> - check_config(NewHConfig); + check_h_config(NewHConfig); Other -> {error,{illegal_config_change,?MODULE,WriteOnce,Other}} end. -check_config(#{type:=Type}=HConfig) -> - case check_h_config(maps:to_list(HConfig)) of - ok when is_atom(Type) -> - {ok,HConfig#{filesync_repeat_interval=>no_repeat}}; +check_h_config(HConfig) -> + case check_h_config(maps:get(type,HConfig),maps:to_list(HConfig)) of ok -> - {ok,HConfig}; + {ok,fix_file_opts(HConfig)}; {error,{Key,Value}} -> {error,{invalid_config,?MODULE,#{Key=>Value}}} 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 | _]) -> +check_h_config(Type,[{type,Type} | Config]) when Type =:= standard_io; + Type =:= standard_error; + Type =:= file -> + check_h_config(Type,Config); +check_h_config(file,[{file,File} | Config]) when is_list(File) -> + check_h_config(file,Config); +check_h_config(file,[{modes,Modes} | Config]) when is_list(Modes) -> + check_h_config(file,Config); +check_h_config(file,[{max_no_bytes,Size} | Config]) + when (is_integer(Size) andalso Size>0) orelse Size=:=infinity -> + check_h_config(file,Config); +check_h_config(file,[{max_no_files,Num} | Config]) when is_integer(Num), Num>=0 -> + check_h_config(file,Config); +check_h_config(file,[{compress_on_rotate,Bool} | Config]) when is_boolean(Bool) -> + check_h_config(file,Config); +check_h_config(file,[{file_check,FileCheck} | Config]) + when is_integer(FileCheck), FileCheck>=0 -> + check_h_config(file,Config); +check_h_config(_Type,[Other | _]) -> {error,Other}; -check_h_config([]) -> +check_h_config(_Type,[]) -> ok. -get_default_config() -> - #{type => standard_io}. +normalize_config(#{type:={file,File}}=HConfig) -> + HConfig#{type=>file,file=>File}; +normalize_config(#{type:={file,File,Modes}}=HConfig) -> + HConfig#{type=>file,file=>File,modes=>Modes}; +normalize_config(HConfig) -> + HConfig. + +merge_default_config(Name,#{type:=Type}=HConfig) -> + merge_default_config(Name,Type,HConfig); +merge_default_config(Name,#{file:=_}=HConfig) -> + merge_default_config(Name,file,HConfig); +merge_default_config(Name,HConfig) -> + merge_default_config(Name,standard_io,HConfig). + +merge_default_config(Name,Type,HConfig) -> + maps:merge(get_default_config(Name,Type),HConfig). + +get_default_config(Name,file) -> + #{type => file, + file => atom_to_list(Name), + modes => [raw,append], + file_check => 0, + max_no_bytes => infinity, + max_no_files => 0, + compress_on_rotate => false}; +get_default_config(_Name,Type) -> + #{type => Type}. + +fix_file_opts(#{modes:=Modes}=HConfig) -> + HConfig#{modes=>fix_modes(Modes)}; +fix_file_opts(HConfig) -> + HConfig#{filesync_repeat_interval=>no_repeat}. + +fix_modes(Modes) -> + %% Ensure write|append|exclusive + Modes1 = + case [M || M <- Modes, + lists:member(M,[write,append,exclusive])] of + [] -> [append|Modes]; + _ -> Modes + end, + %% Ensure raw + Modes2 = + case lists:member(raw,Modes) of + false -> [raw|Modes1]; + true -> Modes1 + end, + %% Ensure delayed_write + case lists:partition(fun(delayed_write) -> true; + ({delayed_write,_,_}) -> true; + (_) -> false + end, Modes2) of + {[],_} -> + [delayed_write|Modes2]; + _ -> + Modes2 + end. -filesync(_Name, _Mode, #{type := Type}=State) when is_atom(Type) -> - {ok,State}; -filesync(_Name, async, #{file_ctrl_pid := FileCtrlPid} = State) -> - ok = file_ctrl_filesync_async(FileCtrlPid), - {ok,State}; -filesync(_Name, sync, #{file_ctrl_pid := FileCtrlPid} = State) -> - Result = file_ctrl_filesync_sync(FileCtrlPid), +config_changed(_Name, + #{file_check:=FileCheck, + max_no_bytes:=Size, + max_no_files:=Count, + compress_on_rotate:=Compress}, + #{file_check:=FileCheck, + max_no_bytes:=Size, + max_no_files:=Count, + compress_on_rotate:=Compress}=State) -> + State; +config_changed(_Name, + #{file_check:=FileCheck, + max_no_bytes:=Size, + max_no_files:=Count, + compress_on_rotate:=Compress}, + #{file_ctrl_pid := FileCtrlPid} = State) -> + FileCtrlPid ! {update_config,#{file_check=>FileCheck, + max_no_bytes=>Size, + max_no_files=>Count, + compress_on_rotate=>Compress}}, + State#{file_check:=FileCheck, + max_no_bytes:=Size, + max_no_files:=Count, + compress_on_rotate:=Compress}; +config_changed(_Name,_NewHConfig,State) -> + State. + +filesync(_Name, SyncAsync, #{file_ctrl_pid := FileCtrlPid} = State) -> + Result = file_ctrl_filesync(SyncAsync, FileCtrlPid), {Result,State}. -write(_Name, async, Bin, #{file_ctrl_pid:=FileCtrlPid} = State) -> - ok = file_write_async(FileCtrlPid, Bin), - {ok,State}; -write(_Name, sync, Bin, #{file_ctrl_pid:=FileCtrlPid} = State) -> - Result = file_write_sync(FileCtrlPid, Bin), +write(_Name, SyncAsync, Bin, #{file_ctrl_pid:=FileCtrlPid} = State) -> + Result = file_write(SyncAsync, FileCtrlPid, Bin), {Result,State}. reset_state(_Name, State) -> State. -handle_info(_Name, {'EXIT',Pid,Why}, #{type := FileInfo, file_ctrl_pid := Pid}) -> +handle_info(_Name, {'EXIT',Pid,Why}, #{file_ctrl_pid := Pid}=State) -> %% file_ctrl_pid died, file error, terminate handler - exit({error,{write_failed,FileInfo,Why}}); + exit({error,{write_failed,maps:with([type,file,modes],State),Why}}); handle_info(_, _, State) -> State. @@ -211,27 +295,33 @@ terminate(_Name, _Reason, #{file_ctrl_pid:=FWPid}) -> %%%----------------------------------------------------------------- %%% -open_log_file(HandlerName, FileInfo) -> - case file_ctrl_start(HandlerName, FileInfo) of - OK = {ok,_FileCtrlPid} -> OK; - Error -> Error - end. - -do_open_log_file({file,FileName}) -> - do_open_log_file({file,FileName,[raw,append,delayed_write]}); - -do_open_log_file({file,FileName,[]}) -> - do_open_log_file({file,FileName,[raw,append,delayed_write]}); - -do_open_log_file({file,FileName,Modes}) -> +open_log_file(HandlerName,#{type:=file, + file:=FileName, + modes:=Modes, + file_check:=FileCheck, + max_no_bytes:=Size, + max_no_files:=Count, + compress_on_rotate:=Compress}) -> try case filelib:ensure_dir(FileName) of ok -> case file:open(FileName, Modes) of {ok, Fd} -> {ok,#file_info{inode=INode}} = - file:read_file_info(FileName), - {ok, {Fd, INode}}; + file:read_file_info(FileName,[raw]), + UpdateModes = [append | Modes--[write,append,exclusive]], + State0 = #{handler_name=>HandlerName, + file_name=>FileName, + modes=>UpdateModes, + file_check=>FileCheck, + fd=>Fd, + inode=>INode, + last_check=>timestamp(), + synced=>false, + write_res=>ok, + sync_res=>ok}, + State = update_rotation({Size,Count,Compress},State0), + {ok,State}; Error -> Error end; @@ -242,21 +332,23 @@ do_open_log_file({file,FileName,Modes}) -> _:Reason -> {error,Reason} end. -close_log_file(Std) when Std == standard_io; Std == standard_error -> - ok; -close_log_file({Fd,_}) -> +close_log_file(#{fd:=Fd}) -> _ = file:datasync(Fd), - _ = file:close(Fd). + _ = file:close(Fd), + ok; +close_log_file(_) -> + ok. + %%%----------------------------------------------------------------- %%% File control process -file_ctrl_start(HandlerName, FileInfo) -> +file_ctrl_start(HandlerName, HConfig) -> Starter = self(), FileCtrlPid = spawn_link(fun() -> - file_ctrl_init(HandlerName, FileInfo, Starter) + file_ctrl_init(HandlerName, HConfig, Starter) end), receive {FileCtrlPid,ok} -> @@ -271,18 +363,16 @@ file_ctrl_start(HandlerName, FileInfo) -> file_ctrl_stop(Pid) -> Pid ! stop. -file_write_async(Pid, Bin) -> +file_write(async, Pid, Bin) -> Pid ! {log,Bin}, - ok. - -file_write_sync(Pid, Bin) -> + ok; +file_write(sync, Pid, Bin) -> file_ctrl_call(Pid, {log,Bin}). -file_ctrl_filesync_async(Pid) -> +file_ctrl_filesync(async, Pid) -> Pid ! filesync, - ok. - -file_ctrl_filesync_sync(Pid) -> + ok; +file_ctrl_filesync(sync, Pid) -> file_ctrl_call(Pid, filesync). file_ctrl_call(Pid, Msg) -> @@ -299,98 +389,255 @@ file_ctrl_call(Pid, Msg) -> {error,{no_response,Pid}} end. -file_ctrl_init(HandlerName, FileInfo, Starter) when is_tuple(FileInfo) -> +file_ctrl_init(HandlerName, + #{type:=file, + file:=FileName} = HConfig, + Starter) -> process_flag(message_queue_data, off_heap), - FileName = element(2, FileInfo), - case do_open_log_file(FileInfo) of - {ok,File} -> + case open_log_file(HandlerName,HConfig) of + {ok,State} -> Starter ! {self(),ok}, - file_ctrl_loop(File, FileName, false, ok, ok, HandlerName); + file_ctrl_loop(State); {error,Reason} -> Starter ! {self(),{error,{open_failed,FileName,Reason}}} end; -file_ctrl_init(HandlerName, StdDev, Starter) -> +file_ctrl_init(HandlerName, #{type:=StdDev}, Starter) -> Starter ! {self(),ok}, - file_ctrl_loop(StdDev, StdDev, false, ok, ok, HandlerName). + file_ctrl_loop(#{handler_name=>HandlerName,dev=>StdDev}). -file_ctrl_loop(File, DevName, Synced, - PrevWriteResult, PrevSyncResult, HandlerName) -> +file_ctrl_loop(State) -> receive %% asynchronous event {log,Bin} -> - File1 = ensure(File, DevName), - Result = write_to_dev(File1, Bin, DevName, - PrevWriteResult, HandlerName), - file_ctrl_loop(File1, DevName, false, - Result, PrevSyncResult, HandlerName); + State1 = write_to_dev(Bin,State), + file_ctrl_loop(State1); %% synchronous event {{log,Bin},{From,MRef}} -> - File1 = ensure(File, DevName), - Result = write_to_dev(File1, Bin, DevName, - PrevWriteResult, HandlerName), + State1 = ensure_file(State), + State2 = write_to_dev(Bin,State1), From ! {MRef,ok}, - file_ctrl_loop(File1, DevName, false, - Result, PrevSyncResult, HandlerName); + file_ctrl_loop(State2); filesync -> - File1 = ensure(File, DevName), - Result = sync_dev(File1, DevName, Synced, - PrevSyncResult, HandlerName), - file_ctrl_loop(File1, DevName, true, - PrevWriteResult, Result, HandlerName); + State1 = sync_dev(State), + file_ctrl_loop(State1); {filesync,{From,MRef}} -> - File1 = ensure(File, DevName), - Result = sync_dev(File1, DevName, Synced, - PrevSyncResult, HandlerName), + State1 = ensure_file(State), + State2 = sync_dev(State1), From ! {MRef,ok}, - file_ctrl_loop(File1, DevName, true, - PrevWriteResult, Result, HandlerName); + file_ctrl_loop(State2); + + {update_config,#{file_check:=FileCheck, + max_no_bytes:=Size, + max_no_files:=Count, + compress_on_rotate:=Compress}} -> + State1 = update_rotation({Size,Count,Compress},State), + file_ctrl_loop(State1#{file_check=>FileCheck}); stop -> - _ = close_log_file(File), + close_log_file(State), stopped end. +maybe_ensure_file(#{file_check:=0}=State) -> + ensure_file(State); +maybe_ensure_file(#{last_check:=T0,file_check:=CheckInt}=State) + when is_integer(CheckInt) -> + T = timestamp(), + if T-T0 > CheckInt -> ensure_file(State); + true -> State + end; +maybe_ensure_file(State) -> + State. + %% In order to play well with tools like logrotate, we need to be able %% to re-create the file if it has disappeared (e.g. if rotated by %% logrotate) -ensure(Fd,DevName) when is_atom(DevName) -> - Fd; -ensure({Fd,INode},FileName) -> - case file:read_file_info(FileName) of - {ok,#file_info{inode=INode}} -> - {Fd,INode}; +ensure_file(#{fd:=Fd0,inode:=INode0,file_name:=FileName,modes:=Modes}=State) -> + case file:read_file_info(FileName,[raw]) of + {ok,#file_info{inode=INode0}} -> + State#{last_check=>timestamp()}; _ -> - _ = file:close(Fd), - _ = file:close(Fd), % delayed_write cause close not to close - case do_open_log_file({file,FileName}) of - {ok,File} -> - File; + close_log_file(Fd0), + case file:open(FileName,Modes) of + {ok,Fd} -> + {ok,#file_info{inode=INode}} = + file:read_file_info(FileName,[raw]), + State#{fd=>Fd,inode=>INode, + last_check=>timestamp(), + synced=>true,sync_res=>ok}; Error -> exit({could_not_reopen_file,Error}) end - end. + end; +ensure_file(State) -> + State. -write_to_dev(DevName, Bin, _DevName, _PrevWriteResult, _HandlerName) - when is_atom(DevName) -> - io:put_chars(DevName, Bin); -write_to_dev({Fd,_}, Bin, FileName, PrevWriteResult, HandlerName) -> +write_to_dev(Bin,#{dev:=DevName}=State) -> + io:put_chars(DevName, Bin), + State; +write_to_dev(Bin, State) -> + State1 = #{fd:=Fd} = maybe_ensure_file(State), Result = ?file_write(Fd, Bin), - maybe_notify_error(write,Result,PrevWriteResult,FileName,HandlerName). + State2 = maybe_rotate_file(Bin,State1), + maybe_notify_error(write,Result,State2), + State2#{synced=>false,write_res=>Result}. -sync_dev(_, _FileName, true, PrevSyncResult, _HandlerName) -> - PrevSyncResult; -sync_dev({Fd,_}, FileName, false, PrevSyncResult, HandlerName) -> +sync_dev(#{synced:=false}=State) -> + State1 = #{fd:=Fd} = maybe_ensure_file(State), Result = ?file_datasync(Fd), - maybe_notify_error(filesync,Result,PrevSyncResult,FileName,HandlerName). + maybe_notify_error(filesync,Result,State1), + State1#{synced=>true,sync_res=>Result}; +sync_dev(State) -> + State. -maybe_notify_error(_Op, ok, _PrevResult, _FileName, _HandlerName) -> +update_rotation({infinity,_,_},State) -> + maybe_remove_archives(0,State), + maps:remove(rotation,State); +update_rotation({Size,Count,Compress},#{file_name:=FileName} = State) -> + maybe_remove_archives(Count,State), + {ok,#file_info{size=CurrSize}} = file:read_file_info(FileName,[raw]), + State1 = State#{rotation=>#{size=>Size, + count=>Count, + compress=>Compress, + curr_size=>CurrSize}}, + maybe_update_compress(0,State1), + maybe_rotate_file(0,State1). + +maybe_remove_archives(Count,#{file_name:=FileName}=State) -> + Archive = rot_file_name(FileName,Count,false), + CompressedArchive = rot_file_name(FileName,Count,true), + case {file:read_file_info(Archive,[raw]), + file:read_file_info(CompressedArchive,[raw])} of + {{error,enoent},{error,enoent}} -> + ok; + _ -> + _ = file:delete(Archive), + _ = file:delete(CompressedArchive), + maybe_remove_archives(Count+1,State) + end. + +maybe_update_compress(Count,#{rotation:=#{count:=Count}}) -> + ok; +maybe_update_compress(N,#{file_name:=FileName, + rotation:=#{compress:=Compress}}=State) -> + Archive = rot_file_name(FileName,N,not Compress), + case file:read_file_info(Archive,[raw]) of + {ok,_} when Compress -> + compress_file(Archive); + {ok,_} -> + decompress_file(Archive); + _ -> + ok + end, + maybe_update_compress(N+1,State). + +maybe_rotate_file(Bin,#{rotation:=_}=State) when is_binary(Bin) -> + maybe_rotate_file(byte_size(Bin),State); +maybe_rotate_file(AddSize,#{rotation:=#{size:=RotSize, + curr_size:=CurrSize}=Rotation}=State) -> + NewSize = CurrSize + AddSize, + if NewSize>RotSize -> + rotate_file(State#{rotation=>Rotation#{curr_size=>NewSize}}); + true -> + State#{rotation=>Rotation#{curr_size=>NewSize}} + end; +maybe_rotate_file(_Bin,State) -> + State. + +rotate_file(#{fd:=Fd0,file_name:=FileName,modes:=Modes,rotation:=Rotation}=State) -> + State1 = sync_dev(State), + _ = file:close(Fd0), + _ = file:close(Fd0), + rotate_files(FileName,maps:get(count,Rotation),maps:get(compress,Rotation)), + case file:open(FileName,Modes) of + {ok,Fd} -> + {ok,#file_info{inode=INode}} = file:read_file_info(FileName,[raw]), + State1#{fd=>Fd,inode=>INode,rotation=>Rotation#{curr_size=>0}}; + Error -> + exit({could_not_reopen_file,Error}) + end. + +rotate_files(FileName,0,_Compress) -> + _ = file:delete(FileName), + ok; +rotate_files(FileName,1,Compress) -> + FileName0 = FileName++".0", + _ = file:rename(FileName,FileName0), + if Compress -> compress_file(FileName0); + true -> ok + end, ok; -maybe_notify_error(_Op, PrevResult, PrevResult, _FileName, _HandlerName) -> +rotate_files(FileName,Count,Compress) -> + _ = file:rename(rot_file_name(FileName,Count-2,Compress), + rot_file_name(FileName,Count-1,Compress)), + rotate_files(FileName,Count-1,Compress). + +rot_file_name(FileName,Count,false) -> + FileName ++ "." ++ integer_to_list(Count); +rot_file_name(FileName,Count,true) -> + rot_file_name(FileName,Count,false) ++ ".gz". + +compress_file(FileName) -> + {ok,In} = file:open(FileName,[read,binary]), + {ok,Out} = file:open(FileName++".gz",[write]), + Z = zlib:open(), + zlib:deflateInit(Z, default, deflated, 31, 8, default), + compress_data(Z,In,Out), + zlib:deflateEnd(Z), + zlib:close(Z), + _ = file:close(In), + _ = file:close(Out), + _ = file:delete(FileName), + ok. + +compress_data(Z,In,Out) -> + case file:read(In,100000) of + {ok,Data} -> + Compressed = zlib:deflate(Z, Data), + _ = file:write(Out,Compressed), + compress_data(Z,In,Out); + eof -> + Compressed = zlib:deflate(Z, <<>>, finish), + _ = file:write(Out,Compressed), + ok + end. + +decompress_file(FileName) -> + {ok,In} = file:open(FileName,[read,binary]), + {ok,Out} = file:open(filename:rootname(FileName,".gz"),[write]), + Z = zlib:open(), + zlib:inflateInit(Z, 31), + decompress_data(Z,In,Out), + zlib:inflateEnd(Z), + zlib:close(Z), + _ = file:close(In), + _ = file:close(Out), + _ = file:delete(FileName), + ok. + +decompress_data(Z,In,Out) -> + case file:read(In,1000) of + {ok,Data} -> + Decompressed = zlib:inflate(Z, Data), + _ = file:write(Out,Decompressed), + decompress_data(Z,In,Out); + eof -> + ok + end. + +maybe_notify_error(_Op, ok, _State) -> + ok; +maybe_notify_error(Op, Result, #{write_res:=WR,sync_res:=SR}) + when (Op==write andalso Result==WR) orelse + (Op==filesync andalso Result==SR) -> %% don't report same error twice - PrevResult; -maybe_notify_error(Op, Error, _PrevResult, FileName, HandlerName) -> + ok; +maybe_notify_error(Op, Error, #{handler_name:=HandlerName,file_name:=FileName}) -> logger_h_common:error_notify({HandlerName,Op,FileName,Error}), - Error. + ok. + +timestamp() -> + erlang:monotonic_time(millisecond). diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl index 70bb775db8..035e5d8974 100644 --- a/lib/kernel/test/logger_SUITE.erl +++ b/lib/kernel/test/logger_SUITE.erl @@ -1048,8 +1048,11 @@ kernel_config(Config) -> ok = rpc:call(Node,logger,internal_init_logger,[]), ok = rpc:call(Node,logger,add_handlers,[kernel]), #{primary:=#{filter_default:=log,filters:=[]}, - handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F}}}], + handlers:=[#{id:=default,filters:=DF, + config:=#{type:=file,file:=F,modes:=Modes}}], module_levels:=[]} = rpc:call(Node,logger,get_config,[]), + [append,delayed_write,raw] = lists:sort(Modes), + %% Same, but using 'logger' parameter instead of 'error_logger' ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again @@ -1060,26 +1063,27 @@ kernel_config(Config) -> ok = rpc:call(Node,logger,internal_init_logger,[]), ok = rpc:call(Node,logger,add_handlers,[kernel]), #{primary:=#{filter_default:=log,filters:=[]}, - handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F}}}], + handlers:=[#{id:=default,filters:=DF, + config:=#{type:=file,file:=F,modes:=Modes}}], module_levels:=[]} = rpc:call(Node,logger,get_config,[]), %% Same, but with type={file,File,Modes} ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), - M = [raw,write,delayed_write], + M = [raw,write], ok = rpc:call(Node,application,set_env,[kernel,logger, [{handler,default,logger_std_h, #{config=>#{type=>{file,F,M}}}}]]), ok = rpc:call(Node,logger,internal_init_logger,[]), ok = rpc:call(Node,logger,add_handlers,[kernel]), #{primary:=#{filter_default:=log,filters:=[]}, - handlers:=[#{id:=default,filters:=DF,config:=#{type:={file,F,M}}}], + handlers:=[#{id:=default,filters:=DF, + config:=#{type:=file,file:=F,modes:=[delayed_write|M]}}], module_levels:=[]} = rpc:call(Node,logger,get_config,[]), %% Same, but with disk_log handler ok = rpc:call(Node,logger,remove_handler,[default]),% so it can be added again ok = rpc:call(Node,application,unset_env,[kernel,error_logger]), - M = [raw,write,delayed_write], ok = rpc:call(Node,application,set_env,[kernel,logger, [{handler,default,logger_disk_log_h, #{config=>#{file=>F}}}]]), diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl index b2c2c8ba67..0c5516f82b 100644 --- a/lib/kernel/test/logger_std_h_SUITE.erl +++ b/lib/kernel/test/logger_std_h_SUITE.erl @@ -112,6 +112,8 @@ all() -> add_remove_instance_standard_error, add_remove_instance_file1, add_remove_instance_file2, + add_remove_instance_file3, + add_remove_instance_file4, default_formatter, filter_config, errors, @@ -142,7 +144,12 @@ all() -> restart_after, handler_requests_under_load, recreate_deleted_log, - reopen_changed_log + reopen_changed_log, + rotate_size, + rotate_size_compressed, + rotate_size_reopen, + rotation_opts, + rotation_opts_restart_handler ]. add_remove_instance_tty(_Config) -> @@ -179,10 +186,27 @@ add_remove_instance_file2(Config) -> add_remove_instance_file2(cleanup,_Config) -> logger_std_h_remove(). -add_remove_instance_file(Log, Type) -> +add_remove_instance_file3(_Config) -> + Log = atom_to_list(?MODULE), + StdHConfig = #{type=>file}, + add_remove_instance_file(Log, StdHConfig). +add_remove_instance_file3(cleanup,_Config) -> + logger_std_h_remove(). + +add_remove_instance_file4(Config) -> + Dir = ?config(priv_dir,Config), + Log = filename:join(Dir,"stdlog4.txt"), + StdHConfig = #{file=>Log,modes=>[]}, + add_remove_instance_file(Log, StdHConfig). +add_remove_instance_file4(cleanup,_Config) -> + logger_std_h_remove(). + +add_remove_instance_file(Log, Type) when not is_map(Type) -> + add_remove_instance_file(Log,#{type=>Type}); +add_remove_instance_file(Log, StdHConfig) when is_map(StdHConfig) -> ok = logger:add_handler(?MODULE, logger_std_h, - #{config => #{type => Type}, + #{config => StdHConfig, filter_default=>stop, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), @@ -257,9 +281,10 @@ errors(Config) -> end, {error, - {handler_not_added,{open_failed,Log,_}}} = + {handler_not_added, + {invalid_config,logger_std_h,#{modes:=bad_file_opt}}}} = logger:add_handler(myh3,logger_std_h, - #{config=>#{type=>{file,Log,[bad_file_opt]}}}), + #{config=>#{type=>{file,Log,bad_file_opt}}}), ok = logger:notice(?msg). @@ -607,24 +632,51 @@ reconfig(cleanup, _Config) -> file_opts(Config) -> Dir = ?config(priv_dir,Config), Log = filename:join(Dir, lists:concat([?FUNCTION_NAME,".log"])), - BadFileOpts = [raw], - BadType = {file,Log,BadFileOpts}, - {error,{handler_not_added,{open_failed,Log,enoent}}} = - logger:add_handler(?MODULE, logger_std_h, - #{config => #{type => BadType}}), + MissingOpts = [raw], + Type1 = {file,Log,MissingOpts}, + ok = logger:add_handler(?MODULE, logger_std_h, + #{config => #{type => Type1}}), + {ok,#{config:=#{type:=file,file:=Log,modes:=Modes1}}} = + logger:get_handler_config(?MODULE), + [append,delayed_write,raw] = lists:sort(Modes1), + ok = logger:remove_handler(?MODULE), OkFileOpts = [raw,append], OkType = {file,Log,OkFileOpts}, ok = logger:add_handler(?MODULE, logger_std_h, - #{config => #{type => OkType}, + #{config => #{type => OkType}, % old format filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), - #{cb_state := #{handler_state := #{type := OkType}}} = + ModOpts = [delayed_write|OkFileOpts], + #{cb_state := #{handler_state := #{type:=file, + file:=Log, + modes:=ModOpts}}} = logger_olp:info(h_proc_name()), - {ok,#{config := #{type := OkType}}} = logger:get_handler_config(?MODULE), + {ok,#{config := #{type:=file, + file:=Log, + modes:=ModOpts}}} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + + ok = logger:add_handler(?MODULE, + logger_std_h, + #{config => #{type => file, + file => Log, + modes => OkFileOpts}, % new format + filter_default=>log, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,self()}}), + + #{cb_state := #{handler_state := #{type:=file, + file:=Log, + modes:=ModOpts}}} = + logger_olp:info(h_proc_name()), + {ok,#{config := #{type:=file, + file:=Log, + modes:=ModOpts}}} = + logger:get_handler_config(?MODULE), logger:notice(M1=?msg,?domain), ?check(M1), B1 = ?bin(M1), @@ -640,13 +692,14 @@ sync(Config) -> Type = {file,Log}, ok = logger:add_handler(?MODULE, logger_std_h, - #{config => #{type => Type}, + #{config => #{type => Type, + file_check => 10000}, filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,nl}}), %% check repeated filesync happens - start_tracer([{logger_std_h, write_to_dev, 5}, + start_tracer([{logger_std_h, write_to_dev, 2}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"first\n">>}, {file,datasync}]), @@ -656,7 +709,7 @@ sync(Config) -> check_tracer(filesync_rep_int()*2), %% check that explicit filesync is only done once - start_tracer([{logger_std_h, write_to_dev, 5}, + start_tracer([{logger_std_h, write_to_dev, 2}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"second\n">>}, {file,datasync}, @@ -675,7 +728,7 @@ sync(Config) -> #{filesync_repeat_interval => no_repeat}), no_repeat = maps:get(filesync_repeat_interval, maps:get(cb_state, logger_olp:info(h_proc_name()))), - start_tracer([{logger_std_h, write_to_dev, 5}, + start_tracer([{logger_std_h, write_to_dev, 2}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"third\n">>}, {file,datasync}, @@ -1285,6 +1338,331 @@ reopen_changed_log(Config) -> reopen_changed_log(cleanup, _Config) -> ok = stop_handler(?MODULE). +rotate_size(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + ok = logger:update_handler_config(?MODULE,#{config=>#{max_no_bytes=>1000, + max_no_files=>2}}), + + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=1000}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + + logger:notice(Str,?domain), + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), + {error,enoent} = file:read_file_info(Log++".1"), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,51)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".1"), + {error,enoent} = file:read_file_info(Log++".2"), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=1000}} = file:read_file_info(Log), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".1"), + {error,enoent} = file:read_file_info(Log++".2"), + + logger:notice("bbbb",?domain), + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=1005}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".1"), + {error,enoent} = file:read_file_info(Log++".2"), + + ok. +rotate_size(cleanup,_Config) -> + ok = stop_handler(?MODULE). + +rotate_size_compressed(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + ok = logger:update_handler_config(?MODULE, + #{config=>#{max_no_bytes=>1000, + max_no_files=>2, + compress_on_rotate=>true}}), + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=1000}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {error,enoent} = file:read_file_info(Log++".0.gz"), + + logger:notice(Str,?domain), + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".0.gz"), + {error,enoent} = file:read_file_info(Log++".1"), + {error,enoent} = file:read_file_info(Log++".1.gz"), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,51)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".0.gz"), + {error,enoent} = file:read_file_info(Log++".1"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".1.gz"), + {error,enoent} = file:read_file_info(Log++".2"), + {error,enoent} = file:read_file_info(Log++".2.gz"), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,50)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=1000}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".0.gz"), + {error,enoent} = file:read_file_info(Log++".1"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".1.gz"), + {error,enoent} = file:read_file_info(Log++".2"), + {error,enoent} = file:read_file_info(Log++".2.gz"), + + logger:notice("bbbb",?domain), + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {error,enoent} = file:read_file_info(Log++".0"), + {ok,#file_info{size=38}} = file:read_file_info(Log++".0.gz"), + {error,enoent} = file:read_file_info(Log++".1"), + {ok,#file_info{size=35}} = file:read_file_info(Log++".1.gz"), + {error,enoent} = file:read_file_info(Log++".2"), + {error,enoent} = file:read_file_info(Log++".2.gz"), + + ok. +rotate_size_compressed(cleanup,_Config) -> + ok = stop_handler(?MODULE). + +rotate_size_reopen(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + ok = logger:update_handler_config(?MODULE,#{config=>#{max_no_bytes=>1000, + max_no_files=>2}}), + + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,40)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=800}} = file:read_file_info(Log), + + {ok,HConfig} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler(?MODULE,maps:get(module,HConfig),HConfig), + {ok,#file_info{size=800}} = file:read_file_info(Log), + + [logger:notice(Str,?domain) || _ <- lists:seq(1,40)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=580}} = file:read_file_info(Log), + {ok,#file_info{size=1020}} = file:read_file_info(Log++".0"), + ok. +rotate_size_reopen(cleanup,_Config) -> + ok = stop_handler(?MODULE). + +rotation_opts(Config) -> + {Log,_HConfig,StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + #{max_no_bytes:=infinity, + max_no_files:=0, + compress_on_rotate:=false} = StdHConfig, + + %% Test bad rotation config + {error,{invalid_config,_,_}} = + logger:update_handler_config(?MODULE,config,#{max_no_bytes=>0}), + {error,{invalid_config,_,_}} = + logger:update_handler_config(?MODULE,config,#{max_no_files=>infinity}), + {error,{invalid_config,_,_}} = + logger:update_handler_config(?MODULE,config, + #{compress_on_rotate=>undefined}), + + + %% Test good rotation config - start with no rotation + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=200}} = file:read_file_info(Log), + [] = filelib:wildcard(Log++".*"), + + %% Turn on rotation, check that existing file is rotated since its + %% size exceeds max_no_bytes + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_bytes=>100, + max_no_files=>2}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=0}} = file:read_file_info(Log), + Log0 = Log++".0", + {ok,#file_info{size=200}} = file:read_file_info(Log0), + [Log0] = filelib:wildcard(Log++".*"), + + %% Fill all logs + [logger:notice(Str,?domain) || _ <- lists:seq(1,13)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=20}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log0), + {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), + [_,_] = filelib:wildcard(Log++".*"), + + %% Extend size and count and check that nothing changes with existing files + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_bytes=>200, + max_no_files=>3}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=20}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log0), + {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), + [_,_] = filelib:wildcard(Log++".*"), + + %% Add more log events and see that extended size and count works + [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=220}} = file:read_file_info(Log0), + {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), + {ok,#file_info{size=120}} = file:read_file_info(Log++".2"), + [_,_,_] = filelib:wildcard(Log++".*"), + + %% Reduce count and check that archive files that exceed the new + %% count are moved + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_files=>1}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=220}} = file:read_file_info(Log0), + [Log0] = filelib:wildcard(Log++".*"), + + %% Extend size and count again, and turn on compression. Check + %% that archives are compressed + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_bytes=>100, + max_no_files=>2, + compress_on_rotate=>true}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=0}} = file:read_file_info(Log), + Log0gz = Log0++".gz", + {ok,#file_info{size=29}} = file:read_file_info(Log0gz), + [Log0gz] = filelib:wildcard(Log++".*"), + + %% Fill all logs + [logger:notice(Str,?domain) || _ <- lists:seq(1,13)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=20}} = file:read_file_info(Log), + {ok,#file_info{size=29}} = file:read_file_info(Log0gz), + {ok,#file_info{size=29}} = file:read_file_info(Log++".1.gz"), + [_,_] = filelib:wildcard(Log++".*"), + + %% Reduce count and turn off compression. Check that archives that + %% exceeds the new count are removed, and the rest are + %% uncompressed. + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_files=>1, + compress_on_rotate=>false}), + timer:sleep(100), % give some time to execute config_changed + {ok,#file_info{size=20}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log0), + [Log0] = filelib:wildcard(Log++".*"), + + %% Check that config and handler state agree on the current rotation settings + {ok,#{config:=#{max_no_bytes:=100, + max_no_files:=1, + compress_on_rotate:=false}}} = + logger:get_handler_config(?MODULE), + #{cb_state:=#{handler_state:=#{max_no_bytes:=100, + max_no_files:=1, + compress_on_rotate:=false}}} = + logger_olp:info(h_proc_name()), + ok. +rotation_opts(cleanup,_Config) -> + ok = stop_handler(?MODULE). + +rotation_opts_restart_handler(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + ok = logger:update_handler_config(?MODULE, + config, + #{max_no_bytes=>100, + max_no_files=>2}), + + %% Fill all logs + Str = lists:duplicate(19,$a), + [logger:notice(Str,?domain) || _ <- lists:seq(1,15)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=60}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=120}} = file:read_file_info(Log++".1"), + [_,_] = filelib:wildcard(Log++".*"), + + %% Stop/start handler and turn off rotation. Check that archives are removed. + {ok,#{config:=StdHConfig1}=HConfig1} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler( + ?MODULE,logger_std_h, + HConfig1#{config=>StdHConfig1#{max_no_bytes=>infinity}}), + timer:sleep(100), + {ok,#file_info{size=60}} = file:read_file_info(Log), + [] = filelib:wildcard(Log++".*"), + + %% Add some log events and check that file is no longer rotated. + [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=260}} = file:read_file_info(Log), + [] = filelib:wildcard(Log++".*"), + + %% Stop/start handler and trun on rotation. Check that file is rotated. + {ok,#{config:=StdHConfig2}=HConfig2} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler( + ?MODULE,logger_std_h, + HConfig2#{config=>StdHConfig2#{max_no_bytes=>100, + max_no_files=>2}}), + timer:sleep(100), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=260}} = file:read_file_info(Log++".0"), + [_] = filelib:wildcard(Log++".*"), + + %% Fill all logs + [logger:notice(Str,?domain) || _ <- lists:seq(1,10)], + logger_std_h:filesync(?MODULE), + {ok,#file_info{size=80}} = file:read_file_info(Log), + {ok,#file_info{size=120}} = file:read_file_info(Log++".0"), + {ok,#file_info{size=260}} = file:read_file_info(Log++".1"), + + %% Stop/start handler, reduce count and turn on compression. Check + %% that excess archives are removed, and the rest compressed. + {ok,#{config:=StdHConfig3}=HConfig3} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler( + ?MODULE,logger_std_h, + HConfig3#{config=>StdHConfig3#{max_no_bytes=>75, + max_no_files=>1, + compress_on_rotate=>true}}), + timer:sleep(100), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=29}} = file:read_file_info(Log++".0.gz"), + [_] = filelib:wildcard(Log++".*"), + + %% Stop/start handler and turn off compression. Check that achives + %% are decompressed. + {ok,#{config:=StdHConfig4}=HConfig4} = logger:get_handler_config(?MODULE), + ok = logger:remove_handler(?MODULE), + ok = logger:add_handler( + ?MODULE,logger_std_h, + HConfig4#{config=>StdHConfig4#{compress_on_rotate=>false}}), + timer:sleep(100), + {ok,#file_info{size=0}} = file:read_file_info(Log), + {ok,#file_info{size=80}} = file:read_file_info(Log++".0"), + [_] = filelib:wildcard(Log++".*"), + + ok. +rotation_opts_restart_handler(cleanup,_Config) -> + ok = stop_handler(?MODULE). + %%%----------------------------------------------------------------- %%% send_requests(TO, Reqs = [{Mod,Func,Args,Res}|Rs]) -> @@ -1305,8 +1683,8 @@ start_handler(Name, TTY, _Config) when TTY == standard_io; ok = logger:add_handler(Name, logger_std_h, #{config => #{type => TTY}, - filter_default=>log, - filters=>?DEFAULT_HANDLER_FILTERS([Name]), + filter_default=>stop, + filters=>filter_only_this_domain(Name), formatter=>{?MODULE,op}}), {ok,HConfig = #{config := StdHConfig}} = logger:get_handler_config(Name), {HConfig,StdHConfig}; @@ -1320,12 +1698,17 @@ start_handler(Name, FuncName, Config) -> ok = logger:add_handler(Name, logger_std_h, #{config => #{type => Type}, - filter_default=>log, - filters=>?DEFAULT_HANDLER_FILTERS([Name]), + filter_default=>stop, + filters=>filter_only_this_domain(Name), formatter=>{?MODULE,op}}), {ok,HConfig = #{config := StdHConfig}} = logger:get_handler_config(Name), {Log,HConfig,StdHConfig}. + +filter_only_this_domain(Name) -> + [{remote_gl,{fun logger_filters:remote_gl/2,stop}}, + {domain,{fun logger_filters:domain/2,{log,super,[Name]}}}]. + stop_handler(Name) -> R = logger:remove_handler(Name), ct:pal("Handler ~p stopped! Result: ~p", [Name,R]), @@ -1658,7 +2041,7 @@ tpl([]) -> tracer({trace,_,call,{logger_h_common,handle_cast,[Op|_]}}, {Pid,[{Mod,Func,Op}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Op}); -tracer({trace,_,call,{Mod=logger_std_h,Func=write_to_dev,[_,Data,_,_,_]}}, +tracer({trace,_,call,{Mod=logger_std_h,Func=write_to_dev,[Data,_]}}, {Pid,[{Mod,Func,Data}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Data}); tracer({trace,_,call,{Mod,Func,_}}, {Pid,[{Mod,Func}|Expected]}) -> @@ -1742,4 +2125,3 @@ filesync_rep_int() -> file_delete(Log) -> file:delete(Log). - diff --git a/lib/ssl/src/ssl_connection.erl b/lib/ssl/src/ssl_connection.erl index 24fb091ddf..ad81288f64 100644 --- a/lib/ssl/src/ssl_connection.erl +++ b/lib/ssl/src/ssl_connection.erl @@ -2691,6 +2691,11 @@ ssl_options_list([Key | Keys], [Value | Values], Acc) -> handle_active_option(false, connection = StateName, To, Reply, State) -> hibernate_after(StateName, State, [{reply, To, Reply}]); +handle_active_option(_, connection = StateName, To, _Reply, #state{connection_env = #connection_env{terminated = true}, + user_data_buffer = {_,0,_}} = State) -> + handle_normal_shutdown(?ALERT_REC(?FATAL, ?CLOSE_NOTIFY, all_data_deliverd), StateName, + State#state{start_or_recv_from = To}), + {stop,{shutdown, peer_close}, State}; handle_active_option(_, connection = StateName0, To, Reply, #state{static_env = #static_env{protocol_cb = Connection}, user_data_buffer = {_,0,_}} = State0) -> case Connection:next_event(StateName0, no_record, State0) of |