Logging - Clojure logging with Logback and SLF4J plus request correlation across servers
Dependencies
Mostly, we set up the dependencies so that clojure.tools.logging, uses SLF4J and Logback.
We also include the shim library that converts Apache Commons Logging to use SLF4J as well.
Setup
The namespace io.aviso.logging.setup performs all the necessary setup; it installs pretty exception reporting for console output and commons logging output, as well as a default uncaught exception handler (that logs the uncaught exception).
Simply have some part of your application require this namespace.
Request Correlation
Ever try to trace a request from a client through a cluster of services? Even if you can get all the logs in one place, how do you pick out the single thread of requests and responses from all the other requests and responses?
With request correlation, each request gets assigned a correlation id on entry to the system. When one server sends a request to another server, it includes the correlation id as a header on the request.
That, plus a little bit of logic in your Logback configuration, allows every request to be flagged.
Request Correlation Middleware
The function io.aviso.logging.correlation/wrap-with-request-correlation is a Ring middleware function; it is passed a Ring request handler and wraps it.
On each request, the request correlation id is extracted, or generated if not present. By default, the correlation id comes from the Correlation-Id header, and is generated as a random UUID if not present.
In addition, the io.aviso.logging.correlation/*correlation-id* Var is bound to the correlation id. This little bit of semi-global state can be used when making requests to other servers, to include the correlation id in the request.
Logging the Correlation Id
The final piece of the puzzle is to get the correlation id logged. this is accomplished by making the correlation id a mapped diagnostic context.
In your logback.xml (or logback-test.xml):
<appender name="SETUP-CORR-ID" class="io.aviso.logging.CorrelationIdAppender"/>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%date{HH:mm:ss.SSS} %mdc{correlation-id} %-5level [%thread] %logger{} - %msg%n</pattern>
</encoder>
</appender>
<root level="info">
<appender-ref ref="SETUP-CORR-ID"/>
<appender-ref ref="STDOUT"/>
</root>The CorrelationIdAppender is used to set up the correlation id into the MDC (the mapped
diagnostic context).
After that, the %mdc{correlation-id} form can extract that value and include it in the
logged output.
Extra MDC
Version 0.2.0 adds a generalization of request correlation; an arbitrary map of keys and values can be added to the MDC.
This takes the form of a new appender class, io.aviso.logging.ExtraMDCAppender:
<appender name="SETUP-MDC" class="io.aviso.logging.ExtraMDCAppender"/>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%date{HH:mm:ss.SSS} %mdc{authenticated} %-5level [%thread] %logger{} - %msg%n</pattern>
</encoder>
</appender>
<root level="info">
<appender-ref ref="SETUP-MDC"/>
<appender-ref ref="STDOUT"/>
</root>In the above example, authenticated is presumably a value that may be bound into the
extra-mdc var.
A macro, with-mdc, makes it easy to binding new keys and values into the extra MDC.
Logback’s message diagnostic map is mutable and designed to be inherited by
sub-threads in a way that overlaps with Clojure’s inheriting of dynamic vars.
Because of this, a value stored into the MDC is "sticky" and may leak into
later logging on the thread, even after exiting the with-mdc block.
The best solution for this is to always set a default for any key
that may be added inside a with-mdc block:
(require '[io.aviso.logging.mdc :refer [set-mdc-default with-mdc]
'[clojure.tools.logging :as l])
(set-mdc-default {:authenticated "none"})
(with-mdc {:authenticated "http"}
...
(l/info "Handling request")
... )Although the "authenticated" key will have value "https"
in the Logback MDC even after exiting from the with-mdc block,
any subsequent logging will reset it back to the default, "none".
