aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorPeter Andersson <[email protected]>2018-06-15 11:04:43 +0200
committerPeter Andersson <[email protected]>2018-06-15 11:04:43 +0200
commit4a25e214ae24292246155cb26d27831550a02922 (patch)
tree74e1e477654914c877e8279ef1db9f1941087831
parent6a82d689a583145ef4c39beb9d4608e583d5f478 (diff)
parent343298ef2ef349e7b74265751fd6151ada224470 (diff)
downloadotp-4a25e214ae24292246155cb26d27831550a02922.tar.gz
otp-4a25e214ae24292246155cb26d27831550a02922.tar.bz2
otp-4a25e214ae24292246155cb26d27831550a02922.zip
Merge branch 'peppe/kernel/logger_updates'
* peppe/kernel/logger_updates: [logger] Correct documentation [logger] Update handler documentation [logger] Fix test suite compilation warnings [logger] Fix failing tests [logger] Change overload_kill_restart_after value to infinity [logger] Change name of function sync/1 to filesync/1 [logger] Reset logger config after tests [logger] Don't delete log file of failing test cases [logger] Set up priority for processes generatig test bursts [logger] Stress overload_kill tests a bit more [logger] Remove some compiler warnings in test suites [logger] Sort keys when testing formatter template [logger] Skip test involving file access rights on windows [logger] Skip some overload protection tests when using dirty schedulers
-rw-r--r--lib/kernel/doc/src/logger_chapter.xml263
-rw-r--r--lib/kernel/doc/src/logger_disk_log_h.xml134
-rw-r--r--lib/kernel/doc/src/logger_std_h.xml104
-rw-r--r--lib/kernel/src/logger_disk_log_h.erl12
-rw-r--r--lib/kernel/src/logger_h_common.erl4
-rw-r--r--lib/kernel/src/logger_h_common.hrl4
-rw-r--r--lib/kernel/src/logger_std_h.erl12
-rw-r--r--lib/kernel/test/logger_SUITE.erl2
-rw-r--r--lib/kernel/test/logger_disk_log_h_SUITE.erl108
-rw-r--r--lib/kernel/test/logger_env_var_SUITE.erl5
-rw-r--r--lib/kernel/test/logger_formatter_SUITE.erl2
-rw-r--r--lib/kernel/test/logger_legacy_SUITE.erl13
-rw-r--r--lib/kernel/test/logger_simple_h_SUITE.erl38
-rw-r--r--lib/kernel/test/logger_std_h_SUITE.erl172
-rw-r--r--lib/kernel/test/logger_test_lib.erl4
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 =&lt; drop_new_reqs_qlen =&lt; flush_reqs_qlen</c></p>
+ <p><c>sync_mode_qlen =&lt; drop_mode_qlen =&lt; flush_qlen</c></p>
<p>and that:</p>
- <p><c>drop_new_reqs_qlen &gt; 1</c></p>
+ <p><c>drop_mode_qlen &gt; 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).