Although Verbose is one of few logging libraries that work with threaded applications (See Comparison of Common Lisp Logging Libraries), I had some trouble getting it to work in my application. I have a Hunchentoot web application which handles each request in a separate thread that is built as a standalone executable. Getting Verbose to work in Slime was trivial but once I built the standalone, it kept crashing.

The Verbose documentation provides all the information needed to make this setup work but not in a step-by-step fashion so this took me some time to figure out.

To work with threaded applications Verbose must run inside a thread of its own. It tries to make life easier for the majority case by starting its thread as soon as it is loaded. Creating a standalone application requires that the running lisp image contains only a single running thread. The Verbose background thread prevents the binary from being built. This can be remedied by preventing Verbose from immediately starting its background thread and then manually start it inside the application.

When Verbose is loaded inside Slime it prints to the REPL’s *standard-output* without fuss but when I loaded it inside my standalone binary it caused the application to crash. I did not investigate the *standard-output* connection logic but I discovered that you must tell Verbose explicitly about the current *standard-output* in a binary otherwise it won’t work.

Steps:

  1. (pushnew :verbose-no-init *features*)

    This feature must be set before the Verbose system is loaded. It prevents Verbose from starting its main background thread, which it does by default immediately when it is loaded.

    I added this form in the .asd file immediately before my application system definition. While executing code inside the .asd file is considered bad style it provided the cleanest way for me to do this otherwise I would have to do it in multiple places to cover all the use cases for development flows and building the production binary. There may be a better way to set *features* before a system is loaded but I have not yet discovered it.

  2. (v:output-here *standard-output*)

    This form makes Verbose use the *standard-output* as it currently exists. Leaving out this line was the cause of my application crashes. I am not sure what the cause is but I suspect Verbose tries to use Slime’s version of *standard-output* if you don’t tell it otherwise, even when it is not running in Slime.

    This must be done before starting the Verbose background thread.

  3. (v:start v:*global-controller*)

    Start the Verbose background thread.

  4. (v:info :main "Hello world!")

    Start logging.

I use systemd to run my applications. Systemd recommends that applications run in the foreground and print logs to the standard output. The application output is captured and logged in whichever way systemd is configured. On default installations this is usually in /var/log/syslog in the standard logging format which prepends the timestamp and some other information. Verbose also by default prints the timestamp in the logged message, which just adds noise and makes syslog difficult to read.

Verbose’s logging format can be configured to be any custom format by subclassing its message class and providing the proper formatting method. This must be done before any other Verbose configuration.

Combining all the code looks like below.

In app.asd:

(pushnew :verbose-no-init *features*)

(defsystem #:app
  ...)

In app.lisp:

(defclass log-message (v:message) ())

(defmethod v:format-message ((stream stream) (message log-message))
  (format stream "[~5,a] ~{<~a>~} ~a"
          (v:level message)
          (v:categories message)
          (v:format-message NIL (v:content message))))

(defun run ()
  (setf v:*default-message-class* 'log-message)
  (v:output-here *standard-output*)
  (v:start v:*global-controller*)
  (v:info :main "Hello world!")
  
  ...)