Merge remote-tracking branch 'origin/logger-refactor' into ipfix-wip

src/apps/bridge/learning.lua

@@ -82,6 +82,7 @@ local bridge_base = require("apps.bridge.base").bridge
 local mac_table = require("apps.bridge.mac_table")
 require("apps.bridge.learning_h")
 local ethernet = require("lib.protocol.ethernet")
+local logger = require("lib.logger")
 
 local empty, receive, transmit = link.empty, link.receive, link.transmit
 local clone = packet.clone
@@ -179,7 +180,7 @@ function bridge:new (arg)
    alloc_pft(o)
    -- Box to store a pointer to a MAC address in memory
    o._mac = ffi.new("uint8_t *[1]")
-   o._logger = lib.logger_new({ module = "bridge" })
+   o._logger = logger.new({ module = "bridge" })
    return o
 end
 

src/apps/bridge/mac_table.lua

@@ -118,6 +118,7 @@ local ffi = require("ffi")
 local C = ffi.C
 local lib = require("core.lib")
 local murmur = require("lib.hash.murmur")
+local logger = require("lib.logger")
 local band = require("bit").band
 require("apps.bridge.learning_h")
 
@@ -206,7 +207,7 @@ function mac_table:new (config)
    -- C.mac_table_insert()
    o._tables_C = ffi.new("hash_table_t *[2]")
    alloc_tables(o, o._buckets)
-   o._logger = lib.logger_new({ module = "mac_table" })
+   o._logger = logger.new({ module = "mac_table" })
    timer.activate(
       timer.new("mac_table_timeout",
                 function (t)

src/apps/ipv6/nd_light.lua

@@ -47,6 +47,7 @@ local tlv = require("lib.protocol.icmp.nd.options.tlv")
 local filter = require("lib.pcap.filter")
 local timer = require("core.timer")
 local lib = require("core.lib")
+local logger = require("lib.logger")
 
 nd_light = subClass(nil)
 nd_light._name = "Partial IPv6 neighbor discovery"
@@ -236,7 +237,7 @@ function nd_light:new (arg)
       p = ffi.new("struct packet *[1]"),
       mem = ffi.new("uint8_t *[1]")
    }
-   o._logger = lib.logger_new({ module = 'nd_light' })
+   o._logger = logger.new({ module = 'nd_light' })
 
    return o
 end

src/core/lib.lua

@@ -457,172 +457,6 @@ function root_check (message)
    end
 end
 
--- Backward compatibility
-token_bucket_new = require("lib.token_bucket").new
-
--- Simple rate-limited logging facility.  Usage:
---
---   local logger = lib.logger_new({ rate = <rate>,
---                                   discard_rate = <drate>,
---                                   fh = <fh>,
---                                   flush = true|false,
---                                   module = <module>,
---                                   date = true|false })
---   logger:log(message)
---
--- <rate>   maximum rate of messages per second.  Additional
---          messages are discarded. Default: 10
--- <drate>  maximum rate of logging of the number of discarded
---          messages.  Default: 0.5
--- <fh>     file handle to log to.  Default: io.stdout
--- flush    flush <fh> after each message if true
--- <module> name of the module to include in the message
--- date     include date in messages if true
---
--- The output format is
--- <date> <module>: message
---
--- The logger uses an automatic throttling mechanism to dynamically
--- lower the logging rate when the rate of discarded messages exceeds
--- the maximum log rate by a factor of 5 over one or multiple adjacent
--- intervals of 10 seconds.  For each such interval, the logging rate
--- is reduced by a factor of 2 with a lower bound of 0.1 Hz (i.e. one
--- message per 10 seconds).  For each 10-second interval for which the
--- rate of discarded messages is below the threshold, the logging rate
--- is increased by 1/4 of the original rate, i.e. it takes at least 40
--- seconds to ramp back up to the original rate.
---
--- The tables lib.logger_default and lib.logger_throttle are exposed
--- to the user as part of the API.
-logger_default = {
-   rate = 10,
-   discard_rate = 0.5,
-   fh = io.stdout,
-   flush = true,
-   module = '',
-   date = true,
-   date_fmt = "%b %d %Y %H:%M:%S ",
-}
-logger_throttle = {
-   interval = 10, -- Sampling interval for discard rate
-   excess = 5,   -- Multiple of rate at which to start throttling
-   increment = 4, -- Fraction of rate to increase for un-throttling
-   min_rate = 0.1, -- Minimum throttled rate
-}
-local logger = {
-   default = logger_default,
-   throttle = logger_throttle,
-}
-logger.mt = { __index = logger }
-
-function logger_new (config)
-   local config = config or logger.default
-   local l = setmetatable({}, logger.mt)
-   _config = setmetatable({}, { __index = logger.default })
-   for k, v in pairs(config) do
-      assert(_config[k], "Logger: unknown configuration option "..k)
-      _config[k] = v
-   end
-   l._config = _config
-   l._tb = token_bucket_new({ rate = _config.rate })
-   l._discard_tb = token_bucket_new({ rate = _config.discard_rate })
-   l._discards = 0
-   local _throttle = {
-      discards = 0,
-      tstamp = C.get_monotonic_time(),
-      rate = _config.rate * logger.throttle.excess,
-      increment = _config.rate/logger.throttle.increment,
-   }
-   l._throttle = setmetatable(_throttle, { __index = logger.throttle })
-   l._preamble = (l._config.module and l._config.module..': ') or ''
-   return l
-end
-
--- Log message <msg> unless the rate limit is exceeded.  Note that
--- <msg> is evaluated upon the method call in any case, which can have
--- a performance impact even when the message is discarded.  This can
--- be avoided by calling the can_log() method first, i.e.
---
---   if logger:can_log() then
---     logger:log('foo')
---   end
---
--- This framework should have very low processing overhead and should
--- be safe to call even form within packet-processing loops.  The
--- bottleneck currently is the call to clock_gettime().  Care has been
--- taken to make sure that this call is executed at most once in the
--- non-rate limited code path.
-
-function logger:log (msg)
-   if self._tb:take(1) then
-      local config = self._config
-      local throttle  = self._throttle
-      throttle.discards = throttle.discards + self._discards
-      local date = ''
-      if config.date then
-         date = os.date(config.date_fmt)
-      end
-      local preamble = date..self._preamble
-      local fh = config.fh
-      local now = C.get_monotonic_time()
-      local interval = now-throttle.tstamp
-      local samples = interval/throttle.interval
-      local drate = throttle.discards/interval
-      local current_rate = self._tb:rate()
-      if self._discards > 0 and self._discard_tb:take(1) then
-         fh:write(string.format(preamble.."%d messages discarded\n",
-                                self._discards))
-         throttle.discards = self._discards
-         self._discards = 0
-      end
-      if samples >= 1 then
-         if drate > throttle.rate then
-            local min_rate = throttle.min_rate
-            if current_rate > min_rate then
-               local throttle_rate = math.max(min_rate,
-                                              current_rate/2^samples)
-               fh:write(string.format(preamble.."message discard rate %.2f exceeds "
-                                      .."threshold (%.2f), throttling logging rate to "
-                                      .."%.2f Hz%s\n",
-                                   drate, throttle.rate, throttle_rate,
-                                   (throttle_rate == min_rate and ' (minimum)') or ''))
-               self._tb:rate(throttle_rate)
-            end
-         else
-            local configured_rate = config.rate
-            if current_rate < configured_rate then
-               local throttle_rate = math.min(configured_rate,
-                                              current_rate + throttle.increment*samples)
-               fh:write(string.format(preamble.."unthrottling logging rate to "
-                                      .."%.2f Hz%s\n",
-                                   throttle_rate,
-                                   (throttle_rate == configured_rate and ' (maximum)') or ''))
-               self._tb:rate(throttle_rate)
-            end
-         end
-         throttle.discards = 0
-         throttle.tstamp = now
-      end
-      fh:write(preamble..msg..'\n')
-      if config.flush then fh:flush() end
-   else
-      self._discards = self._discards + 1
-   end
-end
-
--- Return true if a message can be logged without being discarded,
--- false otherwise.  In the first case, it is guaranteed that the
--- token bucket for the logging rate-limiter contains at least one
--- token.  In the second case, the rate-limit is hit and the counter
--- of discarded messages is increased.
-function logger:can_log ()
-   if self._tb:can_take(1) then
-      return true
-   end
-   self._discards = self._discards + 1
-   return false
-end
-
 -- Wrapper around os.getenv which only returns the variable's value if it
 -- is non-empty.
 function getenv (name)

src/lib/README.logger.md

@@ -0,0 +1,141 @@
+### Logger (lib.logger)
+
+The *logger* module implements a rate-limited logging facility with
+optional throttling of the logging rate under stress.  It uses
+*lib.token_bucket* with the *rdtsc* time-source (if available) for
+rate-limiting, which makes it suitable to be called from
+critical code with minimal impact on performance.
+
+#### Functions
+
+— Function **new** *config*
+
+Creates an instance of a logger.  The required *config* argument must
+be a table with the following keys.
+
+— Key **rate**
+
+*Optional*.  The rate in units of Hz at which the output of log
+messages is limited.  The default is 10 Hz.  The maximum burst size
+(the number of messages that can be posted back-to-back) is
+numerically equal to **rate** (i.e. the maximum number of messages
+allowed during an interval of one second).  Messages that exceed the
+rate limit are discarded.  The number of discarded messages is
+reported periodically, see the **discard_report_rate** configuration
+option.
+
+— Key **discard_report_rate**
+
+*Optional*.  The rate in units of Hz at which reporting of the number
+of discarded messages is limited.  The default is 0.2 Hz.
+
+— Key **fh**
+
+*Optional*.  The file handle to which log messages are written.  The
+default is **io.stdout**.
+
+— Key **flush**
+
+*Optional*. A boolean that indicates wheter **fh** should be flushed
+after each write.  The default is **true**.
+
+— Key **module**
+
+*Optional*. An arbitrary string that will be prepended to each log
+message to identify the component of the application that generated
+the message.  The default is the empty string.
+
+— Key **date**
+
+*Optional*. A boolean that indicates whether each log message should
+be prepended by the current date and time according to the format
+given by the **date_fmt** configuration option.  The default is
+**true**.
+
+— Key **date_fmt**
+
+*Optional*.  A string that defines the format of the time stamp
+prepended to each log message if the **date** configuration option is
+**true**.  It must be a valid format specifier as expected by the
+**os.date** function.  The default is **"%b %d %Y %H:%M:%S "**.
+
+— Key **throttle**
+
+*Optional*.  A boolean that indicates whether automatic throttling of
+the logging rate should be enabled.  The default is **true**.
+
+The mechanism decrease the logging rate when the number of discarded
+messages exceeds a certain threshold to allow a relatively high
+logging rate under normal circumstances while avoiding large amounts
+of messages during "logging storms".
+
+Throttling is coupled to the rate-limiting of discard reports as
+follows.  Whenever a discard report is logged (according to the
+**discard_report_rate** option), the rate of discarded messages since
+the last such event is calculated.
+
+If this rate exceeds a configurable multiple, called the _excess_, of
+**rate**, the effective rate-limit is decreased by a factor of 2.  The
+effective rate-limit is bounded from below by a configurable minimum.
+
+If the rate of discarded messages is below the threshold, the
+effective rate-limit is increased by a configurable fraction of
+**rate**.  The effective rate is bounded from above by **rate**.
+
+— Key **throttle_config**
+
+*Optional*.  This is a table with the following keys.
+
+  * Key **excess**
+
+    *Optional*.  The threshold for the rate of discarded messages at
+    which throttling is applied as detailed above is given by
+    **excess** \* **rate**.  The default is 5 (i.e. the default
+    threshold is 50 Hz).
+
+  * Key **increment**
+
+    *Optional*.  The fraction of **rate** at which the effective
+    rate-limit is increased when the rate of discarded messages is
+    below the threshold.  The default is 4, i.e. the effective
+    increment of the rate is given by **rate**/4 by default.
+
+  * Key **min_rate**
+
+    *Optional*.  The lower bound for the effective rate when
+    throttling is in effect.  The default is 0.1 Hz.
+
+#### Methods
+
+The object returned by the **new** function provides the following
+methods.
+
+— Method **logger:log** *msg*
+
+Print the string *msg* to the logger's file handle.  The string is
+prepended by the date and/or the module name according to the
+configuration. If any messages have been discarded since the last time
+a message has been successfully logged, the number of discarded
+messages is logged as well, subject to the rate-limiting given by
+**discard_report_rate**.  If the discard report is allowd by that
+rate-limit and throttling is enabled, the new effective logging rate
+is calculated and applied as well.
+
+If the rate-limit is exceeded, the message is discarded.
+
+Note that *msg* is evaluated before the method is called.  If the
+evaluation is expensive (e.g. a concatenation of strings) and the
+caller is in a performance-critical section of code, the **can_log**
+method should be used to determine whether the message is allowed by
+the rate-limiter, e.g.
+
+```Lua
+if logger:can_log() then
+   logger:log("foo " .. "bar")
+end
+```
+
+— Method **logger:can_log**
+
+Returns a **true** value if a message can be logged successfully,
+**false** otherwise.

src/lib/ipc/shmem/iftable_mib.lua

@@ -5,6 +5,7 @@ local lib = require("core.lib")
 local mib = require("lib.ipc.shmem.mib")
 local counter = require("core.counter")
 local macaddress = require("lib.macaddress")
+local logger = require("lib.logger")
 local ffi = require("ffi")
 local C = ffi.C
 
@@ -29,7 +30,7 @@ function init_snmp (objs, name, counters, directory, interval)
    end
    local ifTable = mib:new({ directory = directory or nil,
                              filename = name })
-   local logger = lib.logger_new({ module = 'iftable_mib' })
+   local logger = logger.new({ module = 'iftable_mib' })
    -- ifTable
    ifTable:register('ifDescr', 'OctetStr', objs.ifDescr)
    ifTable:register('ifType', 'Integer32')

src/lib/ipsec/esp.lua

@@ -29,7 +29,7 @@ local seq_no_t = require("lib.ipsec.seq_no_t")
 local lib = require("core.lib")
 local ffi = require("ffi")
 local C = ffi.C
-local logger = lib.logger_new({ rate = 32, module = 'esp' })
+local logger = require("lib.logger").new({ rate = 32, module = 'esp' })
 
 require("lib.ipsec.track_seq_no_h")
 local window_t = ffi.typeof("uint8_t[?]")