diff options
Diffstat (limited to 'lib/kernel')
| -rw-r--r-- | lib/kernel/doc/src/kernel_app.xml | 30 | ||||
| -rw-r--r-- | lib/kernel/doc/src/logger.xml | 66 | ||||
| -rw-r--r-- | lib/kernel/doc/src/logger_chapter.xml | 35 | ||||
| -rw-r--r-- | lib/kernel/doc/src/logger_formatter.xml | 217 | ||||
| -rw-r--r-- | lib/kernel/src/error_logger.erl | 6 | ||||
| -rw-r--r-- | lib/kernel/src/logger.erl | 17 | ||||
| -rw-r--r-- | lib/kernel/src/logger_disk_log_h.erl | 4 | ||||
| -rw-r--r-- | lib/kernel/src/logger_formatter.erl | 7 | ||||
| -rw-r--r-- | lib/kernel/src/logger_internal.hrl | 1 | ||||
| -rw-r--r-- | lib/kernel/src/logger_server.erl | 10 | ||||
| -rw-r--r-- | lib/kernel/src/logger_simple.erl | 4 | ||||
| -rw-r--r-- | lib/kernel/src/logger_std_h.erl | 4 | ||||
| -rw-r--r-- | lib/kernel/test/logger_SUITE.erl | 5 | ||||
| -rw-r--r-- | lib/kernel/test/logger_disk_log_h_SUITE.erl | 55 | ||||
| -rw-r--r-- | lib/kernel/test/logger_formatter_SUITE.erl | 46 | ||||
| -rw-r--r-- | lib/kernel/test/logger_std_h_SUITE.erl | 163 |
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<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: <0.74.0> 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: <0.74.0>, exit_reason: "Something went wrong"</code> + <code>2017-12-29 13:31:49.640317 error: process: <0.74.0>, 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: <0.74.0> 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. |