Skip to content

Latest commit

 

History

History
117 lines (89 loc) · 3.98 KB

0136-log4cl-extras.org

File metadata and controls

117 lines (89 loc) · 3.98 KB
Raw

log4cl-extras

Yesterday I’ve posted about the log4cl and promised to tell you about my addons. The library is called log4cl-extras.

The main purpose of log4cl-extras is to make logging suitable for production. It provides JSON formatter, a macro to capture context variables and a macro to log unhandled tracebacks.

Capturing context variables makes each log entry self-sustained. Also, this way you can use do a “request_id” trick to bind many related log messages into a single track.

To show you how does “request_id” trick works, let me create a simple Clack application which will handle a request, simulate the query to the database and use logging.

Pay attention how does it use log4cl-extras/context:with-fields to capture request-id variable:

POFTHEDAY> (defun get-current-user ()
             "This is a fake function simulating SQL queries to database."
             (log:debug "SELECT * FROM users WHERE ...")
             (values "Bob"))

POFTHEDAY> (defun handle-request (env)
             (let* ((headers (getf env :headers))
                    (request-id (or (gethash "x-request-id" headers)
                                    (format nil "~A" (uuid:make-v4-uuid)))))
               (log4cl-extras/context:with-fields (:request-id request-id)
                 (log:debug "Processing request")
                 (let ((user (get-current-user)))
                   (list 200 '(:content-type "text/plain")
                         (list (format nil "Hello ~A!" user)))))))

POFTHEDAY> (defparameter *server*
             (clack:clackup 'handle-request
                            :port 8081))
Hunchentoot server is started.
Listening on 127.0.0.1:8081.

Now we can initialize logging and make a few HTTP requests:

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

POFTHEDAY> (dex:get "http://localhost:8081/")
<DEBUG> [2020-07-20T23:23:28.293441+03:00] Processing request
  Fields:
    request-id: 0E0D035A-B24F-4E69-806C-ACACE6C6B08E
<DEBUG> [2020-07-20T23:23:28.295783+03:00] SELECT * FROM users WHERE ...
  Fields:
    request-id: 0E0D035A-B24F-4E69-806C-ACACE6C6B08E
"Hello Bob!"

Our app is able to use request id passed as an HTTP header X-Request-ID. This is useful when you have many microservices and want to have a single trail of all their logs:

POFTHEDAY> (dex:get "http://localhost:8081/"
                    :headers '(("X-Request-ID" . "Custom ID :)))))")))
<DEBUG> [2020-07-20T23:29:04.123354+03:00] Processing request
  Fields:
    request-id: Custom ID :)))))
<DEBUG> [2020-07-20T23:29:04.123412+03:00] SELECT * FROM users WHERE ...
  Fields:
    request-id: Custom ID :)))))
"Hello Bob!"

This plain text log format is convenient when you are debugging the application. But in production you either want to grep log messages or to feed them to the Elastic Search for further indexing.

In both cases it is more convenient to write each messages as a single-line JSON object:

POFTHEDAY> (log4cl-extras/config:setup
            '(:level :debug
              :appenders ((this-console :layout :json))))

POFTHEDAY> (dex:get "http://localhost:8081/")
{"fields":{"request-id":"20A7..."},"level":"DEBUG","message":"Processing request","timestamp":"2020-07-20T23:32:34.566029+03:00"}
{"fields":{"request-id":"20A7..."},"level":"DEBUG","message":"SELECT * FROM users WHERE ...","timestamp":"2020-07-20T23:32:34.566167+03:00"}
"Hello Bob!"

log4cl-extras also contains a macro to capture unhandled errors along with their tracebacks. It is also very useful for production. I’m using this facility to capture errors in Ultralisp.org.

Read log4cl-extra’s documentation to learn more:

https://github.com/40ants/log4cl-extras