diff options
Diffstat (limited to 'lib/kernel')
48 files changed, 2594 insertions, 1505 deletions
diff --git a/lib/kernel/doc/src/Makefile b/lib/kernel/doc/src/Makefile index 82869d7b15..29dc73a523 100644 --- a/lib/kernel/doc/src/Makefile +++ b/lib/kernel/doc/src/Makefile @@ -42,6 +42,7 @@ XML_REF3_FILES = application.xml \ disk_log.xml \ erl_boot_server.xml \ erl_ddll.xml \ + erl_epmd.xml \ erl_prim_loader_stub.xml \ erlang_stub.xml \ error_handler.xml \ diff --git a/lib/kernel/doc/src/config.xml b/lib/kernel/doc/src/config.xml index fdb2d29f63..8850c1736b 100644 --- a/lib/kernel/doc/src/config.xml +++ b/lib/kernel/doc/src/config.xml @@ -37,10 +37,10 @@ data in the system configuration file <c>Name.config</c>.</p> <p>Configuration parameter values in the configuration file override the values in the application resource files (see - <seealso marker="app"><c>app(4)</c></seealso>. + <seealso marker="app"><c>app(4)</c></seealso>). The values in the configuration file can be overridden by command-line flags (see - <seealso marker="erts:erl"><c>erts:erl(1)</c></seealso>.</p> + <seealso marker="erts:erl"><c>erts:erl(1)</c></seealso>).</p> <p>The value of a configuration parameter is retrieved by calling <c>application:get_env/1,2</c>.</p> </description> diff --git a/lib/kernel/doc/src/erl_epmd.xml b/lib/kernel/doc/src/erl_epmd.xml new file mode 100644 index 0000000000..8b076cd2d7 --- /dev/null +++ b/lib/kernel/doc/src/erl_epmd.xml @@ -0,0 +1,104 @@ +<?xml version="1.0" encoding="utf-8" ?> +<!DOCTYPE erlref SYSTEM "erlref.dtd"> + +<erlref> + <header> + <copyright> + <year>2018</year><year>2018</year> + <holder>Ericsson AB. All Rights Reserved.</holder> + </copyright> + <legalnotice> + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. + + </legalnotice> + + <title>erl_epmd</title> + <prepared>Timmo Verlaan</prepared> + <docno>1</docno> + <date>2018-02-19</date> + <rev>A</rev> + </header> + <module>erl_epmd</module> + <modulesummary> + Erlang interface towards epmd + </modulesummary> + <description> + <p>This module communicates with the EPMD daemon, see <seealso + marker="erts:epmd">epmd</seealso>. To implement your own epmd module please + see <seealso marker="erts:alt_disco">ERTS User's Guide: How to Implement an + Alternative Service Discovery for Erlang Distribution</seealso></p> + </description> + + <funcs> + <func> + <name name="start_link" arity="0"/> + <fsummary>Callback for erl_distribution supervisor.</fsummary> + <desc> + <p>This function is invoked as this module is added as a child of the + <c>erl_distribution</c> supervisor.</p> + </desc> + </func> + + <func> + <name name="register_node" arity="2"/> + <name name="register_node" arity="3"/> + <fsummary>Registers the node with <c>epmd</c>.</fsummary> + <desc> + <p>Registers the node with <c>epmd</c> and tells epmd what port will be + used for the current node. It returns a creation number. This number is + incremented on each register to help with identifying if a node is + reconnecting to epmd.</p> + </desc> + </func> + + <func> + <name name="port_please" arity="2"/> + <name name="port_please" arity="3"/> + <fsummary>Returns the port number for a given node.</fsummary> + <desc> + <p>Requests the distribution port for the given node of an EPMD + instance. Together with the port it returns a distribution protocol + version which has been 5 since Erlang/OTP R6.</p> + </desc> + </func> + + <func> + <name name="address_please" arity="3"/> + <fsummary>Returns address and port.</fsummary> + <desc> + <p>Called by the distribution module. Resolves the <c>Host</c> to an IP + address.</p> + <p>Another epmd module may return port and distribution protocol version + as well.</p> + </desc> + </func> + + <func> + <name name="names" arity="1"/> + <fsummary>Names of Erlang nodes at a host.</fsummary> + <desc> + <p>Called by <seealso marker="net_adm"><c>net_adm:names/0</c></seealso>. + <c>Host</c> defaults to the localhost. Returns the names and associated + port numbers of the Erlang nodes that <c>epmd</c> registered at the + specified host. Returns <c>{error, address}</c> if <c>epmd</c> is not + operational.</p> + <p><em>Example:</em></p> + <pre> +(arne@dunn)1> <input>erl_epmd:names(localhost).</input> +{ok,[{"arne",40262}]}</pre> + </desc> + </func> + </funcs> + +</erlref> + diff --git a/lib/kernel/doc/src/error_logger.xml b/lib/kernel/doc/src/error_logger.xml index cb6165c73e..c9fe9484e4 100644 --- a/lib/kernel/doc/src/error_logger.xml +++ b/lib/kernel/doc/src/error_logger.xml @@ -181,17 +181,21 @@ ok</pre> <func> <name name="get_format_depth" arity="0"/> <fsummary>Get the value of the Kernel application variable - <c>logger_format_depth</c>.</fsummary> + <c>error_logger_format_depth</c>.</fsummary> <desc> <p>Returns <c>max(10, Depth)</c>, where <c>Depth</c> is the - value of - <seealso marker="kernel_app#logger_format_depth"> - logger_format_depth</seealso> + value of <c>error_logger_format_depth</c> in the Kernel application, if Depth is an integer. Otherwise, <c>unlimited</c> is returned.</p> - <p>For backwards compatibility, the value - of <c>error_logger_format_depth</c> is used - if <c>logger_format_depth</c> is not set.</p> + <note> + <p>The <c>error_logger_format_depth</c> variable + is <seealso marker="kernel_app#deprecated-configuration-parameters"> + deprecated</seealso> since + the <seealso marker="logger">Logger API</seealso> was + introduced in OTP-21. The variable, and this function, are + kept for backwards compatibility since they still might be + used by legacy report handlers.</p> + </note> </desc> </func> <func> diff --git a/lib/kernel/doc/src/kernel_app.xml b/lib/kernel/doc/src/kernel_app.xml index f96d946a5d..7cd05dab14 100644 --- a/lib/kernel/doc/src/kernel_app.xml +++ b/lib/kernel/doc/src/kernel_app.xml @@ -122,21 +122,6 @@ application. For more information about configuration parameters, see file <seealso marker="app"><c>app(4)</c></seealso>.</p> <taglist> - <tag><c>browser_cmd = string() | {M,F,A}</c></tag> - <item> - <p>When pressing the <em>Help</em> button in a tool such as Debugger, - the help text (an HTML file <c>File</c>) is by default - displayed in a Netscape browser, which is required to be - operational. This parameter can be used to change the command for - how to display the help text if another browser than Netscape - is preferred, or if another platform than Unix or Windows is - used.</p> - <p>If set to a string <c>Command</c>, the command - <c>"Command File"</c> is evaluated using - <seealso marker="os#cmd/1"><c>os:cmd/1</c></seealso>.</p> - <p>If set to a module-function-args tuple, <c>{M,F,A}</c>, - the call <c>apply(M,F,[File|A])</c> is evaluated.</p> - </item> <tag><c>distributed = [Distrib]</c></tag> <item> <p>Specifies which applications that are distributed and on which @@ -180,78 +165,33 @@ <p>Permissions are described in <seealso marker="application#permit/2"><c>application:permit/2</c></seealso>.</p> </item> - <tag><c>logger_dest = Value</c></tag> + <tag><marker id="logger"/><c>logger = [Config]</c></tag> <item> - <p><c>Value</c> is one of:</p> - <taglist> - <tag><c>tty</c></tag> - <item><p>Installs the standard handler, <seealso marker="logger_std_h"> - <c>logger_std_h(3)</c></seealso>, with <c>type</c> set - to <c>standard_io</c>. This is the default - option.</p></item> - <tag><c>{file, FileName}</c></tag> - <item><p>Installs the standard handler, <seealso marker="logger_std_h"> - <c>logger_std_h(3)</c></seealso>, with <c>type</c> set - to <c>{file, FileName}</c>, where <c>FileName</c> - is a string. The file is opened with encoding UTF-8.</p></item> - <tag><c>{disk_log, FileName}</c></tag> - <item><p>Installs the disk_log handler, <seealso marker="logger_disk_log_h"> - <c>logger_disk_log_h(3)</c></seealso>, with <c>file</c> set - to <c>FileName</c> (a string), and possibly other disk_log - parameters set by the environment variables - <c>logger_disk_log_type</c>, <c>logger_disk_log_maxfiles</c> and - <c>logger_disk_log_maxbytes</c>, - see <seealso marker="#disk_log_vars">below</seealso>. The - file is opened with encoding UTF-8.</p></item> - <tag><c>false</c></tag> - <item> - <p>No standard handler is installed, but - the initial, primitive handler is kept, printing - raw event messages to <c>tty</c>.</p> - </item> - <tag><c>silent</c></tag> - <item> - <p>No standard handler is started, and the initial, - primitive handler is removed.</p> - </item> - </taglist> + <p>Specifies how <seealso marker="logger"><c>logger</c></seealso> should be + configured.</p> + <p>For more details and examples, see the <seealso marker="logger_chapter#logger"> + Configuration</seealso> section in the <seealso marker="logger_chapter"> + Logger User's Guide</seealso>. + </p> </item> - <tag><c>logger_level = Level</c></tag> + <tag><marker id="logger_level"/><c>logger_level = Level</c></tag> <item> - <p><c>Value = emergency | alert | critical | error | warning | + <p><c>Level = emergency | alert | critical | error | warning | notice | info | debug</c></p> <p>This parameter specifies which log levels to log. The specified level, and all levels that are more severe, will be logged.</p> - <p>This configuration parameter is used both for the global - logger level, and for the standard handler started by - the Kernel application (see <c>logger_dest</c> variable above).</p> <p>The default value is <c>info</c>.</p> - </item> - <tag><marker id="disk_log_vars"/> - <c>logger_disk_log_type = halt | wrap</c></tag> - <item/> - <tag><c>logger_disk_log_maxfiles = integer()</c></tag> - <item/> - <tag><c>logger_disk_log_maxbytes = integer()</c></tag> - <item> - <p>If <c>logger_dest</c> is set to {disk_log,File}, then these - parameters specify the configuration to use when opening the - disk log file. They specify the type of disk log, the - maximum number of files (if the type is wrap) and the - maximum size of each file, respectively.</p> - <p>The default values are:</p> - <code> -logger_disk_log_type = wrap -logger_disk_log_maxfiles = 10 -logger_disk_log_maxbytes = 1048576</code> + <p>To change the global log level at run-time, use + <seealso marker="logger#set_logger_config/2"> + <c>logger:set_logger_config(level, error)</c></seealso>.</p> </item> <tag><marker id="logger_sasl_compatible"/> <c>logger_sasl_compatible = boolean()</c></tag> <item> - <p>If this parameter is set to true, then the logger handler - started by kernel will not log any progress-, crash-, or - supervisor reports. If the SASL application is started, + <p>If this parameter is set to true, then the <c>default</c> logger handler + will not log any progress-, crash-, or supervisor reports. + If the SASL application is started, these log events will be sent to a second handler instance named <c>sasl_h</c>, according to values of the SASL environment variables <c>sasl_error_logger</c> @@ -262,6 +202,8 @@ logger_disk_log_maxbytes = 1048576</code> <p>See chapter <seealso marker="logger_chapter#compatibility">Backwards compatibility with error_logger</seealso> for more information about handling of the so called SASL reports.</p> + <note><p>This configuration option only effects the <c>default</c> + and <c>sasl</c> handler. Any other handlers are uneffected.</p></note> </item> <tag><marker id="logger_log_progress"/> <c>logger_log_progress = boolean()</c></tag> @@ -269,51 +211,13 @@ logger_disk_log_maxbytes = 1048576</code> <p>If <c>logger_sasl_compatible = false</c>, then <c>logger_log_progress</c> specifies if progress reports from <c>supervisor</c> - and <c>application_controller</c> shall be logged or - not.</p> + and <c>application_controller</c> shall be logged by the + default logger.</p> <p>If <c>logger_sasl_compatible = true</c>, then <c>logger_log_progress</c> is ignored.</p> - </item> - <tag><marker id="logger_format_depth"/> - <c>logger_format_depth = Depth</c></tag> - <item> - <p>Can be used to limit the size of the - formatted output from the logger handlers.</p> - - <p><c>Depth</c> is a positive integer representing the maximum - depth to which terms are printed by the logger - handlers included in OTP. This - configuration parameter is used by the default formatter, - <seealso marker="logger_formatter"><c>logger_formatter(3)</c></seealso>, - unless the formatter's <c>depth</c> parameter is explicitly set. - (If you have implemented your own formatter, this configuration - parameter has no effect on that.)</p> - - <p><c>Depth</c> is used as follows: Format strings - received by the formatter are rewritten. - The format controls <c>~p</c> and <c>~w</c> are replaced with - <c>~P</c> and <c>~W</c>, respectively, and <c>Depth</c> is - used as the depth parameter. For details, see - <seealso marker="stdlib:io#format/2"><c>io:format/2</c></seealso> - in STDLIB.</p> - - <note><p>A reasonable starting value for <c>Depth</c> is - <c>30</c>. We recommend to test crashing various processes in your - application, examine the logs from the crashes, and then - increase or decrease the value.</p></note> - </item> - <tag><c>logger_max_size = integer() | unlimited</c></tag> - <item> - <p>This parameter specifies a hard maximum size limit (number - of characters) each log event can have when printed by the - default logger formatter. If the resulting string after - formatting an event is bigger than this, it will be - truncated before printed to the handler's destination.</p> - </item> - <tag><c>logger_utc = boolean()</c></tag> - <item> - <p>If set to <c>true</c>, the default formatter will display - all dates in Universal Coordinated Time.</p> + <p>The default value is <c>false</c></p> + <note><p>This configuration option only effects the <c>default</c> + and <c>sasl</c> handler. Any other handlers are uneffected.</p></note> </item> <tag><c>global_groups = [GroupTuple]</c></tag> <item> @@ -587,9 +491,20 @@ MaxT = TickTime + TickTime / 4</code> variables are not set.</p> <taglist> <tag><c>error_logger</c></tag> - <item>Replaced by <c>logger_dest</c></item> + <item>Replaced by setting the type of the default + <seealso marker="logger_std_h#type"><c>logger_std_h</c></seealso> + to the same value. Example: + <code type="none"> +erl -kernel logger '[{handler,default,logger_std_h,#{logger_std_h=>#{type=>{file,"/tmp/erlang.log"}}}}]' + </code> + </item> <tag><c>error_logger_format_depth</c></tag> - <item>Replaced by <c>logger_format_depth</c></item> + <item>Replaced by setting the <seealso marker="logger_formatter#depth"><c>depth</c></seealso> + parameter of the default handlers formatter. Example: + <code type="none"> +erl -kernel logger '[{handler,default,logger_std_h,#{formatter=>{logger_formatter,#{legacy_header=>true,template=>[{logger_formatter,header},"\n",msg,"\n"],depth=>10}}}]' + </code> + </item> </taglist> <p>See <seealso marker="logger_chapter#compatibility">Backwards compatibility with error_logger</seealso> for more diff --git a/lib/kernel/doc/src/logger.xml b/lib/kernel/doc/src/logger.xml index d901454e62..2ee1059df8 100644 --- a/lib/kernel/doc/src/logger.xml +++ b/lib/kernel/doc/src/logger.xml @@ -33,10 +33,49 @@ <file>logger.xml</file> </header> <module>logger</module> - <modulesummary>API module for the logger application.</modulesummary> + <modulesummary>API module for the logger.</modulesummary> <description> - + <p> + This module is the main logger API. It contains functions that allow + application to use a single log API and the system to manage those log + events independently. To log events the logger + <seealso marker="#macros">macros</seealso> should be used. For instance, + to log a new error log event:</p> + <code> +?LOG_ERROR("error happened because: ~p",[Reason]). %% With macro +logger:error("error happened because: ~p",[Reason]). %% Without macro + </code> + <p>This log event will then be sent to the configured log handlers which + by default means that it will be printed to the console. If you want + your systems logs to be printed to a file instead of the console you + have to configure the default handler to do so. The simplest way is + to include the following in your <seealso marker="config"><c>sys.config</c></seealso>.</p> + <code> +[{kernel, + [{logger, + [{handler,default,logger_std_h, + #{logger_std_h=>#{type=>{file,"path/to/file.log"}}}}]}]}]. + </code> + <p> + For more information about: + </p> + <list type="bulleted"> + <item>how to use the API, + see <seealso marker="logger_chapter">the User's Guide</seealso>.</item> + <item>how to configure logger, + see the <seealso marker="logger_chapter#configuration">Configuration</seealso> + section in the User's Guide.</item> + <item>the convinience macros in logger.hrl, + see <seealso marker="#macros">the macro section</seealso>.</item> + <item>what the builtin formatter can do, + see <seealso marker="logger_formatter">logger_formatter</seealso>.</item> + <item>what the builtin handlers can do, + see <seealso marker="logger_std_h">logger_std_h</seealso> and + <seealso marker="logger_disk_log_h">logger_disk_log_h</seealso>.</item> + <item>what builtin filters are available, + see <seealso marker="logger_filters">logger_filters</seealso>.</item> + </list> </description> <datatypes> @@ -348,16 +387,16 @@ <code><![CDATA[1> logger:i(print). Current logger configuration: Level: info - FilterDefault: log + Filter Default: log Filters: Handlers: - Id: logger_std_h + Id: default Module: logger_std_h Level: info Formatter: Module: logger_formatter - Config: #{template => [{logger_formatter,header},"\n",msg,"\n"], - legacy_header => true} + Config: #{legacy_header => true,single_line => false, + template => [{logger_formatter,header},"\n",msg,"\n"]} Filter Default: stop Filters: Id: stop_progress @@ -489,7 +528,7 @@ Current logger configuration: <desc> <p>Add a handler with the given configuration.</p> <p><c><anno>HandlerId</anno></c> is a unique identifier which - must be used in all subsequent calls reffering to this + must be used in all subsequent calls referring to this handler.</p> </desc> </func> @@ -550,17 +589,68 @@ Current logger configuration: </func> <func> + <name name="add_handlers" arity="1" clause_i="1"/> + <fsummary>Setup logger handlers from the applications configuration parameters.</fsummary> + <desc> + <p>Reads the application configuration parameter <c>logger</c> and + calls <c>logger:add_handlers/1</c> with it contents.</p> + </desc> + </func> + + <func> + <name name="add_handlers" arity="1" clause_i="2"/> + <fsummary>Setup logger handlers.</fsummary> + <type name="config_handler"/> + <desc> + <p>This function should be used by custom logger handlers to make + configuration consistent no matter which handler the system uses. + Normal usage to to add a call to <c>logger:add_handlers/1</c> + just after the processes that the handler needs are started + and pass the applications logger config as an argument. Eg.</p> + <code> +-behaviour(application). +start(_, []) -> + case supervisor:start_link({local, my_sup}, my_sup, []) of + {ok, Pid} -> + ok = logger:add_handlers(my_app), + {ok, Pid, []}; + Error -> Error + end.</code> + <p>This will read the <c>logger</c> configuration parameter from + the handler application and start the configured handlers. The contents + of the configuration use the same rules as the + <seealso marker="logger_chapter#handler-configuration">logger handler configuration</seealso>. + </p> + <p>If the handler is meant to replace the default handler the kernels + default handlers have to be disabled before the new handler is added. + A <c>sys.config</c> file that disables the kernel handler and adds + a custom handler could looks like this:</p> + <code> +[{kernel, + [{logger, + %% Disable the default kernel handler + [{handler,default,undefined}]}]}, + {my_app, + [{logger, + %% Enable this handler as the default + [{handler,default,my_handler,#{}}]}]}]. + </code> + </desc> + </func> + + <func> <name name="set_logger_config" arity="1"/> <fsummary>Set configuration data for the logger.</fsummary> <desc> <p>Set configuration data for the logger. This overwrites the current logger configuration.</p> <p>To modify the existing configuration, - use <seealso marker="#set_logger_config-2"><c>set_logger_config/2</c> - </seealso>, or read the current configuration + use <seealso marker="#update_logger_config-1"> + <c>update_logger_config/1</c></seealso>, or, if a more + complex merge is needed, read the current configuration with <seealso marker="#get_logger_config-0"><c>get_logger_config/0</c> - </seealso>, then merge in your added or updated - associations before writing it back.</p> + </seealso>, then do the merge before writing the new + configuration back with this function.</p> <p>If a key is removed compared to the current configuration, the default value is used.</p> </desc> @@ -573,7 +663,23 @@ Current logger configuration: <p>Add or update configuration data for the logger. If the given <c><anno>Key</anno></c> already exists, its associated value will be changed to <c><anno>Value</anno></c>. If it - doesn't exist, it will be added.</p> + does not exist, it will be added.</p> + </desc> + </func> + + <func> + <name name="update_logger_config" arity="1"/> + <fsummary>Update configuration data for the logger.</fsummary> + <desc> + <p>Update configuration data for the logger. This function + behaves as if it was implemented as follows:</p> + <code type="erl"> +{ok,Old} = logger:get_logger_config(), +logger:set_logger_config(maps:merge(Old,Config)). + </code> + <p>To overwrite the existing configuration without any merge, + use <seealso marker="#set_logger_config-1"><c>set_logger_config/1</c> + </seealso>.</p> </desc> </func> @@ -584,11 +690,12 @@ Current logger configuration: <p>Set configuration data for the specified handler. This overwrites the current handler configuration.</p> <p>To modify the existing configuration, - use <seealso marker="#set_handler_config-3"><c>set_handler_config/3</c> - </seealso>, or read the current configuration + use <seealso marker="#update_handler_config-2"> + <c>update_handler_config/2</c></seealso>, or, if a more + complex merge is needed, read the current configuration with <seealso marker="#get_handler_config-1"><c>get_handler_config/1</c> - </seealso>, then merge in your added or updated - associations before writing it back.</p> + </seealso>, then do the merge before writing the new + configuration back with this function.</p> <p>If a key is removed compared to the current configuration, and the key is know by Logger, the default value is used. If it is a custom key, then it is up to the handler @@ -605,12 +712,28 @@ Current logger configuration: <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 <c><anno>Value</anno></c>. If it doesn't exist, it will + to <c><anno>Value</anno></c>. If it does not exist, it will be added.</p> </desc> </func> <func> + <name name="update_handler_config" arity="2"/> + <fsummary>Update configuration data for the specified handler.</fsummary> + <desc> + <p>Update configuration data for the specified handler. This function + behaves as if it was implemented as follows:</p> + <code type="erl"> +{ok,{_,Old}} = logger:get_handler_config(HandlerId), +logger:set_handler_config(HandlerId,maps:merge(Old,Config)). + </code> + <p>To overwrite the existing configuration without any merge, + use <seealso marker="#set_handler_config-2"><c>set_handler_config/2</c> + </seealso>.</p> + </desc> + </func> + + <func> <name name="compare_levels" arity="2"/> <fsummary>Compare the severity of two log levels.</fsummary> <desc> @@ -650,7 +773,7 @@ Current logger configuration: <p>If process metadata exists for the current process, this function behaves as if it was implemented as follows:</p> <code type="erl"> -logger:set_process_metadata(maps:merge(logger:get_process_metadata(),Meta)) +logger:set_process_metadata(maps:merge(logger:get_process_metadata(),Meta)). </code> <p>If no process metadata exists, the function behaves as <seealso marker="#set_process_metadata-1"> diff --git a/lib/kernel/doc/src/logger_chapter.xml b/lib/kernel/doc/src/logger_chapter.xml index 519df2ba48..4232429589 100644 --- a/lib/kernel/doc/src/logger_chapter.xml +++ b/lib/kernel/doc/src/logger_chapter.xml @@ -136,7 +136,7 @@ <item> <p>Filters can be set on the logger or on a handler. Logger filters are applied first, and if passed, the handler filters - for each handler are applied. The handler plugin is only + for each handler are applied. The handler callback is only called if all handler filters for the handler in question also pass.</p> @@ -159,7 +159,7 @@ <code>format(Log,Extra) -> unicode:chardata()</code> - <p>The formatter plugin is called by each handler, and the + <p>The formatter callback is called by each handler, and the returned string can be printed to the handler's destination (stdout, file, ...).</p> </item> @@ -214,8 +214,8 @@ <tag><c>logger_filters:level/2</c></tag> <item> <p>This filter provides a way of filtering log events based - on the log level. See <seealso marker="logger_filters#domain-2"> - <c>logger_filters:domain/2</c></seealso></p> + on the log level. See <seealso marker="logger_filters#level-2"> + <c>logger_filters:level/2</c></seealso></p> </item> <tag><c>logger_filters:progress/2</c></tag> @@ -248,11 +248,97 @@ <section> <title>Configuration</title> + <p>Logger can be configured either when the system starts through + <seealso marker="config">configuration parameters</seealso>, + or at run-time by using the <seealso marker="logger">logger</seealso> + API. The recommended approach is to do the initial configuration in + the <c>sys.config</c> file and then use the API when some configuration + has to be changed at run-time, such as the logging level.</p> + <section> - <title>Application environment variables</title> - <p>See <seealso marker="kernel_app#configuration">Kernel(6)</seealso> for - information about the application environment variables that can - be used for configuring logger.</p> + <title>Application configuration parameters</title> + <p>Logger is best configured by using the configuration parameters + of kernel. There are three possible configuration parameters: + <seealso marker="#logger"><c>logger</c></seealso>, + <seealso marker="kernel_app#logger_level"><c>logger_level</c></seealso>, + <seealso marker="kernel_app#logger_sasl_compatible"><c>logger_sasl_compatible</c></seealso> and + <seealso marker="kernel_app#logger_log_progress"><c>logger_log_progress</c></seealso>. + logger_level, logger_sasl_compatible and logger_log_progress are described in the + <seealso marker="kernel_app#configuration">Kernel Configuration</seealso>, + while <c>logger</c> is described below.</p> + <section> + <marker id="logger"/> + <title>logger</title> + <p>The <c>logger</c> application configuration parameter is used to configure + three different logger aspects; handlers, logger filters and module levels. + The configuration is a list containing tagged tuples that look like this:</p> + <taglist> + <tag><c>DisableHandler = {handler,default,undefined}</c></tag> + <item>Disable the default handler. This will allow another application + to add its own default handler. See <seealso marker="logger#add_handlers/1"> + <c>logger:add_handlers/1</c></seealso> for more details.</item> + <tag><c>AddHandler = {handler,HandlerId,Module,HandlerConfig}</c></tag> + <item>Add a handler as if <seealso marker="logger:add_handler/3"> + <c>logger:add_handler(HandlerId,Module,HandlerConfig)</c></seealso> had been + called.</item> + <tag><c>Filters = {filters, FilterDefault, [Filter]}</c><br/> + <c>FilterDefault = log | stop</c><br/> + <c>Filter = {FilterId, {FilterFun, FilterConfig}}</c></tag> + <item>Add the specified <seealso marker="logger#add_logger_filter/2"> + logger filters</seealso>. Only one entry is allowed of this option.</item> + <tag><c>ModuleLevel</c></tag> + <item><c>{module_level, Level, [Module]}</c>, + this option configures the <seealso marker="logger#set_module_level/2"> + module log level</seealso> to be used. It is possible to have multiple + <c>module_level</c> entries.</item> + </taglist> + <p>Examples:</p> + <list> + <item> + <p>Output logs into a the file "logs/erlang.log"</p> + <code> +[{kernel, + [{logger, + [{handler, default, logger_std_h, + #{ logger_std_h => #{ type => {file,"log/erlang.log"}}}}]}]}]. + </code> + </item> + <item> + <p>Output logs in single line format</p> + <code> +[{kernel, + [{logger, + [{handler, default, logger_std_h, + #{ formatter => { logger_formatter,#{ single_line => true}}}}]}]}]. + </code> + </item> + <item> + <p>Add the pid to each log event</p> + <code> +[{kernel, + [{logger, + [{handler, default, logger_std_h, + #{ formatter => { logger_formatter, + #{ template => [time," ",pid," ",msg,"\n"]}} + }}]}]}]. + </code> + </item> + <item> + <p>Use a different file for debug logging</p> + <code> +[{kernel, + [{logger, + [{handler, default, logger_std_h, + #{ level => error, + logger_std_h => #{ type => {file, "log/erlang.log"}}}}, + {handler, info, logger_std_h, + #{ level => debug, + logger_std_h => #{ type => {file, "log/debug.log"}}}} + ]}]}]. + </code> + </item> + </list> + </section> </section> <section> @@ -330,6 +416,13 @@ <c>logger_formatter</c></seealso>, and <c>Extra</c> is it's configuration map.</p> </item> + <tag>HandlerConfig, <c>term() = term()</c></tag> + <item> + Any keys not listed above are considered to be handler specific + configuration. The configuration of the Kernel handlers can be found in + <seealso marker="logger_std_h"><c>logger_std_h</c></seealso> and + <seealso marker="logger_disk_log_h"><c>logger_disk_log_h</c></seealso>. + </item> </taglist> <p>Note that <c>level</c> and <c>filters</c> are obeyed by @@ -425,7 +518,7 @@ error_logger:add_report_handler/1,2. handler named <c>sasl_h</c>.</p> <p>All SASL reports have a metadata field <c>domain=>[beam,erlang,otp,sasl]</c>, which can be - used, for example, by filters to to stop or allow the + used, for example, by filters to stop or allow the events.</p> </item> </taglist> @@ -661,10 +754,20 @@ do_log(Fd,Log,#{formatter:={FModule,FConfig}}) -> </item> </taglist> - <p>For the overload protection algorithm to work properly, it is a - requirement that:</p> + <p>For the overload protection algorithm to work properly, it is + required that:</p> + + <p><c>toggle_sync_qlen =< drop_new_reqs_qlen =< flush_reqs_qlen</c></p> + + <p>and that:</p> + + <p><c>drop_new_reqs_qlen > 1</c></p> - <p><c>toggle_sync_qlen < drop_new_reqs_qlen < flush_reqs_qlen</c></p> + <p>If <c>toggle_sync_qlen</c> is set to <c>0</c>, the handler will handle all + requests synchronously. Setting the value of <c>toggle_sync_qlen</c> to the same + as <c>drop_new_reqs_qlen</c>, disables the synchronous mode. Likewise, setting + the value of <c>drop_new_reqs_qlen</c> to the same as <c>flush_reqs_qlen</c>, + disables the drop mode.</p> <p>During high load scenarios, the length of the handler message queue rarely grows in a linear and predictable way. Instead, whenever the diff --git a/lib/kernel/doc/src/logger_disk_log_h.xml b/lib/kernel/doc/src/logger_disk_log_h.xml index 90cc4fec30..440ae28e5d 100644 --- a/lib/kernel/doc/src/logger_disk_log_h.xml +++ b/lib/kernel/doc/src/logger_disk_log_h.xml @@ -121,11 +121,11 @@ logger:add_handler(my_disk_log_h, logger_disk_log_h, #{filesync_repeat_interval => 1000}}). </code> <p>In order to use the disk_log handler instead of the default standard - handler when starting en Erlang node, use the kernel configuration parameter - <seealso marker="kernel_app#configuration"><c>logger_dest</c></seealso> with - value <c>{disk_log,FileName}</c>. Example:</p> + handler when starting en Erlang node, change the Kernel default logger to + use disk_log. Example:</p> <code type="none"> -erl -kernel logger_dest '{disk_log,"./system_disk_log"}' +erl -kernel logger '[{handler,default,logger_disk_log_h, + #{ disk_log_opts => #{ file => "./system_disk_log"}}}]' </code> </description> diff --git a/lib/kernel/doc/src/logger_filters.xml b/lib/kernel/doc/src/logger_filters.xml index c34ec7d14c..1bbae8be21 100644 --- a/lib/kernel/doc/src/logger_filters.xml +++ b/lib/kernel/doc/src/logger_filters.xml @@ -78,6 +78,10 @@ <tag><c><anno>Compare</anno> = equals</c></tag> <item><p>The filter matches if <c>Domain</c> is equal to <c>MatchDomain</c>.</p></item> + <tag><c><anno>Compare</anno> = differs</c></tag> + <item><p>The filter matches if <c>Domain</c> differs + from <c>MatchDomain</c>, or if there is no domain field + in metadata.</p></item> <tag><c><anno>Compare</anno> = no_domain</c></tag> <item><p>The filter matches if there is no domain field in metadata. In this case <c><anno>MatchDomain</anno></c> shall diff --git a/lib/kernel/doc/src/logger_formatter.xml b/lib/kernel/doc/src/logger_formatter.xml index 7df4c88f40..370d61d338 100644 --- a/lib/kernel/doc/src/logger_formatter.xml +++ b/lib/kernel/doc/src/logger_formatter.xml @@ -66,7 +66,7 @@ be truncated by the <c>max_size</c> parameter.</p> </note> </item> - <tag><c>depth = pos_integer() | unlimited</c></tag> + <tag><marker id="depth"/><c>depth = pos_integer() | unlimited</c></tag> <item> <p>A positive integer representing the maximum depth to which terms shall be printed by this formatter. Format @@ -155,11 +155,40 @@ and <c>single_line</c>. See <seealso marker="#default_templates">Default Templates</seealso> for more information</p> </item> - <tag><c>utc = boolean()</c></tag> + <tag><c>time_designator = byte()</c></tag> <item> - <p>If set to <c>true</c>, all dates are displayed in Universal - Coordinated Time.</p> - <p>Default is <c>false</c>.</p> + <p>Timestamps are formatted according to RFC3339, and the time + designator is the character used as date and time + separator.</p> + <p>Default is <c>$T</c>.</p> + <p>The value of this parameter is used as + the <c>time_designator</c> option + to <seealso marker="stdlib:calendar#system_time_to_rfc3339-2"> + <c>calendar:system_time_to_rcf3339/2</c></seealso>.</p> + </item> + <tag><c>time_offset = integer() | [byte()]</c></tag> + <item> + <p>The time offset, either a string or an integer, to be + used when formatting the timestamp.</p> + <p>An empty string is interpreted as local time. The + values <c>"Z"</c>, <c>"z"</c> or <c>0</c> are interpreted as + Universal Coordinated Time (UTC).</p> + <p>Strings, other than <c>"Z"</c>, <c>"z"</c>, or <c>""</c>, + must be on the form <c>±[hh]:[mm]</c>, for + example <c>"-02:00"</c> or <c>"+00:00"</c>.</p> + <p>Integers must be in microseconds, meaning that the + offset <c>7200000000</c> is equivalent + to <c>"+02:00"</c>.</p> + <p>The default value is an empty string, meaning that + timestamps are displayed in local time. However, for + backwards compatibility, if the SASL environment + variable <seealso marker="sasl:sasl_app#utc_log"> + <c>utc_log</c></seealso><c>=true</c>, the default is + changed to <c>"Z"</c>, meaning that timestamps are displayed + in UTC.</p> + <p>The value of this parameter is used as the <c>offset</c> + option to <seealso marker="stdlib:calendar#system_time_to_rfc3339-2"> + <c>calendar:system_time_to_rcf3339/2</c></seealso>.</p> </item> </taglist> </section> @@ -174,7 +203,7 @@ <p>The log event used in the examples is:</p> <code> -?LOG_ERROR("name: ~p~nexit_reason: ~p",[my_reg_name,"It crashed"])</code> +?LOG_ERROR("name: ~p~nexit_reason: ~p",[my_name,"It crashed"])</code> <taglist> <tag><c>legacy_header=true</c></tag> @@ -182,9 +211,9 @@ <p>Default template: <c>[{logger_formatter,header},"\n",msg,"\n"]</c></p> <p>Example log entry:</p> - <code> -=ERROR REPORT==== 29-Dec-2017::13:30:51.245123 === -name: my_reg_name + <code type="none"> +2018-05-16T11:55:50.448382+02:00 error: +name: my_name exit_reason: "It crashed"</code> <p>Notice that all eight levels might occur in the heading, @@ -198,7 +227,7 @@ exit_reason: "It crashed"</code> <p>Default template: <c>[time," ",level,": ",msg,"\n"]</c></p> <p>Example log entry:</p> - <code>2017-12-29 13:31:49.640317 error: name: my_reg_name, exit_reason: "It crashed"</code> + <code type="none">2018-05-16T11:55:50.448382+02:00 error: name: my_name, exit_reason: "It crashed"</code> </item> <tag><c>legacy_header=false, single_line=false</c></tag> @@ -206,9 +235,9 @@ exit_reason: "It crashed"</code> <p>Default template: <c>[time," ",level,":\n",msg,"\n"]</c></p> <p>Example log entry:</p> - <code> -2017-12-29 13:32:25.191925 error: -name: my_reg_name + <code type="none"> +2018-05-16T11:55:50.448382+02:00 error: +name: my_name exit_reason: "It crashed"</code> </item> </taglist> diff --git a/lib/kernel/doc/src/logger_std_h.xml b/lib/kernel/doc/src/logger_std_h.xml index fe9b9ca5a9..bf23d874c8 100644 --- a/lib/kernel/doc/src/logger_std_h.xml +++ b/lib/kernel/doc/src/logger_std_h.xml @@ -40,7 +40,7 @@ application. Multiple instances of this handler can be added to logger, and each instance will print logs to <c>standard_io</c>, <c>standard_error</c> or to file. The default instance that starts - with kernel is named <c>logger_std_h</c> - which is the name to be used + with kernel is named <c>default</c> - which is the name to be used for reconfiguration.</p> <p>The handler has an overload protection mechanism that will keep the handler process and the kernel application alive during a high load of log @@ -57,7 +57,7 @@ are stored in a sub map with the key <c>logger_std_h</c>. The following keys and values may be specified:</p> <taglist> - <tag><c>type</c></tag> + <tag><marker id="type"/><c>type</c></tag> <item> <p>This will have the value <c>standard_io</c>, <c>standard_error</c>, <c>{file,LogFileName}</c>, or <c>{file,LogFileName,LogFileOpts}</c>, @@ -105,11 +105,10 @@ logger:add_handler(my_standard_h, logger_std_h, </code> <p>In order to configure the default handler (that starts initially with the kernel application) to log to file instead of <c>standard_io</c>, - use the kernel configuration parameter - <seealso marker="kernel_app#configuration"><c>logger_dest</c></seealso> with - value <c>{file,FileName}</c>. Example:</p> + change the Kernel default logger to use a file. Example:</p> <code type="none"> -erl -kernel logger_dest '{file,"./erl.log"}' +erl -kernel logger '[{handler,default,logger_std_h, + #{ logger_std_h => #{ type => {file,"./log.log"}}}}]' </code> <p>An example of how to replace the standard handler with a disk_log handler at startup can be found in the manual of diff --git a/lib/kernel/doc/src/ref_man.xml b/lib/kernel/doc/src/ref_man.xml index c06914d23d..b6c2714664 100644 --- a/lib/kernel/doc/src/ref_man.xml +++ b/lib/kernel/doc/src/ref_man.xml @@ -32,12 +32,15 @@ </description> <xi:include href="kernel_app.xml"/> + <xi:include href="app.xml"/> <xi:include href="application.xml"/> <xi:include href="auth.xml"/> <xi:include href="code.xml"/> + <xi:include href="config.xml"/> <xi:include href="disk_log.xml"/> <xi:include href="erl_boot_server.xml"/> <xi:include href="erl_ddll.xml"/> + <xi:include href="erl_epmd.xml"/> <xi:include href="erl_prim_loader_stub.xml"/> <xi:include href="erlang_stub.xml"/> <xi:include href="error_handler.xml"/> @@ -66,6 +69,4 @@ <xi:include href="user.xml"/> <xi:include href="wrap_log_reader.xml"/> <xi:include href="zlib_stub.xml"/> - <xi:include href="app.xml"/> - <xi:include href="config.xml"/> </application> diff --git a/lib/kernel/doc/src/specs.xml b/lib/kernel/doc/src/specs.xml index bcc422930e..b8c25ca53b 100644 --- a/lib/kernel/doc/src/specs.xml +++ b/lib/kernel/doc/src/specs.xml @@ -6,6 +6,7 @@ <xi:include href="../specs/specs_disk_log.xml"/> <xi:include href="../specs/specs_erl_boot_server.xml"/> <xi:include href="../specs/specs_erl_ddll.xml"/> + <xi:include href="../specs/specs_erl_epmd.xml"/> <xi:include href="../specs/specs_erl_prim_loader_stub.xml"/> <xi:include href="../specs/specs_erlang_stub.xml"/> <xi:include href="../specs/specs_error_handler.xml"/> diff --git a/lib/kernel/src/application_controller.erl b/lib/kernel/src/application_controller.erl index b9cb722575..ff5df667b5 100644 --- a/lib/kernel/src/application_controller.erl +++ b/lib/kernel/src/application_controller.erl @@ -1272,9 +1272,7 @@ load(S, {ApplData, ApplEnv, IncApps, Descr, Id, Vsn, Apps}) -> NewEnv = merge_app_env(ApplEnv, ConfEnv), CmdLineEnv = get_cmd_env(Name), NewEnv2 = merge_app_env(NewEnv, CmdLineEnv), - NewEnv3 = keyreplaceadd(included_applications, 1, NewEnv2, - {included_applications, IncApps}), - add_env(Name, NewEnv3), + add_env(Name, NewEnv2), Appl = #appl{name = Name, descr = Descr, id = Id, vsn = Vsn, appl_data = ApplData, inc_apps = IncApps, apps = Apps}, ets:insert(ac_tab, {{loaded, Name}, Appl}), @@ -1292,7 +1290,7 @@ load(S, {ApplData, ApplEnv, IncApps, Descr, Id, Vsn, Apps}) -> {ok, NewS}. unload(AppName, S) -> - {ok, IncApps} = get_env(AppName, included_applications), + {ok, IncApps} = get_key(AppName, included_applications), del_env(AppName), ets:delete(ac_tab, {loaded, AppName}), foldl(fun(App, S1) -> @@ -1583,13 +1581,9 @@ do_change_appl({ok, {ApplData, Env, IncApps, Descr, Id, Vsn, Apps}}, CmdLineEnv = get_cmd_env(AppName), NewEnv2 = merge_app_env(NewEnv1, CmdLineEnv), - %% included_apps is made into an env parameter as well - NewEnv3 = keyreplaceadd(included_applications, 1, NewEnv2, - {included_applications, IncApps}), - %% Update ets table with new application env del_env(AppName), - add_env(AppName, NewEnv3), + add_env(AppName, NewEnv2), OldAppl#appl{appl_data=ApplData, descr=Descr, diff --git a/lib/kernel/src/erl_epmd.erl b/lib/kernel/src/erl_epmd.erl index f96bc88913..9a0939972d 100644 --- a/lib/kernel/src/erl_epmd.erl +++ b/lib/kernel/src/erl_epmd.erl @@ -29,10 +29,20 @@ -define(port_please_failure2(Term), noop). -endif. +-ifndef(erlang_daemon_port). +-define(erlang_daemon_port, 4369). +-endif. +-ifndef(epmd_dist_high). +-define(epmd_dist_high, 4370). +-endif. +-ifndef(epmd_dist_low). +-define(epmd_dist_low, 4370). +-endif. + %% External exports -export([start/0, start_link/0, stop/0, port_please/2, port_please/3, names/0, names/1, - register_node/2, register_node/3, open/0, open/1, open/2]). + register_node/2, register_node/3, address_please/3, open/0, open/1, open/2]). %% gen_server callbacks -export([init/1, handle_call/3, handle_cast/2, handle_info/2, @@ -53,7 +63,7 @@ start() -> gen_server:start({local, erl_epmd}, ?MODULE, [], []). - +-spec start_link() -> {ok, pid()} | ignore | {error,term()}. start_link() -> gen_server:start_link({local, erl_epmd}, ?MODULE, [], []). @@ -66,9 +76,22 @@ stop() -> %% return {port, P, Version} | noport %% +-spec port_please(Name, Host) -> {ok, Port, Version} | noport when + Name :: string(), + Host :: inet:ip_address(), + Port :: non_neg_integer(), + Version :: non_neg_integer(). + port_please(Node, Host) -> port_please(Node, Host, infinity). +-spec port_please(Name, Host, Timeout) -> {ok, Port, Version} | noport when + Name :: string(), + Host :: inet:ip_address(), + Timeout :: non_neg_integer() | infinity, + Port :: non_neg_integer(), + Version :: non_neg_integer(). + port_please(Node,HostName, Timeout) when is_atom(HostName) -> port_please1(Node,atom_to_list(HostName), Timeout); port_please(Node,HostName, Timeout) when is_list(HostName) -> @@ -92,10 +115,21 @@ port_please1(Node,HostName, Timeout) -> Else end. +-spec names() -> {ok, [{Name, Port}]} | {error, Reason} when + Name :: string(), + Port :: non_neg_integer(), + Reason :: address | file:posix(). + names() -> {ok, H} = inet:gethostname(), names(H). +-spec names(Host) -> {ok, [{Name, Port}]} | {error, Reason} when + Host :: atom() | string() | inet:ip_address(), + Name :: string(), + Port :: non_neg_integer(), + Reason :: address | file:posix(). + names(HostName) when is_atom(HostName); is_list(HostName) -> case inet:gethostbyname(HostName) of {ok,{hostent, _Name, _ , _Af, _Size, [EpmdAddr | _]}} -> @@ -106,9 +140,22 @@ names(HostName) when is_atom(HostName); is_list(HostName) -> names(EpmdAddr) -> get_names(EpmdAddr). +-spec register_node(Name, Port) -> Result when + Name :: string(), + Port :: non_neg_integer(), + Creation :: non_neg_integer(), + Result :: {ok, Creation} | {error, already_registered} | term(). register_node(Name, PortNo) -> - register_node(Name, PortNo, inet). + register_node(Name, PortNo, inet). + +-spec register_node(Name, Port, Driver) -> Result when + Name :: string(), + Port :: non_neg_integer(), + Driver :: inet_tcp | inet6_tcp | inet | inet6, + Creation :: non_neg_integer(), + Result :: {ok, Creation} | {error, already_registered} | term(). + register_node(Name, PortNo, inet_tcp) -> register_node(Name, PortNo, inet); register_node(Name, PortNo, inet6_tcp) -> @@ -116,6 +163,17 @@ register_node(Name, PortNo, inet6_tcp) -> register_node(Name, PortNo, Family) -> gen_server:call(erl_epmd, {register, Name, PortNo, Family}, infinity). +-spec address_please(Name, Host, AddressFamily) -> Success | {error, term()} when + Name :: string(), + Host :: string() | inet:ip_address(), + AddressFamily :: inet | inet6, + Port :: non_neg_integer(), + Version :: non_neg_integer(), + Success :: {ok, inet:ip_address()} | {ok, inet:ip_address(), Port, Version}. + +address_please(_Name, Host, AddressFamily) -> + inet:getaddr(Host, AddressFamily). + %%%---------------------------------------------------------------------- %%% Callback functions from gen_server %%%---------------------------------------------------------------------- diff --git a/lib/kernel/src/erl_signal_handler.erl b/lib/kernel/src/erl_signal_handler.erl index 22f235d4e4..b76c2a217a 100644 --- a/lib/kernel/src/erl_signal_handler.erl +++ b/lib/kernel/src/erl_signal_handler.erl @@ -19,12 +19,21 @@ -module(erl_signal_handler). -behaviour(gen_event). --export([init/1, format_status/2, +-export([start/0, init/1, format_status/2, handle_event/2, handle_call/2, handle_info/2, terminate/2, code_change/3]). -record(state,{}). +start() -> + %% add signal handler + case whereis(erl_signal_server) of + %% in case of minimal mode + undefined -> ok; + _ -> + gen_event:add_handler(erl_signal_server, erl_signal_handler, []) + end. + init(_Args) -> {ok, #state{}}. diff --git a/lib/kernel/src/error_logger.erl b/lib/kernel/src/error_logger.erl index 47d0ca5ea3..6c3b308308 100644 --- a/lib/kernel/src/error_logger.erl +++ b/lib/kernel/src/error_logger.erl @@ -529,18 +529,38 @@ logfile(filename) -> Flag :: boolean(). tty(true) -> - case lists:member(error_logger_tty_h, which_report_handlers()) of - false -> - add_report_handler(error_logger_tty_h, []); - true -> - ignore - end, + _ = case lists:member(error_logger_tty_h, which_report_handlers()) of + false -> + case logger:get_handler_config(default) of + {ok,{logger_std_h,#{logger_std_h:=#{type:=standard_io}}}} -> + logger:remove_handler_filter(default, + error_logger_tty_false); + _ -> + logger:add_handler(error_logger_tty_true,logger_std_h, + #{filter_default=>stop, + filters=>?DEFAULT_HANDLER_FILTERS( + [beam,erlang,otp]), + formatter=>{?DEFAULT_FORMATTER, + ?DEFAULT_FORMAT_CONFIG}, + logger_std_h=>#{type=>standard_io}}) + end; + true -> + ok + end, ok; tty(false) -> - delete_report_handler(error_logger_tty_h). + delete_report_handler(error_logger_tty_h), + _ = logger:remove_handler(error_logger_tty_true), + _ = case logger:get_handler_config(default) of + {ok,{logger_std_h,#{logger_std_h:=#{type:=standard_io}}}} -> + logger:add_handler_filter(default,error_logger_tty_false, + {fun(_,_) -> stop end, ok}); + _ -> + ok + end, + ok. %%%----------------------------------------------------------------- - -spec limit_term(term()) -> term(). limit_term(Term) -> @@ -552,4 +572,9 @@ limit_term(Term) -> -spec get_format_depth() -> 'unlimited' | pos_integer(). get_format_depth() -> - logger:get_format_depth(). + case application:get_env(kernel, error_logger_format_depth) of + {ok, Depth} when is_integer(Depth) -> + max(10, Depth); + undefined -> + unlimited + end. diff --git a/lib/kernel/src/file.erl b/lib/kernel/src/file.erl index 57d8fc7a15..1d4e37196c 100644 --- a/lib/kernel/src/file.erl +++ b/lib/kernel/src/file.erl @@ -69,7 +69,7 @@ %% Types that can be used from other modules -- alphabetically ordered. -export_type([date_time/0, fd/0, file_info/0, filename/0, filename_all/0, - io_device/0, name/0, name_all/0, posix/0]). + io_device/0, mode/0, name/0, name_all/0, posix/0]). %%% Includes and defines -include("file_int.hrl"). diff --git a/lib/kernel/src/inet_tcp_dist.erl b/lib/kernel/src/inet_tcp_dist.erl index e3fdb1bb22..b4b50899f7 100644 --- a/lib/kernel/src/inet_tcp_dist.erl +++ b/lib/kernel/src/inet_tcp_dist.erl @@ -283,73 +283,22 @@ do_setup(Driver, Kernel, Node, Type, MyNode, LongOrShortNames, SetupTime) -> ?trace("~p~n",[{inet_tcp_dist,self(),setup,Node}]), [Name, Address] = splitnode(Driver, Node, LongOrShortNames), AddressFamily = Driver:family(), - case inet:getaddr(Address, AddressFamily) of + ErlEpmd = net_kernel:epmd_module(), + {ARMod, ARFun} = get_address_resolver(ErlEpmd), + Timer = dist_util:start_timer(SetupTime), + case ARMod:ARFun(Name, Address, AddressFamily) of + {ok, Ip, TcpPort, Version} -> + ?trace("address_please(~p) -> version ~p~n", + [Node,Version]), + do_setup_connect(Driver, Kernel, Node, Address, AddressFamily, + Ip, TcpPort, Version, Type, MyNode, Timer); {ok, Ip} -> - Timer = dist_util:start_timer(SetupTime), - ErlEpmd = net_kernel:epmd_module(), case ErlEpmd:port_please(Name, Ip) of {port, TcpPort, Version} -> ?trace("port_please(~p) -> version ~p~n", [Node,Version]), - dist_util:reset_timer(Timer), - case - Driver:connect( - Ip, TcpPort, - connect_options([{active, false}, {packet, 2}])) - of - {ok, Socket} -> - HSData = #hs_data{ - kernel_pid = Kernel, - other_node = Node, - this_node = MyNode, - socket = Socket, - timer = Timer, - this_flags = 0, - other_version = Version, - f_send = fun Driver:send/2, - f_recv = fun Driver:recv/3, - f_setopts_pre_nodeup = - fun(S) -> - inet:setopts - (S, - [{active, false}, - {packet, 4}, - nodelay()]) - end, - f_setopts_post_nodeup = - fun(S) -> - inet:setopts - (S, - [{active, true}, - {deliver, port}, - {packet, 4}, - nodelay()]) - end, - - f_getll = fun inet:getll/1, - f_address = - fun(_,_) -> - #net_address{ - address = {Ip,TcpPort}, - host = Address, - protocol = tcp, - family = AddressFamily} - end, - mf_tick = fun(S) -> ?MODULE:tick(Driver, S) end, - mf_getstat = fun ?MODULE:getstat/1, - request_type = Type, - mf_setopts = fun ?MODULE:setopts/2, - mf_getopts = fun ?MODULE:getopts/2 - }, - dist_util:handshake_we_started(HSData); - _ -> - %% Other Node may have closed since - %% port_please ! - ?trace("other node (~p) " - "closed since port_please.~n", - [Node]), - ?shutdown(Node) - end; + do_setup_connect(Driver, Kernel, Node, Address, AddressFamily, + Ip, TcpPort, Version, Type, MyNode, Timer); _ -> ?trace("port_please (~p) " "failed.~n", [Node]), @@ -361,6 +310,71 @@ do_setup(Driver, Kernel, Node, Type, MyNode, LongOrShortNames, SetupTime) -> ?shutdown(Node) end. +%% +%% Actual setup of connection +%% +do_setup_connect(Driver, Kernel, Node, Address, AddressFamily, + Ip, TcpPort, Version, Type, MyNode, Timer) -> + dist_util:reset_timer(Timer), + case + Driver:connect( + Ip, TcpPort, + connect_options([{active, false}, {packet, 2}])) + of + {ok, Socket} -> + HSData = #hs_data{ + kernel_pid = Kernel, + other_node = Node, + this_node = MyNode, + socket = Socket, + timer = Timer, + this_flags = 0, + other_version = Version, + f_send = fun Driver:send/2, + f_recv = fun Driver:recv/3, + f_setopts_pre_nodeup = + fun(S) -> + inet:setopts + (S, + [{active, false}, + {packet, 4}, + nodelay()]) + end, + f_setopts_post_nodeup = + fun(S) -> + inet:setopts + (S, + [{active, true}, + {deliver, port}, + {packet, 4}, + nodelay()]) + end, + + f_getll = fun inet:getll/1, + f_address = + fun(_,_) -> + #net_address{ + address = {Ip,TcpPort}, + host = Address, + protocol = tcp, + family = AddressFamily} + end, + mf_tick = fun(S) -> ?MODULE:tick(Driver, S) end, + mf_getstat = fun ?MODULE:getstat/1, + request_type = Type, + mf_setopts = fun ?MODULE:setopts/2, + mf_getopts = fun ?MODULE:getopts/2 + }, + dist_util:handshake_we_started(HSData); + _ -> + %% Other Node may have closed since + %% discovery ! + ?trace("other node (~p) " + "closed since discovery (port_please).~n", + [Node]), + ?shutdown(Node) + end. + connect_options(Opts) -> case application:get_env(kernel, inet_dist_connect_options) of {ok,ConnectOpts} -> @@ -430,6 +444,16 @@ get_tcp_address(Driver, Socket) -> }. %% ------------------------------------------------------------ +%% Determine if EPMD module supports address resolving. Default +%% is to use inet:getaddr/2. +%% ------------------------------------------------------------ +get_address_resolver(EpmdModule) -> + case erlang:function_exported(EpmdModule, address_please, 3) of + true -> {EpmdModule, address_please}; + _ -> {inet, getaddr} + end. + +%% ------------------------------------------------------------ %% Do only accept new connection attempts from nodes at our %% own LAN, if the check_ip environment parameter is true. %% ------------------------------------------------------------ diff --git a/lib/kernel/src/kernel.app.src b/lib/kernel/src/kernel.app.src index afffcd156e..23ac5b3444 100644 --- a/lib/kernel/src/kernel.app.src +++ b/lib/kernel/src/kernel.app.src @@ -140,7 +140,10 @@ inet_db, pg2]}, {applications, []}, - {env, []}, + {env, [{logger_level, info}, + {logger_sasl_compatible, false}, + {logger_log_progress, false} + ]}, {mod, {kernel, []}}, {runtime_dependencies, ["erts-10.0", "stdlib-3.5", "sasl-3.0"]} ] diff --git a/lib/kernel/src/kernel.erl b/lib/kernel/src/kernel.erl index 20aa47f602..b0e8c00bbf 100644 --- a/lib/kernel/src/kernel.erl +++ b/lib/kernel/src/kernel.erl @@ -30,23 +30,13 @@ %%% Callback functions for the kernel application. %%%----------------------------------------------------------------- start(_, []) -> + %% Setup the logger and configure the kernel logger environment + ok = logger:internal_init_logger(), case supervisor:start_link({local, kernel_sup}, kernel, []) of {ok, Pid} -> - %% add signal handler - case whereis(erl_signal_server) of - %% in case of minimal mode - undefined -> ok; - _ -> - ok = gen_event:add_handler(erl_signal_server, erl_signal_handler, []) - end, - %% add error handler - case logger:setup_standard_handler() of - ok -> {ok, Pid, []}; - Error -> - %% Not necessary since the node will crash anyway: - exit(Pid, shutdown), - Error - end; + ok = erl_signal_handler:start(), + ok = logger:add_handlers(kernel), + {ok, Pid, []}; Error -> Error end. @@ -153,7 +143,7 @@ init([]) -> case init:get_argument(mode) of {ok, [["minimal"]]} -> {ok, {SupFlags, - [Code, File, StdError, User, Config, RefC, SafeSup, LoggerSup]}}; + [Code, File, StdError, User, LoggerSup, Config, RefC, SafeSup]}}; _ -> Rpc = #{id => rex, start => {rpc, start_link, []}, diff --git a/lib/kernel/src/kernel_config.erl b/lib/kernel/src/kernel_config.erl index 535083ef27..c5ff1887c2 100644 --- a/lib/kernel/src/kernel_config.erl +++ b/lib/kernel/src/kernel_config.erl @@ -30,11 +30,8 @@ %%%----------------------------------------------------------------- %%% This module implements a process that configures the kernel %%% application. -%%% Its purpose is that in the init phase add an error_logger -%%% and when it dies (when the kernel application dies) deleting the -%%% previously installed error_logger. -%%% Also, this process waits for other nodes at startup, if -%%% specified. +%%% Its purpose is that in the init phase waits for other nodes at startup, +%%% if specified. %%%----------------------------------------------------------------- start_link() -> gen_server:start_link(kernel_config, [], []). diff --git a/lib/kernel/src/logger.erl b/lib/kernel/src/logger.erl index 98a9937111..a839f97e62 100644 --- a/lib/kernel/src/logger.erl +++ b/lib/kernel/src/logger.erl @@ -40,15 +40,18 @@ set_module_level/2, reset_module_level/1, set_logger_config/1, set_logger_config/2, set_handler_config/2, set_handler_config/3, - get_logger_config/0, get_handler_config/1]). + update_logger_config/1, update_handler_config/2, + get_logger_config/0, get_handler_config/1, + add_handlers/1]). + +%% Private configuration +-export([internal_init_logger/0]). %% Misc -export([compare_levels/2]). -export([set_process_metadata/1, update_process_metadata/1, unset_process_metadata/0, get_process_metadata/0]). -export([i/0, i/1]). --export([setup_standard_handler/0, replace_simple_handler/3]). --export([limit_term/1, get_format_depth/0, get_max_size/0, get_utc_config/0]). %% Basic report formatting -export([format_report/1, format_otp_report/1]). @@ -93,8 +96,10 @@ term() => term()}. -type timestamp() :: integer(). +-type config_handler() :: {handler, handler_id(), module(), config()}. + -export_type([log/0,level/0,report/0,msg_fun/0,metadata/0,config/0,handler_id/0, - filter_id/0,filter/0,filter_arg/0,filter_return/0]). + filter_id/0,filter/0,filter_arg/0,filter_return/0, config_handler/0]). %%%----------------------------------------------------------------- %%% API @@ -357,10 +362,22 @@ set_handler_config(HandlerId,Key,Value) -> set_handler_config(HandlerId,Config) -> logger_server:set_config(HandlerId,Config). +-spec update_logger_config(Config) -> ok | {error,term()} when + Config :: config(). +update_logger_config(Config) -> + logger_server:update_config(logger,Config). + +-spec update_handler_config(HandlerId,Config) -> ok | {error,term()} when + HandlerId :: handler_id(), + Config :: config(). +update_handler_config(HandlerId,Config) -> + logger_server:update_config(HandlerId,Config). + -spec get_logger_config() -> {ok,Config} when Config :: config(). get_logger_config() -> - logger_config:get(?LOGGER_TABLE,logger). + {ok,Config} = logger_config:get(?LOGGER_TABLE,logger), + {ok,maps:remove(handlers,Config)}. -spec get_handler_config(HandlerId) -> {ok,{Module,Config}} | {error,term()} when HandlerId :: handler_id(), @@ -441,8 +458,9 @@ i() -> i(_Action = print) -> io:put_chars(i(string)); i(_Action = string) -> - #{logger := #{level := Level, handlers := Handlers, - filters := Filters, filter_default := FilterDefault}, + #{logger := #{level := Level, + filters := Filters, + filter_default := FilterDefault}, handlers := HandlerConfigs, module_levels := Modules} = i(term), [io_lib:format("Current logger configuration:~n", []), @@ -451,16 +469,15 @@ i(_Action = string) -> io_lib:format(" Filters: ~n", []), print_filters(4, Filters), io_lib:format(" Handlers: ~n", []), - print_handlers([C || {Id, _, _} = C <- HandlerConfigs, - lists:member(Id, Handlers)]), + print_handlers(HandlerConfigs), io_lib:format(" Level set per module: ~n", []), print_module_levels(Modules) ]; i(_Action = term) -> {Logger, Handlers, Modules} = logger_config:get(tid()), - #{logger=>Logger, - handlers=>Handlers, - module_levels=>Modules}. + #{logger=>maps:remove(handlers,Logger), + handlers=>lists:keysort(1,Handlers), + module_levels=>lists:keysort(1,Modules)}. print_filters(Indent, {Id, {Fun, Config}}) -> io_lib:format("~sId: ~p~n" @@ -504,118 +521,184 @@ print_module_levels({Module,Level}) -> print_module_levels(ModuleLevels) -> lists:map(fun print_module_levels/1, ModuleLevels). --spec setup_standard_handler() -> ok | {error,term()}. -setup_standard_handler() -> - case get_logger_type() of - {ok,silent} -> - Level = get_logger_level(), - ok = set_logger_config(level,Level), - remove_handler(logger_simple); - {ok,Type} -> - Level = get_logger_level(), - ok = set_logger_config(level,Level), - Filters = get_logger_filters(), - setup_standard_handler(Type,#{level=>Level, - filter_default=>stop, - filters=>Filters}); - Error -> - Error +-spec internal_init_logger() -> ok | {error,term()}. +%% This function is responsible for config of the logger +%% This is done before add_handlers because we want the +%% logger settings to take effect before the kernel supervisor +%% tree is started. +internal_init_logger() -> + try + ok = logger:set_logger_config(level, get_logger_level()), + ok = logger:set_logger_config(filter_default, get_logger_filter_default()), + + [case logger:add_logger_filter(Id, Filter) of + ok -> ok; + {error, Reason} -> throw(Reason) + end || {Id, Filter} <- get_logger_filters()], + + _ = [[case logger:set_module_level(Module, Level) of + ok -> ok; + {error, Reason} -> throw(Reason) + end || Module <- Modules] + || {module_level, Level, Modules} <- get_logger_env()], + + case logger:set_handler_config(logger_simple,filters, + get_default_handler_filters()) of + ok -> ok; + {error,{not_found,logger_simple}} -> ok + end, + + init_kernel_handlers() + catch throw:Reason -> + ?LOG_ERROR("Invalid logger config: ~p", [Reason]), + {error, {bad_config, {kernel, Reason}}} end. --spec setup_standard_handler(Type,Config) -> ok | {error,term()} when - Type :: tty | standard_io | standard_error | {file,File} | - {file,File,Modes} | {disk_log,LogOpts} | false, - File :: file:filename(), - Modes :: [term()], % [file:mode()], or more specific? - Config :: config(), - LogOpts :: map(). -setup_standard_handler(false,#{level:=Level,filters:=Filters}) -> - case set_handler_config(logger_simple,level,Level) of - ok -> - set_handler_config(logger_simple,filters,Filters); - Error -> - Error - end; -setup_standard_handler(Type,Config) -> - {Module,TypeConfig} = get_type_config(Type), - replace_simple_handler(?STANDARD_HANDLER, - Module, - maps:merge(Config,TypeConfig)). - --spec replace_simple_handler(Id,Module,Config) -> ok | {error,term()} when - Id :: handler_id(), - Module :: module(), - Config :: config(). -replace_simple_handler(Id,Module,Config) -> - _ = code:ensure_loaded(Module), - DoBuffer = erlang:function_exported(Module,swap_buffer,2), - case add_handler(Id,Module,Config#{wait_for_buffer=>DoBuffer}) of - ok -> - if DoBuffer -> - {ok,Buffered} = logger_simple:get_buffer(), - _ = remove_handler(logger_simple), - Module:swap_buffer(?STANDARD_HANDLER,Buffered); - true -> - _ = remove_handler(logger_simple), - ok - end, - ok; - Error -> - Error +-spec init_kernel_handlers() -> ok | {error,term()}. +%% Setup the kernel environment variables to be correct +%% The actual handlers are started by a call to add_handlers. +init_kernel_handlers() -> + try + case get_logger_type() of + {ok,silent} -> + ok = logger:remove_handler(logger_simple); + {ok,false} -> + ok; + {ok,Type} -> + init_default_config(Type) + end + catch throw:Reason -> + ?LOG_ERROR("Invalid default handler config: ~p", [Reason]), + {error, {bad_config, {kernel, Reason}}} + end. + +-spec add_handlers(Application) -> ok | {error,term()} when + Application :: atom(); + (HandlerConfig) -> ok | {error,term()} when + HandlerConfig :: [config_handler()]. +%% This function is responsible for resolving the handler config +%% and then starting the correct handlers. This is done after the +%% kernel supervisor tree has been started as it needs the logger_sup. +add_handlers(App) when is_atom(App) -> + add_handlers(application:get_env(App, logger, [])); +add_handlers(HandlerConfig) -> + try + check_logger_config(HandlerConfig), + DefaultAdded = + lists:foldl( + fun({handler, default = Id, Module, Config}, _) + when not is_map_key(filters, Config) -> + %% The default handler should have a couple of extra filters + %% set on it by default. + DefConfig = #{ filter_default => stop, + filters => get_default_handler_filters()}, + setup_handler(Id, Module, maps:merge(DefConfig,Config)), + true; + ({handler, Id, Module, Config}, Default) -> + setup_handler(Id, Module, Config), + Default orelse Id == default; + (_, Default) -> Default + end, false, HandlerConfig), + %% If a default handler was added we try to remove the simple_logger + %% If the simple logger exists it will replay its log events + %% to the handler(s) added in the fold above. + _ = [case logger:remove_handler(logger_simple) of + ok -> ok; + {error,{not_found,logger_simple}} -> ok + end || DefaultAdded], + ok + catch throw:Reason -> + ?LOG_ERROR("Invalid logger handler config: ~p", [Reason]), + {error, {bad_config, {handler, Reason}}} end. +setup_handler(Id, Module, Config) -> + case logger:add_handler(Id, Module, Config) of + ok -> ok; + {error, Reason} -> throw(Reason) + end. + +check_logger_config(_) -> + ok. + +-spec get_logger_type() -> {ok, standard_io | false | silent | + {file, file:name_all()} | + {file, file:name_all(), [file:mode()]}}. get_logger_type() -> - Type0 = - case application:get_env(kernel, logger_dest) of - undefined -> - application:get_env(kernel, error_logger); - T -> - T - end, - case Type0 of + case application:get_env(kernel, error_logger) of {ok, tty} -> - {ok, tty}; + {ok, standard_io}; {ok, {file, File}} when is_list(File) -> {ok, {file, File}}; {ok, {file, File, Modes}} when is_list(File), is_list(Modes) -> {ok, {file, File, Modes}}; - {ok, {disk_log, File}} when is_list(File) -> - {ok, {disk_log, get_disk_log_config(File)}}; {ok, false} -> {ok, false}; {ok, silent} -> {ok, silent}; undefined -> - {ok, tty}; % default value + case lists:member({handler,default,undefined}, get_logger_env()) of + true -> + {ok, false}; + false -> + {ok, standard_io} % default value + end; {ok, Bad} -> - {error,{bad_config, {kernel, {logger_dest, Bad}}}} + throw({error_logger, Bad}) end. -get_disk_log_config(File) -> - Config1 = - case application:get_env(kernel,logger_disk_log_maxfiles) of - undefined -> #{}; - {ok,MF} -> #{max_no_files=>MF} - end, - Config2 = - case application:get_env(kernel,logger_disk_log_maxbytes) of - undefined -> Config1; - {ok,MB} -> Config1#{max_no_bytes=>MB} - end, - Config3 = - case application:get_env(kernel,logger_disk_log_type) of - undefined -> Config2; - {ok,T} -> Config1#{type=>T} - end, - Config3#{file=>File}. - get_logger_level() -> - case application:get_env(kernel,logger_level) of - undefined -> info; - {ok,Level} when ?IS_LEVEL(Level) -> Level + case application:get_env(kernel,logger_level,info) of + Level when ?IS_LEVEL(Level) -> + Level; + Level -> + throw({logger_level, Level}) + end. + +get_logger_filter_default() -> + case lists:keyfind(filters,1,get_logger_env()) of + {filters,Default,_} -> + Default; + false -> + log end. get_logger_filters() -> + lists:foldl( + fun({filters, _, Filters}, _Acc) -> + Filters; + (_, Acc) -> + Acc + end, [], get_logger_env()). + +%% This function looks at the kernel logger environment +%% and updates it so that the correct logger is configured +init_default_config(Type) when Type==standard_io; + Type==standard_error; + element(1,Type)==file -> + Env = get_logger_env(), + DefaultConfig = #{logger_std_h=>#{type=>Type}}, + NewLoggerEnv = + case lists:keyfind(default, 2, Env) of + {handler, default, Module, Config} -> + lists:map( + fun({handler, default, logger_std_h, _}) -> + %% Only want to add the logger_std_h config + %% if not configured by user AND the default + %% handler is still the logger_std_h. + {handler, default, Module, maps:merge(DefaultConfig,Config)}; + (Other) -> + Other + end, Env); + _ -> + %% Nothing has been configured, use default + [{handler, default, logger_std_h, DefaultConfig} | Env] + end, + application:set_env(kernel, logger, NewLoggerEnv, [{timeout,infinity}]); +init_default_config(Type) -> + throw({illegal_logger_type,Type}). + +get_default_handler_filters() -> case application:get_env(kernel, logger_sasl_compatible, false) of true -> ?DEFAULT_HANDLER_FILTERS([beam,erlang,otp]); @@ -631,77 +714,8 @@ get_logger_filters() -> Extra ++ ?DEFAULT_HANDLER_FILTERS([beam,erlang,otp,sasl]) end. -get_type_config({disk_log,LogOpts}) -> - {logger_disk_log_h,#{disk_log_opts=>LogOpts}}; -get_type_config(tty) -> - %% This is only for backwards compatibility with error_logger and - %% old kernel and sasl environment variables - get_type_config(standard_io); -get_type_config(Type) when Type==standard_io; - Type==standard_error; - element(1,Type)==file -> - {logger_std_h,#{logger_std_h=>#{type=>Type}}}; -get_type_config(Type) -> - {error,{illegal_logger_type,Type}}. - -%%%----------------------------------------------------------------- --spec limit_term(term()) -> term(). - -limit_term(Term) -> - try get_format_depth() of - unlimited -> Term; - D -> io_lib:limit_term(Term, D) - catch error:badarg -> - %% This could happen during system termination, after - %% application_controller process is dead. - unlimited - end. - --spec get_format_depth() -> 'unlimited' | pos_integer(). - -get_format_depth() -> - Depth = - case application:get_env(kernel, logger_format_depth) of - {ok, D} when is_integer(D) -> - D; - undefined -> - case application:get_env(kernel, error_logger_format_depth) of - {ok, D} when is_integer(D) -> - D; - undefined -> - unlimited - end - end, - max(10, Depth). - --spec get_max_size() -> 'unlimited' | pos_integer(). - -get_max_size() -> - case application:get_env(kernel, logger_max_size) of - {ok, Size} when is_integer(Size) -> - max(50, Size); - undefined -> - unlimited - end. - --spec get_utc_config() -> boolean(). - -get_utc_config() -> - %% Kernel's logger_utc configuration overrides SASL utc_log, which - %% in turn overrides stdlib config - in order to have uniform - %% timestamps in log messages - case application:get_env(kernel, logger_utc) of - {ok, Val} -> Val; - undefined -> - case application:get_env(sasl, utc_log) of - {ok, Val} -> Val; - undefined -> - case application:get_env(stdlib, utc_log) of - {ok, Val} -> Val; - undefined -> false - end - end - end. +get_logger_env() -> + application:get_env(kernel, logger, []). %%%----------------------------------------------------------------- %%% Internal diff --git a/lib/kernel/src/logger_config.erl b/lib/kernel/src/logger_config.erl index 799aea9617..40dc1b1e1b 100644 --- a/lib/kernel/src/logger_config.erl +++ b/lib/kernel/src/logger_config.erl @@ -31,7 +31,7 @@ -include("logger_internal.hrl"). new(Name) -> - _ = ets:new(Name,[set,protected,named_table]), + _ = ets:new(Name,[set,protected,named_table,{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 0150fa781a..57c54ce27e 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -278,10 +278,11 @@ init([Name, Config = #{disk_log_opts := LogOpts}, 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}), - gen_server:cast(self(), {repeated_disk_log_sync,T0}), + gen_server:cast(self(), repeated_disk_log_sync), enter_loop(Config, State1); Error -> logger_h_common:error_notify({open_disk_log,Name,Error}), @@ -316,8 +317,7 @@ handle_call(disk_log_sync, _From, State = #{id := Name}) -> {reply, Result, State1}; handle_call({change_config,_OldConfig,NewConfig}, _From, - State = #{filesync_repeat_interval := FSyncInt0, - last_log_ts := LastLogTS}) -> + State = #{filesync_repeat_interval := FSyncInt0}) -> HConfig = maps:get(?MODULE, NewConfig, #{}), State1 = #{toggle_sync_qlen := TSQL, drop_new_reqs_qlen := DNRQL, @@ -338,9 +338,8 @@ handle_call({change_config,_OldConfig,NewConfig}, _From, _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, State, undefined)), - _ = gen_server:cast(self(), {repeated_disk_log_sync, - LastLogTS}) - end, + _ = gen_server:cast(self(), repeated_disk_log_sync) + end, {reply, ok, State1}; false -> {reply, {error,{invalid_levels,{TSQL,DNRQL,FRQL}}}, State} @@ -370,24 +369,23 @@ handle_cast({log, Bin}, State) -> %% clause gets called repeatedly by the handler. In order to %% guarantee that a filesync *always* happens after the last log %% request, the repeat operation must be active! -handle_cast({repeated_disk_log_sync,LastLogTS0}, +handle_cast(repeated_disk_log_sync, State = #{id := Name, filesync_repeat_interval := FSyncInt, - last_log_ts := LastLogTS1}) -> + last_op := LastOp}) -> State1 = if is_integer(FSyncInt) -> %% only do filesync if something has been %% written since last time we checked - NewState = if LastLogTS1 == LastLogTS0 -> + 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,LastLogTS1}]), - NewState#{rep_sync_tref => TRef}; + [self(),repeated_disk_log_sync]), + NewState#{rep_sync_tref => TRef, last_op => sync}; true -> State end, @@ -649,10 +647,9 @@ close_disk_log(Name, _) -> ok. disk_log_write(Name, Bin, State) -> - Result = case ?disk_log_blog(Name, Bin) of ok -> - ok; + State#{prev_log_result => ok, last_op => write}; LogError -> _ = case maps:get(prev_log_result, State) of LogError -> @@ -664,29 +661,26 @@ disk_log_write(Name, Bin, State) -> LogOpts, LogError}) end, - LogError - end, - State#{prev_log_result => Result}. + State#{prev_log_result => LogError} + end. disk_log_sync(Name, State) -> - Result = - case ?disk_log_sync(Name) of - ok -> - ok; - SyncError -> - _ = case maps:get(prev_sync_result, State) of - SyncError -> - %% don't report same error twice - ok; - _ -> - LogOpts = maps:get(log_opts, State), - logger_h_common:error_notify({Name,sync, - LogOpts, - SyncError}) - end, - SyncError - end, - State#{prev_sync_result => Result}. + case ?disk_log_sync(Name) of + ok -> + State#{prev_sync_result => ok, last_op => sync}; + SyncError -> + _ = case maps:get(prev_sync_result, State) of + SyncError -> + %% don't report same error twice + ok; + _ -> + LogOpts = maps:get(log_opts, State), + logger_h_common:error_notify({Name,sync, + LogOpts, + SyncError}) + end, + State#{prev_sync_result => SyncError} + end. error_notify_new(Info,Info, _Term) -> ok; diff --git a/lib/kernel/src/logger_filters.erl b/lib/kernel/src/logger_filters.erl index 85928f0fd6..592ff28cc2 100644 --- a/lib/kernel/src/logger_filters.erl +++ b/lib/kernel/src/logger_filters.erl @@ -38,6 +38,7 @@ domain(#{meta:=Meta}=Log,{Action,Compare,MatchDomain}) (Compare==prefix_of orelse Compare==starts_with orelse Compare==equals orelse + Compare==differs orelse Compare==no_domain) andalso is_list(MatchDomain) -> filter_domain(Compare,Meta,MatchDomain,on_match(Action,Log)); @@ -87,9 +88,12 @@ filter_domain(starts_with,#{domain:=Domain},MatchDomain,OnMatch) -> is_prefix(MatchDomain,Domain,OnMatch); filter_domain(equals,#{domain:=Domain},Domain,OnMatch) -> OnMatch; +filter_domain(differs,#{domain:=Domain},MatchDomain,OnMatch) + when Domain=/=MatchDomain -> + OnMatch; filter_domain(Action,Meta,_,OnMatch) -> case maps:is_key(domain,Meta) of - false when Action==no_domain -> OnMatch; + false when Action==no_domain; Action==differs -> OnMatch; _ -> ignore end. diff --git a/lib/kernel/src/logger_formatter.erl b/lib/kernel/src/logger_formatter.erl index 8e954f8d98..602c666cc7 100644 --- a/lib/kernel/src/logger_formatter.erl +++ b/lib/kernel/src/logger_formatter.erl @@ -20,6 +20,7 @@ -module(logger_formatter). -export([format/2]). +-export([check_config/1]). -include("logger_internal.hrl"). @@ -38,7 +39,8 @@ max_size=>pos_integer() | unlimited, depth=>pos_integer() | unlimited, template=>template(), - utc=>boolean()}. + time_designator=>byte(), + time_offset=>integer()|[byte()]}. format(#{level:=Level,msg:=Msg0,meta:=Meta},Config0) when is_map(Config0) -> Config = add_default_config(Config0), @@ -195,16 +197,12 @@ truncate(String,Size) -> String end. -format_time(Timestamp,Config) when is_integer(Timestamp) -> - {Date,Time,Micro} = timestamp_to_datetimemicro(Timestamp,Config), - format_time(Date,Time,Micro); -format_time(Other,_Config) -> - %% E.g. a string - to_string(Other). - -format_time({Y,M,D},{H,Min,S},Micro) -> - io_lib:format("~4w-~2..0w-~2..0w ~2w:~2..0w:~2..0w.~6..0w", - [Y,M,D,H,Min,S,Micro]). +format_time(Timestamp,#{time_offset:=Offset,time_designator:=Des}) + when is_integer(Timestamp) -> + SysTime = Timestamp + erlang:time_offset(microsecond), + calendar:system_time_to_rfc3339(SysTime,[{unit,microsecond}, + {offset,Offset}, + {time_designator,Des}]). %% Assuming this is monotonic time in microseconds timestamp_to_datetimemicro(Timestamp,Config) when is_integer(Timestamp) -> @@ -212,12 +210,12 @@ timestamp_to_datetimemicro(Timestamp,Config) when is_integer(Timestamp) -> Micro = SysTime rem 1000000, Sec = SysTime div 1000000, UniversalTime = erlang:posixtime_to_universaltime(Sec), - {Date,Time} = - case Config of - #{utc:=true} -> UniversalTime; - _ -> erlang:universaltime_to_localtime(UniversalTime) + {{Date,Time},UtcStr} = + case offset_to_utc(maps:get(time_offset,Config)) of + true -> {UniversalTime,"UTC "}; + _ -> {erlang:universaltime_to_localtime(UniversalTime),""} end, - {Date,Time,Micro}. + {Date,Time,Micro,UtcStr}. format_mfa({M,F,A}) when is_atom(M), is_atom(F), is_integer(A) -> atom_to_list(M)++":"++atom_to_list(F)++"/"++integer_to_list(A); @@ -230,9 +228,11 @@ maybe_add_legacy_header(Level, #{time:=Timestamp}=Meta, #{legacy_header:=true}=Config) -> #{title:=Title}=MyMeta = add_legacy_title(Level,maps:get(?MODULE,Meta,#{})), - {{Y,Mo,D},{H,Mi,S},Micro} = timestamp_to_datetimemicro(Timestamp,Config), - Header = io_lib:format("=~ts==== ~w-~s-~4w::~2..0w:~2..0w:~2..0w.~6..0w ~s===", - [Title,D,month(Mo),Y,H,Mi,S,Micro,utcstr(Config)]), + {{Y,Mo,D},{H,Mi,S},Micro,UtcStr} = + timestamp_to_datetimemicro(Timestamp,Config), + Header = + io_lib:format("=~ts==== ~w-~s-~4w::~2..0w:~2..0w:~2..0w.~6..0w ~s===", + [Title,D,month(Mo),Y,H,Mi,S,Micro,UtcStr]), Meta#{?MODULE=>MyMeta#{header=>Header}}; maybe_add_legacy_header(_,Meta,_) -> Meta. @@ -256,20 +256,20 @@ month(10) -> "Oct"; month(11) -> "Nov"; month(12) -> "Dec". -utcstr(#{utc:=true}) -> "UTC "; -utcstr(_) -> "". - -add_default_config(#{utc:=_}=Config0) -> +%% Ensure that all valid configuration parameters exist in the final +%% configuration map +add_default_config(Config0) -> Default = #{legacy_header=>false, single_line=>true, - chars_limit=>unlimited}, - MaxSize = get_max_size(maps:get(max_size,Config0,false)), - Depth = get_depth(maps:get(depth,Config0,false)), + chars_limit=>unlimited, + time_designator=>$T}, + MaxSize = get_max_size(maps:get(max_size,Config0,undefined)), + Depth = get_depth(maps:get(depth,Config0,undefined)), + Offset = get_offset(maps:get(time_offset,Config0,undefined)), add_default_template(maps:merge(Default,Config0#{max_size=>MaxSize, - depth=>Depth})); -add_default_config(Config) -> - add_default_config(Config#{utc=>logger:get_utc_config()}). + depth=>Depth, + time_offset=>Offset})). add_default_template(#{template:=_}=Config) -> Config; @@ -283,12 +283,121 @@ default_template(#{single_line:=true}) -> default_template(_) -> ?DEFAULT_FORMAT_TEMPLATE. -get_max_size(false) -> - logger:get_max_size(); +get_max_size(undefined) -> + unlimited; get_max_size(S) -> max(10,S). -get_depth(false) -> - logger:get_format_depth(); +get_depth(undefined) -> + error_logger:get_format_depth(); get_depth(S) -> max(5,S). + +get_offset(undefined) -> + utc_to_offset(get_utc_config()); +get_offset(Offset) -> + Offset. + +utc_to_offset(true) -> + "Z"; +utc_to_offset(false) -> + "". + +get_utc_config() -> + %% SASL utc_log overrides stdlib config - in order to have uniform + %% timestamps in log messages + case application:get_env(sasl, utc_log) of + {ok, Val} when is_boolean(Val) -> Val; + _ -> + case application:get_env(stdlib, utc_log) of + {ok, Val} when is_boolean(Val) -> Val; + _ -> false + end + end. + +offset_to_utc(Z) when Z=:=0; Z=:="z"; Z=:="Z" -> + true; +offset_to_utc([$+|Tz]) -> + case io_lib:fread("~d:~d", Tz) of + {ok, [0, 0], []} -> + true; + _ -> + false + end; +offset_to_utc(_) -> + false. + +check_config(Config) when is_map(Config) -> + do_check_config(maps:to_list(Config)); +check_config(Config) -> + {error,{invalid_formatter_config,?MODULE,Config}}. + +do_check_config([{Type,L}|Config]) when Type == chars_limit; + Type == depth; + Type == max_size -> + case check_limit(L) of + ok -> do_check_config(Config); + error -> {error,{invalid_formatter_config,?MODULE,{Type,L}}} + end; +do_check_config([{single_line,SL}|Config]) when is_boolean(SL) -> + do_check_config(Config); +do_check_config([{legacy_header,LH}|Config]) when is_boolean(LH) -> + do_check_config(Config); +do_check_config([{report_cb,RCB}|Config]) when is_function(RCB,1) -> + do_check_config(Config); +do_check_config([{template,T}|Config]) when is_list(T) -> + case lists:all(fun(X) when is_atom(X) -> true; + (X) when is_tuple(X), is_atom(element(1,X)) -> true; + (X) when is_list(X) -> io_lib:printable_unicode_list(X); + (_) -> false + end, + T) of + true -> + do_check_config(Config); + false -> + {error,{invalid_formatter_template,?MODULE,T}} + end; +do_check_config([{time_offset,Offset}|Config]) -> + case check_offset(Offset) of + ok -> + do_check_config(Config); + error -> + {error,{invalid_formatter_config,?MODULE,{time_offset,Offset}}} + end; +do_check_config([{time_designator,Char}|Config]) when Char>=0, Char=<255 -> + case io_lib:printable_latin1_list([Char]) of + true -> + do_check_config(Config); + false -> + {error,{invalid_formatter_config,?MODULE,{time_designator,Char}}} + end; +do_check_config([C|_]) -> + {error,{invalid_formatter_config,?MODULE,C}}; +do_check_config([]) -> + ok. + +check_limit(L) when is_integer(L), L>0 -> + ok; +check_limit(unlimited) -> + ok; +check_limit(_) -> + error. + +check_offset(I) when is_integer(I) -> + ok; +check_offset(Tz) when Tz=:=""; Tz=:="Z"; Tz=:="z" -> + ok; +check_offset([Sign|Tz]) when Sign=:=$+; Sign=:=$- -> + check_timezone(Tz); +check_offset(_) -> + error. + +check_timezone(Tz) -> + try io_lib:fread("~d:~d", Tz) of + {ok, [_, _], []} -> + ok; + _ -> + error + catch _:_ -> + error + end. diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl index 7caad366ae..901c4c0dad 100644 --- a/lib/kernel/src/logger_h_common.erl +++ b/lib/kernel/src/logger_h_common.erl @@ -135,7 +135,8 @@ call_cast_or_drop(Name, Bin) -> _:{timeout,_} -> ?observe(Name,{dropped,1}) end; - drop -> ?observe(Name,{dropped,1}) + drop -> + ?observe(Name,{dropped,1}) catch %% if the ETS table doesn't exist (maybe because of a %% handler restart), we can only drop the request @@ -152,12 +153,15 @@ check_load(State = #{id:=Name, mode := Mode, flush_reqs_qlen := FlushQLen}) -> {_,Mem} = process_info(self(), memory), ?observe(Name,{max_mem,Mem}), - %% make sure the handler process doesn't get scheduled - %% out between the message_queue_len check below and the - %% action that follows (flush or write). {_,QLen} = process_info(self(), message_queue_len), ?observe(Name,{max_qlen,QLen}), - + %% When the handler process gets scheduled in, it's impossible + %% to predict the QLen. We could jump "up" arbitrarily from say + %% async to sync, async to drop, sync to flush, etc. However, when + %% the handler process manages the log requests (without flushing), + %% one after the other, we will move "down" from drop to sync and + %% from sync to async. This way we don't risk getting stuck in + %% drop or sync mode with an empty mailbox. {Mode1,_NewDrops,_NewFlushes} = if QLen >= FlushQLen -> @@ -292,7 +296,7 @@ overload_levels_ok(HandlerConfig) -> TSQL = maps:get(toggle_sync_qlen, HandlerConfig, ?TOGGLE_SYNC_QLEN), DNRQL = maps:get(drop_new_reqs_qlen, HandlerConfig, ?DROP_NEW_REQS_QLEN), FRQL = maps:get(flush_reqs_qlen, HandlerConfig, ?FLUSH_REQS_QLEN), - (TSQL < DNRQL) andalso (DNRQL < FRQL). + (DNRQL > 1) andalso (TSQL =< DNRQL) andalso (DNRQL =< FRQL). error_notify(Term) -> ?internal_log(error, Term). diff --git a/lib/kernel/src/logger_h_common.hrl b/lib/kernel/src/logger_h_common.hrl index 89378dbb10..ed365ce6eb 100644 --- a/lib/kernel/src/logger_h_common.hrl +++ b/lib/kernel/src/logger_h_common.hrl @@ -124,7 +124,7 @@ %%% slow down execution and therefore should not be include in code %%% to be officially released. -%% -define(TEST_HOOKS, true). +-define(TEST_HOOKS, true). -ifdef(TEST_HOOKS). -define(TEST_HOOKS_TAB, logger_h_test_hooks). diff --git a/lib/kernel/src/logger_internal.hrl b/lib/kernel/src/logger_internal.hrl index 8c0fc2725d..f9377259f3 100644 --- a/lib/kernel/src/logger_internal.hrl +++ b/lib/kernel/src/logger_internal.hrl @@ -22,7 +22,7 @@ -define(LOGGER_KEY,'$logger_config$'). -define(HANDLER_KEY,'$handler_config$'). -define(LOGGER_META_KEY,'$logger_metadata$'). --define(STANDARD_HANDLER, logger_std_h). +-define(STANDARD_HANDLER, default). -define(DEFAULT_HANDLER_FILTERS, ?DEFAULT_HANDLER_FILTERS([beam,erlang,otp])). -define(DEFAULT_HANDLER_FILTERS(Domain), diff --git a/lib/kernel/src/logger_server.erl b/lib/kernel/src/logger_server.erl index a7f302ac8f..275b9c476f 100644 --- a/lib/kernel/src/logger_server.erl +++ b/lib/kernel/src/logger_server.erl @@ -27,7 +27,7 @@ add_filter/2, remove_filter/2, set_module_level/2, reset_module_level/1, cache_module_level/1, - set_config/2, set_config/3]). + set_config/2, set_config/3, update_config/2]). %% gen_server callbacks -export([init/1, handle_call/3, handle_cast/2, handle_info/2, @@ -36,8 +36,9 @@ -include("logger_internal.hrl"). -define(SERVER, logger). +-define(LOGGER_SERVER_TAG, '$logger_cb_process'). --record(state, {tid}). +-record(state, {tid, async_req, async_req_queue}). %%%=================================================================== %%% API @@ -47,23 +48,18 @@ start_link() -> gen_server:start_link({local, ?SERVER}, ?MODULE, [], []). add_handler(Id,Module,Config0) -> - case sanity_check(logger,handlers,[Id]) of - ok -> - try check_mod(Module) of + try {check_id(Id),check_mod(Module)} of + {ok,ok} -> + case sanity_check(Id,Config0) of ok -> - case sanity_check(Id,Config0) of - ok -> - Default = default_config(Id), - Config = maps:merge(Default,Config0), - call({add_handler,Id,Module,Config}); - Error -> - Error - end - catch throw:Error -> - {error,Error} - end; - Error -> - Error + Default = default_config(Id), + Config = maps:merge(Default,Config0), + call({add_handler,Id,Module,Config}); + Error -> + Error + end + catch throw:Error -> + {error,Error} end. remove_handler(HandlerId) -> @@ -96,10 +92,7 @@ cache_module_level(Module) -> set_config(Owner,Key,Value) -> - case sanity_check(Owner,Key,Value) of - ok -> call({update_config,Owner,#{Key=>Value}}); - Error -> Error - end. + update_config(Owner,#{Key=>Value}). set_config(Owner,Config0) -> case sanity_check(Owner,Config0) of @@ -110,6 +103,14 @@ set_config(Owner,Config0) -> Error end. +update_config(Owner, Config) -> + case sanity_check(Owner,Config) of + ok -> + call({update_config,Owner,Config}); + Error -> + Error + end. + %%%=================================================================== %%% gen_server callbacks %%%=================================================================== @@ -122,93 +123,99 @@ init([]) -> logger_config:create(Tid,logger,LoggerConfig), SimpleConfig0 = maps:merge(default_config(logger_simple), #{filter_default=>stop, - filters=>?DEFAULT_HANDLER_FILTERS, - logger_simple=>#{buffer=>true}}), + filters=>?DEFAULT_HANDLER_FILTERS}), %% If this fails, then the node should crash {ok,SimpleConfig} = logger_simple:adding_handler(logger_simple,SimpleConfig0), logger_config:create(Tid,logger_simple,logger_simple,SimpleConfig), - {ok, #state{tid=Tid}}. - -handle_call({add_handler,Id,Module,HConfig}, _From, #state{tid=Tid}=State) -> - Reply = - case logger_config:exist(Tid,Id) of - true -> - {error,{already_exist,Id}}; - false -> - %% inform the handler - case call_h(Module,adding_handler,[Id,HConfig],{ok,HConfig}) of - {ok,HConfig1} -> - logger_config:create(Tid,Id,Module,HConfig1), - {ok,Config} = do_get_config(Tid,logger), - Handlers = maps:get(handlers,Config,[]), - do_set_config(Tid,logger, - Config#{handlers=>[Id|Handlers]}), - ok; - {error,HReason} -> - {error,{handler_not_added,HReason}} - end - end, - {reply,Reply,State}; -handle_call({remove_handler,HandlerId}, _From, #state{tid=Tid}=State) -> - Reply = - case logger_config:get(Tid,HandlerId) of - {ok,{Module,_}} -> - {ok,Config} = do_get_config(Tid,logger), - Handlers0 = maps:get(handlers,Config,[]), - Handlers = lists:delete(HandlerId,Handlers0), - %% inform the handler - _ = call_h(Module,removing_handler,[HandlerId,Config],ok), - do_set_config(Tid,logger,Config#{handlers=>Handlers}), - logger_config:delete(Tid,HandlerId), - ok; - _ -> - {error,{not_found,HandlerId}} - end, - {reply,Reply,State}; + {ok, #state{tid=Tid, async_req_queue = queue:new()}}. + +handle_call({add_handler,Id,Module,HConfig}, From, #state{tid=Tid}=State) -> + case logger_config:exist(Tid,Id) of + true -> + {reply,{error,{already_exist,Id}},State}; + false -> + call_h_async( + fun() -> + %% inform the handler + call_h(Module,adding_handler,[Id,HConfig],{ok,HConfig}) + end, + fun({ok,HConfig1}) -> + %% We know that the call_h would have loaded the module + %% if it existed, so it is safe here to call function_exported + %% to find out if this is a valid handler + case erlang:function_exported(Module, log, 2) of + true -> + logger_config:create(Tid,Id,Module,HConfig1), + {ok,Config} = do_get_config(Tid,logger), + Handlers = maps:get(handlers,Config,[]), + do_set_config(Tid,logger, + Config#{handlers=>[Id|Handlers]}); + false -> + {error,{invalid_handler, + {function_not_exported, + {Module,log,2}}}} + end; + ({error,HReason}) -> + {error,{handler_not_added,HReason}} + end,From,State) + end; +handle_call({remove_handler,HandlerId}, From, #state{tid=Tid}=State) -> + case logger_config:get(Tid,HandlerId) of + {ok,{Module,HConfig}} -> + {ok,Config} = do_get_config(Tid,logger), + Handlers0 = maps:get(handlers,Config,[]), + Handlers = lists:delete(HandlerId,Handlers0), + call_h_async( + fun() -> + %% inform the handler + call_h(Module,removing_handler,[HandlerId,HConfig],ok) + end, + fun(_Res) -> + do_set_config(Tid,logger,Config#{handlers=>Handlers}), + logger_config:delete(Tid,HandlerId), + ok + end,From,State); + _ -> + {reply,{error,{not_found,HandlerId}},State} + end; handle_call({add_filter,Id,Filter}, _From,#state{tid=Tid}=State) -> Reply = do_add_filter(Tid,Id,Filter), {reply,Reply,State}; handle_call({remove_filter,Id,FilterId}, _From, #state{tid=Tid}=State) -> Reply = do_remove_filter(Tid,Id,FilterId), {reply,Reply,State}; -handle_call({update_config,Id,NewConfig}, _From, #state{tid=Tid}=State) -> - Reply = - case logger_config:get(Tid,Id) of - {ok,{Module,OldConfig}} -> - Config = maps:merge(OldConfig,NewConfig), - case call_h(Module,changing_config,[Id,OldConfig,Config], - {ok,Config}) of - {ok,Config1} -> - do_set_config(Tid,Id,Config1); - Error -> - Error - end; - {ok,OldConfig} -> - Config = maps:merge(OldConfig,NewConfig), - do_set_config(Tid,Id,Config); - Error -> - Error - end, - {reply,Reply,State}; +handle_call({update_config,Id,NewConfig}, From, #state{tid=Tid}=State) -> + case logger_config:get(Tid,Id) of + {ok,{_Module,OldConfig}} -> + Config = maps:merge(OldConfig,NewConfig), + handle_call({set_config,Id,Config}, From, State); + {ok,OldConfig} -> + Config = maps:merge(OldConfig,NewConfig), + {reply,do_set_config(Tid,Id,Config),State}; + Error -> + {reply,Error,State} + end; handle_call({set_config,logger,Config}, _From, #state{tid=Tid}=State) -> - Reply = do_set_config(Tid,logger,Config), - {reply,Reply,State}; -handle_call({set_config,HandlerId,Config}, _From, #state{tid=Tid}=State) -> - Reply = - case logger_config:get(Tid,HandlerId) of - {ok,{Module,OldConfig}} -> - case call_h(Module,changing_config,[HandlerId,OldConfig,Config], - {ok,Config}) of - {ok,Config1} -> - do_set_config(Tid,HandlerId,Config1); - Error -> - Error - end; - _ -> - {error,{not_found,HandlerId}} - end, + {ok,#{handlers:=Handlers}} = logger_config:get(Tid,logger), + Reply = do_set_config(Tid,logger,Config#{handlers=>Handlers}), {reply,Reply,State}; +handle_call({set_config,HandlerId,Config}, From, #state{tid=Tid}=State) -> + case logger_config:get(Tid,HandlerId) of + {ok,{Module,OldConfig}} -> + call_h_async( + fun() -> + call_h(Module,changing_config,[HandlerId,OldConfig,Config], + {ok,Config}) + end, + fun({ok,Config1}) -> + do_set_config(Tid,HandlerId,Config1); + (Error) -> + Error + end,From,State); + _ -> + {reply,{error,{not_found,HandlerId}},State} + end; handle_call({set_module_level,Module,Level}, _From, #state{tid=Tid}=State) -> Reply = logger_config:set_module_level(Tid,Module,Level), {reply,Reply,State}; @@ -216,6 +223,8 @@ handle_call({reset_module_level,Module}, _From, #state{tid=Tid}=State) -> Reply = logger_config:reset_module_level(Tid,Module), {reply,Reply,State}. +handle_cast({async_req_reply,_Ref,_Reply} = Reply,State) -> + call_h_reply(Reply,State); handle_cast({cache_module_level,Module}, #state{tid=Tid}=State) -> logger_config:cache_module_level(Tid,Module), {noreply, State}. @@ -235,11 +244,21 @@ handle_info({log,Level,Report,Meta}, State) -> handle_info({Ref,_Reply},State) when is_reference(Ref) -> %% Assuming this is a timed-out gen_server reply - ignoring {noreply, State}; -handle_info(Unexpected,State) -> +handle_info({'DOWN',_Ref,_Proc,_Pid,_Reason} = Down,State) -> + call_h_reply(Down,State); +handle_info(Unexpected,State) when element(1,Unexpected) == 'EXIT' -> + %% The simple logger will send an 'EXIT' message when it is replaced + %% We may as well ignore all 'EXIT' messages that we get ?LOG_INTERNAL(debug, [{logger,got_unexpected_message}, {process,?SERVER}, {message,Unexpected}]), + {noreply,State}; +handle_info(Unexpected,State) -> + ?LOG_INTERNAL(info, + [{logger,got_unexpected_message}, + {process,?SERVER}, + {message,Unexpected}]), {noreply,State}. terminate(_Reason, _State) -> @@ -249,8 +268,11 @@ terminate(_Reason, _State) -> %%% Internal functions %%%=================================================================== call(Request) -> - case whereis(?SERVER) of - Pid when Pid==self() -> + Action = element(1,Request), + case get(?LOGGER_SERVER_TAG) of + true when + Action == add_handler; Action == remove_handler; + Action == update_config; Action == set_config -> {error,{attempting_syncronous_call_to_self,Request}}; _ -> gen_server:call(?SERVER,Request,?DEFAULT_LOGGER_CALL_TIMEOUT) @@ -301,8 +323,7 @@ do_set_config(Tid,Id,Config) -> default_config(logger) -> #{level=>info, filters=>[], - filter_default=>log, - handlers=>[]}; + filter_default=>log}; default_config(_) -> #{level=>info, filters=>[], @@ -333,9 +354,6 @@ get_type(Id) -> check_config(Owner,[{level,Level}|Config]) -> check_level(Level), check_config(Owner,Config); -check_config(logger,[{handlers,Handlers}|Config]) -> - check_handlers(Handlers), - check_config(logger,Config); check_config(Owner,[{filters,Filters}|Config]) -> check_filters(Filters), check_config(Owner,Config); @@ -373,14 +391,6 @@ check_level(Level) -> throw({invalid_level,Level}) end. -check_handlers([Id|Handlers]) -> - check_id(Id), - check_handlers(Handlers); -check_handlers([]) -> - ok; -check_handlers(Handlers) -> - throw({invalid_handlers,Handlers}). - check_filters([{Id,{Fun,_Args}}|Filters]) when is_atom(Id), is_function(Fun,2) -> check_filters(Filters); check_filters([Filter|_]) -> @@ -395,40 +405,24 @@ check_filter_default(FD) when FD==stop; FD==log -> check_filter_default(FD) -> throw({invalid_filter_default,FD}). -check_formatter({logger_formatter,Config}) when is_map(Config) -> - check_logger_formatter_config(maps:to_list(Config)); -check_formatter({logger_formatter,Config}) -> - throw({invalid_formatter_config,Config}); -check_formatter({Mod,_}) -> - %% no knowledge of other formatters - check_mod(Mod); +check_formatter({Mod,Config}) -> + check_mod(Mod), + try Mod:check_config(Config) of + ok -> ok; + {error,Error} -> throw(Error) + catch + C:R:S -> + case {C,R,S} of + {error,undef,[{Mod,check_config,[Config],_}|_]} -> + ok; + _ -> + throw({callback_crashed, + {C,R,logger:filter_stacktrace(?MODULE,S)}}) + end + end; check_formatter(Formatter) -> throw({invalid_formatter,Formatter}). - -check_logger_formatter_config([{template,T}|Config]) when is_list(T) -> - case lists:all(fun(X) when is_atom(X) -> true; - (X) when is_tuple(X), is_atom(element(1,X)) -> true; - (X) when is_list(X) -> io_lib:printable_unicode_list(X); - (_) -> false - end, - T) of - true -> - check_logger_formatter_config(Config); - false -> - throw({invalid_formatter_template,T}) - end; -check_logger_formatter_config([{legacy_header,LH}|Config]) when is_boolean(LH) -> - check_logger_formatter_config(Config); -check_logger_formatter_config([{single_line,SL}|Config]) when is_boolean(SL) -> - check_logger_formatter_config(Config); -check_logger_formatter_config([{utc,Utc}|Config]) when is_boolean(Utc) -> - check_logger_formatter_config(Config); -check_logger_formatter_config([C|_]) -> - throw({invalid_formatter_config,C}); -check_logger_formatter_config([]) -> - ok. - 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 @@ -440,7 +434,59 @@ call_h(Module, Function, Args, DefRet) -> {error,undef,[{Module,Function,Args,_}|_]} -> DefRet; _ -> - {error,{callback_crashed, - {C,R,logger:filter_stacktrace(?MODULE,S)}}} + ST = logger:filter_stacktrace(?MODULE,S), + ?LOG_INTERNAL(error, + [{logger,callback_crashed}, + {process,?SERVER}, + {reason,{C,R,ST}}]), + {error,{callback_crashed,{C,R,ST}}} end end. + +%% There are all sort of API functions that can cause deadlocks if called +%% from the handler callbacks. So we spawn a process that does the request +%% for the logger_server. There are still APIs that will cause problems, +%% namely logger:add_handler +call_h_async(AsyncFun,PostFun,From,#state{ async_req = undefined } = State) -> + Parent = self(), + {Pid, Ref} = spawn_monitor( + fun() -> + put(?LOGGER_SERVER_TAG,true), + receive Ref -> Ref end, + gen_server:cast(Parent, {async_req_reply, Ref, AsyncFun()}) + end), + Pid ! Ref, + {noreply,State#state{ async_req = {Ref,PostFun,From} }}; +call_h_async(AsyncFun,PostFun,From,#state{ async_req_queue = Q } = State) -> + {noreply,State#state{ async_req_queue = queue:in({AsyncFun,PostFun,From},Q) }}. + +call_h_reply({async_req_reply,Ref,Reply}, + #state{ async_req = {Ref,PostFun,From}, async_req_queue = Q} = State) -> + erlang:demonitor(Ref,[flush]), + _ = gen_server:reply(From, PostFun(Reply)), + {Value,NewQ} = queue:out(Q), + NewState = State#state{ async_req = undefined, + async_req_queue = NewQ }, + case Value of + {value,{AsyncFun,NPostFun,NFrom}} -> + call_h_async(AsyncFun,NPostFun,NFrom,NewState); + empty -> + {noreply,NewState} + end; +call_h_reply({'DOWN',Ref,_Proc,Pid,Reason}, #state{ async_req = {Ref,_PostFun,_From}} = State) -> + %% This clause should only be triggered if someone explicitly sends an exit signal + %% to the spawned process. It is only here to make sure that the logger_server does + %% not deadlock if that happens. + ?LOG_INTERNAL(error, + [{logger,process_exited}, + {process,Pid}, + {reason,Reason}]), + call_h_reply( + {async_req_reply,Ref,{error,{logger_process_exited,Pid,Reason}}}, + State); +call_h_reply(Unexpected,State) -> + ?LOG_INTERNAL(info, + [{logger,got_unexpected_message}, + {process,?SERVER}, + {message,Unexpected}]), + {noreply,State}. diff --git a/lib/kernel/src/logger_simple.erl b/lib/kernel/src/logger_simple.erl index a1b427b96c..5272455a2d 100644 --- a/lib/kernel/src/logger_simple.erl +++ b/lib/kernel/src/logger_simple.erl @@ -20,37 +20,18 @@ -module(logger_simple). -export([adding_handler/2, removing_handler/2, log/2]). --export([get_buffer/0]). %% This module implements a simple handler for logger. It is the %% default used during system start. %%%----------------------------------------------------------------- -%%% API -get_buffer() -> - case whereis(?MODULE) of - undefined -> - {error,noproc}; - Pid -> - Ref = erlang:monitor(process,Pid), - Pid ! {get_buffer,self()}, - receive - {buffer,Buffer} -> - erlang:demonitor(Ref,[flush]), - {ok,Buffer}; - {'DOWN',Ref,process,Pid,Reason} -> - {error,Reason} - end - end. - -%%%----------------------------------------------------------------- %%% Logger callback adding_handler(?MODULE,Config) -> Me = self(), case whereis(?MODULE) of undefined -> - {Pid,Ref} = spawn_opt(fun() -> init(Me,Config) end, + {Pid,Ref} = spawn_opt(fun() -> init(Me) end, [link,monitor,{message_queue_data,off_heap}]), receive {'DOWN',Ref,process,Pid,Reason} -> @@ -102,48 +83,44 @@ log(_,_) -> %%%----------------------------------------------------------------- %%% Process -init(Starter,Config) -> +init(Starter) -> register(?MODULE,self()), Starter ! {self(),started}, - BufferSize = - case Config of - #{?MODULE:=#{buffer:=true}} -> - 10; - _ -> - infinity - end, - loop(#{buffer_size=>BufferSize,dropped=>0,buffer=>[]},infinity). + loop(#{buffer_size=>10,dropped=>0,buffer=>[]}). -loop(Buffer,Timeout) -> +loop(Buffer) -> receive stop -> - ok; - {get_buffer,From} -> - loop(Buffer#{send_to=>From},0); + %% We replay the logger messages of there is + %% a default handler when the simple handler + %% is removed. + case logger:get_handler_config(default) of + {ok, _} -> + replay_buffer(Buffer); + _ -> + ok + end; {log,#{msg:=_,meta:=#{time:=_}}=Log} -> do_log(Log), - loop(update_buffer(Buffer,Log),Timeout); + loop(update_buffer(Buffer,Log)); _ -> %% Unexpected message - flush it! - loop(Buffer,Timeout) - after Timeout -> - #{dropped:=D,buffer:=B,send_to:=Pid} = Buffer, - LogList = lists:reverse(B) ++ drop_msg(D), - Pid ! {buffer,LogList}, - loop(Buffer#{buffer_size=>infinity, - dropped=>0, - buffer=>[], - send_to=>false}, - infinity) + loop(Buffer) end. -update_buffer(#{buffer_size:=infinity}=Buffer,_Log) -> - Buffer; update_buffer(#{buffer_size:=0,dropped:=D}=Buffer,_Log) -> Buffer#{dropped=>D+1}; update_buffer(#{buffer_size:=S,buffer:=B}=Buffer,Log) -> Buffer#{buffer_size=>S-1,buffer=>[Log|B]}. +replay_buffer(#{ dropped := D, buffer := Buffer }) -> + lists:foreach( + fun F(#{msg := {Tag, Msg}} = L) when Tag =:= string; Tag =:= report -> + F(L#{ msg := Msg }); + F(#{ level := Level, msg := Msg, meta := MD}) -> + logger:log(Level, Msg, MD) + end, lists:reverse(Buffer, drop_msg(D))). + drop_msg(0) -> []; drop_msg(N) -> diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index 31edcfea8b..e5e0febc88 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -257,10 +257,11 @@ init([Name, Config, file_ctrl_sync => FileCtrlSyncInt, last_qlen => 0, last_log_ts => T0, + last_op => sync, burst_win_ts => T0, burst_msg_count => 0}), proc_lib:init_ack({ok,self()}), - gen_server:cast(self(), {repeated_filesync,T0}), + gen_server:cast(self(), repeated_filesync), enter_loop(Config, State1); Error -> logger_h_common:error_notify({init_handler,Name,Error}), @@ -310,12 +311,11 @@ handle_call(filesync, _From, State = #{type := Type, if is_atom(Type) -> {reply, ok, State}; true -> - {reply, file_ctrl_filesync_sync(FileCtrlPid), State} + {reply, file_ctrl_filesync_sync(FileCtrlPid), State#{last_op=>sync}} end; handle_call({change_config,_OldConfig,NewConfig}, _From, - State = #{filesync_repeat_interval := FSyncInt0, - last_log_ts := LastLogTS}) -> + State = #{filesync_repeat_interval := FSyncInt0}) -> HConfig = maps:get(?MODULE, NewConfig, #{}), State1 = maps:merge(State, HConfig), case logger_h_common:overload_levels_ok(State1) of @@ -334,8 +334,7 @@ handle_call({change_config,_OldConfig,NewConfig}, _From, _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, State, undefined)), - gen_server:cast(self(), {repeated_filesync, - LastLogTS}) + gen_server:cast(self(), repeated_filesync) end, {reply, ok, State1}; false -> @@ -365,24 +364,24 @@ handle_cast({log, Bin}, State) -> %% clause gets called repeatedly by the handler. In order to %% guarantee that a filesync *always* happens after the last log %% request, the repeat operation must be active! -handle_cast({repeated_filesync,LastLogTS0}, +handle_cast(repeated_filesync, State = #{type := Type, file_ctrl_pid := FileCtrlPid, filesync_repeat_interval := FSyncInt, - last_log_ts := LastLogTS1}) -> + 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 LastLogTS1 == LastLogTS0 -> + if LastOp == sync -> ok; true -> file_ctrl_filesync_async(FileCtrlPid) end, {ok,TRef} = timer:apply_after(FSyncInt, gen_server,cast, - [self(),{repeated_filesync,LastLogTS1}]), - State#{rep_sync_tref => TRef}; + [self(),repeated_filesync]), + State#{rep_sync_tref => TRef, last_op => sync}; true -> State end, @@ -600,6 +599,7 @@ write(Name, Mode, T1, Bin, _CallOrCast, State1#{mode => Mode1, last_qlen := LastQLen1, last_log_ts => T1, + last_op => write, burst_win_ts => BurstWinT, burst_msg_count => BurstMsgCount1, file_ctrl_sync => diff --git a/lib/kernel/test/Makefile b/lib/kernel/test/Makefile index 8599a3d814..2f637ca9de 100644 --- a/lib/kernel/test/Makefile +++ b/lib/kernel/test/Makefile @@ -79,6 +79,7 @@ MODULES= \ logger_legacy_SUITE \ logger_simple_SUITE \ logger_std_h_SUITE \ + logger_test_lib \ os_SUITE \ pg2_SUITE \ seq_trace_SUITE \ diff --git a/lib/kernel/test/application_SUITE.erl b/lib/kernel/test/application_SUITE.erl index c00fb44c46..988f26280f 100644 --- a/lib/kernel/test/application_SUITE.erl +++ b/lib/kernel/test/application_SUITE.erl @@ -1603,8 +1603,7 @@ get_key(Conf) when is_list(Conf) -> {ok, [{init, [kalle]}, {takeover, []}, {go, [sune]}]} = rpc:call(Cp1, application, get_key, [appinc, start_phases]), {ok, Env} = rpc:call(Cp1, application, get_key, [appinc ,env]), - [{included_applications,[appinc1,appinc2]}, - {own2,val2},{own_env1,value1}] = lists:sort(Env), + [{own2,val2},{own_env1,value1}] = lists:sort(Env), {ok, []} = rpc:call(Cp1, application, get_key, [appinc, modules]), {ok, {application_starter, [ch_sup, {appinc, 41, 43}] }} = rpc:call(Cp1, application, get_key, [appinc, mod]), @@ -1625,8 +1624,7 @@ get_key(Conf) when is_list(Conf) -> {mod, {application_starter, [ch_sup, {appinc, 41, 43}] }}, {start_phases, [{init, [kalle]}, {takeover, []}, {go, [sune]}]}]} = rpc:call(Cp1, application, get_all_key, [appinc]), - [{included_applications,[appinc1,appinc2]}, - {own2,val2},{own_env1,value1}] = lists:sort(Env), + [{own2,val2},{own_env1,value1}] = lists:sort(Env), {ok, "Test of new app file, including appnew"} = gen_server:call({global, {ch,41}}, {get_pid_key, description}), @@ -1643,8 +1641,7 @@ get_key(Conf) when is_list(Conf) -> {ok, [{init, [kalle]}, {takeover, []}, {go, [sune]}]} = gen_server:call({global, {ch,41}}, {get_pid_key, start_phases}), {ok, Env} = gen_server:call({global, {ch,41}}, {get_pid_key, env}), - [{included_applications,[appinc1,appinc2]}, - {own2,val2},{own_env1,value1}] = lists:sort(Env), + [{own2,val2},{own_env1,value1}] = lists:sort(Env), {ok, []} = gen_server:call({global, {ch,41}}, {get_pid_key, modules}), {ok, {application_starter, [ch_sup, {appinc, 41, 43}] }} = @@ -1671,8 +1668,7 @@ get_key(Conf) when is_list(Conf) -> {mod, {application_starter, [ch_sup, {appinc, 41, 43}] }}, {start_phases, [{init, [kalle]}, {takeover, []}, {go, [sune]}]}]} = gen_server:call({global, {ch,41}}, get_pid_all_key), - [{included_applications,[appinc1,appinc2]}, - {own2,val2},{own_env1,value1}] = lists:sort(Env), + [{own2,val2},{own_env1,value1}] = lists:sort(Env), stop_node_nice(Cp1), ok. diff --git a/lib/kernel/test/erl_distribution_SUITE.erl b/lib/kernel/test/erl_distribution_SUITE.erl index 0470f09f29..9c6712ad74 100644 --- a/lib/kernel/test/erl_distribution_SUITE.erl +++ b/lib/kernel/test/erl_distribution_SUITE.erl @@ -244,7 +244,7 @@ illegal(Name) -> test_node(Name) -> test_node(Name, false). test_node(Name, Illigal) -> - ProgName = atom_to_list(lib:progname()), + ProgName = ct:get_progname(), Command = ProgName ++ " -noinput " ++ long_or_short() ++ Name ++ " -eval \"net_adm:ping('" ++ atom_to_list(node()) ++ "')\"" ++ case Illigal of diff --git a/lib/kernel/test/error_logger_warn_SUITE.erl b/lib/kernel/test/error_logger_warn_SUITE.erl index a8087e11f9..ef55a2d339 100644 --- a/lib/kernel/test/error_logger_warn_SUITE.erl +++ b/lib/kernel/test/error_logger_warn_SUITE.erl @@ -480,9 +480,12 @@ rb_utc() -> UtcLog=case application:get_env(sasl,utc_log) of {ok,true} -> true; - _AllOthers -> + {ok,false} -> application:set_env(sasl,utc_log,true), - false + false; + undefined -> + application:set_env(sasl,utc_log,true), + undefined end, application:start(sasl), rb:start([{report_dir, rd()}]), @@ -494,7 +497,12 @@ rb_utc() -> Sum=one_rb_findstr([],"UTC"), rb:stop(), application:stop(sasl), - application:set_env(sasl,utc_log,UtcLog), + case UtcLog of + undefined -> + application:unset_env(sasl,utc_log); + _ -> + application:set_env(sasl,utc_log,UtcLog) + end, stop_node(Node), ok. diff --git a/lib/kernel/test/heart_SUITE.erl b/lib/kernel/test/heart_SUITE.erl index 22db24de5f..e95635b800 100644 --- a/lib/kernel/test/heart_SUITE.erl +++ b/lib/kernel/test/heart_SUITE.erl @@ -168,7 +168,7 @@ reboot(Config) when is_list(Config) -> {ok, Node} = start_check(slave, ?UNIQ_NODE_NAME), ok = rpc:call(Node, heart, set_cmd, - [atom_to_list(lib:progname()) ++ + [ct:get_progname() ++ " -noshell -heart " ++ name(Node) ++ "&"]), rpc:call(Node, init, reboot, []), receive @@ -203,7 +203,7 @@ node_start_immediately_after_crash_test(Config) when is_list(Config) -> [{"ERL_CRASH_DUMP_SECONDS", "0"}]), ok = rpc:call(Node, heart, set_cmd, - [atom_to_list(lib:progname()) ++ + [ct:get_progname() ++ " -noshell -heart " ++ name(Node) ++ "&"]), Mod = exhaust_atoms, @@ -254,7 +254,7 @@ node_start_soon_after_crash_test(Config) when is_list(Config) -> [{"ERL_CRASH_DUMP_SECONDS", "10"}]), ok = rpc:call(Node, heart, set_cmd, - [atom_to_list(lib:progname()) ++ + [ct:get_progname() ++ " -noshell -heart " ++ name(Node) ++ "&"]), Mod = exhaust_atoms, @@ -309,7 +309,7 @@ set_cmd(Config) when is_list(Config) -> clear_cmd(Config) when is_list(Config) -> {ok, Node} = start_check(slave, ?UNIQ_NODE_NAME), ok = rpc:call(Node, heart, set_cmd, - [atom_to_list(lib:progname()) ++ + [ct:get_progname() ++ " -noshell -heart " ++ name(Node) ++ "&"]), rpc:call(Node, init, reboot, []), receive diff --git a/lib/kernel/test/kernel_config_SUITE.erl b/lib/kernel/test/kernel_config_SUITE.erl index 9a4578917d..a21020ff97 100644 --- a/lib/kernel/test/kernel_config_SUITE.erl +++ b/lib/kernel/test/kernel_config_SUITE.erl @@ -76,7 +76,7 @@ sync(Conf) when is_list(Conf) -> %% Reset wall_clock {T1,_} = erlang:statistics(wall_clock), io:format("~p~n", [{t1, T1}]), - Command = lists:concat([lib:progname(), + Command = lists:append([ct:get_progname(), " -detached -sname cp1 ", "-config ", Config, " -env ERL_CRASH_DUMP erl_crash_dump.cp1"]), diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl index f311a9c7ed..e602fa2576 100644 --- a/lib/kernel/test/logger_SUITE.erl +++ b/lib/kernel/test/logger_SUITE.erl @@ -40,18 +40,18 @@ suite() -> [{timetrap,{seconds,30}}]. init_per_suite(Config) -> - case logger:get_handler_config(logger_std_h) of + case logger:get_handler_config(?STANDARD_HANDLER) of {ok,StdH} -> - ok = logger:remove_handler(logger_std_h), - [{logger_std_h,StdH}|Config]; + ok = logger:remove_handler(?STANDARD_HANDLER), + [{default_handler,StdH}|Config]; _ -> Config end. end_per_suite(Config) -> - case ?config(logger_std_h,Config) of + case ?config(default_handler,Config) of {HMod,HConfig} -> - ok = logger:add_handler(logger_std_h,HMod,HConfig); + ok = logger:add_handler(?STANDARD_HANDLER,HMod,HConfig); _ -> ok end. @@ -105,12 +105,12 @@ start_stop(_Config) -> add_remove_handler(_Config) -> register(callback_receiver,self()), - {ok,#{handlers:=Hs0}} = logger:get_logger_config(), + #{handlers:=Hs0} = logger:i(), {error,{not_found,h1}} = logger:get_handler_config(h1), ok = logger:add_handler(h1,?MODULE,#{}), [add] = test_server:messages_get(), - {ok,#{handlers:=Hs}} = logger:get_logger_config(), - [h1|Hs0] = Hs, + #{handlers:=Hs} = logger:i(), + {value,_,Hs0} = lists:keytake(h1,1,Hs), {ok,{?MODULE,#{level:=info,filters:=[],filter_default:=log}}} = % defaults logger:get_handler_config(h1), ok = logger:set_handler_config(h1,filter_default,stop), @@ -124,7 +124,7 @@ add_remove_handler(_Config) -> ok = check_logged(info,"hello",[],?MY_LOC(1)), ok = logger:remove_handler(h1), [remove] = test_server:messages_get(), - {ok,#{handlers:=Hs0}} = logger:get_logger_config(), + #{handlers:=Hs0} = logger:i(), {error,{not_found,h1}} = logger:get_handler_config(h1), {error,{not_found,h1}} = logger:remove_handler(h1), logger:info("hello",[]), @@ -218,33 +218,52 @@ change_config(_Config) -> {ok,{?MODULE,#{level:=info,filter_default:=stop}=C2}} = logger:get_handler_config(h1), false = maps:is_key(custom,C2), - {error,fail} = logger:set_handler_config(h1,#{fail=>true}), + {error,fail} = logger:set_handler_config(h1,#{conf_call=>fun() -> {error,fail} end}), {error,{attempting_syncronous_call_to_self,_}} = logger:set_handler_config( - h1,#{call=>fun() -> logger:set_module_level(?MODULE,debug) end}), + h1,#{conf_call=>fun() -> logger:set_handler_config(?MODULE,#{}) end}), + ok = + logger:set_handler_config( + h1,#{conf_call=>fun() -> logger:set_module_level(?MODULE,debug) end}), {ok,{?MODULE,C2}} = logger:get_handler_config(h1), - %% Change one key only - {error,fail} = logger:set_handler_config(h1,fail,true), + %% Change handler config: Single key + {error,fail} = logger:set_handler_config(h1,conf_call,fun() -> {error,fail} end), ok = logger:set_handler_config(h1,custom,custom), [changing_config] = test_server:messages_get(), {ok,{?MODULE,#{custom:=custom}=C3}} = logger:get_handler_config(h1), C2 = maps:remove(custom,C3), + %% Change handler config: Map + ok = logger:update_handler_config(h1,#{custom=>new_custom}), + [changing_config] = test_server:messages_get(), + {ok,{_,C4}} = logger:get_handler_config(h1), + C4 = C3#{custom:=new_custom}, + + %% Change logger config: Single key + {ok,LConfig0} = logger:get_logger_config(), + ok = logger:set_logger_config(level,warning), + {ok,LConfig1} = logger:get_logger_config(), + LConfig1 = LConfig0#{level:=warning}, + + %% Change logger config: Map + ok = logger:update_logger_config(#{level=>error}), + {ok,LConfig2} = logger:get_logger_config(), + LConfig2 = LConfig1#{level:=error}, + %% Overwrite logger config - check that defaults are added - {ok,LConfig} = logger:get_logger_config(), ok = logger:set_logger_config(#{filter_default=>stop}), - {ok,#{level:=info,filters:=[],handlers:=[],filter_default:=stop}=LC1} = - logger:get_logger_config(), - 4 = maps:size(LC1), - - %% Change one key only - ok = logger:set_logger_config(handlers,[h1]), - {ok,#{level:=info,filters:=[],handlers:=[h1],filter_default:=stop}} = + {ok,#{level:=info,filters:=[],filter_default:=stop}=LC1} = logger:get_logger_config(), + 3 = maps:size(LC1), + %% Check that internal 'handlers' field has not been changed + #{handlers:=HCs} = logger:i(), + HIds1 = [Id || {Id,_,_} <- HCs], + {ok,#{handlers:=HIds2}} = logger_config:get(?LOGGER_TABLE,logger), + HIds1 = lists:sort(HIds2), %% Cleanup - ok = logger:set_logger_config(LConfig), + ok = logger:set_logger_config(LConfig0), [] = test_server:messages_get(), ok. @@ -425,6 +444,7 @@ filter_failed(cleanup,_Config) -> ok. handler_failed(_Config) -> + register(callback_receiver,self()), {error,{invalid_id,1}} = logger:add_handler(1,?MODULE,#{}), {error,{invalid_module,"nomodule"}} = logger:add_handler(h1,"nomodule",#{}), {error,{invalid_handler_config,bad}} = logger:add_handler(h1,?MODULE,bad), @@ -434,26 +454,62 @@ handler_failed(_Config) -> logger:add_handler(h1,?MODULE,#{filter_default=>true}), {error,{invalid_formatter,[]}} = logger:add_handler(h1,?MODULE,#{formatter=>[]}), - ok = logger:add_handler(h1,nomodule,#{filter_default=>log}), + {error,{invalid_handler,_}} = logger:add_handler(h1,nomodule,#{filter_default=>log}), logger:info(?map_rep), check_no_log(), - #{logger:=#{handlers:=Ids1}, - handlers:=H1} = logger:i(), - false = lists:member(h1,Ids1), + #{handlers:=H1} = logger:i(), false = lists:keymember(h1,1,H1), {error,{not_found,h1}} = logger:remove_handler(h1), - ok = logger:add_handler(h2,?MODULE,#{filter_default=>log,crash=>true}), + ok = logger:add_handler(h2,?MODULE,#{filter_default=>log,log_call=>fun() -> a = b end}), {error,{already_exist,h2}} = logger:add_handler(h2,othermodule,#{}), + [add] = test_server:messages_get(), logger:info(?map_rep), - check_no_log(), - #{logger:=#{handlers:=Ids2}, - handlers:=H2} = logger:i(), - false = lists:member(h2,Ids2), + [remove] = test_server:messages_get(), + #{handlers:=H2} = logger:i(), false = lists:keymember(h2,1,H2), {error,{not_found,h2}} = logger:remove_handler(h2), + CallAddHandler = fun() -> logger:add_handler(h2,?MODULE,#{}) end, + CrashHandler = fun() -> a = b end, + KillHandler = fun() -> exit(self(), die) end, + + {error,{handler_not_added,{attempting_syncronous_call_to_self,_}}} = + logger:add_handler(h1,?MODULE,#{add_call=>CallAddHandler}), + {error,{handler_not_added,{callback_crashed,_}}} = + logger:add_handler(h1,?MODULE,#{add_call=>CrashHandler}), + {error,{handler_not_added,{logger_process_exited,_,die}}} = + logger:add_handler(h1,?MODULE,#{add_call=>KillHandler}), + + check_no_log(), + ok = logger:add_handler(h1,?MODULE,#{}), + {error,{attempting_syncronous_call_to_self,_}} = + logger:set_handler_config(h1,#{conf_call=>CallAddHandler}), + {error,{callback_crashed,_}} = + logger:set_handler_config(h1,#{conf_call=>CrashHandler}), + {error,{logger_process_exited,_,die}} = + logger:set_handler_config(h1,#{conf_call=>KillHandler}), + + {error,{attempting_syncronous_call_to_self,_}} = + logger:set_handler_config(h1,conf_call,CallAddHandler), + {error,{callback_crashed,_}} = + logger:set_handler_config(h1,conf_call,CrashHandler), + {error,{logger_process_exited,_,die}} = + logger:set_handler_config(h1,conf_call,KillHandler), + + ok = logger:remove_handler(h1), + [add,remove] = test_server:messages_get(), + + check_no_log(), + ok = logger:add_handler(h1,?MODULE,#{rem_call=>CallAddHandler}), + ok = logger:remove_handler(h1), + ok = logger:add_handler(h1,?MODULE,#{rem_call=>CrashHandler}), + ok = logger:remove_handler(h1), + ok = logger:add_handler(h1,?MODULE,#{rem_call=>KillHandler}), + ok = logger:remove_handler(h1), + [add,add,add] = test_server:messages_get(), + ok. handler_failed(cleanup,_Config) -> @@ -466,10 +522,6 @@ config_sanity_check(_Config) -> {error,{invalid_filter_default,bad}} = logger:set_logger_config(filter_default,bad), {error,{invalid_level,bad}} = logger:set_logger_config(level,bad), - {error,{invalid_handlers,bad}} = logger:set_logger_config(handlers,bad), - {error,{invalid_id,{bad,bad}}} = - logger:set_logger_config(handlers,[{bad,bad}]), - {error,{invalid_id,"bad"}} = logger:set_logger_config(handlers,["bad"]), {error,{invalid_filters,bad}} = logger:set_logger_config(filters,bad), {error,{invalid_filter,bad}} = logger:set_logger_config(filters,[bad]), {error,{invalid_filter,{_,_}}} = @@ -499,29 +551,96 @@ config_sanity_check(_Config) -> logger:set_handler_config(h1,formatter,bad), {error,{invalid_module,{bad}}} = logger:set_handler_config(h1,formatter,{{bad},cfg}), - {error,{invalid_formatter_config,bad}} = + {error,{invalid_formatter_config,logger_formatter,bad}} = logger:set_handler_config(h1,formatter,{logger_formatter,bad}), - {error,{invalid_formatter_config,{bad,bad}}} = + {error,{invalid_formatter_config,logger_formatter,{bad,bad}}} = logger:set_handler_config(h1,formatter,{logger_formatter,#{bad=>bad}}), - {error,{invalid_formatter_config,{template,bad}}} = + {error,{invalid_formatter_config,logger_formatter,{template,bad}}} = logger:set_handler_config(h1,formatter,{logger_formatter, #{template=>bad}}), - {error,{invalid_formatter_template,[1]}} = + {error,{invalid_formatter_template,logger_formatter,[1]}} = logger:set_handler_config(h1,formatter,{logger_formatter, #{template=>[1]}}), ok = logger:set_handler_config(h1,formatter,{logger_formatter, #{template=>[]}}), - {error,{invalid_formatter_config,{single_line,bad}}} = + {error,{invalid_formatter_config,logger_formatter,{single_line,bad}}} = logger:set_handler_config(h1,formatter,{logger_formatter, #{single_line=>bad}}), ok = logger:set_handler_config(h1,formatter,{logger_formatter, #{single_line=>true}}), - {error,{invalid_formatter_config,{legacy_header,bad}}} = + {error,{invalid_formatter_config,logger_formatter,{legacy_header,bad}}} = logger:set_handler_config(h1,formatter,{logger_formatter, #{legacy_header=>bad}}), ok = logger:set_handler_config(h1,formatter,{logger_formatter, #{legacy_header=>true}}), + {error,{invalid_formatter_config,logger_formatter,{report_cb,bad}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{report_cb=>bad}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{report_cb=>fun(R) -> + {"~p",[R]} + end}}), + {error,{invalid_formatter_config,logger_formatter,{chars_limit,bad}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{chars_limit=>bad}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{chars_limit=>unlimited}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{chars_limit=>4}}), + {error,{invalid_formatter_config,logger_formatter,{depth,bad}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{depth=>bad}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{depth=>unlimited}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{depth=>4}}), + {error,{invalid_formatter_config,logger_formatter,{max_size,bad}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{max_size=>bad}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{max_size=>unlimited}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{max_size=>4}}), + ok = logger:set_handler_config(h1,formatter,{module,config}), + {error,{callback_crashed,{error,{badmatch,3},[{?MODULE,check_config,1,_}]}}} = + logger:set_handler_config(h1,formatter,{?MODULE,crash}), ok = logger:set_handler_config(h1,custom,custom), + + %% Old utc parameter is no longer allowed (replaced by time_offset) + {error,{invalid_formatter_config,logger_formatter,{utc,true}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{utc=>true}}), + {error,{invalid_formatter_config,logger_formatter,{time_offset,bad}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>bad}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>0}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>""}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>"Z"}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>"z"}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>"-0:0"}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>"+10:13"}}), + + {error,{invalid_formatter_config,logger_formatter,{time_offset,"+0"}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_offset=>"+0"}}), + + {error,{invalid_formatter_config,logger_formatter,{time_designator,bad}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_designator=>bad}}), + {error,{invalid_formatter_config,logger_formatter,{time_designator,"s"}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_designator=>"s"}}), + {error,{invalid_formatter_config,logger_formatter,{time_designator,0}}} = + logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_designator=>0}}), + ok = logger:set_handler_config(h1,formatter,{logger_formatter, + #{time_designator=>$\s}}), ok. config_sanity_check(cleanup,_Config) -> @@ -720,16 +839,19 @@ check_maps(Expected,Got,What) -> end. %% Handler +adding_handler(_Id,#{add_call:=Fun}) -> + Fun(); adding_handler(_Id,Config) -> maybe_send(add), {ok,Config}. + +removing_handler(_Id,#{rem_call:=Fun}) -> + Fun(); removing_handler(_Id,_Config) -> maybe_send(remove), ok. -changing_config(_Id,_Old,#{call:=Fun}) -> +changing_config(_Id,_Old,#{conf_call:=Fun}) -> Fun(); -changing_config(_Id,_Old,#{fail:=true}) -> - {error,fail}; changing_config(_Id,_Old,Config) -> maybe_send(changing_config), {ok,Config}. @@ -740,8 +862,8 @@ maybe_send(Msg) -> Pid -> Pid ! Msg end. -log(_Log,#{crash:=true}) -> - a=b; +log(_Log,#{log_call:=Fun}) -> + Fun(); log(Log,Config) -> TcProc = maps:get(tc_proc,Config,self()), TcProc ! {Log,Config}, @@ -829,3 +951,8 @@ test_macros(emergency=Level) -> %%% Called by macro ?TRY(X) my_try(Fun) -> try Fun() catch C:R -> {C,R} end. + +check_config(crash) -> + erlang:error({badmatch,3}); +check_config(_) -> + ok. diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl index 63e5b56021..3aa1c3557b 100644 --- a/lib/kernel/test/logger_disk_log_h_SUITE.erl +++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl @@ -31,7 +31,8 @@ end). suite() -> - [{timetrap,{seconds,30}}]. + [{timetrap,{seconds,30}}, + {ct_hooks,[logger_test_lib]}]. init_per_suite(Config) -> timer:start(), % to avoid progress report @@ -327,7 +328,8 @@ formatter_fail(Config) -> logger:add_handler(Name, logger_disk_log_h, HConfig), Pid = whereis(Name), true = is_pid(Pid), - {ok,#{handlers:=H}} = logger:get_logger_config(), + #{handlers:=HC1} = logger:i(), + H = [Id || {Id,_,_} <- HC1], true = lists:member(Name,H), %% Formatter is added automatically @@ -356,7 +358,8 @@ formatter_fail(Config) -> %% Check that handler is still alive and was never dead Pid = whereis(Name), - {ok,#{handlers:=H}} = logger:get_logger_config(), + #{handlers:=HC2} = logger:i(), + H = [Id || {Id,_,_} <- HC2], ok. formatter_fail(cleanup,_Config) -> @@ -369,10 +372,18 @@ config_fail(_Config) -> #{logger_disk_log_h => #{bad => bad}, filter_default=>log, formatter=>{?MODULE,self()}}), - {error,{handler_not_added,{invalid_levels,{42,42,_}}}} = + + {error,{handler_not_added,{invalid_levels,{_,1,_}}}} = + logger:add_handler(?MODULE,logger_disk_log_h, + #{logger_disk_log_h => #{drop_new_reqs_qlen=>1}}), + {error,{handler_not_added,{invalid_levels,{43,42,_}}}} = logger:add_handler(?MODULE,logger_disk_log_h, - #{logger_disk_log_h => #{toggle_sync_qlen=>42, + #{logger_disk_log_h => #{toggle_sync_qlen=>43, drop_new_reqs_qlen=>42}}), + {error,{handler_not_added,{invalid_levels,{_,43,42}}}} = + logger:add_handler(?MODULE,logger_disk_log_h, + #{logger_disk_log_h => #{drop_new_reqs_qlen=>43, + flush_reqs_qlen=>42}}), ok = logger:add_handler(?MODULE,logger_disk_log_h, #{filter_default=>log, @@ -717,7 +728,7 @@ write_failure(Config) -> Log = lists:concat([File,".1"]), ct:pal("Log = ~p", [Log]), - Node = start_h_on_new_node(Config, ?FUNCTION_NAME, File), + Node = start_h_on_new_node(Config, File), 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]), @@ -761,7 +772,7 @@ sync_failure(Config) -> File = filename:join(Dir, FileName), - Node = start_h_on_new_node(Config, ?FUNCTION_NAME, File), + Node = start_h_on_new_node(Config, File), 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]), @@ -801,21 +812,12 @@ sync_failure(cleanup, _Config) -> Nodes = nodes(), [test_server:stop_node(Node) || Node <- Nodes]. -start_h_on_new_node(_Config, Func, File) -> - Pa = filename:dirname(code:which(?MODULE)), - Dest = - case os:type() of - {win32,_} -> - lists:concat([" {disk_log,\\\"",File,"\\\"}"]); - _ -> - lists:concat([" \'{disk_log,\"",File,"\"}\'"]) - end, - Args = lists:concat([" -kernel ",logger_dest,Dest," -pa ",Pa]), - NodeName = lists:concat([?MODULE,"_",Func]), - ct:pal("Starting ~s with ~tp", [NodeName,Args]), - {ok,Node} = test_server:start_node(NodeName, peer, [{args, Args}]), - Pid = rpc:call(Node,erlang,whereis,[?STANDARD_HANDLER]), - true = is_pid(Pid), +start_h_on_new_node(Config, File) -> + {ok,_,Node} = + logger_test_lib:setup( + Config, + [{logger,[{handler,default,logger_disk_log_h, + #{ disk_log_opts => #{ file => File }}}]}]), ok = rpc:call(Node,logger,set_handler_config,[?STANDARD_HANDLER,formatter, {?MODULE,nl}]), Node. @@ -848,62 +850,115 @@ internal_log(Type, Term) -> op_switch_to_sync(Config) -> {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + NumOfReqs = 500, NewHConfig = - HConfig#{logger_disk_log_h => DLHConfig#{toggle_sync_qlen => 3, - drop_new_reqs_qlen => 501, - flush_reqs_qlen => 2000, + HConfig#{logger_disk_log_h => DLHConfig#{toggle_sync_qlen => 2, + drop_new_reqs_qlen => NumOfReqs+1, + flush_reqs_qlen => 2*NumOfReqs, enable_burst_limit => false}}, ok = logger:set_handler_config(?MODULE, NewHConfig), - NumOfReqs = 500, send_burst({n,NumOfReqs}, seq, {chars,79}, info), - NumOfReqs = count_lines(Log), - ok = file:delete(Log). + Lines = count_lines(Log), + ok = file:delete(Log), + NumOfReqs = Lines, + ok. op_switch_to_sync(cleanup, _Config) -> ok = stop_handler(?MODULE). +op_switch_to_drop() -> + [{timetrap,{seconds,180}}]. op_switch_to_drop(Config) -> - {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), - - NewHConfig = - HConfig#{logger_disk_log_h => DLHConfig#{toggle_sync_qlen => 2, - drop_new_reqs_qlen => 3, - flush_reqs_qlen => 600, - enable_burst_limit => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), - NumOfReqs = 500, - send_burst({n,NumOfReqs}, seq, {chars,79}, info), - Logged = count_lines(Log), - ct:pal("Number of messages dropped = ~w (~w)", - [NumOfReqs-Logged,NumOfReqs]), - true = (Logged < NumOfReqs), - ok = file:delete(Log). + Test = + fun() -> + {Log,HConfig,DLHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + NumOfReqs = 300, + Procs = 2, + Bursts = 10, + NewHConfig = + HConfig#{logger_disk_log_h => + DLHConfig#{toggle_sync_qlen => 1, + drop_new_reqs_qlen => 2, + flush_reqs_qlen => Procs*NumOfReqs*Bursts, + enable_burst_limit => false}}, + ok = logger:set_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 + %% bursts to increase the chance of message buildup. + [send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info) || + _ <- lists:seq(1, Bursts)], + Logged = count_lines(Log), + ok= stop_handler(?MODULE), + _ = file:delete(Log), + ct:pal("Number of messages dropped = ~w (~w)", + [Procs*NumOfReqs*Bursts-Logged,Procs*NumOfReqs*Bursts]), + true = (Logged < (Procs*NumOfReqs*Bursts)), + true = (Logged > 0), + ok + end, + %% As it's tricky to get the timing right in only one go, we perform the + %% test repeatedly, hoping that will generate a successful result. + case repeat_until_ok(Test, 10) of + {ok,{Failures,_Result}} -> + ct:log("Failed ~w times before success!", [Failures]); + {fails,Reason} -> + ct:fail(Reason) + end. op_switch_to_drop(cleanup, _Config) -> - ok = stop_handler(?MODULE). + _ = stop_handler(?MODULE). op_switch_to_flush() -> [{timetrap,{minutes,3}}]. op_switch_to_flush(Config) -> - {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + Test = + fun() -> + {Log,HConfig,DLHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + + %% NOTE: it's important that both async and sync + %% requests have been queued when the flush happens + %% (verify with coverage of flush_log_requests/2) - %% it's important that both async and sync requests have been queued - %% when the flush happens (verify with coverage of flush_log_requests/2) - - NewHConfig = - HConfig#{logger_disk_log_h => DLHConfig#{toggle_sync_qlen => 2, - drop_new_reqs_qlen => 99, - flush_reqs_qlen => 100, - enable_burst_limit => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), - NumOfReqs = 1000, - Procs = 500, - send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info), - Logged = count_lines(Log), - ct:pal("Number of messages flushed/dropped = ~w (~w)", - [(NumOfReqs*Procs)-Logged,NumOfReqs*Procs]), - true = (Logged < (NumOfReqs*Procs)), - ok = file:delete(Log). + NewHConfig = + HConfig#{logger_disk_log_h => + DLHConfig#{toggle_sync_qlen => 2, + %% disable drop mode + drop_new_reqs_qlen => 300, + flush_reqs_qlen => 300, + enable_burst_limit => false}}, + ok = logger:set_handler_config(?MODULE, NewHConfig), + NumOfReqs = 1500, + Procs = 10, + Bursts = 10, + %% It sometimes happens that the handler either gets + %% the requests in a slow enough pace so that flushing + %% never occurs, or it gets all messages at once, + %% causing all messages to get flushed (no dropping of + %% sync messages gets tested). Therefore, lets + %% generate a number of bursts to increase the chance + %% of message buildup in some random fashion. + [send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info) || + _ <- lists:seq(1,Bursts)], + Logged = count_lines(Log), + ok= stop_handler(?MODULE), + _ = file:delete(Log), + ct:pal("Number of messages flushed/dropped = ~w (~w)", + [NumOfReqs*Procs*Bursts-Logged,NumOfReqs*Procs*Bursts]), + true = (Logged < (NumOfReqs*Procs*Bursts)), + true = (Logged > 0), + ok + end, + %% As it's tricky to get the timing right in only one go, we perform the + %% test repeatedly, hoping that will generate a successful result. + case repeat_until_ok(Test, 10) of + {ok,{Failures,_Result}} -> + ct:log("Failed ~w times before success!", [Failures]); + {fails,Reason} -> + ct:fail(Reason) + end. op_switch_to_flush(cleanup, _Config) -> - ok = stop_handler(?MODULE). + _ = stop_handler(?MODULE). limit_burst_disabled(Config) -> @@ -987,7 +1042,7 @@ qlen_kill_new(Config) -> {_Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), Pid0 = whereis(?MODULE), {_,Mem0} = process_info(Pid0, memory), - RestartAfter = 2000, + RestartAfter = ?HANDLER_RESTART_AFTER, NewHConfig = HConfig#{logger_disk_log_h => DLHConfig#{enable_kill_overloaded=>true, @@ -1008,7 +1063,7 @@ qlen_kill_new(Config) -> killed -> ct:pal("Slow shutdown, handler process was killed!", []) end, - timer:sleep(RestartAfter + 1000), + timer:sleep(RestartAfter + 2000), true = is_pid(whereis(?MODULE)), ok after @@ -1024,7 +1079,7 @@ mem_kill_new(Config) -> {_Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), Pid0 = whereis(?MODULE), {_,Mem0} = process_info(Pid0, memory), - RestartAfter = 2000, + RestartAfter = ?HANDLER_RESTART_AFTER, NewHConfig = HConfig#{logger_disk_log_h => DLHConfig#{enable_kill_overloaded=>true, @@ -1045,7 +1100,7 @@ mem_kill_new(Config) -> killed -> ct:pal("Slow shutdown, handler process was killed!", []) end, - timer:sleep(RestartAfter * 2), + timer:sleep(RestartAfter + 2000), true = is_pid(whereis(?MODULE)), ok after @@ -1078,7 +1133,7 @@ restart_after(Config) -> end, {Log,_,_} = start_handler(?MODULE, ?FUNCTION_NAME, Config), - RestartAfter = 2000, + RestartAfter = ?HANDLER_RESTART_AFTER, NewHConfig2 = HConfig#{logger_disk_log_h=>DLHConfig#{enable_kill_overloaded=>true, handler_overloaded_qlen=>10, @@ -1090,7 +1145,7 @@ restart_after(Config) -> send_burst({n,100}, {spawn,2,0}, {chars,79}, info), receive {'DOWN', MRef2, _, _, _Info2} -> - timer:sleep(RestartAfter + 1000), + timer:sleep(RestartAfter + 2000), Pid1 = whereis(?MODULE), true = is_pid(Pid1), false = (Pid1 == Pid0), @@ -1361,6 +1416,29 @@ count_lines1(File) -> file:close(Dev), Lines. +repeat_until_ok(Fun, N) -> + repeat_until_ok(Fun, 0, N, undefined). + +repeat_until_ok(_Fun, Stop, Stop, Reason) -> + {fails,Reason}; + +repeat_until_ok(Fun, C, Stop, FirstReason) -> + if C > 0 -> timer:sleep(5000); + true -> ok + end, + try Fun() of + Result -> + {ok,{C,Result}} + catch + _:Reason:Stack -> + ct:pal("Test fails: ~p (~p)~n", [Reason,hd(Stack)]), + if FirstReason == undefined -> + repeat_until_ok(Fun, C+1, Stop, {Reason,Stack}); + true -> + repeat_until_ok(Fun, C+1, Stop, FirstReason) + end + end. + start_tracer(Trace,Expected) -> Pid = self(), dbg:tracer(process,{fun tracer/2,{Pid,Expected}}), @@ -1382,7 +1460,8 @@ tpl([{M,F,A}|Trace]) -> tpl([]) -> ok. -tracer({trace,_,call,{logger_disk_log_h,handle_cast,[{Op,_}|_]}}, {Pid,[{Mod,Func,Op}|Expected]}) -> +tracer({trace,_,call,{logger_disk_log_h,handle_cast,[Op|_]}}, + {Pid,[{Mod,Func,Op}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Op}); tracer({trace,_,call,{Mod=disk_log,Func=blog,[_,Data]}}, {Pid,[{Mod,Func,Data}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Data}); diff --git a/lib/kernel/test/logger_env_var_SUITE.erl b/lib/kernel/test/logger_env_var_SUITE.erl index c2d3364701..764f443634 100644 --- a/lib/kernel/test/logger_env_var_SUITE.erl +++ b/lib/kernel/test/logger_env_var_SUITE.erl @@ -1,4 +1,4 @@ -% +%% %% %CopyrightBegin% %% %% Copyright Ericsson AB 2018. All Rights Reserved. @@ -21,83 +21,65 @@ -compile(export_all). --include_lib("common_test/include/ct.hrl"). -include_lib("kernel/include/logger.hrl"). -include_lib("kernel/src/logger_internal.hrl"). --define(all_vars,[{kernel,logger_dest}, - {kernel,logger_level}, - {kernel,logger_log_progress}, - {kernel,logger_sasl_compatible}, - {kernel,error_logger}]). +-import(logger_test_lib,[setup/2,log/3,sync_and_read/3]). suite() -> - [{timetrap,{seconds,30}}]. + [{timetrap,{seconds,60}}, + {ct_hooks,[logger_test_lib]}]. init_per_suite(Config) -> - Env = [{App,Key,application:get_env(App,Key)} || {App,Key} <- ?all_vars], - Removed = cleanup(), - [{env,Env},{logger,Removed}|Config]. - -end_per_suite(Config) -> - [application:set_env(App,Key,Val) || - {App,Key,Val} <- ?config(env,Config), - Val =/= undefined], - Hs = ?config(logger,Config), - [ok = logger:add_handler(Id,Mod,C) || {Id,Mod,C} <- Hs], - ok. - -init_per_group(_Group, Config) -> - Config. - -end_per_group(_Group, _Config) -> - ok. - -init_per_testcase(_TestCase, Config) -> Config. -end_per_testcase(Case, Config) -> - try apply(?MODULE,Case,[cleanup,Config]) - catch error:undef -> ok - end, - cleanup(), +end_per_suite(_Config) -> ok. groups() -> - []. - -all() -> + [{error_logger,[],[error_logger_tty, + error_logger_tty_sasl_compatible, + error_logger_false, + error_logger_false_progress, + error_logger_false_sasl_compatible, + error_logger_silent, + error_logger_silent_sasl_compatible, + error_logger_file]}, + {logger,[],[logger_file, + logger_file_sasl_compatible, + logger_file_log_progress, + logger_file_no_filter, + logger_file_no_filter_level, + logger_file_formatter, + logger_filters, + logger_filters_stop, + logger_module_level, + logger_disk_log, + logger_disk_log_formatter, + logger_undefined, + logger_many_handlers_default_first, + logger_many_handlers_default_last, + logger_many_handlers_default_last_broken_filter + ]}, + {bad,[],[bad_error_logger, + bad_level, + bad_sasl_compatibility, + bad_progress]}]. + +all() -> [default, default_sasl_compatible, - dest_tty, - dest_tty_sasl_compatible, - dest_false, - dest_false_progress, - dest_false_sasl_compatible, - dest_silent, - dest_silent_sasl_compatible, - dest_file_old, - dest_file, - dest_disk_log, - %% disk_log_vars, % or test this in logger_disk_log_SUITE? sasl_compatible_false, sasl_compatible_false_no_progress, sasl_compatible, - bad_dest%% , - %% bad_level, - %% bad_sasl_compatibility, - %% bad_progress + {group,bad}, + {group,error_logger}, + {group,logger} ]. default(Config) -> - {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, - undefined, - undefined, % dest - undefined, % level - undefined, % sasl comp (default=false) - undefined), % progress (default=false) - {logger_std_h,logger_std_h,StdC} = lists:keyfind(logger_std_h,1,Hs), - true = is_pid(whereis(logger_std_h)), + {ok,#{handlers:=Hs},_Node} = setup(Config,[]), + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), info = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = @@ -105,18 +87,12 @@ default(Config) -> true = lists:keymember(stop_progress,1,StdFilters), false = lists:keymember(logger_simple,1,Hs), false = lists:keymember(sasl_h,1,Hs), - false = is_pid(whereis(sasl_h)), ok. default_sasl_compatible(Config) -> - {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, - undefined, - undefined, % dest - undefined, % level - true, % sasl comp (default=false) - undefined), % progress (default=false) - {logger_std_h,logger_std_h,StdC} = lists:keyfind(logger_std_h,1,Hs), - true = is_pid(whereis(logger_std_h)), + {ok,#{handlers:=Hs},_Node} = setup(Config, + [{logger_sasl_compatible,true}]), + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), info = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), {domain,{_,{log,prefix_of,[beam,erlang,otp]}}} = @@ -124,18 +100,11 @@ default_sasl_compatible(Config) -> false = lists:keymember(stop_progress,1,StdFilters), false = lists:keymember(logger_simple,1,Hs), true = lists:keymember(sasl_h,1,Hs), - true = is_pid(whereis(sasl_h)), ok. -dest_tty(Config) -> - {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - tty, % dest - undefined, % level - undefined, % sasl comp (default=false) - undefined), % progress (default=false) - {logger_std_h,logger_std_h,StdC} = lists:keyfind(logger_std_h,1,Hs), - true = is_pid(whereis(logger_std_h)), +error_logger_tty(Config) -> + {ok,#{handlers:=Hs},_Node} = setup(Config,[{error_logger,tty}]), + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), info = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = @@ -143,18 +112,13 @@ dest_tty(Config) -> true = lists:keymember(stop_progress,1,StdFilters), false = lists:keymember(logger_simple,1,Hs), false = lists:keymember(sasl_h,1,Hs), - false = is_pid(whereis(sasl_h)), ok. -dest_tty_sasl_compatible(Config) -> - {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - tty, % dest - undefined, % level - true, % sasl comp (default=false) - undefined), % progress (default=false) - {logger_std_h,logger_std_h,StdC} = lists:keyfind(logger_std_h,1,Hs), - true = is_pid(whereis(logger_std_h)), +error_logger_tty_sasl_compatible(Config) -> + {ok,#{handlers:=Hs},_Node} = setup(Config, + [{error_logger,tty}, + {logger_sasl_compatible,true}]), + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), info = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), {domain,{_,{log,prefix_of,[beam,erlang,otp]}}} = @@ -162,19 +126,17 @@ dest_tty_sasl_compatible(Config) -> false = lists:keymember(stop_progress,1,StdFilters), false = lists:keymember(logger_simple,1,Hs), true = lists:keymember(sasl_h,1,Hs), - true = is_pid(whereis(sasl_h)), ok. -dest_false(Config) -> - {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - false, % dest - notice, % level - undefined, % sasl comp (default=false) - undefined), % progress (default=false) - false = lists:keymember(logger_std_h,1,Hs), +error_logger_false(Config) -> + {ok,#{handlers:=Hs,logger:=L},_Node} = + setup(Config, + [{error_logger,false}, + {logger_level,notice}]), + false = lists:keymember(?STANDARD_HANDLER,1,Hs), {logger_simple,logger_simple,SimpleC} = lists:keyfind(logger_simple,1,Hs), - notice = maps:get(level,SimpleC), + info = maps:get(level,SimpleC), + notice = maps:get(level,L), SimpleFilters = maps:get(filters,SimpleC), {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = lists:keyfind(domain,1,SimpleFilters), @@ -182,16 +144,16 @@ dest_false(Config) -> false = lists:keymember(sasl_h,1,Hs), ok. -dest_false_progress(Config) -> - {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - false, % dest - notice, % level - undefined, % sasl comp (default=false) - true), % progress (default=false) - false = lists:keymember(logger_std_h,1,Hs), +error_logger_false_progress(Config) -> + {ok,#{handlers:=Hs,logger:=L},_Node} = + setup(Config, + [{error_logger,false}, + {logger_level,notice}, + {logger_log_progress,true}]), + false = lists:keymember(?STANDARD_HANDLER,1,Hs), {logger_simple,logger_simple,SimpleC} = lists:keyfind(logger_simple,1,Hs), - notice = maps:get(level,SimpleC), + info = maps:get(level,SimpleC), + notice = maps:get(level,L), SimpleFilters = maps:get(filters,SimpleC), {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = lists:keyfind(domain,1,SimpleFilters), @@ -199,253 +161,496 @@ dest_false_progress(Config) -> false = lists:keymember(sasl_h,1,Hs), ok. -dest_false_sasl_compatible(Config) -> - {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - false, % dest - notice, % level - true, % sasl comp (default=false) - undefined), % progress (default=false) - false = lists:keymember(logger_std_h,1,Hs), +error_logger_false_sasl_compatible(Config) -> + {ok,#{handlers:=Hs,logger:=L},_Node} = + setup(Config, + [{error_logger,false}, + {logger_level,notice}, + {logger_sasl_compatible,true}]), + false = lists:keymember(?STANDARD_HANDLER,1,Hs), {logger_simple,logger_simple,SimpleC} = lists:keyfind(logger_simple,1,Hs), - notice = maps:get(level,SimpleC), + info = maps:get(level,SimpleC), + notice = maps:get(level,L), SimpleFilters = maps:get(filters,SimpleC), {domain,{_,{log,prefix_of,[beam,erlang,otp]}}} = lists:keyfind(domain,1,SimpleFilters), false = lists:keymember(stop_progress,1,SimpleFilters), true = lists:keymember(sasl_h,1,Hs), - true = is_pid(whereis(sasl_h)), ok. -dest_silent(Config) -> - {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - silent, % dest - undefined, % level - undefined, % sasl comp (default=false) - undefined), % progress (default=false) - false = lists:keymember(logger_std_h,1,Hs), +error_logger_silent(Config) -> + {ok,#{handlers:=Hs},_Node} = setup(Config, + [{error_logger,silent}]), + false = lists:keymember(?STANDARD_HANDLER,1,Hs), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + ok. + +error_logger_silent_sasl_compatible(Config) -> + {ok,#{handlers:=Hs},_Node} = setup(Config, + [{error_logger,silent}, + {logger_sasl_compatible,true}]), + false = lists:keymember(?STANDARD_HANDLER,1,Hs), + false = lists:keymember(logger_simple,1,Hs), + true = lists:keymember(sasl_h,1,Hs), + ok. + + +error_logger_file(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,_Hs,Node} = setup(Config, + [{error_logger,{file,Log}}]), + check_default_log(Node,Log, + file,% dest + 0),% progress in std logger + ok. + + +logger_file(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs},Node} + = setup(Config, + [{logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{logger_std_h=>#{type=>{file,Log}}}}]}]), + check_default_log(Node,Log, + file,% dest + 0),% progress in std logger + + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + StdFilters = maps:get(filters,StdC), + {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = + lists:keyfind(domain,1,StdFilters), + true = lists:keymember(stop_progress,1,StdFilters), false = lists:keymember(logger_simple,1,Hs), false = lists:keymember(sasl_h,1,Hs), + ok. -dest_silent_sasl_compatible(Config) -> - {ok,{_Log,Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - silent, % dest - undefined, % level - true, % sasl comp (default=false) - undefined), % progress (default=false) - false = lists:keymember(logger_std_h,1,Hs), +logger_file_sasl_compatible(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs},Node} + = setup(Config, + [{logger_sasl_compatible,true}, + {logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{logger_std_h=>#{type=>{file,Log}}}}]}]), + check_default_log(Node,Log, + file,% dest + 0),% progress in std logger + + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + StdFilters = maps:get(filters,StdC), + {domain,{_,{log,prefix_of,[beam,erlang,otp]}}} = + lists:keyfind(domain,1,StdFilters), + false = lists:keymember(stop_progress,1,StdFilters), false = lists:keymember(logger_simple,1,Hs), true = lists:keymember(sasl_h,1,Hs), - true = is_pid(whereis(sasl_h)), + + ok. + +logger_file_log_progress(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs},Node} + = setup(Config, + [{logger_log_progress,true}, + {logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{logger_std_h=>#{type=>{file,Log}}}}]}]), + check_default_log(Node,Log, + file,% dest + 6),% progress in std logger + + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + StdFilters = maps:get(filters,StdC), + {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = + lists:keyfind(domain,1,StdFilters), + false = lists:keymember(stop_progress,1,StdFilters), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + + ok. + +logger_file_no_filter(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs},Node} + = setup(Config, + [{logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{filter_default=>log,filters=>[], + logger_std_h=>#{type=>{file,Log}}}}]}]), + check_default_log(Node,Log, + file,% dest + 6),% progress in std logger + + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + [] = maps:get(filters,StdC), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + + ok. + +logger_file_no_filter_level(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs},Node} + = setup(Config, + [{logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{filters=>[],level=>error, + logger_std_h=>#{type=>{file,Log}}}}]}]), + check_default_log(Node,Log, + file,% dest + 0,% progress in std logger + error),% level + + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + error = maps:get(level,StdC), + [] = maps:get(filters,StdC), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + + ok. + +logger_file_formatter(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs},Node} + = setup(Config, + [{logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{filters=>[], + formatter=>{logger_formatter,#{}}, + logger_std_h=>#{type=>{file,Log}}}}]}]), + check_single_log(Node,Log, + file,% dest + 6),% progress in std logger + + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + [] = maps:get(filters,StdC), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + + ok. + +logger_filters(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs,logger:=Logger},Node} + = setup(Config, + [{logger_log_progress,true}, + {logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{logger_std_h=>#{type=>{file,Log}}}}, + {filters,log,[{stop_progress,{fun logger_filters:progress/2,stop}}]} + ]}]), + check_default_log(Node,Log, + file,% dest + 0),% progress in std logger + + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + StdFilters = maps:get(filters,StdC), + {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = + lists:keyfind(domain,1,StdFilters), + false = lists:keymember(stop_progress,1,StdFilters), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + LoggerFilters = maps:get(filters,Logger), + true = lists:keymember(stop_progress,1,LoggerFilters), + + ok. + +logger_filters_stop(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs,logger:=Logger},Node} + = setup(Config, + [{logger_log_progress,true}, + {logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{filters=>[], + logger_std_h=>#{type=>{file,Log}}}}, + {filters,stop,[{log_error,{fun logger_filters:level/2,{log,gt,info}}}]} + ]}]), + check_default_log(Node,Log, + file,% dest + 0, + notice),% progress in std logger + + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + [] = maps:get(filters,StdC), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + LoggerFilters = maps:get(filters,Logger), + true = lists:keymember(log_error,1,LoggerFilters), + + ok. + +logger_module_level(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs,module_levels:=ModuleLevels},Node} + = setup(Config, + [{logger_log_progress,true}, + {logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{logger_std_h=>#{type=>{file,Log}}}}, + {module_level,error,[supervisor]} + ]}]), + check_default_log(Node,Log, + file,% dest + 3),% progress in std logger + + {?STANDARD_HANDLER,logger_std_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + StdFilters = maps:get(filters,StdC), + {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = + lists:keyfind(domain,1,StdFilters), + false = lists:keymember(stop_progress,1,StdFilters), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + [{supervisor,error}] = ModuleLevels, + ok. + +logger_disk_log(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs},Node} + = setup(Config, + [{logger, + [{handler,?STANDARD_HANDLER,logger_disk_log_h, + #{disk_log_opts=>#{file=>Log}}}]}]), + check_default_log(Node,Log, + disk_log,% dest + 0),% progress in std logger + + {?STANDARD_HANDLER,logger_disk_log_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + StdFilters = maps:get(filters,StdC), + {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = + lists:keyfind(domain,1,StdFilters), + true = lists:keymember(stop_progress,1,StdFilters), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), + ok. +logger_disk_log_formatter(Config) -> + Log = file(Config,?FUNCTION_NAME), + {ok,#{handlers:=Hs},Node} + = setup(Config, + [{logger, + [{handler,?STANDARD_HANDLER,logger_disk_log_h, + #{filters=>[], + formatter=>{logger_formatter,#{}}, + disk_log_opts=>#{file=>Log}}}]}]), + check_single_log(Node,Log, + disk_log,% dest + 6),% progress in std logger + + {?STANDARD_HANDLER,logger_disk_log_h,StdC} = lists:keyfind(?STANDARD_HANDLER,1,Hs), + info = maps:get(level,StdC), + [] = maps:get(filters,StdC), + false = lists:keymember(logger_simple,1,Hs), + false = lists:keymember(sasl_h,1,Hs), -dest_file_old(Config) -> - {ok,{Log,_Hs}} = setup(Config,?FUNCTION_NAME, - error_logger, - file, % dest - undefined, % level - undefined, % sasl comp (default=false) - undefined), % progress (default=false) - check_log(Log, - file, % dest - 0), % progress in std logger ok. - - -dest_file(Config) -> - {ok,{Log,_Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - file, % dest - undefined, % level - undefined, % sasl comp (default=false) - undefined), % progress (default=false) - check_log(Log, - file, % dest - 0), % progress in std logger + +logger_undefined(Config) -> + {ok,#{handlers:=Hs,logger:=L},_Node} = + setup(Config,[{logger,[{handler,?STANDARD_HANDLER,undefined}]}]), + false = lists:keymember(?STANDARD_HANDLER,1,Hs), + {logger_simple,logger_simple,SimpleC} = lists:keyfind(logger_simple,1,Hs), + info = maps:get(level,SimpleC), + info = maps:get(level,L), + SimpleFilters = maps:get(filters,SimpleC), + {domain,{_,{log,prefix_of,[beam,erlang,otp,sasl]}}} = + lists:keyfind(domain,1,SimpleFilters), + true = lists:keymember(stop_progress,1,SimpleFilters), + false = lists:keymember(sasl_h,1,Hs), ok. - - -dest_disk_log(Config) -> - {ok,{Log,_Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - disk_log, % dest - undefined, % level - undefined, % sasl comp (default=false) - undefined), % progress (default=false) - check_log(Log, - disk_log, % dest - 0), % progress in std logger + + +%% Test that we can add multiple handlers with the default first +logger_many_handlers_default_first(Config) -> + LogErr = file(Config,logger_many_handlers_default_first_error), + LogInfo = file(Config,logger_many_handlers_default_first_info), + + logger_many_handlers( + Config,[{logger, + [{handler,?STANDARD_HANDLER,logger_std_h, + #{level=>error, + filters=>[], + formatter=>{logger_formatter,#{}}, + logger_std_h=>#{type=>{file,LogErr}}} + }, + {handler,info,logger_std_h, + #{level=>info, + filters=>[{level,{fun logger_filters:level/2,{stop,gteq,error}}}], + logger_std_h=>#{type=>{file,LogInfo}}} + } + ]}], LogErr, LogInfo, 6). + +%% Test that we can add multiple handlers with the default last +logger_many_handlers_default_last(Config) -> + LogErr = file(Config,logger_many_handlers_default_last_error), + LogInfo = file(Config,logger_many_handlers_default_last_info), + logger_many_handlers( + Config,[{logger, + [{handler,info,logger_std_h, + #{level=>info, + filters=>[{level,{fun logger_filters:level/2,{stop,gteq,error}}}], + logger_std_h=>#{type=>{file,LogInfo}}} + }, + {handler,?STANDARD_HANDLER,logger_std_h, + #{level=>error, + filters=>[], + formatter=>{logger_formatter,#{}}, + logger_std_h=>#{type=>{file,LogErr}}} + } + ]}], LogErr, LogInfo, 7). + +%% Check that we can handle that an added logger has a broken filter +%% This used to cause a deadlock. +logger_many_handlers_default_last_broken_filter(Config) -> + LogErr = file(Config,logger_many_handlers_default_first_broken_filter_error), + LogInfo = file(Config,logger_many_handlers_default_first_broken_filter_info), + + logger_many_handlers( + Config,[{logger, + [{handler,info,logger_std_h, + #{level=>info, + filters=>[{broken,{fun logger_filters:level/2,broken_state}}, + {level,{fun logger_filters:level/2,{stop,gteq,error}}}], + logger_std_h=>#{type=>{file,LogInfo}}} + }, + {handler,?STANDARD_HANDLER,logger_std_h, + #{level=>error, + filters=>[], + formatter=>{logger_formatter,#{}}, + logger_std_h=>#{type=>{file,LogErr}}} + } + ]}], LogErr, LogInfo, 7). + +logger_many_handlers(Config, Env, LogErr, LogInfo, NumProgress) -> + {ok,#{handlers:=Hs},Node} = setup(Config,Env), + check_single_log(Node,LogErr, + file,% dest + 0,% progress in std logger + error), % level + ok = rpc:call(Node,logger_std_h,filesync,[info]), + {ok, Bin} = file:read_file(LogInfo), + ct:log("Log content:~n~s",[Bin]), + match(Bin,<<"PROGRESS REPORT">>,NumProgress,info,info), + match(Bin,<<"ALERT REPORT">>,0,alert,info), + ok. - sasl_compatible_false(Config) -> - {ok,{Log,_Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - file, % dest - undefined, % level - false, % sasl comp - true), % progress - check_log(Log, - file, % dest - 4), % progress in std logger + Log = file(Config,?FUNCTION_NAME), + {ok,_Hs,Node} = setup(Config, + [{error_logger,{file,Log}}, + {logger_sasl_compatible,false}, + {logger_log_progress,true}]), + check_default_log(Node,Log, + file,% dest + 6),% progress in std logger ok. sasl_compatible_false_no_progress(Config) -> - {ok,{Log,_Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - file, % dest - undefined, % level - false, % sasl comp - false), % progress - check_log(Log, - file, % dest - 0), % progress in std logger + Log = file(Config,?FUNCTION_NAME), + {ok,_Hs,Node} = setup(Config, + [{error_logger,{file,Log}}, + {logger_sasl_compatible,false}, + {logger_log_progress,false}]), + check_default_log(Node,Log, + file,% dest + 0),% progress in std logger ok. sasl_compatible(Config) -> - {ok,{Log,_Hs}} = setup(Config,?FUNCTION_NAME, - logger_dest, - file, % dest - undefined, % level - true, % sasl comp - undefined), % progress - check_log(Log, - file, % dest - 0), % progress in std logger + Log = file(Config,?FUNCTION_NAME), + {ok,_Hs,Node} = setup(Config, + [{error_logger,{file,Log}}, + {sasl_compatible,true}]), + check_default_log(Node,Log, + file,% dest + 0),% progress in std logger ok. -bad_dest(Config) -> - {error,{bad_config,{kernel,{logger_dest,baddest}}}} = - setup(Config,?FUNCTION_NAME, - logger_dest, - baddest, - undefined, - undefined, - undefined). +bad_error_logger(Config) -> + error = setup(Config,[{error_logger,baddest}]). bad_level(Config) -> - error = - setup(Config,?FUNCTION_NAME, - logger_dest, - tty, - badlevel, - undefined, - undefined). + error = setup(Config,[{logger_level,badlevel}]). bad_sasl_compatibility(Config) -> - error = - setup(Config,?FUNCTION_NAME, - logger_dest, - tty, - info, - badcomp, - undefined). + error = setup(Config,[{logger_sasl_compatible,badcomp}]). bad_progress(Config) -> - error = - setup(Config,?FUNCTION_NAME, - logger_dest, - tty, - info, - undefined, - badprogress). + error = setup(Config,[{logger_log_progress,badprogress}]). %%%----------------------------------------------------------------- %%% Internal -setup(Config,Func,DestVar,Dest,Level,SaslComp,Progress) -> - ok = logger:add_handler(logger_simple,logger_simple, - #{filter_default=>log, - logger_simple=>#{buffer=>true}}), - Dir = ?config(priv_dir,Config), - File = lists:concat([?MODULE,"_",Func,".log"]), - Log = filename:join(Dir,File), - case Dest of - undefined -> - ok; - F when F==file; F==disk_log -> - application:set_env(kernel,DestVar,{Dest,Log}); - _ -> - application:set_env(kernel,DestVar,Dest) - end, - case Level of - undefined -> - ok; - _ -> - application:set_env(kernel,logger_level,Level) - end, - case SaslComp of - undefined -> - ok; - _ -> - application:set_env(kernel,logger_sasl_compatible,SaslComp) - end, - case Progress of - undefined -> - ok; - _ -> - application:set_env(kernel,logger_log_progress,Progress) - end, - case logger:setup_standard_handler() of - ok -> - application:start(sasl), - StdH = case Dest of - NoH when NoH==false; NoH==silent -> false; - _ -> true - end, - StdH = is_pid(whereis(?STANDARD_HANDLER)), - SaslH = if SaslComp -> true; - true -> false - end, - SaslH = is_pid(whereis(sasl_h)), - {ok,{Log,maps:get(handlers,logger:i())}}; - Error -> - Error - end. +file(Config,Func) -> + filename:join(proplists:get_value(priv_dir,Config), + lists:concat([Func,".log"])). + +check_default_log(Node,Log,Dest,NumProgress) -> + check_default_log(Node,Log,Dest,NumProgress,info). +check_default_log(Node,Log,Dest,NumProgress,Level) -> + + {ok,Bin1,Bin2} = check_log(Node,Log,Dest), + + match(Bin1,<<"PROGRESS REPORT">>,NumProgress,info,Level), + match(Bin1,<<"ALERT REPORT">>,1,alert,Level), + match(Bin1,<<"INFO REPORT">>,0,info,Level), + match(Bin1,<<"DEBUG REPORT">>,0,debug,Level), + + match(Bin2,<<"INFO REPORT">>,1,info,Level), + match(Bin2,<<"DEBUG REPORT">>,0,debug,Level), + ok. + +check_single_log(Node,Log,Dest,NumProgress) -> + check_single_log(Node,Log,Dest,NumProgress,info). +check_single_log(Node,Log,Dest,NumProgress,Level) -> + + {ok,Bin1,Bin2} = check_log(Node,Log,Dest), -check_log(Log,Dest,NumProgress) -> - ok = logger:alert("dummy1"), - ok = logger:debug("dummy1"), + match(Bin1,<<"info:">>,NumProgress,info,Level), + match(Bin1,<<"alert:">>,1,alert,Level), + match(Bin1,<<"debug:">>,0,debug,Level), + + match(Bin2,<<"info:">>,NumProgress+1,info,Level), + match(Bin2,<<"debug:">>,0,debug,Level), + + ok. + +check_log(Node,Log,Dest) -> + + ok = log(Node,alert,["dummy1"]), + ok = log(Node,debug,["dummy1"]), %% Check that there are progress reports (supervisor and %% application_controller) and an error report (the call above) in %% the log. There should not be any info reports yet. - {ok,Bin1} = sync_and_read(Dest,Log), + {ok,Bin1} = sync_and_read(Node,Dest,Log), ct:log("Log content:~n~s",[Bin1]), - match(Bin1,<<"PROGRESS REPORT">>,NumProgress), - match(Bin1,<<"ALERT REPORT">>,1), - match(Bin1,<<"INFO REPORT">>,0), - match(Bin1,<<"DEBUG REPORT">>,0), %% Then stop sasl and see that the info report from %% application_controller is there - ok = application:stop(sasl), - {ok,Bin2} = sync_and_read(Dest,Log), + ok = rpc:call(Node,application,stop,[sasl]), + {ok,Bin2} = sync_and_read(Node,Dest,Log), ct:log("Log content:~n~s",[Bin2]), - match(Bin2,<<"INFO REPORT">>,1), - match(Bin1,<<"DEBUG REPORT">>,0), - ok. + {ok,Bin1,Bin2}. -match(Bin,Pattern,0) -> +match(Bin,Pattern,0,_,_) -> nomatch = re:run(Bin,Pattern,[{capture,none}]); -match(Bin,Pattern,N) -> - {match,M} = re:run(Bin,Pattern,[{capture,all},global]), - N = length(M). - -sync_and_read(disk_log,Log) -> - logger_disk_log_h:disk_log_sync(?STANDARD_HANDLER), - file:read_file(Log ++ ".1"); -sync_and_read(file,Log) -> - logger_std_h:filesync(?STANDARD_HANDLER), - file:read_file(Log). - -cleanup() -> - application:stop(sasl), - [application:unset_env(App,Key) || {App,Key} <- ?all_vars], - #{handlers:=Hs0} = logger:i(), - Hs = lists:keydelete(cth_log_redirect,1,Hs0), - [ok = logger:remove_handler(Id) || {Id,_,_} <- Hs], - Hs. +match(Bin,Pattern,N,LogLevel,ConfLevel) -> + case logger:compare_levels(LogLevel,ConfLevel) of + lt -> match(Bin,Pattern,0,LogLevel,ConfLevel); + _ -> + {match,M} = re:run(Bin,Pattern,[{capture,all},global]), + N = length(M) + end. diff --git a/lib/kernel/test/logger_filters_SUITE.erl b/lib/kernel/test/logger_filters_SUITE.erl index 21f14bbc02..c4b31370ff 100644 --- a/lib/kernel/test/logger_filters_SUITE.erl +++ b/lib/kernel/test/logger_filters_SUITE.erl @@ -81,6 +81,8 @@ domain(_Config) -> stop = logger_filters:domain(?dlog([]),{stop,starts_with,[]}), L3 = logger_filters:domain(L3=?dlog([]),{log,equals,[]}), stop = logger_filters:domain(?dlog([]),{stop,equals,[]}), + ignore = logger_filters:domain(?dlog([]),{log,differs,[]}), + ignore = logger_filters:domain(?dlog([]),{stop,differs,[]}), ignore = logger_filters:domain(?dlog([]),{log,no_domain,[]}), ignore = logger_filters:domain(?dlog([]),{stop,no_domain,[]}), @@ -90,15 +92,19 @@ domain(_Config) -> ignore = logger_filters:domain(?dlog([a]),{stop,starts_with,[a,b]}), ignore = logger_filters:domain(?dlog([a]),{log,equals,[a,b]}), ignore = logger_filters:domain(?dlog([a]),{stop,equals,[a,b]}), + L5 = logger_filters:domain(L5=?dlog([a]),{log,differs,[a,b]}), + stop = logger_filters:domain(?dlog([a]),{stop,differs,[a,b]}), ignore = logger_filters:domain(?dlog([a]),{log,no_domain,[a,b]}), ignore = logger_filters:domain(?dlog([a]),{stop,no_domain,[a,b]}), ignore = logger_filters:domain(?dlog([a,b]),{log,prefix_of,[a]}), ignore = logger_filters:domain(?dlog([a,b]),{stop,prefix_of,[a]}), - L5 = logger_filters:domain(L5=?dlog([a,b]),{log,starts_with,[a]}), + L6 = logger_filters:domain(L6=?dlog([a,b]),{log,starts_with,[a]}), stop = logger_filters:domain(?dlog([a,b]),{stop,starts_with,[a]}), ignore = logger_filters:domain(?dlog([a,b]),{log,equals,[a]}), ignore = logger_filters:domain(?dlog([a,b]),{stop,equals,[a]}), + L7 = logger_filters:domain(L7=?dlog([a,b]),{log,differs,[a]}), + stop = logger_filters:domain(?dlog([a,b]),{stop,differs,[a]}), ignore = logger_filters:domain(?dlog([a,b]),{log,no_domain,[a]}), ignore = logger_filters:domain(?dlog([a,b]),{stop,no_domain,[a]}), @@ -108,26 +114,33 @@ domain(_Config) -> ignore = logger_filters:domain(?ndlog,{stop,starts_with,[a]}), ignore = logger_filters:domain(?ndlog,{log,equals,[a]}), ignore = logger_filters:domain(?ndlog,{stop,equals,[a]}), - L6 = logger_filters:domain(L6=?ndlog,{log,no_domain,[a]}), + L8 = logger_filters:domain(L8=?ndlog,{log,differs,[a]}), + stop = logger_filters:domain(?ndlog,{stop,differs,[a]}), + L9 = logger_filters:domain(L9=?ndlog,{log,no_domain,[a]}), stop = logger_filters:domain(?ndlog,{stop,no_domain,[a]}), - L7 = logger_filters:domain(L7=?dlog([a,b,c,d]),{log,prefix_of,[a,b,c,d]}), + L10 = logger_filters:domain(L10=?dlog([a,b,c,d]),{log,prefix_of,[a,b,c,d]}), stop = logger_filters:domain(?dlog([a,b,c,d]),{stop,prefix_of,[a,b,c,d]}), - L8 = logger_filters:domain(L8=?dlog([a,b,c,d]),{log,starts_with,[a,b,c,d]}), + L11 = logger_filters:domain(L11=?dlog([a,b,c,d]),{log,starts_with,[a,b,c,d]}), stop = logger_filters:domain(?dlog([a,b,c,d]),{stop,starts_with,[a,b,c,d]}), - L9 = logger_filters:domain(L9=?dlog([a,b,c,d]),{log,equals,[a,b,c,d]}), + L12 = logger_filters:domain(L12=?dlog([a,b,c,d]),{log,equals,[a,b,c,d]}), stop = logger_filters:domain(?dlog([a,b,c,d]),{stop,equals,[a,b,c,d]}), + ignore = logger_filters:domain(?dlog([a,b,c,d]),{log,differs,[a,b,c,d]}), + ignore = logger_filters:domain(?dlog([a,b,c,d]),{stop,differs,[a,b,c,d]}), ignore = logger_filters:domain(?dlog([a,b,c,d]),{log,no_domain,[a,b,c,d]}), ignore = logger_filters:domain(?dlog([a,b,c,d]),{stop,no_domain,[a,b,c,d]}), %% A domain field in meta which is not a list is allowed by the - %% filter, but it will never match. + %% filter, but since MatchDomain is always a list of atoms, only + %% Action=differs can ever match. ignore = logger_filters:domain(?dlog(dummy),{log,prefix_of,[a,b,c,d]}), ignore = logger_filters:domain(?dlog(dummy),{stop,prefix_of,[a,b,c,d]}), ignore = logger_filters:domain(?dlog(dummy),{log,starts_with,[a,b,c,d]}), ignore = logger_filters:domain(?dlog(dummy),{stop,starts_with,[a,b,c,d]}), ignore = logger_filters:domain(?dlog(dummy),{log,equals,[a,b,c,d]}), ignore = logger_filters:domain(?dlog(dummy),{stop,equals,[a,b,c,d]}), + L13 = logger_filters:domain(L13=?dlog(dummy),{log,differs,[a,b,c,d]}), + stop = logger_filters:domain(?dlog(dummy),{stop,differs,[a,b,c,d]}), ignore = logger_filters:domain(?dlog(dummy),{log,no_domain,[a,b,c,d]}), ignore = logger_filters:domain(?dlog(dummy),{stop,no_domain,[a,b,c,d]}), diff --git a/lib/kernel/test/logger_formatter_SUITE.erl b/lib/kernel/test/logger_formatter_SUITE.erl index 7d1f33746d..9baadfd65a 100644 --- a/lib/kernel/test/logger_formatter_SUITE.erl +++ b/lib/kernel/test/logger_formatter_SUITE.erl @@ -73,7 +73,7 @@ all() -> default(_Config) -> String1 = format(info,{"~p",[term]},#{},#{}), ct:log(String1), - [_Date,_Time,"info:","term\n"] = string:lexemes(String1," "), + [_DateTime,"info:","term\n"] = string:lexemes(String1," "), Time = timestamp(), ExpectedTimestamp = default_time_format(Time), @@ -297,22 +297,22 @@ max_size(_Config) -> single_line=>false}, "12345678901234567890" = format(info,{"12345678901234567890",[]},#{},Cfg), - application:set_env(kernel,logger_max_size,11), - "12345678901234567890" = % min value is 50, so this is not limited - format(info,{"12345678901234567890",[]},#{},Cfg), - "12345678901234567890123456789012345678901234567..." = % 50 - format(info, - {"123456789012345678901234567890123456789012345678901234567890", - []}, - #{}, - Cfg), - application:set_env(kernel,logger_max_size,53), - "12345678901234567890123456789012345678901234567890..." = %53 - format(info, - {"123456789012345678901234567890123456789012345678901234567890", - []}, - #{}, - Cfg), + %% application:set_env(kernel,logger_max_size,11), + %% "12345678901234567890" = % min value is 50, so this is not limited + %% format(info,{"12345678901234567890",[]},#{},Cfg), + %% "12345678901234567890123456789012345678901234567..." = % 50 + %% format(info, + %% {"123456789012345678901234567890123456789012345678901234567890", + %% []}, + %% #{}, + %% Cfg), + %% application:set_env(kernel,logger_max_size,53), + %% "12345678901234567890123456789012345678901234567890..." = %53 + %% format(info, + %% {"123456789012345678901234567890123456789012345678901234567890", + %% []}, + %% #{}, + %% Cfg), "123456789012..." = format(info,{"12345678901234567890",[]},#{},Cfg#{max_size=>15}), "12345678901234567890" = @@ -341,12 +341,6 @@ depth(_Config) -> {"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]}, #{}, #{template=>Template}), - application:set_env(kernel,logger_format_depth,12), - "[1,2,3,4,5,6,7,8,9,0,1|...]" = - format(info, - {"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]}, - #{}, - #{template=>Template}), "[1,2,3,4,5,6,7,8,9,0,1,2|...]" = format(info, {"~p",[[1,2,3,4,5,6,7,8,9,0,1,2,3,4,5,6,7,8,9,0]]}, @@ -361,7 +355,7 @@ depth(_Config) -> depth=>unlimited}), ok. depth(cleanup,_Config) -> - application:unset_env(kernel,logger_format_depth), + application:unset_env(kernel,error_logger_format_depth), ok. chars_limit(_Config) -> @@ -370,7 +364,7 @@ chars_limit(_Config) -> lists:seq(1,100), maps:from_list(lists:zip(lists:seq(1,100), lists:duplicate(100,value)))]}, - Meta = #{time=>"2018-04-26 9:15:40.449879"}, + Meta = #{time=>timestamp()}, Template = [time," - ", msg, "\n"], FC = #{template=>Template, depth=>unlimited, @@ -382,7 +376,7 @@ chars_limit(_Config) -> L1 = string:length(String1), ct:log("String1: ~p~nLength1: ~p~n",[lists:flatten(String1),L1]), true = L1 > CL1, - true = L1 < CL1 + 10, + true = L1 < CL1 + 15, String2 = format(info,FA,Meta,FC#{chars_limit=>CL1,depth=>10}), L2 = string:length(String2), @@ -394,13 +388,13 @@ chars_limit(_Config) -> L3 = string:length(String3), ct:log("String3: ~p~nLength3: ~p~n",[lists:flatten(String3),L3]), true = L3 > CL3, - true = L3 < CL3 + 10, + true = L3 < CL3 + 15, String4 = format(info,FA,Meta,FC#{chars_limit=>CL3,depth=>10}), L4 = string:length(String4), ct:log("String4: ~p~nLength4: ~p~n",[lists:flatten(String4),L4]), true = L4 > CL3, - true = L4 < CL3 + 10, + true = L4 < CL3 + 15, %% Test that max_size truncates the string which is limited by %% depth and chars_limit @@ -439,29 +433,58 @@ format_mfa(_Config) -> ok. format_time(_Config) -> - Time1 = timestamp(), - ExpectedTimestamp1 = default_time_format(Time1), - String1 = format(info,{"~p",[term]},#{time=>Time1},#{}), - ct:log(String1), - " info: term\n" = string:prefix(String1,ExpectedTimestamp1), - - Time2 = timestamp(), - ExpectedTimestamp2 = default_time_format(Time2,true), - String2 = format(info,{"~p",[term]},#{time=>Time2},#{utc=>true}), - ct:log(String2), - " info: term\n" = string:prefix(String2,ExpectedTimestamp2), - - application:set_env(kernel,logger_utc,true), - Time3 = timestamp(), - ExpectedTimestamp3 = default_time_format(Time3,true), - String3 = format(info,{"~p",[term]},#{time=>Time3},#{}), - ct:log(String3), - " info: term\n" = string:prefix(String3,ExpectedTimestamp3), + Time = timestamp(), + Meta = #{time=>Time}, + FC = #{template=>[time]}, + Msg = {string,""}, + ExpectedLocal = default_time_format(Time,false), + ExpectedUtc = default_time_format(Time,true), + + %% default - local time + ExpectedLocal = format(info,Msg,Meta,FC), + + %% time_offset config parameter to formatter + ExpectedLocal = format(info,Msg,Meta,FC#{time_offset=>""}), + ExpectedUtc = format(info,Msg,Meta,FC#{time_offset=>"Z"}), + + %% stdlib utc_log works when time_offset parameter is not set + application:set_env(stdlib,utc_log,true), + ExpectedUtc = format(info,Msg,Meta,FC), + + %% sasl utc_log overwrites stdlib utc_log + application:set_env(sasl,utc_log,false), + ExpectedLocal = format(info,Msg,Meta,FC), + + %% sasl utc_log overwrites stdlib utc_log + application:set_env(sasl,utc_log,true), + application:set_env(stdlib,utc_log,false), + ExpectedUtc = format(info,Msg,Meta,FC), + + %% time_offset config parameter to formatter + %% overwrites sasl and stdlib utc_log + application:set_env(sasl,utc_log,false), + ExpectedUtc = format(info,Msg,Meta,FC#{time_offset=>"Z"}), + + %% time_offset config parameter to formatter + %% overwrites sasl and stdlib utc_log + application:set_env(sasl,utc_log,true), + application:set_env(stdlib,utc_log,true), + ExpectedLocal = format(info,Msg,Meta,FC#{time_offset=>""}), + + %% time_designator config parameter to formatter + ExpectedLocalS = default_time_format(Time,false,$\s), + ExpectedUtcS = default_time_format(Time,true,$\s), + + ExpectedLocalS = format(info,Msg,Meta,FC#{time_offset=>"", + time_designator=>$\s}), + ExpectedUtcS = format(info,Msg,Meta,FC#{time_offset=>"Z", + time_designator=>$\s}), ok. format_time(cleanup,_Config) -> - application:unset_env(kernel,logger_utc), + application:unset_env(sasl,utc_log), + application:unset_env(stdlib,utc_log), ok. level_or_msg_in_meta(_Config) -> @@ -520,22 +543,17 @@ format(Log,Config) -> default_time_format(Timestamp) -> default_time_format(Timestamp,false). -default_time_format(Timestamp0,Utc) when is_integer(Timestamp0) -> +default_time_format(Timestamp,Utc) -> + default_time_format(Timestamp,Utc,$T). + +default_time_format(Timestamp0,Utc,Sep) -> Timestamp=Timestamp0+erlang:time_offset(microsecond), - %% calendar:system_time_to_rfc3339(Time,[{unit,microsecond}]). - Micro = Timestamp rem 1000000, - Sec = Timestamp div 1000000, - UniversalTime = erlang:posixtime_to_universaltime(Sec), - {Date,Time} = - if Utc -> UniversalTime; - true -> erlang:universaltime_to_localtime(UniversalTime) - end, - default_time_format(Date,Time,Micro). - -default_time_format({Y,M,D},{H,Min,S},Micro) -> - lists:flatten( - io_lib:format("~4w-~2..0w-~2..0w ~2w:~2..0w:~2..0w.~6..0w", - [Y,M,D,H,Min,S,Micro])). + Offset = if Utc -> "Z"; + true -> "" + end, + calendar:system_time_to_rfc3339(Timestamp,[{unit,microsecond}, + {time_designator,Sep}, + {offset,Offset}]). integer(Str) -> is_integer(list_to_integer(Str)). diff --git a/lib/kernel/test/logger_simple_SUITE.erl b/lib/kernel/test/logger_simple_SUITE.erl index 5d8d32492d..0d505b14f5 100644 --- a/lib/kernel/test/logger_simple_SUITE.erl +++ b/lib/kernel/test/logger_simple_SUITE.erl @@ -25,6 +25,8 @@ -include_lib("kernel/include/logger.hrl"). -include_lib("kernel/src/logger_internal.hrl"). +-import(logger_test_lib, [setup/2, log/3, sync_and_read/3]). + -define(check_no_log,[] = test_server:messages_get()). -define(check(Expected), receive {log,Expected} -> @@ -42,15 +44,15 @@ -define(keyval_rep,[{function,?FUNCTION_NAME}, {line,?LINE}]). suite() -> - [{timetrap,{seconds,30}}]. + [{timetrap,{seconds,30}}, + {ct_hooks, [logger_test_lib]}]. init_per_suite(Config) -> #{handlers:=Hs0} = logger:i(), Hs = lists:keydelete(cth_log_redirect,1,Hs0), [ok = logger:remove_handler(Id) || {Id,_,_} <- Hs], Env = [{App,Key,application:get_env(App,Key)} || - {App,Key} <- [{kernel,logger_dest}, - {kernel,logger_level}]], + {App,Key} <- [{kernel,logger_level}]], [{env,Env},{logger,Hs}|Config]. end_per_suite(Config) -> @@ -79,7 +81,7 @@ groups() -> all() -> [start_stop, - get_buffer, + replace_default, replace_file, replace_disk_log ]. @@ -100,99 +102,46 @@ start_stop(_Config) -> start_stop(cleanup,_Config) -> logger:remove_handler(logger_simple). -get_buffer(_Config) -> - %% Start simple without buffer - ok = logger:add_handler(logger_simple,logger_simple, - #{filter_default=>log}), - logger:emergency(?str), - logger:alert(?str,[]), - logger:error(?map_rep), - logger:info(?keyval_rep), - {ok,[]} = logger_simple:get_buffer(), % no buffer - ok = logger:remove_handler(logger_simple), +%% This testcase just tests that it does not crash, the default handler prints +%% to stdout which we cannot read from in a detached slave. +replace_default(Config) -> - %% Start with buffer - ok = logger:add_handler(logger_simple,logger_simple, - #{filter_default=>log, - logger_simple=>#{buffer=>true}}), - logger:emergency(M1=?str), - logger:alert(M2=?str,[]), - logger:error(M3=?map_rep), - logger:info(M4=?keyval_rep), - logger:info(M41=?keyval_rep++[not_key_val]), - error_logger:error_report(some_type,M5=?map_rep), - error_logger:warning_report("some_type",M6=?map_rep), - logger:critical(M7=?str,[A7=?keyval_rep]), - logger:notice(M8=["fake",string,"line:",?LINE]), - {ok,Buffered1} = logger_simple:get_buffer(), - [#{level:=emergency,msg:={string,M1}}, - #{level:=alert,msg:={M2,[]}}, - #{level:=error,msg:={report,M3}}, - #{level:=info,msg:={report,M4}}, - #{level:=info,msg:={report,M41}}, - #{level:=error,msg:={report,#{label:={error_logger,error_report}, - report:=M5}}}, - #{level:=warning,msg:={report,#{label:={error_logger,warning_report}, - report:=M6}}}, - #{level:=critical,msg:={M7,[A7]}}, - #{level:=notice,msg:={string,M8}}] = Buffered1, - - %% Keep logging - should not buffer any more - logger:emergency(?str), - logger:alert(?str,[]), - logger:error(?map_rep), - logger:info(?keyval_rep), - {ok,[]} = logger_simple:get_buffer(), - ok = logger:remove_handler(logger_simple), + {ok, _, Node} = logger_test_lib:setup(Config, [{logger, [{handler, default, undefined}]}]), + log(Node, emergency, [M1=?str]), + log(Node, alert, [M2=?str,[]]), + log(Node, error, [M3=?map_rep]), + log(Node, info, [M4=?keyval_rep]), + log(Node, info, [M41=?keyval_rep++[not_key_val]]), + rpc:call(Node, error_logger, error_report, [some_type,M5=?map_rep]), + rpc:call(Node, error_logger, warning_report, ["some_type",M6=?map_rep]), + log(Node, critical, [M7=?str,[A7=?keyval_rep]]), + log(Node, notice, [M8=["fake",string,"line:",?LINE]]), + + Env = rpc:call(Node, application, get_env, [kernel, logger, []]), + ok = rpc:call(Node, logger, add_handlers, [Env]), - %% Fill buffer and drop - ok = logger:add_handler(logger_simple,logger_simple, - #{filter_default=>log, - logger_simple=>#{buffer=>true}}), - logger:emergency(M9=?str), - M10=?str, - [logger:info(M10) || _ <- lists:seq(1,8)], - logger:error(M11=?str), - logger:error(?str), - logger:error(?str), - {ok,Buffered3} = logger_simple:get_buffer(), - 11 = length(Buffered3), - [#{level:=emergency,msg:={string,M9}}, - #{level:=info,msg:={string,M10}}, - #{level:=info,msg:={string,M10}}, - #{level:=info,msg:={string,M10}}, - #{level:=info,msg:={string,M10}}, - #{level:=info,msg:={string,M10}}, - #{level:=info,msg:={string,M10}}, - #{level:=info,msg:={string,M10}}, - #{level:=info,msg:={string,M10}}, - #{level:=error,msg:={string,M11}}, - #{level:=info,msg:={"Simple handler buffer full, dropped ~w messages",[2]}}] - = Buffered3, ok. -get_buffer(cleanup,_Config) -> - logger:remove_handler(logger_simple). replace_file(Config) -> - ok = logger:add_handler(logger_simple,logger_simple, - #{filter_default=>log, - logger_simple=>#{buffer=>true}}), - logger:emergency(M1=?str), - logger:alert(M2=?str,[]), - logger:error(?map_rep), - logger:info(?keyval_rep), - undefined = whereis(?STANDARD_HANDLER), - PrivDir = ?config(priv_dir,Config), - File = filename:join(PrivDir,atom_to_list(?FUNCTION_NAME)++".log"), - - application:set_env(kernel,logger_dest,{file,File}), - application:set_env(kernel,logger_level,info), - - ok = logger:setup_standard_handler(), - true = is_pid(whereis(?STANDARD_HANDLER)), - ok = logger_std_h:filesync(?STANDARD_HANDLER), - {ok,Bin} = file:read_file(File), - Lines = [unicode:characters_to_list(L) || + + {ok, _, Node} = logger_test_lib:setup(Config, [{logger, [{handler, default, undefined}]}]), + log(Node, emergency, [M1=?str]), + log(Node, alert, [M2=?str,[]]), + log(Node, error, [M3=?map_rep]), + log(Node, info, [M4=?keyval_rep]), + log(Node, info, [M41=?keyval_rep++[not_key_val]]), + log(Node, critical, [M7=?str,[A7=?keyval_rep]]), + log(Node, notice, [M8=["fake",string,"line:",?LINE]]), + + File = filename:join(proplists:get_value(priv_dir,Config), + atom_to_list(?FUNCTION_NAME)++".log"), + + ok = rpc:call(Node, logger, add_handlers, + [[{handler, default, logger_std_h, + #{ logger_std_h => #{ type => {file, File} }}}]]), + + {ok,Bin} = sync_and_read(Node, file, File), + Lines = [unicode:characters_to_list(L) || L <- binary:split(Bin,<<"\n">>,[global,trim])], ["=EMERGENCY REPORT===="++_, M1, @@ -203,32 +152,38 @@ replace_file(Config) -> _, "=INFO REPORT===="++_, _, - _] = Lines, + _, + "=INFO REPORT===="++_, + _, + _, + _, + "=CRITICAL REPORT===="++_, + _, + _, + "=NOTICE REPORT===="++_, + _ + ] = Lines, ok. -replace_file(cleanup,_Config) -> - logger:remove_handler(?STANDARD_HANDLER), - logger:remove_handler(logger_simple). - + replace_disk_log(Config) -> - ok = logger:add_handler(logger_simple,logger_simple, - #{filter_default=>log, - logger_simple=>#{buffer=>true}}), - logger:emergency(M1=?str), - logger:alert(M2=?str,[]), - logger:error(?map_rep), - logger:info(?keyval_rep), - undefined = whereis(?STANDARD_HANDLER), - PrivDir = ?config(priv_dir,Config), - File = filename:join(PrivDir,atom_to_list(?FUNCTION_NAME)), - - application:set_env(kernel,logger_dest,{disk_log,File}), - application:set_env(kernel,logger_level,info), - - ok = logger:setup_standard_handler(), - true = is_pid(whereis(?STANDARD_HANDLER)), - ok = logger_disk_log_h:disk_log_sync(?STANDARD_HANDLER), - {ok,Bin} = file:read_file(File++".1"), - Lines = [unicode:characters_to_list(L) || + + {ok, _, Node} = logger_test_lib:setup(Config, [{logger, [{handler, default, undefined}]}]), + log(Node, emergency, [M1=?str]), + log(Node, alert, [M2=?str,[]]), + log(Node, error, [M3=?map_rep]), + log(Node, info, [M4=?keyval_rep]), + log(Node, info, [M41=?keyval_rep++[not_key_val]]), + log(Node, critical, [M7=?str,[A7=?keyval_rep]]), + log(Node, notice, [M8=["fake",string,"line:",?LINE]]), + + File = filename:join(proplists:get_value(priv_dir,Config), + atom_to_list(?FUNCTION_NAME)++".log"), + + ok = rpc:call(Node, logger, add_handlers, + [[{handler, default, logger_disk_log_h, + #{ disk_log_opts => #{ file => File }}}]]), + {ok,Bin} = sync_and_read(Node, disk_log, File), + Lines = [unicode:characters_to_list(L) || L <- binary:split(Bin,<<"\n">>,[global,trim])], ["=EMERGENCY REPORT===="++_, M1, @@ -239,9 +194,15 @@ replace_disk_log(Config) -> _, "=INFO REPORT===="++_, _, - _|_] = Lines, % the tail might be an info report about opening the disk log + _, + "=INFO REPORT===="++_, + _, + _, + _, + "=CRITICAL REPORT===="++_, + _, + _, + "=NOTICE REPORT===="++_, + _ + ] = Lines, ok. -replace_disk_log(cleanup,_Config) -> - logger:remove_handler(?STANDARD_HANDLER), - logger:remove_handler(logger_simple). - diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl index 7c8d63cbbd..fc59d393e0 100644 --- a/lib/kernel/test/logger_std_h_SUITE.erl +++ b/lib/kernel/test/logger_std_h_SUITE.erl @@ -50,11 +50,12 @@ end). suite() -> - [{timetrap,{seconds,30}}]. + [{timetrap,{seconds,30}}, + {ct_hooks,[logger_test_lib]}]. init_per_suite(Config) -> timer:start(), % to avoid progress report - {ok,{?STANDARD_HANDLER,#{formatter:=OrigFormatter}}} = + {ok,{logger_std_h,#{formatter:=OrigFormatter}}} = logger:get_handler_config(?STANDARD_HANDLER), [{formatter,OrigFormatter}|Config]. @@ -241,7 +242,8 @@ formatter_fail(Config) -> filters=>?DEFAULT_HANDLER_FILTERS([?MODULE])}), Pid = whereis(?MODULE), true = is_pid(Pid), - {ok,#{handlers:=H}} = logger:get_logger_config(), + #{handlers:=HC1} = logger:i(), + H = [Id || {Id,_,_} <- HC1], true = lists:member(?MODULE,H), %% Formatter is added automatically @@ -270,7 +272,8 @@ formatter_fail(Config) -> %% Check that handler is still alive and was never dead Pid = whereis(?MODULE), - {ok,#{handlers:=H}} = logger:get_logger_config(), + #{handlers:=HC2} = logger:i(), + H = [Id || {Id,_,_} <- HC2], ok. @@ -289,10 +292,17 @@ config_fail(_Config) -> #{logger_std_h => #{restart_type => bad}, filter_default=>log, formatter=>{?MODULE,self()}}), - {error,{handler_not_added,{invalid_levels,{42,42,_}}}} = + {error,{handler_not_added,{invalid_levels,{_,1,_}}}} = logger:add_handler(?MODULE,logger_std_h, - #{logger_std_h => #{toggle_sync_qlen=>42, + #{logger_std_h => #{drop_new_reqs_qlen=>1}}), + {error,{handler_not_added,{invalid_levels,{43,42,_}}}} = + logger:add_handler(?MODULE,logger_std_h, + #{logger_std_h => #{toggle_sync_qlen=>43, drop_new_reqs_qlen=>42}}), + {error,{handler_not_added,{invalid_levels,{_,43,42}}}} = + logger:add_handler(?MODULE,logger_std_h, + #{logger_std_h => #{drop_new_reqs_qlen=>43, + flush_reqs_qlen=>42}}), ok = logger:add_handler(?MODULE,logger_std_h, #{filter_default=>log, @@ -315,29 +325,32 @@ config_fail(cleanup,_Config) -> logger:remove_handler(?MODULE). crash_std_h_to_file(Config) -> - crash_std_h(Config,?FUNCTION_NAME,logger_dest,file). + Dir = ?config(priv_dir,Config), + Log = filename:join(Dir,lists:concat([?MODULE,"_",?FUNCTION_NAME,".log"])), + crash_std_h(Config,?FUNCTION_NAME, + [{handler,default,logger_std_h, + #{ logger_std_h => #{ type => {file, Log} }}}], + file, Log). crash_std_h_to_file(cleanup,_Config) -> crash_std_h(cleanup). crash_std_h_to_disk_log(Config) -> - crash_std_h(Config,?FUNCTION_NAME,logger_dest,disk_log). + Dir = ?config(priv_dir,Config), + Log = filename:join(Dir,lists:concat([?MODULE,"_",?FUNCTION_NAME,".log"])), + crash_std_h(Config,?FUNCTION_NAME, + [{handler,default,logger_disk_log_h, + #{ disk_log_opts => #{ file => Log }}}], + disk_log,Log). crash_std_h_to_disk_log(cleanup,_Config) -> crash_std_h(cleanup). -crash_std_h(Config,Func,Var,Type) -> +crash_std_h(Config,Func,Var,Type,Log) -> Dir = ?config(priv_dir,Config), - File = lists:concat([?MODULE,"_",Func,".log"]), - Log = filename:join(Dir,File), + SysConfig = filename:join(Dir,lists:concat([?MODULE,"_",Func,".config"])), + ok = file:write_file(SysConfig, io_lib:format("[{kernel,[{logger,~p}]}].",[Var])), Pa = filename:dirname(code:which(?MODULE)), - TypeAndLog = - case os:type() of - {win32,_} -> - lists:concat([" {",Type,",\\\"",Log,"\\\"}"]); - _ -> - lists:concat([" \'{",Type,",\"",Log,"\"}\'"]) - end, - Args = lists:concat([" -kernel ",Var,TypeAndLog," -pa ",Pa]), Name = lists:concat([?MODULE,"_",Func]), + Args = lists:concat([" -config ",filename:rootname(SysConfig)," -pa ",Pa]), ct:pal("Starting ~p with ~tp", [Name,Args]), %% Start a node which prints kernel logs to the destination specified by Type {ok,Node} = test_server:start_node(Name, peer, [{args, Args}]), @@ -578,7 +591,7 @@ write_failure(Config) -> Dir = ?config(priv_dir, Config), File = lists:concat([?MODULE,"_",?FUNCTION_NAME,".log"]), Log = filename:join(Dir, File), - Node = start_std_h_on_new_node(Config, ?FUNCTION_NAME, Log), + Node = start_std_h_on_new_node(Config, Log), 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]), @@ -615,7 +628,7 @@ sync_failure(Config) -> Dir = ?config(priv_dir, Config), File = lists:concat([?MODULE,"_",?FUNCTION_NAME,".log"]), Log = filename:join(Dir, File), - Node = start_std_h_on_new_node(Config, ?FUNCTION_NAME, Log), + Node = start_std_h_on_new_node(Config, Log), 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]), @@ -651,21 +664,12 @@ sync_failure(cleanup, _Config) -> Nodes = nodes(), [test_server:stop_node(Node) || Node <- Nodes]. -start_std_h_on_new_node(_Config, Func, Log) -> - Pa = filename:dirname(code:which(?MODULE)), - Dest = - case os:type() of - {win32,_} -> - lists:concat([" {file,\\\"",Log,"\\\"}"]); - _ -> - lists:concat([" \'{file,\"",Log,"\"}\'"]) - end, - Args = lists:concat([" -kernel ",logger_dest,Dest," -pa ",Pa]), - Name = lists:concat([?MODULE,"_",Func]), - ct:pal("Starting ~s with ~tp", [Name,Args]), - {ok,Node} = test_server:start_node(Name, peer, [{args, Args}]), - Pid = rpc:call(Node,erlang,whereis,[?STANDARD_HANDLER]), - true = is_pid(Pid), +start_std_h_on_new_node(Config, Log) -> + {ok,_,Node} = + logger_test_lib:setup( + Config, + [{logger,[{handler,default,logger_std_h, + #{ logger_std_h => #{ type => {file,Log}}}}]}]), ok = rpc:call(Node,logger,set_handler_config,[?STANDARD_HANDLER,formatter, {?MODULE,nl}]), Node. @@ -691,16 +695,17 @@ internal_log(Type, Term) -> op_switch_to_sync_file(Config) -> {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + NumOfReqs = 500, NewHConfig = - HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 3, - drop_new_reqs_qlen => 501, - flush_reqs_qlen => 2000, + HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 2, + drop_new_reqs_qlen => NumOfReqs+1, + flush_reqs_qlen => 2*NumOfReqs, enable_burst_limit => false}}, ok = logger:set_handler_config(?MODULE, NewHConfig), %% TRecvPid = start_op_trace(), - NumOfReqs = 500, send_burst({n,NumOfReqs}, seq, {chars,79}, info), - NumOfReqs = count_lines(Log), + Lines = count_lines(Log), + ok = file:delete(Log), %% true = analyse_trace(TRecvPid, %% fun(Events) -> find_mode(async,Events) end), %% true = analyse_trace(TRecvPid, @@ -711,68 +716,82 @@ op_switch_to_sync_file(Config) -> %% fun(Events) -> find_mode(drop,Events) end), %% false = analyse_trace(TRecvPid, %% fun(Events) -> find_mode(flush,Events) end), - ok = file:delete(Log), %% stop_op_trace(TRecvPid), + NumOfReqs = Lines, ok. op_switch_to_sync_file(cleanup, _Config) -> ok = stop_handler(?MODULE). op_switch_to_sync_tty(Config) -> {HConfig,StdHConfig} = start_handler(?MODULE, standard_io, Config), + NumOfReqs = 500, NewHConfig = HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 3, - drop_new_reqs_qlen => 501, - flush_reqs_qlen => 2000, + drop_new_reqs_qlen => NumOfReqs+1, + flush_reqs_qlen => 2*NumOfReqs, enable_burst_limit => false}}, ok = logger:set_handler_config(?MODULE, NewHConfig), - NumOfReqs = 500, send_burst({n,NumOfReqs}, seq, {chars,79}, info), ok. op_switch_to_sync_tty(cleanup, _Config) -> ok = stop_handler(?MODULE). +op_switch_to_drop_file() -> + [{timetrap,{seconds,180}}]. op_switch_to_drop_file(Config) -> - {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), - - NewHConfig = - HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 2, - drop_new_reqs_qlen => 3, - flush_reqs_qlen => 600, + Test = + fun() -> + {Log,HConfig,StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + NumOfReqs = 300, + Procs = 2, + Bursts = 10, + NewHConfig = + HConfig#{logger_std_h => + StdHConfig#{toggle_sync_qlen => 1, + drop_new_reqs_qlen => 2, + flush_reqs_qlen => + Procs*NumOfReqs*Bursts, enable_burst_limit => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), - %% TRecvPid = start_op_trace(), - NumOfReqs = 500, - send_burst({n,NumOfReqs}, seq, {chars,79}, info), - Logged = count_lines(Log), - ct:pal("Number of messages dropped = ~w (~w)", - [NumOfReqs-Logged,NumOfReqs]), - true = (Logged < NumOfReqs), - %% true = analyse_trace(TRecvPid, - %% fun(Events) -> find_mode(async,Events) end), - %% true = analyse_trace(TRecvPid, - %% fun(Events) -> find_mode(drop,Events) end), - %% false = analyse_trace(TRecvPid, - %% fun(Events) -> find_mode(flush,Events) end), - %% true = analyse_trace(TRecvPid, - %% fun(Events) -> find_switch(async,drop,Events) - %% orelse find_switch(sync,drop,Events) - %% end), - ok = file:delete(Log), - %% stop_op_trace(TRecvPid), - ok. + ok = logger:set_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 + %% bursts to increase the chance of message buildup. + [send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info) || + _ <- lists:seq(1, Bursts)], + Logged = count_lines(Log), + ok = stop_handler(?MODULE), + _ = file:delete(Log), + ct:pal("Number of messages dropped = ~w (~w)", + [Procs*NumOfReqs*Bursts-Logged,Procs*NumOfReqs*Bursts]), + true = (Logged < (Procs*NumOfReqs*Bursts)), + true = (Logged > 0), + ok + end, + %% As it's tricky to get the timing right in only one go, we perform the + %% test repeatedly, hoping that will generate a successful result. + case repeat_until_ok(Test, 10) of + {ok,{Failures,_Result}} -> + ct:log("Failed ~w times before success!", [Failures]); + {fails,Reason} -> + ct:fail(Reason) + end. op_switch_to_drop_file(cleanup, _Config) -> - ok = stop_handler(?MODULE). + _ = stop_handler(?MODULE). op_switch_to_drop_tty(Config) -> {HConfig,StdHConfig} = start_handler(?MODULE, standard_io, Config), + NumOfReqs = 300, + Procs = 2, NewHConfig = - HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 2, - drop_new_reqs_qlen => 3, - flush_reqs_qlen => 600, + HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 1, + drop_new_reqs_qlen => 2, + flush_reqs_qlen => + Procs*NumOfReqs+1, enable_burst_limit => false}}, ok = logger:set_handler_config(?MODULE, NewHConfig), - NumOfReqs = 500, - send_burst({n,NumOfReqs}, seq, {chars,79}, info), + send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info), ok. op_switch_to_drop_tty(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -780,32 +799,54 @@ op_switch_to_drop_tty(cleanup, _Config) -> op_switch_to_flush_file() -> [{timetrap,{minutes,3}}]. op_switch_to_flush_file(Config) -> - {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), - - %% it's important that both async and sync requests have been queued - %% when the flush happens (verify with coverage of flush_log_requests/2) - - NewHConfig = - HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 2, - drop_new_reqs_qlen => 99, - flush_reqs_qlen => 100, + Test = + fun() -> + {Log,HConfig,StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + + %% NOTE: it's important that both async and sync + %% requests have been queued when the flush happens + %% (verify with coverage of flush_log_requests/2) + + NewHConfig = + HConfig#{logger_std_h => + StdHConfig#{toggle_sync_qlen => 2, + %% disable drop mode + drop_new_reqs_qlen => 300, + flush_reqs_qlen => 300, enable_burst_limit => false}}, - ok = logger:set_handler_config(?MODULE, NewHConfig), - NumOfReqs = 10000, - Procs = 100, - send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info), - Logged = count_lines(Log), - ct:pal("Number of messages flushed/dropped = ~w (~w)", - [(NumOfReqs*Procs)-Logged,NumOfReqs*Procs]), - true = (Logged < (NumOfReqs*Procs)), - - %%! --- Thu Apr 12 13:46:00 2018 --- peppe was here! - %%! TODO: Verify that handler has switched to flush mode - - ok = file:delete(Log), - ok. + ok = logger:set_handler_config(?MODULE, NewHConfig), + NumOfReqs = 1500, + Procs = 10, + Bursts = 10, + %% It sometimes happens that the handler either gets + %% the requests in a slow enough pace so that flushing + %% never occurs, or it gets all messages at once, + %% causing all messages to get flushed (no dropping of + %% sync messages gets tested). Therefore, lets + %% generate a number of bursts to increase the chance + %% of message buildup in some random fashion. + [send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info) || + _ <- lists:seq(1,Bursts)], + Logged = count_lines(Log), + ok = stop_handler(?MODULE), + _ = file:delete(Log), + ct:pal("Number of messages flushed/dropped = ~w (~w)", + [NumOfReqs*Procs*Bursts-Logged,NumOfReqs*Procs*Bursts]), + true = (Logged < (NumOfReqs*Procs*Bursts)), + true = (Logged > 0), + ok + end, + %% As it's tricky to get the timing right in only one go, we perform the + %% test repeatedly, hoping that will generate a successful result. + case repeat_until_ok(Test, 10) of + {ok,{Failures,_Result}} -> + ct:log("Failed ~w times before success!", [Failures]); + {fails,Reason} -> + ct:fail(Reason) + end. op_switch_to_flush_file(cleanup, _Config) -> - ok = stop_handler(?MODULE). + _ = stop_handler(?MODULE). op_switch_to_flush_tty(Config) -> {HConfig,StdHConfig} = start_handler(?MODULE, standard_io, Config), @@ -815,12 +856,13 @@ op_switch_to_flush_tty(Config) -> NewHConfig = HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 2, - drop_new_reqs_qlen => 99, + %% disable drop mode + drop_new_reqs_qlen => 100, flush_reqs_qlen => 100, enable_burst_limit => false}}, ok = logger:set_handler_config(?MODULE, NewHConfig), - NumOfReqs = 10000, - Procs = 10, + NumOfReqs = 1000, + Procs = 100, send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info), ok. op_switch_to_flush_tty(cleanup, _Config) -> @@ -904,10 +946,10 @@ kill_disabled(cleanup, _Config) -> ok = stop_handler(?MODULE). qlen_kill_new(Config) -> - {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + {_Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), Pid0 = whereis(?MODULE), {_,Mem0} = process_info(Pid0, memory), - RestartAfter = 2000, + RestartAfter = ?HANDLER_RESTART_AFTER, NewHConfig = HConfig#{logger_std_h=>StdHConfig#{enable_kill_overloaded=>true, handler_overloaded_qlen=>10, @@ -927,7 +969,7 @@ qlen_kill_new(Config) -> killed -> ct:pal("Slow shutdown, handler process was killed!", []) end, - timer:sleep(RestartAfter + 1000), + timer:sleep(RestartAfter + 2000), true = is_pid(whereis(?MODULE)), ok after @@ -941,7 +983,7 @@ qlen_kill_new(cleanup, _Config) -> %% choke the standard handler on remote node to verify the termination %% works as expected -qlen_kill_std(Config) -> +qlen_kill_std(_Config) -> %%! HERE %% Dir = ?config(priv_dir, Config), %% File = lists:concat([?MODULE,"_",?FUNCTION_NAME,".log"]), @@ -955,10 +997,10 @@ qlen_kill_std(Config) -> {skip,"Not done yet"}. mem_kill_new(Config) -> - {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + {_Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), Pid0 = whereis(?MODULE), {_,Mem0} = process_info(Pid0, memory), - RestartAfter = 2000, + RestartAfter = ?HANDLER_RESTART_AFTER, NewHConfig = HConfig#{logger_std_h=>StdHConfig#{enable_kill_overloaded=>true, handler_overloaded_qlen=>50000, @@ -978,7 +1020,7 @@ mem_kill_new(Config) -> killed -> ct:pal("Slow shutdown, handler process was killed!", []) end, - timer:sleep(RestartAfter * 2), + timer:sleep(RestartAfter + 2000), true = is_pid(whereis(?MODULE)), ok after @@ -992,7 +1034,7 @@ mem_kill_new(cleanup, _Config) -> %% choke the standard handler on remote node to verify the termination %% works as expected -mem_kill_std(Config) -> +mem_kill_std(_Config) -> {skip,"Not done yet"}. restart_after(Config) -> @@ -1016,7 +1058,7 @@ restart_after(Config) -> end, {Log,_,_} = start_handler(?MODULE, ?FUNCTION_NAME, Config), - RestartAfter = 2000, + RestartAfter = ?HANDLER_RESTART_AFTER, NewHConfig2 = HConfig#{logger_std_h=>StdHConfig#{enable_kill_overloaded=>true, handler_overloaded_qlen=>10, @@ -1028,7 +1070,7 @@ restart_after(Config) -> send_burst({n,100}, {spawn,2,0}, {chars,79}, info), receive {'DOWN', MRef2, _, _, _Info2} -> - timer:sleep(RestartAfter + 1000), + timer:sleep(RestartAfter + 2000), Pid1 = whereis(?MODULE), true = is_pid(Pid1), false = (Pid1 == Pid0), @@ -1074,7 +1116,7 @@ handler_requests_under_load(Config) -> NoOfReqs = lists:foldl(fun({_,Res}, N) -> N + length(Res) end, 0, ReqResult), ct:pal("~w requests made. Errors: ~n~p", [NoOfReqs,Errors]), ok = file:delete(Log). -handler_requests_under_load(cleanup, Config) -> +handler_requests_under_load(cleanup, _Config) -> ok = stop_handler(?MODULE). send_requests(HName, TO, Reqs = [{Req,Res}|Rs]) -> @@ -1126,8 +1168,9 @@ start_handler(Name, FuncName, Config) -> {Log,HConfig,StdHConfig}. stop_handler(Name) -> - ok = logger:remove_handler(Name), - ct:pal("Handler ~p stopped!", [Name]). + R = logger:remove_handler(Name), + ct:pal("Handler ~p stopped! Result: ~p", [Name,R]), + R. count_lines(File) -> wait_until_written(File, -1), @@ -1299,6 +1342,30 @@ try_match_file(_,Pattern,_,Incorrect) -> [Pattern,Incorrect]), erlang:error({error,not_matching_pattern,Pattern,Incorrect}). +repeat_until_ok(Fun, N) -> + repeat_until_ok(Fun, 0, N, undefined). + +repeat_until_ok(_Fun, Stop, Stop, Reason) -> + {fails,Reason}; + +repeat_until_ok(Fun, C, Stop, FirstReason) -> + if C > 0 -> timer:sleep(5000); + true -> ok + end, + try Fun() of + Result -> + {ok,{C,Result}} + catch + _:Reason:Stack -> + ct:pal("Test fails: ~p (~p)~n", [Reason,hd(Stack)]), + if FirstReason == undefined -> + repeat_until_ok(Fun, C+1, Stop, {Reason,Stack}); + true -> + repeat_until_ok(Fun, C+1, Stop, FirstReason) + end + end. + + %%%----------------------------------------------------------------- %%% start_op_trace() -> @@ -1339,17 +1406,17 @@ find_mode(flush, Events) -> find_mode(Mode, Events) -> lists:keymember([{mode,Mode}], 3, Events). -find_switch(From, To, Events) -> - try lists:foldl(fun({trace_return,check_load,{To,_,_,_}}, - {trace_call,check_load,[#{mode := From}]}) -> - throw(match); - (Event, _) -> - Event - end, undefined, Events) of - _ -> false - catch - throw:match -> true - end. +%% find_switch(_From, To, Events) -> +%% try lists:foldl(fun({trace_return,check_load,{To,_,_,_}}, +%% {trace_call,check_load,[#{mode := From}]}) -> +%% throw(match); +%% (Event, _) -> +%% Event +%% end, undefined, Events) of +%% _ -> false +%% catch +%% throw:match -> true +%% end. analyse_trace(TRecvPid, TestFun) -> TRecvPid ! {test,self(),TestFun}, @@ -1411,7 +1478,7 @@ tpl([{M,F,A}|Trace]) -> tpl([]) -> ok. -tracer({trace,_,call,{logger_std_h,handle_cast,[{Op,_}|_]}}, +tracer({trace,_,call,{logger_std_h,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/test/logger_test_lib.erl b/lib/kernel/test/logger_test_lib.erl new file mode 100644 index 0000000000..4ac05e6480 --- /dev/null +++ b/lib/kernel/test/logger_test_lib.erl @@ -0,0 +1,82 @@ +% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2018. All Rights Reserved. +%% +%% Licensed under the Apache License, Version 2.0 (the "License"); +%% you may not use this file except in compliance with the License. +%% You may obtain a copy of the License at +%% +%% http://www.apache.org/licenses/LICENSE-2.0 +%% +%% Unless required by applicable law or agreed to in writing, software +%% distributed under the License is distributed on an "AS IS" BASIS, +%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +%% See the License for the specific language governing permissions and +%% limitations under the License. +%% +%% %CopyrightEnd% +%% +-module(logger_test_lib). + +-include_lib("kernel/src/logger_internal.hrl"). + +-export([setup/2, log/3, sync_and_read/3]). + +-export([init/2, + pre_init_per_suite/3, pre_init_per_testcase/4, + post_end_per_testcase/5, post_end_per_suite/3]). + +setup(Config,Vars) -> + FuncStr = lists:concat([proplists:get_value(suite, Config), "_", + proplists:get_value(tc, Config)]), + ConfigFileName = filename:join(proplists:get_value(priv_dir, Config), FuncStr), + file:write_file(ConfigFileName ++ ".config", io_lib:format("[{kernel, ~p}].",[Vars])), + case test_server:start_node(proplists:get_value(tc, Config), slave, + [{args, ["-pa ",filename:dirname(code:which(?MODULE)), + " -boot start_sasl -kernel start_timer true " + "-config ",ConfigFileName]}]) of + {ok, Node} -> + L = rpc:call(Node, logger, i, []), + ct:log("~p",[L]), + {ok, L, Node}; + {error, Reason} -> + ct:log("Failed to start node: ~p",[Reason]), + error + end. + +log(Node, F, A) -> + log(Node, logger, F, A). +log(Node, M, F, A) -> + MD = #{ gl => rpc:call(Node, erlang, whereis, [logger]) }, + rpc:call(Node, M, F, A ++ [MD]). + +sync_and_read(Node,disk_log,Log) -> + rpc:call(Node,logger_disk_log_h,disk_log_sync,[?STANDARD_HANDLER]), + file:read_file(Log ++ ".1"); +sync_and_read(Node, file,Log) -> + ok = rpc:call(Node,logger_std_h,filesync,[?STANDARD_HANDLER]), + file:read_file(Log). + + +init(_, _) -> + {ok, []}. + +pre_init_per_suite(_Suite, Config, State) -> + {[{nodes, nodes()} | Config], State}. + +pre_init_per_testcase(Suite, TC, Config, State) -> + cleanup(Config), + {[{suite, Suite}, {tc, TC} | Config], State}. + +post_end_per_testcase(_, _TC, Config, Res, State) -> + cleanup(Config), + {Res, State}. + +post_end_per_suite(_, Config, State) -> + cleanup(Config), + {Config, State}. + +cleanup(Config) -> + [test_server:stop_node(N) || N <- nodes(), + not lists:member(N, proplists:get_value(nodes, Config))]. diff --git a/lib/kernel/test/os_SUITE.erl b/lib/kernel/test/os_SUITE.erl index 591fbb2125..abbc301360 100644 --- a/lib/kernel/test/os_SUITE.erl +++ b/lib/kernel/test/os_SUITE.erl @@ -227,8 +227,8 @@ find_executable(Config) when is_list(Config) -> DataDir = proplists:get_value(data_dir, Config), %% Smoke test. - case lib:progname() of - erl -> + case ct:get_progname() of + "erl" -> ErlPath = os:find_executable("erl"), true = is_list(ErlPath), true = filelib:is_regular(ErlPath); @@ -388,7 +388,7 @@ comp(Expected, Got) -> ct:fail(failed) end. -%% Like lib:nonl/1, but strips \r as well as \n. +%% strips \n and \r\n from end of string strip_nl([$\r, $\n]) -> []; strip_nl([$\n]) -> []; |