diff options
Diffstat (limited to 'lib/kernel')
27 files changed, 2092 insertions, 1681 deletions
diff --git a/lib/kernel/doc/src/inet.xml b/lib/kernel/doc/src/inet.xml index ed775d67eb..87b08e4e36 100644 --- a/lib/kernel/doc/src/inet.xml +++ b/lib/kernel/doc/src/inet.xml @@ -198,6 +198,79 @@ fe80::204:acff:fe17:bf38 </desc> </datatype> <datatype> + <name name="getifaddrs_ifopts"/> + <desc> + <p> + Interface address description list returned from + <seealso marker="#getifaddrs/0"><c>getifaddrs/0,1</c></seealso> + for a named interface, translated from the returned + data of the POSIX API function <c>getaddrinfo()</c>. + </p> + <p> + <c><anno>Hwaddr</anno></c> is hardware dependent, + for example, on Ethernet interfaces it is + the 6-byte Ethernet address (MAC address (EUI-48 address)). + </p> + <p> + The tuples <c>{addr,<anno>Addr</anno>}</c>, + <c>{netmask,<anno>Netmask</anno>}</c>, and possibly + <c>{broadaddr,<anno>Broadaddr</anno>}</c> or + <c>{dstaddr,<anno>Dstaddr</anno>}</c> + are repeated in the list + if the interface has got multiple addresses. + An interface may have multiple <c>{flag,_}</c> tuples + for example if it has different flags + for different address families. + Multiple <c>{hwaddr,<anno>Hwaddr</anno>}</c> tuples + is hard to say anything definite about, though. + The tuple <c>{flag,<anno>Flags</anno>}</c> is mandatory, + all others are optional. + </p> + <p> + Do not rely too much on the order + of <c><anno>Flags</anno></c> atoms + or the <c><anno>Ifopt</anno></c> tuples. + There are however some rules: + </p> + <list type="bulleted"> + <item><p> + A <c>{flag,_}</c> tuple applies to all other tuples that follow. + </p></item> + <item><p> + Immediately after <c>{addr,_}</c> follows <c>{netmask,_}</c>. + </p></item> + <item><p> + Immediately thereafter may <c>{broadaddr,_}</c> follow + if <c>broadcast</c> is member of <c><anno>Flags</anno></c>, + or <c>{dstaddr,_}</c> if <c>pointtopoint</c> + is member of <c><anno>Flags</anno></c>. + Both <c>{dstaddr,_}</c> and <c>{broadaddr,_}</c> + does not occur for the same <c>{addr,_}</c>. + </p></item> + <item><p> + Any <c>{netmask,_}</c>, <c>{broadaddr,_}</c>, or + <c>{dstaddr,_}</c> tuples that follow an + <c>{addr,<anno>Addr</anno>}</c> + tuple concerns the address <c><anno>Addr</anno></c>. + </p></item> + </list> + <p> + The tuple <c>{hwaddr,_}</c> is not returned on Solaris, as the + hardware address historically belongs to the link layer + and it is not returned by the Solaris API function + <c>getaddrinfo()</c>. + </p> + <warning> + <p> + On Windows, the data is fetched from different + OS API functions, so the <c><anno>Netmask</anno></c> + and <c><anno>Broadaddr</anno></c> values may be calculated, + just as some <c><anno>Flags</anno></c> values. + </p> + </warning> + </desc> + </datatype> + <datatype> <name name="posix"/> <desc> <p>An atom that is named from the POSIX error codes used in Unix, @@ -324,38 +397,64 @@ fe80::204:acff:fe17:bf38 <name name="getifaddrs" arity="0"/> <fsummary>Return a list of interfaces and their addresses.</fsummary> <desc> - <p>Returns a list of 2-tuples containing interface names and the - interface addresses. <c><anno>Ifname</anno></c> is a Unicode string. - <c><anno>Hwaddr</anno></c> is hardware dependent, for example, on - Ethernet interfaces - it is the 6-byte Ethernet address (MAC address (EUI-48 address)).</p> - <p>The tuples <c>{addr,<anno>Addr</anno>}</c>, <c>{netmask,_}</c>, and - <c>{broadaddr,_}</c> are repeated in the result list if the interface - has multiple addresses. If you come across an interface with - multiple <c>{flag,_}</c> or <c>{hwaddr,_}</c> tuples, you have - a strange interface or possibly a bug in this function. The tuple - <c>{flag,_}</c> is mandatory, all others are optional.</p> - <p>Do not rely too much on the order of <c><anno>Flag</anno></c> atoms - or <c><anno>Ifopt</anno></c> tuples. There are however some rules:</p> - <list type="bulleted"> - <item><p>Immediately after - <c>{addr,_}</c> follows <c>{netmask,_}</c>.</p></item> - <item><p>Immediately thereafter follows <c>{broadaddr,_}</c> if flag - <c>broadcast</c> is <em>not</em> set and flag - <c>pointtopoint</c> <em>is</em> set.</p></item> - <item><p>Any <c>{netmask,_}</c>, <c>{broadaddr,_}</c>, or - <c>{dstaddr,_}</c> tuples that follow an <c>{addr,_}</c> - tuple concerns that address.</p></item> - </list> - <p>The tuple <c>{hwaddr,_}</c> is not returned on Solaris, as the - hardware address historically belongs to the link layer and only - the superuser can read such addresses.</p> - <warning> - <p>On Windows, the data is fetched from different OS API functions, - so the <c><anno>Netmask</anno></c> and <c><anno>Broadaddr</anno></c> - values can be calculated, just as some <c><anno>Flag</anno></c> - values. Report flagrant bugs.</p> - </warning> + <p> + Returns a list of 2-tuples containing interface names and + the interfaces' addresses. <c><anno>Ifname</anno></c> + is a Unicode string and + <c><anno>Ifopts</anno></c> is a list of + interface address description tuples. + </p> + <p> + The interface address description tuples + are documented under the type of the + <seealso marker="#type-getifaddrs_ifopts"> + <c><anno>Ifopts</anno></c> + </seealso> + value. + </p> + </desc> + </func> + + <func> + <name>getifaddrs(Opts) -> + {ok, [{Ifname, Ifopts}]} | {error, Posix} + </name> + <fsummary>Return a list of interfaces and their addresses.</fsummary> + <type> + <v> + Opts = [{netns, Namespace}] + </v> + <v> + Namespace = + <seealso marker="file#type-filename_all"> + file:filename_all() + </seealso> + </v> + <v>Ifname = string()</v> + <v> + Ifopts = + <seealso marker="#type-getifaddrs_ifopts"> + getifaddrs_ifopts() + </seealso> + </v> + <v>Posix = <seealso marker="#type-posix">posix()</seealso></v> + </type> + <desc> + <p> + The same as + <seealso marker="#getifaddrs/0"><c>getifaddrs/0</c></seealso> + but the <c>Option</c> + <c>{netns, Namespace}</c> sets a network namespace + for the OS call, on platforms that supports that feature. + </p> + <p> + See the socket option + <seealso marker="#option-netns"> + <c>{netns, Namespace}</c> + </seealso> + under + <seealso marker="#setopts/2"><c>setopts/2</c></seealso>. + </p> </desc> </func> @@ -950,20 +1049,29 @@ get_tcpi_sacked(Sock) -> </item> <tag><c>{mode, Mode :: binary | list}</c></tag> <item> - <p>Received <c>Packet</c> is delivered as defined by <c>Mode</c>. + <p> + Received <c>Packet</c> is delivered as defined by <c>Mode</c>. </p> </item> - <tag><c>{netns, Namespace :: file:filename_all()}</c></tag> + <tag> + <marker id="option-netns"/> + <c>{netns, Namespace :: file:filename_all()}</c> + </tag> <item> - <p>Sets a network namespace for the socket. Parameter + <p> + Sets a network namespace for the socket. Parameter <c>Namespace</c> is a filename defining the namespace, for example, <c>"/var/run/netns/example"</c>, typically created by command <c>ip netns add example</c>. This option must be used in a function call that creates a socket, that is, <seealso marker="gen_tcp#connect/3"><c>gen_tcp:connect/3,4</c></seealso>, <seealso marker="gen_tcp#listen/2"><c>gen_tcp:listen/2</c></seealso>, - <seealso marker="gen_udp#open/1"><c>gen_udp:open/1,2</c></seealso>, or - <seealso marker="gen_sctp#open/0"><c>gen_sctp:open/0,1,2</c></seealso>.</p> + <seealso marker="gen_udp#open/1"><c>gen_udp:open/1,2</c></seealso> + or + <seealso marker="gen_sctp#open/0"><c>gen_sctp:open/0,1,2</c></seealso>, + and also + <seealso marker="#getifaddrs/1"><c>getifaddrs/1</c></seealso>. + </p> <p>This option uses the Linux-specific syscall <c>setns()</c>, such as in Linux kernel 3.0 or later, and therefore only exists when the runtime system @@ -1039,6 +1147,18 @@ setcap cap_sys_admin,cap_sys_ptrace,cap_dac_read_search+epi beam.smp</code> is turned on for the socket, which means that also small amounts of data are sent immediately.</p> </item> + <tag><c>{nopush, Boolean}</c>(TCP/IP sockets)</tag> + <item> + <p>This translates to <c>TCP_NOPUSH</c> on BSD and + to <c>TCP_CORK</c> on Linux.</p> + <p>If <c>Boolean == true</c>, the corresponding option + is turned on for the socket, which means that small + amounts of data are accumulated until a full MSS-worth + of data is available or this option is turned off.</p> + <p>Note that while <c>TCP_NOPUSH</c> socket option is available on OSX, its semantics + is very different (e.g., unsetting it does not cause immediate send + of accumulated data). Hence, <c>nopush</c> option is intentionally ignored on OSX.</p> + </item> <tag><c>{packet, PacketType}</c>(TCP/IP sockets)</tag> <item> <p><marker id="packet"/>Defines the type of packets to use for a socket. diff --git a/lib/kernel/doc/src/logger.xml b/lib/kernel/doc/src/logger.xml index 464c65ba76..556f25f96a 100644 --- a/lib/kernel/doc/src/logger.xml +++ b/lib/kernel/doc/src/logger.xml @@ -290,7 +290,10 @@ logger:error("error happened because: ~p", [Reason]). % Without macro <section> <title>Macros</title> - <p>The following macros are defined:</p> + <p>The following macros are defined in <c>logger.hrl</c>, which + is included in a module with the directive</p> + <code> + -include_lib("kernel/include/logger.hrl").</code> <list> <item><c>?LOG_EMERGENCY(StringOrReport[,Metadata])</c></item> @@ -748,6 +751,14 @@ start(_, []) -> exists, its associated value will be changed to the given value. If it does not exist, it will be added.</p> + <p>If the value is incomplete, which for example can be the + case for the <c>config</c> key, it is up to the handler + implementation how the unspecified parts are set. For all + handlers in the Kernel application, unspecified data for + the <c>config</c> key is set to default values. To update + only specified data, and keep the existing configuration for + the rest, use <seealso marker="#update_handler_config-3"> + <c>update_handler_config/3</c></seealso>.</p> <p>See the definition of the <seealso marker="#type-handler_config"> <c>handler_config()</c></seealso> type for more @@ -933,6 +944,42 @@ logger:set_handler_config(HandlerId, maps:merge(Old, Config)). </func> <func> + <name name="update_handler_config" arity="3" clause_i="1"/> + <name name="update_handler_config" arity="3" clause_i="2"/> + <name name="update_handler_config" arity="3" clause_i="3"/> + <name name="update_handler_config" arity="3" clause_i="4"/> + <name name="update_handler_config" arity="3" clause_i="5"/> + <fsummary>Add or update configuration data for the specified + handler.</fsummary> + <type variable="HandlerId"/> + <type variable="Level" name_i="1"/> + <type variable="FilterDefault" name_i="2"/> + <type variable="Filters" name_i="3"/> + <type variable="Formatter" name_i="4"/> + <type variable="Config" name_i="5"/> + <type variable="Return"/> + <desc> + <p>Add or update configuration data for the specified + handler. If the given <c><anno>Key</anno></c> already + exists, its associated value will be changed + to the given value. If it does not exist, it will + be added.</p> + <p>If the value is incomplete, which for example can be the + case for the <c>config</c> key, it is up to the handler + implementation how the unspecified parts are set. For all + handlers in the Kernel application, unspecified data for + the <c>config</c> key is not changed. To reset unspecified + data to default values, + use <seealso marker="#set_handler_config-3"> + <c>set_handler_config/3</c></seealso>.</p> + <p>See the definition of + the <seealso marker="#type-handler_config"> + <c>handler_config()</c></seealso> type for more + information about the different parameters.</p> + </desc> + </func> + + <func> <name name="update_primary_config" arity="1"/> <fsummary>Update primary configuration data for Logger.</fsummary> <desc> @@ -1041,10 +1088,11 @@ logger:set_process_metadata(maps:merge(logger:get_process_metadata(), Meta)). </func> <func> - <name>HModule:changing_config(Config1, Config2) -> {ok, Config3} | {error, Reason}</name> + <name>HModule:changing_config(SetOrUpdate, OldConfig, NewConfig) -> {ok, Config} | {error, Reason}</name> <fsummary>The configuration for this handler is about to change.</fsummary> <type> - <v>Config1 = Config2 = Config3 = + <v>SetOrUpdate = set | update</v> + <v>OldConfig = NewConfig = Config = <seealso marker="#type-handler_config">handler_config()</seealso></v> <v>Reason = term()</v> </type> @@ -1053,18 +1101,51 @@ logger:set_process_metadata(maps:merge(logger:get_process_metadata(), Meta)). <p>The function is called on a temporary process when the configuration for a handler is about to change. The purpose is to verify and act on the new configuration.</p> - <p><c>Config1</c> is the existing configuration - and <c>Config2</c> is the new configuration.</p> + <p><c>OldConfig</c> is the existing configuration + and <c>NewConfig</c> is the new configuration.</p> <p>The handler identity is associated with the <c>id</c> key - in <c>Config1</c>.</p> + in <c>OldConfig</c>.</p> + <p><c>SetOrUpdate</c> has the value <c>set</c> if the + configuration change originates from a call to + <seealso marker="#set_handler_config-2"> + <c>set_handler_config/2,3</c></seealso>, and <c>update</c> + if it originates from <seealso marker="#update_handler_config-2"> + <c>update_handler_config/2,3</c></seealso>. The handler can + use this parameteter to decide how to update the value of + the <c>config</c> field, that is, the handler specific + configuration data. Typically, if <c>SetOrUpdate</c> + equals <c>set</c>, values that are not specified must be + given their default values. If <c>SetOrUpdate</c> + equals <c>update</c>, the values found in <c>OldConfig</c> + must be used instead.</p> <p>If everything succeeds, the callback function must return a - possibly adjusted configuration in <c>{ok,Config3}</c>.</p> + possibly adjusted configuration in <c>{ok,Config}</c>.</p> <p>If the configuration is faulty, the callback function must return <c>{error,Reason}</c>.</p> </desc> </func> <func> + <name>HModule:filter_config(Config) -> FilteredConfig</name> + <fsummary>Remove internal data from configuration.</fsummary> + <type> + <v>Config = FilteredConfig = + <seealso marker="#type-handler_config">handler_config()</seealso></v> + </type> + <desc> + <p>This callback function is optional.</p> + <p>The function is called when one of the Logger API functions + for fetching the handler configuration is called, for + example + <seealso marker="#get_handler_config-1"> + <c>logger:get_handler_config/1</c></seealso>.</p> + <p>It allows the handler to remove internal data fields from + its configuration data before it is returned to the + caller.</p> + </desc> + </func> + + <func> <name>HModule:log(LogEvent, Config) -> void()</name> <fsummary>Log the given log event.</fsummary> <type> @@ -1136,7 +1217,7 @@ logger:set_process_metadata(maps:merge(logger:get_process_metadata(), Meta)). <item><seealso marker="logger#set_handler_config-2"> <c>logger:set_handler_config/2,3</c></seealso></item> <item><seealso marker="logger#update_handler_config-2"> - <c>logger:updata_handler_config/2</c></seealso></item> + <c>logger:update_handler_config/2,3</c></seealso></item> <item><seealso marker="logger#update_formatter_config-2"> <c>logger:update_formatter_config/2</c></seealso></item> </list> diff --git a/lib/kernel/doc/src/logger_chapter.xml b/lib/kernel/doc/src/logger_chapter.xml index 4a81cfa34a..458e61cef5 100644 --- a/lib/kernel/doc/src/logger_chapter.xml +++ b/lib/kernel/doc/src/logger_chapter.xml @@ -113,7 +113,10 @@ of functions on the form <c>logger:Level/1,2,3</c>, which are all shortcuts for <seealso marker="logger#log-2"> - <c>logger:log(Level,Arg1[,Arg2[,Arg3]])</c></seealso>.</p> + <c>logger:log(Level,Arg1[,Arg2[,Arg3]])</c></seealso>.</p> + <p>The macros are defined in <c>logger.hrl</c>, which is included + in a module with the directive</p> + <code>-include_lib("kernel/include/logger.hrl").</code> <p>The difference between using the macros and the exported functions is that macros add location (originator) information to the metadata, and performs lazy evaluation by wrapping the @@ -384,8 +387,8 @@ logger:debug(#{got => connection_request, id => Id, state => State}, <p>In addition to the mandatory callback function <c>log/2</c>, a handler module can export the optional callback - functions <c>adding_handler/1</c>, <c>changing_config/2</c> - and <c>removing_handler/1</c>. See + functions <c>adding_handler/1</c>, <c>changing_config/3</c>, + <c>filter_config/1</c>, and <c>removing_handler/1</c>. See section <seealso marker="logger#handler_callback_functions">Handler Callback Functions</seealso> in the logger(3) manual page for more information about these function.</p> @@ -555,7 +558,7 @@ logger:debug(#{got => connection_request, id => Id, state => State}, <item><seealso marker="logger#set_handler_config-2"> <c>set_handler_config/2,3</c></seealso></item> <item><seealso marker="logger#update_handler_config-2"> - <c>update_handler_config/2</c></seealso></item> + <c>update_handler_config/2,3</c></seealso></item> <item><seealso marker="logger#add_handler_filter-3"> <c>add_handler_filter/3</c></seealso></item> <item><seealso marker="logger#remove_handler_filter-2"> @@ -704,9 +707,13 @@ logger:debug(#{got => connection_request, id => Id, state => State}, <item> <p>If <c>HandlerId</c> is <c>default</c>, then this entry modifies the default handler, equivalent to calling</p> - <pre><seealso marker="logger#set_handler_config-2"> - logger:set_handler_config(default, Module, HandlerConfig) - </seealso></pre> + <pre><seealso marker="logger#remove_handler-1"> + logger:remove_handler(default) + </seealso></pre> + <p>followed by</p> + <pre><seealso marker="logger#add_handler-3"> + logger:add_handler(default, Module, HandlerConfig) + </seealso></pre> <p>For all other values of <c>HandlerId</c>, this entry adds a new handler, equivalent to calling</p> <pre><seealso marker="logger:add_handler/3"> @@ -1024,7 +1031,8 @@ ok</pre> <list> <item><c>adding_handler(Config)</c></item> <item><c>removing_handler(Config)</c></item> - <item><c>changing_config(OldConfig, NewConfig)</c></item> + <item><c>changing_config(SetOrUpdate, OldConfig, NewConfig)</c></item> + <item><c>filter_config(Config)</c></item> </list> <p>When a handler is added, by for example a call to <seealso marker="logger#add_handler-3"> @@ -1043,11 +1051,18 @@ ok</pre> <p>When <seealso marker="logger#set_handler_config-2"> <c>logger:set_handler_config/2,3</c></seealso> or <seealso marker="logger#update_handler_config/2"> - <c>logger:update_handler_config/2</c></seealso> is called, + <c>logger:update_handler_config/2,3</c></seealso> is called, Logger - calls <c>HModule:changing_config(OldConfig, NewConfig)</c>. If + calls <c>HModule:changing_config(SetOrUpdate, OldConfig, NewConfig)</c>. If this function returns <c>{ok,NewConfig1}</c>, Logger writes <c>NewConfig1</c> to the configuration database.</p> + <p>When <seealso marker="logger#get_config-0"> + <c>logger:get_config/0</c></seealso> or + <seealso marker="logger#get_handler_config-0"> + <c>logger:get_handler_config/0,1</c></seealso> is called, + Logger calls <c>HModule:filter_config(Config)</c>. This function + must return the handler configuration where internal data is + removed.</p> <p>A simple handler that prints to the terminal can be implemented as follows:</p> diff --git a/lib/kernel/doc/src/logger_disk_log_h.xml b/lib/kernel/doc/src/logger_disk_log_h.xml index dfe2ab3275..d9b941a0a9 100644 --- a/lib/kernel/doc/src/logger_disk_log_h.xml +++ b/lib/kernel/doc/src/logger_disk_log_h.xml @@ -66,6 +66,10 @@ corresponds to the <c>name</c> property in the <seealso marker="disk_log#open-1"><c>dlog_option()</c></seealso> datatype.</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><c>type</c></tag> <item> @@ -73,6 +77,8 @@ corresponds to the <c>type</c> property in the <seealso marker="disk_log#open-1"><c>dlog_option()</c></seealso> datatype.</p> + <p>The value is set when the handler is added, and it can not + be changed in runtime.</p> <p>Defaults to <c>wrap</c>.</p> </item> <tag><c>max_no_files</c></tag> @@ -82,6 +88,8 @@ corresponds to the <c>MaxNoFiles</c> element in the <c>size</c> property in the <seealso marker="disk_log#open-1"><c>dlog_option()</c></seealso> datatype.</p> + <p>The value is set when the handler is added, and it can not + be changed in runtime.</p> <p>Defaults to <c>10</c>.</p> <p>The setting has no effect on a halt log.</p> </item> @@ -93,6 +101,8 @@ corresponds to the <c>MaxNoBytes</c> element in the <c>size</c> property in the <seealso marker="disk_log#open-1"><c>dlog_option()</c></seealso> datatype.</p> + <p>The value is set when the handler is added, and it can not + be changed in runtime.</p> <p>Defaults to <c>1048576</c> bytes for a wrap log, and <c>infinity</c> for a halt log.</p> </item> diff --git a/lib/kernel/doc/src/logger_formatter.xml b/lib/kernel/doc/src/logger_formatter.xml index 24772fd6c4..d066e263df 100644 --- a/lib/kernel/doc/src/logger_formatter.xml +++ b/lib/kernel/doc/src/logger_formatter.xml @@ -303,7 +303,7 @@ exit_reason: "It crashed"</code> <item><seealso marker="logger#set_handler_config-2"> <c>logger:set_handler_config/2,3</c></seealso></item> <item><seealso marker="logger#update_handler_config-2"> - <c>logger:updata_handler_config/2</c></seealso></item> + <c>logger:update_handler_config/2</c></seealso></item> <item><seealso marker="logger#update_formatter_config-2"> <c>logger:update_formatter_config/2</c></seealso></item> </list> diff --git a/lib/kernel/doc/src/logger_std_h.xml b/lib/kernel/doc/src/logger_std_h.xml index fcd8189bae..e156f5719b 100644 --- a/lib/kernel/doc/src/logger_std_h.xml +++ b/lib/kernel/doc/src/logger_std_h.xml @@ -74,7 +74,9 @@ circular logging. Use the disk_log handler, <seealso marker="logger_disk_log_h"><c>logger_disk_log_h</c></seealso>, for this.</p> - <p> Defaults to <c>standard_io</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> </item> <tag><c>filesync_repeat_interval</c></tag> <item> diff --git a/lib/kernel/doc/src/notes.xml b/lib/kernel/doc/src/notes.xml index 8188ede6a2..bfbaf6ef3e 100644 --- a/lib/kernel/doc/src/notes.xml +++ b/lib/kernel/doc/src/notes.xml @@ -31,6 +31,22 @@ </header> <p>This document describes the changes made to the Kernel application.</p> +<section><title>Kernel 6.1.1</title> + + <section><title>Fixed Bugs and Malfunctions</title> + <list> + <item> + <p> + Fix bug causing net_kernel process crash on connection + attempt from node with name identical to local node.</p> + <p> + Own Id: OTP-15438 Aux Id: ERL-781 </p> + </item> + </list> + </section> + +</section> + <section><title>Kernel 6.1</title> <section><title>Fixed Bugs and Malfunctions</title> diff --git a/lib/kernel/src/inet.erl b/lib/kernel/src/inet.erl index 5dd68dc285..9f22eb6aaa 100644 --- a/lib/kernel/src/inet.erl +++ b/lib/kernel/src/inet.erl @@ -154,6 +154,15 @@ 'running' | 'multicast' | 'loopback']} | {'hwaddr', ether_address()}. +-type getifaddrs_ifopts() :: + [Ifopt :: {flags, Flags :: [up | broadcast | loopback | + pointtopoint | running | multicast]} | + {addr, Addr :: ip_address()} | + {netmask, Netmask :: ip_address()} | + {broadaddr, Broadaddr :: ip_address()} | + {dstaddr, Dstaddr :: ip_address()} | + {hwaddr, Hwaddr :: [byte()]}]. + -type address_family() :: 'inet' | 'inet6' | 'local'. -type socket_protocol() :: 'tcp' | 'udp' | 'sctp'. -type socket_type() :: 'stream' | 'dgram' | 'seqpacket'. @@ -321,32 +330,32 @@ getopts(Socket, Opts) -> Other end. --spec getifaddrs(Socket :: socket()) -> - {'ok', [string()]} | {'error', posix()}. - +-spec getifaddrs( + [Option :: {netns, Namespace :: file:filename_all()}] + | socket()) -> + {'ok', [{Ifname :: string(), + Ifopts :: getifaddrs_ifopts()}]} + | {'error', posix()}. +getifaddrs(Opts) when is_list(Opts) -> + withsocket(fun(S) -> prim_inet:getifaddrs(S) end, Opts); getifaddrs(Socket) -> prim_inet:getifaddrs(Socket). --spec getifaddrs() -> {ok, Iflist} | {error, posix()} when - Iflist :: [{Ifname,[Ifopt]}], - Ifname :: string(), - Ifopt :: {flags,[Flag]} | {addr,Addr} | {netmask,Netmask} - | {broadaddr,Broadaddr} | {dstaddr,Dstaddr} - | {hwaddr,Hwaddr}, - Flag :: up | broadcast | loopback | pointtopoint - | running | multicast, - Addr :: ip_address(), - Netmask :: ip_address(), - Broadaddr :: ip_address(), - Dstaddr :: ip_address(), - Hwaddr :: [byte()]. - +-spec getifaddrs() -> + {'ok', [{Ifname :: string(), + Ifopts :: getifaddrs_ifopts()}]} + | {'error', posix()}. getifaddrs() -> withsocket(fun(S) -> prim_inet:getifaddrs(S) end). --spec getiflist(Socket :: socket()) -> - {'ok', [string()]} | {'error', posix()}. +-spec getiflist( + [Option :: {netns, Namespace :: file:filename_all()}] + | socket()) -> + {'ok', [string()]} | {'error', posix()}. + +getiflist(Opts) when is_list(Opts) -> + withsocket(fun(S) -> prim_inet:getiflist(S) end, Opts); getiflist(Socket) -> prim_inet:getiflist(Socket). @@ -363,11 +372,19 @@ getiflist() -> ifget(Socket, Name, Opts) -> prim_inet:ifget(Socket, Name, Opts). --spec ifget(Name :: string() | atom(), Opts :: [if_getopt()]) -> +-spec ifget( + Name :: string() | atom(), + Opts :: [if_getopt() | + {netns, Namespace :: file:filename_all()}]) -> {'ok', [if_getopt_result()]} | {'error', posix()}. ifget(Name, Opts) -> - withsocket(fun(S) -> prim_inet:ifget(S, Name, Opts) end). + {NSOpts,IFOpts} = + lists:partition( + fun ({netns,_}) -> true; + (_) -> false + end, Opts), + withsocket(fun(S) -> prim_inet:ifget(S, Name, IFOpts) end, NSOpts). -spec ifset(Socket :: socket(), Name :: string() | atom(), @@ -377,11 +394,19 @@ ifget(Name, Opts) -> ifset(Socket, Name, Opts) -> prim_inet:ifset(Socket, Name, Opts). --spec ifset(Name :: string() | atom(), Opts :: [if_setopt()]) -> +-spec ifset( + Name :: string() | atom(), + Opts :: [if_setopt() | + {netns, Namespace :: file:filename_all()}]) -> 'ok' | {'error', posix()}. ifset(Name, Opts) -> - withsocket(fun(S) -> prim_inet:ifset(S, Name, Opts) end). + {NSOpts,IFOpts} = + lists:partition( + fun ({netns,_}) -> true; + (_) -> false + end, Opts), + withsocket(fun(S) -> prim_inet:ifset(S, Name, IFOpts) end, NSOpts). -spec getif() -> {'ok', [{ip_address(), ip_address() | 'undefined', ip_address()}]} | @@ -391,10 +416,14 @@ getif() -> withsocket(fun(S) -> getif(S) end). %% backwards compatible getif --spec getif(Socket :: socket()) -> +-spec getif( + [Option :: {netns, Namespace :: file:filename_all()}] + | socket()) -> {'ok', [{ip_address(), ip_address() | 'undefined', ip_address()}]} | {'error', posix()}. +getif(Opts) when is_list(Opts) -> + withsocket(fun(S) -> getif(S) end, Opts); getif(Socket) -> case prim_inet:getiflist(Socket) of {ok, IfList} -> @@ -415,7 +444,10 @@ getif(Socket) -> end. withsocket(Fun) -> - case inet_udp:open(0,[]) of + withsocket(Fun, []). +%% +withsocket(Fun, Opts) -> + case inet_udp:open(0, Opts) of {ok,Socket} -> Res = Fun(Socket), inet_udp:close(Socket), diff --git a/lib/kernel/src/inet_int.hrl b/lib/kernel/src/inet_int.hrl index c8e09d18ad..f6525d7261 100644 --- a/lib/kernel/src/inet_int.hrl +++ b/lib/kernel/src/inet_int.hrl @@ -162,6 +162,7 @@ -define(INET_OPT_PKTOPTIONS, 45). -define(INET_OPT_TTL, 46). -define(INET_OPT_RECVTTL, 47). +-define(TCP_OPT_NOPUSH, 48). % Specific SCTP options: separate range: -define(SCTP_OPT_RTOINFO, 100). -define(SCTP_OPT_ASSOCINFO, 101). diff --git a/lib/kernel/src/inet_tcp_dist.erl b/lib/kernel/src/inet_tcp_dist.erl index d1701afdaa..c37212b0f9 100644 --- a/lib/kernel/src/inet_tcp_dist.erl +++ b/lib/kernel/src/inet_tcp_dist.erl @@ -450,7 +450,7 @@ get_tcp_address(Driver, Socket) -> get_address_resolver(EpmdModule) -> case erlang:function_exported(EpmdModule, address_please, 3) of true -> {EpmdModule, address_please}; - _ -> {inet, getaddr} + _ -> {erl_epmd, address_please} end. %% ------------------------------------------------------------ diff --git a/lib/kernel/src/kernel.appup.src b/lib/kernel/src/kernel.appup.src index 305a1c788c..e73cea8351 100644 --- a/lib/kernel/src/kernel.appup.src +++ b/lib/kernel/src/kernel.appup.src @@ -16,13 +16,40 @@ %% limitations under the License. %% %% %CopyrightEnd% +%% +%% We allow upgrade from, and downgrade to all previous +%% versions from the following OTP releases: +%% - OTP 20 +%% - OTP 21 +%% +%% We also allow upgrade from, and downgrade to all +%% versions that have branched off from the above +%% stated previous versions. +%% {"%VSN%", - %% Up from - max one major revision back - [{<<"5\\.3(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-20.0 - {<<"5\\.4(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-20.1+ - {<<"6\\.0(\\.[0-9]+)*">>,[restart_new_emulator]}], % OTP-21 - %% Down to - max one major revision back - [{<<"5\\.3(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-20.0 - {<<"5\\.4(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-20.1+ - {<<"6\\.0(\\.[0-9]+)*">>,[restart_new_emulator]}] % OTP-21 -}. + [{<<"^5\\.3$">>,[restart_new_emulator]}, + {<<"^5\\.3\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^5\\.3\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^5\\.4$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.2(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.3(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.0$">>,[restart_new_emulator]}, + {<<"^6\\.0\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^6\\.0\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.1$">>,[restart_new_emulator]}, + {<<"^6\\.1\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}], + [{<<"^5\\.3$">>,[restart_new_emulator]}, + {<<"^5\\.3\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^5\\.3\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^5\\.4$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.2(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.3(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.0$">>,[restart_new_emulator]}, + {<<"^6\\.0\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^6\\.0\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.1$">>,[restart_new_emulator]}, + {<<"^6\\.1\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}]}. diff --git a/lib/kernel/src/logger.erl b/lib/kernel/src/logger.erl index 752dd8d493..6762998d4f 100644 --- a/lib/kernel/src/logger.erl +++ b/lib/kernel/src/logger.erl @@ -43,7 +43,8 @@ get_module_level/0, get_module_level/1, set_primary_config/1, set_primary_config/2, set_handler_config/2, set_handler_config/3, - update_primary_config/1, update_handler_config/2, + update_primary_config/1, + update_handler_config/2, update_handler_config/3, update_formatter_config/2, update_formatter_config/3, get_primary_config/0, get_handler_config/1, get_handler_config/0, get_handler_ids/0, get_config/0, @@ -423,6 +424,29 @@ set_handler_config(HandlerId,Config) -> update_primary_config(Config) -> logger_server:update_config(primary,Config). +-spec update_handler_config(HandlerId,level,Level) -> Return when + HandlerId :: handler_id(), + Level :: level() | all | none, + Return :: ok | {error,term()}; + (HandlerId,filter_default,FilterDefault) -> Return when + HandlerId :: handler_id(), + FilterDefault :: log | stop, + Return :: ok | {error,term()}; + (HandlerId,filters,Filters) -> Return when + HandlerId :: handler_id(), + Filters :: [{filter_id(),filter()}], + Return :: ok | {error,term()}; + (HandlerId,formatter,Formatter) -> Return when + HandlerId :: handler_id(), + Formatter :: {module(), formatter_config()}, + Return :: ok | {error,term()}; + (HandlerId,config,Config) -> Return when + HandlerId :: handler_id(), + Config :: term(), + Return :: ok | {error,term()}. +update_handler_config(HandlerId,Key,Value) -> + logger_server:update_config(HandlerId,Key,Value). + -spec update_handler_config(HandlerId,Config) -> ok | {error,term()} when HandlerId :: handler_id(), Config :: handler_config(). @@ -439,7 +463,14 @@ get_primary_config() -> HandlerId :: handler_id(), Config :: handler_config(). get_handler_config(HandlerId) -> - logger_config:get(?LOGGER_TABLE,HandlerId). + case logger_config:get(?LOGGER_TABLE,HandlerId) of + {ok,#{module:=Module}=Config} -> + {ok,try Module:filter_config(Config) + catch _:_ -> Config + end}; + Error -> + Error + end. -spec get_handler_config() -> [Config] when Config :: handler_config(). diff --git a/lib/kernel/src/logger_config.erl b/lib/kernel/src/logger_config.erl index 6bfe658552..5e9faf332c 100644 --- a/lib/kernel/src/logger_config.erl +++ b/lib/kernel/src/logger_config.erl @@ -31,7 +31,9 @@ -include("logger_internal.hrl"). new(Name) -> - _ = ets:new(Name,[set,protected,named_table,{write_concurrency,true}]), + _ = ets:new(Name,[set,protected,named_table, + {read_concurrency,true}, + {write_concurrency,true}]), ets:whereis(Name). delete(Tid,Id) -> diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index a8f141f135..41e0d51a9d 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -19,58 +19,33 @@ %% -module(logger_disk_log_h). --behaviour(gen_server). - -include("logger.hrl"). -include("logger_internal.hrl"). -include("logger_h_common.hrl"). %%% API --export([start_link/3, info/1, filesync/1, reset/1]). +-export([info/1, filesync/1, reset/1]). -%% gen_server callbacks --export([init/1, handle_call/3, handle_cast/2, handle_info/2, - terminate/2, code_change/3]). +%% logger_h_common callbacks +-export([init/2, check_config/4, reset_state/2, + filesync/3, write/4, handle_info/3, terminate/3]). %% logger callbacks --export([log/2, adding_handler/1, removing_handler/1, changing_config/2]). - -%% handler internal --export([log_handler_info/4]). +-export([log/2, adding_handler/1, removing_handler/1, changing_config/3, + filter_config/1]). %%%=================================================================== %%% API %%%=================================================================== %%%----------------------------------------------------------------- -%%% Start a disk_log handler process and link to caller. -%%% This function is called by the kernel supervisor when this -%%% handler process gets added (as a result of calling add/3). --spec start_link(Name, Config, HandlerState) -> {ok,Pid} | {error,Reason} when - Name :: atom(), - Config :: logger:handler_config(), - HandlerState :: map(), - Pid :: pid(), - Reason :: term(). - -start_link(Name, Config, HandlerState) -> - proc_lib:start_link(?MODULE,init,[[Name,Config,HandlerState]]). - -%%%----------------------------------------------------------------- %%% -spec filesync(Name) -> ok | {error,Reason} when Name :: atom(), Reason :: handler_busy | {badarg,term()}. -filesync(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - disk_log_sync, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; filesync(Name) -> - {error,{badarg,{filesync,[Name]}}}. + logger_h_common:filesync(?MODULE,Name). %%%----------------------------------------------------------------- %%% @@ -79,15 +54,8 @@ filesync(Name) -> Info :: term(), Reason :: handler_busy | {badarg,term()}. -info(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - info, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; info(Name) -> - {error,{badarg,{info,[Name]}}}. + logger_h_common:info(?MODULE,Name). %%%----------------------------------------------------------------- %%% @@ -95,16 +63,8 @@ info(Name) -> Name :: atom(), Reason :: handler_busy | {badarg,term()}. -reset(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - reset, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; reset(Name) -> - {error,{badarg,{reset,[Name]}}}. - + logger_h_common:reset(?MODULE,Name). %%%=================================================================== %%% logger callbacks @@ -112,89 +72,82 @@ reset(Name) -> %%%----------------------------------------------------------------- %%% Handler being added -adding_handler(#{id:=Name}=Config) -> - case check_config(adding, Config) of - {ok, Config1} -> - %% create initial handler state by merging defaults with config - HConfig = maps:get(config, Config1, #{}), - HState = maps:merge(get_init_state(), HConfig), - case logger_h_common:overload_levels_ok(HState) of - true -> - start(Name, Config1, HState); - false -> - #{sync_mode_qlen := SMQL, - drop_mode_qlen := DMQL, - flush_qlen := FQL} = HState, - {error,{invalid_levels,{SMQL,DMQL,FQL}}} - end; - Error -> - Error - end. +adding_handler(Config) -> + logger_h_common:adding_handler(Config). %%%----------------------------------------------------------------- %%% Updating handler config -changing_config(OldConfig = #{id:=Name, config:=OldHConfig}, - NewConfig = #{id:=Name, config:=NewHConfig}) -> - #{type:=Type, file:=File, max_no_files:=MaxFs, - max_no_bytes:=MaxBytes} = OldHConfig, - case NewHConfig of - #{type:=Type, file:=File, max_no_files:=MaxFs, - max_no_bytes:=MaxBytes} -> - changing_config1(OldConfig, NewConfig); - _ -> - {error,{illegal_config_change,OldConfig,NewConfig}} - end; -changing_config(OldConfig, NewConfig) -> - {error,{illegal_config_change,OldConfig,NewConfig}}. - -changing_config1(OldConfig=#{config:=OldHConfig}, NewConfig) -> - case check_config(changing, NewConfig) of - {ok,NewConfig1 = #{config:=NewHConfig}} -> - #{handler_pid:=HPid, - mode_tab:=ModeTab} = OldHConfig, - NewHConfig1 = NewHConfig#{handler_pid=>HPid, - mode_tab=>ModeTab}, - NewConfig2 = NewConfig1#{config=>NewHConfig1}, - try gen_server:call(HPid, {change_config,OldConfig,NewConfig2}, - ?DEFAULT_CALL_TIMEOUT) of - ok -> {ok,NewConfig2}; - HError -> HError - catch - _:{timeout,_} -> {error,handler_busy} - end; - Error -> - Error - end. +changing_config(SetOrUpdate, OldConfig, NewConfig) -> + logger_h_common:changing_config(SetOrUpdate, OldConfig, NewConfig). -check_config(adding, #{id:=Name}=Config) -> - %% merge handler specific config data - HConfig = merge_default_logopts(Name, maps:get(config, Config, #{})), - case check_h_config(maps:to_list(HConfig)) of +%%%----------------------------------------------------------------- +%%% Handler being removed +removing_handler(Config) -> + logger_h_common:removing_handler(Config). + +%%%----------------------------------------------------------------- +%%% Log a string or report +-spec log(LogEvent, Config) -> ok when + LogEvent :: logger:log_event(), + Config :: logger:handler_config(). + +log(LogEvent, Config) -> + logger_h_common:log(LogEvent, Config). + +%%%----------------------------------------------------------------- +%%% Remove internal fields from configuration +filter_config(Config) -> + logger_h_common:filter_config(Config). + +%%%=================================================================== +%%% logger_h_common callbacks +%%%=================================================================== +init(Name, #{file:=File,type:=Type,max_no_bytes:=MNB,max_no_files:=MNF}) -> + case open_disk_log(Name, File, Type, MNB, MNF) of ok -> - {ok,Config#{config=>HConfig}}; + {ok,#{log_opts => #{file => File, + type => Type, + max_no_bytes => MNB, + max_no_files => MNF}, + prev_log_result => ok, + prev_sync_result => ok, + prev_disk_log_info => undefined}}; Error -> Error - end; -check_config(changing, Config) -> - HConfig = maps:get(config, Config, #{}), - case check_h_config(maps:to_list(HConfig)) of - ok -> {ok,Config}; - Error -> Error end. -merge_default_logopts(Name, HConfig) -> - Type = maps:get(type, HConfig, wrap), - {DefaultNoFiles,DefaultNoBytes} = - case Type of - halt -> {undefined,infinity}; - _wrap -> {10,1048576} +check_config(Name,set,undefined,HConfig0) -> + HConfig=merge_default_logopts(Name,maps:merge(get_default_config(),HConfig0)), + check_config(HConfig); +check_config(_Name,SetOrUpdate,OldHConfig,NewHConfig0) -> + WriteOnce = maps:with([type,file,max_no_files,max_no_bytes],OldHConfig), + Default = + case SetOrUpdate of + set -> + %% Do not reset write-once fields to defaults + maps:merge(get_default_config(),WriteOnce); + update -> + OldHConfig end, - {ok,Dir} = file:get_cwd(), - Defaults = #{file => filename:join(Dir,Name), - max_no_files => DefaultNoFiles, - max_no_bytes => DefaultNoBytes, - type => Type}, - maps:merge(Defaults, HConfig). + + NewHConfig = maps:merge(Default,NewHConfig0), + + %% Fail if write-once fields are changed + case maps:with([type,file,max_no_files,max_no_bytes],NewHConfig) of + WriteOnce -> + check_config(NewHConfig); + Other -> + {Old,New} = logger_server:diff_maps(WriteOnce,Other), + {error,{illegal_config_change,?MODULE,Old,New}} + end. + +check_config(HConfig) -> + case check_h_config(maps:to_list(HConfig)) of + ok -> + {ok,HConfig}; + {error,{Key,Value}} -> + {error,{invalid_config,?MODULE,#{Key=>Value}}} + end. check_h_config([{file,File}|Config]) when is_list(File) -> check_h_config(Config); @@ -208,447 +161,59 @@ check_h_config([{max_no_bytes,N}|Config]) when is_integer(N), N>0 -> check_h_config(Config); check_h_config([{type,Type}|Config]) when Type==wrap; Type==halt -> check_h_config(Config); -check_h_config([Other | Config]) -> - case logger_h_common:check_common_config(Other) of - valid -> - check_h_config(Config); - invalid -> - {error,{invalid_config,?MODULE,Other}} - end; +check_h_config([Other | _]) -> + {error,Other}; check_h_config([]) -> ok. -%%%----------------------------------------------------------------- -%%% Handler being removed -removing_handler(#{id:=Name}) -> - stop(Name). - -%%%----------------------------------------------------------------- -%%% Log a string or report --spec log(LogEvent, Config) -> ok when - LogEvent :: logger:log_event(), - Config :: logger:handler_config(). +get_default_config() -> + #{}. -log(LogEvent, Config = #{id := Name, - config := #{handler_pid := HPid, - mode_tab := ModeTab}}) -> - %% if the handler has crashed, we must drop this event - %% and hope the handler restarts so we can try again - true = is_process_alive(HPid), - Bin = logger_h_common:log_to_binary(LogEvent, Config), - logger_h_common:call_cast_or_drop(Name, HPid, ModeTab, Bin). +merge_default_logopts(Name, HConfig) -> + Type = maps:get(type, HConfig, wrap), + {DefaultNoFiles,DefaultNoBytes} = + case Type of + halt -> {undefined,infinity}; + _wrap -> {10,1048576} + end, + {ok,Dir} = file:get_cwd(), + Defaults = #{file => filename:join(Dir,Name), + max_no_files => DefaultNoFiles, + max_no_bytes => DefaultNoBytes, + type => Type}, + maps:merge(Defaults, HConfig). -%%%=================================================================== -%%% gen_server callbacks -%%%=================================================================== +filesync(Name,_Mode,State) -> + Result = ?disk_log_sync(Name), + maybe_notify_error(Name, filesync, Result, prev_sync_result, State). -init([Name, - Config = #{config := HConfig = #{file:=File, - type:=Type, - max_no_bytes:=MNB, - max_no_files:=MNF}}, - State = #{dl_sync_int := DLSyncInt}]) -> - - RegName = ?name_to_reg_name(?MODULE,Name), - register(RegName, self()), - process_flag(trap_exit, true), - process_flag(message_queue_data, off_heap), - - ?init_test_hooks(), - ?start_observation(Name), - - LogOpts = #{file=>File, type=>Type, max_no_bytes=>MNB, max_no_files=>MNF}, - case open_disk_log(Name, File, Type, MNB, MNF) of - ok -> - try ets:new(Name, [public]) of - ModeTab -> - ?set_mode(ModeTab, async), - T0 = ?timestamp(), - State1 = - ?merge_with_stats(State#{ - id => Name, - mode_tab => ModeTab, - mode => async, - dl_sync => DLSyncInt, - log_opts => LogOpts, - last_qlen => 0, - last_log_ts => T0, - burst_win_ts => T0, - burst_msg_count => 0, - last_op => sync, - prev_log_result => ok, - prev_sync_result => ok, - prev_disk_log_info => undefined}), - Config1 = - Config#{config => HConfig#{handler_pid => self(), - mode_tab => ModeTab}}, - proc_lib:init_ack({ok,self(),Config1}), - gen_server:cast(self(), repeated_disk_log_sync), - case logger_h_common:unset_restart_flag(Name, ?MODULE) of - true -> - %% inform about restart - gen_server:cast(self(), {log_handler_info, - "Handler ~p restarted", - [Name]}); - false -> - %% initial start - ok - end, - gen_server:enter_loop(?MODULE, [], State1) - catch - _:Error -> - unregister(RegName), - logger_h_common:error_notify({open_disk_log,Name,Error}), - proc_lib:init_ack(Error) - end; - Error -> - unregister(RegName), - logger_h_common:error_notify({open_disk_log,Name,Error}), - proc_lib:init_ack(Error) - end. +write(Name, Mode, Bin, State) -> + Result = ?disk_log_write(Name, Mode, Bin), + maybe_notify_error(Name, log, Result, prev_log_result, State). -%% This is the synchronous log event. -handle_call({log, Bin}, _From, State) -> - {Result,State1} = do_log(Bin, call, State), - %% Result == ok | dropped - {reply, Result, State1}; - -handle_call(disk_log_sync, _From, State = #{id := Name}) -> - State1 = #{prev_sync_result := Result} = disk_log_sync(Name, State), - {reply, Result, State1}; - -handle_call({change_config,_OldConfig,NewConfig}, _From, - State = #{filesync_repeat_interval := FSyncInt0}) -> - HConfig = maps:get(config, NewConfig, #{}), - State1 = #{sync_mode_qlen := SMQL, - drop_mode_qlen := DMQL, - flush_qlen := FQL} = maps:merge(State, HConfig), - case logger_h_common:overload_levels_ok(State1) of - true -> - _ = - case maps:get(filesync_repeat_interval, HConfig, undefined) of - undefined -> - ok; - no_repeat -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, - State, - undefined)); - FSyncInt0 -> - ok; - _FSyncInt1 -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, - State, - undefined)), - _ = gen_server:cast(self(), repeated_disk_log_sync) - end, - {reply, ok, State1}; - false -> - {reply, {error,{invalid_levels,{SMQL,DMQL,FQL}}}, State} - end; - -handle_call(info, _From, State) -> - {reply, State, State}; - -handle_call(reset, _From, State) -> - State1 = ?merge_with_stats(State), - {reply, ok, State1#{last_qlen => 0, - last_log_ts => ?timestamp(), - prev_log_result => ok, - prev_sync_result => ok, - prev_disk_log_info => undefined}}; - -handle_call(stop, _From, State) -> - {stop, {shutdown,stopped}, ok, State}. - - -%% This is the asynchronous log event. -handle_cast({log, Bin}, State) -> - {_,State1} = do_log(Bin, cast, State), - {noreply, State1}; - -handle_cast({log_handler_info, Format, Args}, State = #{id:=Name}) -> - log_handler_info(Name, Format, Args, State), - {noreply, State}; - -%% If FILESYNC_REPEAT_INTERVAL is set to a millisec value, this -%% clause gets called repeatedly by the handler. In order to -%% guarantee that a filesync *always* happens after the last log -%% event, the repeat operation must be active! -handle_cast(repeated_disk_log_sync, - State = #{id := Name, - filesync_repeat_interval := FSyncInt, - last_op := LastOp}) -> - State1 = - if is_integer(FSyncInt) -> - %% only do filesync if something has been - %% written since last time we checked - NewState = if LastOp == sync -> - State; - true -> - disk_log_sync(Name, State) - end, - {ok,TRef} = - timer:apply_after(FSyncInt, gen_server,cast, - [self(),repeated_disk_log_sync]), - NewState#{rep_sync_tref => TRef, last_op => sync}; - true -> - State - end, - {noreply,State1}. +reset_state(_Name, State) -> + State#{prev_log_result => ok, + prev_sync_result => ok, + prev_disk_log_info => undefined}. %% The disk log owner must handle status messages from disk_log. -handle_info({disk_log, _Node, _Log, {wrap,_NoLostItems}}, State) -> - {noreply, State}; -handle_info({disk_log, _Node, Log, Info = {truncated,_NoLostItems}}, - State = #{id := Name, prev_disk_log_info := PrevInfo}) -> - error_notify_new(Info, PrevInfo, {disk_log,Name,Log,Info}), - {noreply, State#{prev_disk_log_info => Info}}; -handle_info({disk_log, _Node, Log, Info = {blocked_log,_Items}}, - State = #{id := Name, prev_disk_log_info := PrevInfo}) -> - error_notify_new(Info, PrevInfo, {disk_log,Name,Log,Info}), - {noreply, State#{prev_disk_log_info => Info}}; -handle_info({disk_log, _Node, Log, full}, - State = #{id := Name, prev_disk_log_info := PrevInfo}) -> - error_notify_new(full, PrevInfo, {disk_log,Name,Log,full}), - {noreply, State#{prev_disk_log_info => full}}; -handle_info({disk_log, _Node, Log, Info = {error_status,_Status}}, - State = #{id := Name, prev_disk_log_info := PrevInfo}) -> - error_notify_new(Info, PrevInfo, {disk_log,Name,Log,Info}), - {noreply, State#{prev_disk_log_info => Info}}; - -handle_info({'EXIT',_Pid,_Why}, State = #{id := _Name}) -> - {noreply, State}; - -handle_info(_, State) -> - {noreply, State}. - -terminate(Reason, State = #{id := Name}) -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, State, - undefined)), +handle_info(Name, {disk_log, _Node, Log, Info={truncated,_NoLostItems}}, State) -> + maybe_notify_status(Name, Log, Info, prev_disk_log_info, State); +handle_info(Name, {disk_log, _Node, Log, Info = {blocked_log,_Items}}, State) -> + maybe_notify_status(Name, Log, Info, prev_disk_log_info, State); +handle_info(Name, {disk_log, _Node, Log, Info = full}, State) -> + maybe_notify_status(Name, Log, Info, prev_disk_log_info, State); +handle_info(Name, {disk_log, _Node, Log, Info = {error_status,_Status}}, State) -> + maybe_notify_status(Name, Log, Info, prev_disk_log_info, State); +handle_info(_, _, State) -> + State. + +terminate(Name, _Reason, _State) -> _ = close_disk_log(Name, normal), - ok = logger_h_common:stop_or_restart(Name, Reason, State), - unregister(?name_to_reg_name(?MODULE, Name)), ok. -code_change(_OldVsn, State, _Extra) -> - {ok, State}. - %%%----------------------------------------------------------------- %%% Internal functions - -%%%----------------------------------------------------------------- -%%% -get_init_state() -> - #{sync_mode_qlen => ?SYNC_MODE_QLEN, - drop_mode_qlen => ?DROP_MODE_QLEN, - flush_qlen => ?FLUSH_QLEN, - burst_limit_enable => ?BURST_LIMIT_ENABLE, - burst_limit_max_count => ?BURST_LIMIT_MAX_COUNT, - burst_limit_window_time => ?BURST_LIMIT_WINDOW_TIME, - overload_kill_enable => ?OVERLOAD_KILL_ENABLE, - overload_kill_qlen => ?OVERLOAD_KILL_QLEN, - overload_kill_mem_size => ?OVERLOAD_KILL_MEM_SIZE, - overload_kill_restart_after => ?OVERLOAD_KILL_RESTART_AFTER, - dl_sync_int => ?CONTROLLER_SYNC_INTERVAL, - filesync_ok_qlen => ?FILESYNC_OK_QLEN, - filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}. - -%%%----------------------------------------------------------------- -%%% Add a disk_log handler to the logger. -%%% This starts a dedicated handler process which should always -%%% exist if the handler is registered with logger (and should not -%%% exist if the handler is not registered). -%%% -%%% Config is the logger:handler_config() map. Handler specific parameters -%%% should be provided with a sub map associated with a key named -%%% 'config', e.g: -%%% -%%% Config = #{config => #{sync_mode_qlen => 50} -%%% -%%% The 'config' sub map will also contain parameters for configuring -%%% the disk_log: -%%% -%%% Config = #{config => #{file => file:filename(), -%%% max_no_bytes => integer(), -%%% max_no_files => integer(), -%%% type => wrap | halt}}. -%%% -%%% If type == halt, then max_no_files is ignored. -%%% -%%% The disk_log handler process is linked to logger_sup, which is -%%% part of the kernel application's supervision tree. -start(Name, Config, HandlerState) -> - LoggerDLH = - #{id => Name, - start => {?MODULE, start_link, [Name,Config,HandlerState]}, - restart => temporary, - shutdown => 2000, - type => worker, - modules => [?MODULE]}, - case supervisor:start_child(logger_sup, LoggerDLH) of - {ok,Pid,Config1} -> - ok = logger_handler_watcher:register_handler(Name,Pid), - {ok,Config1}; - Error -> - Error - end. - -%%%----------------------------------------------------------------- -%%% Stop and remove the handler. -stop(Name) -> - case whereis(?name_to_reg_name(?MODULE,Name)) of - undefined -> - ok; - Pid -> - %% We don't want to do supervisor:terminate_child here - %% since we need to distinguish this explicit stop from a - %% system termination in order to avoid circular attempts - %% at removing the handler (implying deadlocks and - %% timeouts). - %% And we don't need to do supervisor:delete_child, since - %% the restart type is temporary, which means that the - %% child specification is automatically removed from the - %% supervisor when the process dies. - _ = gen_server:call(Pid, stop), - ok - end. - -%%%----------------------------------------------------------------- -%%% Logging and overload control. --define(update_dl_sync(C, Interval), - if C == 0 -> Interval; - true -> C-1 end). - -%% check for overload between every event (and set Mode to async, -%% sync or drop accordingly), but never flush the whole mailbox -%% before LogWindowSize events have been handled -do_log(Bin, CallOrCast, State = #{id:=Name, mode := Mode0}) -> - T1 = ?timestamp(), - - %% check if the handler is getting overloaded, or if it's - %% recovering from overload (the check must be done for each - %% event to react quickly to large bursts of events and - %% to ensure that the handler can never end up in drop mode - %% with an empty mailbox, which would stop operation) - {Mode1,QLen,Mem,State1} = logger_h_common:check_load(State), - - if (Mode1 == drop) andalso (Mode0 =/= drop) -> - log_handler_info(Name, "Handler ~p switched to drop mode", - [Name], State); - (Mode0 == drop) andalso ((Mode1 == async) orelse (Mode1 == sync)) -> - log_handler_info(Name, "Handler ~p switched to ~w mode", - [Name,Mode1], State); - true -> - ok - end, - - %% kill the handler if it can't keep up with the load - logger_h_common:kill_if_choked(Name, QLen, Mem, ?MODULE, State), - - if Mode1 == flush -> - flush(Name, QLen, T1, State1); - true -> - write(Name, Mode1, T1, Bin, CallOrCast, State1) - end. - -%% this function is called by do_log/3 after an overload check -%% has been performed, where QLen > FlushQLen -flush(Name, _QLen0, T1, State=#{last_log_ts := _T0, mode_tab := ModeTab}) -> - %% flush messages in the mailbox (a limited number in - %% order to not cause long delays) - NewFlushed = logger_h_common:flush_log_events(?FLUSH_MAX_N), - - %% write info in log about flushed messages - log_handler_info(Name, "Handler ~p flushed ~w log events", - [Name,NewFlushed], State), - - %% because of the receive loop when flushing messages, the - %% handler will be scheduled out often and the mailbox could - %% grow very large, so we'd better check the queue again here - {_,_QLen1} = process_info(self(), message_queue_len), - ?observe(Name,{max_qlen,_QLen1}), - - %% Add 1 for the current log event - ?observe(Name,{flushed,NewFlushed+1}), - - State1 = ?update_max_time(?diff_time(T1,_T0),State), - {dropped,?update_other(flushed,FLUSHED,NewFlushed, - State1#{mode => ?set_mode(ModeTab,async), - last_qlen => 0, - last_log_ts => T1})}. - -%% this function is called to write to disk_log -write(Name, Mode, T1, Bin, _CallOrCast, - State = #{mode_tab := ModeTab, - dl_sync := DLSync, - dl_sync_int := DLSyncInt, - last_qlen := LastQLen, - last_log_ts := T0}) -> - %% check if we need to limit the number of writes - %% during a burst of log events - {DoWrite,BurstWinT,BurstMsgCount} = logger_h_common:limit_burst(State), - - %% only send a synhrounous event to the disk_log process - %% every DLSyncInt time, to give the handler time between - %% writes so it can keep up with incoming messages - {Status,LastQLen1,State1} = - if DoWrite, DLSync == 0 -> - ?observe(Name,{_CallOrCast,1}), - NewState = disk_log_write(Name, Bin, State), - {ok, element(2,process_info(self(),message_queue_len)), - NewState}; - DoWrite -> - ?observe(Name,{_CallOrCast,1}), - NewState = disk_log_write(Name, Bin, State), - {ok, LastQLen, NewState}; - not DoWrite -> - ?observe(Name,{flushed,1}), - {dropped, LastQLen, State} - end, - - %% Check if the time since the previous log event is long enough - - %% and the queue length small enough - to assume the mailbox has - %% been emptied, and if so, do filesync operation and reset mode to - %% async. Note that this is the best we can do to detect an idle - %% handler without setting a timer after each log call/cast. If the - %% time between two consecutive log events is fast and no new - %% event comes in after the last one, idle state won't be detected! - Time = ?diff_time(T1,T0), - {Mode1,BurstMsgCount1,State2} = - if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso - (Time > ?IDLE_DETECT_TIME_USEC) -> - {?change_mode(ModeTab,Mode,async), 0, disk_log_sync(Name,State1)}; - true -> - {Mode, BurstMsgCount,State1} - end, - - State3 = - ?update_calls_or_casts(_CallOrCast,1,State2), - State4 = - ?update_max_time(Time, - State3#{mode => Mode1, - last_qlen := LastQLen1, - last_log_ts => T1, - burst_win_ts => BurstWinT, - burst_msg_count => BurstMsgCount1, - dl_sync => ?update_dl_sync(DLSync,DLSyncInt)}), - {Status,State4}. - - -log_handler_info(Name, Format, Args, State) -> - Config = - case logger:get_handler_config(Name) of - {ok,Conf} -> Conf; - _ -> #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}} - end, - Meta = #{time=>erlang:system_time(microsecond)}, - Bin = logger_h_common:log_to_binary(#{level => notice, - msg => {Format,Args}, - meta => Meta}, Config), - _ = disk_log_write(Name, Bin, State), - ok. - - open_disk_log(Name, File, Type, MaxNoBytes, MaxNoFiles) -> case filelib:ensure_dir(File) of ok -> @@ -681,43 +246,26 @@ close_disk_log(Name, _) -> _ = disk_log:lclose(Name), ok. -disk_log_write(Name, Bin, State) -> - case ?disk_log_blog(Name, Bin) of - ok -> - State#{prev_log_result => ok, last_op => write}; - LogError -> - _ = case maps:get(prev_log_result, State) of - LogError -> - %% don't report same error twice - ok; - _ -> - LogOpts = maps:get(log_opts, State), - logger_h_common:error_notify({Name,log, - LogOpts, - LogError}) - end, - State#{prev_log_result => LogError} - end. - -disk_log_sync(Name, State) -> - case ?disk_log_sync(Name) of - ok -> - State#{prev_sync_result => ok, last_op => sync}; - SyncError -> - _ = case maps:get(prev_sync_result, State) of - SyncError -> - %% don't report same error twice - ok; - _ -> - LogOpts = maps:get(log_opts, State), - logger_h_common:error_notify({Name,filesync, - LogOpts, - SyncError}) - end, - State#{prev_sync_result => SyncError} - end. +disk_log_write(Name, sync, Bin) -> + disk_log:blog(Name, Bin); +disk_log_write(Name, async, Bin) -> + disk_log:balog(Name, Bin). + +%%%----------------------------------------------------------------- +%%% Print error messages, but don't repeat the same message +maybe_notify_error(Name, Op, Result, Key, #{log_opts:=LogOpts}=State) -> + {Result,error_notify_new({Name, Op, LogOpts, Result}, Result, Key, State)}. -error_notify_new(Info,Info, _Term) -> +maybe_notify_status(Name, Log, Info, Key, State) -> + error_notify_new({disk_log, Name, Log, Info}, Info, Key, State). + +error_notify_new(Term, What, Key, State) -> + error_notify_new(What, maps:get(Key,State), Term), + State#{Key => What}. + +error_notify_new(ok,_Prev,_Term) -> + ok; +error_notify_new(Same,Same,_Term) -> ok; -error_notify_new(_Info0,_Info1, Term) -> +error_notify_new(_New,_Prev,Term) -> logger_h_common:error_notify(Term). diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl index 38ac7d8ffc..74a2d158fc 100644 --- a/lib/kernel/src/logger_h_common.erl +++ b/lib/kernel/src/logger_h_common.erl @@ -18,26 +18,469 @@ %% %CopyrightEnd% %% -module(logger_h_common). +-behaviour(gen_server). -include("logger_h_common.hrl"). -include("logger_internal.hrl"). --export([log_to_binary/2, - check_common_config/1, - call_cast_or_drop/4, - check_load/1, - limit_burst/1, - kill_if_choked/5, - flush_log_events/0, - flush_log_events/1, - handler_exit/2, - set_restart_flag/2, - unset_restart_flag/2, - cancel_timer/1, - stop_or_restart/3, - overload_levels_ok/1, - error_notify/1, - info_notify/1]). +%% API +-export([start_link/1, info/2, filesync/2, reset/2]). + +%% gen_server and proc_lib callbacks +-export([init/1, handle_call/3, handle_cast/2, handle_info/2, + terminate/2, code_change/3]). + +%% logger callbacks +-export([log/2, adding_handler/1, removing_handler/1, changing_config/3, + filter_config/1]). + +%% Library functions for handlers +-export([error_notify/1]). + +%%%----------------------------------------------------------------- +-define(CONFIG_KEYS,[sync_mode_qlen, + drop_mode_qlen, + flush_qlen, + burst_limit_enable, + burst_limit_max_count, + burst_limit_window_time, + overload_kill_enable, + overload_kill_qlen, + overload_kill_mem_size, + overload_kill_restart_after, + filesync_repeat_interval]). +-define(READ_ONLY_KEYS,[handler_pid,mode_tab]). + +%%%----------------------------------------------------------------- +%%% API + +%% This function is called by the logger_sup supervisor +start_link(Args) -> + proc_lib:start_link(?MODULE,init,[Args]). + +filesync(Module, Name) -> + call(Module, Name, filesync). + +info(Module, Name) -> + call(Module, Name, info). + +reset(Module, Name) -> + call(Module, Name, reset). + +%%%----------------------------------------------------------------- +%%% Handler being added +adding_handler(#{id:=Name,module:=Module}=Config) -> + HConfig0 = maps:get(config, Config, #{}), + HandlerConfig0 = maps:without(?CONFIG_KEYS,HConfig0), + case Module:check_config(Name,set,undefined,HandlerConfig0) of + {ok,HandlerConfig} -> + ModifiedCommon = maps:with(?CONFIG_KEYS,HandlerConfig), + CommonConfig0 = maps:with(?CONFIG_KEYS,HConfig0), + CommonConfig = maps:merge( + maps:merge(get_default_config(), CommonConfig0), + ModifiedCommon), + case check_config(CommonConfig) of + ok -> + HConfig = maps:merge(CommonConfig,HandlerConfig), + start(Config#{config => HConfig}); + {error,Faulty} -> + {error,{invalid_config,Module,Faulty}} + end; + Error -> + Error + end. + +%%%----------------------------------------------------------------- +%%% Handler being removed +removing_handler(#{id:=Name, module:=Module}) -> + case whereis(?name_to_reg_name(Module,Name)) of + undefined -> + ok; + Pid -> + %% We don't want to do supervisor:terminate_child here + %% since we need to distinguish this explicit stop from a + %% system termination in order to avoid circular attempts + %% at removing the handler (implying deadlocks and + %% timeouts). + %% And we don't need to do supervisor:delete_child, since + %% the restart type is temporary, which means that the + %% child specification is automatically removed from the + %% supervisor when the process dies. + _ = gen_server:call(Pid, stop), + ok + end. + +%%%----------------------------------------------------------------- +%%% Updating handler config +changing_config(SetOrUpdate, + #{id:=Name,config:=OldHConfig,module:=Module}, + NewConfig0) -> + NewHConfig0 = maps:get(config, NewConfig0, #{}), + OldHandlerConfig = maps:without(?CONFIG_KEYS++?READ_ONLY_KEYS,OldHConfig), + NewHandlerConfig0 = maps:without(?CONFIG_KEYS++?READ_ONLY_KEYS,NewHConfig0), + case Module:check_config(Name, SetOrUpdate, + OldHandlerConfig,NewHandlerConfig0) of + {ok, NewHandlerConfig} -> + ModifiedCommon = maps:with(?CONFIG_KEYS,NewHandlerConfig), + NewCommonConfig0 = maps:with(?CONFIG_KEYS,NewHConfig0), + CommonDefault = + case SetOrUpdate of + set -> + get_default_config(); + update -> + maps:with(?CONFIG_KEYS,OldHConfig) + end, + NewCommonConfig = maps:merge( + maps:merge(CommonDefault,NewCommonConfig0), + ModifiedCommon), + case check_config(NewCommonConfig) of + ok -> + ReadOnly = maps:with(?READ_ONLY_KEYS,OldHConfig), + NewHConfig = maps:merge( + maps:merge(NewCommonConfig,NewHandlerConfig), + ReadOnly), + NewConfig = NewConfig0#{config=>NewHConfig}, + HPid = maps:get(handler_pid,OldHConfig), + case call(HPid, {change_config,NewConfig}) of + ok -> {ok,NewConfig}; + Error -> Error + end; + {error,Faulty} -> + {error,{invalid_config,Module,Faulty}} + end; + Error -> + Error + end. + +%%%----------------------------------------------------------------- +%%% Log a string or report +-spec log(LogEvent, Config) -> ok when + LogEvent :: logger:log_event(), + Config :: logger:handler_config(). + +log(LogEvent, Config = #{id := Name, + config := #{handler_pid := HPid, + mode_tab := ModeTab}}) -> + %% if the handler has crashed, we must drop this event + %% and hope the handler restarts so we can try again + true = is_process_alive(HPid), + Bin = log_to_binary(LogEvent, Config), + call_cast_or_drop(Name, HPid, ModeTab, Bin). + +%%%----------------------------------------------------------------- +%%% Remove internal fields from configuration +filter_config(#{config:=HConfig}=Config) -> + Config#{config=>maps:without(?READ_ONLY_KEYS,HConfig)}. + +%%%----------------------------------------------------------------- +%%% Start the handler process +%%% +%%% The process must always exist if the handler is registered with +%%% logger (and must not exist if the handler is not registered). +%%% +%%% The handler process is linked to logger_sup, which is part of the +%%% kernel application's supervision tree. +start(#{id := Name} = Config0) -> + ChildSpec = + #{id => Name, + start => {?MODULE, start_link, [Config0]}, + restart => temporary, + shutdown => 2000, + type => worker, + modules => [?MODULE]}, + case supervisor:start_child(logger_sup, ChildSpec) of + {ok,Pid,Config} -> + ok = logger_handler_watcher:register_handler(Name,Pid), + {ok,Config}; + Error -> + Error + end. + +%%%=================================================================== +%%% gen_server callbacks +%%%=================================================================== + +init(#{id := Name, module := Module, + formatter := Formatter, config := HConfig0} = Config0) -> + RegName = ?name_to_reg_name(Module,Name), + register(RegName, self()), + process_flag(trap_exit, true), + process_flag(message_queue_data, off_heap), + + ?init_test_hooks(), + ?start_observation(Name), + + case Module:init(Name, HConfig0) of + {ok,HState} -> + try ets:new(Name, [public]) of + ModeTab -> + ?set_mode(ModeTab, async), + T0 = ?timestamp(), + HConfig = HConfig0#{handler_pid => self(), + mode_tab => ModeTab}, + Config = Config0#{config => HConfig}, + proc_lib:init_ack({ok,self(),Config}), + %% Storing common config in state to avoid copying + %% (sending) the config data for each log message + CommonConfig = maps:with(?CONFIG_KEYS,HConfig), + State = + ?merge_with_stats( + CommonConfig#{id => Name, + module => Module, + mode_tab => ModeTab, + mode => async, + ctrl_sync_count => + ?CONTROLLER_SYNC_INTERVAL, + last_qlen => 0, + last_log_ts => T0, + last_op => sync, + burst_win_ts => T0, + burst_msg_count => 0, + formatter => Formatter, + handler_state => HState}), + State1 = set_repeated_filesync(State), + unset_restart_flag(State1), + gen_server:enter_loop(?MODULE, [], State1) + catch + _:Error -> + unregister(RegName), + error_notify({init_handler,Name,Error}), + proc_lib:init_ack(Error) + end; + Error -> + unregister(RegName), + error_notify({init_handler,Name,Error}), + proc_lib:init_ack(Error) + end. + +%% This is the synchronous log event. +handle_call({log, Bin}, _From, State) -> + {Result,State1} = do_log(Bin, call, State), + %% Result == ok | dropped + {reply,Result, State1}; + +handle_call(filesync, _From, State = #{id := Name, + module := Module, + handler_state := HandlerState}) -> + {Result,HandlerState1} = Module:filesync(Name,sync,HandlerState), + {reply, Result, State#{handler_state=>HandlerState1, last_op=>sync}}; + +handle_call({change_config, #{formatter:=Formatter, config:=NewHConfig}}, _From, + State = #{filesync_repeat_interval := FSyncInt0}) -> + %% In the future, if handler_state must be updated due to config + %% change, then we need to add a callback to Module here. + CommonConfig = maps:with(?CONFIG_KEYS,NewHConfig), + State1 = maps:merge(State, CommonConfig), + State2 = + case maps:get(filesync_repeat_interval, NewHConfig) of + FSyncInt0 -> + State1; + _FSyncInt1 -> + set_repeated_filesync(cancel_repeated_filesync(State1)) + end, + {reply, ok, State2#{formatter:=Formatter}}; + +handle_call(info, _From, State) -> + {reply, State, State}; + +handle_call(reset, _From, + #{id:=Name,module:=Module,handler_state:=HandlerState}=State) -> + State1 = ?merge_with_stats(State), + {reply, ok, State1#{last_qlen => 0, + last_log_ts => ?timestamp(), + handler_state => Module:reset_state(Name,HandlerState)}}; + +handle_call(stop, _From, State) -> + {stop, {shutdown,stopped}, ok, State}. + +%% This is the asynchronous log event. +handle_cast({log, Bin}, State) -> + {_,State1} = do_log(Bin, cast, State), + {noreply, State1}; + +%% If FILESYNC_REPEAT_INTERVAL is set to a millisec value, this +%% clause gets called repeatedly by the handler. In order to +%% guarantee that a filesync *always* happens after the last log +%% event, the repeat operation must be active! +handle_cast(repeated_filesync,State = #{filesync_repeat_interval := no_repeat}) -> + %% This clause handles a race condition which may occur when + %% config changes filesync_repeat_interval from an integer value + %% to no_repeat. + {noreply,State}; +handle_cast(repeated_filesync, + State = #{id := Name, + module := Module, + handler_state := HandlerState, + last_op := LastOp}) -> + State1 = + if LastOp == sync -> + State; + true -> + {_,HS} = Module:filesync(Name, async, HandlerState), + State#{handler_state => HS, last_op => sync} + end, + {noreply,set_repeated_filesync(State1)}. + +handle_info(Info, #{id := Name, module := Module, + handler_state := HandlerState} = State) -> + {noreply,State#{handler_state => Module:handle_info(Name,Info,HandlerState)}}. + +terminate(Reason, State = #{id := Name, + module := Module, + handler_state := HandlerState}) -> + _ = cancel_repeated_filesync(State), + _ = Module:terminate(Name, Reason, HandlerState), + ok = stop_or_restart(Name, Reason, State), + unregister(?name_to_reg_name(Module, Name)), + ok. + +code_change(_OldVsn, State, _Extra) -> + {ok, State}. + + +%%%----------------------------------------------------------------- +%%% Internal functions +call(Module, Name, Op) when is_atom(Name) -> + call(?name_to_reg_name(Module,Name), Op); +call(_, Name, Op) -> + {error,{badarg,{Op,[Name]}}}. + +call(Server, Msg) -> + try + gen_server:call(Server, Msg, ?DEFAULT_CALL_TIMEOUT) + catch + _:{timeout,_} -> {error,handler_busy} + end. + +%% check for overload between every event (and set Mode to async, +%% sync or drop accordingly), but never flush the whole mailbox +%% before LogWindowSize events have been handled +do_log(Bin, CallOrCast, State = #{id:=Name, mode:=Mode0}) -> + T1 = ?timestamp(), + + %% check if the handler is getting overloaded, or if it's + %% recovering from overload (the check must be done for each + %% event to react quickly to large bursts of events and + %% to ensure that the handler can never end up in drop mode + %% with an empty mailbox, which would stop operation) + {Mode1,QLen,Mem,State1} = check_load(State), + + if (Mode1 == drop) andalso (Mode0 =/= drop) -> + log_handler_info(Name, "Handler ~p switched to drop mode", + [Name], State); + (Mode0 == drop) andalso ((Mode1 == async) orelse (Mode1 == sync)) -> + log_handler_info(Name, "Handler ~p switched to ~w mode", + [Name,Mode1], State); + true -> + ok + end, + + %% kill the handler if it can't keep up with the load + kill_if_choked(Name, QLen, Mem, State), + + if Mode1 == flush -> + flush(Name, QLen, T1, State1); + true -> + write(Name, Mode1, T1, Bin, CallOrCast, State1) + end. + +%% this clause is called by do_log/3 after an overload check +%% has been performed, where QLen > FlushQLen +flush(Name, _QLen0, T1, State=#{last_log_ts := _T0, mode_tab := ModeTab}) -> + %% flush messages in the mailbox (a limited number in + %% order to not cause long delays) + NewFlushed = flush_log_events(?FLUSH_MAX_N), + + %% write info in log about flushed messages + log_handler_info(Name, "Handler ~p flushed ~w log events", + [Name,NewFlushed], State), + + %% because of the receive loop when flushing messages, the + %% handler will be scheduled out often and the mailbox could + %% grow very large, so we'd better check the queue again here + {_,_QLen1} = process_info(self(), message_queue_len), + ?observe(Name,{max_qlen,_QLen1}), + + %% Add 1 for the current log event + ?observe(Name,{flushed,NewFlushed+1}), + + State1 = ?update_max_time(?diff_time(T1,_T0),State), + State2 = ?update_max_qlen(_QLen1,State1), + {dropped,?update_other(flushed,FLUSHED,NewFlushed, + State2#{mode => ?set_mode(ModeTab,async), + last_qlen => 0, + last_log_ts => T1})}. + +%% this clause is called to write to file +write(Name, Mode, T1, Bin, _CallOrCast, + State = #{module := Module, + handler_state := HandlerState, + mode_tab := ModeTab, + ctrl_sync_count := CtrlSync, + last_qlen := LastQLen, + last_log_ts := T0}) -> + %% check if we need to limit the number of writes + %% during a burst of log events + {DoWrite,State1} = limit_burst(State), + + %% only log synhrounously every ?CONTROLLER_SYNC_INTERVAL time, to + %% give the handler time between writes so it can keep up with + %% incoming messages + {Result,LastQLen1,HandlerState1} = + if DoWrite, CtrlSync == 0 -> + ?observe(Name,{_CallOrCast,1}), + {_,HS1} = Module:write(Name, sync, Bin, HandlerState), + {ok,element(2, process_info(self(), message_queue_len)),HS1}; + DoWrite -> + ?observe(Name,{_CallOrCast,1}), + {_,HS1} = Module:write(Name, async, Bin, HandlerState), + {ok,LastQLen,HS1}; + not DoWrite -> + ?observe(Name,{flushed,1}), + {dropped,LastQLen,HandlerState} + end, + + %% Check if the time since the previous log event is long enough - + %% and the queue length small enough - to assume the mailbox has + %% been emptied, and if so, do filesync operation and reset mode to + %% async. Note that this is the best we can do to detect an idle + %% handler without setting a timer after each log call/cast. If the + %% time between two consecutive log events is fast and no new + %% event comes in after the last one, idle state won't be detected! + Time = ?diff_time(T1,T0), + State2 = + if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso + (Time > ?IDLE_DETECT_TIME_USEC) -> + {_,HS2} = Module:filesync(Name,async,HandlerState), + State1#{mode => ?change_mode(ModeTab, Mode, async), + burst_msg_count => 0, + handler_state => HS2}; + true -> + State1#{mode => Mode, handler_state => HandlerState1} + end, + State3 = ?update_calls_or_casts(_CallOrCast,1,State2), + State4 = ?update_max_qlen(LastQLen1,State3), + State5 = + ?update_max_time(Time, + State4#{last_qlen := LastQLen1, + last_log_ts => T1, + last_op => write, + ctrl_sync_count => + if CtrlSync==0 -> ?CONTROLLER_SYNC_INTERVAL; + true -> CtrlSync-1 + end}), + {Result,State5}. + +log_handler_info(Name, Format, Args, #{module:=Module, + formatter:=Formatter, + handler_state:=HandlerState}) -> + Config = #{formatter=>Formatter}, + Meta = #{time=>erlang:system_time(microsecond)}, + Bin = log_to_binary(#{level => notice, + msg => {Format,Args}, + meta => Meta}, Config), + _ = Module:write(Name, async, Bin, HandlerState), + ok. %%%----------------------------------------------------------------- %%% Convert log data on any form to binary @@ -94,46 +537,65 @@ string_to_binary(String) -> throw(Error) end. - %%%----------------------------------------------------------------- %%% Check that the configuration term is valid -check_common_config({mode_tab,_Tid}) -> - valid; -check_common_config({handler_pid,Pid}) when is_pid(Pid) -> - valid; - -check_common_config({sync_mode_qlen,N}) when is_integer(N) -> - valid; -check_common_config({drop_mode_qlen,N}) when is_integer(N) -> - valid; -check_common_config({flush_qlen,N}) when is_integer(N) -> - valid; - -check_common_config({burst_limit_enable,Bool}) when Bool == true; - Bool == false -> - valid; -check_common_config({burst_limit_max_count,N}) when is_integer(N) -> - valid; -check_common_config({burst_limit_window_time,N}) when is_integer(N) -> - valid; - -check_common_config({overload_kill_enable,Bool}) when Bool == true; - Bool == false -> - valid; -check_common_config({overload_kill_qlen,N}) when is_integer(N) -> - valid; -check_common_config({overload_kill_mem_size,N}) when is_integer(N) -> - valid; -check_common_config({overload_kill_restart_after,NorA}) when is_integer(NorA); - NorA == infinity -> - valid; - -check_common_config({filesync_repeat_interval,NorA}) when is_integer(NorA); - NorA == no_repeat -> - valid; -check_common_config(_) -> - invalid. +check_config(Config) when is_map(Config) -> + case check_common_config(maps:to_list(Config)) of + ok -> + case overload_levels_ok(Config) of + true -> + ok; + false -> + Faulty = maps:with([sync_mode_qlen, + drop_mode_qlen, + flush_qlen],Config), + {error,{invalid_levels,Faulty}} + end; + Error -> + Error + end. + +check_common_config([{sync_mode_qlen,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{drop_mode_qlen,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{flush_qlen,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{burst_limit_enable,Bool}|Config]) when is_boolean(Bool) -> + check_common_config(Config); +check_common_config([{burst_limit_max_count,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{burst_limit_window_time,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{overload_kill_enable,Bool}|Config]) when is_boolean(Bool) -> + check_common_config(Config); +check_common_config([{overload_kill_qlen,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{overload_kill_mem_size,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{overload_kill_restart_after,NorA}|Config]) + when is_integer(NorA); NorA == infinity -> + check_common_config(Config); +check_common_config([{filesync_repeat_interval,NorA}|Config]) + when is_integer(NorA); NorA == no_repeat -> + check_common_config(Config); +check_common_config([{Key,Value}|_]) -> + {error,#{Key=>Value}}; +check_common_config([]) -> + ok. +get_default_config() -> + #{sync_mode_qlen => ?SYNC_MODE_QLEN, + drop_mode_qlen => ?DROP_MODE_QLEN, + flush_qlen => ?FLUSH_QLEN, + burst_limit_enable => ?BURST_LIMIT_ENABLE, + burst_limit_max_count => ?BURST_LIMIT_MAX_COUNT, + burst_limit_window_time => ?BURST_LIMIT_WINDOW_TIME, + overload_kill_enable => ?OVERLOAD_KILL_ENABLE, + overload_kill_qlen => ?OVERLOAD_KILL_QLEN, + overload_kill_mem_size => ?OVERLOAD_KILL_MEM_SIZE, + overload_kill_restart_after => ?OVERLOAD_KILL_RESTART_AFTER, + filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}. %%%----------------------------------------------------------------- %%% Overload Protection @@ -146,15 +608,13 @@ call_cast_or_drop(_Name, HandlerPid, ModeTab, Bin) -> async -> gen_server:cast(HandlerPid, {log,Bin}); sync -> - try gen_server:call(HandlerPid, {log,Bin}, ?DEFAULT_CALL_TIMEOUT) of - %% if return value from call == dropped, the - %% message has been flushed by handler and should - %% therefore not be counted as dropped in stats - ok -> ok; - dropped -> ok - catch - _:{timeout,_} -> - ?observe(_Name,{dropped,1}) + case call(HandlerPid, {log,Bin}) of + ok -> + ok; + _Other -> + %% dropped or {error,handler_busy} + ?observe(_Name,{dropped,1}), + ok end; drop -> ?observe(_Name,{dropped,1}) @@ -165,10 +625,8 @@ call_cast_or_drop(_Name, HandlerPid, ModeTab, Bin) -> end, ok. -handler_exit(_Name, Reason) -> - exit(Reason). - -set_restart_flag(Name, Module) -> +set_restart_flag(#{id := Name, module := Module} = State) -> + log_handler_info(Name, "Handler ~p overloaded and stopping", [Name], State), Flag = list_to_atom(lists:concat([Module,"_",Name,"_restarting"])), spawn(fun() -> register(Flag, self()), @@ -176,14 +634,14 @@ set_restart_flag(Name, Module) -> end), ok. -unset_restart_flag(Name, Module) -> +unset_restart_flag(#{id := Name, module := Module} = State) -> Flag = list_to_atom(lists:concat([Module,"_",Name,"_restarting"])), case whereis(Flag) of undefined -> - false; + ok; Pid -> exit(Pid, kill), - true + log_handler_info(Name, "Handler ~p restarted", [Name], State) end. check_load(State = #{id:=_Name, mode_tab := ModeTab, mode := Mode, @@ -221,46 +679,41 @@ check_load(State = #{id:=_Name, mode_tab := ModeTab, mode := Mode, ?update_other(flushes,FLUSHES,_NewFlushes, State1#{last_qlen => QLen})}. -limit_burst(#{burst_limit_enable := false}) -> - {true,0,0}; +limit_burst(#{burst_limit_enable := false}=State) -> + {true,State}; limit_burst(#{burst_win_ts := BurstWinT0, burst_msg_count := BurstMsgCount, burst_limit_window_time := BurstLimitWinTime, - burst_limit_max_count := BurstLimitMaxCnt}) -> + burst_limit_max_count := BurstLimitMaxCnt} = State) -> if (BurstMsgCount >= BurstLimitMaxCnt) -> %% the limit for allowed messages has been reached BurstWinT1 = ?timestamp(), case ?diff_time(BurstWinT1,BurstWinT0) of BurstCheckTime when BurstCheckTime < (BurstLimitWinTime*1000) -> %% we're still within the burst time frame - {false,BurstWinT0,BurstMsgCount}; + {false,?update_other(burst_drops,BURSTS,1,State)}; _BurstCheckTime -> %% burst time frame passed, reset counters - {true,BurstWinT1,0} + {true,State#{burst_win_ts => BurstWinT1, + burst_msg_count => 0}} end; true -> %% the limit for allowed messages not yet reached - {true,BurstWinT0,BurstMsgCount+1} + {true,State#{burst_win_ts => BurstWinT0, + burst_msg_count => BurstMsgCount+1}} end. -kill_if_choked(Name, QLen, Mem, HandlerMod, - State = #{overload_kill_enable := KillIfOL, - overload_kill_qlen := OLKillQLen, - overload_kill_mem_size := OLKillMem}) -> +kill_if_choked(Name, QLen, Mem, State = #{overload_kill_enable := KillIfOL, + overload_kill_qlen := OLKillQLen, + overload_kill_mem_size := OLKillMem}) -> if KillIfOL andalso ((QLen > OLKillQLen) orelse (Mem > OLKillMem)) -> - HandlerMod:log_handler_info(Name, - "Handler ~p overloaded and stopping", - [Name], State), - set_restart_flag(Name, HandlerMod), - handler_exit(Name, {shutdown,{overloaded,Name,QLen,Mem}}); + set_restart_flag(State), + exit({shutdown,{overloaded,Name,QLen,Mem}}); true -> ok end. -flush_log_events() -> - flush_log_events(-1). - flush_log_events(Limit) -> process_flag(priority, high), Flushed = flush_log_events(0, Limit), @@ -283,16 +736,29 @@ flush_log_events(N, Limit) -> 0 -> N end. -cancel_timer(TRef) when is_atom(TRef) -> ok; -cancel_timer(TRef) -> timer:cancel(TRef). +set_repeated_filesync(#{filesync_repeat_interval:=FSyncInt} = State) + when is_integer(FSyncInt) -> + {ok,TRef} = timer:apply_after(FSyncInt, gen_server, cast, + [self(),repeated_filesync]), + State#{rep_sync_tref=>TRef}; +set_repeated_filesync(State) -> + State. +cancel_repeated_filesync(State) -> + case maps:take(rep_sync_tref,State) of + {TRef,State1} -> + _ = timer:cancel(TRef), + State1; + error -> + State + end. stop_or_restart(Name, {shutdown,Reason={overloaded,_Name,_QLen,_Mem}}, #{overload_kill_restart_after := RestartAfter}) -> %% If we're terminating because of an overload situation (see - %% logger_h_common:kill_if_choked/4), we need to remove the handler - %% and set a restart timer. A separate process must perform this - %% in order to avoid deadlock. + %% kill_if_choked/4), we need to remove the handler and set a + %% restart timer. A separate process must perform this in order to + %% avoid deadlock. HandlerPid = self(), ConfigResult = logger:get_handler_config(Name), RemoveAndRestart = @@ -306,8 +772,11 @@ stop_or_restart(Name, {shutdown,Reason={overloaded,_Name,_QLen,_Mem}}, exit(HandlerPid, kill) end, case ConfigResult of - {ok,#{module:=HMod}=HConfig} when is_integer(RestartAfter) -> + {ok,#{module:=HMod}=HConfig0} when is_integer(RestartAfter) -> _ = logger:remove_handler(Name), + HConfig = try HMod:filter_config(HConfig0) + catch _:_ -> HConfig0 + end, _ = timer:apply_after(RestartAfter, logger, add_handler, [Name,HMod,HConfig]); {ok,_} -> @@ -331,6 +800,3 @@ overload_levels_ok(HandlerConfig) -> error_notify(Term) -> ?internal_log(error, Term). - -info_notify(Term) -> - ?internal_log(info, Term). diff --git a/lib/kernel/src/logger_h_common.hrl b/lib/kernel/src/logger_h_common.hrl index e0a7b6e3ca..261b0a6246 100644 --- a/lib/kernel/src/logger_h_common.hrl +++ b/lib/kernel/src/logger_h_common.hrl @@ -137,7 +137,7 @@ ets:insert(?TEST_HOOKS_TAB, {internal_log,{logger,internal_log}}), ets:insert(?TEST_HOOKS_TAB, {file_write,ok}), ets:insert(?TEST_HOOKS_TAB, {file_datasync,ok}), - ets:insert(?TEST_HOOKS_TAB, {disk_log_blog,ok}), + ets:insert(?TEST_HOOKS_TAB, {disk_log_write,ok}), ets:insert(?TEST_HOOKS_TAB, {disk_log_sync,ok})). -define(set_internal_log(MOD_FUNC), @@ -150,7 +150,7 @@ ets:insert(?TEST_HOOKS_TAB, {internal_log,{logger,internal_log}}), ets:insert(?TEST_HOOKS_TAB, {file_write,ok}), ets:insert(?TEST_HOOKS_TAB, {file_datasync,ok}), - ets:insert(?TEST_HOOKS_TAB, {disk_log_blog,ok}), + ets:insert(?TEST_HOOKS_TAB, {disk_log_write,ok}), ets:insert(?TEST_HOOKS_TAB, {disk_log_sync,ok})). -define(internal_log(TYPE, TERM), @@ -171,11 +171,11 @@ [{_,ERROR}] -> ERROR catch _:_ -> file:datasync(DEVICE) end). - -define(disk_log_blog(LOG, DATA), - try ets:lookup(?TEST_HOOKS_TAB, disk_log_blog) of - [{_,ok}] -> disk_log:blog(LOG, DATA); + -define(disk_log_write(LOG, MODE, DATA), + try ets:lookup(?TEST_HOOKS_TAB, disk_log_write) of + [{_,ok}] -> disk_log_write(LOG, MODE, DATA); [{_,ERROR}] -> ERROR - catch _:_ -> disk_log:blog(LOG, DATA) end). + catch _:_ -> disk_log_write(LOG, MODE, DATA) end). -define(disk_log_sync(LOG), try ets:lookup(?TEST_HOOKS_TAB, disk_log_sync) of @@ -194,7 +194,7 @@ -define(internal_log(TYPE, TERM), logger:internal_log(TYPE, TERM)). -define(file_write(DEVICE, DATA), file:write(DEVICE, DATA)). -define(file_datasync(DEVICE), file:datasync(DEVICE)). - -define(disk_log_blog(LOG, DATA), disk_log:blog(LOG, DATA)). + -define(disk_log_write(LOG, MODE, DATA), disk_log_write(LOG, MODE, DATA)). -define(disk_log_sync(LOG), disk_log:sync(LOG)). -define(DEFAULT_CALL_TIMEOUT, 10000). -endif. @@ -210,7 +210,7 @@ -ifdef(SAVE_STATS). -define(merge_with_stats(STATE), STATE#{flushes => 0, flushed => 0, drops => 0, - casts => 0, calls => 0, + burst_drops => 0, casts => 0, calls => 0, max_qlen => 0, max_time => 0}). -define(update_max_qlen(QLEN, STATE), diff --git a/lib/kernel/src/logger_server.erl b/lib/kernel/src/logger_server.erl index a1d40f1123..b7735dbcf7 100644 --- a/lib/kernel/src/logger_server.erl +++ b/lib/kernel/src/logger_server.erl @@ -27,9 +27,13 @@ add_filter/2, remove_filter/2, set_module_level/2, unset_module_level/0, unset_module_level/1, cache_module_level/1, - set_config/2, set_config/3, update_config/2, + set_config/2, set_config/3, + update_config/2, update_config/3, update_formatter_config/2]). +%% Helper +-export([diff_maps/2]). + %% gen_server callbacks -export([init/1, handle_call/3, handle_cast/2, handle_info/2, terminate/2]). @@ -105,12 +109,25 @@ cache_module_level(Module) -> gen_server:cast(?SERVER,{cache_module_level,Module}). set_config(Owner,Key,Value) -> - update_config(Owner,#{Key=>Value}). + case sanity_check(Owner,Key,Value) of + ok -> + call({change_config,set,Owner,Key,Value}); + Error -> + Error + end. set_config(Owner,Config) -> case sanity_check(Owner,Config) of ok -> - call({set_config,Owner,Config}); + call({change_config,set,Owner,Config}); + Error -> + Error + end. + +update_config(Owner,Key,Value) -> + case sanity_check(Owner,Key,Value) of + ok -> + call({change_config,update,Owner,Key,Value}); Error -> Error end. @@ -118,7 +135,7 @@ set_config(Owner,Config) -> update_config(Owner, Config) -> case sanity_check(Owner,Config) of ok -> - call({update_config,Owner,Config}); + call({change_config,update,Owner,Config}); Error -> Error end. @@ -204,46 +221,72 @@ handle_call({add_filter,Id,Filter}, _From,#state{tid=Tid}=State) -> handle_call({remove_filter,Id,FilterId}, _From, #state{tid=Tid}=State) -> Reply = do_remove_filter(Tid,Id,FilterId), {reply,Reply,State}; -handle_call({update_config,primary,NewConfig}, _From, #state{tid=Tid}=State) -> +handle_call({change_config,SetOrUpd,primary,Config0}, _From, + #state{tid=Tid}=State) -> + {ok,#{handlers:=Handlers}=OldConfig} = logger_config:get(Tid,primary), + Default = + case SetOrUpd of + set -> default_config(primary); + update -> OldConfig + end, + Config = maps:merge(Default,Config0), + Reply = logger_config:set(Tid,primary,Config#{handlers=>Handlers}), + {reply,Reply,State}; +handle_call({change_config,_SetOrUpd,primary,Key,Value}, _From, + #state{tid=Tid}=State) -> {ok,OldConfig} = logger_config:get(Tid,primary), - Config = maps:merge(OldConfig,NewConfig), - {reply,logger_config:set(Tid,primary,Config),State}; -handle_call({update_config,HandlerId,NewConfig}, From, #state{tid=Tid}=State) -> + Reply = logger_config:set(Tid,primary,OldConfig#{Key=>Value}), + {reply,Reply,State}; +handle_call({change_config,SetOrUpd,HandlerId,Config0}, From, + #state{tid=Tid}=State) -> case logger_config:get(Tid,HandlerId) of {ok,#{module:=Module}=OldConfig} -> - Config = maps:merge(OldConfig,NewConfig), - call_h_async( - fun() -> - call_h(Module,changing_config,[OldConfig,Config], - {ok,Config}) - end, - fun({ok,Config1}) -> - logger_config:set(Tid,HandlerId,Config1); - (Error) -> - Error - end,From,State); - Error -> - {reply,Error,State} + Default = + case SetOrUpd of + set -> default_config(HandlerId,Module); + update -> OldConfig + end, + Config = maps:merge(Default,Config0), + case check_config_change(OldConfig,Config) of + ok -> + call_h_async( + fun() -> + call_h(Module,changing_config, + [SetOrUpd,OldConfig,Config], + {ok,Config}) + end, + fun({ok,Config1}) -> + logger_config:set(Tid,HandlerId,Config1); + (Error) -> + Error + end,From,State); + Error -> + {reply,Error,State} + end; + _ -> + {reply,{error,{not_found,HandlerId}},State} end; -handle_call({set_config,primary,Config0}, _From, #state{tid=Tid}=State) -> - Config = maps:merge(default_config(primary),Config0), - {ok,#{handlers:=Handlers}} = logger_config:get(Tid,primary), - Reply = logger_config:set(Tid,primary,Config#{handlers=>Handlers}), - {reply,Reply,State}; -handle_call({set_config,HandlerId,Config0}, From, #state{tid=Tid}=State) -> +handle_call({change_config,SetOrUpd,HandlerId,Key,Value}, From, + #state{tid=Tid}=State) -> case logger_config:get(Tid,HandlerId) of {ok,#{module:=Module}=OldConfig} -> - Config = maps:merge(default_config(HandlerId,Module),Config0), - call_h_async( - fun() -> - call_h(Module,changing_config,[OldConfig,Config], - {ok,Config}) - end, - fun({ok,Config1}) -> - logger_config:set(Tid,HandlerId,Config1); - (Error) -> - Error - end,From,State); + Config = OldConfig#{Key=>Value}, + case check_config_change(OldConfig,Config) of + ok -> + call_h_async( + fun() -> + call_h(Module,changing_config, + [SetOrUpd,OldConfig,Config], + {ok,Config}) + end, + fun({ok,Config1}) -> + logger_config:set(Tid,HandlerId,Config1); + (Error) -> + Error + end,From,State); + Error -> + {reply,Error,State} + end; _ -> {reply,{error,{not_found,HandlerId}},State} end; @@ -320,7 +363,7 @@ call(Request) -> true when Action == add_handler; Action == remove_handler; Action == add_filter; Action == remove_filter; - Action == update_config; Action == set_config -> + Action == change_config -> {error,{attempting_syncronous_call_to_self,Request}}; _ -> gen_server:call(?SERVER,Request,?DEFAULT_LOGGER_CALL_TIMEOUT) @@ -458,6 +501,15 @@ check_formatter({Mod,Config}) -> check_formatter(Formatter) -> throw({invalid_formatter,Formatter}). +%% When changing configuration for a handler, the id and module fields +%% can not be changed. +check_config_change(#{id:=Id,module:=Module},#{id:=Id,module:=Module}) -> + ok; +check_config_change(OldConfig,NewConfig) -> + {Old,New} = logger_server:diff_maps(maps:with([id,module],OldConfig), + maps:with([id,module],NewConfig)), + {error,{illegal_config_change,Old,New}}. + call_h(Module, Function, Args, DefRet) -> %% Not calling code:ensure_loaded + erlang:function_exported here, %% since in some rare terminal cases, the code_server might not @@ -466,6 +518,11 @@ call_h(Module, Function, Args, DefRet) -> catch C:R:S -> case {C,R,S} of + {error,undef,[{Module,Function=changing_config,Args,_}|_]} + when length(Args)=:=3 -> + %% Backwards compatible call, if changing_config/3 + %% did not exist. + call_h(Module, Function, tl(Args), DefRet); {error,undef,[{Module,Function,Args,_}|_]} -> DefRet; _ -> @@ -525,3 +582,14 @@ call_h_reply(Unexpected,State) -> {process,?SERVER}, {message,Unexpected}]), {noreply,State}. + +%% Return two maps containing only the fields that differ. +diff_maps(M1,M2) -> + diffs(lists:sort(maps:to_list(M1)),lists:sort(maps:to_list(M2)),#{},#{}). + +diffs([H|T1],[H|T2],D1,D2) -> + diffs(T1,T2,D1,D2); +diffs([{K,V1}|T1],[{K,V2}|T2],D1,D2) -> + diffs(T1,T2,D1#{K=>V1},D2#{K=>V2}); +diffs([],[],D1,D2) -> + {D1,D2}. diff --git a/lib/kernel/src/logger_simple_h.erl b/lib/kernel/src/logger_simple_h.erl index 8b51dd8569..fe181722f3 100644 --- a/lib/kernel/src/logger_simple_h.erl +++ b/lib/kernel/src/logger_simple_h.erl @@ -50,7 +50,6 @@ removing_handler(#{id:=simple}) -> ok; Pid -> Ref = erlang:monitor(process,Pid), - unlink(Pid), Pid ! stop, receive {'DOWN',Ref,process,Pid,_} -> ok @@ -99,7 +98,11 @@ loop(Buffer) -> replay_buffer(Buffer); _ -> ok - end; + end, + %% Before stopping, we unlink the logger process to avoid + %% an unexpected EXIT message + unlink(whereis(logger)), + ok; {log,#{msg:=_,meta:=#{time:=_}}=Log} -> do_log(Log), loop(update_buffer(Buffer,Log)); diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index 66fa6b6ab6..63d1dbaba2 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -19,8 +19,6 @@ %% -module(logger_std_h). --behaviour(gen_server). - -include("logger.hrl"). -include("logger_internal.hrl"). -include("logger_h_common.hrl"). @@ -28,51 +26,28 @@ -include_lib("kernel/include/file.hrl"). %% API --export([start_link/3, info/1, filesync/1, reset/1]). +-export([info/1, filesync/1, reset/1]). -%% gen_server and proc_lib callbacks --export([init/1, handle_call/3, handle_cast/2, handle_info/2, - terminate/2, code_change/3]). +%% logger_h_common callbacks +-export([init/2, check_config/4, reset_state/2, + filesync/3, write/4, handle_info/3, terminate/3]). %% logger callbacks --export([log/2, adding_handler/1, removing_handler/1, changing_config/2]). - -%% handler internal --export([log_handler_info/4]). +-export([log/2, adding_handler/1, removing_handler/1, changing_config/3, + filter_config/1]). %%%=================================================================== %%% API %%%=================================================================== %%%----------------------------------------------------------------- -%%% Start a standard handler process and link to caller. -%%% This function is called by the kernel supervisor when this -%%% handler process gets added --spec start_link(Name, Config, HandlerState) -> {ok,Pid} | {error,Reason} when - Name :: atom(), - Config :: logger:handler_config(), - HandlerState :: map(), - Pid :: pid(), - Reason :: term(). - -start_link(Name, Config, HandlerState) -> - proc_lib:start_link(?MODULE,init,[[Name,Config,HandlerState]]). - -%%%----------------------------------------------------------------- %%% -spec filesync(Name) -> ok | {error,Reason} when Name :: atom(), Reason :: handler_busy | {badarg,term()}. -filesync(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - filesync, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; filesync(Name) -> - {error,{badarg,{filesync,[Name]}}}. + logger_h_common:filesync(?MODULE,Name). %%%----------------------------------------------------------------- %%% @@ -81,15 +56,8 @@ filesync(Name) -> Info :: term(), Reason :: handler_busy | {badarg,term()}. -info(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - info, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; info(Name) -> - {error,{badarg,{info,[Name]}}}. + logger_h_common:info(?MODULE,Name). %%%----------------------------------------------------------------- %%% @@ -97,116 +65,42 @@ info(Name) -> Name :: atom(), Reason :: handler_busy | {badarg,term()}. -reset(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - reset, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; reset(Name) -> - {error,{badarg,{reset,[Name]}}}. - + logger_h_common:reset(?MODULE,Name). %%%=================================================================== -%%% logger callbacks +%%% logger callbacks - just forward to logger_h_common %%%=================================================================== %%%----------------------------------------------------------------- %%% Handler being added -adding_handler(#{id:=Name}=Config) -> - case check_config(adding, Config) of - {ok, Config1} -> - %% create initial handler state by merging defaults with config - HConfig = maps:get(config, Config1, #{}), - HState = maps:merge(get_init_state(), HConfig), - case logger_h_common:overload_levels_ok(HState) of - true -> - start(Name, Config1, HState); - false -> - #{sync_mode_qlen := SMQL, - drop_mode_qlen := DMQL, - flush_qlen := FQL} = HState, - {error,{invalid_levels,{SMQL,DMQL,FQL}}} - end; - Error -> - Error - end. +-spec adding_handler(Config) -> {ok,Config} | {error,Reason} when + Config :: logger:handler_config(), + Reason :: term(). + +adding_handler(Config) -> + logger_h_common:adding_handler(Config). %%%----------------------------------------------------------------- %%% Updating handler config -changing_config(OldConfig=#{id:=Name, config:=OldHConfig}, - NewConfig=#{id:=Name}) -> - #{type:=Type, handler_pid:=HPid, mode_tab:=ModeTab} = OldHConfig, - NewHConfig = maps:get(config, NewConfig, #{}), - case maps:get(type, NewHConfig, Type) of - Type -> - NewHConfig1 = NewHConfig#{type=>Type, - handler_pid=>HPid, - mode_tab=>ModeTab}, - changing_config1(HPid, OldConfig, - NewConfig#{config=>NewHConfig1}); - _ -> - {error,{illegal_config_change,OldConfig,NewConfig}} - end; -changing_config(OldConfig, NewConfig) -> - {error,{illegal_config_change,OldConfig,NewConfig}}. - -changing_config1(HPid, OldConfig, NewConfig) -> - case check_config(changing, NewConfig) of - Result = {ok,NewConfig1} -> - try gen_server:call(HPid, {change_config,OldConfig,NewConfig1}, - ?DEFAULT_CALL_TIMEOUT) of - ok -> Result; - HError -> HError - catch - _:{timeout,_} -> {error,handler_busy} - end; - Error -> - Error - end. - -check_config(adding, Config) -> - %% Merge in defaults on handler level - HConfig0 = maps:get(config, Config, #{}), - HConfig = maps:merge(#{type => standard_io}, - HConfig0), - case check_h_config(maps:to_list(HConfig)) of - ok -> - {ok,Config#{config=>HConfig}}; - Error -> - Error - end; -check_config(changing, Config) -> - HConfig = maps:get(config, Config, #{}), - case check_h_config(maps:to_list(HConfig)) of - ok -> {ok,Config}; - Error -> Error - end. - -check_h_config([{type,Type} | Config]) when Type == standard_io; - Type == standard_error -> - check_h_config(Config); -check_h_config([{type,{file,File}} | Config]) when is_list(File) -> - check_h_config(Config); -check_h_config([{type,{file,File,Modes}} | Config]) when is_list(File), - is_list(Modes) -> - check_h_config(Config); -check_h_config([Other | Config]) -> - case logger_h_common:check_common_config(Other) of - valid -> - check_h_config(Config); - invalid -> - {error,{invalid_config,?MODULE,Other}} - end; -check_h_config([]) -> - ok. +-spec changing_config(SetOrUpdate, OldConfig, NewConfig) -> + {ok,Config} | {error,Reason} when + SetOrUpdate :: set | update, + OldConfig :: logger:handler_config(), + NewConfig :: logger:handler_config(), + Config :: logger:handler_config(), + Reason :: term(). +changing_config(SetOrUpdate, OldConfig, NewConfig) -> + logger_h_common:changing_config(SetOrUpdate, OldConfig, NewConfig). %%%----------------------------------------------------------------- %%% Handler being removed -removing_handler(#{id:=Name}) -> - stop(Name). +-spec removing_handler(Config) -> ok when + Config :: logger:handler_config(). + +removing_handler(Config) -> + logger_h_common:removing_handler(Config). %%%----------------------------------------------------------------- %%% Log a string or report @@ -214,192 +108,103 @@ removing_handler(#{id:=Name}) -> LogEvent :: logger:log_event(), Config :: logger:handler_config(). -log(LogEvent, Config = #{id := Name, - config := #{handler_pid := HPid, - mode_tab := ModeTab}}) -> - %% if the handler has crashed, we must drop this event - %% and hope the handler restarts so we can try again - true = is_process_alive(HPid), - Bin = logger_h_common:log_to_binary(LogEvent, Config), - logger_h_common:call_cast_or_drop(Name, HPid, ModeTab, Bin). +log(LogEvent, Config) -> + logger_h_common:log(LogEvent, Config). -%%%=================================================================== -%%% gen_server callbacks -%%%=================================================================== - -init([Name, Config = #{config := HConfig}, - State0 = #{type := Type, file_ctrl_sync_int := FileCtrlSyncInt}]) -> - RegName = ?name_to_reg_name(?MODULE,Name), - register(RegName, self()), - process_flag(trap_exit, true), - process_flag(message_queue_data, off_heap), +%%%----------------------------------------------------------------- +%%% Remove internal fields from configuration +-spec filter_config(Config) -> Config when + Config :: logger:handler_config(). - ?init_test_hooks(), - ?start_observation(Name), - - case do_init(Name, Type) of - {ok,InitState} -> - try ets:new(Name, [public]) of - ModeTab -> - ?set_mode(ModeTab, async), - State = maps:merge(State0, InitState), - T0 = ?timestamp(), - State1 = - ?merge_with_stats(State#{ - mode_tab => ModeTab, - mode => async, - file_ctrl_sync => FileCtrlSyncInt, - last_qlen => 0, - last_log_ts => T0, - last_op => sync, - burst_win_ts => T0, - burst_msg_count => 0}), - Config1 = - Config#{config => HConfig#{handler_pid => self(), - mode_tab => ModeTab}}, - proc_lib:init_ack({ok,self(),Config1}), - gen_server:cast(self(), repeated_filesync), - gen_server:enter_loop(?MODULE, [], State1) - catch - _:Error -> - unregister(RegName), - logger_h_common:error_notify({init_handler,Name,Error}), - proc_lib:init_ack(Error) - end; - Error -> - unregister(RegName), - logger_h_common:error_notify({init_handler,Name,Error}), - proc_lib:init_ack(Error) - end. +filter_config(Config) -> + logger_h_common:filter_config(Config). -do_init(Name, Type) -> +%%%=================================================================== +%%% logger_h_common callbacks +%%%=================================================================== +init(Name, #{type := Type}) -> case open_log_file(Name, Type) of {ok,FileCtrlPid} -> - case logger_h_common:unset_restart_flag(Name, ?MODULE) of - true -> - %% inform about restart - gen_server:cast(self(), {log_handler_info, - "Handler ~p restarted", - [Name]}); - false -> - %% initial start - ok - end, - {ok,#{id=>Name,type=>Type,file_ctrl_pid=>FileCtrlPid}}; + {ok,#{type=>Type,file_ctrl_pid=>FileCtrlPid}}; Error -> Error end. -%% This is the synchronous log event. -handle_call({log, Bin}, _From, State) -> - {Result,State1} = do_log(Bin, call, State), - %% Result == ok | dropped - {reply,Result, State1}; - -handle_call(filesync, _From, State = #{type := Type, - file_ctrl_pid := FileCtrlPid}) -> - if is_atom(Type) -> - {reply, ok, State}; - true -> - {reply, file_ctrl_filesync_sync(FileCtrlPid), State#{last_op=>sync}} - end; +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), + Default = + case SetOrUpdate of + set -> + %% Do not reset write-once fields to defaults + maps:merge(get_default_config(),WriteOnce); + update -> + OldHConfig + end, -handle_call({change_config,_OldConfig,NewConfig}, _From, - State = #{filesync_repeat_interval := FSyncInt0}) -> - HConfig = maps:get(config, NewConfig, #{}), - State1 = maps:merge(State, HConfig), - case logger_h_common:overload_levels_ok(State1) of - true -> - _ = - case maps:get(filesync_repeat_interval, HConfig, undefined) of - undefined -> - ok; - no_repeat -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, - State, - undefined)); - FSyncInt0 -> - ok; - _FSyncInt1 -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, - State, - undefined)), - gen_server:cast(self(), repeated_filesync) - end, - {reply, ok, State1}; - false -> - #{sync_mode_qlen := SMQL, - drop_mode_qlen := DMQL, - flush_qlen := FQL} = State1, - {reply, {error,{invalid_levels,{SMQL,DMQL,FQL}}}, State} - end; + NewHConfig = maps:merge(Default, NewHConfig0), -handle_call(info, _From, State) -> - {reply, State, State}; - -handle_call(reset, _From, State) -> - State1 = ?merge_with_stats(State), - {reply, ok, State1#{last_qlen => 0, - last_log_ts => ?timestamp()}}; - -handle_call(stop, _From, State) -> - {stop, {shutdown,stopped}, ok, State}. - -%% This is the asynchronous log event. -handle_cast({log, Bin}, State) -> - {_,State1} = do_log(Bin, cast, State), - {noreply, State1}; - -handle_cast({log_handler_info, Format, Args}, State = #{id:=Name}) -> - log_handler_info(Name, Format, Args, State), - {noreply, State}; - -%% If FILESYNC_REPEAT_INTERVAL is set to a millisec value, this -%% clause gets called repeatedly by the handler. In order to -%% guarantee that a filesync *always* happens after the last log -%% event, the repeat operation must be active! -handle_cast(repeated_filesync, - State = #{type := Type, - file_ctrl_pid := FileCtrlPid, - filesync_repeat_interval := FSyncInt, - last_op := LastOp}) -> - State1 = - if not is_atom(Type), is_integer(FSyncInt) -> - %% only do filesync if something has been - %% written since last time we checked - if LastOp == sync -> - ok; - true -> - file_ctrl_filesync_async(FileCtrlPid) - end, - {ok,TRef} = - timer:apply_after(FSyncInt, gen_server,cast, - [self(),repeated_filesync]), - State#{rep_sync_tref => TRef, last_op => sync}; - true -> - State - end, - {noreply,State1}. - -handle_info({'EXIT',Pid,Why}, State = #{id := Name, type := FileInfo}) -> - case maps:get(file_ctrl_pid, State, undefined) of - Pid -> - %% file error, terminate handler - logger_h_common:handler_exit(Name, - {error,{write_failed,FileInfo,Why}}); - _Other -> - %% ignore EXIT - ok - end, - {noreply, State}; + %% Fail if write-once fields are changed + case maps:with([type],NewHConfig) of + WriteOnce -> + check_config(NewHConfig); + Other -> + {error,{illegal_config_change,?MODULE,WriteOnce,Other}} + end. -handle_info(_Info, State) -> - {noreply, State}. +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}}; + ok -> + {ok,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 | _]) -> + {error,Other}; +check_h_config([]) -> + ok. -terminate(Reason, State = #{id:=Name, file_ctrl_pid:=FWPid, - type:=_FileInfo}) -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, State, - undefined)), +get_default_config() -> + #{type => standard_io}. + +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), + {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), + {Result,State}. + +reset_state(_Name, State) -> + State. + +handle_info(_Name, {'EXIT',Pid,Why}, #{type := FileInfo, file_ctrl_pid := Pid}) -> + %% file_ctrl_pid died, file error, terminate handler + exit({error,{write_failed,FileInfo,Why}}); +handle_info(_, _, State) -> + State. + +terminate(_Name, _Reason, #{file_ctrl_pid:=FWPid}) -> case is_process_alive(FWPid) of true -> unlink(FWPid), @@ -410,17 +215,12 @@ terminate(Reason, State = #{id:=Name, file_ctrl_pid:=FWPid, ok after ?DEFAULT_CALL_TIMEOUT -> - exit(FWPid, kill) + exit(FWPid, kill), + ok end; false -> ok - end, - ok = logger_h_common:stop_or_restart(Name, Reason, State), - unregister(?name_to_reg_name(?MODULE, Name)), - ok. - -code_change(_OldVsn, State, _Extra) -> - {ok, State}. + end. %%%=================================================================== %%% Internal functions @@ -428,200 +228,6 @@ code_change(_OldVsn, State, _Extra) -> %%%----------------------------------------------------------------- %%% -get_init_state() -> - #{sync_mode_qlen => ?SYNC_MODE_QLEN, - drop_mode_qlen => ?DROP_MODE_QLEN, - flush_qlen => ?FLUSH_QLEN, - burst_limit_enable => ?BURST_LIMIT_ENABLE, - burst_limit_max_count => ?BURST_LIMIT_MAX_COUNT, - burst_limit_window_time => ?BURST_LIMIT_WINDOW_TIME, - overload_kill_enable => ?OVERLOAD_KILL_ENABLE, - overload_kill_qlen => ?OVERLOAD_KILL_QLEN, - overload_kill_mem_size => ?OVERLOAD_KILL_MEM_SIZE, - overload_kill_restart_after => ?OVERLOAD_KILL_RESTART_AFTER, - file_ctrl_sync_int => ?CONTROLLER_SYNC_INTERVAL, - filesync_ok_qlen => ?FILESYNC_OK_QLEN, - filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}. - -%%%----------------------------------------------------------------- -%%% Add a standard handler to the logger. -%%% This starts a dedicated handler process which should always -%%% exist if the handler is registered with logger (and should not -%%% exist if the handler is not registered). -%%% -%%% Handler specific config should be provided with a sub map associated -%%% with a key named 'config', e.g: -%%% -%%% Config = #{config => #{sync_mode_qlen => 50} -%%% -%%% The standard handler process is linked to logger_sup, which is -%%% part of the kernel application's supervision tree. -start(Name, Config, HandlerState) -> - LoggerStdH = - #{id => Name, - start => {?MODULE, start_link, [Name,Config,HandlerState]}, - restart => temporary, - shutdown => 2000, - type => worker, - modules => [?MODULE]}, - case supervisor:start_child(logger_sup, LoggerStdH) of - {ok,Pid,Config1} -> - ok = logger_handler_watcher:register_handler(Name,Pid), - {ok,Config1}; - Error -> - Error - end. - -%%%----------------------------------------------------------------- -%%% Stop and remove the handler. -stop(Name) -> - case whereis(?name_to_reg_name(?MODULE,Name)) of - undefined -> - ok; - Pid -> - %% We don't want to do supervisor:terminate_child here - %% since we need to distinguish this explicit stop from a - %% system termination in order to avoid circular attempts - %% at removing the handler (implying deadlocks and - %% timeouts). - %% And we don't need to do supervisor:delete_child, since - %% the restart type is temporary, which means that the - %% child specification is automatically removed from the - %% supervisor when the process dies. - _ = gen_server:call(Pid, stop), - ok - end. - -%%%----------------------------------------------------------------- -%%% Logging and overload control. --define(update_file_ctrl_sync(C, Interval), - if C == 0 -> Interval; - true -> C-1 end). - -%% check for overload between every event (and set Mode to async, -%% sync or drop accordingly), but never flush the whole mailbox -%% before LogWindowSize events have been handled -do_log(Bin, CallOrCast, State = #{id:=Name, mode:=Mode0}) -> - T1 = ?timestamp(), - - %% check if the handler is getting overloaded, or if it's - %% recovering from overload (the check must be done for each - %% event to react quickly to large bursts of events and - %% to ensure that the handler can never end up in drop mode - %% with an empty mailbox, which would stop operation) - {Mode1,QLen,Mem,State1} = logger_h_common:check_load(State), - - if (Mode1 == drop) andalso (Mode0 =/= drop) -> - log_handler_info(Name, "Handler ~p switched to drop mode", - [Name], State); - (Mode0 == drop) andalso ((Mode1 == async) orelse (Mode1 == sync)) -> - log_handler_info(Name, "Handler ~p switched to ~w mode", - [Name,Mode1], State); - true -> - ok - end, - - %% kill the handler if it can't keep up with the load - logger_h_common:kill_if_choked(Name, QLen, Mem, ?MODULE, State), - - if Mode1 == flush -> - flush(Name, QLen, T1, State1); - true -> - write(Name, Mode1, T1, Bin, CallOrCast, State1) - end. - -%% this clause is called by do_log/3 after an overload check -%% has been performed, where QLen > FlushQLen -flush(Name, _QLen0, T1, State=#{last_log_ts := _T0, mode_tab := ModeTab}) -> - %% flush messages in the mailbox (a limited number in - %% order to not cause long delays) - NewFlushed = logger_h_common:flush_log_events(?FLUSH_MAX_N), - - %% write info in log about flushed messages - log_handler_info(Name, "Handler ~p flushed ~w log events", - [Name,NewFlushed], State), - - %% because of the receive loop when flushing messages, the - %% handler will be scheduled out often and the mailbox could - %% grow very large, so we'd better check the queue again here - {_,_QLen1} = process_info(self(), message_queue_len), - ?observe(Name,{max_qlen,_QLen1}), - - %% Add 1 for the current log event - ?observe(Name,{flushed,NewFlushed+1}), - - State1 = ?update_max_time(?diff_time(T1,_T0),State), - {dropped,?update_other(flushed,FLUSHED,NewFlushed, - State1#{mode => ?set_mode(ModeTab,async), - last_qlen => 0, - last_log_ts => T1})}. - -%% this clause is called to write to file -write(_Name, Mode, T1, Bin, _CallOrCast, - State = #{mode_tab := ModeTab, - file_ctrl_pid := FileCtrlPid, - file_ctrl_sync := FileCtrlSync, - last_qlen := LastQLen, - last_log_ts := T0, - file_ctrl_sync_int := FileCtrlSyncInt}) -> - %% check if we need to limit the number of writes - %% during a burst of log events - {DoWrite,BurstWinT,BurstMsgCount} = logger_h_common:limit_burst(State), - - %% only send a synhrounous event to the file controller process - %% every FileCtrlSyncInt time, to give the handler time between - %% file writes so it can keep up with incoming messages - {Result,LastQLen1} = - if DoWrite, FileCtrlSync == 0 -> - ?observe(_Name,{_CallOrCast,1}), - file_write_sync(FileCtrlPid, Bin, false), - {ok,element(2, process_info(self(), message_queue_len))}; - DoWrite -> - ?observe(_Name,{_CallOrCast,1}), - file_write_async(FileCtrlPid, Bin), - {ok,LastQLen}; - not DoWrite -> - ?observe(_Name,{flushed,1}), - {dropped,LastQLen} - end, - - %% Check if the time since the previous log event is long enough - - %% and the queue length small enough - to assume the mailbox has - %% been emptied, and if so, do filesync operation and reset mode to - %% async. Note that this is the best we can do to detect an idle - %% handler without setting a timer after each log call/cast. If the - %% time between two consecutive log events is fast and no new - %% event comes in after the last one, idle state won't be detected! - Time = ?diff_time(T1,T0), - {Mode1,BurstMsgCount1} = - if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso - (Time > ?IDLE_DETECT_TIME_USEC) -> - %% do filesync if necessary - case maps:get(type, State) of - Std when is_atom(Std) -> - ok; - _File -> - file_ctrl_filesync_async(FileCtrlPid) - end, - {?change_mode(ModeTab, Mode, async),0}; - true -> - {Mode,BurstMsgCount} - end, - State1 = - ?update_calls_or_casts(_CallOrCast,1,State), - State2 = - ?update_max_time(Time, - State1#{mode => Mode1, - last_qlen := LastQLen1, - last_log_ts => T1, - last_op => write, - burst_win_ts => BurstWinT, - burst_msg_count => BurstMsgCount1, - file_ctrl_sync => - ?update_file_ctrl_sync(FileCtrlSync, - FileCtrlSyncInt)}), - {Result,State2}. - open_log_file(HandlerName, FileInfo) -> case file_ctrl_start(HandlerName, FileInfo) of OK = {ok,_FileCtrlPid} -> OK; @@ -653,19 +259,6 @@ close_log_file(Fd) -> _ = file:close(Fd). -log_handler_info(Name, Format, Args, #{file_ctrl_pid := FileCtrlPid}) -> - Config = - case logger:get_handler_config(Name) of - {ok,Conf} -> Conf; - _ -> #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}} - end, - Meta = #{time=>erlang:system_time(microsecond)}, - Bin = logger_h_common:log_to_binary(#{level => notice, - msg => {Format,Args}, - meta => Meta}, Config), - _ = file_write_async(FileCtrlPid, Bin), - ok. - %%%----------------------------------------------------------------- %%% File control process @@ -692,24 +285,19 @@ file_write_async(Pid, Bin) -> Pid ! {log,Bin}, ok. -file_write_sync(Pid, Bin, FileSync) -> - case file_ctrl_call(Pid, {log,self(),Bin,FileSync}) of - {error,Reason} -> - {error,{write_failed,Bin,Reason}}; - Result -> - Result - end. +file_write_sync(Pid, Bin) -> + file_ctrl_call(Pid, {log,Bin}). file_ctrl_filesync_async(Pid) -> Pid ! filesync, ok. file_ctrl_filesync_sync(Pid) -> - file_ctrl_call(Pid, {filesync,self()}). + file_ctrl_call(Pid, filesync). file_ctrl_call(Pid, Msg) -> MRef = monitor(process, Pid), - Pid ! {Msg,MRef}, + Pid ! {Msg,{self(),MRef}}, receive {MRef,Result} -> demonitor(MRef, [flush]), @@ -727,74 +315,43 @@ file_ctrl_init(HandlerName, FileInfo, Starter) when is_tuple(FileInfo) -> case do_open_log_file(FileInfo) of {ok,Fd} -> Starter ! {self(),ok}, - file_ctrl_loop(Fd, file, FileName, false, ok, ok, HandlerName); + file_ctrl_loop(Fd, FileName, false, ok, ok, HandlerName); {error,Reason} -> Starter ! {self(),{error,{open_failed,FileName,Reason}}} end; file_ctrl_init(HandlerName, StdDev, Starter) -> Starter ! {self(),ok}, - file_ctrl_loop(StdDev, standard_io, StdDev, false, ok, ok, HandlerName). + file_ctrl_loop(StdDev, StdDev, false, ok, ok, HandlerName). -file_ctrl_loop(Fd, Type, DevName, Synced, +file_ctrl_loop(Fd, DevName, Synced, PrevWriteResult, PrevSyncResult, HandlerName) -> receive %% asynchronous event {log,Bin} -> - Result = if Type == file -> - write_to_dev(Fd, Bin, DevName, - PrevWriteResult, HandlerName); - true -> - io:put_chars(Fd, Bin) - end, - file_ctrl_loop(Fd, Type, DevName, false, + Fd1 = ensure(Fd, DevName), + Result = write_to_dev(Fd1, Bin, DevName, PrevWriteResult, HandlerName), + file_ctrl_loop(Fd1, DevName, false, Result, PrevSyncResult, HandlerName); %% synchronous event - {{log,From,Bin,FileSync},MRef} -> - if Type == file -> - %% check that file hasn't been deleted - CheckFile = - fun() -> {ok,_} = file:read_file_info(DevName) end, - spawn_link(CheckFile), - WResult = write_to_dev(Fd, Bin, DevName, - PrevWriteResult, HandlerName), - {Synced1,SResult} = - if not FileSync -> - {false,PrevSyncResult}; - true -> - case sync_dev(Fd, DevName, - PrevSyncResult, HandlerName) of - ok -> {true,ok}; - Error -> {false,Error} - end - end, - From ! {MRef,ok}, - file_ctrl_loop(Fd, Type, DevName, Synced1, - WResult, SResult, HandlerName); - true -> - _ = io:put_chars(Fd, Bin), - From ! {MRef,ok}, - file_ctrl_loop(Fd, Type, DevName, false, - ok, PrevSyncResult, HandlerName) - end; + {{log,Bin},{From,MRef}} -> + Fd1 = ensure(Fd, DevName), + Result = write_to_dev(Fd1, Bin, DevName, PrevWriteResult, HandlerName), + From ! {MRef,ok}, + file_ctrl_loop(Fd1, DevName, false, + Result, PrevSyncResult, HandlerName); - filesync when not Synced -> - Result = sync_dev(Fd, DevName, PrevSyncResult, HandlerName), - file_ctrl_loop(Fd, Type, DevName, true, + filesync -> + Fd1 = ensure(Fd, DevName), + Result = sync_dev(Fd1, DevName, Synced, PrevSyncResult, HandlerName), + file_ctrl_loop(Fd1, DevName, true, PrevWriteResult, Result, HandlerName); - filesync -> - file_ctrl_loop(Fd, Type, DevName, true, - PrevWriteResult, PrevSyncResult, HandlerName); - - {{filesync,From},MRef} -> - Result = if not Synced -> - sync_dev(Fd, DevName, PrevSyncResult, HandlerName); - true -> - ok - end, + {filesync,{From,MRef}} -> + Fd1 = ensure(Fd, DevName), + Result = sync_dev(Fd1, DevName, Synced, PrevSyncResult, HandlerName), From ! {MRef,ok}, - file_ctrl_loop(Fd, Type, DevName, true, + file_ctrl_loop(Fd1, DevName, true, PrevWriteResult, Result, HandlerName); stop -> @@ -802,27 +359,44 @@ file_ctrl_loop(Fd, Type, DevName, Synced, stopped end. -write_to_dev(Fd, Bin, FileName, PrevWriteResult, HandlerName) -> - case ?file_write(Fd, Bin) of - ok -> - ok; - PrevWriteResult -> - %% don't report same error twice - PrevWriteResult; - Error -> - logger_h_common:error_notify({HandlerName,write,FileName,Error}), - Error +%% 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,FileName) -> + case file:read_file_info(FileName) of + {ok,_} -> + Fd; + _ -> + _ = file:close(Fd), + _ = file:close(Fd), % delayed_write cause close not to close + case do_open_log_file({file,FileName}) of + {ok,Fd1} -> + Fd1; + Error -> + exit({could_not_reopen_file,Error}) + end end. -sync_dev(Fd, DevName, PrevSyncResult, HandlerName) -> - case ?file_datasync(Fd) of - ok -> - ok; - PrevSyncResult -> - %% don't report same error twice - PrevSyncResult; - Error -> - logger_h_common:error_notify({HandlerName,filesync,DevName,Error}), - Error - end. +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) -> + Result = ?file_write(Fd, Bin), + maybe_notify_error(write,Result,PrevWriteResult,FileName,HandlerName). +sync_dev(_Fd, _FileName, true, PrevSyncResult, _HandlerName) -> + PrevSyncResult; +sync_dev(Fd, FileName, false, PrevSyncResult, HandlerName) -> + Result = ?file_datasync(Fd), + maybe_notify_error(filesync,Result,PrevSyncResult,FileName,HandlerName). + +maybe_notify_error(_Op, ok, _PrevResult, _FileName, _HandlerName) -> + ok; +maybe_notify_error(_Op, PrevResult, PrevResult, _FileName, _HandlerName) -> + %% don't report same error twice + PrevResult; +maybe_notify_error(Op, Error, _PrevResult, FileName, HandlerName) -> + logger_h_common:error_notify({HandlerName,Op,FileName,Error}), + Error. diff --git a/lib/kernel/src/net_kernel.erl b/lib/kernel/src/net_kernel.erl index 3cf11fd7b1..a9dc77837e 100644 --- a/lib/kernel/src/net_kernel.erl +++ b/lib/kernel/src/net_kernel.erl @@ -808,7 +808,8 @@ handle_info({AcceptPid, {accept_pending,MyNode,Node,Address,Type}}, State) -> _:_ -> error_logger:error_msg("~n** Cannot get connection id for node ~w~n", [Node]), - AcceptPid ! {self(),{accept_pending,nok_pending}} + AcceptPid ! {self(),{accept_pending,nok_pending}}, + {noreply, State} end end; diff --git a/lib/kernel/test/gen_tcp_misc_SUITE.erl b/lib/kernel/test/gen_tcp_misc_SUITE.erl index 194522c009..c47de58fae 100644 --- a/lib/kernel/test/gen_tcp_misc_SUITE.erl +++ b/lib/kernel/test/gen_tcp_misc_SUITE.erl @@ -52,7 +52,8 @@ several_accepts_in_one_go/1, accept_system_limit/1, active_once_closed/1, send_timeout/1, send_timeout_active/1, otp_7731/1, zombie_sockets/1, otp_7816/1, otp_8102/1, - wrapping_oct/0, wrapping_oct/1, otp_9389/1, otp_13939/1]). + wrapping_oct/0, wrapping_oct/1, otp_9389/1, otp_13939/1, + otp_12242/1]). %% Internal exports. -export([sender/3, not_owner/1, passive_sockets_server/2, priority_server/1, @@ -95,7 +96,8 @@ all() -> killing_multi_acceptors2, several_accepts_in_one_go, accept_system_limit, active_once_closed, send_timeout, send_timeout_active, otp_7731, wrapping_oct, - zombie_sockets, otp_7816, otp_8102, otp_9389]. + zombie_sockets, otp_7816, otp_8102, otp_9389, + otp_12242]. groups() -> []. @@ -1967,20 +1969,20 @@ recvtclass(_Config) -> {skip,{ipv6_not_supported,IFs}} end. -%% These version numbers are the highest noted in daily tests -%% where the test fails for a plausible reason, so -%% skip on that platform. +%% These version numbers are above the highest noted +%% in daily tests where the test fails for a plausible reason, +%% so skip on platforms of lower version, i.e they are future +%% versions where it is possible that it might not fail. %% -%% On newer versions it might be fixed, but we'll see about that -%% when machines with newer versions gets installed... -%% If the test still fails for a plausible reason these +%% When machines with newer versions gets installed, +%% if the test still fails for a plausible reason these %% version numbers simply should be increased. %% Or maybe we should change to only test on known good %% platforms - change {unix,_} to false? %% pktoptions is not supported for IPv4 recvtos_ok({unix,openbsd}, OSVer) -> not semver_lt(OSVer, {6,4,0}); -recvtos_ok({unix,darwin}, OSVer) -> not semver_lt(OSVer, {17,6,0}); +recvtos_ok({unix,darwin}, OSVer) -> not semver_lt(OSVer, {19,0,0}); %% Using the option returns einval, so it is not implemented. recvtos_ok({unix,freebsd}, OSVer) -> not semver_lt(OSVer, {11,2,0}); recvtos_ok({unix,sunos}, OSVer) -> not semver_lt(OSVer, {5,12,0}); @@ -1992,7 +1994,7 @@ recvtos_ok(_, _) -> false. %% pktoptions is not supported for IPv4 recvttl_ok({unix,openbsd}, OSVer) -> not semver_lt(OSVer, {6,4,0}); -recvttl_ok({unix,darwin}, OSVer) -> not semver_lt(OSVer, {17,6,0}); +recvttl_ok({unix,darwin}, OSVer) -> not semver_lt(OSVer, {19,0,0}); %% Using the option returns einval, so it is not implemented. recvttl_ok({unix,freebsd}, OSVer) -> not semver_lt(OSVer, {11,2,0}); recvttl_ok({unix,sunos}, OSVer) -> not semver_lt(OSVer, {5,12,0}); @@ -2003,7 +2005,7 @@ recvttl_ok(_, _) -> false. %% pktoptions is not supported for IPv6 recvtclass_ok({unix,openbsd}, OSVer) -> not semver_lt(OSVer, {6,4,0}); -recvtclass_ok({unix,darwin}, OSVer) -> not semver_lt(OSVer, {17,6,0}); +recvtclass_ok({unix,darwin}, OSVer) -> not semver_lt(OSVer, {19,0,0}); recvtclass_ok({unix,sunos}, OSVer) -> not semver_lt(OSVer, {5,12,0}); %% Using the option returns einval, so it is not implemented. recvtclass_ok({unix,freebsd}, OSVer) -> not semver_lt(OSVer, {11,2,0}); @@ -3284,3 +3286,143 @@ otp_13939(Config) when is_list(Config) -> exit(Pid, normal), ct:fail("Server process blocked on send.") end. + +otp_12242(Config) when is_list(Config) -> + case os:type() of + {win32,_} -> + %% Even if we set sndbuf and recbuf to small sizes + %% Windows either happily accepts to send GBytes of data + %% in no time, so the second send below that is supposed + %% to time out just succedes, or the first send that + %% is supposed to fill the inet_drv I/O queue and + %% start waiting for when more data can be sent + %% instead sends all data but suffers a send + %% failure that closes the socket + {skipped,backpressure_broken_on_win32}; + _ -> + %% Find the IPv4 address of an up and running interface + %% that is not loopback nor pointtopoint + {ok,IFList} = inet:getifaddrs(), + ct:pal("IFList ~p~n", [IFList]), + case + lists:flatten( + [lists:filtermap( + fun ({addr,Addr}) when tuple_size(Addr) =:= 4 -> + {true,Addr}; + (_) -> + false + end, Opts) + || {_,Opts} <- IFList, + case lists:keyfind(flags, 1, Opts) of + {_,Flags} -> + lists:member(up, Flags) + andalso + lists:member(running, Flags) + andalso + not lists:member(loopback, Flags) + andalso + not lists:member(pointtopoint, Flags); + false -> + false + end]) + of + [Addr|_] -> + otp_12242(Addr); + Other -> + {skipped,{no_external_address,Other}} + end + end; +%% +otp_12242(Addr) when tuple_size(Addr) =:= 4 -> + ct:timetrap(30000), + ct:pal("Using address ~p~n", [Addr]), + Bufsize = 16 * 1024, + Datasize = 128 * 1024 * 1024, % At least 1 s on GBit interface + Blob = binary:copy(<<$x>>, Datasize), + LOpts = + [{backlog,4},{reuseaddr,true},{ip,Addr}, + binary,{active,false}, + {recbuf,Bufsize},{sndbuf,Bufsize},{buffer,Bufsize}], + COpts = + [binary,{active,false},{ip,Addr}, + {linger,{true,1}}, % 1 s + {send_timeout,500}, + {recbuf,Bufsize},{sndbuf,Bufsize},{buffer,Bufsize}], + Dir = filename:dirname(code:which(?MODULE)), + {ok,ListenerNode} = + test_server:start_node( + ?UNIQ_NODE_NAME, slave, [{args,"-pa " ++ Dir}]), + Tester = self(), + Listener = + spawn( + ListenerNode, + fun () -> + {ok,L} = gen_tcp:listen(0, LOpts), + {ok,LPort} = inet:port(L), + Tester ! {self(),port,LPort}, + {ok,A} = gen_tcp:accept(L), + ok = gen_tcp:close(L), + receive + {Tester,stop} -> + ok = gen_tcp:close(A) + end + end), + ListenerMref = monitor(process, Listener), + LPort = receive {Listener,port,P} -> P end, + {ok,C} = gen_tcp:connect(Addr, LPort, COpts, infinity), + {ok,ReadCOpts} = inet:getopts(C, [recbuf,sndbuf,buffer]), + ct:pal("ReadCOpts ~p~n", [ReadCOpts]), + %% + %% Fill the buffers + ct:pal("Sending ~p bytes~n", [Datasize]), + ok = gen_tcp:send(C, Blob), + ct:pal("Sent ~p bytes~n", [Datasize]), + %% Spawn the Closer, + %% try to ensure that the close call is in progress + %% before the owner proceeds with sending + Owner = self(), + {_Closer,CloserMref} = + spawn_opt( + fun () -> + Owner ! {tref, erlang:start_timer(50, Owner, closing)}, + ct:pal("Calling gen_tcp:close(C)~n"), + try gen_tcp:close(C) of + Result -> + ct:pal("gen_tcp:close(C) -> ~p~n", [Result]), + ok = Result + catch + Class:Reason:Stacktrace -> + ct:pal( + "gen_tcp:close(C) >< ~p:~p~n ~p~n", + [Class,Reason,Stacktrace]), + erlang:raise(Class, Reason, Stacktrace) + end + end, [link,monitor]), + receive + {tref,Tref} -> + receive {timeout,Tref,_} -> ok end, + ct:pal("Sending ~p bytes again~n", [Datasize]), + %% Now should the close be in progress... + %% All buffers are full, remote end is not reading, + %% and the send timeout is 1 s so this will timeout: + {error,timeout} = gen_tcp:send(C, Blob), + ct:pal("Sending ~p bytes again timed out~n", [Datasize]), + ok = inet:setopts(C, [{send_timeout,10000}]), + %% There is a hidden timeout here. Port close is sampled + %% every 5 s by prim_inet:send_recv_reply. + %% Linger is 3 s so the Closer will finish this send: + ct:pal("Sending ~p bytes with 10 s timeout~n", [Datasize]), + {error,closed} = gen_tcp:send(C, Blob), + ct:pal("Sending ~p bytes with 10 s timeout was closed~n", + [Datasize]), + normal = wait(CloserMref), + ct:pal("The Closer has exited~n"), + Listener ! {Tester,stop}, + receive {'DOWN',ListenerMref,_,_,_} -> ok end, + ct:pal("The Listener has exited~n"), + test_server:stop_node(ListenerNode), + ok + end. + +wait(Mref) -> + receive {'DOWN',Mref,_,_,Reason} -> Reason end. diff --git a/lib/kernel/test/inet_SUITE.erl b/lib/kernel/test/inet_SUITE.erl index 2e5f8c7d2c..f436eafad3 100644 --- a/lib/kernel/test/inet_SUITE.erl +++ b/lib/kernel/test/inet_SUITE.erl @@ -1060,28 +1060,26 @@ getservbyname_overflow(Config) when is_list(Config) -> getifaddrs(Config) when is_list (Config) -> {ok,IfAddrs} = inet:getifaddrs(), io:format("IfAddrs = ~p.~n", [IfAddrs]), - case - {os:type(), - [If || - {If,Opts} <- IfAddrs, - lists:keymember(hwaddr, 1, Opts)]} of - {{unix,sunos},[]} -> ok; - {OT,[]} -> - ct:fail({should_have_hwaddr,OT}); - _ -> ok + case [If || {If,Opts} <- IfAddrs, lists:keymember(hwaddr, 1, Opts)] of + [] -> + case os:type() of + {unix,sunos} -> ok; + OT -> + ct:fail({should_have_hwaddr,OT}) + end; + [_|_] -> ok end, - Addrs = - [element(1, A) || A <- ifaddrs(IfAddrs)], + Addrs = ifaddrs(IfAddrs), io:format("Addrs = ~p.~n", [Addrs]), [check_addr(Addr) || Addr <- Addrs], ok. -check_addr({addr,Addr}) +check_addr(Addr) when tuple_size(Addr) =:= 8, element(1, Addr) band 16#FFC0 =:= 16#FE80 -> io:format("Addr: ~p link local; SKIPPED!~n", [Addr]), ok; -check_addr({addr,Addr}) -> +check_addr(Addr) -> io:format("Addr: ~p.~n", [Addr]), Ping = "ping", Pong = "pong", @@ -1097,78 +1095,86 @@ check_addr({addr,Addr}) -> ok = gen_tcp:close(S2), ok = gen_tcp:close(L). --record(ifopts, {name,flags,addrs=[],hwaddr}). - -ifaddrs([]) -> []; -ifaddrs([{If,Opts}|IOs]) -> - #ifopts{flags=F} = Ifopts = check_ifopts(Opts, #ifopts{name=If}), - case F of - {flags,Flags} -> - case lists:member(running, Flags) of - true -> Ifopts#ifopts.addrs; - false -> [] - end ++ ifaddrs(IOs); - undefined -> - ifaddrs(IOs) +ifaddrs(IfOpts) -> + IfMap = collect_ifopts(IfOpts), + ChkFun = + fun Self({{_,Flags} = Key, Opts}, ok) -> + Broadcast = lists:member(broadcast, Flags), + P2P = lists:member(pointtopoint, Flags), + case Opts of + [{addr,_},{netmask,_},{broadaddr,_}|Os] + when Broadcast -> + Self({Key, Os}, ok); + [{addr,_},{netmask,_},{dstaddr,_}|Os] + when P2P -> + Self({Key, Os}, ok); + [{addr,_},{netmask,_}|Os] -> + Self({Key, Os}, ok); + [{hwaddr,_}|Os] -> + Self({Key, Os}, ok); + [] -> + ok + end + end, + fold_ifopts(ChkFun, ok, IfMap), + AddrsFun = + fun ({{_,Flags}, Opts}, Acc) -> + case + lists:member(running, Flags) + andalso (not lists:member(pointtopoint, Flags)) + of + true -> + lists:reverse( + [Addr || {addr,Addr} <- Opts], + Acc); + false -> + Acc + end + end, + fold_ifopts(AddrsFun, [], IfMap). + +collect_ifopts(IfOpts) -> + collect_ifopts(IfOpts, #{}). +%% +collect_ifopts(IfOpts, IfMap) -> + case IfOpts of + [{If,[{flags,Flags}|Opts]}|IfOs] -> + Key = {If,Flags}, + case maps:is_key(Key, IfMap) of + true -> + ct:fail({unexpected_ifopts,IfOpts,IfMap}); + false -> + collect_ifopts(IfOs, IfMap, Opts, Key, []) + end; + [] -> + IfMap; + _ -> + ct:fail({unexpected_ifopts,IfOpts,IfMap}) + end. +%% +collect_ifopts(IfOpts, IfMap, Opts, Key, R) -> + case Opts of + [{flags,_}|_] -> + {If,_} = Key, + collect_ifopts( + [{If,Opts}|IfOpts], maps:put(Key, lists:reverse(R), IfMap)); + [OptVal|Os] -> + collect_ifopts(IfOpts, IfMap, Os, Key, [OptVal|R]); + [] -> + collect_ifopts(IfOpts, maps:put(Key, lists:reverse(R), IfMap)) end. -check_ifopts([], #ifopts{flags=F,addrs=Raddrs}=Ifopts) -> - Addrs = lists:reverse(Raddrs), - R = Ifopts#ifopts{addrs=Addrs}, - io:format("~p.~n", [R]), - %% See how we did... - {flags,Flags} = F, - case lists:member(broadcast, Flags) of - true -> - [case A of - {{addr,_},{netmask,_},{broadaddr,_}} -> - A; - {{addr,T},{netmask,_}} when tuple_size(T) =:= 8 -> - A - end || A <- Addrs]; - false -> - case lists:member(pointtopoint, Flags) of - true -> - [case A of - {{addr,_},{netmask,_},{dstaddr,_}} -> - A - end || A <- Addrs]; - false -> - [case A of - {{addr,_},{netmask,_}} -> - A - end || A <- Addrs] - end - end, - R; -check_ifopts([{flags,_}=F|Opts], #ifopts{flags=undefined}=Ifopts) -> - check_ifopts(Opts, Ifopts#ifopts{flags=F}); -check_ifopts([{flags,_}=F|Opts], #ifopts{flags=Flags}=Ifopts) -> - case F of - Flags -> - check_ifopts(Opts, Ifopts); - _ -> - ct:fail({multiple_flags,F,Ifopts}) - end; -check_ifopts( - [{addr,_}=A,{netmask,_}=N,{dstaddr,_}=D|Opts], - #ifopts{addrs=Addrs}=Ifopts) -> - check_ifopts(Opts, Ifopts#ifopts{addrs=[{A,N,D}|Addrs]}); -check_ifopts( - [{addr,_}=A,{netmask,_}=N,{broadaddr,_}=B|Opts], - #ifopts{addrs=Addrs}=Ifopts) -> - check_ifopts(Opts, Ifopts#ifopts{addrs=[{A,N,B}|Addrs]}); -check_ifopts( - [{addr,_}=A,{netmask,_}=N|Opts], - #ifopts{addrs=Addrs}=Ifopts) -> - check_ifopts(Opts, Ifopts#ifopts{addrs=[{A,N}|Addrs]}); -check_ifopts([{addr,_}=A|Opts], #ifopts{addrs=Addrs}=Ifopts) -> - check_ifopts(Opts, Ifopts#ifopts{addrs=[{A}|Addrs]}); -check_ifopts([{hwaddr,Hwaddr}=H|Opts], #ifopts{hwaddr=undefined}=Ifopts) - when is_list(Hwaddr) -> - check_ifopts(Opts, Ifopts#ifopts{hwaddr=H}); -check_ifopts([{hwaddr,_}=H|_], #ifopts{}=Ifopts) -> - ct:fail({multiple_hwaddrs,H,Ifopts}). +fold_ifopts(Fun, Acc, IfMap) -> + fold_ifopts(Fun, Acc, IfMap, maps:keys(IfMap)). +%% +fold_ifopts(Fun, Acc, IfMap, Keys) -> + case Keys of + [Key|Ks] -> + Opts = maps:get(Key, IfMap), + fold_ifopts(Fun, Fun({Key,Opts}, Acc), IfMap, Ks); + [] -> + Acc + end. %% Works just like lists:member/2, except that any {127,_,_,_} tuple %% matches any other {127,_,_,_}. We do this to handle Linux systems diff --git a/lib/kernel/test/inet_sockopt_SUITE.erl b/lib/kernel/test/inet_sockopt_SUITE.erl index ada9c2689c..27ff74e309 100644 --- a/lib/kernel/test/inet_sockopt_SUITE.erl +++ b/lib/kernel/test/inet_sockopt_SUITE.erl @@ -110,9 +110,14 @@ simple(Config) when is_list(Config) -> {S1,S2} = create_socketpair(Opt, Opt), {ok,Opt} = inet:getopts(S1,OptTags), {ok,Opt} = inet:getopts(S2,OptTags), - COpt = [{X,case X of nodelay -> false;_ -> Y end} || {X,Y} <- Opt], + NoPushOpt = case os:type() of + {unix, Osname} when Osname =:= linux; Osname =:= freebsd -> {nopush, true}; + {_,_} -> {nopush, false} + end, + COpt = [{X,case X of nodelay -> false;_ -> Y end} || {X,Y} <- [NoPushOpt|Opt]], + COptTags = [X || {X,_} <- COpt], inet:setopts(S1,COpt), - {ok,COpt} = inet:getopts(S1,OptTags), + {ok,COpt} = inet:getopts(S1,COptTags), {ok,Opt} = inet:getopts(S2,OptTags), gen_tcp:close(S1), gen_tcp:close(S2), diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl index b7ccba8e70..d831d0d108 100644 --- a/lib/kernel/test/logger_SUITE.erl +++ b/lib/kernel/test/logger_SUITE.erl @@ -246,6 +246,18 @@ change_config(_Config) -> {ok,C4} = logger:get_handler_config(h1), C4 = C3#{custom:=new_custom}, + %% Change handler config: Id and module can not be changed + {error,{illegal_config_change,Old,New}} = + logger:set_handler_config(h1,id,newid), + %% Check that only the faulty field is included in return + [{id,h1}] = maps:to_list(Old), + [{id,newid}] = maps:to_list(New), + %% Check that both fields are included when both are changed + {error,{illegal_config_change, + #{id:=h1,module:=?MODULE}, + #{id:=newid,module:=newmodule}}} = + logger:set_handler_config(h1,#{id=>newid,module=>newmodule}), + %% Change primary config: Single key PConfig0 = logger:get_primary_config(), ok = logger:set_primary_config(level,warning), diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl index a815db14e9..87b8250781 100644 --- a/lib/kernel/test/logger_disk_log_h_SUITE.erl +++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl @@ -92,6 +92,7 @@ all() -> disk_log_opts, default_formatter, logging, + filter_config, errors, formatter_fail, config_fail, @@ -302,6 +303,20 @@ logging(cleanup, _Config) -> Name = list_to_atom(lists:concat([?FUNCTION_NAME,"_1"])), remove_and_stop(Name). +filter_config(_Config) -> + ok = logger:add_handler(?MODULE,logger_disk_log_h,#{}), + {ok,#{config:=HConfig}=Config} = logger:get_handler_config(?MODULE), + HConfig = maps:without([handler_pid,mode_tab],HConfig), + + FakeFullHConfig = HConfig#{handler_pid=>self(),mode_tab=>erlang:make_ref()}, + #{config:=HConfig} = + logger_disk_log_h:filter_config(Config#{config=>FakeFullHConfig}), + ok. + +filter_config(cleanup,_Config) -> + logger:remove_handler(?MODULE), + ok. + errors(Config) -> PrivDir = ?config(priv_dir,Config), Name1 = list_to_atom(lists:concat([?FUNCTION_NAME,"_1"])), @@ -316,13 +331,31 @@ errors(Config) -> %%! TODO: %%! Check how bad log_opts are handled! - {error,{illegal_config_change,_,_}} = - logger:set_handler_config(Name1, - config, - #{file=>LogFile1, - type=>halt}), - {error,{illegal_config_change,_,_}} = - logger:set_handler_config(Name1,id,new), + {error,{illegal_config_change, + logger_disk_log_h, + #{type:=wrap}, + #{type:=halt}}} = + logger:update_handler_config(Name1, + config, + #{type=>halt, + file=>LogFile1}), + + {error,{illegal_config_change, + logger_disk_log_h, + #{file:=LogFile1}, + #{file:="newfilename"}}} = + logger:update_handler_config(Name1, + config, + #{file=>"newfilename"}), + + %% Read-only fields may (accidentially) be included in the change, + %% but it won't take effect + {ok,C} = logger:get_handler_config(Name1), + ok = logger:set_handler_config(Name1,config, + #{handler_pid=>self(), + mode_tab=>erlang:make_ref()}), + {ok,C} = logger:get_handler_config(Name1), + ok = logger:remove_handler(Name1), {error,{not_found,Name1}} = logger:remove_handler(Name1), @@ -380,20 +413,25 @@ formatter_fail(cleanup,_Config) -> ok. config_fail(_Config) -> - {error,{handler_not_added,{invalid_config,logger_disk_log_h,{bad,bad}}}} = + {error,{handler_not_added,{invalid_config,logger_disk_log_h,#{bad:=bad}}}} = logger:add_handler(?MODULE,logger_disk_log_h, #{config => #{bad => bad}, filter_default=>log, formatter=>{?MODULE,self()}}), - {error,{handler_not_added,{invalid_levels,{_,1,_}}}} = + {error,{handler_not_added,{invalid_config,logger_disk_log_h, + {invalid_levels,#{drop_mode_qlen:=1}}}}} = logger:add_handler(?MODULE,logger_disk_log_h, #{config => #{drop_mode_qlen=>1}}), - {error,{handler_not_added,{invalid_levels,{43,42,_}}}} = + {error,{handler_not_added,{invalid_config,logger_disk_log_h, + {invalid_levels,#{sync_mode_qlen:=43, + drop_mode_qlen:=42}}}}} = logger:add_handler(?MODULE,logger_disk_log_h, #{config => #{sync_mode_qlen=>43, drop_mode_qlen=>42}}), - {error,{handler_not_added,{invalid_levels,{_,43,42}}}} = + {error,{handler_not_added,{invalid_config,logger_disk_log_h, + {invalid_levels,#{drop_mode_qlen:=43, + flush_qlen:=42}}}}} = logger:add_handler(?MODULE,logger_disk_log_h, #{config => #{drop_mode_qlen=>43, flush_qlen=>42}}), @@ -402,22 +440,19 @@ config_fail(_Config) -> #{filter_default=>log, formatter=>{?MODULE,self()}}), %% can't change the disk log options for a log already in use - {error,{illegal_config_change,_,_}} = - logger:set_handler_config(?MODULE,config, - #{max_no_files=>2}), - %% can't change name of an existing handler - {error,{illegal_config_change,_,_}} = - logger:set_handler_config(?MODULE,id,bad), + {error,{illegal_config_change,logger_disk_log_h,_,_}} = + logger:update_handler_config(?MODULE,config, + #{max_no_files=>2}), %% incorrect values of OP params {ok,#{config := HConfig}} = logger:get_handler_config(?MODULE), - {error,{invalid_levels,_}} = - logger:set_handler_config(?MODULE,config, - HConfig#{sync_mode_qlen=>100, - flush_qlen=>99}), + {error,{invalid_config,logger_disk_log_h,{invalid_levels,_}}} = + logger:update_handler_config(?MODULE,config, + HConfig#{sync_mode_qlen=>100, + flush_qlen=>99}), %% invalid name of config parameter - {error,{invalid_config,logger_disk_log_h,{filesync_rep_int,2000}}} = - logger:set_handler_config(?MODULE, config, - HConfig#{filesync_rep_int => 2000}), + {error,{invalid_config,logger_disk_log_h,#{filesync_rep_int:=2000}}} = + logger:update_handler_config(?MODULE, config, + HConfig#{filesync_rep_int => 2000}), ok. config_fail(cleanup,_Config) -> logger:remove_handler(?MODULE). @@ -456,13 +491,30 @@ reconfig(Config) -> overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE, overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER, filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL, - log_opts := #{type := ?DISK_LOG_TYPE, - max_no_files := ?DISK_LOG_MAX_NO_FILES, - max_no_bytes := ?DISK_LOG_MAX_NO_BYTES, - file := _DiskLogFile}} = + handler_state := + #{log_opts := #{type := ?DISK_LOG_TYPE, + max_no_files := ?DISK_LOG_MAX_NO_FILES, + max_no_bytes := ?DISK_LOG_MAX_NO_BYTES, + file := DiskLogFile}}} = logger_disk_log_h:info(?MODULE), + {ok,#{config := + #{sync_mode_qlen := ?SYNC_MODE_QLEN, + drop_mode_qlen := ?DROP_MODE_QLEN, + flush_qlen := ?FLUSH_QLEN, + burst_limit_enable := ?BURST_LIMIT_ENABLE, + burst_limit_max_count := ?BURST_LIMIT_MAX_COUNT, + burst_limit_window_time := ?BURST_LIMIT_WINDOW_TIME, + overload_kill_enable := ?OVERLOAD_KILL_ENABLE, + overload_kill_qlen := ?OVERLOAD_KILL_QLEN, + overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE, + overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER, + filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL, + file := DiskLogFile, + max_no_files := ?DISK_LOG_MAX_NO_FILES, + max_no_bytes := ?DISK_LOG_MAX_NO_BYTES, + type := wrap} = HConfig0}} = + logger:get_handler_config(?MODULE), - {ok,#{config := HConfig0}} = logger:get_handler_config(?MODULE), HConfig1 = HConfig0#{sync_mode_qlen => 1, drop_mode_qlen => 2, flush_qlen => 3, @@ -488,6 +540,29 @@ reconfig(Config) -> overload_kill_restart_after := infinity, filesync_repeat_interval := no_repeat} = logger_disk_log_h:info(?MODULE), + {ok,#{config:=HConfig1}} = logger:get_handler_config(?MODULE), + + ok = logger:update_handler_config(?MODULE, config, + #{flush_qlen => ?FLUSH_QLEN}), + {ok,#{config:=C1}} = logger:get_handler_config(?MODULE), + ct:log("C1: ~p",[C1]), + C1 = HConfig1#{flush_qlen => ?FLUSH_QLEN}, + + ok = logger:set_handler_config(?MODULE, config, #{sync_mode_qlen => 1}), + {ok,#{config:=C2}} = logger:get_handler_config(?MODULE), + ct:log("C2: ~p",[C2]), + C2 = HConfig0#{sync_mode_qlen => 1}, + + ok = logger:set_handler_config(?MODULE, config, #{drop_mode_qlen => 100}), + {ok,#{config:=C3}} = logger:get_handler_config(?MODULE), + ct:log("C3: ~p",[C3]), + C3 = HConfig0#{drop_mode_qlen => 100}, + + ok = logger:update_handler_config(?MODULE, config, #{sync_mode_qlen => 1}), + {ok,#{config:=C4}} = logger:get_handler_config(?MODULE), + ct:log("C4: ~p",[C4]), + C4 = HConfig0#{sync_mode_qlen => 1, + drop_mode_qlen => 100}, ok = logger:remove_handler(?MODULE), @@ -502,11 +577,49 @@ reconfig(Config) -> max_no_files => 1, max_no_bytes => 1024, file => File}}), - #{log_opts := #{type := halt, - max_no_files := 1, - max_no_bytes := 1024, - file := File}} = + #{handler_state := + #{log_opts := #{type := halt, + max_no_files := 1, + max_no_bytes := 1024, + file := File}}} = logger_disk_log_h:info(?MODULE), + {ok,#{config := + #{type := halt, + max_no_files := 1, + max_no_bytes := 1024, + file := File}=HaltHConfig} = Config2} = + logger:get_handler_config(?MODULE), + + ok = logger:update_handler_config(?MODULE, level, notice), + {ok,C5} = logger:get_handler_config(?MODULE), + ct:log("C5: ~p",[C5]), + C5 = Config2#{level => notice}, + + ok = logger:set_handler_config(?MODULE, level, info), + {ok,C6} = logger:get_handler_config(?MODULE), + ct:log("C6: ~p",[C6]), + C6 = Config2#{level => info}, + + %% You are not allowed to actively set the write once fields + %% (type, max_no_files, max_no_bytes, file) in runtime. + {error, {illegal_config_change,_,_,_}} = + logger:set_handler_config(?MODULE,config,#{type=>wrap}), + {error, {illegal_config_change,_,_,_}} = + logger:set_handler_config(?MODULE,config,#{max_no_files=>2}), + {error, {illegal_config_change,_,_,_}} = + logger:set_handler_config(?MODULE,config,#{max_no_bytes=>2048}), + {error, {illegal_config_change,_,_,_}} = + logger:set_handler_config(?MODULE,config,#{file=>"otherfile.log"}), + {ok,C7} = logger:get_handler_config(?MODULE), + ct:log("C7: ~p",[C7]), + C7 = C6, + + %% ... but if you don't specify the write once fields, then + %% set_handler_config shall NOT reset them to their default value + ok = logger:set_handler_config(?MODULE,config,#{sync_mode_qlen=>1}), + {ok,#{config:=C8}} = logger:get_handler_config(?MODULE), + ct:log("C8: ~p",[C8]), + C8 = HaltHConfig#{sync_mode_qlen=>1}, ok. reconfig(cleanup, _Config) -> @@ -523,20 +636,20 @@ sync(Config) -> filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,nl}}), - start_tracer([{disk_log,blog,2}, - {logger_disk_log_h,disk_log_sync,2}], - [{disk_log,blog,<<"first\n">>}, - {logger_disk_log_h,disk_log_sync}]), + start_tracer([{logger_disk_log_h,disk_log_write,3}, + {disk_log,sync,1}], + [{logger_disk_log_h,disk_log_write,<<"first\n">>}, + {disk_log,sync}]), logger:notice("first", ?domain), %% wait for automatic disk_log_sync check_tracer(?FILESYNC_REPEAT_INTERVAL*2), - %% check that if there's no repeated disk_log_sync active, + %% check that if there's no repeated filesync active, %% a disk_log_sync is still performed when handler goes idle {ok,#{config := HConfig}} = logger:get_handler_config(?MODULE), HConfig1 = HConfig#{filesync_repeat_interval => no_repeat}, - ok = logger:set_handler_config(?MODULE, config, HConfig1), + ok = logger:update_handler_config(?MODULE, config, HConfig1), no_repeat = maps:get(filesync_repeat_interval, logger_disk_log_h:info(?MODULE)), @@ -545,12 +658,12 @@ sync(Config) -> %% triggered by the idle timeout between "fourth" and "fifth". timer:sleep(?IDLE_DETECT_TIME_MSEC*2), - start_tracer([{disk_log,blog,2}, - {logger_disk_log_h,disk_log_sync,2}], - [{disk_log,blog,<<"second\n">>}, - {logger_disk_log_h,disk_log_sync}, - {disk_log,blog,<<"third\n">>}, - {logger_disk_log_h,disk_log_sync}]), + start_tracer([{logger_disk_log_h,disk_log_write,3}, + {disk_log,sync,1}], + [{logger_disk_log_h,disk_log_write,<<"second\n">>}, + {disk_log,sync}, + {logger_disk_log_h,disk_log_write,<<"third\n">>}, + {disk_log,sync}]), logger:notice("second", ?domain), timer:sleep(?IDLE_DETECT_TIME_MSEC*2), @@ -560,22 +673,22 @@ sync(Config) -> try_read_file(Log, {ok,<<"first\nsecond\nthird\n">>}, 1000), - %% switch repeated disk_log_sync on and verify that the looping works + %% switch repeated filesync on and verify that the looping works SyncInt = 1000, WaitT = 4500, - OneSync = {logger_disk_log_h,handle_cast,repeated_disk_log_sync}, - %% receive 1 initial repeated_disk_log_sync, then 1 per sec - start_tracer([{logger_disk_log_h,handle_cast,2}], - [OneSync || _ <- lists:seq(1, 1 + trunc(WaitT/SyncInt))]), + OneSync = {logger_h_common,handle_cast,repeated_filesync}, + %% receive 1 repeated_filesync per sec + start_tracer([{logger_h_common,handle_cast,2}], + [OneSync || _ <- lists:seq(1, trunc(WaitT/SyncInt))]), HConfig2 = HConfig#{filesync_repeat_interval => SyncInt}, - ok = logger:set_handler_config(?MODULE, config, HConfig2), + ok = logger:update_handler_config(?MODULE, config, HConfig2), SyncInt = maps:get(filesync_repeat_interval, logger_disk_log_h:info(?MODULE)), timer:sleep(WaitT), HConfig3 = HConfig#{filesync_repeat_interval => no_repeat}, - ok = logger:set_handler_config(?MODULE, config, HConfig3), + ok = logger:update_handler_config(?MODULE, config, HConfig3), check_tracer(100), ok. sync(cleanup,_Config) -> @@ -609,7 +722,7 @@ disk_log_wrap(Config) -> end, {ok,_} = dbg:tracer(process, {TraceFun, Tester}), {ok,_} = dbg:p(whereis(h_proc_name()), [c]), - {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []), + {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 3, []), Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,MaxBytes)], ct:pal("String = ~p (~w)", [Text, erts_debug:size(Text)]), @@ -627,7 +740,7 @@ disk_log_wrap(Config) -> timer:sleep(1000), dbg:stop_clear(), Received = lists:flatmap(fun({trace,_M,handle_info, - [{disk_log,_Node,_Name,What},_]}) -> + [_,{disk_log,_Node,_Name,What},_]}) -> [{trace,What}]; ({log,_}) -> [] @@ -663,7 +776,7 @@ disk_log_full(Config) -> end, {ok,_} = dbg:tracer(process, {TraceFun, Tester}), {ok,_} = dbg:p(whereis(h_proc_name()), [c]), - {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []), + {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 3, []), NoOfChars = 5, Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,NoOfChars)], @@ -673,14 +786,18 @@ disk_log_full(Config) -> timer:sleep(2000), dbg:stop_clear(), Received = lists:flatmap(fun({trace,_M,handle_info, - [{disk_log,_Node,_Name,What},_]}) -> + [_,{disk_log,_Node,_Name,What},_]}) -> [{trace,What}]; ({log,_}) -> [] end, test_server:messages_get()), ct:pal("Trace =~n~p", [Received]), - [{trace,full}, - {trace,{error_status,{error,{full,_}}}}] = Received, + + %% The tail here could be an error_status notification, if the + %% last write was synchronous, but in most cases it will not be + [{trace,full}|_] = Received, + %% [{trace,full}, + %% {trace,{error_status,{error,{full,_}}}}] = Received, ok. disk_log_full(cleanup, _Config) -> dbg:stop_clear(), @@ -712,14 +829,14 @@ disk_log_events(Config) -> end, {ok,_} = dbg:tracer(process, {TraceFun, Tester}), {ok,_} = dbg:p(whereis(h_proc_name()), [c]), - {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []), + {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 3, []), [whereis(h_proc_name()) ! E || E <- Events], %% wait for trace messages timer:sleep(2000), dbg:stop_clear(), Received = lists:map(fun({trace,_M,handle_info, - [Got,_]}) -> Got + [_,Got,_]}) -> Got end, test_server:messages_get()), ct:pal("Trace =~n~p", [Received]), NoOfEvents = length(Events), @@ -742,13 +859,15 @@ write_failure(Config) -> false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])), rpc:call(Node, ets, insert, [?TEST_HOOKS_TAB,{tester,self()}]), rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]), - rpc:call(Node, ?MODULE, set_result, [disk_log_blog,ok]), + rpc:call(Node, ?MODULE, set_result, [disk_log_write,ok]), HState = rpc:call(Node, logger_disk_log_h, info, [?STANDARD_HANDLER]), - ct:pal("LogOpts = ~p", [LogOpts = maps:get(log_opts, HState)]), + ct:pal("LogOpts = ~p", [LogOpts = maps:get(log_opts, + maps:get(handler_state,HState))]), + %% ?check and ?check_no_log in this test only check for internal log events ok = log_on_remote_node(Node, "Logged1"), rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]), - ?check_no_log, + ?check_no_log, % no internal log when write ok SyncRepInt = case (fun() -> is_atom(?FILESYNC_REPEAT_INTERVAL) end)() of true -> 5500; @@ -757,24 +876,26 @@ write_failure(Config) -> try_read_file(Log, {ok,<<"Logged1\n">>}, SyncRepInt), - rpc:call(Node, ?MODULE, set_result, [disk_log_blog,{error,no_such_log}]), + rpc:call(Node, ?MODULE, set_result, [disk_log_write,{error,no_such_log}]), ok = log_on_remote_node(Node, "Cause simple error printout"), + %% this should have caused an internal log ?check({error,{?STANDARD_HANDLER,log,LogOpts,{error,no_such_log}}}), - + ok = log_on_remote_node(Node, "No second error printout"), - ?check_no_log, + ?check_no_log, % but don't log same error twice - rpc:call(Node, ?MODULE, set_result, [disk_log_blog, + rpc:call(Node, ?MODULE, set_result, [disk_log_write, {error,{full,?STANDARD_HANDLER}}]), ok = log_on_remote_node(Node, "Cause simple error printout"), + %% this was a different error, so it should be logged ?check({error,{?STANDARD_HANDLER,log,LogOpts, {error,{full,?STANDARD_HANDLER}}}}), - rpc:call(Node, ?MODULE, set_result, [disk_log_blog,ok]), + rpc:call(Node, ?MODULE, set_result, [disk_log_write,ok]), ok = log_on_remote_node(Node, "Logged2"), rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]), - ?check_no_log, + ?check_no_log, % no internal log when write ok try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, SyncRepInt), ok. write_failure(cleanup, _Config) -> @@ -794,10 +915,10 @@ sync_failure(Config) -> rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]), rpc:call(Node, ?MODULE, set_result, [disk_log_sync,ok]), HState = rpc:call(Node, logger_disk_log_h, info, [?STANDARD_HANDLER]), - LogOpts = maps:get(log_opts, HState), + LogOpts = maps:get(log_opts, maps:get(handler_state,HState)), SyncInt = 500, - ok = rpc:call(Node, logger, set_handler_config, + ok = rpc:call(Node, logger, update_handler_config, [?STANDARD_HANDLER, config, #{filesync_repeat_interval => SyncInt}]), Info = rpc:call(Node, logger_disk_log_h, info, [?STANDARD_HANDLER]), @@ -872,7 +993,7 @@ op_switch_to_sync(Config) -> drop_mode_qlen => NumOfReqs+1, flush_qlen => 2*NumOfReqs, burst_limit_enable => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Lines = count_lines(Log), NumOfReqs = Lines, @@ -897,7 +1018,7 @@ op_switch_to_drop(Config) -> drop_mode_qlen => 2, flush_qlen => Procs*NumOfReqs*Bursts, burst_limit_enable => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), %% It sometimes happens that the handler either gets %% the requests in a slow enough pace so that dropping %% never occurs. Therefore, lets generate a number of @@ -943,7 +1064,7 @@ op_switch_to_flush(Config) -> drop_mode_qlen => 300, flush_qlen => 300, burst_limit_enable => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), NumOfReqs = 1500, Procs = 10, Bursts = 10, @@ -985,7 +1106,7 @@ limit_burst_disabled(Config) -> burst_limit_window_time => 2000, drop_mode_qlen => 200, flush_qlen => 300}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), NumOfReqs = 100, send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), @@ -1005,7 +1126,7 @@ limit_burst_enabled_one(Config) -> burst_limit_window_time => 2000, drop_mode_qlen => 200, flush_qlen => 300}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), NumOfReqs = 100, send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), @@ -1026,7 +1147,7 @@ limit_burst_enabled_period(Config) -> burst_limit_window_time => BurstTWin, drop_mode_qlen => 20000, flush_qlen => 20001}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), Windows = 3, Sent = send_burst({t,BurstTWin*Windows}, seq, {chars,79}, notice), @@ -1046,7 +1167,7 @@ kill_disabled(Config) -> HConfig#{config=>DLHConfig#{overload_kill_enable=>false, overload_kill_qlen=>10, overload_kill_mem_size=>100}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), NumOfReqs = 100, send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), @@ -1068,7 +1189,7 @@ qlen_kill_new(Config) -> overload_kill_qlen=>10, overload_kill_mem_size=>Mem0+50000, overload_kill_restart_after=>RestartAfter}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), MRef = erlang:monitor(process, Pid0), NumOfReqs = 100, Procs = 4, @@ -1105,7 +1226,7 @@ mem_kill_new(Config) -> overload_kill_qlen=>50000, overload_kill_mem_size=>Mem0+500, overload_kill_restart_after=>RestartAfter}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), MRef = erlang:monitor(process, Pid0), NumOfReqs = 100, Procs = 4, @@ -1139,7 +1260,7 @@ restart_after(Config) -> HConfig#{config=>DLHConfig#{overload_kill_enable=>true, overload_kill_qlen=>10, overload_kill_restart_after=>infinity}}, - ok = logger:set_handler_config(?MODULE, NewHConfig1), + ok = logger:update_handler_config(?MODULE, NewHConfig1), MRef1 = erlang:monitor(process, whereis(h_proc_name())), %% kill handler send_burst({n,100}, {spawn,4,0}, {chars,79}, notice), @@ -1161,7 +1282,7 @@ restart_after(Config) -> HConfig#{config=>DLHConfig#{overload_kill_enable=>true, overload_kill_qlen=>10, overload_kill_restart_after=>RestartAfter}}, - ok = logger:set_handler_config(?MODULE, NewHConfig2), + ok = logger:update_handler_config(?MODULE, NewHConfig2), Pid0 = whereis(h_proc_name()), MRef2 = erlang:monitor(process, Pid0), %% kill handler @@ -1194,7 +1315,7 @@ handler_requests_under_load(Config) -> drop_mode_qlen => 1000, flush_qlen => 2000, burst_limit_enable => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), Pid = spawn_link(fun() -> send_requests(?MODULE, 1, [{filesync,[]}, {info,[]}, {reset,[]}, @@ -1227,9 +1348,9 @@ send_requests(HName, TO, Reqs = [{Req,Res}|Rs]) -> Result = case Req of change_config -> - logger:set_handler_config(HName, logger_disk_log_h, - #{overload_kill_enable => - false}); + logger:update_handler_config(HName, logger_disk_log_h, + #{overload_kill_enable => + false}); Func -> logger_disk_log_h:Func(HName) end, @@ -1499,10 +1620,10 @@ tpl([{M,F,A}|Trace]) -> tpl([]) -> ok. -tracer({trace,_,call,{logger_disk_log_h,handle_cast,[Op|_]},Caller}, +tracer({trace,_,call,{logger_h_common,handle_cast,[Op|_]},Caller}, {Pid,[{Mod,Func,Op}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Op},Caller); -tracer({trace,_,call,{Mod=disk_log,Func=blog,[_,Data]},Caller}, {Pid,[{Mod,Func,Data}|Expected]}) -> +tracer({trace,_,call,{Mod=logger_disk_log_h,Func=disk_log_write,[_,_,Data]},Caller}, {Pid,[{Mod,Func,Data}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Data},Caller); tracer({trace,_,call,{Mod,Func,_},Caller}, {Pid,[{Mod,Func}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func},Caller); diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl index 3426567bbf..eb17a6d857 100644 --- a/lib/kernel/test/logger_std_h_SUITE.erl +++ b/lib/kernel/test/logger_std_h_SUITE.erl @@ -108,6 +108,7 @@ all() -> add_remove_instance_file1, add_remove_instance_file2, default_formatter, + filter_config, errors, formatter_fail, config_fail, @@ -135,11 +136,12 @@ all() -> mem_kill_new, mem_kill_std, restart_after, - handler_requests_under_load + handler_requests_under_load, + recreate_deleted_log ]. add_remove_instance_tty(_Config) -> - {error,{handler_not_added,{invalid_config,logger_std_h,{type,tty}}}} = + {error,{handler_not_added,{invalid_config,logger_std_h,#{type:=tty}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{type => tty}, filter_default=>log, @@ -204,6 +206,20 @@ default_formatter(_Config) -> match = re:run(Msg,"=NOTICE REPORT====.*\n"++M1,[{capture,none}]), ok. +filter_config(_Config) -> + ok = logger:add_handler(?MODULE,logger_std_h,#{}), + {ok,#{config:=HConfig}=Config} = logger:get_handler_config(?MODULE), + HConfig = maps:without([handler_pid,mode_tab],HConfig), + + FakeFullHConfig = HConfig#{handler_pid=>self(),mode_tab=>erlang:make_ref()}, + #{config:=HConfig} = + logger_std_h:filter_config(Config#{config=>FakeFullHConfig}), + ok. + +filter_config(cleanup,_Config) -> + logger:remove_handler(?MODULE), + ok. + errors(Config) -> Dir = ?config(priv_dir,Config), Log = filename:join(Dir,?FUNCTION_NAME), @@ -219,7 +235,7 @@ errors(Config) -> {error, {handler_not_added, - {invalid_config,logger_std_h,{type,faulty_type}}}} = + {invalid_config,logger_std_h,#{type:=faulty_type}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{type => faulty_type}}), @@ -293,25 +309,30 @@ formatter_fail(cleanup,_Config) -> logger:remove_handler(?MODULE). config_fail(_Config) -> - {error,{handler_not_added,{invalid_config,logger_std_h,{bad,bad}}}} = + {error,{handler_not_added,{invalid_config,logger_std_h,#{bad:=bad}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{bad => bad}, filter_default=>log, formatter=>{?MODULE,self()}}), {error,{handler_not_added,{invalid_config,logger_std_h, - {restart_type,bad}}}} = + #{restart_type:=bad}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{restart_type => bad}, filter_default=>log, formatter=>{?MODULE,self()}}), - {error,{handler_not_added,{invalid_levels,{_,1,_}}}} = + {error,{handler_not_added,{invalid_config,logger_std_h, + {invalid_levels,#{drop_mode_qlen:=1}}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{drop_mode_qlen=>1}}), - {error,{handler_not_added,{invalid_levels,{43,42,_}}}} = + {error,{handler_not_added,{invalid_config,logger_std_h, + {invalid_levels,#{sync_mode_qlen:=43, + drop_mode_qlen:=42}}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{sync_mode_qlen=>43, drop_mode_qlen=>42}}), - {error,{handler_not_added,{invalid_levels,{_,43,42}}}} = + {error,{handler_not_added,{invalid_config,logger_std_h, + {invalid_levels,#{drop_mode_qlen:=43, + flush_qlen:=42}}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{drop_mode_qlen=>43, flush_qlen=>42}}), @@ -319,18 +340,26 @@ config_fail(_Config) -> ok = logger:add_handler(?MODULE,logger_std_h, #{filter_default=>log, formatter=>{?MODULE,self()}}), - {error,{illegal_config_change,_,_}} = + {error,{illegal_config_change,logger_std_h,#{type:=_},#{type:=_}}} = logger:set_handler_config(?MODULE,config, #{type=>{file,"file"}}), - {error,{illegal_config_change,_,_}} = - logger:set_handler_config(?MODULE,id,bad), - {error,{invalid_levels,_}} = + + {error,{invalid_config,logger_std_h,{invalid_levels,_}}} = logger:set_handler_config(?MODULE,config, #{sync_mode_qlen=>100, flush_qlen=>99}), - {error,{invalid_config,logger_std_h,{filesync_rep_int,2000}}} = + {error,{invalid_config,logger_std_h,#{filesync_rep_int:=2000}}} = logger:set_handler_config(?MODULE, config, #{filesync_rep_int => 2000}), + + %% Read-only fields may (accidentially) be included in the change, + %% but it won't take effect + {ok,C} = logger:get_handler_config(?MODULE), + ok = logger:set_handler_config(?MODULE,config, + #{handler_pid=>self(), + mode_tab=>erlang:make_ref()}), + {ok,C} = logger:get_handler_config(?MODULE), + ok. config_fail(cleanup,_Config) -> @@ -445,8 +474,8 @@ reconfig(Config) -> filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), #{id := ?MODULE, - type := standard_io, - file_ctrl_pid := FileCtrlPid, + handler_state := #{type := standard_io, + file_ctrl_pid := FileCtrlPid}, sync_mode_qlen := ?SYNC_MODE_QLEN, drop_mode_qlen := ?DROP_MODE_QLEN, flush_qlen := ?FLUSH_QLEN, @@ -457,9 +486,26 @@ reconfig(Config) -> overload_kill_qlen := ?OVERLOAD_KILL_QLEN, overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE, overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER, - filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL} = + filesync_repeat_interval := no_repeat} = DefaultInfo = logger_std_h:info(?MODULE), + {ok, + #{config:= + #{type := standard_io, + sync_mode_qlen := ?SYNC_MODE_QLEN, + drop_mode_qlen := ?DROP_MODE_QLEN, + flush_qlen := ?FLUSH_QLEN, + burst_limit_enable := ?BURST_LIMIT_ENABLE, + burst_limit_max_count := ?BURST_LIMIT_MAX_COUNT, + burst_limit_window_time := ?BURST_LIMIT_WINDOW_TIME, + overload_kill_enable := ?OVERLOAD_KILL_ENABLE, + overload_kill_qlen := ?OVERLOAD_KILL_QLEN, + overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE, + overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER, + filesync_repeat_interval := no_repeat} = + DefaultHConf}} + = logger:get_handler_config(?MODULE), + ok = logger:set_handler_config(?MODULE, config, #{sync_mode_qlen => 1, drop_mode_qlen => 2, @@ -471,10 +517,10 @@ reconfig(Config) -> overload_kill_qlen => 100000, overload_kill_mem_size => 10000000, overload_kill_restart_after => infinity, - filesync_repeat_interval => no_repeat}), + filesync_repeat_interval => 5000}), #{id := ?MODULE, - type := standard_io, - file_ctrl_pid := FileCtrlPid, + handler_state := #{type := standard_io, + file_ctrl_pid := FileCtrlPid}, sync_mode_qlen := 1, drop_mode_qlen := 2, flush_qlen := 3, @@ -485,7 +531,77 @@ reconfig(Config) -> overload_kill_qlen := 100000, overload_kill_mem_size := 10000000, overload_kill_restart_after := infinity, - filesync_repeat_interval := no_repeat} = logger_std_h:info(?MODULE), + filesync_repeat_interval := no_repeat} = Info = logger_std_h:info(?MODULE), + + {ok,#{config := + #{type := standard_io, + sync_mode_qlen := 1, + drop_mode_qlen := 2, + flush_qlen := 3, + burst_limit_enable := false, + burst_limit_max_count := 10, + burst_limit_window_time := 10, + overload_kill_enable := true, + overload_kill_qlen := 100000, + overload_kill_mem_size := 10000000, + overload_kill_restart_after := infinity, + filesync_repeat_interval := no_repeat} = HConf}} = + logger:get_handler_config(?MODULE), + + ok = logger:update_handler_config(?MODULE, config, + #{flush_qlen => ?FLUSH_QLEN}), + {ok,#{config:=C1}} = logger:get_handler_config(?MODULE), + ct:log("C1: ~p",[C1]), + C1 = HConf#{flush_qlen => ?FLUSH_QLEN}, + + ok = logger:set_handler_config(?MODULE, config, #{sync_mode_qlen => 1}), + {ok,#{config:=C2}} = logger:get_handler_config(?MODULE), + ct:log("C2: ~p",[C2]), + C2 = DefaultHConf#{sync_mode_qlen => 1}, + + ok = logger:set_handler_config(?MODULE, config, #{drop_mode_qlen => 100}), + {ok,#{config:=C3}} = logger:get_handler_config(?MODULE), + ct:log("C3: ~p",[C3]), + C3 = DefaultHConf#{drop_mode_qlen => 100}, + + ok = logger:update_handler_config(?MODULE, config, #{sync_mode_qlen => 1}), + {ok,#{config:=C4}} = logger:get_handler_config(?MODULE), + ct:log("C4: ~p",[C4]), + C4 = DefaultHConf#{sync_mode_qlen => 1, + drop_mode_qlen => 100}, + + ok = logger:remove_handler(?MODULE), + + File = filename:join(Dir,lists:concat([?FUNCTION_NAME,".log"])), + ok = logger:add_handler(?MODULE, + logger_std_h, + #{config => #{type => {file,File}}, + filter_default=>log, + filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), + formatter=>{?MODULE,self()}}), + + {ok,#{config:=#{filesync_repeat_interval:=FSI}=FileHConfig}} = + logger:get_handler_config(?MODULE), + ok = logger:update_handler_config(?MODULE,config, + #{filesync_repeat_interval=>FSI+2000}), + {ok,#{config:=C5}} = logger:get_handler_config(?MODULE), + ct:log("C5: ~p",[C5]), + C5 = FileHConfig#{filesync_repeat_interval=>FSI+2000}, + + %% You are not allowed to actively set 'type' in runtime, since + %% this is a write once field. + {error, {illegal_config_change,logger_std_h,_,_}} = + logger:set_handler_config(?MODULE,config,#{type=>standard_io}), + {ok,#{config:=C6}} = logger:get_handler_config(?MODULE), + ct:log("C6: ~p",[C6]), + C6 = C5, + + %% ... but if you don't specify 'type', then set_handler_config shall + %% NOT reset it to its default value + ok = logger:set_handler_config(?MODULE,config,#{sync_mode_qlen=>1}), + {ok,#{config:=C7}} = logger:get_handler_config(?MODULE), + ct:log("C7: ~p",[C7]), + C7 = FileHConfig#{sync_mode_qlen=>1}, ok. reconfig(cleanup, _Config) -> @@ -510,7 +626,7 @@ file_opts(Config) -> filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), - #{type := OkType} = logger_std_h:info(?MODULE), + #{handler_state := #{type := OkType}} = logger_std_h:info(?MODULE), logger:notice(M1=?msg,?domain), ?check(M1), B1 = ?bin(M1), @@ -533,10 +649,8 @@ sync(Config) -> %% check repeated filesync happens start_tracer([{logger_std_h, write_to_dev, 5}, - {logger_std_h, sync_dev, 4}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"first\n">>}, - {logger_std_h, sync_dev}, {file,datasync}]), logger:notice("first", ?domain), @@ -545,10 +659,8 @@ sync(Config) -> %% check that explicit filesync is only done once start_tracer([{logger_std_h, write_to_dev, 5}, - {logger_std_h, sync_dev, 4}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"second\n">>}, - {logger_std_h, sync_dev}, {file,datasync}, {no_more,500} ]), @@ -561,21 +673,18 @@ sync(Config) -> %% check that if there's no repeated filesync active, %% a filesync is still performed when handler goes idle - logger:set_handler_config(?MODULE, config, - #{filesync_repeat_interval => no_repeat}), + ok = logger:update_handler_config(?MODULE, config, + #{filesync_repeat_interval => no_repeat}), no_repeat = maps:get(filesync_repeat_interval, logger_std_h:info(?MODULE)), %% The following timer is to make sure the time from last log %% ("second") to next ("third") is long enough, so the a flush is %% triggered by the idle timeout between "thrid" and "fourth". timer:sleep(?IDLE_DETECT_TIME_MSEC*2), start_tracer([{logger_std_h, write_to_dev, 5}, - {logger_std_h, sync_dev, 4}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"third\n">>}, - {logger_std_h, sync_dev}, {file,datasync}, {logger_std_h, write_to_dev, <<"fourth\n">>}, - {logger_std_h, sync_dev}, {file,datasync}]), logger:notice("third", ?domain), %% wait for automatic filesync @@ -587,17 +696,17 @@ sync(Config) -> %% switch repeated filesync on and verify that the looping works SyncInt = 1000, WaitT = 4500, - OneSync = {logger_std_h,handle_cast,repeated_filesync}, - %% receive 1 initial repeated_filesync, then 1 per sec - start_tracer([{logger_std_h,handle_cast,2}], - [OneSync || _ <- lists:seq(1, 1 + trunc(WaitT/SyncInt))]), + OneSync = {logger_h_common,handle_cast,repeated_filesync}, + %% receive 1 repeated_filesync per sec + start_tracer([{logger_h_common,handle_cast,2}], + [OneSync || _ <- lists:seq(1, trunc(WaitT/SyncInt))]), - logger:set_handler_config(?MODULE, config, - #{filesync_repeat_interval => SyncInt}), + ok = logger:update_handler_config(?MODULE, config, + #{filesync_repeat_interval => SyncInt}), SyncInt = maps:get(filesync_repeat_interval, logger_std_h:info(?MODULE)), timer:sleep(WaitT), - logger:set_handler_config(?MODULE, config, - #{filesync_repeat_interval => no_repeat}), + ok = logger:update_handler_config(?MODULE, config, + #{filesync_repeat_interval => no_repeat}), check_tracer(100), ok. sync(cleanup, _Config) -> @@ -652,7 +761,7 @@ sync_failure(Config) -> rpc:call(Node, ?MODULE, set_result, [file_datasync,ok]), SyncInt = 500, - ok = rpc:call(Node, logger, set_handler_config, + ok = rpc:call(Node, logger, update_handler_config, [?STANDARD_HANDLER, config, #{filesync_repeat_interval => SyncInt}]), Info = rpc:call(Node, logger_std_h, info, [?STANDARD_HANDLER]), @@ -718,7 +827,7 @@ op_switch_to_sync_file(Config) -> drop_mode_qlen => NumOfReqs+1, flush_qlen => 2*NumOfReqs, burst_limit_enable => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), %% TRecvPid = start_op_trace(), send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Lines = count_lines(Log), @@ -747,7 +856,7 @@ op_switch_to_sync_tty(Config) -> drop_mode_qlen => NumOfReqs+1, flush_qlen => 2*NumOfReqs, burst_limit_enable => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), send_burst({n,NumOfReqs}, seq, {chars,79}, notice), ok. op_switch_to_sync_tty(cleanup, _Config) -> @@ -770,7 +879,7 @@ op_switch_to_drop_file(Config) -> flush_qlen => Procs*NumOfReqs*Bursts, burst_limit_enable => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), %% It sometimes happens that the handler gets the %% requests in a slow enough pace so that dropping %% never occurs. Therefore, lets generate a number of @@ -807,7 +916,7 @@ op_switch_to_drop_tty(Config) -> flush_qlen => Procs*NumOfReqs+1, burst_limit_enable => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice), ok. op_switch_to_drop_tty(cleanup, _Config) -> @@ -832,7 +941,7 @@ op_switch_to_flush_file(Config) -> drop_mode_qlen => 300, flush_qlen => 300, burst_limit_enable => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), NumOfReqs = 1500, Procs = 10, Bursts = 10, @@ -879,7 +988,7 @@ op_switch_to_flush_tty(Config) -> drop_mode_qlen => 100, flush_qlen => 100, burst_limit_enable => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), NumOfReqs = 1000, Procs = 100, send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice), @@ -895,7 +1004,7 @@ limit_burst_disabled(Config) -> burst_limit_window_time => 2000, drop_mode_qlen => 200, flush_qlen => 300}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), NumOfReqs = 100, send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), @@ -915,7 +1024,7 @@ limit_burst_enabled_one(Config) -> burst_limit_window_time => 2000, drop_mode_qlen => 200, flush_qlen => 300}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), NumOfReqs = 100, send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), @@ -936,7 +1045,7 @@ limit_burst_enabled_period(Config) -> burst_limit_window_time => BurstTWin, drop_mode_qlen => 20000, flush_qlen => 20001}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), Windows = 3, Sent = send_burst({t,BurstTWin*Windows}, seq, {chars,79}, notice), @@ -956,7 +1065,7 @@ kill_disabled(Config) -> HConfig#{config=>StdHConfig#{overload_kill_enable=>false, overload_kill_qlen=>10, overload_kill_mem_size=>100}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), NumOfReqs = 100, send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), @@ -977,7 +1086,7 @@ qlen_kill_new(Config) -> overload_kill_qlen=>10, overload_kill_mem_size=>Mem0+50000, overload_kill_restart_after=>RestartAfter}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), MRef = erlang:monitor(process, Pid0), NumOfReqs = 100, Procs = 4, @@ -1011,7 +1120,7 @@ qlen_kill_std(_Config) -> %% File = lists:concat([?MODULE,"_",?FUNCTION_NAME,".log"]), %% Log = filename:join(Dir, File), %% Node = start_std_h_on_new_node(Config, ?FUNCTION_NAME, Log), - %% ok = rpc:call(Node, logger, set_handler_config, + %% ok = rpc:call(Node, logger, update_handler_config, %% [?STANDARD_HANDLER, config, %% #{overload_kill_enable=>true, %% overload_kill_qlen=>10, @@ -1028,7 +1137,7 @@ mem_kill_new(Config) -> overload_kill_qlen=>50000, overload_kill_mem_size=>Mem0+500, overload_kill_restart_after=>RestartAfter}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), MRef = erlang:monitor(process, Pid0), NumOfReqs = 100, Procs = 4, @@ -1067,7 +1176,7 @@ restart_after(Config) -> HConfig#{config=>StdHConfig#{overload_kill_enable=>true, overload_kill_qlen=>10, overload_kill_restart_after=>infinity}}, - ok = logger:set_handler_config(?MODULE, NewHConfig1), + ok = logger:update_handler_config(?MODULE, NewHConfig1), MRef1 = erlang:monitor(process, whereis(h_proc_name())), %% kill handler send_burst({n,100}, {spawn,4,0}, {chars,79}, notice), @@ -1082,14 +1191,15 @@ restart_after(Config) -> ct:pal("Handler state = ~p", [Info1]), ct:fail("Handler not dead! It should not have survived this!") end, - + {Log,_,_} = start_handler(?MODULE, ?FUNCTION_NAME, Config), RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER, + NewHConfig2 = HConfig#{config=>StdHConfig#{overload_kill_enable=>true, overload_kill_qlen=>10, overload_kill_restart_after=>RestartAfter}}, - ok = logger:set_handler_config(?MODULE, NewHConfig2), + ok = logger:update_handler_config(?MODULE, NewHConfig2), Pid0 = whereis(h_proc_name()), MRef2 = erlang:monitor(process, Pid0), %% kill handler @@ -1123,7 +1233,7 @@ handler_requests_under_load(Config) -> drop_mode_qlen => 1000, flush_qlen => 2000, burst_limit_enable => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), + ok = logger:update_handler_config(?MODULE, NewHConfig), Pid = spawn_link(fun() -> send_requests(?MODULE, 1, [{filesync,[]}, {info,[]}, {reset,[]}, @@ -1146,6 +1256,22 @@ handler_requests_under_load(Config) -> handler_requests_under_load(cleanup, _Config) -> ok = stop_handler(?MODULE). +recreate_deleted_log(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + logger:notice("first",?domain), + logger_std_h:filesync(?MODULE), + ok = file:rename(Log,Log++".old"), + logger:notice("second",?domain), + logger_std_h:filesync(?MODULE), + {ok,<<"first\n">>} = file:read_file(Log++".old"), + {ok,<<"second\n">>} = file:read_file(Log), + ok. +recreate_deleted_log(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +%%%----------------------------------------------------------------- +%%% send_requests(HName, TO, Reqs = [{Req,Res}|Rs]) -> receive {From,finish} -> @@ -1155,9 +1281,9 @@ send_requests(HName, TO, Reqs = [{Req,Res}|Rs]) -> Result = case Req of change_config -> - logger:set_handler_config(HName, config, - #{overload_kill_enable => - false}); + logger:update_handler_config(HName, config, + #{overload_kill_enable => + false}); Func -> logger_std_h:Func(HName) end, @@ -1167,8 +1293,8 @@ send_requests(HName, TO, Reqs = [{Req,Res}|Rs]) -> %%%----------------------------------------------------------------- %%% -start_handler(Name, TTY, Config) when TTY == standard_io; - TTY == standard_error-> +start_handler(Name, TTY, _Config) when TTY == standard_io; + TTY == standard_error-> ok = logger:add_handler(Name, logger_std_h, #{config => #{type => TTY}, @@ -1422,7 +1548,7 @@ start_op_trace() -> {ok,_} = dbg:p(self(), [c]), MS1 = dbg:fun2ms(fun([_]) -> return_trace() end), - {ok,_} = dbg:tp(logger_h_common, check_load, 1, MS1), + {ok,_} = dbg:tpl(logger_h_common, check_load, 1, MS1), {ok,_} = dbg:tpl(logger_h_common, flush_log_requests, 2, []), @@ -1496,7 +1622,9 @@ analyse(Msgs) -> start_tracer(Trace,Expected) -> Pid = self(), - FileCtrlPid = maps:get(file_ctrl_pid, logger_std_h:info(?MODULE)), + FileCtrlPid = maps:get(file_ctrl_pid, + maps:get(handler_state, + logger_std_h:info(?MODULE))), dbg:tracer(process,{fun tracer/2,{Pid,Expected}}), dbg:p(whereis(h_proc_name()),[c]), dbg:p(FileCtrlPid,[c]), @@ -1517,7 +1645,7 @@ tpl([{M,F,A}|Trace]) -> tpl([]) -> ok. -tracer({trace,_,call,{logger_std_h,handle_cast,[Op|_]}}, +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,_,_,_]}}, diff --git a/lib/kernel/vsn.mk b/lib/kernel/vsn.mk index df95174c9f..35e6a16a49 100644 --- a/lib/kernel/vsn.mk +++ b/lib/kernel/vsn.mk @@ -1 +1 @@ -KERNEL_VSN = 6.1 +KERNEL_VSN = 6.1.1 |