Just enough Clojure data logging with Logback and LogstashEncoder

logback.xml

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE configuration>

<configuration debug="true">
    <import class="ch.qos.logback.core.ConsoleAppender"/>
    <import class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"/>
    <import class="ch.qos.logback.core.rolling.RollingFileAppender"/>
    <import class="ch.qos.logback.classic.filter.ThresholdFilter"/>
    <import class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"/>
    <import class="net.logstash.logback.encoder.LogstashEncoder"/>

    <appender name="STDOUT" class="ConsoleAppender">
        <encoder class="PatternLayoutEncoder">
            <pattern>%date %-5level [%thread] %logger{20} - %msg {%mdc}%n</pattern>
        </encoder>
    </appender>

    <appender name="stash" class="RollingFileAppender">
        <filter class="ThresholdFilter">
            <level>info</level>
        </filter>
        <file>logs/stash.log</file>
        <rollingPolicy class="TimeBasedRollingPolicy">
            <fileNamePattern>logs/stash.%d{yyyy-MM-dd}.log.gz</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder class="LogstashEncoder" />
    </appender>

    <logger name="kws.api" level="debug"/>

    <root level="info">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="stash"/>
    </root>
</configuration>

logging.clj

(ns kws.api.tools.logging
  (:require
   [clojure.tools.logging :as log]
   [clojure.tools.logging.impl :as log-impl])
  (:import (org.slf4j MDC)))

(defn mdc-put
  "Puts given value under given key in the current MDC."
  [k v]
  (when (some? k) (MDC/put (name k) (str v))))

(defn mdc-remove
  "Removes given key from the current MDC."
  [k]
  (when (some? k) (MDC/remove (name k))))

(defn mdc-put-all
  "Puts all entries of given map into the current MDC.
   Keys with null values are removed from the current MDC."
  [m]
  (when-let [m (not-empty m)]
    (doseq [e m]
      (if-some [v (val e)]
        (mdc-put (key e) v)
        (mdc-remove (key e))))))

(defn mdc-remove-all
  "Removes all entries of given map from the current MDC."
  [m]
  (when-let [m (not-empty m)]
    (doseq [k (keys m)]
      (mdc-remove k))))

(defmacro with-context
  "Wraps a body of expressions with a given map of data in the current MDC."
  [ctx & body]
  `(let [ctx# ~ctx]
     (if (not (map? ctx#))
       (throw (IllegalArgumentException. "with-context requires a map"))
       (try
         (mdc-put-all ctx#)
         ~@body
         (finally
           (mdc-remove-all ctx#))))))

(defn mdc-propagate
  "Returns a new function from a given function f.
   This new function will run with a copy of the current MDC."
  [f]
  (let [ctx (MDC/getCopyOfContextMap)]
    (fn [& args]
      (when ctx (MDC/setContextMap ctx))
      (apply f args))))

(defmacro log*
  [logger level msg & {:as m}]
  `(let [m# ~m
         ex# (:exception m#)
         ctx# (if ex# (dissoc m# :exception) m#)]
     (mdc-put-all ctx#)
     (if (instance? Throwable ex#)
       (let [xdata# (ex-data ex#)]
         (when xdata# (mdc-put-all xdata#))
         (log/log* ~logger ~level ex# ~msg)
         (when xdata# (mdc-remove-all xdata#)))
       (log/log* ~logger ~level nil ~msg))
     (mdc-remove-all ctx#)))

(defmacro log
  "Logs a message and keyvals at the given log level."
  ([level msg]
   `(log/log ~level ~msg))
  ([level msg & keyvals]
   `(let [logger# (log-impl/get-logger log/*logger-factory* ~*ns*)]
      (when (log-impl/enabled? logger# ~level)
        (log* logger# ~level ~msg ~@keyvals)))))

(defmacro trace
  "Logs a message and keyvals at :trace level."
  [msg & keyvals]
  `(log :trace ~msg ~@keyvals))

(defmacro debug
  "Logs a message and keyvals at :debug level."
  [msg & keyvals]
  `(log :debug ~msg ~@keyvals))

(defmacro info
  "Logs a message and keyvals at :info level."
  [msg & keyvals]
  `(log :info ~msg ~@keyvals))

(defmacro warn
  "Logs a message and keyvals at :warn level."
  [msg & keyvals]
  `(log :warn ~msg ~@keyvals))

(defmacro error
  "Logs a message and keyvals at :error level."
  [msg & keyvals]
  `(log :error ~msg ~@keyvals))

(defmacro fatal
  "Logs a message and keyvals at :fatal level."
  [msg & keyvals]
  `(log :fatal ~msg ~@keyvals))

usage.clj

;; Example API usage

;; Pros:
;;   - Easy logstash usage
;;   - Easy configuration with logback.xml (ex: only messages higher than debug go to json file)
;;   - Simple API with message and key-values
;;   - Show ex-data key-values

;; Cons:
;;   - Uses "flat" Slf4j MDC string for key-values, so everything is a string in json file


(info "hello")
;; (text) => hello {}
;; (json) => {"message":"hello", ...}


(info :server/start)
;; (text) => :server/start {}
;; (json) => {"message":":server/start", ...}


(info "hello" :exception (ex-info "boom" {}))
;; (text) => "hello {}"
;;           [...stacktrace]
;; (json) => {"message":"hello", "stack_trace":"[...]", ...}


(info :server/start :port 80 :timeout 800)
(info :server/start :port 80 {:timeout 800})
(info :server/start {:port 80 :timeout 800})
;; (text) => :server/start {port=80, timeout=800}
;; (json) => {"message":":server/start", "port":"80", "timeout":"800", ...}


(info :client/by-id :user-id 123 :exception (ex-info "boom" {:status 500}))
;; (text) => :client/by-id {user-id=80, status=500}
;;           [...stacktrace]
;; (json) => {"message":":client/by-id", "user-id":"123", "status":"500",
;;            "stack_trace":"[...]", ...}


(with-context {:user-id 12}
  (info :client-order/by-id :order-id 74))
;; (text) => :client-order/by-id {user-id=12, order-id=74}
;; (json) => {"message":":client-order/by-id", "user-id":"12", "order-id":"74", ...}

(with-context {:user-id 11}
  ;; MDC is not propagated to other threads!
  @(future-call #(info :call/back :r 1)))
;; (text) => :call/back {r=1}
;; (json) => {"message":":call/back", "r":"1", ...}

(with-context {:user-id 11}
  ;; explicitly propagate MDC to an other thread
  @(future-call (mdc-propagate #(info :call/back :r 1))))
;; (text) => :call/back {r=1, user-id=11}
;; (json) => {"message":":call/back", "r":"1", "user-id":"11", ...}