Reading Clojure Stacktraces

Clojure stacktraces are not incredibly user friendly. Once I got used to the status quo, I forgot how much noise lives within a stacktrace; however, every so often a Clojure beginner will remind the community that stacktraces are a bit convoluted. You can blame the JWM, lack of prioritization from the Clojure community, or someone else if you wish, but the reality is - I don't expect stacktraces to change anytime soon. This blog entry is about separating the signal from the noise within a stacktrace.

note: all code for this blog entry can be found at: http://github.com/blog-jayfields-com/Reading-Clojure-Stacktraces

Let's start with a very simple example.


Running (I'm using 'lein run') the above code you should get a stacktrace that looks like the output below.

lmp-jfields03:reading-clojure-stacktraces jfields$ lein run
Exception in thread "main" java.lang.RuntimeException: thrown
 at reading_clojure_stacktraces.core$foo.invoke(core.clj:3)
 at reading_clojure_stacktraces.core$_main.invoke(core.clj:6)
 at clojure.lang.Var.invoke(Var.java:397)
 at user$eval37.invoke(NO_SOURCE_FILE:1)
 at clojure.lang.Compiler.eval(Compiler.java:6465)
 at clojure.lang.Compiler.eval(Compiler.java:6455)
[blah blah blah]

I snipped a fair bit of stacktrace and replaced it with [blah blah blah]. I did that because that's what I mentally do as well, I look for the last line that includes a file that I've created and I ignore everything after a few lines below my line. That is my first recommendation - If you see a stacktrace, it's likely that the problem is in your code, not Clojure. Look for the last line of your code (N) and ignore every line below N + 3.

In this example, user$eval... likely has something to do with lein, and I can safely assume that the problem is likely not in there. Moving up from there I can see a line from my code:

reading_clojure_stacktraces.core$_main.invoke(core.clj:6)

When I read the above line I see the problem is in namespace 'reading-clojure-stacktraces/core', in the function '-main', in the file core.clj, on line 6. I'm no Clojure internals expert, but I believe Clojure actually creates a class named reading_clojure_stacktraces.core$_main with an 'invoke' method; however, I truthfully don't know (and you wont need to either). Whether a class is created or not, it makes sense that the line will need to be formatted to fit a valid Java class name - which explains why our dashes have been converted to underscores.

Moving up another line, I can see that the issue is likely inside the 'foo' function of the reading-clojure-stacktraces namespace. A quick review of the original code shows that line 3 of core.clj contains the call to throw, and everything makes perfect sense.

If all Clojure stacktraces were this simple, I probably wouldn't bother with this blog entry; however, things can become a bit more complicated as you introduce anonymous functions.

The following snippet of code removes the 'foo' function and throws an exception from within an anonymous function.

Another trip to 'lein run' produces the following output.

Exception in thread "main" java.lang.RuntimeException: thrown
 at reading_clojure_stacktraces.core$_main$fn__9.invoke(core.clj:4)
 at reading_clojure_stacktraces.core$_main.invoke(core.clj:4)
 at clojure.lang.Var.invoke(Var.java:397)
 at user$eval38.invoke(NO_SOURCE_FILE:1)
 at clojure.lang.Compiler.eval(Compiler.java:6465)

The above stacktrace does give you the correct file and line number of where the issue originates; however, you'll notice that the function that threw the exception has become a bit less easy to identify. My use of an anonymous function led to Clojure naming the function fn__9, and there's nothing wrong with that. In fact, this example is especially readable as the stacktrace shows that fn__9 was created inside the -main function.

I expect you'd be able to find the issue with our contrived example without any further help; however, production code (often making use of high order functions) can lead to significantly more complex stacktraces. You could forsake anonymous functions, but there's a nice middle ground that is also helpful for debugging - temporarily name your anonymous functions.

Clojure's reader transforms the Anonymous function literal in the following way.

#(...) => (fn [args] (...))

Therefore, the following code will be the same as the example above, from Clojure's perspective.

Another quick 'lein run' verifies that the stacktrace is the same (and I see no reason to repeat it here). However, now that we've switched to fn, we can provide a (rarely used, optional) name.

At this point, 'lein run' should produce the following output.

Exception in thread "main" java.lang.RuntimeException: thrown
 at reading_clojure_stacktraces.core$_main$i_throw__9.invoke(core.clj:4)
 at reading_clojure_stacktraces.core$_main.invoke(core.clj:4)
 at clojure.lang.Var.invoke(Var.java:397)
 at user$eval38.invoke(NO_SOURCE_FILE:1)
 at clojure.lang.Compiler.eval(Compiler.java:6465)

Now our line contains a bit more information. The two $ signs still indicate that the function with an issue is a function created inside -main; however, our stacktrace also includes the name (in bold) we specified for our function. You can use any valid symbol characters, so feel free to put anything you want in the name while you're debugging.

note: Symbols begin with a non-numeric character and can contain alphanumeric characters and *, +, !, -, _, and ? -- clojure.org.

So far, all of the examples have been somewhat noisy, but mildly easy to mentally filter. Unfortunately, idiomatic Clojure code can also lead to stacktraces that bounce back and forth between your code and the standard library, leaving you to sift through significantly longer stacktraces.

The following snippet of code throws a NullPointerException due to a mistake I clearly made, but the last line of 'my code' is in the lower half of a long stacktrace.

The above example code produces the below stacktrace.

Exception in thread "main" java.lang.NullPointerException
 at clojure.lang.Numbers.ops(Numbers.java:942)
 at clojure.lang.Numbers.inc(Numbers.java:110)
 at clojure.core$inc.invoke(core.clj:862)
 at clojure.core$map$fn__3811.invoke(core.clj:2430)
 at clojure.lang.LazySeq.sval(LazySeq.java:42)
 at clojure.lang.LazySeq.seq(LazySeq.java:60)
 at clojure.lang.RT.seq(RT.java:466)
 at clojure.core$seq.invoke(core.clj:133)
 at clojure.core$print_sequential.invoke(core_print.clj:46)
 at clojure.core$fn__4990.invoke(core_print.clj:140)
 at clojure.lang.MultiFn.invoke(MultiFn.java:167)
 at clojure.core$pr_on.invoke(core.clj:3264)
 at clojure.core$pr.invoke(core.clj:3276)
 at clojure.lang.AFn.applyToHelper(AFn.java:161)
 at clojure.lang.RestFn.applyTo(RestFn.java:132)
 at clojure.core$apply.invoke(core.clj:600)
 at clojure.core$prn.doInvoke(core.clj:3309)
 at clojure.lang.RestFn.applyTo(RestFn.java:137)
 at clojure.core$apply.invoke(core.clj:600)
 at clojure.core$println.doInvoke(core.clj:3329)
 at clojure.lang.RestFn.invoke(RestFn.java:408)
 at reading_clojure_stacktraces.core$_main.invoke(core.clj:7)
 at clojure.lang.Var.invoke(Var.java:397)
 at user$eval37.invoke(NO_SOURCE_FILE:1)
 at clojure.lang.Compiler.eval(Compiler.java:6465)
 at clojure.lang.Compiler.eval(Compiler.java:6455)

In situations like these, I generally look at the top few lines to get a bit of context, and then I scroll down to find the last line of 'my code'. Looking at the top 4 lines from the stacktrace I can see that the issue is with the inc function, which was passed to the high order function named map. If I look father down the stacktrace, I can see that line 7 in reading-clojure-stacktraces.core is where the issue began in 'my code'.

If you look at line 7 of (reading-clojure-stacktraces) core.clj, you'll notice that I'm merely printing the results of calling foo - yet the issue seems to be with the map function that is invoked within foo. This is because map is lazy, and the evaluation is deferred until we attempt to print the results of mapping inc. While it's not exactly obvious, the stacktrace does contain all the hints we need to find the issue. Line 3 lets us know that inc is getting a nil. Line 4 lets us know that it's happening inside a map. Line 5 lets us know that we're dealing with laziness. And, the line containing our namespace lets us know where to begin looking.

The following example is very similar; however, it uses a partial to achieve the same result.

The above example code produces the below stacktrace.

Exception in thread "main" java.lang.NullPointerException
 at clojure.lang.Numbers.ops(Numbers.java:942)
 at clojure.lang.Numbers.add(Numbers.java:126)
 at clojure.core$_PLUS_.invoke(core.clj:927)
 at clojure.lang.AFn.applyToHelper(AFn.java:163)
 at clojure.lang.RestFn.applyTo(RestFn.java:132)
 at clojure.core$apply.invoke(core.clj:602)
 at clojure.core$partial$fn__3794.doInvoke(core.clj:2341)
 at clojure.lang.RestFn.invoke(RestFn.java:408)
 at clojure.core$map$fn__3811.invoke(core.clj:2430)
 at clojure.lang.LazySeq.sval(LazySeq.java:42)
 at clojure.lang.LazySeq.seq(LazySeq.java:60)
 at clojure.lang.RT.seq(RT.java:466)
 at clojure.core$seq.invoke(core.clj:133)
 at clojure.core$print_sequential.invoke(core_print.clj:46)
 at clojure.core$fn__4990.invoke(core_print.clj:140)
 at clojure.lang.MultiFn.invoke(MultiFn.java:167)
 at clojure.core$pr_on.invoke(core.clj:3264)
 at clojure.core$pr.invoke(core.clj:3276)
 at clojure.lang.AFn.applyToHelper(AFn.java:161)
 at clojure.lang.RestFn.applyTo(RestFn.java:132)
 at clojure.core$apply.invoke(core.clj:600)
 at clojure.core$prn.doInvoke(core.clj:3309)
 at clojure.lang.RestFn.applyTo(RestFn.java:137)
 at clojure.core$apply.invoke(core.clj:600)
 at clojure.core$println.doInvoke(core.clj:3329)
 at clojure.lang.RestFn.invoke(RestFn.java:408)
 at reading_clojure_stacktraces.core$_main.invoke(core.clj:7)
 at clojure.lang.Var.invoke(Var.java:397)
 at user$eval37.invoke(NO_SOURCE_FILE:1)
 at clojure.lang.Compiler.eval(Compiler.java:6465)

Again, you'll want to skim the stacktrace for hints. In the above stacktrace we can see that line 3 is telling us that + is the issue. Line 7 lets us know that partial was used. And, the remaining hints are the same as the previous example.

Skimming for hints may look painful at first. However, you quickly learn to filter out the common Clojure related noise. For example, anything that starts with 'clojure' and looks like a standard Java class name is highly unlikely to be where a problem exists. For example, clojure.lang.Numbers.ops isn't likely to have a bug. Likewise, you'll often see the same classes and methods repeated across all possible errors - clojure.lang.AFn, clojure.lang.RestFn, clojure.core$apply, clojure.lang.LazySeq, clojure.lang.RT, clojure.lang.MultiFn, etc, etc. These functions are often used building blocks for almost everything Clojure does. Those lines provide a bit of signal, but (for the most part) can safely be ignored.

Again, it can be a bit annoying to deal with Clojure stacktraces when getting started; however, if you take the time to understand which lines are signal and which lines are noise, then they become helpful debugging tools.

related: If you want a testing library that helps you filter some of the stacktrace noise, you might want to check out expectations.