cl-grip -- Logging System for Common Lisp

Overview

cl-grip is a high-level logging system for Common Lisp, focusing on a clear user interface, support for flexible structured logging, and easy extensibility for different backends to support direct logging to various inputs.

Concepts

Levels

Grip represents levels of messages as a number between 1 and 100, with "named levels" occurring at intervals of 10. The levels are defined as constants in the grip.level package. The named levels are:

• trace
• debug
• info
• notice
• warning
• error
• critical
• alert
• emergency

Loggers posses a "threshold" level and only messages with levels greater than or equal to the threshold.

Messages

Messages wrap data sent to the logger and contain additional metadata used in the production of log messages. Grip's core provides a simple "string" log message that wraps strings, as well as a "structured" message type that wraps simple alist/plist and hashmaps.

The following generic functions control message creation and behavior:

• loggable-p
• export-message
• make-message
• resolve-output

Loggers

Loggers store configuration and state related to the delivery of log messages, in the case of loggers that write to streams, this may a reference to the stream itself, or may include a message buffer, or credentials to an external service. The primary implementation is the stream-journal which writes all messages to the provided stream, standard output by default, or perhaps a file. There is also a base-journal which is used as a base class, and unconditionally prints log lines to standard output. The merged-journal stores a vector of other journals, and has a send-mesage method that distributes messages to all loggers.

The following generic functions control logger behavior:

• send-message delivers the message to the configured output, if the message is logable.
• format-message formats the entire log line.
• log> send a message at a specific log level. There are implementations that take base-message implementations others that use make-message to convert to a message type.

By convention send-message should call format-message (which can in turn call resolve-message).

There are also a collection of methods on (logger message) for each log level that are implemented generically in terms of log>, they are:

• trace>
• debug>
• info>
• notice>
• warning>
• error>
• critical>
• alert>
• emergency>

Formatters

Loggers hold a separate formating object which is responsible for configuring the output format of log lines. These objects hold configuration and are passed to the following generic functions:

• resolve-output is responsible for formating the output of the logging payload.
• format-message is responsible for formating the entire log message, typically by calling resolve-output, but also has access to the logger itself, and may attach some additional metdata (e.g. the log level and logger name.)

Use

Core Logging Functionality

The core "grip" system has very few external dependencies, and a secondary "ext" system contains implementations that rely on other external libraries, which you can opt into as needed.

By default you can load the grip package and begin using the logging methods without further configuration: there is a default logger configured so that the following operations will work: :

(grip:info> "log message")

To send structured data: :

(grip:info> '(:msg "hello"
         :value 100))

 (let ((msg (make-hash-table :test #'string=)))
   (setf (gethash "message" msg)  "test message")
   (setf (gethash "value" msg)  val)
   (eel "value" "value")

   (grip:error> msg))

In the more advanced case, you can set up your own logger and populate the *default-logger* variable in the grip package, as in: :

(setf grip:*default-logger* (make-instance 'grip.logger:stream-journal :name "example" :output-target *error-output*))

At this point, you can use the default logging methods which will now send standard error. Alternately, you can define a logging instance and store it centerally (or pass it around) and pass it directly to logging methods, as in: :

(let ((logger (make-instance 'grip.logger:stream-journal :name "example" :output-target *error-output*)))
  (grip.logger:info> logger "hello world"))

You can easily pass strings, association lists, property lists, hash-tables, or any type that implements the export-message method. Additionally, the new-message function, which is exported from the grip package, is useful for creating messages, and provides a few useful additional options:

• To produce with a formatted string content, you can use one of the following forms: :

  (new-message "hello {{name}}, welcome to {{place}}" :args '(("name" . "kip") ("place". "grip")))
  (new-message "hello ~A, welcome to ~A" :args '("kip" "grip"))

  Will produce a message that is formated with substitutions. The first form, using alists, uses double-brace substitution (using cl-strings), and the second form uses standard format macro formatting. This type, for whatever it's worth defers string processing until the message is logged, at which point the resolved message is cached, which may be more efficient for longer strings with multiple outputs as well as in cases where messages may not be logged.

• To modify the conditional flag in a message (or :when argument to the message constructor), which will prevent it from being logged. Use this to avoid wrapping your logging statements in when blocks. :

  (new-message "hello kip!" :when (should-log (now)))

• To define the level when creating the message, which is also available using make-message, to facilitate passing messages directly to log>. The default level value is +debug+ but this is optional, and safely set to the correct level when using a log level method. :

  (new-message "hello kip!" :level +info+)

Advanced Features

In addition to common workflows, cl-grip contains a few additional or non-obvious featres that might be interesting for some use-cases:

JSON Formatting

The grip.ext.json package includes two formatters that produce JSON formatted output:

• json-simple-formatter does not annotate messages or add any metadata to the output, but sends messages in a JSON format.
• json-metadata-formatter adds a metadata field holding a JSON object with three fields: time, level, and logger name.

To use, just create and set the relevant object, as in the following: :

(setf (message-formatter *default-journal*) (make-instance 'json-meatadata-formatter))
(setf (message-formatter *default-journal*) (make-instance 'json-simple-formatter))

You can also construct a logger and pass the :format initarg, as in: :

(make-instance 'stream-journal
   :name "grip"
   :threshold +info+
   :format (make-instance 'json-metadata-formatter)
   :output-target *standard-output)

Merged Output Targets

The core merged-journal implementation provides support for a kind of tee'd output pattern where the same log messages are dispatched to more than one output target. Often it makes sense to send output to some kind of centralized log storage system (perhaps on a buffer), while also mirroring those messages locally in some form.

The method merge-journals will take any two journal implementations and create a merged output. There implementations to support merging outputs into an existing mergered journal, or merging two other journals.

Buffered Output

The grip.ext.buffer package provides an output target that buffers messages dispatched to an underlying sender for a defined interval or maximum number of messages. To use, create an instance as follows: :

(make-instance 'buffered-journal
   :journal (make-instance 'base-journal)
   :size 500
   :interval (local-time-duration:duration :sec 15))

The only required initform is journal, size defaults to 100, and the interval defaults to 10 seconds.

The implementation uses chanl to handle the background processing, and is likely to perform poorly on particularly low-volume workloads. Messages are sent to the journal wrapped in batches.

Batched Messages

In the grip.message package there is a batch-message class, with the accompanying merge-messages generic function that should make it possible to combine groups of messages in a single "batch". There's fallback behavior that will unwindind and "send" each of the constituent messages individually. The implementations of merge-messages make batches easy to construct: :

(merge-messages (make-message +info+ "one") (make-message +info+ "two"))

(let ((batch (make-instance 'batch-message')))
   (merge-messages batch (make-message +info+ two)))

You can also use merge-messages to merge two batches (the messages from the smaller batch are added to the larger batch,) and there are implementations to passing the arguments in the opposite order.

The concept is that a batch of messages may make it easier for output implementations to take advantage of bulk delivery methods, which are more efficient at scale, particularly for output targets that might have some kind of rate limiting. Internally, batch-messages are used by the buffered-journal.

Extension

Grip's design privileges extensibility and simple . Message formatting, line formating, output targets, and even logger behavior should be easy to override and customize. This section will cover what classes you need to create and methods you should implement.

Output Targets

To write log data to a different output:

• subclass grip.logger:base-journal, to store the configuration and state of your logger, and
• specialize the generic function grip.logger:send-message to declare how messages would be delivered.

Consider the following implementation, from the tests tests for a logger that just stores messages in a vector: :

(defclass in-memory-journal (base-journal)
  ((output-target
    :initform (make-array 0 :adjustable t :fill-pointer t)
    :reader output-target))
  (:documentation "a basic logger with similar semantics to the basic
  journals but that saves "))

(defmethod send-message ((logger in-memory-journal) (msg grip.message:base-message))
  (when (loggable-p msg (threshold logger))
    (vector-push-extend msg (output-target logger))
    (format-message logger (message-formatter logger) msg)))

You can choose to specialize other methods, including format-message, which takes the logger as an argument, and any of the grip.logger logging methods (e.g. those that end in >,) but that is optional.

Message Formatting

There are two formating and message processing stages, first the resolve-output message process the content or payload of the message, while the format-message calls resolve-output and packages additional information into message. In the default case, format-message is responsible for adding the name of the logger, the timestamp, and the log level.

The base-journal implementation has a formater slot that holds a message format configuration object, which is passed to both formatting functions, so that loggers can configure how messages are output.

Development

Grip is available under the terms of the Apache v2 license.

Please feel free to create issues if you experience a problem or have a feature request. Pull requests are particularly welcome and encouraged!

Workflow Suggestions

• I suggest checking out this repository in your ~/quicklisp/local-projects/ directory (or equivalent). To run coverage tests you will want also make this available in ~/.roswell/local-projects/tychoish/cl-grip` (I use symlinks for these operations.)
• To run tests, you can either run them interactively in SLIME, or use the make test target in the makefile. I prefer SLIME for interface for development purposes, but the makefile is useful for validating the tests in a clean environment.
• A make coverage target exists to produce a coverage report in report/cover-index.html directory. This target depends on having rove in the PATH which you can achieve by ros install fukamachi/rove.

Guidelines

In general, consider the following guidelines:

• grip aims to have full test coverage, particularly for the core system, although this isn't always practical. Do write tests! If you have trouble figuring out how to test a feature, or a change in a pull request, don't worry and we can work that out later.
• limit the number of dependencies in the core package. If you want to write a logger that
• grip uses a single package per file model. at this time, and attempts to limit the number of exported symbols per package.

While there is not a strong roadmap or timeline for grip, if you're interested in contributing to grip but don't know where to start, the following features or areas might be a good place to start:

• benchmarking: while the implementation is straight forward, it would be nice to know what kind of overhead the logging infrastructure takes, and some kind of benchmarking would be useful in determining the impact of changes.
• logging output targets. There are a number of potential logging/messaging output formats that could be interesting:
  • (ext) logging directly to splunk, probably using their HEC and some kind of message batching.
  • (ext) logging directly to the SumoLogic service, which should be broadly similar to splunk, but would require a separate implementation.
  • (ext) output implementations targeting "alerting workloads" including XMPP, slack, email, and webhook delivery.
• message handling improvements:
  • (core) extending the structured-message and make-message handlers to do better with additional input types.
  • (ext) improve the automatic metadata collection and population for structured messages, both during message collection and also by configuring formatters.
  • (core) provide easier helpers for creating arbitrary structured messages. Perhaps a with-message macro or similar.
  • (ext) message implementations and tooling that collect data about the application state.
• implementation of a stream object which wraps a logger implementation, using trivial gray streams to facilitate using a logger in APIs that rely on a stream (like output of a file.)