Logging

A critical part of Pedestal is how it performs logging.

SLF4J

At the core, Pedestal builds upon the Simple Logging Facade for Java. This facade is an abstraction over several different libraries used for logging, such as Logback, Apache Log4j or the built-in java.util.logging packages.

As part of your application’s dependencies, you can include an adapter to your preferred logging library (see the notes on such dependencies).

If you fail to include any such library, you will see the following warning:

user=> (require '[io.pedestal.log :as l])
SLF4J: No SLF4J providers were found.
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See https://www.slf4j.org/codes.html#noProviders for further details.

Without a logging adapter, all logging is a no-op. You should include a logging adapter, even if just for testing.

Events, Not Strings

Pedestal departs from many Java and even Clojure logging frameworks in that it’s core approach is to log events, not strings. These events are in the form of a Clojure map.

The intent is that logging in one program can be a source of data for another. Although this kind of thing is possible when logging output is primarily formatted for human readability, doing so in practice often involves reams for special rules and regular expressions - with Pedestal, it is very straight-forward to isolate the Clojure map and then parse it as EDN data.

Logging macros

The central macros in the io.pedestal.log namespace are trace, debug, info, warn, and error. These macros are responsible for obtaining a LoggerSource instance based on the namespace name (unless overridden) and converting the passed keys and values into a Clojure map, which is printed to a string and logged as the event message.

Added to the map is the extra key, :line, which identifies the line number in the source.

Bear in mind that often, Java libraries do their own logging, and that logging will not be formatted as Clojure maps.

It is common for loggers to add an :in key, whose value is symbol identifying the function containing the logging call.

Example:

(ns org.example.routes
  (:require [io.pedestal.log :as l]) ...

    ...
    (l/debug :in 'auth :user-id user-id :roles user-roles)
    ...

Sample logging output:

DEBUG org.example.routes - {:in auth, :user-id "3d1535dd-18fa-40f1-95f8-78d7f44b0319", :roles #{"buyer" "admin" "manager"}, :line 37}

Note that the order of keys in the map is not specified.

The use of macros, not functions, ensures that logging is efficient. The code emitted by the macro always checks to see if logging is enabled for the logger; when it is not, no further work occurs - the expressions passed to the macro are not evaluated.

Exceptions

A common case when logging is to log caught exceptions; the exception is specified with the :exception key, and the value must be some kind of java.lang.Throwable, though it’s generally an instance of java.lang.Exception.

   (try
     ...
     true
     (catch Exception e
       (l/error :in 'processor :exception e)
       false))

Other special keys

Table 1. Other special keys used with logging macros
Key	Value
:io.pedestal.log/logger	The logger instance to use, rather than the default. The logger must satisfy the `LoggerSource` protocol. The default is a logger with name matching the namespace.
:io.pedestal.log/formatter	A function that can be passed an event map and return a string used when logging (the underlying logging APIs expect a string message). The default is `pr-str` (via `default-formatter`).

spy macro

The spy macro takes an expression, evaluates it, and returns it. Before returning, it logs the expression (as key :spy) and the result (as key :value) at debug level. This is often useful during REPL-driven development.

Overriding the LoggerSource

The logging functionality is itself pluggable; what Pedestal supplies out of the box is an adapter for SLF4J in the form of a LoggerSource protocol, extended onto SLF4J’s org.slf4j.Logger interface.

If you wish to use pedestal-log with a different logging library, you may specify an override for the logger source; this is a function that is passed a logger name string, and returns an instance that extends LoggerSource.

The override can be specified as the fully qualified name of a Clojure function, either via system property io.pedestal.log.overrideLogger or by environment variable PEDESTAL_LOGGER.

Overriding the default event formatter

By default, log event data is formatted to a string using pr-str (this default is provided by default-formatter), before being passed (via the methods of the LoggerSource protocol) to the underlying logging implementation.

However, this can be overridden, which is useful for:

Identifying and removing or redacting personal data that should not be logged
Formatting the log output in a particular way, such as formatting as JSON rather than EDN

The system property io.pedestal.log.formatter, or environment variable PEDESTAL_LOG_FORMATTER, can specify a fully qualified function name; this function is passed the event map and returns a string, and will be used instead of pr-str as the default when the :io.pedestal.log/formatter key is not provided.

Mapped Diagnostic Context (SLF4J)

The MDC is a feature of SLF4J that is mapped onto different logging implementations, just like the Logger. An SLF4J MDC is essentially a map of string keys and string values stored as per-thread global state.

The SLF4J MDC is useful for storing additional values that should be logged; a common example is a request correlation id.

When setting up the format for logging, an additional directive is used to output the MDC. For example, when using ch.qos.logback.core.ConsoleAppender, the %msg pattern outputs the message string (the printed version of the Clojure event map); the %X pattern is used to print out individual keys in the MDC.

Pedestal has its own MDC, as a dynamic var.

The default behavior is for the Pedestal MDC map to be formatted (as with an event map) and stored into the MDC using the key "io.pedestal". Thus the pattern %X{io.pedestal} will print out that Pedestal MDC.

The macro with-context and allows values to bound to the Pedestal MDC, which are then copied into the "io.pedestal" key of the SLF4J MDC; at the end of the block, the prior state of the SLF4J and Pedestal MDCs are restored.

Be careful about using the SLF4J MDC when using core.async or any kind of thread pool; the MDC is stored per-thread, and there isn’t an easy way to copy its value over to arbitrary new threads.

Table 2. Special Keys used with `with-context`
Key	Value
:io.pedestal.log/mdc	The MDC to use, which must implement `LoggingMDC`.
:io.pedestal.log/formatter	A function that can be passed an MDC map and return a string used when setting the `io.pedestal` key of the SLF4J MDC. The default is `pr-str` via `default-formatter`.

Example logback-test.xml

Logback supports overriding a logging configuration file that is used in production with one that is only used in tests - it’s simply a matter of having a file named logback-test.xml on the classpath.

A full production Logback configuration will often set limits on what’s logged, and deal with writing output to timestamped files. For testing and local development, you want to be less selective on logging output, and log to the console.

This is a somewhat minimal example:

<configuration scan="true" scanPeriod="1 seconds">

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%-5level %logger - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="debug">
        <appender-ref ref="STDOUT"/>
    </root>

    <logger name="org.eclipse.jetty" level="warn"/>
    <logger name="io.pedestal" level="warn"/>

</configuration>

Both Jetty and Pedestal can produce quite a bit of debug output, so the sample above disables that logging.

Because the Logback configuration enables file scanning, it can be updated at runtime to enable or disable logging of specific namespaces.