Add documentation of the built-in logger handlers

7 files changed, 406 insertions, 35 deletions

diff --git a/lib/kernel/doc/src/Makefile b/lib/kernel/doc/src/Makefile
index 10bdf46119..82869d7b15 100644
--- a/lib/kernel/doc/src/Makefile
+++ b/lib/kernel/doc/src/Makefile
@@ -58,6 +58,7 @@ XML_REF3_FILES = application.xml \
 	init_stub.xml \
         logger.xml \
         logger_std_h.xml \
+        logger_disk_log_h.xml \
         logger_filters.xml \
         logger_formatter.xml \
 	net_adm.xml \
diff --git a/lib/kernel/doc/src/logger_chapter.xml b/lib/kernel/doc/src/logger_chapter.xml
index 2a325453da..0bc3b37476 100644
--- a/lib/kernel/doc/src/logger_chapter.xml
+++ b/lib/kernel/doc/src/logger_chapter.xml
@@ -296,6 +296,7 @@
     </section>
 
     <section>
+      <marker id="handler_configuration"/>
       <title>Handler configuration</title>
       <taglist>
 	<tag><c>level</c></tag>
@@ -577,8 +578,8 @@ log(#{msg:={F,A}},#{myhandler_fd:=Fd}) ->
     <p>For examples of overload protection, please refer to the
       implementation
       of <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-->.</p>
+      and <seealso marker="logger_disk_log_h"><c>logger_disk_log_h</c>
+      </seealso>.</p>
 
     <p>Below is a simpler example of a handler which logs through one
       single process, and uses the default formatter to gain a common
@@ -632,6 +633,179 @@ my_report_cb(R) ->
     </code>
   </section>
 
+  <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>
+    
+    <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>
+      
+      <taglist>
+	<tag><c>toggle_sync_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
+	  operation is resumed. The switch from asynchronous to synchronous
+	  mode will force the logging tempo of few busy senders to slow down,
+	  but can not protect the handler sufficiently in situations of many
+	  concurrent senders.</p>
+	</item>
+	<tag><c>drop_new_reqs_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>
+	</item>
+	<tag><c>flush_reqs_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>
+	</item>
+      </taglist>
+
+      <p>For the overload protection algorithm to work properly, it is a
+      requirement that:</p>
+
+      <p><c>toggle_sync_qlen &lt; drop_new_reqs_qlen &lt; flush_reqs_qlen</c></p>
+
+      <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>
+
+      <p>A configuration example:</p>
+      <code type="none">
+logger:add_handler(my_standard_h, logger_std_h,
+                   #{logger_std_h =>
+                              #{type => {file,"./system_info.log"},
+                                toggle_sync_qlen => 100,
+                                drop_new_reqs_qlen => 1000,
+                                flush_reqs_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 console, with massive amounts of
+      printouts. These are the configuration parameters:</p>
+      
+      <taglist>
+	<tag><c>enable_burst_limit</c></tag>
+	<item>
+	  <p>This is set to <c>true</c> by default. The value <c>false</c>
+	  disables the burst control feature.</p>
+	</item>
+	<tag><c>burst_limit_size</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>
+	</item>
+	<tag><c>burst_window_time</c></tag>
+	<item>
+	  <p>The default window is <c>1000</c> milliseconds long.</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"},
+                     logger_disk_log_h =>
+                              #{burst_limit_size => 10,
+                                burst_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>
+      
+      <taglist>
+	<tag><c>enable_kill_overloaded</c></tag>
+	<item>
+	  <p>This is set to <c>false</c> by default. The value <c>true</c>
+	  enables the feature.</p>
+	</item>
+	<tag><c>handler_overloaded_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>
+	</item>
+	<tag><c>handler_overloaded_mem</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>
+	</item>
+	<tag><c>handler_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>
+	</item>
+      </taglist>
+    </section>
+  </section>
 
   <section>
     <title>See Also</title>
diff --git a/lib/kernel/doc/src/logger_disk_log_h.xml b/lib/kernel/doc/src/logger_disk_log_h.xml
new file mode 100644
index 0000000000..90cc4fec30
--- /dev/null
+++ b/lib/kernel/doc/src/logger_disk_log_h.xml
@@ -0,0 +1,146 @@
+<?xml version="1.0" encoding="utf-8" ?>
+<!DOCTYPE erlref SYSTEM "erlref.dtd">
+
+<erlref>
+  <header>
+    <copyright>
+      <year>2017</year>
+      <holder>Ericsson AB. All Rights Reserved.</holder>
+    </copyright>
+    <legalnotice>
+      Licensed under the Apache License, Version 2.0 (the "License");
+      you may not use this file except in compliance with the License.
+      You may obtain a copy of the License at
+
+          http://www.apache.org/licenses/LICENSE-2.0
+
+      Unless required by applicable law or agreed to in writing, software
+      distributed under the License is distributed on an "AS IS" BASIS,
+      WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+      See the License for the specific language governing permissions and
+      limitations under the License.
+
+    </legalnotice>
+
+    <title>logger_disk_log_h</title>
+    <prepared></prepared>
+    <responsible></responsible>
+    <docno></docno>
+    <approved></approved>
+    <checked></checked>
+    <date></date>
+    <rev>A</rev>
+    <file>logger_disk_log_h.xml</file>
+  </header>
+  <module>logger_disk_log_h</module>
+  <modulesummary>A disk_log based handler for the Logger
+  application.</modulesummary>
+
+  <description>
+    <p>This is a handler for the Logger application that offers circular
+    (wrapped) logs by using the disk_log application. Multiple instances
+    of this handler can be added to logger, and each instance will print 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 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
+    <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
+    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
+    datatype
+    <seealso marker="disk_log#open-1"><c>dlog_option()</c></seealso>.</p>
+    <p>Parameters in the <c>disk_log_opts</c> map:</p>
+    <taglist>
+      <tag><c>file</c></tag>
+      <item>This is the full name of the disk_log log file.</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>
+      <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>
+      <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>logger_disk_log_h</c>. It may contain the
+    following parameter:</p>
+    <taglist>
+      <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#disk_log_sync-1"><c>disk_log_sync/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
+    <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>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},
+                     logger_disk_log_h =>
+                              #{filesync_repeat_interval => 1000}}).
+    </code>
+    <p>In order to use the disk_log handler instead of the default standard
+    handler when starting en Erlang node, use the kernel configuration parameter
+    <seealso marker="kernel_app#configuration"><c>logger_dest</c></seealso> with
+    value <c>{disk_log,FileName}</c>. Example:</p>
+    <code type="none">
+erl -kernel logger_dest '{disk_log,"./system_disk_log"}'
+    </code>
+  </description>
+
+  <funcs>
+
+    <func>
+      <name name="disk_log_sync" arity="1" clause_i="1"/>
+      <fsummary>Writes buffered data to disk.</fsummary>
+      <desc>
+        <p>Write buffered data to disk.</p>
+      </desc>
+    </func>
+
+  </funcs>
+
+</erlref>
+
+
diff --git a/lib/kernel/doc/src/logger_std_h.xml b/lib/kernel/doc/src/logger_std_h.xml
index 2a368b16eb..fe9b9ca5a9 100644
--- a/lib/kernel/doc/src/logger_std_h.xml
+++ b/lib/kernel/doc/src/logger_std_h.xml
@@ -39,42 +39,94 @@
     <p>This is the default handler for the Logger
       application. Multiple instances of this handler can be added to
       logger, and each instance will print logs to <c>standard_io</c>,
-      <c>standard_error</c> or to a file.</p>
-
-    <p>To add a new instance,
-      use <seealso marker="logger#add_handler-3"><c>logger:add_handler/3</c>
+      <c>standard_error</c> or to file. The default instance that starts
+      with kernel is named <c>logger_std_h</c> - which is the name to be used
+      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
+      <seealso marker="logger_chapter#overload_protection"><c>User's Guide</c>
       </seealso>.</p>
-
-    <p>The handler configuration may contain the following keys,
-      associated with values as described:</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 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>logger_std_h</c>. The following
+       keys and values may be specified:</p>
     <taglist>
-      <tag><c>filters</c></tag>
-      <item>
-	<p>A list of <c>{Id,{Fun,Args}}</c>, each representing a filter
-	  that may selct or modify log events to forward to this
-	  handler.</p></item>
-      <tag><c>filter_default</c></tag>
-      <item>
-	<p>The atom <c>log</c> or <c>stop</c>, specifying what to
-	  do with a log event if all filters
-	  return <c>ignore</c>.</p></item>
-      <tag><c>formatter</c></tag>
+      <tag><c>type</c></tag>
       <item>
-	<p><c>{Module,Extra}</c>,
-	  where <c>Module:format(Log,Extra)</c> will be called by
-	  the handler to produce the string that will be printed to
-	  the handler's destination.</p></item>
-      <tag><c>level</c></tag>
+	<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>
+      <tag><c>filesync_repeat_interval</c></tag>
       <item>
-	<p>The level of log events that <c>logger</c> shall forward to
-	  this handler. Log events of the specified, or more severe
-	  levels, are forwarded.</p></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#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
+    <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>Example of adding a standard handler:</p>
+    <code type="none">
+logger:add_handler(my_standard_h, logger_std_h,
+                   #{level => info,
+                     filter_default => log,
+                     logger_std_h =>
+                              #{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>,
+    use the kernel configuration parameter
+    <seealso marker="kernel_app#configuration"><c>logger_dest</c></seealso> with
+    value <c>{file,FileName}</c>. Example:</p>
+    <code type="none">
+erl -kernel logger_dest '{file,"./erl.log"}'
+    </code>
+    <p>An example of how to replace the standard handler with a disk_log handler
+    at startup can be found in the manual of
+    <seealso marker="logger_disk_log_h"><c>logger_disk_log_h</c></seealso>.</p>
   </description>
 
-<!--  <funcs>
-  </funcs> -->
+  <funcs>
+
+    <func>
+      <name name="filesync" arity="1" clause_i="1"/>
+      <fsummary>Writes buffered data to disk.</fsummary>
+      <desc>
+        <p>Write buffered data to disk.</p>
+      </desc>
+    </func>
+
+  </funcs>
 
 </erlref>
 
diff --git a/lib/kernel/doc/src/ref_man.xml b/lib/kernel/doc/src/ref_man.xml
index 7f4d5b384f..c06914d23d 100644
--- a/lib/kernel/doc/src/ref_man.xml
+++ b/lib/kernel/doc/src/ref_man.xml
@@ -56,6 +56,7 @@
   <xi:include href="logger_filters.xml"/>
   <xi:include href="logger_formatter.xml"/>
   <xi:include href="logger_std_h.xml"/>
+  <xi:include href="logger_disk_log_h.xml"/>
   <xi:include href="net_adm.xml"/>
   <xi:include href="net_kernel.xml"/>
   <xi:include href="os.xml"/>
diff --git a/lib/kernel/doc/src/specs.xml b/lib/kernel/doc/src/specs.xml
index a67e26ef16..bcc422930e 100644
--- a/lib/kernel/doc/src/specs.xml
+++ b/lib/kernel/doc/src/specs.xml
@@ -24,6 +24,7 @@
   <xi:include href="../specs/specs_logger_filters.xml"/>
   <xi:include href="../specs/specs_logger_formatter.xml"/>
   <xi:include href="../specs/specs_logger_std_h.xml"/>
+  <xi:include href="../specs/specs_logger_disk_log_h.xml"/>
   <xi:include href="../specs/specs_net_adm.xml"/>
   <xi:include href="../specs/specs_net_kernel.xml"/>
   <xi:include href="../specs/specs_os.xml"/>
diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl
index 7a5082fb84..7caad366ae 100644
--- a/lib/kernel/src/logger_h_common.erl
+++ b/lib/kernel/src/logger_h_common.erl
@@ -133,10 +133,6 @@ call_cast_or_drop(Name, Bin) ->
                 dropped -> ok
             catch
                 _:{timeout,_} ->
-                    %%! --- Tue Mar  6 23:10:48 2018 --- peppe was here!
-                    erlang:display('CLIENT_TIMEOUT'),
-                    %% exit('CLIENT_TIMEOUT'),
-
                     ?observe(Name,{dropped,1})
             end;
         drop -> ?observe(Name,{dropped,1})