idiomatic logging in clojure

Question

I'm new to clojure and would like to understand the approaches of logging in a clojure, coming from an imperative background. In a java production-program I would usually LOG (debug/info) in start-end of a method, something like that:

public void foo(){
   logger.debug("starting method to embrace %s", rightIdioms);
   doSomething();
   logger.debug("successfully embraced %s idioms", idioms.length);
}

I'm familiar with the pro's/con's of logging and know the tools available for that in clojure,

I can also find some con's of logging in the approach mentioned above, which deepens the tension I feel when logging in none-imperative:

1. logging is a side effect and clojure pushes to no-side-effects.

2. more lines-of-code or 'code-complexity': in java - having big classes is common (getters, setters, constructors), in clojure, expressions return values, logging 'difficults' the process and hardens small functions and namespaces: (one example would be the need to change from if to if-let or if-do to perform a logging):

   (defn foo [x]
     (if (neg? x)
       (inc x)
       x))
   
   (defn foo [x]
     (if (neg? x)
       (let [new-x (inc x)] 
         (logger/debug (format "inc value, now %s" new-x)
         new-x))
       x))
   

I have read logging with clojure/tap or tracing but not sure i fully found it useful.

What are the approaches or the idiomatic way to do logging in clojure?

Answer 1

For bigger projects, with multiple entry/end points and services, I would go with Riemann, as described in a blog post by JUXT.

For single application or a service I would use plaintext logging combined with JSON logging by using Cambium (which provides nice encoders and macros for logging) and Unilog (which allows to configure and start Logback using Clojure data structures).

Logback is a Java thing, a successor of popular Log4j but faster and more flexible, yet with compatible API. Thanks to Unilog there is no need to hand-craft its configuration files in XML format. It's worth reading Logback's documentation to understand Java logging – it even contains an architecture diagram. After 30 minutes the basics will be clear and one can go with Clojure layer.

Here is an example of my configuration with customized JSON encoders (identified as :json-console and :json-log):

(ns io.randomseed.blabla.logging


(:require   [cheshire.core                   :as cheshire]
            [unilog.config                   :as   unilog]
            [cambium.codec                   :as    codec]
            [cambium.core                    :as      log]
            [cambium.mdc                     :as     mlog]
            [logback-bundle.json.flat-layout :as     flat])

  (:import  [logback_bundle.json                 FlatJsonLayout ValueDecoder]
            [ch.qos.logback.contrib.jackson      JacksonJsonFormatter]
            [ch.qos.logback.core.encoder         LayoutWrappingEncoder]
            [ch.qos.logback.contrib.json.classic JsonLayout]
            [java.nio.charset                    Charset])))

(def config
  {:level      :info
   :console    false
   :appenders  [{:appender       :console
                 :encoder        :pattern
                 :pattern        "%p [%d{yyyy-MM-dd HH:mm:ss.SSS Z}] %t - %c %m%n"}
                {:appender       :rolling-file
                 :file           "/home/users/siefca/.blabla/blabla.log"
                 :pattern        "%p [%d{yyyy-MM-dd'T'HH:mm:ss.SSSZ}] %t - %c %m%n"
                 :rolling-policy {:type              :time-based
                                  :max-history                 7
                                  :pattern     ".%d{yyyy-MM-dd}"}}
                {:appender        :rolling-file
                 :file            "/home/users/siefca/.blabla/blabla-json.log"
                 :encoder         :json-log
                 :rolling-policy  {:type             :time-based
                                   :max-history                7
                                   :pattern    ".%d{yyyy-MM-dd}"}}]
   :overrides  {"org.apache.http"      :debug
                "org.apache.http.wire" :error}})

;;
;; JSON should not be stringified when using flat layout
;;

(flat/set-decoder! codec/destringify-val)

;;
;; Cheshire attached to FlatJsonLayout
;; gives more flexibility when it comes
;; to expressing different objects 
;;

(FlatJsonLayout/setGlobalDecoder
 (reify ValueDecoder
   (decode [this encoded-value]
     (cheshire/parse-string encoded-value))))

;;
;; Custom encoders
;;

(defmethod unilog/build-encoder :json-console
  [config]
  (assoc config :encoder (doto (LayoutWrappingEncoder.)
                           (.setCharset (Charset/forName "UTF-8"))
                           (.setLayout  (doto (FlatJsonLayout.)
                                          (.setIncludeMDC                true)
                                          (.setIncludeException          true)
                                          (.setAppendLineSeparator       true)
                                          (.setTimestampFormatTimezoneId "UTC")
                                          (.setTimestampFormat           "yyyy-MM-dd HH:mm:ss.SSS")
                                          (.setJsonFormatter (doto (JacksonJsonFormatter.)
                                                               (.setPrettyPrint true))))))))

(defmethod unilog/build-encoder :json-log
  [config]
  (assoc config :encoder (doto (LayoutWrappingEncoder.)
                           (.setCharset (Charset/forName "UTF-8"))
                           (.setLayout  (doto (FlatJsonLayout.)
                                          (.setIncludeMDC                 true)
                                          (.setIncludeException           true)
                                          (.setAppendLineSeparator       false)
                                          (.setTimestampFormatTimezoneId "UTC")
                                          (.setJsonFormatter (doto (JacksonJsonFormatter.)
                                                               (.setPrettyPrint false))))))))

;;
;; Let's start logging
;;

(unilog/start-logging! config)

Dependencies:

{:deps {logback-bundle/json-bundle                    {:mvn/version "0.3.0"}
        cambium/cambium.core                          {:mvn/version "1.1.0"}
        cambium/cambium.logback.core                  {:mvn/version "0.4.4"}
        cambium/cambium.logback.json                  {:mvn/version "0.4.4"}
        cambium/cambium.codec-cheshire                {:mvn/version "1.0.0"}
        spootnik/unilog                               {:mvn/version "0.7.27"}}}

Answer 2

Few best practices are given in this blog post, it suggestion to log data and not strings could be very useful and fit with clojure-style of logging. a log event could be something like that:

{:service     :user.profile/update
 :level       :debug
 :time        "2020-01-01"
 :description {:before '0
               :after  '1}
 :metric       10ms}

Where metric can be anything, from time the update took, to the number of rows pulled from the db.

Then when you have data, you could do anything with it - analyzing it to gain insights or group-by to search and find. You can always turn the data structure back to a string if needed for console-logging.

Answer 3

I think the best logging library in Clojure at present is Cambium. I think it is a little nicer than its (older) rival Timbre.

To help with program flow when logging or debugging function output, I sometimes use a small with-result macro from the Tupelo Library. For example:

  (is= 42
    (with-result 42
      (spyx (+ 2 3))))

this unit test shows that the result 42 is returned, even though the innermost expression is 5. The spyx debugging tool (short for "spy explicit") prints the following when the test is run:

(+ 2 3) => 5

If you wanted a permanent logging output, use Cambium, for example:

(log/info "Application started")
(log/info {:args (vec args) :argc (count args)} "Arguments received")

with result:

18:56:42.054 [main] INFO  myapp.main - Application started { ns=myapp.main, line=8, column=3 }
18:56:42.060 [main] INFO  myapp.main - Arguments received { args=["foo" "10"], argc=2, ns=myapp.main, line=9, column=3 }

---

I would re-write the function a little to save the final result into a variable, then do the logging in one of the 2 forms:

(ns tst.demo.core
  (:use tupelo.core tupelo.test)
  (:require [cambium.core :as log]))


(defn foo-1 [x]
  (let [result (if (neg? x)
                 (inc x)
                 x)]
    (log/debug (format "foo-1 => %s" result))
    result))

(defn foo-2 [x]
  (let [new-x (if (neg? x)
                (inc x)
                x)]
    (with-result new-x
      (log/debug (format "foo-2 => %s" new-x)))))

(dotest
  (is= 42
    (with-result 42
      (spyx (+ 2 3))))

  (is=  2 (foo-1 2))
  (is= -1 (foo-1 -2))

  (is=  2 (foo-2 2))
  (is= -1 (foo-2 -2))
  )

which yields output:

-------------------------------
   Clojure 1.10.1    Java 13
-------------------------------

Testing tst.demo.core
(+ 2 3) => 5
11:31:47.377 [main] DEBUG tst.demo.core - foo-1 => 2 { ns=tst.demo.core, line=15, column=5 }
11:31:47.378 [main] DEBUG tst.demo.core - foo-1 => -1 { ns=tst.demo.core, line=15, column=5 }
11:31:47.379 [main] DEBUG tst.demo.core - foo-2 => 2 { ns=tst.demo.core, line=23, column=7 }
11:31:47.379 [main] DEBUG tst.demo.core - foo-2 => -1 { ns=tst.demo.core, line=23, column=7 }

Ran 2 tests containing 7 assertions.
0 failures, 0 errors.

For temporary debugging printouts, I'd do it like so:

(defn foo [x]
  (if (neg? x)
    (spyx :foo-inc (inc x))
    (spyx :foo-noop x)))

with test:

  (is=  2 (foo 2))
  (is= -1 (foo -2))

and output

:foo-noop x => 2
:foo-inc (inc x) => -1

---

Sample Project

You can clone the following repo to see how everything is set up:

• https://github.com/io-tupelo/clj-template

Answer 4

The compiled Clojure code is 100% Java code. So, I recommend to use standard Java loggers and Clojure wrappers: log4j2 (java) + pedestal.log (Clojure). This approach allows to mix java projects with Clojure code.

Here is example of log4j settings adapted to use in Clojure. Log4j2 example. Just replace {{namespace}} placeholder with your namespace. These settings allows to get EDN structures as logging output. Don't use strings as log data, because when you put data to a string you ruin the data. Parsing log strings is bad idea.

To log any data to log4j2 use pedestal.log library Pedestal.log This wrapper is never blocks code thread and executes logging in different thread as data. Also print namespace (class) name and source line in logs.

Also you can log data using tap> facility from clojure.core. Here is the docs Clojure tap>. Here is the description How is tap> works tap is a shared, globally accessible system for distributing a series of informational or diagnostic values to a set of (presumably effectful) handler functions. It can be used as a better debug prn, or for facilities like logging etc.

You can tap different logging adapters tap> example

Answer 5

Logging won't side-effect program data, so the Clojure ethic does not frown on it.

To avoid having to remodel a function to log its inputs and outputs, a quick hack is to abuse pre- and post-conditions:

(defn foo [x]
  {:pre [(do (println "foo" x) 
             true)]
   :post [(do (println "foo" x "==>" %) 
              true)]}
  (if (neg? x)
    (inc x)
    x))

The true makes the condition succeed. Otherwise, the program would stop.

Pre- and post-conditions are documented here: https://clojure.org/reference/special_forms#_fn_name_param_condition_map_expr_2

Here's how the logging-enhanced foo looks in the REPL:

user> (foo -7)
foo -7
foo -7 ==> -6
-6