Why You Can't Use Clojure's `println` for Logging, and How to Fix It

This is a blog about the development of Yeller, The Exception Tracker with Answers Read more about Yeller here

I was seeing some weird things in my application logs that didn’t quite make sense. Output that looked jumbled, interleaved and so on. This was getting annoying - it was hard to debug those production problems that logs help for.

And the surprising cause of this?

Clojure’s println has a race condition.

Yeller logs to STDOUT - via the 12 factor app set of ideas. For that, you don’t need a complicated log library with levels and thousands of lines of xml and so on. println should suffice.

But its output is all garbled.

So, that race condition:

In multithreaded scenarios, the newline coming out of println isn’t always going to be in the right place, and if you call println (or print ) with multiple arguments, you’ll end up with interspersed output that looks something like this:

;; call this on multiple threads: ;; (println 1 2 3) ;; receive output like this: 1 12 3 2 1 23 3 1 21 32 3 1 2 13 2 3 11 2 2 3 31 12 32 1 32 3 1 12 23 3 1 2 31 2 3

Pretty annoying for your production logs, or even just local debugging, right?

The test case to reproduce that:

(print (with-out-str (let [out *out*] (doall (map deref (doall (map (fn [_] (future (binding [*out* out] (dotimes [_ 5] (println 1 2 3))))) (range 5))))))))

Nice and simple, just calling println with multiple arguments from 5 threads at a time (and using with-out-str to combine the results

This isn’t Java’s fault - normal printstreams/etc work fine in the presence of concurrency (no interleaving). The issue is in clojure.core

Indeed, if you replace (println 1 2 3) in the above with (.write *out* "1 2 3

") , then you get a perfectly sane output:

1 2 3 1 2 3 ;; and so on

So this seems weird - why is something as simple as println racy? Well, let’s take a look at the code:

(defn println "Same as print followed by (newline)" {:added "1.0" :static true} [& more] (binding [*print-readably* nil] (apply prn more)))

Ok, a layer of indirection over prn

Anyway, onwards to prn :

(defn prn "Same as pr followed by (newline). Observes *flush-on-newline*" {:added "1.0" :static true} [& more] (apply pr more) (newline) (when *flush-on-newline* (flush)))

Ok, so here’s part of the problem - prn calls pr with the arguments, then after that, calls newline (which just prints "

" to *out* ). This means you can get double layers of newlines, because it’s not atomic. But that still shouldn’t mean you can interleave (println 1 2 3) to get interspersed output. Let’s look at pr :

(defn pr "Prints the object(s) to the output stream that is the current value of *out*. Prints the object(s), separated by spaces if there is more than one. By default, pr and prn print in a way that objects can be read by the reader" {:dynamic true :added "1.0"} ([] nil) ([x] (pr-on x *out*)) ([x & more] (pr x) (. *out* (append \space)) (if-let [nmore (next more)] (recur (first more) nmore) (apply pr more))))

Pretty simple - does a loop over the inputs ( more ), and prints each one of them, printing spaces in between. Here’s the cause of our multiple arguments getting interleaved - Clojure’s pr just prints each argument individually, rather that concatenating strings.

What you can do

Fixing this issue is relatively simple. Replace your use of println with this function:

(defn safe-println [& more] (.write *out* (str (clojure.string/join " " more) "

")))

This functions relatively similarly to println , only it doesn’t have any race conditions because it does all the writing to *out* in one go. There’s some minor differences - deep down clojure’s printing respects a bunch of *binding* thread local variables to alter it’s output that this doesn’t.

This is a pretty simple change, but can help a lot when debugging concurrent code.

Thanks to Reid Draper, Michael Bernstein, Leo Cassarani and Phil Hagelberg for proof reading this post and confirming I was correct about this println behavior.

This is a blog about the development of Yeller, the Exception Tracker with Answers. Read more about Yeller here