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\n"), 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 "\n" 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) "\n")))

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

Learn how to Debug Production Errors

I've put together a course on debugging production web applications. It covers a whole heap of techniques to speed up debugging. Shortcuts you can take, changes you can make to your systems to make debugging easier, common mistakes to avoid and a bunch more.

I won't spam you - I'll send you exactly 8 emails for the course, and that's it.