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
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.
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.