aboutsummaryrefslogtreecommitdiffstats
path: root/lib/kernel
diff options
context:
space:
mode:
authorSiri Hansen <[email protected]>2018-05-07 12:02:59 +0200
committerSiri Hansen <[email protected]>2018-05-07 12:02:59 +0200
commitcd832e85a3029162c31659ca174efdf43a08c8d2 (patch)
tree160726aa478bfce1ab6d221dc0b40e5dcfaa33ce /lib/kernel
parent4c350d64b85686b731d0888c36159b4d126e5cf1 (diff)
parent3c9e4adff06a3f74513cb6658405e43e674133c1 (diff)
downloadotp-cd832e85a3029162c31659ca174efdf43a08c8d2.tar.gz
otp-cd832e85a3029162c31659ca174efdf43a08c8d2.tar.bz2
otp-cd832e85a3029162c31659ca174efdf43a08c8d2.zip
Merge branch 'siri/logger-fix'
* siri/logger-fix: Change logger callback removing_handler/1 to removing_handler/2 Don't crash logger_server due to unexpected message Add logger:update_process_metadata/1 Improve documentation of logger:set_*_config functions Change return type from logger_formatter:format/2 Improve test of logger_disk_log_h and logger_std_h Update logger documentation Set single_line=true by default in logger_formatter
Diffstat (limited to 'lib/kernel')
-rw-r--r--lib/kernel/doc/src/kernel_app.xml30
-rw-r--r--lib/kernel/doc/src/logger.xml66
-rw-r--r--lib/kernel/doc/src/logger_chapter.xml35
-rw-r--r--lib/kernel/doc/src/logger_formatter.xml217
-rw-r--r--lib/kernel/src/error_logger.erl6
-rw-r--r--lib/kernel/src/logger.erl17
-rw-r--r--lib/kernel/src/logger_disk_log_h.erl4
-rw-r--r--lib/kernel/src/logger_formatter.erl7
-rw-r--r--lib/kernel/src/logger_internal.hrl1
-rw-r--r--lib/kernel/src/logger_server.erl10
-rw-r--r--lib/kernel/src/logger_simple.erl4
-rw-r--r--lib/kernel/src/logger_std_h.erl4
-rw-r--r--lib/kernel/test/logger_SUITE.erl5
-rw-r--r--lib/kernel/test/logger_disk_log_h_SUITE.erl55
-rw-r--r--lib/kernel/test/logger_formatter_SUITE.erl46
-rw-r--r--lib/kernel/test/logger_std_h_SUITE.erl163
16 files changed, 408 insertions, 262 deletions
diff --git a/lib/kernel/doc/src/kernel_app.xml b/lib/kernel/doc/src/kernel_app.xml
index 554d675383..f96d946a5d 100644
--- a/lib/kernel/doc/src/kernel_app.xml
+++ b/lib/kernel/doc/src/kernel_app.xml
@@ -226,7 +226,7 @@
<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>
+ <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>
@@ -251,14 +251,14 @@ logger_disk_log_maxbytes = 1048576</code>
<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 starated,
+ supervisor reports. If the SASL application is started,
these log events will be sent to a second handler instance
- named sasl_h, according to values of the SASL environment
- variables <c>sasl_error_logger</c>
+ named <c>sasl_h</c>, according to values of the SASL
+ environment variables <c>sasl_error_logger</c>
and <c>sasl_errlog_type</c>, see
<seealso marker="sasl:sasl_app#configuration">SASL(6)
</seealso></p>
- <p>The default value is <c>false</c></p>
+ <p>The default value is <c>false</c>.</p>
<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>
@@ -271,7 +271,7 @@ logger_disk_log_maxbytes = 1048576</code>
reports from <c>supervisor</c>
and <c>application_controller</c> shall be logged or
not.</p>
- <p>If <c>logger_sasl_compatible = false</c>,
+ <p>If <c>logger_sasl_compatible = true</c>,
then <c>logger_log_progress</c> is ignored.</p>
</item>
<tag><marker id="logger_format_depth"/>
@@ -280,14 +280,6 @@ logger_disk_log_maxbytes = 1048576</code>
<p>Can be used to limit the size of the
formatted output from the logger handlers.</p>
- <note><p>This configuration parameter was introduced in OTP 18.1
- and is experimental. Based on user feedback, it
- can be changed or improved in future releases, for example,
- to gain better control over how to limit the size of the
- formatted output. We have no plans to remove this
- new feature entirely, unless it turns out to be
- useless.</p></note>
-
<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
@@ -312,11 +304,11 @@ logger_disk_log_maxbytes = 1048576</code>
</item>
<tag><c>logger_max_size = integer() | unlimited</c></tag>
<item>
- <p>This parameter specifies the maximum size (bytes) each
- log event can have when printed by the standard logger
- handler. If the resulting string after formatting an event
- is bigger than this, it will be truncated before printed
- to the handler's destination.</p>
+ <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>
diff --git a/lib/kernel/doc/src/logger.xml b/lib/kernel/doc/src/logger.xml
index 66e6e5c689..2f7feb5eef 100644
--- a/lib/kernel/doc/src/logger.xml
+++ b/lib/kernel/doc/src/logger.xml
@@ -131,8 +131,8 @@
<code>
#{mfa=>{?MODULE,?FUNCTION_NAME,?FUNCTION_ARITY},
- file=>?FILE,
- line=>?LINE}
+ file=>?FILE,
+ line=>?LINE}
</code>
<p>The call is wrapped in a case statement and will be evaluated
@@ -297,7 +297,7 @@
<tag>print</tag>
<item>Pretty print all the current logger configuration to
standard out. Example:
- <code><![CDATA[1> logger:i().
+ <code><![CDATA[1> logger:i(print).
Current logger configuration:
Level: info
FilterDefault: log
@@ -404,21 +404,55 @@ Current logger configuration:
<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
+ 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>
+ </desc>
+ </func>
+
+ <func>
<name name="set_logger_config" arity="2"/>
<fsummary>Add or update configuration data for the logger.</fsummary>
<desc>
- <p>Add or update configuration data for the logger.</p>
+ <p>Add or update configuration data for the logger. If the
+ given <c><anno>Key</anno></c> already exists, its associated
+ value will be set to <c><anno>Value</anno></c>. If it
+ doesn't exist, it will be added.</p>
</desc>
</func>
<func>
<name name="set_handler_config" arity="2"/>
+ <fsummary>Set configuration data for the specified handler.</fsummary>
+ <desc>
+ <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
+ 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>
+ </desc>
+ </func>
+
+ <func>
<name name="set_handler_config" arity="3"/>
<fsummary>Add or update configuration data for the specified
handler.</fsummary>
<desc>
<p>Add or update configuration data for the specified
- handler.</p>
+ handler. If the
+ given <c><anno>Key</anno></c> already exists, its associated
+ value will be set to <c><anno>Value</anno></c>. If it
+ doesn't exist, it will be added.</p>
</desc>
</func>
@@ -437,10 +471,9 @@ Current logger configuration:
<name name="set_process_metadata" arity="1"/>
<fsummary>Set metadata to use when logging from current process.</fsummary>
<desc>
- <p>Set metadata which <c>logger</c> automatically inserts it
- in all log events produced on the current
- process. Subsequent calls will overwrite previous data set
- by this function.</p>
+ <p>Set metadata which <c>logger</c> automatically inserts in
+ all log events produced on the current process. Subsequent
+ calls will overwrite previous data set by this function.</p>
<p>When logging, location data produced by the log macros,
and/or metadata given as argument to the log call (API
function or macro), will be merged with the process
@@ -452,6 +485,21 @@ Current logger configuration:
</func>
<func>
+ <name name="update_process_metadata" arity="1"/>
+ <fsummary>Update metadata to use when logging from current process.</fsummary>
+ <desc>
+ <p>Update metadata to use when logging from current process</p>
+ <p>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))
+ </code>
+ <p>If no process metadata exists, the function behaves as
+ <seealso marker="#set_process_metadata-1"><c>set_process_metadata/1</c>
+ </seealso>.</p>
+ </desc>
+ </func>
+
+ <func>
<name name="get_process_metadata" arity="0"/>
<fsummary>Retrieve data set with set_process_metadata/1.</fsummary>
<desc>
diff --git a/lib/kernel/doc/src/logger_chapter.xml b/lib/kernel/doc/src/logger_chapter.xml
index 88dcfbe8d9..519df2ba48 100644
--- a/lib/kernel/doc/src/logger_chapter.xml
+++ b/lib/kernel/doc/src/logger_chapter.xml
@@ -157,7 +157,7 @@
<p>A formatter is defined as a module exporting the following
function:</p>
- <code>format(Log,Extra) -> string()</code>
+ <code>format(Log,Extra) -> unicode:chardata()</code>
<p>The formatter plugin is called by each handler, and the
returned string can be printed to the handler's destination
@@ -322,19 +322,6 @@
return <c>ignore</c>.</p>
<p>Default is <c>log</c>.</p>
</item>
- <tag><c>depth = pos_integer() | unlimited</c></tag>
- <item>
- <p>Specifies if the depth of terms in the log events shall
- be limited by using control characters <c>~P</c>
- and <c>~W</c> instead of <c>~p</c> and <c>~w</c>,
- respectively. See
- <seealso marker="stdlib:io#format-1"><c>io:format</c></seealso>.</p>
- </item>
- <tag><c>max_size = pos_integer() | unlimited</c></tag>
- <item>
- <p>Specifies if the size of a log event shall be limited by
- truncating the formatted string.</p>
- </item>
<tag><c>formatter = {Module::module(),Extra::term()}</c></tag>
<item>
<p>See <seealso marker="#Formatter">Formatter</seealso> for more
@@ -347,10 +334,9 @@
<p>Note that <c>level</c> and <c>filters</c> are obeyed by
Logger itself before forwarding the log events to each
- handler, while <c>depth</c>, <c>max_size</c>
- and <c>formatter</c> are left to the handler
- implementation. All Logger's built-in handlers do apply these
- configuration parameters before printing.</p>
+ handler, while <c>formatter</c> is left to the handler
+ implementation. All Logger's built-in handlers will call the
+ given formatter before printing.</p>
</section>
</section>
@@ -488,8 +474,9 @@ error_logger:add_report_handler/1,2.
level => debug}
2> <input>logger:add_handler(debug_handler,logger_std_h,Config).</input>
ok</pre>
- <p>By default, the handler receives all events, so we need to add a filter
- to stop all non-debug events:</p>
+ <p>By default, the handler receives all events
+ (<c>filter_defalt=log</c>), so we need to add a filter to stop
+ all non-debug events:</p>
<pre>
3> <input>Fun = fun(#{level:=debug}=Log,_) -> Log; (_,_) -> stop end.</input>
#Fun&lt;erl_eval.12.98642416>
@@ -516,7 +503,7 @@ ok</pre>
<p>It may also implement the following callbacks:</p>
<code>
adding_handler(logger:handler_id(),logger:config()) -> {ok,logger:config()} | {error,term()}
-removing_handler(logger:handler_id()) -> ok
+removing_handler(logger:handler_id(),logger:config()) -> ok
changing_config(logger:handler_id(),logger:config(),logger:config()) -> {ok,logger:config()} | {error,term()}
</code>
<p>When logger:add_handler(Id,Module,Config) is called, logger
@@ -526,7 +513,7 @@ changing_config(logger:handler_id(),logger:config(),logger:config()) -> {ok,logg
events as calls to Module:log/2.</p>
<p>A handler can be removed by calling
logger:remove_handler(Id). logger will call
- Module:removing_handler(Id), and then remove the handler's
+ Module:removing_handler(Id,Config), and then remove the handler's
configuration from the configuration database.</p>
<p>When logger:set_handler_config is called, logger calls
Module:changing_config(Id,OldConfig,NewConfig). If this function
@@ -547,7 +534,7 @@ log(Log,#{formatter:={FModule,FConfig}) ->
this:</p>
<code>
-module(myhandler).
--export([adding_handler/2, removing_handler/1, log/2]).
+-export([adding_handler/2, removing_handler/2, log/2]).
-export([init/1, handle_call/3, handle_cast/2, terminate/2]).
adding_handler(Id,Config) ->
@@ -576,7 +563,7 @@ log(Log,#{myhandler_fd:=Fd,formatter:={FModule,FConfig}}) ->
single process.</p>
<code>
-module(myhandler).
--export([adding_handler/2, removing_handler/1, log/2]).
+-export([adding_handler/2, removing_handler/2, log/2]).
-export([init/1, handle_call/3, handle_cast/2, terminate/2]).
adding_handler(Id,Config) ->
diff --git a/lib/kernel/doc/src/logger_formatter.xml b/lib/kernel/doc/src/logger_formatter.xml
index 6a17e3641f..a0940100ee 100644
--- a/lib/kernel/doc/src/logger_formatter.xml
+++ b/lib/kernel/doc/src/logger_formatter.xml
@@ -37,116 +37,157 @@
<description>
<p>Default formatter for the Logger application.</p>
- </description>
-
- <datatypes>
- <datatype>
- <name name="template"/>
- <desc>
- </desc>
- </datatype>
- </datatypes>
-
- <funcs>
- <func>
- <name name="format" arity="2"/>
- <fsummary>Formats the given message.</fsummary>
- <desc>
- <p>Formats the given message.</p>
- <p>The template is a list of atoms, tuples and strings. Atoms
- can be <c>level</c> or <c>msg</c>, which are placeholders
- for the severity level and the log message,
- repectively. Tuples are interpreted as placeholders for
- metadata. Each element in the tuple must be an atom which
- matches a key in the nested metadata map, e.g. the
- tuple <c>{key1,key2}</c> will be replaced by the value of
- the key2 field in this nested map (the value vill be
- converted to a string):</p>
-
-<code>
-#{key1=>#{key2=>my_value,
- ...},
- ...}</code>
-
-
- <p> Strings are printed literally.</p>
-
- <p><c>depth</c> is a positive integer representing the maximum
- depth to which terms shall be printed by this
- formatter. Format strings passed to this formatter are
- rewritten. The format controls ~p and ~w are replaced with
- ~P and ~W, respectively, and the value is used as the depth
- parameter. For details, see
- <seealso marker="stdlib:io#format-2">io:format/2,3</seealso>
- in STDLIB.</p>
-
- <p><c>chars_limit</c> is a positive integer representing the
- value of the option with the same name to be used when calling
- <seealso marker="stdlib:io#format-3">io:format/3</seealso>. This
- value limits the total number of characters printed bu the
- formatter. Notes that this is a soft limit. For a hard
- truncation limit, see option <c>max_size</c>.</p>
-
- <p><c>max_size</c> is a positive integer representing the
- maximum size a string returned from this formatter can
- have. If the formatted string is longer, after possibly
- being limited by <c>depth</c> and/or <c>chars_limit</c>, it
- will be truncated.</p>
-
- <p><c>utc</c> is a boolean. If set to true, all dates are
- displayed in Universal Coordinated Time. Default
- is <c>false</c>.</p>
- <p><c>report_cb</c> must be a function with arity 1,
- returning <c>{Format,Args}</c>. This function will replace
- any <c>report_cb</c> found in metadata.</p>
-
- <p>If <c>single_line=true</c>, all newlines in the message are
- replaced with <c>", "</c>, and whitespaces following directly
- after newlines are removed. Note that newlines added by the
- formatter template are not replaced.</p>
+ </description>
- <p>If <c>legacy_header=true</c> a header field is added to
+ <section>
+ <title>Configuration</title>
+ <p>The following configuration parameters can be set
+ for <c>logger_formatter</c>:</p>
+ <taglist>
+ <tag><c>single_line = boolean()</c></tag>
+ <item>
+ <p>If set to <c>true</c>, all newlines in the message are
+ replaced with <c>", "</c>, and whitespaces following
+ directly after newlines are removed. Note that newlines
+ added by the formatter template are not replaced.</p>
+ <p>Default is <c>true</c>.</p>
+ </item>
+ <tag><c>legacy_header = boolen()</c></tag>
+ <item>
+ <p>If set to <c>true</c> a header field is added to
logger_formatter's part of <c>Metadata</c>. The value of
this field is a string similar to the header created by the
old <c>error_logger</c> event handlers. It can be included
in the log event by adding the
- tuple <c>{logger_formatter,header}</c> to the template.</p>
-
- <p>The default template when <c>legacy_header=true</c> is</p>
-
- <code>[{logger_formatter,header},"\n",msg,"\n"]</code>
+ tuple <c>{logger_formatter,header}</c> to the
+ template. See <seealso marker="#default_templates">Default
+ Templates</seealso> for more information</p>
+ <p>Default is <c>false</c>.</p>
+ </item>
+ <tag><c>report_cb = fun((logger:report()) -> {io:format(),[term()]})</c></tag>
+ <item>
+ <p>A function with arity 1,
+ returning <c>{Format,Args}</c>. This function will replace
+ any <c>report_cb</c> found in metadata.</p>
+ </item>
+ <tag><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
+ strings passed to this formatter are rewritten. The format
+ controls ~p and ~w are replaced with ~P and ~W,
+ respectively, and the value is used as the depth
+ parameter. For details, see
+ <seealso marker="stdlib:io#format-2">io:format/2,3</seealso>
+ in STDLIB.</p>
+ <p>Default is <c>unlimited</c>.</p>
+ </item>
+ <tag><c>chars_limit = pos_integer() | unlimited</c></tag>
+ <item>
+ <p>A positive integer representing the value of the option
+ with the same name to be used when calling
+ <seealso marker="stdlib:io_lib#format-3">io_lib:format/3</seealso>.
+ This value limits the total number of characters printed
+ for each log event. Note that this is a soft limit. For a
+ hard truncation limit, see option <c>max_size</c>.</p>
+ <p>Default is <c>unlimited</c>.</p>
+ </item>
+ <tag><c>max_size = pos_integer() | unlimited</c></tag>
+ <item>
+ <p>A positive integer representing the absolute maximum size
+ a string returned from this formatter can have. If the
+ formatted string is longer, after possibly being limited
+ by <c>depth</c> and/or <c>chars_limit</c>, it will be
+ truncated.</p>
+ <p>Default is <c>unlimited</c>.</p>
+ </item>
+ <tag><c>template = </c><seealso marker="#type-template"><c>template()</c></seealso></tag>
+ <item>
+ <p>The template is a list of atoms, tuples and strings. The
+ atoms <c>level</c> or <c>msg</c>, are treated as
+ placeholders for the severity level and the log message,
+ repectively. Other atoms or tuples are interpreted as
+ placeholders for metadata, where atoms are expected to
+ match top level keys, and tuples represent paths to sub
+ keys in a nested map. For example the
+ tuple <c>{key1,key2}</c> will be replaced by the value of
+ the <c>key2</c> field in the nested map below. The
+ atom <c>key1</c> on its own would be replaced by the
+ complete value of the <c>key1</c> field. The values are
+ converted to strings.</p>
- <p>which will cause log entries like this:</p>
+<code>
+#{key1=>#{key2=>my_value,
+ ...}
+ ...}</code>
- <code>=ERROR REPORT==== 29-Dec-2017::13:30:51.245123 ===
+ <p>Strings are printed literally.</p>
+ <p>The default template differs depending on the values
+ of <c>legacy_header</c>
+ and <c>single_line</c>. See <seealso marker="#default_templates">Default
+ Templates</seealso> for more information</p>
+ </item>
+ <tag><c>utc = boolean()</c></tag>
+ <item>
+ <p>If set to <c>true</c>, all dates are displayed in Universal
+ Coordinated Time. Default is <c>false</c>.</p>
+ </item>
+ </taglist>
+ </section>
+
+ <section>
+ <marker id="default_templates"/>
+ <title>Default templates</title>
+ <p>The default template when <c>legacy_header=true</c> is</p>
+
+ <code>[{logger_formatter,header},"\n",msg,"\n"]</code>
+
+ <p>which will cause log entries like this:</p>
+
+ <code>=ERROR REPORT==== 29-Dec-2017::13:30:51.245123 ===
process: &lt;0.74.0&gt;
exit_reason: "Something went wrong"</code>
- <p>Note that all eight levels might occur here, not
- only <c>ERROR</c>, <c>WARNING</c> or <c>INFO</c>. And also
- that micro seconds are added at the end of the
- timestamp.</p>
+ <p>Note that all eight levels might occur here, not
+ only <c>ERROR</c>, <c>WARNING</c> or <c>INFO</c>. And also that
+ micro seconds are added at the end of the timestamp.</p>
- <p>The default template when <c>single_line=true</c> is</p>
+ <p>The default template when <c>single_line=true</c> is</p>
- <code>[time," ",level,": ",msg,"\n"]</code>
+ <code>[time," ",level,": ",msg,"\n"]</code>
- <p>which will cause log entries like this:</p>
+ <p>which will cause log entries like this:</p>
- <code>2017-12-29 13:31:49.640317 error: process: &lt;0.74.0&gt;, exit_reason: "Something went wrong"</code>
+ <code>2017-12-29 13:31:49.640317 error: process: &lt;0.74.0&gt;, exit_reason: "Something went wrong"</code>
- <p>The default template when both <c>legacy_header</c> and
- <c>single_line</c> are set to false is:</p>
+ <p>The default template when both <c>legacy_header</c> and
+ <c>single_line</c> are set to false is:</p>
- <code>[time," ",level,":\n",msg,"\n"]</code>
+ <code>[time," ",level,":\n",msg,"\n"]</code>
- <p>which will cause log entries like this:</p>
+ <p>which will cause log entries like this:</p>
- <code>2017-12-29 13:32:25.191925 error:
+ <code>2017-12-29 13:32:25.191925 error:
process: &lt;0.74.0&gt;
exit_reason: "Something went wrong"</code>
+ </section>
+
+ <datatypes>
+ <datatype>
+ <name name="template"/>
+ <desc>
+ </desc>
+ </datatype>
+ </datatypes>
+ <funcs>
+ <func>
+ <name name="format" arity="2"/>
+ <fsummary>Formats the given message.</fsummary>
+ <desc>
+ <p>This the callback function to be called from handlers. It
+ formats the given messages.</p>
</desc>
</func>
diff --git a/lib/kernel/src/error_logger.erl b/lib/kernel/src/error_logger.erl
index 0706220a94..47d0ca5ea3 100644
--- a/lib/kernel/src/error_logger.erl
+++ b/lib/kernel/src/error_logger.erl
@@ -32,7 +32,7 @@
which_report_handlers/0]).
%% logger callbacks
--export([adding_handler/2, removing_handler/1, log/2]).
+-export([adding_handler/2, removing_handler/2, log/2]).
-export([get_format_depth/0, limit_term/1]).
@@ -111,8 +111,8 @@ adding_handler(?MODULE,Config) ->
Error
end.
--spec removing_handler(logger:handler_id()) -> ok.
-removing_handler(?MODULE) ->
+-spec removing_handler(logger:handler_id(),logger:config()) -> ok.
+removing_handler(?MODULE,_Config) ->
stop(),
ok.
diff --git a/lib/kernel/src/logger.erl b/lib/kernel/src/logger.erl
index 943ef8c2d1..5562764204 100644
--- a/lib/kernel/src/logger.erl
+++ b/lib/kernel/src/logger.erl
@@ -44,8 +44,8 @@
%% Misc
-export([compare_levels/2]).
--export([set_process_metadata/1, unset_process_metadata/0,
- get_process_metadata/0]).
+-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]).
@@ -390,6 +390,19 @@ set_process_metadata(Meta) when is_map(Meta) ->
set_process_metadata(Meta) ->
erlang:error(badarg,[Meta]).
+-spec update_process_metadata(Meta) -> ok when
+ Meta :: metadata().
+update_process_metadata(Meta) when is_map(Meta) ->
+ case get_process_metadata() of
+ undefined ->
+ set_process_metadata(Meta);
+ Meta0 when is_map(Meta0) ->
+ set_process_metadata(maps:merge(Meta0,Meta)),
+ ok
+ end;
+update_process_metadata(Meta) ->
+ erlang:error(badarg,[Meta]).
+
-spec get_process_metadata() -> Meta | undefined when
Meta :: metadata().
get_process_metadata() ->
diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl
index 3b71f936d8..0150fa781a 100644
--- a/lib/kernel/src/logger_disk_log_h.erl
+++ b/lib/kernel/src/logger_disk_log_h.erl
@@ -34,7 +34,7 @@
%% logger callbacks
-export([log/2,
- adding_handler/2, removing_handler/1,
+ adding_handler/2, removing_handler/2,
changing_config/3, swap_buffer/2]).
%%%===================================================================
@@ -223,7 +223,7 @@ check_my_config([]) ->
%%%-----------------------------------------------------------------
%%% Handler being removed
-removing_handler(Name) ->
+removing_handler(Name, _Config) ->
stop(Name).
%%%-----------------------------------------------------------------
diff --git a/lib/kernel/src/logger_formatter.erl b/lib/kernel/src/logger_formatter.erl
index 386e7832e2..8e954f8d98 100644
--- a/lib/kernel/src/logger_formatter.erl
+++ b/lib/kernel/src/logger_formatter.erl
@@ -29,7 +29,7 @@
%%%-----------------------------------------------------------------
%%% API
--spec format(Log,Config) -> String when
+-spec format(Log,Config) -> unicode:chardata() when
Log :: logger:log(),
Config :: #{single_line=>boolean(),
legacy_header=>boolean(),
@@ -38,8 +38,7 @@
max_size=>pos_integer() | unlimited,
depth=>pos_integer() | unlimited,
template=>template(),
- utc=>boolean()},
- String :: string().
+ utc=>boolean()}.
format(#{level:=Level,msg:=Msg0,meta:=Meta},Config0)
when is_map(Config0) ->
Config = add_default_config(Config0),
@@ -263,7 +262,7 @@ utcstr(_) -> "".
add_default_config(#{utc:=_}=Config0) ->
Default =
#{legacy_header=>false,
- single_line=>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)),
diff --git a/lib/kernel/src/logger_internal.hrl b/lib/kernel/src/logger_internal.hrl
index 82df499c2b..8c0fc2725d 100644
--- a/lib/kernel/src/logger_internal.hrl
+++ b/lib/kernel/src/logger_internal.hrl
@@ -31,6 +31,7 @@
{no_domain,{fun logger_filters:domain/2,{log,no_domain,[]}}}]).
-define(DEFAULT_FORMATTER,logger_formatter).
-define(DEFAULT_FORMAT_CONFIG,#{legacy_header=>true,
+ single_line=>false,
template=>?DEFAULT_FORMAT_TEMPLATE_HEADER}).
-define(DEFAULT_FORMAT_TEMPLATE_HEADER,
[{logger_formatter,header},"\n",msg,"\n"]).
diff --git a/lib/kernel/src/logger_server.erl b/lib/kernel/src/logger_server.erl
index 6ef3b8582a..a7f302ac8f 100644
--- a/lib/kernel/src/logger_server.erl
+++ b/lib/kernel/src/logger_server.erl
@@ -158,7 +158,7 @@ handle_call({remove_handler,HandlerId}, _From, #state{tid=Tid}=State) ->
Handlers0 = maps:get(handlers,Config,[]),
Handlers = lists:delete(HandlerId,Handlers0),
%% inform the handler
- _ = call_h(Module,removing_handler,[HandlerId],ok),
+ _ = call_h(Module,removing_handler,[HandlerId,Config],ok),
do_set_config(Tid,logger,Config#{handlers=>Handlers}),
logger_config:delete(Tid,HandlerId),
ok;
@@ -234,7 +234,13 @@ handle_info({log,Level,Report,Meta}, State) ->
{noreply, State};
handle_info({Ref,_Reply},State) when is_reference(Ref) ->
%% Assuming this is a timed-out gen_server reply - ignoring
- {noreply, State}.
+ {noreply, State};
+handle_info(Unexpected,State) ->
+ ?LOG_INTERNAL(debug,
+ [{logger,got_unexpected_message},
+ {process,?SERVER},
+ {message,Unexpected}]),
+ {noreply,State}.
terminate(_Reason, _State) ->
ok.
diff --git a/lib/kernel/src/logger_simple.erl b/lib/kernel/src/logger_simple.erl
index 23ff6ccd2e..a1b427b96c 100644
--- a/lib/kernel/src/logger_simple.erl
+++ b/lib/kernel/src/logger_simple.erl
@@ -19,7 +19,7 @@
%%
-module(logger_simple).
--export([adding_handler/2, removing_handler/1, log/2]).
+-export([adding_handler/2, removing_handler/2, log/2]).
-export([get_buffer/0]).
%% This module implements a simple handler for logger. It is the
@@ -63,7 +63,7 @@ adding_handler(?MODULE,Config) ->
{error,{handler_process_name_already_exists,?MODULE}}
end.
-removing_handler(?MODULE) ->
+removing_handler(?MODULE,_Config) ->
case whereis(?MODULE) of
undefined ->
ok;
diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl
index cbc9db372c..31edcfea8b 100644
--- a/lib/kernel/src/logger_std_h.erl
+++ b/lib/kernel/src/logger_std_h.erl
@@ -35,7 +35,7 @@
terminate/2, code_change/3]).
%% logger callbacks
--export([log/2, adding_handler/2, removing_handler/1,
+-export([log/2, adding_handler/2, removing_handler/2,
changing_config/3, swap_buffer/2]).
%%%===================================================================
@@ -207,7 +207,7 @@ check_my_config([]) ->
%%%-----------------------------------------------------------------
%%% Handler being removed
-removing_handler(Name) ->
+removing_handler(Name,_Config) ->
stop(Name).
%%%-----------------------------------------------------------------
diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl
index 0edce3e34c..f311a9c7ed 100644
--- a/lib/kernel/test/logger_SUITE.erl
+++ b/lib/kernel/test/logger_SUITE.erl
@@ -666,6 +666,9 @@ process_metadata(_Config) ->
check_logged(info,S3,#{time=>Time,line=>0,custom=>func}),
ProcMeta = logger:get_process_metadata(),
+ ok = logger:update_process_metadata(#{custom=>changed,custom2=>added}),
+ Expected = ProcMeta#{custom:=changed,custom2=>added},
+ Expected = logger:get_process_metadata(),
ok = logger:unset_process_metadata(),
undefined = logger:get_process_metadata(),
@@ -720,7 +723,7 @@ check_maps(Expected,Got,What) ->
adding_handler(_Id,Config) ->
maybe_send(add),
{ok,Config}.
-removing_handler(_Id) ->
+removing_handler(_Id,_Config) ->
maybe_send(remove),
ok.
changing_config(_Id,_Old,#{call:=Fun}) ->
diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl
index c7c6137380..63e5b56021 100644
--- a/lib/kernel/test/logger_disk_log_h_SUITE.erl
+++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl
@@ -497,24 +497,19 @@ disk_log_sync(Config) ->
filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
formatter=>{?MODULE,nl}}),
- start_tracer([{?MODULE,format,2},
- {disk_log,blog,2},
+ start_tracer([{disk_log,blog,2},
{disk_log,sync,1}],
- [{formatter,"first"},
- {disk_log,blog},
+ [{disk_log,blog,<<"first\n">>},
{disk_log,sync}]),
logger:info("first", ?domain),
%% wait for automatic disk_log_sync
check_tracer(?FILESYNC_REPEAT_INTERVAL*2),
- start_tracer([{?MODULE,format,2},
- {disk_log,blog,2},
+ start_tracer([{disk_log,blog,2},
{disk_log,sync,1}],
- [{formatter,"second"},
- {formatter,"third"},
- {disk_log,blog},
- {disk_log,blog},
+ [{disk_log,blog,<<"second\n">>},
+ {disk_log,blog,<<"third\n">>},
{disk_log,sync}]),
%% two log requests in fast succession will make the handler skip
%% an automatic disk log sync
@@ -531,13 +526,10 @@ disk_log_sync(Config) ->
no_repeat = maps:get(filesync_repeat_interval,
logger_disk_log_h:info(?MODULE)),
- start_tracer([{?MODULE,format,2},
- {disk_log,blog,2},
+ start_tracer([{disk_log,blog,2},
{disk_log,sync,1}],
- [{formatter,"fourth"},
- {disk_log,blog},
- {formatter,"fifth"},
- {disk_log,blog},
+ [{disk_log,blog,<<"fourth\n">>},
+ {disk_log,blog,<<"fifth\n">>},
{disk_log,sync}]),
logger:info("fourth", ?domain),
@@ -566,6 +558,7 @@ disk_log_sync(Config) ->
check_tracer(100),
ok.
disk_log_sync(cleanup,_Config) ->
+ dbg:stop_clear(),
logger:remove_handler(?MODULE).
disk_log_wrap(Config) ->
@@ -623,6 +616,7 @@ disk_log_wrap(Config) ->
ok.
disk_log_wrap(cleanup,_Config) ->
+ dbg:stop_clear(),
logger:remove_handler(?MODULE).
disk_log_full(Config) ->
@@ -668,6 +662,7 @@ disk_log_full(Config) ->
{trace,{error_status,{error,{full,_}}}}] = Received,
ok.
disk_log_full(cleanup, _Config) ->
+ dbg:stop_clear(),
logger:remove_handler(?MODULE).
disk_log_events(Config) ->
@@ -713,6 +708,7 @@ disk_log_events(Config) ->
end, Received),
ok.
disk_log_events(cleanup, _Config) ->
+ dbg:stop_clear(),
logger:remove_handler(?MODULE).
write_failure(Config) ->
@@ -763,7 +759,7 @@ sync_failure(Config) ->
Dir = ?config(priv_dir, Config),
FileName = lists:concat([?MODULE,"_",?FUNCTION_NAME]),
File = filename:join(Dir, FileName),
- Log = lists:concat([File,".1"]),
+
Node = start_h_on_new_node(Config, ?FUNCTION_NAME, File),
false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])),
@@ -832,10 +828,10 @@ log_on_remote_node(Node,Msg) ->
ok.
%% functions for test hook macros to be called by rpc
-set_internal_log(Mod, Func) ->
- ?set_internal_log({Mod,Func}).
-set_result(Op, Result) ->
- ?set_result(Op, Result).
+set_internal_log(_Mod, _Func) ->
+ ?set_internal_log({_Mod,_Func}).
+set_result(_Op, _Result) ->
+ ?set_result(_Op, _Result).
set_defaults() ->
?set_defaults().
@@ -885,7 +881,7 @@ op_switch_to_drop(cleanup, _Config) ->
ok = stop_handler(?MODULE).
op_switch_to_flush() ->
- [{timetrap,{seconds,60}}].
+ [{timetrap,{minutes,3}}].
op_switch_to_flush(Config) ->
{Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
@@ -988,7 +984,7 @@ kill_disabled(cleanup, _Config) ->
ok = stop_handler(?MODULE).
qlen_kill_new(Config) ->
- {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
+ {_Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
Pid0 = whereis(?MODULE),
{_,Mem0} = process_info(Pid0, memory),
RestartAfter = 2000,
@@ -1025,7 +1021,7 @@ qlen_kill_new(cleanup, _Config) ->
ok = stop_handler(?MODULE).
mem_kill_new(Config) ->
- {Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
+ {_Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
Pid0 = whereis(?MODULE),
{_,Mem0} = process_info(Pid0, memory),
RestartAfter = 2000,
@@ -1111,7 +1107,7 @@ restart_after(cleanup, _Config) ->
%% during high load to verify that sync, dropping and flushing is
%% handled correctly.
handler_requests_under_load() ->
- [{timetrap,{seconds,60}}].
+ [{timetrap,{minutes,3}}].
handler_requests_under_load(Config) ->
{Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
NewHConfig =
@@ -1140,7 +1136,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]) ->
@@ -1369,7 +1365,6 @@ start_tracer(Trace,Expected) ->
Pid = self(),
dbg:tracer(process,{fun tracer/2,{Pid,Expected}}),
dbg:p(whereis(?MODULE),[c]),
- dbg:p(Pid,[c]),
tpl(Trace),
ok.
@@ -1387,13 +1382,14 @@ tpl([{M,F,A}|Trace]) ->
tpl([]) ->
ok.
-tracer({trace,_,call,{?MODULE,format,[#{msg:={string,Msg}}|_]}}, {Pid,[{formatter,Msg}|Expected]}) ->
- maybe_tracer_done(Pid,Expected,{formatter,Msg});
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});
tracer({trace,_,call,{Mod,Func,_}}, {Pid,[{Mod,Func}|Expected]}) ->
maybe_tracer_done(Pid,Expected,{Mod,Func});
tracer({trace,_,call,Call}, {Pid,Expected}) ->
+ ct:log("Tracer got unexpected: ~p~nExpected: ~p~n",[Call,Expected]),
Pid ! {tracer_got_unexpected,Call,Expected},
{Pid,Expected}.
@@ -1413,5 +1409,6 @@ check_tracer(T) ->
dbg:stop_clear(),
ct:fail({tracer_got_unexpected,Got,Expected})
after T ->
+ dbg:stop_clear(),
ct:fail({timeout,tracer})
end.
diff --git a/lib/kernel/test/logger_formatter_SUITE.erl b/lib/kernel/test/logger_formatter_SUITE.erl
index ac1abba629..7d1f33746d 100644
--- a/lib/kernel/test/logger_formatter_SUITE.erl
+++ b/lib/kernel/test/logger_formatter_SUITE.erl
@@ -73,18 +73,19 @@ all() ->
default(_Config) ->
String1 = format(info,{"~p",[term]},#{},#{}),
ct:log(String1),
- [_Date,_Time,"info:\nterm\n"] = string:lexemes(String1," "),
+ [_Date,_Time,"info:","term\n"] = string:lexemes(String1," "),
Time = timestamp(),
ExpectedTimestamp = default_time_format(Time),
String2 = format(info,{"~p",[term]},#{time=>Time},#{}),
ct:log(String2),
- " info:\nterm\n" = string:prefix(String2,ExpectedTimestamp),
+ " info: term\n" = string:prefix(String2,ExpectedTimestamp),
ok.
legacy_header(_Config) ->
Time = timestamp(),
- String1 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>true}),
+ String1 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>true,
+ single_line=>false}),
ct:log(String1),
"=INFO REPORT==== "++Rest = String1,
[Timestamp,"\nterm\n"] = string:lexemes(Rest," ="),
@@ -98,12 +99,14 @@ legacy_header(_Config) ->
true = lists:member(M,["Jan","Feb","Mar","Apr","May","Jun",
"Jul","Aug","Sep","Oct","Nov","Dec"]),
- String2 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>false}),
+ String2 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>false,
+ single_line=>false}),
ct:log(String2),
ExpectedTimestamp = default_time_format(Time),
" info:\nterm\n" = string:prefix(String2,ExpectedTimestamp),
- String3 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>bad}),
+ String3 = format(info,{"~p",[term]},#{time=>Time},#{legacy_header=>bad,
+ single_line=>false}),
ct:log(String3),
String3 = String2,
@@ -114,7 +117,8 @@ legacy_header(_Config) ->
String4 = String1,
String5 = format(info,{"~p",[term]},#{}, % <--- no time
- #{legacy_header=>true}),
+ #{legacy_header=>true,
+ single_line=>false}),
ct:log(String5),
"=INFO REPORT==== "++_ = String5,
ok.
@@ -289,38 +293,36 @@ report_cb(_Config) ->
ok.
max_size(_Config) ->
- Template = [msg],
+ Cfg = #{template=>[msg],
+ single_line=>false},
"12345678901234567890" =
- format(info,{"12345678901234567890",[]},#{},#{template=>Template}),
+ 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",[]},#{},#{template=>Template}),
+ format(info,{"12345678901234567890",[]},#{},Cfg),
"12345678901234567890123456789012345678901234567..." = % 50
format(info,
{"123456789012345678901234567890123456789012345678901234567890",
[]},
#{},
- #{template=>Template}),
+ Cfg),
application:set_env(kernel,logger_max_size,53),
"12345678901234567890123456789012345678901234567890..." = %53
format(info,
{"123456789012345678901234567890123456789012345678901234567890",
[]},
#{},
- #{template=>Template}),
+ Cfg),
"123456789012..." =
- format(info,{"12345678901234567890",[]},#{},#{template=>Template,
- max_size=>15}),
+ format(info,{"12345678901234567890",[]},#{},Cfg#{max_size=>15}),
"12345678901234567890" =
- format(info,{"12345678901234567890",[]},#{},#{template=>Template,
- max_size=>unlimited}),
+ format(info,{"12345678901234567890",[]},#{},Cfg#{max_size=>unlimited}),
%% Check that one newline at the end of the line is kept (if it exists)
"12345678901...\n" =
- format(info,{"12345678901234567890\n",[]},#{},#{template=>Template,
- max_size=>15}),
+ format(info,{"12345678901234567890\n",[]},#{},Cfg#{max_size=>15}),
"12345678901...\n" =
- format(info,{"12345678901234567890",[]},#{},#{template=>[msg,"\n"],
- max_size=>15}),
+ format(info,{"12345678901234567890",[]},#{},Cfg#{template=>[msg,"\n"],
+ max_size=>15}),
ok.
max_size(cleanup,_Config) ->
application:unset_env(kernel,logger_max_size),
@@ -441,20 +443,20 @@ format_time(_Config) ->
ExpectedTimestamp1 = default_time_format(Time1),
String1 = format(info,{"~p",[term]},#{time=>Time1},#{}),
ct:log(String1),
- " info:\nterm\n" = string:prefix(String1,ExpectedTimestamp1),
+ " 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:\nterm\n" = string:prefix(String2,ExpectedTimestamp2),
+ " 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:\nterm\n" = string:prefix(String3,ExpectedTimestamp3),
+ " info: term\n" = string:prefix(String3,ExpectedTimestamp3),
ok.
diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl
index e940e0a026..7c8d63cbbd 100644
--- a/lib/kernel/test/logger_std_h_SUITE.erl
+++ b/lib/kernel/test/logger_std_h_SUITE.erl
@@ -499,86 +499,79 @@ filesync(Config) ->
#{logger_std_h => #{type => Type},
filter_default=>log,
filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]),
- formatter=>{?MODULE,self()}}),
- Tester = self(),
- TraceFun = fun({trace,_,call,{Mod,Func,Details}}, Pid) ->
- Pid ! {trace,Mod,Func,Details},
- Pid;
- ({trace,TPid,'receive',Received}, Pid) ->
- Pid ! {trace,TPid,Received},
- Pid
- end,
- {ok,_} = dbg:tracer(process, {TraceFun, Tester}),
- FileCtrlPid = maps:get(file_ctrl_pid , logger_std_h:info(?MODULE)),
- {ok,_} = dbg:p(FileCtrlPid, [c]),
- {ok,_} = dbg:tpl(logger_std_h, write_to_dev, 5, []),
- {ok,_} = dbg:tpl(logger_std_h, sync_dev, 4, []),
- {ok,_} = dbg:tp(file, datasync, 1, []),
+ formatter=>{?MODULE,nl}}),
+
+ %% check repeated filesync happens
+ start_tracer([{logger_std_h, write_to_dev, 5},
+ {logger_std_h, sync_dev, 4},
+ {file, datasync, 1}],
+ [{logger_std_h, write_to_dev, <<"first\n">>},
+ {logger_std_h, sync_dev},
+ {file,datasync}]),
logger:info("first", ?domain),
%% wait for automatic filesync
- timer:sleep(?FILESYNC_REP_INT),
- Expected1 = [{log,"first"}, {trace,logger_std_h,write_to_dev},
- {trace,logger_std_h,sync_dev}, {trace,file,datasync}],
-
+ check_tracer(?FILESYNC_REP_INT*2),
+
+ %% check that explicit filesync is only done once
+ start_tracer([{logger_std_h, write_to_dev, 5},
+ {logger_std_h, sync_dev, 4},
+ {file, datasync, 1}],
+ [{logger_std_h, write_to_dev, <<"second\n">>},
+ {logger_std_h, sync_dev},
+ {file,datasync},
+ {no_more,500}
+ ]),
logger:info("second", ?domain),
%% do explicit filesync
logger_std_h:filesync(?MODULE),
%% a second filesync should be ignored
logger_std_h:filesync(?MODULE),
- Expected2 = [{log,"second"}, {trace,logger_std_h,write_to_dev},
- {trace,logger_std_h,sync_dev}, {trace,file,datasync}],
+ check_tracer(100),
%% check that if there's no repeated filesync active,
%% a filesync is still performed when handler goes idle
logger:set_handler_config(?MODULE, logger_std_h,
#{filesync_repeat_interval => no_repeat}),
no_repeat = maps:get(filesync_repeat_interval, logger_std_h:info(?MODULE)),
+ %% The following timer is to make sure the time from last log
+ %% ("second") to next ("third") is long enough, so the a flush is
+ %% triggered by the idle timeout between "thrid" and "fourth".
+ timer:sleep(?IDLE_DETECT_TIME_MSEC*2),
+ start_tracer([{logger_std_h, write_to_dev, 5},
+ {logger_std_h, sync_dev, 4},
+ {file, datasync, 1}],
+ [{logger_std_h, write_to_dev, <<"third\n">>},
+ {logger_std_h, sync_dev},
+ {file,datasync},
+ {logger_std_h, write_to_dev, <<"fourth\n">>},
+ {logger_std_h, sync_dev},
+ {file,datasync}]),
logger:info("third", ?domain),
+ %% wait for automatic filesync
timer:sleep(?IDLE_DETECT_TIME_MSEC*2),
logger:info("fourth", ?domain),
%% wait for automatic filesync
- timer:sleep(?IDLE_DETECT_TIME_MSEC*2),
- Expected3 = [{log,"third"}, {trace,logger_std_h,write_to_dev},
- {log,"fourth"}, {trace,logger_std_h,write_to_dev},
- {trace,logger_std_h,sync_dev}, {trace,file,datasync}],
-
- dbg:stop_clear(),
-
- %% verify that filesync has been performed as expected
- Received1 = lists:map(fun({trace,M,F,_}) -> {trace,M,F};
- (Other) -> Other
- end, test_server:messages_get()),
- ct:pal("Trace #1 =~n~p", [Received1]),
- Received1 = Expected1 ++ Expected2 ++ Expected3,
-
- try_read_file(Log, {ok,<<"first\nsecond\nthird\nfourth\n">>}, 1000),
-
- {ok,_} = dbg:tracer(process, {TraceFun, Tester}),
- {ok,_} = dbg:p(whereis(?MODULE), [c]),
- {ok,_} = dbg:tpl(logger_std_h, handle_cast, 2, []),
+ check_tracer(?IDLE_DETECT_TIME_MSEC*2),
%% switch repeated filesync on and verify that the looping works
SyncInt = 1000,
WaitT = 4500,
+ OneSync = {logger_std_h,handle_cast,repeated_filesync},
+ %% receive 1 initial repeated_filesync, then 1 per sec
+ start_tracer([{logger_std_h,handle_cast,2}],
+ [OneSync || _ <- lists:seq(1, 1 + trunc(WaitT/SyncInt))]),
+
logger:set_handler_config(?MODULE, logger_std_h,
#{filesync_repeat_interval => SyncInt}),
SyncInt = maps:get(filesync_repeat_interval, logger_std_h:info(?MODULE)),
timer:sleep(WaitT),
logger:set_handler_config(?MODULE, logger_std_h,
- #{filesync_repeat_interval => no_repeat}),
- dbg:stop_clear(),
-
- Received2 = lists:map(fun({trace,_M,handle_cast,[{Op,_},_]}) -> {trace,Op};
- (Other) -> Other
- end, test_server:messages_get()),
- ct:pal("Trace #2 =~n~p", [Received2]),
- OneSync = [{trace,repeated_filesync}],
- %% receive 1 initial repeated_filesync, then 1 per sec
- Received2 =
- lists:flatten([OneSync || _ <- lists:seq(1, 1 + trunc(WaitT/SyncInt))]),
+ #{filesync_repeat_interval => no_repeat}),
+ check_tracer(100),
ok.
filesync(cleanup, _Config) ->
+ dbg:stop_clear(),
logger:remove_handler(?MODULE).
write_failure(Config) ->
@@ -785,7 +778,7 @@ op_switch_to_drop_tty(cleanup, _Config) ->
ok = stop_handler(?MODULE).
op_switch_to_flush_file() ->
- [{timetrap,{seconds,60}}].
+ [{timetrap,{minutes,3}}].
op_switch_to_flush_file(Config) ->
{Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
@@ -1052,7 +1045,7 @@ restart_after(cleanup, _Config) ->
%% during high load to verify that sync, dropping and flushing is
%% handled correctly.
handler_requests_under_load() ->
- [{timetrap,{seconds,60}}].
+ [{timetrap,{minutes,3}}].
handler_requests_under_load(Config) ->
{Log,HConfig,StdHConfig} =
start_handler(?MODULE, ?FUNCTION_NAME, Config),
@@ -1394,3 +1387,67 @@ analyse(Msgs) ->
From ! {result,self(),TestFun(Msgs)},
analyse(Msgs)
end.
+
+start_tracer(Trace,Expected) ->
+ Pid = self(),
+ FileCtrlPid = maps:get(file_ctrl_pid, logger_std_h:info(?MODULE)),
+ dbg:tracer(process,{fun tracer/2,{Pid,Expected}}),
+ dbg:p(whereis(?MODULE),[c]),
+ dbg:p(FileCtrlPid,[c]),
+ tpl(Trace),
+ ok.
+
+tpl([{M,F,A}|Trace]) ->
+ {ok,Match} = dbg:tpl(M,F,A,[]),
+ case lists:keyfind(matched,1,Match) of
+ {_,_,1} ->
+ ok;
+ _ ->
+ dbg:stop_clear(),
+ throw({skip,"Can't trace "++atom_to_list(M)++":"++
+ atom_to_list(F)++"/"++integer_to_list(A)})
+ end,
+ tpl(Trace);
+tpl([]) ->
+ ok.
+
+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,_,_,_]}},
+ {Pid,[{Mod,Func,Data}|Expected]}) ->
+ maybe_tracer_done(Pid,Expected,{Mod,Func,Data});
+tracer({trace,_,call,{Mod,Func,_}}, {Pid,[{Mod,Func}|Expected]}) ->
+ maybe_tracer_done(Pid,Expected,{Mod,Func});
+tracer({trace,_,call,Call}, {Pid,Expected}) ->
+ ct:log("Tracer got unexpected: ~p~nExpected: ~p~n",[Call,Expected]),
+ Pid ! {tracer_got_unexpected,Call,Expected},
+ {Pid,Expected}.
+
+maybe_tracer_done(Pid,[]=Expected,Got) ->
+ ct:log("Tracer got: ~p~n",[Got]),
+ Pid ! {tracer_done,0},
+ {Pid,Expected};
+maybe_tracer_done(Pid,[{no_more,T}]=Expected,Got) ->
+ ct:log("Tracer got: ~p~n",[Got]),
+ Pid ! {tracer_done,T},
+ {Pid,Expected};
+maybe_tracer_done(Pid,Expected,Got) ->
+ ct:log("Tracer got: ~p~n",[Got]),
+ {Pid,Expected}.
+
+check_tracer(T) ->
+ check_tracer(T,fun() -> ct:fail({timeout,tracer}) end).
+check_tracer(T,TimeoutFun) ->
+ receive
+ {tracer_done,Delay} ->
+ %% Possibly wait Delay ms to check that no unexpected
+ %% traces are received
+ check_tracer(Delay,fun() -> ok end);
+ {tracer_got_unexpected,Got,Expected} ->
+ dbg:stop_clear(),
+ ct:fail({tracer_got_unexpected,Got,Expected})
+ after T ->
+ dbg:stop_clear(),
+ TimeoutFun()
+ end.