A logger that sends to multiple destinations in multiple formats. Based on arnesi logger

a-cl-logger

## a-cl-logger

A common lisp logging library providing context sensitive logging of
more than just strings to more than just local files / output streams

This started as a significant refactor arnesi logging and the many
chunks of surrounding code.

### Goals

 * node-logstash integration
 * Swank presentations integration (objects are printed to the REPL as
   an inspectable presentation (C-c M-p)
 * Support logging of more than just strings, eg: json
 * Context sensitive logging (easily use the dynamic context to add to 
   the data being logged)
 * Gracefully handle slime/swank reconnects
 * Errors in logging shouldnt cause application errors, but should
   still be debuggable

### Quickstart

```

(eval-when (:compile-toplevel :load-toplevel :execute)
  (ql:quickload :a-cl-logger))

;; log to stderr
(a-cl-logger:define-logger testlog ())
(defun do-something(x)
  (testlog.debug "starting to do something to ~a" x)
  (testlog.info "did something to ~a" x))

;; log to stderr and a file (see note about buffering in "Gotchas" below)
(a-cl-logger:define-logger filelog ()
  :appenders (make-instance 'a-cl-logger:file-log-appender
                :log-file "test.log"))

;; log to stderr and a file (see note about buffering in "Gotchas" below)
(a-cl-logger:define-logger filelog ()
  :appenders (make-instance 'a-cl-logger:json-file-log-appender
                :log-file "test.json.log"))


```

### Description and Glossary 

A Logger is a mechanism for generating a text message and have that
messaged saved somewhere for future review. Logging can be used as a
debugging mechanism or for just reporting on the status of a system.

Messages are sent to a particular Logger. Each logger sends the
messages it receives to its appenders. An appenders's job is to take a
message and write it somewhere. Loggers are organized in a hierarchy
and messages sent to a logger will also be sent to that loggers's
parents (if valid). Only if the message is enabled for the current
logger will it be propogated to the parents.

Each logger has a level which is used to determine whether a particular
message should be processed or not. Loggers inherit their log level from
their parents. If a logger has multiple direct parents its log level is
the min of the levels of its parents.

### Glossary

 * Logger - an object that contains a list of places to send messages
   (appenders) and a level.  Loggers are hierarchical and will send 
   messages to all parent appenders and defer to parent levels.
 * Level - dribble, debug, info, warn, error, fatal, a name and number
   indicating the sevarity of log messages.  Levels are used to filter
   which messages are sent to which loggers and appenders
 * Appenders - an object that transmits a message to a location (file,
   repl, node-logstash) in a given format (by using the formatter
   found in the formatter slot)
 * Formatter - format-message is specialized on a formatter, which is
   stored on each appender.
 * Message - The data trying to be logged, a localtime:timestamp, and
   a level indicating this message's importance

### Log message format:

Messages contain:
 * format-string and arguments
 * plist of keys/values
 * logger
 * level

The default printing of a message is  
"{ts} {logger}{level} formatted-msg {key,val ...}" 

eg:

```
(testlog.debug "Format-string example:#~d" 1)
(testlog.debug :a-plist-key :a-plist-value :some-key "some value")
```

### Logging

Logging can be accomplished by a couple of means:

#### Helper macros ####

Helper 

```
(testlog.debug "Format-string example:#~d" 1)
(testlog.info :a-plist-key :a-plist-value :some-key "some value")
```

These helper macros will handle errors in log argument evaluation (you
can still debug if *debug-hook* is bound). They will also capture the
literal arguments provided to the macro to ease debugging.

#### do-log ####
The `do-log` function can also be used to create log messages

```
(do-log *testlog* +info+ "Format-string example:#~d" 1)
(do-log 'testlog +debug+ :a-plist-key :a-plist-value :some-key "some value")
```

There is also a helper get-log-fn which will create a function of
(&rest args) that logs to a given logger and level).  This is useful
for libraries that supply functional logging hooks

```
(get-log-fn *testlog* :level +info+) => (lambda (&rest args) ...)
```

### Root Logger

There is a root logger which all other loggers have as a parent by
default.  This is a conveneint place to put appenders that should
always apply.  You can remove the root by removing it from the parents
slot of a logger.

### Appenders and Formatters

 * An appender controls writing a log message to a specific destination
 * Each appender has a formatter that controls the way the log message
   is printed.

### Filtering

This will mute timing messages to any file appenders
(eg: send timing only to the repl / logstash)
```
(define-logger app-log ())
(define-logger timing-log (app-log))
(defun mute-timing-file-appends (c)
    (let* ((m (a-log:message c))
           (l (a-log:logger m))
           (a (a-log:appender c)))
      (when (and (typep a 'a-log:file-log-appender)
                 (eql l *timing-log*))
        (abort c))))
(a-log:add-signal-handler
 *timing-log* 'a-log:appending-message 'mute-timing-file-appends)
```
### Signals and Restarts - Context Sensitive Logging

Messages generate signals on being created and on being appended.

 * generating-message - signaled when a message is created
 * logging-message - signaled when a specific logger begins handling a
   message
 * appending-message - signaled when a specific appender begins
   handling a message


#### Muffling log messages / aborting

Each signal can be aborted which will prevent the operation from
occuring.

Aborting while appending will prevent the message from going to a
single destination.  Aborting while logging will prevent the message
from going to ANY appenders of the log or its parents.  Aborting while
generating a message just muffles that log message entirely

#### Changing / Adding to the messages being logged

At each of these points you can invoke the restart `change-message` to
alter the message going out.  Generally the message you change to will
be a copy of the original (see copy-message).

Each of these signals are wrapped in a `change-message` restart that
can be used to modify the message for the remainder of the operation.
(IE: a specific appender will operate on a new copy of the message
with different, supplemental data).

#### Default Handlers

Signals can be handled by handler-binds on the dynamic context or by
adding default-handlers to the `default-signal-bindings` slot on the
logger.  This can be accomplished using `add-signal-handler` passing 
the logger, a condition type and a fn.

Here are some examples. The first prevents the timing log from being inserted
into the log file.  The second prevents a particular log message from 
being inserted into the logs.

```
(defun mute-timing-file-appends (c)
    (let* ((m (a-log:message c))
           (l (a-log:logger m))
           (a (a-log:appender c)))
      (when (and (typep a 'a-log:file-log-appender)
                 (eql l *timing-log*))
        (abort c))))

(a-log:add-signal-handler
 *timing-log* 'a-log:appending-message 'mute-timing-file-appends)

(defun ignore-foreach-warnings (c)
  (let ((fs (a-log:format-control (a-log:message c))))
    (when (cl-ppcre:scan #?r"(?i)invalid argument supplied for foreach" fs)
      (abort c))))

(a-log:add-signal-handler
 *wp-log* 'a-log:generating-message 'ignore-foreach-warnings)

```

### Helper Functions

 * `get-log-fn`: given a logger and an optional level create a function
   of &rest args that logs to the given logger. Useful for interacting
   with libraries providing functional logging hooks
 
 * `with-appender`: create a dynamic scope inside which messages to
   logger will additionally be appended to this appender

 * `when-log-message-generated/logged/appended`: These are macros that
   establish a dynamic context inside of which log messages will be
   intercepted at key points in their life cycle.  The first body is 
   the message handler and the second is the scope.
 
 * `setup-logger`: a function that will ensure log-level and standard
   debug-io-appender / file-appenders are in place.  Useful when debug
   IO become rebound etc (slime session resets).  Probably not as
   useful now that there is a root logger and we dont have to constantly 
   attach the same appenders everywhere

### Gotchas

 * There are some SBCL specifics.  Cross platform help would be nice
  * "--quiet" command line arg
  * logstash hostname 
 * file log appender output may be buffered by the lisp
   implementation's stream operations. If you have a slow process,
   messages may take some time to be written to the log file. Use
   `(make-instance 'a-cl-logger:file-log-appender :log-file "test.log"
   :buffer-p nil)` to aggressively call
   [force-output](http://l1sp.org/cl/force-output) and ensure the log
   file is accurate.

### Differences From Arnesi/src/log.lisp

 * There has been some significant renaming
  * deflogger -> define-logger
  * log-category -> logger
  * appenders are separate from formatters
 * File streams ensure the file is open to write to
 * Failing to write to one appender / logger doesnt prevent the rest
   from working

## Examples:
!! These examples are all in SBCL !!

### Capturing log output to strings

```
(a-log:with-logged-output (a-log:*root-logger*)
  (run-some-data *context*)
  )
=>
"Log message 1
Log message 2
Log message 3"
```

### Filtering message content

This will abort / mute log messages that match a certain warning

```
(defun ignore-foreach-warnings (c)
  (let ((fs (a-log:format-control (a-log:message c))))
    (when (cl-ppcre:scan #?r"(?i)invalid argument supplied for foreach" fs)
      (abort c))))

(define-logger my-module-log (my-log))

```

#### Filter log messages globally for a specific logger:

```
(a-log:add-signal-handler
 *my-module-log* 'a-log:generating-message 'ignore-foreach-warnings)
```

#### Filter log messages locally for a logger:

```
(defmacro with-muted-foreach-warnings (() &body body)
  (handler-bind ((a-log:generating-message #'ignore-foreach-warnings))
    (progn ,@body)))
```

### Basic Context Sensitive Logging

(a-log:when-log-message-generated
    ((a-log:push-into-message :a 1 :b 2))
  (log.debug "This message will have a=1 and b=2 in its data"))


### Logging the lexical environment

```

(a-log:define-logger my-log ()
  :appenders (make-instance 'a-log:stream-log-appender :stream *standard-output*))

(defun compile-env-data-list (env)
  (let* ((blocks (mapcar #'first (reverse (sb-c::lexenv-blocks env))))
         (lex-vars (reverse (sb-c::lexenv-vars env)))
         (vars (iter (for (name . v) in lex-vars)
                 (for ignore? = (ignore-errors (sb-c:lambda-var-ignorep v)))
                 (unless ignore?
                   (collect `(quote ,name))
                   (collect name)))))
    (values
     (first blocks)
     `(list :blocks (princ-to-string '(,@blocks))
       (list ,@vars)))))

(defmacro with-env-stats-recorder (()
                                   &body body &environment env)
  "puts data and tag from the lexical env into the message"
  (multiple-value-bind (name data-forms)
      (compile-env-data-list env)
    `(a-log:when-log-message-generated
      ((a-log:push-into-message :lexical-data (,@data-forms) :name ',name))
      ,@body)))

(defun test-cs-logging (&key (a 1) (b 2))
  (my-log.info "OUT of Env Recorder ")
  (with-env-stats-recorder ()
    (my-log.info "In test-cs-logger recorder ")
    (let ((c (+ 1 b)))
      (flet ((again (d)
               (incf d)
               (with-env-stats-recorder ()
                 (my-log.info "In again ~a " d))))
        (again a)
        (again b)))))
```



a-cl-logger

Upstream URL

Author

License

a-cl-logger

Version:

License:

Authors:

Dependencies:

a-cl-logger-logstash

License:

Authors:

Dependencies:

a-cl-logger-tests

License:

Authors:

Dependencies:

Dependencies (11)

Dependents (0)