- Description: A bunch of addons to
LOG4CL:JSONappender, 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
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)
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 theREPL.:JSON- a layout which outputs each message and all it's data as aJSONdocuments. 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-CONSOLEcorresponds toLOG4CL:THIS-CONSOLE-APPENDERclass.DAILYcorresponds toLOG4CL:DAILY-FILE-APPENDERclass.FILEcorresponds toLOG4CL: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.
class log4cl-extras/plain:plain-layout (layout)
class log4cl-extras/json:json-layout (layout)
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.
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"
}
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.
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)
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.
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!
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
HTTPheader 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.
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.