LOG4CL-EXTRAS - Addons for Log4CL

LOG4CL-EXTRAS ASDF System Details

• Description: A bunch of addons to LOG4CL: JSON appender, context fields, cross-finger appender, etc.

• Licence: BSD

• Author: Alexander Artemenko

• Homepage: https://40ants.com/log4cl-extras/

• Bug tracker: https://github.com/40ants/log4cl-extras/issues

• Source control: GIT

• Depends on: 40ants-doc, alexandria, cl-strings, dissect, global-vars, jonathan, local-time, log4cl, named-readtables, pythonic-string-reader, with-output-to-stream

Installation

You can install this library from Quicklisp, but you want to receive updates quickly, then install it from Ultralisp.org:

(ql-dist:install-dist "http://dist.ultralisp.org/"
                      :prompt nil)
(ql:quickload :log4cl-extras)

Configuration

By default LOG4CL outputs log items like this:

CL-USER> (log:info "Hello")
 <INFO> [01:15:37] cl-user () - Hello

However logging extra context fields requires a custom "layout". Layout defines the way how the message will be formatted.

This system defines two layout types:

• :PLAIN - a layout for printing messages to the REPL.

• :JSON - a layout which outputs each message and all it's data as a JSON documents. Use it to feed logs to Elastic Search or a service like Datadog to Papertrail.

To use these custom layouts, you have to use setup function. It also allows to set a log level for root logger and appenders. Here is a minimal example showing how to configure logger for the REPL:

CL-USER> (log4cl-extras/config:setup
          '(:level :debug
            :appenders ((this-console :layout :plain))))
NIL

CL-USER> (log:info "Hello")
<INFO> [2021-05-16T01:16:46.978992+03:00] Hello

CL-USER> (log4cl-extras/context:with-fields (:foo "Bar")
           (log:info "Hello"))
<INFO> [2021-05-16T01:26:30.331849+03:00] Hello
  Fields:
    foo: Bar

If you replace :PLAIN with :JSON, you'll get this:

CL-USER> (log4cl-extras/config:setup
          '(:level :debug
            :appenders ((this-console :layout :json))))
; No values
CL-USER> (log4cl-extras/context:with-fields (:foo "Bar")
           (log:info "Hello"))
{"fields":{"foo":"Bar"},"level":"INFO","message":"Hello","timestamp":"2021-05-16T01:27:54.879336+03:00"}

Appender in terms of log4cl is a target for log output. You can combine multiple appenders in a single call to setup function.

Here is the example of the config, suitable for production. Here we log all messages as JSON records into the file, rotated on the daily basis. And all errors and warnings will be written to the REPL.

(log4cl-extras/config:setup
 '(:level :debug
   :appenders ((this-console :layout :plain
                             :filter :warn)
               (daily :layout :json
                      :name-format "/app/logs/app.log"
                      :backup-name-format "app-%Y%m%d.log"))))

Also, setup allows to change log levels for different loggers:

(setup
 '(:level :error
   :appenders
   (this-console
    (file
     :file "foo.log"
     :layout json))
   :loggers
   ((log4cl-extras/config
     :loggers
     ((foo :level :debug)
      (bar
       :loggers
       ((some-class
         :level debug))))))))

Layouts

Context Fields

Macro with-fields let to to capture some information into the dynamic variable. All messages logged inside the with-fields form will have these fields attached:

CL-USER> (log4cl-extras/config:setup
          '(:level :debug
            :appenders ((this-console :layout :plain))))

CL-USER> (defun process-request ()
           (log:info "Processing request"))

CL-USER> (log4cl-extras/context:with-fields (:request-id 42)
           (process-request))
<INFO> [2020-07-19T10:03:21.079636Z] Processing request
  Fields:
    request-id: 42

;; Now let's switch to JSON layout:
CL-USER> (log4cl-extras/config:setup
          '(:level :debug
            :appenders ((this-console :layout :json))))

CL-USER> (log4cl-extras/context:with-fields (:request-id 42)
           (process-request))
{"fields": {"request-id": 42},
 "level": "INFO",
 "message": "Processing request",
 "timestamp": "2020-07-19T10:03:32.855593Z"}

Beware!, catching context fields costs some time even if they are not logged.

Logging Unhandled Errors

Quickstart

If you want to log unhandled signals traceback, then use with-log-unhandled macro.

Usually it is good idea, to use with-log-unhandled in the main function or in a function which handles a HTTP request.

If some error condition will be signaled by the body, it will be logged as an error with "traceback" field like this:

CL-USER> (defun foo ()
           (error "Some error happened"))

CL-USER> (defun bar ()
           (foo))

CL-USER> (log4cl-extras/error:with-log-unhandled ()
           (bar))

<ERROR> [2020-07-19T10:14:39.644805Z] Unhandled exception
  Fields:
  Traceback (most recent call last):
    File "NIL", line NIL, in FOO
      (FOO)
    File "NIL", line NIL, in BAR
      (BAR)
    File "NIL", line NIL, in (LAMBDA (…
      ((LAMBDA ()))
    File "NIL", line NIL, in SIMPLE-EV…
      (SB-INT:SIMPLE-EVAL-IN-LEXENV
       (LOG4CL-EXTRAS/ERROR:WITH-LOG-UNHANDLED NIL
         (BAR))
       #<NULL-LEXENV>)
    ...
       #<CLOSURE (LAMBDA () :IN SLYNK::CALL-WITH-LISTENER) {100A6B043B}>)
     
     
  Condition: Some error happened
; Debugger entered on #<SIMPLE-ERROR "Some error happened" {100A7A5DB3}>

The JSON layout will write such error like this:

{
  "fields": {
    "traceback": "Traceback (most recent call last):\n  File \"NIL\", line NIL, in FOO\n    (FOO)\n  File \"NIL\", line NIL, in BAR\n    (BAR)\n...\nCondition: Some error happened"
  },
  "level": "ERROR",
  "message": "Unhandled exception",
  "timestamp": "2020-07-19T10:21:33.557418Z"
}

Printing Backtrace

There is a helper function print-backtrace for extracting and printing backtrace, which can be used separately from logging. One use case is to render backtrace on the web page when a site is in a debug mode:

CL-USER> (log4cl-extras/error:print-backtrace :depth 3)
Traceback (most recent call last):
   0 File "/Users/art/.roswell/src/sbcl-2.0.11/src/code/eval.lisp", line 291
       In SB-INT:SIMPLE-EVAL-IN-LEXENV
     Args ((LOG4CL-EXTRAS/ERROR:PRINT-BACKTRACE :DEPTH 3) #<NULL-LEXENV>)
   1 File "/Users/art/.roswell/src/sbcl-2.0.11/src/code/eval.lisp", line 311
       In EVAL
     Args ((LOG4CL-EXTRAS/ERROR:PRINT-BACKTRACE :DEPTH 3))
   2 File "/Users/art/projects/lisp/sly/contrib/slynk-mrepl.lisp"
       In (LAMBDA () :IN SLYNK-MREPL::MREPL-EVAL-1)
     Args ()

By default, it prints to the *DEBUG-IO*, but you can pass it a :STREAM argument which has the same semantic as a stream for FORMAT function.

Other useful parameters are :DEPTH and :MAX-CALL-LENGTH. They allow to control how long and wide backtrace will be.

Also, you might pass :CONDITION. If it is given, it will be printed after the backtrace.

And finally, you can pass a list of functions to filter arguments before printing. This way secret or unnecesary long values can be stripped. See the next section to learn how to not log secret values.

API

Condition REBLOCKS-WEBSOCKET:NO-ACTIVE-WEBSOCKETS: No active websockets bound to the current page.

CL-USER> (log4cl-extras/error:make-placeholder "secret value")

#<secret value>

How Keep Secrets Out of Logs

When backtrace is printed to log files it is good idea to omit passwords, tokens, cookies, and other potentially sensitive values.

Here is a potential situation where you have a password and trying to create a new connection to the database. But because of some network error, an unhandled error along with a backtrace will be logged. Pay attention to our secret password in the log:

CL-USER> (log4cl-extras/config:setup
           '(:level :error
             :appenders ((this-console :layout plain))))
   
CL-USER> (defun connect (password)
           "Normally, we don't control this function's code
  because it is from the third-party library."
           (check-type password string)
           (error "Network timeout"))
   
CL-USER> (defun authenticate (password)
           "This function is in our app's codebase.
  It is calling a third-party DB driver."     
           (connect password))
   
CL-USER> (defun bar (password)
           (authenticate password))
   
CL-USER> (log4cl-extras/error:with-log-unhandled (:depth 5)
           (bar "The Secret Password"))
<ERROR> [2021-01-24T14:13:24.460890+03:00] Unhandled exception
  Fields:
  Traceback (most recent call last):
     0 File "unknown"
         In (FLET "H0")
       Args (#<SIMPLE-ERROR "Network timeout" {100F065533}>)
     1 File "/Users/art/.roswell/src/sbcl-2.0.11/src/code/cold-error.lisp", line 81
         In SB-KERNEL::%SIGNAL
       Args (#<SIMPLE-ERROR "Network timeout" {100F065533}>)
     2 File "/Users/art/.roswell/src/sbcl-2.0.11/src/code/cold-error.lisp", line 154
         In ERROR
       Args ("Network timeout")
     3 File "unknown"
         In CONNECT
       Args ("The Secret Password")
     4 File "unknown"
         In AUTHENTICATE
       Args ("The Secret Password")
  
  Condition: Network timeout

With log4cl-extras you can keep values in secret in two ways.

Easy Way

The easiest way, is to wrap all sensitive data using secret-values library as soon as possible and unwrap them only before usage.

Lets see what will happen if we'll use a wrapped password.

First, we need to teach AUTHENTICATE function, how to unwrap the password, before passing it to the driver:

CL-USER> (defun authenticate (password)
           "This function is in our app's codebase.
  It is calling a third-party DB driver."
           (connect
            (secret-values:ensure-value-revealed
             password)))

Next, we need to wrap password into a special object. It is better to do this as soon as possible. In production code you'll probably have something like (secret-values:conceal-value (uiop:getenv "POSTGRES_PASSWORD")):

CL-USER> (log4cl-extras/error:with-log-unhandled (:depth 5)
           (bar (secret-values:conceal-value
                 "The Secret Password")))
<ERROR> [2021-01-24T14:16:01.667651+03:00] Unhandled exception
  Fields:
  Traceback (most recent call last):
     0 File "unknown"
         In (FLET "H0")
       Args (#<SIMPLE-ERROR "Network timeout" {10036CB1A3}>)
     1 File "/Users/art/.roswell/src/sbcl-2.0.11/src/code/cold-error.lisp", line 81
         In SB-KERNEL::%SIGNAL
       Args (#<SIMPLE-ERROR "Network timeout" {10036CB1A3}>)
     2 File "/Users/art/.roswell/src/sbcl-2.0.11/src/code/cold-error.lisp", line 154
         In ERROR
       Args ("Network timeout")
     3 File "unknown"
         In CONNECT
       Args ("The Secret Password")
     4 File "unknown"
         In AUTHENTICATE
       Args (#<SECRET-VALUES:SECRET-VALUE {10036CB183}>)
     
  Condition: Network timeout

Pay attention to the fourth stack frame. AUTHENTICATE function has #<SECRET-VALUES:SECRET-VALUE {10036CB183}> as the first argument. But why do we see "The Secret Password" in the third frame anyway?

It is because we have to pass a raw version of the password to the libraries we don't control.

Here is where log4cl-extras comes to the resque. It provides a package LOG4CL-EXTRAS/SECRETS. It is optional and is not loaded together with the primary system.

Earlier, I've mentioned :ARGS-FILTERS argument to the log4cl-extras/error:print-backtrace function. Package LOG4CL-EXTRAS/SECRETS provides a function make-secrets-replacer which can be used to filter secret values.

We can add it into the global variable log4cl-extras/error:*args-filter-constructors* like this:

CL-USER> (ql:quickload :log4cl-extras/secrets)
(:LOG4CL-EXTRAS/SECRETS)
   
CL-USER> (setf log4cl-extras/error:*args-filter-constructors*
               (list 'log4cl-extras/secrets:make-secrets-replacer))
(#<FUNCTION LOG4CL-EXTRAS/SECRETS:MAKE-SECRETS-REPLACER>)

Now let's try to connect to our fake database again:

CL-USER> (log4cl-extras/error:with-log-unhandled (:depth 5)
           (bar (secret-values:conceal-value
                 "The Secret Password")))
<ERROR> [2021-01-24T14:27:17.851716+03:00] Unhandled exception
  Fields:
  Traceback (most recent call last):
     0 File "unknown"
         In (FLET "H0")
       Args (#<SIMPLE-ERROR "Network timeout" {100800F723}>)
     1 File "/Users/art/.roswell/src/sbcl-2.0.11/src/code/cold-error.lisp", line 81
         In SB-KERNEL::%SIGNAL
       Args (#<SIMPLE-ERROR "Network timeout" {100800F723}>)
     2 File "/Users/art/.roswell/src/sbcl-2.0.11/src/code/cold-error.lisp", line 154
         In ERROR
       Args ("Network timeout")
     3 File "unknown"
         In CONNECT
       Args (#<secret value>)
     4 File "unknown"
         In AUTHENTICATE
       Args (#<secret value>)
  
  Condition: Network timeout

Now both third and fourth frames show #<secret value> instead of the password. This is because (log4cl-extras/secrets:make-secrets-replacer) call returns a closure which remembers and replaces raw values of the secrets too!

Hard Way

Sometimes it is desireable to remove from tracebacks other kinds of data. For example I don't want to see Lack's environments, because of a few reasons:

• they contain cookies and it is insecure to log them;

• they may contain HTTP header with tokens;

• env objects are list with large amount of data and this makes tracebacks unreadable.

Let's create a filter for arguments, which will replace Lack's environments with a placeholder.

First, we need to create a placeholder object:

CL-USER> (defvar +lack-env-placeholder+
           (log4cl-extras/error:make-placeholder "lack env"))
+LACK-ENV-PLACEHOLDER+

Next, we need to define a filter function. Each filter function should accept two arguments:

• a function's name, which can be a symbol or a list like (:method foo-bar (...))

• a list of arguments.

Filter should return two values, which can be the same is inputs or a transformed in some way.

For example, we know that the Lack's env is a plist with :REQUEST-METHOD, :REQUEST-URI and other values. We can to write a predicate like this:

CL-USER> (defun lack-env-p (arg)
           (and (listp arg)
                (member :request-method arg)
                (member :request-uri arg)))

And to use it in our filter:

CL-USER> (defun remove-lack-env-from-frame (func-name args)
           "Removes Lack's env from stackframes to make backtrace concise."
           (values func-name
                   (loop for arg in args
                         if (lack-env-p arg)
                           collect +lack-env-placeholder+
                         else
                           collect arg)))

Now let's try to use it:

CL-USER> (defun request-handler (app env)
           (authenticate (secret-values:conceal-value
                          "Secret password"))
           (pass-further app env))
   
CL-USER> (setf log4cl-extras/error:*args-filters*
               (list 'remove-lack-env-from-frame)
               log4cl-extras/error:*args-filter-constructors*
               ;; We need this too to keep DB password safe, remember?
               (list 'log4cl-extras/secrets:make-secrets-replacer))

Now pay attention to the fifth frame, where second argument is replaced with #<lack env>!!!

CL-USER> (log4cl-extras/error:with-log-unhandled (:depth 7)
           (request-handler 42
                            (list :request-method :post
                                  :request-uri "/login/"
                                  :cookies "Session hash, and other secrets.")))
<ERROR> [2021-01-24T14:56:45.502656+03:00] Unhandled exception
  Fields:
  Traceback (most recent call last):
     0 File "unknown"
         In (FLET "H0")
       Args (#<SIMPLE-ERROR "Network timeout" {1004233EB3}>)
     1 File "/Users/art/.roswell/src/sbcl-2.0.11/src/code/cold-error.lisp", line 81
         In SB-KERNEL::%SIGNAL
       Args (#<SIMPLE-ERROR "Network timeout" {1004233EB3}>)
     2 File "/Users/art/.roswell/src/sbcl-2.0.11/src/code/cold-error.lisp", line 154
         In ERROR
       Args ("Network timeout")
     3 File "unknown"
         In CONNECT
       Args (#<secret value>)
     4 File "unknown"
         In AUTHENTICATE
       Args (#<secret value>)
     5 File "unknown"
         In REQUEST-HANDLER
       Args (42 #<lack env>)
     6 File "unknown"
         In (LAMBDA ())
       Args ()
     
  Condition: Network timeout

For such simple case like replacing args matching a predicate, log4cl-extras has a small helper log4cl-extras/error:make-args-filter:

CL-USER> (setf log4cl-extras/error:*args-filters*
               (list (log4cl-extras/error:make-args-filter
                      'lack-env-p
                      (log4cl-extras/error:make-placeholder "LACK ENV BEING HERE")))
               log4cl-extras/error:*args-filter-constructors*
               ;; We need this too to keep DB password safe, remember?
               (list 'log4cl-extras/secrets:make-secrets-replacer))
   
<ERROR> [2021-01-24T15:09:48.839513+03:00] Unhandled exception
  Fields:
  Traceback (most recent call last):
     0 File "unknown"
         In (FLET "H0")
       Args (#<SIMPLE-ERROR "Network timeout" {1003112243}>)
     1 File "/Users/art/.roswell/src/sbcl-2.0.11/src/code/cold-error.lisp", line 81
         In SB-KERNEL::%SIGNAL
       Args (#<SIMPLE-ERROR "Network timeout" {1003112243}>)
     2 File "/Users/art/.roswell/src/sbcl-2.0.11/src/code/cold-error.lisp", line 154
         In ERROR
       Args ("Network timeout")
     3 File "unknown"
         In CONNECT
       Args (#<secret value>)
     4 File "unknown"
         In AUTHENTICATE
       Args (#<secret value>)
     5 File "unknown"
         In REQUEST-HANDLER
       Args (42 #<LACK ENV BEING HERE>)
     6 File "unknown"
         In (LAMBDA ())
       Args ()
  
  Condition: Network timeout

Appenders

In case of errors, LOG4CL removes appender from the logger. After that log message will be lost.

I don't like this behaviour and prefer to see such errors in logs and to log other messages. This library defines a special appender classes which are not removed on errors but output this message instead: "Caught SOME-ERROR: Error description - Unable to log the message.".

When you use log4cl-extras/config:setup function it automatically uses these appenders.

To debug logging errors interactively, you can set *debug-on-error* variable to T.