diff options
Diffstat (limited to 'lib/kernel')
| -rw-r--r-- | lib/kernel/doc/src/logger_chapter.xml | 263 | ||||
| -rw-r--r-- | lib/kernel/doc/src/logger_disk_log_h.xml | 134 | ||||
| -rw-r--r-- | lib/kernel/doc/src/logger_std_h.xml | 104 | ||||
| -rw-r--r-- | lib/kernel/src/logger_disk_log_h.erl | 12 | ||||
| -rw-r--r-- | lib/kernel/src/logger_h_common.erl | 4 | ||||
| -rw-r--r-- | lib/kernel/src/logger_h_common.hrl | 4 | ||||
| -rw-r--r-- | lib/kernel/src/logger_std_h.erl | 12 | ||||
| -rw-r--r-- | lib/kernel/test/logger_SUITE.erl | 2 | ||||
| -rw-r--r-- | lib/kernel/test/logger_disk_log_h_SUITE.erl | 108 | ||||
| -rw-r--r-- | lib/kernel/test/logger_env_var_SUITE.erl | 5 | ||||
| -rw-r--r-- | lib/kernel/test/logger_formatter_SUITE.erl | 2 | ||||
| -rw-r--r-- | lib/kernel/test/logger_legacy_SUITE.erl | 13 | ||||
| -rw-r--r-- | lib/kernel/test/logger_simple_h_SUITE.erl | 38 | ||||
| -rw-r--r-- | lib/kernel/test/logger_std_h_SUITE.erl | 172 | ||||
| -rw-r--r-- | lib/kernel/test/logger_test_lib.erl | 4 |
15 files changed, 490 insertions, 387 deletions
diff --git a/lib/kernel/doc/src/logger_chapter.xml b/lib/kernel/doc/src/logger_chapter.xml index f7df0a3e6e..a4951022bb 100644 --- a/lib/kernel/doc/src/logger_chapter.xml +++ b/lib/kernel/doc/src/logger_chapter.xml @@ -97,6 +97,7 @@ defined.</p> </section> <section> + <marker id="logger_api"/> <title>Logger API</title> <p>The API for logging consists of a set of <seealso marker="logger#macros">macros</seealso>, and a set @@ -1103,184 +1104,210 @@ do_log(Fd, LogEvent, #{formatter := {FModule, FConfig}}) -> <section> <marker id="overload_protection"/> <title>Protecting the Handler from Overload</title> - <p>In order for the built-in handlers to survive, and stay responsive, - during periods of high load (i.e. when huge numbers of incoming - log requests must be handled), a mechanism for overload protection - has been implemented in the - <seealso marker="logger_std_h"><c>logger_std_h</c></seealso> - and <seealso marker="logger_disk_log_h"><c>logger_disk_log_h</c> - </seealso> handler. The mechanism, used by both handlers, works - as follows:</p> + <p>The default handlers, <seealso marker="logger_std_h"> + <c>logger_std_h</c></seealso> and <seealso marker="logger_disk_log_h"> + <c>logger_disk_log_h</c></seealso>, feature an overload protection + mechanism, which makes it possible for the handlers to survive, + and stay responsive, during periods of high load (when huge + numbers of incoming log requests must be handled). + The mechanism works as follows:</p> <section> <title>Message Queue Length</title> <p>The handler process keeps track of the length of its message - queue and reacts in different ways depending on the current status. - The purpose is to keep the handler in, or (as quickly as possible), - get the handler into, a state where it can keep up with the pace - of incoming log requests. The memory usage of the handler must never - keep growing larger and larger, since that would eventually cause the - handler to crash. Three thresholds with associated actions have been - defined:</p> + queue and takes some form of action when the current length exceeds a + configurable threshold. The purpose is to keep the handler in, or to + as quickly as possible get the handler into, a state where it can + keep up with the pace of incoming log events. The memory use of the + handler must never grow larger and larger, since that will eventually + cause the handler to crash. These three thresholds, with associated + actions, exist:</p> <taglist> - <tag><c>toggle_sync_qlen</c></tag> + <tag><c>sync_mode_qlen</c></tag> <item> - <p>The default value of this level is <c>10</c> messages, - and as long as the length of the message queue is lower, all log - requests are handled asynchronously. This simply means that the - process sending the log request (by calling a log function in the - Logger API) does not wait for a response from the handler but - continues executing immediately after the request (i.e. it will not - be affected by the time it takes the handler to print to the log - device). If the message queue grows larger than this value, however, - the handler starts handling the log requests synchronously instead, - meaning the process sending the request will have to wait for a - response. When the handler manages to reduce the message queue to a - level below the <c>toggle_sync_qlen</c> threshold, asynchronous + <p>As long as the length of the message queue is lower than this + value, all log events are handled asynchronously. This means that + the client process sending the log event, by calling a log function + in the <seealso marker="logger_chapter#logger_api">Logger API</seealso>, + does not wait for a response from the handler but continues + executing immediately after the event is sent. It is not affected + by the time it takes the handler to print the event to the log + device. If the message queue grows larger than this value, + the handler starts handling log events synchronously instead, + meaning that the client process sending the event must wait for a + response. When the handler reduces the message queue to a + level below the <c>sync_mode_qlen</c> threshold, asynchronous operation is resumed. The switch from asynchronous to synchronous - mode will force the logging tempo of few busy senders to slow down, - but cannot protect the handler sufficiently in situations of many - concurrent senders.</p> + mode can slow down the logging tempo of one, or a few, busy senders, + but cannot protect the handler sufficiently in a situation of many + busy concurrent senders.</p> + <p>Defaults to <c>10</c> messages.</p> </item> - <tag><c>drop_new_reqs_qlen</c></tag> + <tag><c>drop_mode_qlen</c></tag> <item> - <p>When the message queue has grown larger than this threshold, which - defaults to <c>200</c> messages, the handler switches to a mode in - which it drops any new requests being made. Dropping a message in - this state means that the log function never actually sends a message - to the handler. The log call simply returns without an action. When - the length of the message queue has been reduced to a level below this - threshold, synchronous or asynchronous request handling mode is - resumed.</p> + <p>When the message queue grows larger than this threshold, the + handler switches to a mode in which it drops all new events that + senders want to log. Dropping an event in this mode means that the + call to the log function never results in a message being sent to + the handler, but the function returns without taking any action. + The handler keeps logging the events that are already in its message + queue, and when the length of the message queue is reduced to a level + below the threshold, synchronous or asynchronous mode is resumed. + Notice that when the handler activates or deactivates drop mode, + information about it is printed in the log.</p> + <p>Defaults to <c>200</c> messages.</p> </item> - <tag><c>flush_reqs_qlen</c></tag> + <tag><c>flush_qlen</c></tag> <item> - <p>Above this threshold, which defaults to <c>1000</c> messages, a - flush operation takes place, in which all messages buffered in the - process mailbox get deleted without any logging actually taking - place. (Processes waiting for a response from a synchronous log request - will receive a reply indicating that the request has been dropped).</p> + <p>If the length of the message queue grows larger than this threshold, + a flush (delete) operation takes place. To flush events, the handler + discards the messages in the message queue by receiving them in a + loop without logging. Client processes waiting for a response from a + synchronous log request receive a reply from the handler indicating + that the request is dropped. The handler process increases its + priority during the flush loop to make sure that no new events + are received during the operation. Notice that after the flush operation + is performed, the handler prints information in the log about how many + events have been deleted.</p> + <p>Defaults to <c>1000</c> messages.</p> </item> </taglist> <p>For the overload protection algorithm to work properly, it is required that:</p> - <p><c>toggle_sync_qlen =< drop_new_reqs_qlen =< flush_reqs_qlen</c></p> + <p><c>sync_mode_qlen =< drop_mode_qlen =< flush_qlen</c></p> <p>and that:</p> - <p><c>drop_new_reqs_qlen > 1</c></p> + <p><c>drop_mode_qlen > 1</c></p> - <p>If <c>toggle_sync_qlen</c> is set to <c>0</c>, the handler will handle all - requests synchronously. Setting the value of <c>toggle_sync_qlen</c> to the same - as <c>drop_new_reqs_qlen</c>, disables the synchronous mode. Likewise, setting - the value of <c>drop_new_reqs_qlen</c> to the same as <c>flush_reqs_qlen</c>, - disables the drop mode.</p> + <p>To disable certain modes, do the following:</p> + <list> + <item>If <c>sync_mode_qlen</c> is set to <c>0</c>, all log events are handled + synchronously. That is, asynchronous logging is disabled.</item> + <item>If <c>sync_mode_qlen</c> is set to the same value as + <c>drop_mode_qlen</c>, synchronous mode is disabled. That is, the handler + always runs in asynchronous mode, unless dropping or flushing is invoked.</item> + <item>If <c>drop_mode_qlen</c> is set to the same value as <c>flush_qlen</c>, + drop mode is disabled and can never occur.</item> + </list> <p>During high load scenarios, the length of the handler message queue rarely grows in a linear and predictable way. Instead, whenever the - handler process gets scheduled in, it can have an almost arbitrary number - of messages waiting in the mailbox. It's for this reason that the overload - protection mechanism is focused on acting quickly and quite drastically - (such as immediately dropping or flushing messages) as soon as a large - queue length is detected. </p> - - <p>The thresholds listed above may be modified by the user if, e.g, a handler - shouldn't drop or flush messages unless the message queue length grows - extremely large. (The handler must be allowed to use large amounts of memory - under such circumstances however). Another example of when the user might want - to change the settings is if, for performance reasons, the logging processes must - never get blocked by synchronous log requests, while dropping or flushing requests - is perfectly acceptable (since it doesn't affect the performance of the - loggers).</p> + handler process is scheduled in, it can have an almost arbitrary number + of messages waiting in the message queue. It is for this reason that the overload + protection mechanism is focused on acting quickly, and quite drastically, + such as immediately dropping or flushing messages, when a large queue length + is detected.</p> + + <p>The values of the previously listed thresholds can be specified by the user. + This way, a handler can be configured to, for example, not drop or flush + messages unless the message queue length of the handler process grows extremely + large. Notice that large amounts of memory can be required for the node under such + circumstances. Another example of user configuration is when, for performance + reasons, the client processes must never be blocked by synchronous log requests. + It is possible, perhaps, that dropping or flushing events is still acceptable, since + it does not affect the performance of the client processes sending the log events.</p> <p>A configuration example:</p> <code type="none"> logger:add_handler(my_standard_h, logger_std_h, - #{config => - #{type => {file,"./system_info.log"}, - toggle_sync_qlen => 100, - drop_new_reqs_qlen => 1000, - flush_reqs_qlen => 2000}}). + #{config => #{type => {file,"./system_info.log"}, + sync_mode_qlen => 100, + drop_mode_qlen => 1000, + flush_qlen => 2000}}). </code> </section> <section> <title>Controlling Bursts of Log Requests</title> - <p>A potential problem with large bursts of log requests, is that log files - may get full or wrapped too quickly (in the latter case overwriting - previously logged data that could be of great importance). For this reason, - both built-in handlers offer the possibility to set a maximum level of how - many requests to process with a certain time frame. With this burst control - feature enabled, the handler will take care of bursts of log requests - without choking log files, or the terminal, with massive amounts of - printouts. These are the configuration parameters:</p> - + <p>Large bursts of log events - many events received by the handler + under a short period of time - can potentially cause problems, such as:</p> + <list> + <item>Log files grow very large, very quickly.</item> + <item>Circular logs wrap too quickly so that important data is overwritten.</item> + <item>Write buffers grow large, which slows down file sync operations.</item> + </list> + + <p>For this reason, both built-in handlers offer the possibility to specify the + maximum number of events to be handled within a certain time frame. + With this burst control feature enabled, the handler can avoid choking the log with + massive amounts of printouts. The configuration parameters are:</p> <taglist> - <tag><c>enable_burst_limit</c></tag> + <tag><c>burst_limit_enable</c></tag> <item> - <p>This is set to <c>true</c> by default. The value <c>false</c> - disables the burst control feature.</p> + <p>Value <c>true</c> enables burst control and <c>false</c> disables it.</p> + <p>Defaults to <c>true</c>.</p> </item> - <tag><c>burst_limit_size</c></tag> + <tag><c>burst_limit_max_count</c></tag> <item> - <p>This is how many requests should be processed within the - <c>burst_window_time</c> time frame. After this maximum has been - reached, successive requests will be dropped until the end of the - time frame. The default value is <c>500</c> messages.</p> + <p>This is the maximum number of events to handle within a + <c>burst_limit_window_time</c> time frame. After the limit is + reached, successive events are dropped until the end of the time frame.</p> + <p>Defaults to <c>500</c> events.</p> </item> - <tag><c>burst_window_time</c></tag> + <tag><c>burst_limit_window_time</c></tag> <item> - <p>The default window is <c>1000</c> milliseconds long.</p> + <p>See the previous description of <c>burst_limit_max_count</c>.</p> + <p>Defaults to <c>1000</c> milliseconds.</p> </item> </taglist> <p>A configuration example:</p> <code type="none"> logger:add_handler(my_disk_log_h, logger_disk_log_h, - #{disk_log_opts => - #{file => "./my_disk_log"}, - config => - #{burst_limit_size => 10, - burst_window_time => 500}}). + #{config => #{file => "./my_disk_log", + burst_limit_enable => true, + burst_limit_max_count => 20, + burst_limit_window_time => 500}}). </code> </section> <section> - <title>Terminating a Large Handler</title> - <p>A handler process may grow large even if it can manage peaks of high load - without crashing. The overload protection mechanism includes user configurable - levels for a maximum allowed message queue length and maximum allowed memory - usage. This feature is disabled by default, but can be switched on by means - of the following configuration parameters:</p> - + <title>Terminating an Overloaded Handler</title> + <p>It is possible that a handler, even if it can successfully manage peaks + of high load without crashing, can build up a large message queue, or use a + large amount of memory. The overload protection mechanism includes an + automatic termination and restart feature for the purpose of guaranteeing + that a handler does not grow out of bounds. The feature is configured + with the following parameters:</p> <taglist> - <tag><c>enable_kill_overloaded</c></tag> + <tag><c>overload_kill_enable</c></tag> <item> - <p>This is set to <c>false</c> by default. The value <c>true</c> - enables the feature.</p> + <p>Value <c>true</c> enables the feature and <c>false</c> disables it.</p> + <p>Defaults to <c>false</c>.</p> </item> - <tag><c>handler_overloaded_qlen</c></tag> + <tag><c>overload_kill_qlen</c></tag> <item> - <p>This is the maximum allowed queue length. If the mailbox grows larger - than this, the handler process gets terminated.</p> + <p>This is the maximum allowed queue length. If the message queue grows + larger than this, the handler process is terminated.</p> + <p>Defaults to <c>20000</c> messages.</p> </item> - <tag><c>handler_overloaded_mem</c></tag> + <tag><c>overload_kill_mem_size</c></tag> <item> - <p>This is the maximum allowed memory usage of the handler process. If - the handler grows any larger, the process gets terminated.</p> + <p>This is the maximum memory size that the handler process is allowed to use. + If the handler grows larger than this, the process is terminated.</p> + <p>Defaults to <c>3000000</c> bytes.</p> </item> - <tag><c>handler_restart_after</c></tag> + <tag><c>overload_kill_restart_after</c></tag> <item> - <p>If the handler gets terminated because of its queue length or - memory usage, it can get automatically restarted again after a - configurable delay time. The time is specified in milliseconds - and <c>5000</c> is the default value. The value <c>never</c> can - also be set, which prevents a restart.</p> + <p>If the handler is terminated, it restarts automatically after a + delay specified in milliseconds. The value <c>infinity</c> prevents + restarts.</p> + <p>Defaults to <c>5000</c> milliseconds.</p> </item> </taglist> + <p>If the handler process is terminated because of overload, it prints + information about it in the log. It also prints information about when a + restart has taken place, and the handler is back in action.</p> + <note> + <p>The sizes of the log events affect the memory needs of the handler. + For information about how to limit the size of log events, see the + <seealso marker="logger_formatter"><c>logger_formatter(3)</c></seealso> + manual page.</p> + </note> </section> </section> diff --git a/lib/kernel/doc/src/logger_disk_log_h.xml b/lib/kernel/doc/src/logger_disk_log_h.xml index 63c29cb010..98439983cf 100644 --- a/lib/kernel/doc/src/logger_disk_log_h.xml +++ b/lib/kernel/doc/src/logger_disk_log_h.xml @@ -33,106 +33,112 @@ <file>logger_disk_log_h.xml</file> </header> <module>logger_disk_log_h</module> - <modulesummary>A disk_log based handler for the Logger.</modulesummary> + <modulesummary>A disk_log based handler for Logger</modulesummary> <description> <p>This is a handler for Logger that offers circular (wrapped) logs by using <seealso marker="disk_log"><c>disk_log</c></seealso>. - Multiple instances - of this handler can be added to Logger, and each instance prints to - its own disk_log file, created with the name and settings specified in - the handler configuration.</p> + Multiple instances of this handler can be added to Logger, and each instance + prints to its own disk log file, created with the name and settings specified + in the handler configuration.</p> <p>The default standard handler, <seealso marker="logger_std_h"><c>logger_std_h</c></seealso>, can be - replaced by a disk_log handler at start up of the Kernel application. + replaced by a disk_log handler at startup of the Kernel application. See an example of this below.</p> - <p>The handler has an overload protection mechanism that will keep the handler - process and the Kernel application alive during a high load of log - requests. How this feature works, and how to modify the configuration, - is described in the + <p>The handler has an overload protection mechanism that keeps the handler + process and the Kernel application alive during high loads of log + events. How overload protection works, and how to configure it, is + described in the <seealso marker="logger_chapter#overload_protection"><c>User's Guide</c> </seealso>.</p> <p>To add a new instance of the disk_log handler, use <seealso marker="logger#add_handler-3"><c>logger:add_handler/3</c> - </seealso>. The handler configuration argument is a map which may contain + </seealso>. The handler configuration argument is a map which can contain general configuration parameters, as documented in the <seealso marker="logger_chapter#handler_configuration"><c>User's Guide</c> - </seealso>, as well as handler specific parameters.</p> - <p>The settings for the disk_log log file should be specified with the - key <c>disk_log_opts</c>. These settings are a subset of the disk_log - data type - <seealso marker="disk_log#open-1"><c>dlog_option()</c></seealso>.</p> - <p>Parameters in the <c>disk_log_opts</c> map:</p> + </seealso>, and handler specific parameters. The specific data + is stored in a sub map with the key <c>config</c>, and can contain the + following parameters:</p> <taglist> <tag><c>file</c></tag> - <item>This is the full name of the disk_log log file.</item> + <item> + <p>This is the full name of the disk log file. The option + corresponds to the <c>name</c> property in the + <seealso marker="disk_log#open-1"><c>dlog_option()</c></seealso> + datatype.</p> + </item> <tag><c>type</c></tag> - <item>This is the disk_log type, <c>wrap</c> or <c>halt</c>. The - default value is <c>wrap</c>.</item> + <item> + <p>This is the disk log type, <c>wrap</c> or <c>halt</c>. The option + corresponds to the <c>type</c> property in the + <seealso marker="disk_log#open-1"><c>dlog_option()</c></seealso> + datatype.</p> + <p>Defaults to <c>wrap</c>.</p> + </item> <tag><c>max_no_files</c></tag> - <item>This is the maximum number of files that disk_log will use - for its circular logging. The default value is <c>10</c>. (The setting - has no effect on a halt log).</item> + <item> + <p>This is the maximum number of files that disk_log uses + for its circular logging. The option + corresponds to the <c>MaxNoFiles</c> element in the <c>size</c> property in the + <seealso marker="disk_log#open-1"><c>dlog_option()</c></seealso> + datatype.</p> + <p>Defaults to <c>10</c>.</p> + <p>The setting has no effect on a halt log.</p> + </item> <tag><c>max_no_bytes</c></tag> - <item>This is the maximum number of bytes that will be written to - a log file before disk_log proceeds with the next file in order (or - generates an error in case of a full halt log). The default value for - a wrap log is <c>1048576</c> bytes, and <c>infinity</c> for a halt - log.</item> - </taglist> - <p>Specific configuration for the handler (represented as a sub map) - is specified with the key <c>config</c>. It may contain the - following parameter:</p> - <taglist> + <item> + <p>This is the maximum number of bytes that is written to + a log file before disk_log proceeds with the next file in order, or + generates an error in case of a full halt log. The option + corresponds to the <c>MaxNoBytes</c> element in the <c>size</c> property in the + <seealso marker="disk_log#open-1"><c>dlog_option()</c></seealso> + datatype.</p> + <p>Defaults to <c>1048576</c> bytes for a wrap log, and + <c>infinity</c> for a halt log.</p> + </item> <tag><c>filesync_repeat_interval</c></tag> <item> - <p>This value (in milliseconds) specifies how often the handler will - do a disk_log sync operation in order to make sure that buffered data - gets written to disk. The handler will repeatedly attempt this - operation, but only perform it if something has actually been logged - since the last sync. The default value is <c>5000</c> milliseconds. - If <c>no_repeat</c> is set as value, the repeated sync operation is - disabled. The user can also call the - <seealso marker="logger_disk_log_h#sync-1"><c>sync/1</c> - </seealso> function to perform a disk_log sync.</p></item> + <p>This value, in milliseconds, specifies how often the handler does + a disk_log sync operation to write buffered data to disk. The handler attempts + the operation repeatedly, but only performs a new sync if something has + actually been logged.</p> + <p>Defaults to <c>5000</c> milliseconds.</p> + <p>If <c>no_repeat</c> is set as value, the repeated sync operation + is disabled. The user can also call the + <seealso marker="logger_disk_log_h#filesync-1"><c>filesync/1</c> + </seealso> function to perform a disk_log sync.</p> + </item> </taglist> - <p>There are a number of other configuration parameters available, that are - to be used for customizing the overload protection behaviour. The same - parameters are used both in the standard handler and the disk_log handler, - and are documented in the + <p>Other configuration parameters exist, to be used for customizing + the overload protection behaviour. The same parameters are used both in the + standard handler and the disk_log handler, and are documented in the <seealso marker="logger_chapter#overload_protection"><c>User's Guide</c> </seealso>.</p> - <p>Note that when changing the configuration of the handler in runtime, by - calling - <seealso marker="logger#set_handler_config-2"><c>logger:set_handler_config/2 - or logger:set_handler_config/3</c></seealso>, the <c>disk_log_opts</c> - settings may not be modified.</p> + <p>Notice that when changing the configuration of the handler in runtime, the + disk_log options (<c>file</c>, <c>type</c>, <c>max_no_files</c>, + <c>max_no_bytes</c>) must not be modified.</p> <p>Example of adding a disk_log handler:</p> <code type="none"> logger:add_handler(my_disk_log_h, logger_disk_log_h, - #{level => error, - filter_default => log, - disk_log_opts => - #{file => "./my_disk_log", - type => wrap, - max_no_files => 4, - max_no_bytes => 10000}, - config => - #{filesync_repeat_interval => 1000}}). + #{config => #{file => "./my_disk_log", + type => wrap, + max_no_files => 4, + max_no_bytes => 10000}, + filesync_repeat_interval => 1000}}). </code> - <p>In order to use the disk_log handler instead of the default standard + <p>To use the disk_log handler instead of the default standard handler when starting an Erlang node, change the Kernel default logger to - use disk_log. Example:</p> + use <c>logger_disk_log_h</c>. Example:</p> <code type="none"> erl -kernel logger '[{handler,default,logger_disk_log_h, - #{disk_log_opts => #{file => "./system_disk_log"}}}]' + #{config => #{file => "./system_disk_log"}}}]' </code> </description> <funcs> <func> - <name name="sync" arity="1" clause_i="1"/> + <name name="filesync" arity="1" clause_i="1"/> <fsummary>Writes buffered data to disk.</fsummary> <desc> <p>Write buffered data to disk.</p> diff --git a/lib/kernel/doc/src/logger_std_h.xml b/lib/kernel/doc/src/logger_std_h.xml index 89e11389c5..95b4baf160 100644 --- a/lib/kernel/doc/src/logger_std_h.xml +++ b/lib/kernel/doc/src/logger_std_h.xml @@ -33,92 +33,84 @@ <file>logger_std_h.xml</file> </header> <module>logger_std_h</module> - <modulesummary>Default handler for Logger.</modulesummary> + <modulesummary>Standard handler for Logger.</modulesummary> <description> - <p>This is the default handler for Logger. + <p>This is the standard handler for Logger. Multiple instances of this handler can be added to - Logger, and each instance will print logs to <c>standard_io</c>, - <c>standard_error</c> or to file. The default instance that starts - with Kernel is named <c>default</c> - which is the name to be used - for reconfiguration.</p> - <p>The handler has an overload protection mechanism that will keep the handler - process and the Kernel application alive during a high load of log - requests. How this feature works, and how to modify the configuration, - is described in the + Logger, and each instance prints logs to <c>standard_io</c>, + <c>standard_error</c>, or to file.</p> + <p>The handler has an overload protection mechanism that keeps the handler + process and the Kernel application alive during high loads of log + events. How overload protection works, and how to configure it, is + described in the <seealso marker="logger_chapter#overload_protection"><c>User's Guide</c> </seealso>.</p> <p>To add a new instance of the standard handler, use <seealso marker="logger#add_handler-3"><c>logger:add_handler/3</c> - </seealso>. The handler configuration argument is a map which may contain - general configuration parameters, as documented in the + </seealso>. The handler configuration argument is a map which can contain + general configuration parameters, as documented in the <seealso marker="logger_chapter#handler_configuration"><c>User's Guide</c> - </seealso>, as well as handler specific parameters. The specific parameters - are stored in a sub map with the key <c>config</c>. The following - keys and values may be specified:</p> + </seealso>, and handler specific parameters. The specific data + is stored in a sub map with the key <c>config</c>, and can contain the + following parameters:</p> <taglist> <tag><marker id="type"/><c>type</c></tag> <item> - <p>This will have the value <c>standard_io</c>, <c>standard_error</c>, - <c>{file,LogFileName}</c>, or <c>{file,LogFileName,LogFileOpts}</c>, - where <c>standard_io</c> is the default value for type. It's recommended - to not specify <c>LogFileOpts</c> if not absolutely necessary. The - default options used by the handler to open a file for logging are: - <c>raw</c>, <c>append</c> and <c>delayed_write</c>. The standard - handler does not have support for circular logging. Use the - <seealso marker="logger_disk_log_h"><c>logger_disk_log_h</c> - </seealso> handler for this.</p></item> + <p>This has the value <c>standard_io</c>, <c>standard_error</c>, + <c>{file,LogFileName}</c>, or <c>{file,LogFileName,LogFileOpts}</c>.</p> + <p> Defaults to <c>standard_io</c>.</p> + <p>It is recommended not to specify <c>LogFileOpts</c> unless absolutely + necessary. The default options used by the handler to open a file for logging are + <c>raw</c>, <c>append</c>, and <c>delayed_write</c>. Notice that the standard + handler does not have support for circular logging. Use the disk_log handler, + <seealso marker="logger_disk_log_h"><c>logger_disk_log_h</c></seealso>, + for this.</p> + </item> <tag><c>filesync_repeat_interval</c></tag> <item> - <p>This value (in milliseconds) specifies how often the handler will - do a file sync operation in order to make sure that buffered data gets - written to disk. The handler will repeatedly attempt this - operation, but only perform it if something has actually been logged - since the last sync. The default value is <c>5000</c> milliseconds. - If <c>no_repeat</c> is set as value, the repeated file sync operation - is disabled, and it will be the operating system settings that determine - how quickly or slowly data gets written to disk. The user can also call - the <seealso marker="logger_std_h#sync-1"><c>sync/1</c></seealso> - function to perform a file sync.</p></item> + <p>This value, in milliseconds, specifies how often the handler does + a file sync operation to write buffered data to disk. The handler attempts + the operation repeatedly, but only performs a new sync if something has + actually been logged.</p> + <p>Defaults to <c>5000</c> milliseconds.</p> + <p>If <c>no_repeat</c> is set as value, the repeated file sync operation + is disabled, and it is the operating system settings that determine + how quickly or slowly data is written to disk. The user can also call + the <seealso marker="logger_std_h#filesync-1"><c>filesync/1</c></seealso> + function to perform a file sync.</p> + </item> </taglist> - <p>There are a number of other configuration parameters available, that are - to be used for customizing the overload protection behaviour. The same - parameters are used both in the standard handler and the disk_log handler, - and are documented in the + <p>Other configuration parameters exist, to be used for customizing + the overload protection behaviour. The same parameters are used both in the + standard handler and the disk_log handler, and are documented in the <seealso marker="logger_chapter#overload_protection"><c>User's Guide</c> </seealso>.</p> - <p>Note that when changing the configuration of the handler in runtime, by - calling - <seealso marker="logger#set_handler_config-2"><c>logger:set_handler_config/2</c> - </seealso>, or - <seealso marker="logger#set_handler_config-3"><c>logger:set_handler_config/3</c> - </seealso>, - the <c>type</c> parameter may not be modified.</p> + <p>Notice that if changing the configuration of the handler in runtime, + the <c>type</c> parameter must not be modified.</p> <p>Example of adding a standard handler:</p> <code type="none"> logger:add_handler(my_standard_h, logger_std_h, - #{level => info, - filter_default => log, - config => - #{type => {file,"./system_info.log"}, - filesync_repeat_interval => 1000}}). + #{config => #{type => {file,"./system_info.log"}, + filesync_repeat_interval => 1000}}). </code> - <p>In order to configure the default handler (that starts initially with - the Kernel application) to log to file instead of <c>standard_io</c>, - change the Kernel default logger to use a file. Example:</p> + <p>To set the default handler, that starts initially with + the Kernel application, to log to file instead of <c>standard_io</c>, + change the Kernel default logger configuration. Example:</p> <code type="none"> erl -kernel logger '[{handler,default,logger_std_h, #{config => #{type => {file,"./log.log"}}}}]' </code> <p>An example of how to replace the standard handler with a disk_log handler - at start up can be found in the manual of - <seealso marker="logger_disk_log_h"><c>logger_disk_log_h</c></seealso>.</p> + at startup is found in the + <seealso marker="logger_disk_log_h"><c>logger_disk_log_h</c></seealso> + manual.</p> </description> <funcs> <func> - <name name="sync" arity="1" clause_i="1"/> + <name name="filesync" arity="1" clause_i="1"/> <fsummary>Writes buffered data to disk.</fsummary> <desc> <p>Write buffered data to disk.</p> diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index a074d0210e..f08621c9c5 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -26,7 +26,7 @@ -include("logger_h_common.hrl"). %%% API --export([start_link/3, info/1, sync/1, reset/1]). +-export([start_link/3, info/1, filesync/1, reset/1]). %% gen_server callbacks -export([init/1, handle_call/3, handle_cast/2, handle_info/2, @@ -58,19 +58,19 @@ start_link(Name, Config, HandlerState) -> %%%----------------------------------------------------------------- %%% --spec sync(Name) -> ok | {error,Reason} when +-spec filesync(Name) -> ok | {error,Reason} when Name :: atom(), Reason :: handler_busy | {badarg,term()}. -sync(Name) when is_atom(Name) -> +filesync(Name) when is_atom(Name) -> try gen_server:call(?name_to_reg_name(?MODULE,Name), disk_log_sync, ?DEFAULT_CALL_TIMEOUT) catch _:{timeout,_} -> {error,handler_busy} end; -sync(Name) -> - {error,{badarg,{sync,[Name]}}}. +filesync(Name) -> + {error,{badarg,{filesync,[Name]}}}. %%%----------------------------------------------------------------- %%% @@ -704,7 +704,7 @@ disk_log_sync(Name, State) -> ok; _ -> LogOpts = maps:get(log_opts, State), - logger_h_common:error_notify({Name,sync, + logger_h_common:error_notify({Name,filesync, LogOpts, SyncError}) end, diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl index d556938f02..f9f762405c 100644 --- a/lib/kernel/src/logger_h_common.erl +++ b/lib/kernel/src/logger_h_common.erl @@ -115,7 +115,7 @@ check_common_config({overload_kill_qlen,N}) when is_integer(N) -> check_common_config({overload_kill_mem_size,N}) when is_integer(N) -> valid; check_common_config({overload_kill_restart_after,NorA}) when is_integer(NorA); - NorA == never -> + NorA == infinity -> valid; check_common_config({filesync_repeat_interval,NorA}) when is_integer(NorA); @@ -261,7 +261,7 @@ flush_log_events(Limit, Limit) -> Limit; flush_log_events(N, Limit) -> %% flush log events but leave other events, such as - %% file/disk_log_sync, info and change_config, so that these + %% filesync, info and change_config, so that these %% have a chance to be processed even under heavy load receive {'$gen_cast',{log,_}} -> diff --git a/lib/kernel/src/logger_h_common.hrl b/lib/kernel/src/logger_h_common.hrl index ad80b51109..e0a7b6e3ca 100644 --- a/lib/kernel/src/logger_h_common.hrl +++ b/lib/kernel/src/logger_h_common.hrl @@ -41,10 +41,10 @@ -define(OVERLOAD_KILL_MEM_SIZE, 3000000). %% This is the default time that the handler will wait before -%% restarting and accepting new requests. The value 'never' +%% restarting and accepting new requests. The value 'infinity' %% disables restarts. -define(OVERLOAD_KILL_RESTART_AFTER, 5000). -%%-define(OVERLOAD_KILL_RESTART_AFTER, never). +%%-define(OVERLOAD_KILL_RESTART_AFTER, infinity). %% The handler sends asynchronous write requests to the process %% controlling the i/o device, but every once in this interval diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index ce9daa50ab..a03e1ffc2a 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -28,7 +28,7 @@ -include_lib("kernel/include/file.hrl"). %% API --export([start_link/3, info/1, sync/1, reset/1]). +-export([start_link/3, info/1, filesync/1, reset/1]). %% gen_server and proc_lib callbacks -export([init/1, handle_call/3, handle_cast/2, handle_info/2, @@ -60,19 +60,19 @@ start_link(Name, Config, HandlerState) -> %%%----------------------------------------------------------------- %%% --spec sync(Name) -> ok | {error,Reason} when +-spec filesync(Name) -> ok | {error,Reason} when Name :: atom(), Reason :: handler_busy | {badarg,term()}. -sync(Name) when is_atom(Name) -> +filesync(Name) when is_atom(Name) -> try gen_server:call(?name_to_reg_name(?MODULE,Name), filesync, ?DEFAULT_CALL_TIMEOUT) catch _:{timeout,_} -> {error,handler_busy} end; -sync(Name) -> - {error,{badarg,{sync,[Name]}}}. +filesync(Name) -> + {error,{badarg,{filesync,[Name]}}}. %%%----------------------------------------------------------------- %%% @@ -816,7 +816,7 @@ sync_dev(Fd, DevName, PrevSyncResult, HandlerName) -> %% don't report same error twice PrevSyncResult; Error -> - logger_h_common:error_notify({HandlerName,sync,DevName,Error}), + logger_h_common:error_notify({HandlerName,filesync,DevName,Error}), Error end. diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl index f837c31e64..b367b4dd54 100644 --- a/lib/kernel/test/logger_SUITE.erl +++ b/lib/kernel/test/logger_SUITE.erl @@ -329,7 +329,7 @@ log_no_levels(_Config) -> ok. log_no_levels(cleanup,_Config) -> logger:remove_handler(h1), - logger:set_primary_config(level,info), + logger:set_primary_config(level,notice), logger:unset_module_level(?MODULE), ok. diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl index 5f7b505ecb..4c6fa1b5af 100644 --- a/lib/kernel/test/logger_disk_log_h_SUITE.erl +++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl @@ -1,3 +1,22 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2018. All Rights Reserved. +%% +%% Licensed under the Apache License, Version 2.0 (the "License"); +%% you may not use this file except in compliance with the License. +%% You may obtain a copy of the License at +%% +%% http://www.apache.org/licenses/LICENSE-2.0 +%% +%% Unless required by applicable law or agreed to in writing, software +%% distributed under the License is distributed on an "AS IS" BASIS, +%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +%% See the License for the specific language governing permissions and +%% limitations under the License. +%% +%% %CopyrightEnd% +%% -module(logger_disk_log_h_SUITE). -compile(export_all). @@ -26,10 +45,6 @@ -define(log_no(File,N), lists:concat([File,".",N])). -define(domain,#{domain=>[?MODULE]}). --define(SYNC_REP_INT, if is_atom(?FILESYNC_REPEAT_INTERVAL) -> 5500; - true -> ?FILESYNC_REPEAT_INTERVAL + 500 - end). - suite() -> [{timetrap,{seconds,30}}, {ct_hooks,[logger_test_lib]}]. @@ -50,9 +65,10 @@ end_per_group(_Group, _Config) -> init_per_testcase(TestHooksCase, Config) when TestHooksCase == write_failure; TestHooksCase == sync_failure -> - if ?TEST_HOOKS_TAB == undefined -> + case (fun() -> ?TEST_HOOKS_TAB == undefined end)() of + true -> {skip,"Define the TEST_HOOKS macro to run this test"}; - true -> + false -> ct:print("********** ~w **********", [TestHooksCase]), Config end; @@ -124,7 +140,7 @@ create_log(Config) -> formatter=>{?MODULE,self()}}, #{file=>LogFile1}), logger:notice("hello", ?domain), - logger_disk_log_h:sync(Name1), + logger_disk_log_h:filesync(Name1), ct:pal("Checking contents of ~p", [?log_no(LogFile1,1)]), try_read_file(?log_no(LogFile1,1), {ok,<<"hello\n">>}, 5000), @@ -137,7 +153,7 @@ create_log(Config) -> formatter=>{?MODULE,self()}}, #{file=>LogFile2}), logger:notice("dummy", ?domain), - logger_disk_log_h:sync(Name2), + logger_disk_log_h:filesync(Name2), ct:pal("Checking contents of ~p", [?log_no(LogFile2,1)]), try_read_file(?log_no(LogFile2,1), {ok,<<"dummy\n">>}, 5000), @@ -158,7 +174,7 @@ open_existing_log(Config) -> formatter=>{?MODULE,self()}}, #{file=>LogFile1}), logger:notice("one", ?domain), - logger_disk_log_h:sync(HName), + logger_disk_log_h:filesync(HName), ct:pal("Checking contents of ~p", [?log_no(LogFile1,1)]), try_read_file(?log_no(LogFile1,1), {ok,<<"one\n">>}, 5000), logger:notice("two", ?domain), @@ -172,7 +188,7 @@ open_existing_log(Config) -> formatter=>{?MODULE,self()}}, #{file=>LogFile1}), logger:notice("three", ?domain), - logger_disk_log_h:sync(HName), + logger_disk_log_h:filesync(HName), try_read_file(?log_no(LogFile1,1), {ok,<<"one\ntwo\nthree\n">>}, 5000), remove_and_stop(HName), try_read_file(?log_no(LogFile1,1), {ok,<<"one\ntwo\nthree\n">>}, 5000). @@ -197,22 +213,22 @@ disk_log_opts(Config) -> {WFileFull,wrap,{Size,2},1} = {Get(file,WInfo1),Get(type,WInfo1), Get(size,WInfo1),Get(current_file,WInfo1)}, logger:notice("123", ?domain), - logger_disk_log_h:sync(WName), + logger_disk_log_h:filesync(WName), timer:sleep(500), 1 = Get(current_file, disk_log:info(WName)), logger:notice("45", ?domain), - logger_disk_log_h:sync(WName), + logger_disk_log_h:filesync(WName), timer:sleep(500), 1 = Get(current_file, disk_log:info(WName)), logger:notice("6", ?domain), - logger_disk_log_h:sync(WName), + logger_disk_log_h:filesync(WName), timer:sleep(500), 2 = Get(current_file, disk_log:info(WName)), logger:notice("7890", ?domain), - logger_disk_log_h:sync(WName), + logger_disk_log_h:filesync(WName), timer:sleep(500), 2 = Get(current_file, disk_log:info(WName)), @@ -230,7 +246,7 @@ disk_log_opts(Config) -> {HFile1Full,halt,infinity} = {Get(file,HInfo1),Get(type,HInfo1), Get(size,HInfo1)}, logger:notice("12345", ?domain), - logger_disk_log_h:sync(HName1), + logger_disk_log_h:filesync(HName1), timer:sleep(500), 1 = Get(no_written_items, disk_log:info(HName1)), @@ -407,8 +423,8 @@ config_fail(cleanup,_Config) -> logger:remove_handler(?MODULE). bad_input(_Config) -> - {error,{badarg,{sync,["BadType"]}}} = - logger_disk_log_h:sync("BadType"), + {error,{badarg,{filesync,["BadType"]}}} = + logger_disk_log_h:filesync("BadType"), {error,{badarg,{info,["BadType"]}}} = logger_disk_log_h:info("BadType"), {error,{badarg,{reset,["BadType"]}}} = logger_disk_log_h:reset("BadType"). @@ -456,7 +472,7 @@ reconfig(Config) -> overload_kill_enable => true, overload_kill_qlen => 100000, overload_kill_mem_size => 10000000, - overload_kill_restart_after => never, + overload_kill_restart_after => infinity, filesync_repeat_interval => no_repeat}, ok = logger:set_handler_config(?MODULE, config, HConfig1), #{id := ?MODULE, @@ -469,7 +485,7 @@ reconfig(Config) -> overload_kill_enable := true, overload_kill_qlen := 100000, overload_kill_mem_size := 10000000, - overload_kill_restart_after := never, + overload_kill_restart_after := infinity, filesync_repeat_interval := no_repeat} = logger_disk_log_h:info(?MODULE), @@ -526,7 +542,7 @@ sync(Config) -> logger:notice("second", ?domain), logger:notice("third", ?domain), %% do explicit sync - logger_disk_log_h:sync(?MODULE), + logger_disk_log_h:filesync(?MODULE), check_tracer(100), %% check that if there's no repeated disk_log_sync active, @@ -739,9 +755,15 @@ write_failure(Config) -> ct:pal("LogOpts = ~p", [LogOpts = maps:get(log_opts, HState)]), ok = log_on_remote_node(Node, "Logged1"), - rpc:call(Node, logger_disk_log_h, sync, [?STANDARD_HANDLER]), + rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]), ?check_no_log, - try_read_file(Log, {ok,<<"Logged1\n">>}, ?SYNC_REP_INT), + + SyncRepInt = case (fun() -> is_atom(?FILESYNC_REPEAT_INTERVAL) end)() of + true -> 5500; + false -> ?FILESYNC_REPEAT_INTERVAL + 500 + end, + + try_read_file(Log, {ok,<<"Logged1\n">>}, SyncRepInt), rpc:call(Node, ?MODULE, set_result, [disk_log_blog,{error,no_such_log}]), ok = log_on_remote_node(Node, "Cause simple error printout"), @@ -759,9 +781,9 @@ write_failure(Config) -> rpc:call(Node, ?MODULE, set_result, [disk_log_blog,ok]), ok = log_on_remote_node(Node, "Logged2"), - rpc:call(Node, logger_disk_log_h, sync, [?STANDARD_HANDLER]), + rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]), ?check_no_log, - try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, ?SYNC_REP_INT), + try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, SyncRepInt), ok. write_failure(cleanup, _Config) -> Nodes = nodes(), @@ -795,7 +817,7 @@ sync_failure(Config) -> rpc:call(Node, ?MODULE, set_result, [disk_log_sync,{error,no_such_log}]), ok = log_on_remote_node(Node, "Cause simple error printout"), - ?check({error,{?STANDARD_HANDLER,sync,LogOpts,{error,no_such_log}}}), + ?check({error,{?STANDARD_HANDLER,filesync,LogOpts,{error,no_such_log}}}), ok = log_on_remote_node(Node, "No second error printout"), ?check_no_log, @@ -803,7 +825,7 @@ sync_failure(Config) -> rpc:call(Node, ?MODULE, set_result, [disk_log_sync,{error,{blocked_log,?STANDARD_HANDLER}}]), ok = log_on_remote_node(Node, "Cause simple error printout"), - ?check({error,{?STANDARD_HANDLER,sync,LogOpts, + ?check({error,{?STANDARD_HANDLER,filesync,LogOpts, {error,{blocked_log,?STANDARD_HANDLER}}}}), rpc:call(Node, ?MODULE, set_result, [disk_log_sync,ok]), @@ -861,8 +883,8 @@ op_switch_to_sync(Config) -> ok = logger:set_handler_config(?MODULE, NewHConfig), send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Lines = count_lines(Log), - ok = file_delete(Log), NumOfReqs = Lines, + ok = file_delete(Log), ok. op_switch_to_sync(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -892,11 +914,11 @@ op_switch_to_drop(Config) -> _ <- lists:seq(1, Bursts)], Logged = count_lines(Log), ok = stop_handler(?MODULE), - _ = file_delete(Log), ct:pal("Number of messages dropped = ~w (~w)", [Procs*NumOfReqs*Bursts-Logged,Procs*NumOfReqs*Bursts]), true = (Logged < (Procs*NumOfReqs*Bursts)), true = (Logged > 0), + _ = file_delete(Log), ok end, %% As it's tricky to get the timing right in only one go, we perform the @@ -944,11 +966,11 @@ op_switch_to_flush(Config) -> _ <- lists:seq(1,Bursts)], Logged = count_lines(Log), ok= stop_handler(?MODULE), - _ = file_delete(Log), ct:pal("Number of messages flushed/dropped = ~w (~w)", [NumOfReqs*Procs*Bursts-Logged,NumOfReqs*Procs*Bursts]), true = (Logged < (NumOfReqs*Procs*Bursts)), true = (Logged > 0), + _ = file_delete(Log), ok end, %% As it's tricky to get the timing right in only one go, we perform the @@ -976,8 +998,9 @@ limit_burst_disabled(Config) -> send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), ct:pal("Number of messages logged = ~w", [Logged]), + NumOfReqs = Logged, ok = file_delete(Log), - NumOfReqs = Logged. + ok. limit_burst_disabled(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -995,8 +1018,9 @@ limit_burst_enabled_one(Config) -> send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), ct:pal("Number of messages logged = ~w", [Logged]), + ReqLimit = Logged, ok = file_delete(Log), - ReqLimit = Logged. + ok. limit_burst_enabled_one(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -1017,9 +1041,10 @@ limit_burst_enabled_period(Config) -> Logged = count_lines(Log), ct:pal("Number of messages sent = ~w~nNumber of messages logged = ~w", [Sent,Logged]), - ok = file_delete(Log), true = (Logged > (ReqLimit*Windows)) andalso - (Logged < (ReqLimit*(Windows+2))). + (Logged < (ReqLimit*(Windows+2))), + ok = file_delete(Log), + ok. limit_burst_enabled_period(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -1119,7 +1144,7 @@ restart_after(Config) -> NewHConfig1 = HConfig#{config=>DLHConfig#{overload_kill_enable=>true, overload_kill_qlen=>10, - overload_kill_restart_after=>never}}, + overload_kill_restart_after=>infinity}}, ok = logger:set_handler_config(?MODULE, NewHConfig1), MRef1 = erlang:monitor(process, whereis(h_proc_name())), %% kill handler @@ -1173,7 +1198,7 @@ handler_requests_under_load(Config) -> flush_qlen => 2000, burst_limit_enable => false}}, ok = logger:set_handler_config(?MODULE, NewHConfig), - Pid = spawn_link(fun() -> send_requests(?MODULE, 1, [{sync,[]}, + Pid = spawn_link(fun() -> send_requests(?MODULE, 1, [{filesync,[]}, {info,[]}, {reset,[]}, {change_config,[]}]) @@ -1220,6 +1245,8 @@ start_handler(Name, FuncName, Config) -> Dir = ?config(priv_dir,Config), File = filename:join(Dir, FuncName), ct:pal("Logging to ~tp", [File]), + FullFile = lists:concat([File,".1"]), + _ = file_delete(FullFile), ok = logger:add_handler(Name, logger_disk_log_h, #{config=>#{file => File, @@ -1229,7 +1256,7 @@ start_handler(Name, FuncName, Config) -> filters=>?DEFAULT_HANDLER_FILTERS([Name]), formatter=>{?MODULE,op}}), {ok,HConfig = #{config := DLHConfig}} = logger:get_handler_config(Name), - {lists:concat([File,".1"]),HConfig,DLHConfig}. + {FullFile,HConfig,DLHConfig}. stop_handler(Name) -> ct:pal("Stopping handler ~p!", [Name]), @@ -1256,7 +1283,8 @@ send_n_burst(N, seq, Text, Class) -> send_n_burst(N-1, seq, Text, Class); send_n_burst(N, {spawn,Ps,TO}, Text, Class) -> ct:pal("~w processes each sending ~w messages", [Ps,N]), - PerProc = fun() -> + PerProc = fun() -> + process_flag(priority,high), send_n_burst(N, seq, Text, Class) end, MRefs = [begin if TO == 0 -> ok; true -> timer:sleep(TO) end, @@ -1399,10 +1427,10 @@ wait_until_written(File, Sz) -> {ok,#file_info{size = Sz}} -> timer:sleep(1000), case file:read_file_info(File) of - {ok,#file_info{size = Sz1}} -> + {ok,#file_info{size = Sz}} -> ok; - {ok,#file_info{size = Sz2}} -> - wait_until_written(File, Sz2) + {ok,#file_info{size = Sz1}} -> + wait_until_written(File, Sz1) end; {ok,#file_info{size = Sz1}} -> wait_until_written(File, Sz1) diff --git a/lib/kernel/test/logger_env_var_SUITE.erl b/lib/kernel/test/logger_env_var_SUITE.erl index 6e182d4bca..04a4364947 100644 --- a/lib/kernel/test/logger_env_var_SUITE.erl +++ b/lib/kernel/test/logger_env_var_SUITE.erl @@ -214,6 +214,7 @@ logger_file(Config) -> file,% dest 0),% progress in std logger + notice = maps:get(level,P), #{module:=logger_std_h} = StdC = find(?STANDARD_HANDLER,Hs), all = maps:get(level,StdC), StdFilters = maps:get(filters,StdC), @@ -525,12 +526,12 @@ logger_many_handlers_default_last_broken_filter(Config) -> {logger_level,info}], LogErr, LogInfo, 7). logger_many_handlers(Config, Env, LogErr, LogInfo, NumProgress) -> - {ok,#{handlers:=Hs},Node} = setup(Config,Env), + {ok,_,Node} = setup(Config,Env), check_single_log(Node,LogErr, file,% dest 0,% progress in std logger error), % level - ok = rpc:call(Node,logger_std_h,sync,[info]), + ok = rpc:call(Node,logger_std_h,filesync,[info]), {ok, Bin} = file:read_file(LogInfo), ct:log("Log content:~n~s",[Bin]), match(Bin,<<"info:">>,NumProgress,info,info), diff --git a/lib/kernel/test/logger_formatter_SUITE.erl b/lib/kernel/test/logger_formatter_SUITE.erl index 864a40b618..8fe8d5199b 100644 --- a/lib/kernel/test/logger_formatter_SUITE.erl +++ b/lib/kernel/test/logger_formatter_SUITE.erl @@ -208,7 +208,7 @@ template(_Config) -> time=>Time, tuple=>{1,atom,"list"}, nested=>#{subkey=>subvalue}}, - Template6 = lists:join(";",maps:keys(maps:remove(nested,Meta6)) ++ + Template6 = lists:join(";",lists:sort(maps:keys(maps:remove(nested,Meta6))) ++ [[nested,subkey]]), String6 = format(info,{"~p",[term]},Meta6,#{template=>Template6, single_line=>true}), diff --git a/lib/kernel/test/logger_legacy_SUITE.erl b/lib/kernel/test/logger_legacy_SUITE.erl index de73b6152a..c3cab07d81 100644 --- a/lib/kernel/test/logger_legacy_SUITE.erl +++ b/lib/kernel/test/logger_legacy_SUITE.erl @@ -20,6 +20,8 @@ -module(logger_legacy_SUITE). -compile(export_all). +-compile({nowarn_deprecated_function,[{gen_fsm,start,3}, + {gen_fsm,send_all_state_event,2}]}). -include_lib("common_test/include/ct.hrl"). -include_lib("kernel/include/logger.hrl"). @@ -89,6 +91,7 @@ init_per_group(_Group, Config) -> end_per_group(sasl, Config) -> Apps = ?config(stop_apps,Config), [application:stop(App) || App <- Apps], + ok = logger:set_primary_config(level,notice), ok; end_per_group(_Group, _Config) -> ok. @@ -122,7 +125,7 @@ all() -> gen_server(_Config) -> {ok,Pid} = gen_server:start(?MODULE,gen_server,[]), - Msg = fun() -> a=b end, + Msg = fun() -> erlang:error({badmatch,b}) end, Pid ! Msg, ?check({warning_msg,"** Undefined handle_info in ~p"++_,[?MODULE,Msg]}), ok = gen_server:cast(Pid,Msg), @@ -132,7 +135,7 @@ gen_server(_Config) -> gen_event(_Config) -> {ok,Pid} = gen_event:start(), ok = gen_event:add_handler(Pid,?MODULE,gen_event), - Msg = fun() -> a=b end, + Msg = fun() -> erlang:error({badmatch,b}) end, Pid ! Msg, ?check({warning_msg,"** Undefined handle_info in ~tp"++_,[?MODULE,Msg]}), gen_event:notify(Pid,Msg), @@ -141,7 +144,7 @@ gen_event(_Config) -> gen_fsm(_Config) -> {ok,Pid} = gen_fsm:start(?MODULE,gen_fsm,[]), - Msg = fun() -> a=b end, + Msg = fun() -> erlang:error({badmatch,b}) end, Pid ! Msg, ?check({warning_msg,"** Undefined handle_info in ~p"++_,[?MODULE,Msg]}), gen_fsm:send_all_state_event(Pid,Msg), @@ -150,7 +153,7 @@ gen_fsm(_Config) -> gen_statem(_Config) -> {ok,Pid} = gen_statem:start(?MODULE,gen_statem,[]), - Msg = fun() -> a=b end, + Msg = fun() -> erlang:error({badmatch,b}) end, Pid ! Msg, ?check({error,"** State machine ~tp terminating"++_, [Pid,{info,Msg},{mystate,gen_statem},error,{badmatch,b}|_]}). @@ -179,7 +182,7 @@ sasl_reports(Config) -> ok = gen_server:cast(ChPid, fun() -> spawn_link(fun() -> receive x->ok end end) end), - Msg = fun() -> a=b end, + Msg = fun() -> erlang:error({badmatch,b}) end, ok = gen_server:cast(ChPid,Msg), ?check_no_flush({error,"** Generic server ~tp terminating"++_, [ChPid,{'$gen_cast',Msg},gen_server,{{badmatch,b},_}]}), diff --git a/lib/kernel/test/logger_simple_h_SUITE.erl b/lib/kernel/test/logger_simple_h_SUITE.erl index e4e48b538a..79e5c057ad 100644 --- a/lib/kernel/test/logger_simple_h_SUITE.erl +++ b/lib/kernel/test/logger_simple_h_SUITE.erl @@ -107,15 +107,15 @@ start_stop(cleanup,_Config) -> replace_default(Config) -> {ok, _, Node} = logger_test_lib:setup(Config, [{logger, [{handler, default, undefined}]}]), - log(Node, emergency, [M1=?str]), - log(Node, alert, [M2=?str,[]]), - log(Node, error, [M3=?map_rep]), - log(Node, info, [M4=?keyval_rep]), - log(Node, info, [M41=?keyval_rep++[not_key_val]]), - rpc:call(Node, error_logger, error_report, [some_type,M5=?map_rep]), - rpc:call(Node, error_logger, warning_report, ["some_type",M6=?map_rep]), - log(Node, critical, [M7=?str,[A7=?keyval_rep]]), - log(Node, notice, [M8=["fake",string,"line:",?LINE]]), + log(Node, emergency, [?str]), + log(Node, alert, [?str,[]]), + log(Node, error, [?map_rep]), + log(Node, info, [?keyval_rep]), + log(Node, info, [?keyval_rep++[not_key_val]]), + rpc:call(Node, error_logger, error_report, [some_type,?map_rep]), + rpc:call(Node, error_logger, warning_report, ["some_type",?map_rep]), + log(Node, critical, [?str,[?keyval_rep]]), + log(Node, notice, [["fake",string,"line:",?LINE]]), Env = rpc:call(Node, application, get_env, [kernel, logger, []]), ok = rpc:call(Node, logger, add_handlers, [Env]), @@ -127,11 +127,11 @@ replace_file(Config) -> {ok, _, Node} = logger_test_lib:setup(Config, [{logger, [{handler, default, undefined}]}]), log(Node, emergency, [M1=?str]), log(Node, alert, [M2=?str,[]]), - log(Node, error, [M3=?map_rep]), - log(Node, warning, [M4=?keyval_rep]), - log(Node, warning, [M41=?keyval_rep++[not_key_val]]), - log(Node, critical, [M7=?str,[A7=?keyval_rep]]), - log(Node, notice, [M8=["fake",string,"line:",?LINE]]), + log(Node, error, [?map_rep]), + log(Node, warning, [?keyval_rep]), + log(Node, warning, [?keyval_rep++[not_key_val]]), + log(Node, critical, [?str,[?keyval_rep]]), + log(Node, notice, [["fake",string,"line:",?LINE]]), File = filename:join(proplists:get_value(priv_dir,Config), atom_to_list(?FUNCTION_NAME)++".log"), @@ -171,11 +171,11 @@ replace_disk_log(Config) -> {ok, _, Node} = logger_test_lib:setup(Config, [{logger, [{handler, default, undefined}]}]), log(Node, emergency, [M1=?str]), log(Node, alert, [M2=?str,[]]), - log(Node, error, [M3=?map_rep]), - log(Node, warning, [M4=?keyval_rep]), - log(Node, warning, [M41=?keyval_rep++[not_key_val]]), - log(Node, critical, [M7=?str,[A7=?keyval_rep]]), - log(Node, notice, [M8=["fake",string,"line:",?LINE]]), + log(Node, error, [?map_rep]), + log(Node, warning, [?keyval_rep]), + log(Node, warning, [?keyval_rep++[not_key_val]]), + log(Node, critical, [?str,[?keyval_rep]]), + log(Node, notice, [["fake",string,"line:",?LINE]]), File = filename:join(proplists:get_value(priv_dir,Config), atom_to_list(?FUNCTION_NAME)++".log"), diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl index 36b123b07d..134358bb64 100644 --- a/lib/kernel/test/logger_std_h_SUITE.erl +++ b/lib/kernel/test/logger_std_h_SUITE.erl @@ -45,10 +45,6 @@ -define(bin(Msg), list_to_binary(Msg++"\n")). -define(domain,#{domain=>[?MODULE]}). --define(FILESYNC_REP_INT, if is_atom(?FILESYNC_REPEAT_INTERVAL) -> 5500; - true -> ?FILESYNC_REPEAT_INTERVAL + 500 - end). - suite() -> [{timetrap,{seconds,30}}, {ct_hooks,[logger_test_lib]}]. @@ -73,12 +69,25 @@ end_per_group(_Group, _Config) -> init_per_testcase(TestHooksCase, Config) when TestHooksCase == write_failure; TestHooksCase == sync_failure -> - if ?TEST_HOOKS_TAB == undefined -> + case (fun() -> ?TEST_HOOKS_TAB == undefined end)() of + true -> {skip,"Define the TEST_HOOKS macro to run this test"}; - true -> + false -> ct:print("********** ~w **********", [TestHooksCase]), Config end; +init_per_testcase(OPCase, Config) when + OPCase == qlen_kill_new; + OPCase == restart_after -> + case re:run(erlang:system_info(system_version), + "dirty-schedulers-TEST", + [{capture,none}]) of + match -> + {skip,"Overload protection test skipped on dirty-schedulers-TEST"}; + nomatch -> + ct:print("********** ~w **********", [OPCase]), + Config + end; init_per_testcase(TestCase, Config) -> ct:print("********** ~w **********", [TestCase]), Config. @@ -175,13 +184,13 @@ add_remove_instance_file(Log, Type) -> logger:notice(M1=?msg,?domain), ?check(M1), B1 = ?bin(M1), - try_read_file(Log, {ok,B1}, ?FILESYNC_REP_INT), + try_read_file(Log, {ok,B1}, filesync_rep_int()), ok = logger:remove_handler(?MODULE), timer:sleep(500), undefined = whereis(h_proc_name()), logger:notice(?msg,?domain), ?check_no_log, - try_read_file(Log, {ok,B1}, ?FILESYNC_REP_INT), + try_read_file(Log, {ok,B1}, filesync_rep_int()), ok. default_formatter(_Config) -> @@ -214,11 +223,17 @@ errors(Config) -> logger:add_handler(?MODULE,logger_std_h, #{config => #{type => faulty_type}}), - NoDir = lists:concat(["/",?MODULE,"_dir"]), - {error, - {handler_not_added,{{open_failed,NoDir,eacces},_}}} = - logger:add_handler(myh2,logger_std_h, - #{config=>#{type=>{file,NoDir}}}), + case os:type() of + {win32,_} -> + %% No use in testing file access on windows + ok; + _ -> + NoDir = lists:concat(["/",?MODULE,"_dir"]), + {error, + {handler_not_added,{{open_failed,NoDir,eacces},_}}} = + logger:add_handler(myh2,logger_std_h, + #{config=>#{type=>{file,NoDir}}}) + end, {error, {handler_not_added,{{open_failed,Log,_},_}}} = @@ -393,7 +408,7 @@ crash_std_h(cleanup) -> [test_server:stop_node(Node) || Node <- Nodes]. sync_and_read(Node,disk_log,Log) -> - rpc:call(Node,logger_disk_log_h,sync,[?STANDARD_HANDLER]), + rpc:call(Node,logger_disk_log_h,filesync,[?STANDARD_HANDLER]), case file:read_file(Log ++ ".1") of {ok,<<>>} -> timer:sleep(5000), @@ -402,7 +417,7 @@ sync_and_read(Node,disk_log,Log) -> Ok end; sync_and_read(Node,file,Log) -> - rpc:call(Node,logger_std_h,sync,[?STANDARD_HANDLER]), + rpc:call(Node,logger_std_h,filesync,[?STANDARD_HANDLER]), case file:read_file(Log) of {ok,<<>>} -> timer:sleep(5000), @@ -412,7 +427,7 @@ sync_and_read(Node,file,Log) -> end. bad_input(_Config) -> - {error,{badarg,{sync,["BadType"]}}} = logger_std_h:sync("BadType"), + {error,{badarg,{filesync,["BadType"]}}} = logger_std_h:filesync("BadType"), {error,{badarg,{info,["BadType"]}}} = logger_std_h:info("BadType"), {error,{badarg,{reset,["BadType"]}}} = logger_std_h:reset("BadType"). @@ -455,7 +470,7 @@ reconfig(Config) -> overload_kill_enable => true, overload_kill_qlen => 100000, overload_kill_mem_size => 10000000, - overload_kill_restart_after => never, + overload_kill_restart_after => infinity, filesync_repeat_interval => no_repeat}), #{id := ?MODULE, type := standard_io, @@ -469,7 +484,7 @@ reconfig(Config) -> overload_kill_enable := true, overload_kill_qlen := 100000, overload_kill_mem_size := 10000000, - overload_kill_restart_after := never, + overload_kill_restart_after := infinity, filesync_repeat_interval := no_repeat} = logger_std_h:info(?MODULE), ok. @@ -499,7 +514,7 @@ file_opts(Config) -> logger:notice(M1=?msg,?domain), ?check(M1), B1 = ?bin(M1), - try_read_file(Log, {ok,B1}, ?FILESYNC_REP_INT), + try_read_file(Log, {ok,B1}, filesync_rep_int()), ok. file_opts(cleanup, _Config) -> logger:remove_handler(?MODULE). @@ -526,7 +541,7 @@ sync(Config) -> logger:notice("first", ?domain), %% wait for automatic filesync - check_tracer(?FILESYNC_REP_INT*2), + check_tracer(filesync_rep_int()*2), %% check that explicit filesync is only done once start_tracer([{logger_std_h, write_to_dev, 5}, @@ -539,9 +554,9 @@ sync(Config) -> ]), logger:notice("second", ?domain), %% do explicit sync - logger_std_h:sync(?MODULE), + logger_std_h:filesync(?MODULE), %% a second sync should be ignored - logger_std_h:sync(?MODULE), + logger_std_h:filesync(?MODULE), check_tracer(100), %% check that if there's no repeated filesync active, @@ -600,9 +615,9 @@ write_failure(Config) -> rpc:call(Node, ?MODULE, set_result, [file_write,ok]), ok = log_on_remote_node(Node, "Logged1"), - rpc:call(Node, logger_std_h, sync, [?STANDARD_HANDLER]), + rpc:call(Node, logger_std_h, filesync, [?STANDARD_HANDLER]), ?check_no_log, - try_read_file(Log, {ok,<<"Logged1\n">>}, ?FILESYNC_REP_INT), + try_read_file(Log, {ok,<<"Logged1\n">>}, filesync_rep_int()), rpc:call(Node, ?MODULE, set_result, [file_write,{error,terminated}]), ok = log_on_remote_node(Node, "Cause simple error printout"), @@ -618,9 +633,9 @@ write_failure(Config) -> rpc:call(Node, ?MODULE, set_result, [file_write,ok]), ok = log_on_remote_node(Node, "Logged2"), - rpc:call(Node, logger_std_h, sync, [?STANDARD_HANDLER]), + rpc:call(Node, logger_std_h, filesync, [?STANDARD_HANDLER]), ?check_no_log, - try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, ?FILESYNC_REP_INT), + try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, filesync_rep_int()), ok. write_failure(cleanup, _Config) -> Nodes = nodes(), @@ -649,14 +664,14 @@ sync_failure(Config) -> rpc:call(Node, ?MODULE, set_result, [file_datasync,{error,terminated}]), ok = log_on_remote_node(Node, "Cause simple error printout"), - ?check({error,{?STANDARD_HANDLER,sync,Log,{error,terminated}}}), + ?check({error,{?STANDARD_HANDLER,filesync,Log,{error,terminated}}}), ok = log_on_remote_node(Node, "No second error printout"), ?check_no_log, rpc:call(Node, ?MODULE, set_result, [file_datasync,{error,eacces}]), ok = log_on_remote_node(Node, "Cause simple error printout"), - ?check({error,{?STANDARD_HANDLER,sync,Log,{error,eacces}}}), + ?check({error,{?STANDARD_HANDLER,filesync,Log,{error,eacces}}}), rpc:call(Node, ?MODULE, set_result, [file_datasync,ok]), ok = log_on_remote_node(Node, "Logged2"), @@ -677,10 +692,10 @@ start_std_h_on_new_node(Config, Log) -> Node. %% 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(). @@ -707,7 +722,6 @@ op_switch_to_sync_file(Config) -> %% TRecvPid = start_op_trace(), send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Lines = count_lines(Log), - ok = file_delete(Log), %% true = analyse_trace(TRecvPid, %% fun(Events) -> find_mode(async,Events) end), %% true = analyse_trace(TRecvPid, @@ -720,6 +734,7 @@ op_switch_to_sync_file(Config) -> %% fun(Events) -> find_mode(flush,Events) end), %% stop_op_trace(TRecvPid), NumOfReqs = Lines, + ok = file_delete(Log), ok. op_switch_to_sync_file(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -764,11 +779,11 @@ op_switch_to_drop_file(Config) -> _ <- lists:seq(1, Bursts)], Logged = count_lines(Log), ok = stop_handler(?MODULE), - _ = file_delete(Log), ct:pal("Number of messages dropped = ~w (~w)", [Procs*NumOfReqs*Bursts-Logged,Procs*NumOfReqs*Bursts]), true = (Logged < (Procs*NumOfReqs*Bursts)), true = (Logged > 0), + _ = file_delete(Log), ok end, %% As it's tricky to get the timing right in only one go, we perform the @@ -832,11 +847,11 @@ op_switch_to_flush_file(Config) -> _ <- lists:seq(1,Bursts)], Logged = count_lines(Log), ok = stop_handler(?MODULE), - _ = file_delete(Log), ct:pal("Number of messages flushed/dropped = ~w (~w)", [NumOfReqs*Procs*Bursts-Logged,NumOfReqs*Procs*Bursts]), true = (Logged < (NumOfReqs*Procs*Bursts)), true = (Logged > 0), + _ = file_delete(Log), ok end, %% As it's tricky to get the timing right in only one go, we perform the @@ -885,8 +900,9 @@ limit_burst_disabled(Config) -> send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), ct:pal("Number of messages logged = ~w", [Logged]), + NumOfReqs = Logged, ok = file_delete(Log), - NumOfReqs = Logged. + ok. limit_burst_disabled(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -904,8 +920,9 @@ limit_burst_enabled_one(Config) -> send_burst({n,NumOfReqs}, seq, {chars,79}, notice), Logged = count_lines(Log), ct:pal("Number of messages logged = ~w", [Logged]), + ReqLimit = Logged, ok = file_delete(Log), - ReqLimit = Logged. + ok. limit_burst_enabled_one(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -926,9 +943,10 @@ limit_burst_enabled_period(Config) -> Logged = count_lines(Log), ct:pal("Number of messages sent = ~w~nNumber of messages logged = ~w", [Sent,Logged]), - ok = file_delete(Log), true = (Logged > (ReqLimit*Windows)) andalso - (Logged < (ReqLimit*(Windows+2))). + (Logged < (ReqLimit*(Windows+2))), + ok = file_delete(Log), + ok. limit_burst_enabled_period(cleanup, _Config) -> ok = stop_handler(?MODULE). @@ -950,7 +968,7 @@ kill_disabled(cleanup, _Config) -> ok = stop_handler(?MODULE). qlen_kill_new(Config) -> - {_Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), Pid0 = whereis(h_proc_name()), {_,Mem0} = process_info(Pid0, memory), RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER, @@ -962,7 +980,7 @@ qlen_kill_new(Config) -> ok = logger:set_handler_config(?MODULE, NewHConfig), MRef = erlang:monitor(process, Pid0), NumOfReqs = 100, - Procs = 2, + Procs = 4, send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice), %% send_burst({n,NumOfReqs}, seq, {chars,79}, notice), receive @@ -973,8 +991,8 @@ qlen_kill_new(Config) -> killed -> ct:pal("Slow shutdown, handler process was killed!", []) end, - timer:sleep(RestartAfter + 2000), - true = is_pid(whereis(h_proc_name())), + file_delete(Log), + {ok,_} = wait_for_process_up(h_proc_name(), RestartAfter * 3), ok after 5000 -> @@ -1001,7 +1019,7 @@ qlen_kill_std(_Config) -> {skip,"Not done yet"}. mem_kill_new(Config) -> - {_Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), + {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), Pid0 = whereis(h_proc_name()), {_,Mem0} = process_info(Pid0, memory), RestartAfter = ?OVERLOAD_KILL_RESTART_AFTER, @@ -1013,7 +1031,7 @@ mem_kill_new(Config) -> ok = logger:set_handler_config(?MODULE, NewHConfig), MRef = erlang:monitor(process, Pid0), NumOfReqs = 100, - Procs = 2, + Procs = 4, send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, notice), %% send_burst({n,NumOfReqs}, seq, {chars,79}, notice), receive @@ -1024,8 +1042,8 @@ mem_kill_new(Config) -> killed -> ct:pal("Slow shutdown, handler process was killed!", []) end, - timer:sleep(RestartAfter * 3), - true = is_pid(whereis(h_proc_name())), + file_delete(Log), + {ok,_} = wait_for_process_up(h_proc_name(), RestartAfter * 3), ok after 5000 -> @@ -1041,23 +1059,27 @@ mem_kill_new(cleanup, _Config) -> mem_kill_std(_Config) -> {skip,"Not done yet"}. +restart_after() -> + [{timetrap,{minutes,2}}]. restart_after(Config) -> {Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), NewHConfig1 = HConfig#{config=>StdHConfig#{overload_kill_enable=>true, overload_kill_qlen=>10, - overload_kill_restart_after=>never}}, + overload_kill_restart_after=>infinity}}, ok = logger:set_handler_config(?MODULE, NewHConfig1), MRef1 = erlang:monitor(process, whereis(h_proc_name())), %% kill handler - send_burst({n,100}, {spawn,2,0}, {chars,79}, notice), + send_burst({n,100}, {spawn,4,0}, {chars,79}, notice), receive - {'DOWN', MRef1, _, _, _Info1} -> - timer:sleep(?OVERLOAD_KILL_RESTART_AFTER + 1000), - undefined = whereis(h_proc_name()), + {'DOWN', MRef1, _, _, _Reason1} -> + file_delete(Log), + error = wait_for_process_up(h_proc_name(),?OVERLOAD_KILL_RESTART_AFTER * 3), ok after 5000 -> + Info1 = logger_std_h:info(?MODULE), + ct:pal("Handler state = ~p", [Info1]), ct:fail("Handler not dead! It should not have survived this!") end, @@ -1071,16 +1093,17 @@ restart_after(Config) -> Pid0 = whereis(h_proc_name()), MRef2 = erlang:monitor(process, Pid0), %% kill handler - send_burst({n,100}, {spawn,2,0}, {chars,79}, notice), + send_burst({n,100}, {spawn,4,0}, {chars,79}, notice), receive - {'DOWN', MRef2, _, _, _Info2} -> - timer:sleep(RestartAfter + 2000), - Pid1 = whereis(h_proc_name()), - true = is_pid(Pid1), + {'DOWN', MRef2, _, _, _Reason2} -> + file_delete(Log), + {ok,Pid1} = wait_for_process_up(h_proc_name(),RestartAfter * 3), false = (Pid1 == Pid0), ok after 5000 -> + Info2 = logger_std_h:info(?MODULE), + ct:pal("Handler state = ~p", [Info2]), ct:fail("Handler not dead! It should not have survived this!") end, ok. @@ -1101,7 +1124,7 @@ handler_requests_under_load(Config) -> flush_qlen => 2000, burst_limit_enable => false}}, ok = logger:set_handler_config(?MODULE, NewHConfig), - Pid = spawn_link(fun() -> send_requests(?MODULE, 1, [{sync,[]}, + Pid = spawn_link(fun() -> send_requests(?MODULE, 1, [{filesync,[]}, {info,[]}, {reset,[]}, {change_config,[]}]) @@ -1160,6 +1183,7 @@ start_handler(Name, FuncName, Config) -> Log = filename:join(Dir, lists:concat([FuncName,".log"])), ct:pal("Logging to ~tp", [Log]), Type = {file,Log}, + _ = file_delete(Log), ok = logger:add_handler(Name, logger_std_h, #{config => #{type => Type}, @@ -1184,10 +1208,10 @@ wait_until_written(File, Sz) -> {ok,#file_info{size = Sz}} -> timer:sleep(1000), case file:read_file_info(File) of - {ok,#file_info{size = Sz1}} -> + {ok,#file_info{size = Sz}} -> ok; - {ok,#file_info{size = Sz2}} -> - wait_until_written(File, Sz2) + {ok,#file_info{size = Sz1}} -> + wait_until_written(File, Sz1) end; {ok,#file_info{size = Sz1}} -> wait_until_written(File, Sz1) @@ -1230,7 +1254,8 @@ send_n_burst(N, seq, Text, Class) -> send_n_burst(N-1, seq, Text, Class); send_n_burst(N, {spawn,Ps,TO}, Text, Class) -> ct:pal("~w processes each sending ~w messages", [Ps,N]), - PerProc = fun() -> + PerProc = fun() -> + process_flag(priority,high), send_n_burst(N, seq, Text, Class) end, MRefs = [begin if TO == 0 -> ok; true -> timer:sleep(TO) end, @@ -1300,7 +1325,7 @@ add_remove_instance_nofile(Type) -> logger:notice(M1=?msg,?domain), ?check(M1), %% check that sync doesn't do damage even if not relevant - ok = logger_std_h:sync(?MODULE), + ok = logger_std_h:filesync(?MODULE), ok = logger:remove_handler(?MODULE), timer:sleep(500), undefined = whereis(h_proc_name()), @@ -1541,3 +1566,24 @@ h_proc_name(Name) -> file_delete(Log) -> file:delete(Log). + +wait_for_process_up(Name,T) -> + N = (T div 500) + 1, + wait_for_process_up1(Name,N). + +wait_for_process_up1(_Name,0) -> + error; +wait_for_process_up1(Name,N) -> + timer:sleep(500), + case whereis(Name) of + Pid when is_pid(Pid) -> + {ok,Pid}; + undefined -> + wait_for_process_up1(Name,N-1) + end. + +filesync_rep_int() -> + case (fun() -> is_atom(?FILESYNC_REPEAT_INTERVAL) end)() of + true -> 5500; + false -> ?FILESYNC_REPEAT_INTERVAL + 500 + end. diff --git a/lib/kernel/test/logger_test_lib.erl b/lib/kernel/test/logger_test_lib.erl index 9097453c10..81eb9ce5eb 100644 --- a/lib/kernel/test/logger_test_lib.erl +++ b/lib/kernel/test/logger_test_lib.erl @@ -52,10 +52,10 @@ log(Node, M, F, A) -> rpc:call(Node, M, F, A ++ [MD]). sync_and_read(Node,disk_log,Log) -> - rpc:call(Node,logger_disk_log_h,sync,[?STANDARD_HANDLER]), + rpc:call(Node,logger_disk_log_h,filesync,[?STANDARD_HANDLER]), file:read_file(Log ++ ".1"); sync_and_read(Node, file,Log) -> - ok = rpc:call(Node,logger_std_h,sync,[?STANDARD_HANDLER]), + ok = rpc:call(Node,logger_std_h,filesync,[?STANDARD_HANDLER]), file:read_file(Log). |