Quickdocs

Q

log4cl-extras

2024-10-12

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

Upstream URL

github.com/40ants/log4cl-extras

Author

Alexander Artemenko

License

BSD
README
Provided Systems

LOG4CL-EXTRAS - Addons for Log4CL

LOG4CL-EXTRAS ASDF System Details

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:

function log4cl-extras/config:setup config

Setup loggers and appenders via confg.

Example:

(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))))))))

As you can see, setup function accepts a plist with keys :LEVEL, :APPENDERS and :LOGGERS.

:LEVEL key holds a logging level for the root logger. It could be :INFO, :WARN or :ERROR.

:APPENDERS is a list of list where each sublist should start from the appender type and arguments for it's constructor.

Supported appenders are:

  • THIS-CONSOLE corresponds to LOG4CL:THIS-CONSOLE-APPENDER class.
  • DAILY corresponds to LOG4CL:DAILY-FILE-APPENDER class.
  • FILE corresponds to LOG4CL:FILE-APPENDER.

To lookup supported arguments for each appender type, see these classes initargs. the only difference is that :LAYOUT argument is processed in a special way: :JSON value replaced with log4cl-extras/json:json-layout and :PLAIN is replaced with log4cl-extras/plain:plain-layout.

And finally, you can pass to setup a list of loggers. Each item in this list should be plist where first item is a symbolic name of a package or a function name inside a package and other items are params for a nested setup call.

Layouts

class log4cl-extras/plain:plain-layout (layout)

class log4cl-extras/json:json-layout (layout)

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.

macro log4cl-extras/context:with-fields (&rest fields) &body body

Captures content of given fields into a dynamic variable.

These fields will be logged along with any log entry inside the with-fields body.

function log4cl-extras/context:get-fields

Returns an alist of all fields defined using with-fields macro in the current stack.

Keys are returned as downcased strings, prepared for logging.

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

variable log4cl-extras/error:*max-traceback-depth* 10

Keeps default value for traceback depth logged by with-log-unhandled macro

variable log4cl-extras/error:*max-call-length* 100

The max length of each line in a traceback. It is useful to limit it because otherwise some log collectors can discard the whole log entry.

variable log4cl-extras/error:*args-filters* nil

Add to this variable functions of two arguments to change arguments before they will be dumped as part of the backtrace to the log.

This is not a special variable, because it should be changed system-wide and can be accessedd from multiple threads.

variable log4cl-extras/error:*args-filter-constructors* nil

Add to this variable functions of zero arguments. Each function should return an argument filter function suitable for using in the *args-filters* variable.

These constructors can be used to create argument filters with state suitable for processing of a single backtrace only. For example, log4cl-extras/secrets:make-secrets-replacer function, keeps tracks every secret value used in all frames of the backtrace. We don't want to keep these values forever and to mix secrets of different users in the same place. Thus this function should be used as a "constructor". In this case it will create a new secret replacer for every backtrace to be processed.

macro log4cl-extras/error:with-log-unhandled (&key (depth *max-traceback-depth*) (errors-to-ignore nil)) &body body

Logs any ERROR condition signaled from the body. Logged message will have a "traceback" field.

You may specify a list of error classes to ignore as ERRORS-TO-IGNORE argument. Errors matching (typep err ) will not be logged as "Unhandled".

function log4cl-extras/error:print-backtrace &key (stream *debug-io*) (condition nil) (depth *max-traceback-depth*) (max-call-length *max-call-length*) (args-filters (get-current-args-filters)) (format-condition #'format-condition-object)

A helper to print backtrace. Could be useful to out backtrace at places other than logs, for example at a web page.

This function applies the same filtering rules as with-log-unhandled macro.

By default condition description is printed like this:

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

But you can change this by providing an argument FORMAT-CONDITION. It should be a function of two arguments: (stream condition).

function log4cl-extras/error:make-args-filter predicate placeholder

Returns a function, suitable to be used in *args-filters* variable.

Function PREDICATE will be applied to each argument in the frame and if it returns T, then argument will be replaced with PLACEHOLDER.

class log4cl-extras/error:placeholder ()

Objects of this class can be used as replacement to arguments in a backtrace.

They are printed like #<some-name>.

This form was choosen to match the way how SBCL shows unused arguments: #<unused argument>.

Placeholders should be created with make-placeholder function.

function log4cl-extras/error:make-placeholder name

Creates a placeholder for some secret value or omitted argument.

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

#<secret value>

See Hard Way section to learn, how to use placeholders to remove sensitive information from logs.

function log4cl-extras/error:placeholder-p obj

reader log4cl-extras/error:placeholder-name (placeholder) (:name)

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

function log4cl-extras/secrets:make-secrets-replacer

Returns a function which can be used to filter backtrace arguments.

Beware, don't add result of the call to make-secrets-replacer to the log4cl-extras/error:*args-filters* variable, because it will collect all secrets and keep them in memory until the end of the program.

Use log4cl-extras/error:*args-filter-constructors* instead, to keep secrets only during the backtrace processing.

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.

class log4cl-extras/appenders:stable-daily-file-appender (dont-disable-mixin daily-file-appender)

class log4cl-extras/appenders:stable-file-appender (dont-disable-mixin file-appender)

class log4cl-extras/appenders:stable-this-console-appender (dont-disable-mixin this-console-appender)

class log4cl-extras/appenders:dont-disable-mixin ()

variable log4cl-extras/appenders:*debug-on-error* nil

When T, then INVOKE-DEBUGGER will be called in case of any error during logging the message.

[generated by 40ANTS-DOC]

Dependencies (18)

  • 40ants-asdf-system
  • alexandria
  • ci
  • cl-hamcrest
  • cl-str
  • cl-strings
  • dissect
  • doc
  • docs-builder
  • global-vars
  • jonathan
  • local-time
  • log4cl
  • named-readtables
  • pythonic-string-reader
  • rove
  • secret-values
  • with-output-to-stream

Dependents (8)

  • GitHub
  • Quicklisp