LOG4CL-EXTRAS - Addons for Log4CL
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 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
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.
Captures content of given fields into a dynamic variable.
These fields will be logged along with any log entry
+inside the with-fields body.
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
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.
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.
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.
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".
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).
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.
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.
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.
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:
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.
When T, then INVOKE-DEBUGGER will be called in case of any error during logging the message.
+
