The first part in this series is about logging. When you’re playing with your at the REPL, you can immediately see what’s going on. When your code is running on a server in some data center, and you had a problem 6 hours ago, it’s too late for a REPL. You need logs.

Having good logs is an art, but adding logging to a Clojure project is straightforward. So this is where we will start.

This article will show you how to use clojure.tools.logging, and get it set up using the Log4j logging backend. I’ll explain some common logging concepts, cover how to get Log4j installed, configured and working in a Leiningen project, and as an aside explain how to read Clojure stack traces. Finally I’ll run through some code that’s useful for interacting with the logger configuration at run time.

Logging Basics

Logs are a record of what happened as your program was executing. If something went wrong with your program’s execution, you can’t rewind time to see what actually happened, but if you have a log file, you might have log data to help you deduce what the problem was.

Logs are also used as a way to record “expected” problems and trigger manual follow-up activities (for example, if your log contains “Account creation failed” messages, you can go back and contact the people whose accounts weren’t created). I don’t think you should consider log files as a durable data store, so I strongly recommend that you don’t use logs for this type of thing.

Logging tools generally have the concept of “log levels”. These let you express the severity of a particular piece of log data. This fairly well-understood semantic lets you structure your log data, and helps you (and others) read your log files when looking for problems.

Logs are frequently stored in text files on disk. Take a look at the files in /var/log/ on any Unix system – whilst you may not understand the details of any given log, their structure and usage will likely be apparent.

The output also need not just be a simple text file. Loggers are frequently capable of logging to standard output (e.g. for a Heroku-style 12 Factor App), to syslog, or writing structured log files aimed at ingestion into log analytics platforms.

There are lots of choices available to Clojure programmers. Logback, Log4j, commons-logging and Timbre are just a few. Largely because of its ubiquity and the ease with which you can set it up I based this post on logging to Log4j, but it pretty much everything applies to these other libraries.

Clojure ❤ logging

OK, let’s get this going. It’s really simple: set up your dependencies, configure the logger, and insert some log statements.

I created a new Leiningen project for this, which I’m calling “rabbet” (lein new rabbet).

Dependencies

Add clojure.tools.logging and log4j to your dependencies list in project.clj:

1
2
3
4
5
6
7

:dependencies [[org.clojure/tools.logging "0.3.1"]
               [log4j/log4j "1.2.17" :exclusions [javax.mail/mail
                                                 javax.jms/jms
                                                 com.sun.jmdk/jmxtools
                                                 com.sun.jmx/jmxri]]
              ;; ...etc
              ]

Note: I’m using Log4j version 1.2 here. Log4j 2 isn’t currently supported by clojure.tools.logging.

Quick configuration

Log4j’s output is commonly controlled from a log4j.properties file. You set up the types of logs that are created, the format of the logs, and the verbosity of the logs.

Get started by creating resources/log4j.properties in your project containing this:

1
2
3
4
5
6
7
8
9
10

log4j.rootLogger=ERROR, file

log4j.logger.rabbet.core=INFO

log4j.appender.file=org.apache.log4j.RollingFileAppender
log4j.appender.file.File=log/rabbet.log
log4j.appender.file.MaxFileSize=1MB
log4j.appender.file.MaxBackupIndex=10
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss.SSS} | %-5p | %t | %c | %m%n

I also suggest that you add log/ to your .gitignore.

Using clojure.tools.logging

It’s super simple. Add this code to src/rabbet/core.clj:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18

(ns rabbet.core
  (:require [clojure.tools.logging :as log]))

;; Output log statements at various levels:
(log/trace "This is the lowest (least important) log level")
(log/debug "For programmer info...")
(log/warn "Something bad might have happened.")

;; You can dump all kinds of things out to the log:
(log/info "this happened:"
          {:foo 12 :bar :quux}
          "that was fun!")

;; Exceptions have a special arity:
(try
  (/ 10 (dec 1)) ;; <-- dividing by zero rarely works.
  (catch Exception e
    (log/error e "Dividing failed!")))

Evaluate the file and take a look at the output in the log file (log/rabbet.log):

1
2
3
4
5
6
7
8
9
10
11
12
13

2015-06-14 14:26:48.957 | WARN  | nREPL-worker-2 | rabbet.core | Something bad might have happened.
2015-06-14 14:26:48.960 | INFO  | nREPL-worker-2 | rabbet.core | this happened: {:foo 12, :bar :quux} that was fun!
2015-06-14 14:26:48.963 | ERROR | nREPL-worker-2 | rabbet.core | Dividing failed!
java.lang.ArithmeticException: Divide by zero
  at clojure.lang.Numbers.divide(Numbers.java:158)
  at clojure.lang.Numbers.divide(Numbers.java:3808)
  at rabbet.core$eval12281.invoke(core.clj:16)
  at clojure.lang.Compiler.eval(Compiler.java:6792)
  at clojure.lang.Compiler.load(Compiler.java:7237)
         <--- snip --->
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
  at java.lang.Thread.run(Thread.java:745)

You can see three interesting log lines, one for the log/warn call, one for the log/info call, and one for the log/error call. Because we passed the caught exception to the log/error call, the stack trace of the exception is also printed to the log.

The log statements are timestamped (a good thing), indicate clearly how bad the information they contain might be (another good thing), and in the case of the exception you can even see where the exception was thrown.

What you don’t see is output from the log/trace and log/debug calls. This is because we configured Log4j to output at the INFO level for our namespace. Let’s dig into that configuration.

Configuration details

Log4j is a fairly substantial library, but it has but a handful of important concepts that can easily be explained by looking back at the log4j.properties file.

Log Levels

Log4j defines the following levels:

• TRACE
• DEBUG
• INFO
• WARN
• ERROR
• FATAL

Obviously there’s a semantic ordering here – the least bad is at the top, the worst is at the bottom.

When logging some data you choose the log level that best represents each log datum. In the example earlier, I logged a divide-by-zero exception at the ERROR level (using the log/error function). Conceptually, an ERROR is more severe than a WARNing, which is in turn more severe than an INFO, etc. When you add log calls to your code, add them at an appropriate level.

Appenders

Appenders are where log output gets written to. Log4j has a rich set of loggers, and an API for creating your own. Some interesting appenders are:

• ConsoleAppender – writes to standard out or standard error
• FileAppender – writes to a log file
• RollingFileAppender – writes to a log file, and also has options for rolling the log with size-based criteria
• DailyRollingFileAppender – writes to a log file, and rolls the log with time-based criteria
• SMTPAppender – sends emails
• SyslogAppender – writes to Syslog
• NTEventLogAppender – writes to Windows event log

There are also third-party appenders, e.g. logging directly to Splunk.

Our log4j.properties defines only one appender. Interpreting lines 5 through 8 of the config, it is named file, and it is a RollingFileAppender. It creates and logs to log/rabbet.log. It will allow 1MB of log data to accumulate in the file before starting writing to a new log file, and renaming the older log file(s). It will keep a total of 10 old log files, and any older ones will get deleted when log rolling occurs.

You can configure Log4j to output to multiple appenders at the same time, each of which having a different active configuration. The most common use case for this is having some log lines printed on standard output, and having all log lines kept in a log file and with a more detailed layout format.

Loggers

Loggers are what you make logging calls to. They are hierarchical, and control the threshold of the log level to output. The hierarchy is based on package and class naming (namespaces in Clojure). It’s a sparse tree, so if you don’t define a logger for a particular namespace, the closest ancestor in the tree will be used. Since there’s always a root logger, there’s always an ancestor.

Line 1 of our log4j.properties defines the root logger as being at level ERROR, and the logger named file is configured to listen at the root logger level.

Line 3 defines a specialization: for the namespace rabbet.core, the log threshold is set to INFO. The effect of this is that the active log level for log statements in the rabbet.core namespace, or any sub-namespace therein, will be increased to INFO. All other namespaces are still covered by the root logger, which is logging at ERROR level.

Layouts

Layouts are how you specify what the formatting of the log output is. There are a number of different layouts available (see the direct known subclasses of the Layout class) but I’ll cover only one: PatternLayout.

The last line in our log4j.properties describes the pattern we’re using for the file appender. Skipping over the justification and padding details, %d{yyyy-MM-dd HH:mm:ss.SSS} | %-5p | %t | %c | %m%n will format the log into pipe-delimited fields, with each line having a timestamp, a log priority (level), the thread name, the class, and the log message (followed by a newline).

There are other interesting things you might want in your log output, or perhaps you’d rather every field in the log was fixed-width. You can find out more from the PatternLayout API doc.

Logging without logging

Recall the example above where the (log/trace ...) and (log/debug ...) calls resulted in no output. Looking at the log configuration file, there are two lines are responsible for this behavior:

1
2
3
4
5

# Set the overall log level for the `file` appender to ERROR:
log4j.rootLogger=ERROR, file

# Override the log level for the `rabbet.core` namespace to INFO:
log4j.logger.rabbet.core=INFO

So for the rabbet.core namespace, output for TRACE and DEBUG messages is suppressed. This means you can add all kinds of log calls to your source file, and then through the logger configuration set whether those log statements are output to the log.

This configuration is fairly typical. ERROR logs for any namespaces are always output to the log file, and more information is output for the source for my project. I can leave all of the DEBUG and TRACE calls in the code, and when I need to investigate a problem, I can just increase the log level in log4j.properties and get lots more data in the log.

A quick aside: reading Clojure stack traces

If you’re new to stack traces, they can be a little intimidating.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28

java.lang.ArithmeticException: Divide by zero
  at clojure.lang.Numbers.divide(Numbers.java:158)
  at clojure.lang.Numbers.divide(Numbers.java:3808)
  at rabbet.core$eval12281.invoke(core.clj:16)
  at clojure.lang.Compiler.eval(Compiler.java:6792)
  at clojure.lang.Compiler.load(Compiler.java:7237)
  at user$eval12257.invoke(form-init323843885648136810.clj:1)
  at clojure.lang.Compiler.eval(Compiler.java:6792)
  at clojure.lang.Compiler.eval(Compiler.java:6755)
  at clojure.core$eval.invoke(core.clj:3079)
  at clojure.main$repl$read_eval_print__7093$fn__7096.invoke(main.clj:240)
  at clojure.main$repl$read_eval_print__7093.invoke(main.clj:240)
  at clojure.main$repl$fn__7102.invoke(main.clj:258)
  at clojure.main$repl.doInvoke(main.clj:258)
  at clojure.lang.RestFn.invoke(RestFn.java:1523)
  at clojure.tools.nrepl.middleware.interruptible_eval$evaluate$fn__1673.invoke(interruptible_eval.clj:53)
  at clojure.lang.AFn.applyToHelper(AFn.java:152)
  at clojure.lang.AFn.applyTo(AFn.java:144)
  at clojure.core$apply.invoke(core.clj:628)
  at clojure.core$with_bindings_STAR_.doInvoke(core.clj:1866)
  at clojure.lang.RestFn.invoke(RestFn.java:425)
  at clojure.tools.nrepl.middleware.interruptible_eval$evaluate.invoke(interruptible_eval.clj:51)
  at clojure.tools.nrepl.middleware.interruptible_eval$interruptible_eval$fn__1715$fn__1718.invoke(interruptible_eval.clj:183)
  at clojure.tools.nrepl.middleware.interruptible_eval$run_next$fn__1708.invoke(interruptible_eval.clj:152)
  at clojure.lang.AFn.run(AFn.java:22)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
  at java.lang.Thread.run(Thread.java:745)

If this all looks like noise to you, here’s how I suggest you break it down:

• Read the stack trace from the top down.
• What type of exception was thrown?
  • Start at the top. java.lang.ArithmeticException – this is the type of exception thrown. It’s usually a good clue about the kind of problem you’re looking for.
• What is the exception message?
  • Divide by zero – this is the message the exception was created with (e.g. (throw (ArithmeticException. "Divide by zero"))). Sometimes this is very useful, but it’s just a descriptive field that a programmer can type some words into, so you are relying on their descriptive skills.
• Where did the exception get thrown?
  • The stack trace output has a standard structure – at <package>.<packages>.<class>.<method>(<filename>:<line number>), and since the order comes from unwinding the stack, the top of the stack trace is the “most specific”, or the deepest point in your program. The bottom of the stack trace is going to be the “lest specific”, the original initiating point in the code for the execution stack (e.g. a main function).
  • The first line in the stack trace is where the exception was thrown – at clojure.lang.Numbers.divide(Numbers.java:158). This first method call – divide in clojure.lang.Numbers – is what threw the exception. At this point, we know a lot about the problem: a divide-by-zero arithmetic exception was thrown by a divide method call on a Number. That’s really helpful to know what we’re looking for.
• But what really caused the exception?
  • The first two lines of the stack trace are in Clojure’s functions. A decent heuristic is that there aren’t bugs in core Clojure or in Java, so if an exception is thrown the problem is in your code. So skip over the lines for Clojure functions and focus on those lines related to your own namespaces – that’s probably where the problem lies.
  • Reading downwards, the third line of the stack trace, at rabbet.core$eval12281.invoke(core.clj:16) comes from one of our source files. Since the Clojure compiler does all manner of clever code generation things, you will see some seemingly spurious data (in this case, we never wrote a function called eval12281, but the Clojure compiler actually did). You will quickly learn to ignore the generated bits and see only the important information. I squint my eyes and see at rabbet.core(core.clj:16), which tells me to go and look at line 16 in the source file that defines the rabbet.core namespace, and whose name is core.clj. So open up src/rabbet/core.clj, and see what on line 16 matches the rest of what you know about the problem.
  • In a real-world example you will need to repeat these last couple of steps and keep working your way down the stack trace to get an understanding of how the actual problem came about. Focus on stack frames for namespaces you own.

Dynamic Reconfiguration

This is a coda to the main part of the article, but I sometimes find it really useful to tweak the log configuration when I’m getting the project set up, and when I’m debugging. Here are some of my use cases:

I like to be able to change the global log level (and without having to restart the JVM). Sometimes it’s when I’ve scattered loads of trace and debug log calls through the code and I want to increase the log verbosity and see all of what’s being emitted. Sometimes I want to just see warnings and errors, so I want to decrease the verbosity.

Also, it’s useful to be able to change the log level for a specific namespace or package. The use case is similar: I’ll scatter a load of trace and debug calls through a namespace, and have the logger output all of these log lines but keep the log output from other namespaces fairly quiet.

The final use case I’ll cover is reloading the logger configuration file. I don’t use this a lot, but if I’m tweaking the logger patterns, or trying out different log appenders, it’s a big time saver to be able to just edit the config file and call a reload function instead of having to restart the JVM. It is possible to set up Log4J to do this automatically, but I don’t really need this under normal circumstances, so a runtime approach is handy.

Before getting to the code that does this, I should note that there are libraries that do loads of log config for you, including all of the above and plenty more. I’m only really interested in a subset of their functionality, so I’ll leave it as an exercise to the reader to investigate these (I suggest clj-logging-config).

Source

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59

(ns rabbet.log
  (:require [clojure.java.io :as io]
            [clojure.set :as set])
  (:import (org.apache.log4j Level
                             Logger
                             PropertyConfigurator)))

(def log-levels {:all Level/ALL
                 :trace Level/TRACE
                 :debug Level/DEBUG
                 :info Level/INFO
                 :warn Level/WARN
                 :error Level/ERROR
                 :fatal Level/FATAL
                 :off Level/OFF})

(defn- set-logger-level*
  [^org.apache.log4j.Logger logger level]
  {:pre [(log-levels level)]}
  (.setLevel logger (log-levels level)))

(defn set-root-logger-level!
  "Sets the root logger to be at `level`."
  [level]
  (set-logger-level* (Logger/getRootLogger)
                     level))

(defn set-logger-level!
  "Sets the specified `logger` to be at `level`."
  [logger level]
  (set-logger-level* (Logger/getLogger logger)
                     level))

(defn loggers-seq []
  (-> (Logger/getRootLogger)
      .getLoggerRepository
      .getCurrentLoggers
      enumeration-seq))

(defn logger-levels [loggers]
  (into {}
        (for [logger loggers]
          [(.getName logger) ((set/map-invert log-levels) (.getEffectiveLevel logger))])))

(defn set-all-loggers-level!
  "Sets the level of all configured loggers to be at `level`."
  [level]
  (doseq [logger (loggers-seq)]
    (set-logger-level* logger level)))

(defn reload-config!
  "Reconfigures log4j from a log4j.properties file on the classpath"
  []
  (with-open [config-stream
              (-> "log4j.properties"
                  io/resource
                  io/file
                  io/input-stream)]
    (PropertyConfigurator/configure config-stream)))

Usage

Three functions are useful, and here’s how you would use them:

1
2
3
4
5
6
7
8
9
10

(require '[rabbet.log :as rlog])

;; Reload the config file:
(rlog/reload-config!)

;; Set all loggers to emit errors and worse:
(rlog/set-all-loggers-level! :all)

;; Set one specific namespace to emit all log events:
(rlog/set-logger-level! "rabbet.foo" :all)

Summary

Do logging! I’ve covered how easy it is to set up clojure.tools.logging logging to Log4j, and shown how to do some basic logger configuration to get you up and running.

The hard bit is in balancing what to log, how much to log, and how much to keep. I recommend a liberal sprinkling of log calls, but pick appropriate levels for the calls – lots of trace and debug calls, but hopefully not too many errors. If an exception is thrown, catch blocks are an obvious place to drop a log call. Use this arity of the log calls:

1
2
3
4

(try
  (stuff ...)
  (catch Exception e
    (log/error e "foobar went wrong"))

Add log calls, put useful data into the calls, and tune the logger configuration to your liking. If you want more or less log output, you can leave the code alone and just change the configuration file, or even change the active configuration at runtime.

Please get in touch if you’d like to see more on this, or if you have any kind of feedback. @iantruslove

Image Credit: http://chestofbooks.com/home-improvement/woodworking/Cabinet-Making/