REPL Based Debugging in ClojureDana BorinskiBlockedUnblockFollowFollowingJun 2We’ve spoken in previous posts, about why we have chosen Clojure and how important it is to our engineering culture.
In this post I’d like to focus on some of the basics of Clojure — debugging.
Clojure is a dynamic and functional programming language that provides some powerful tools out of the box for debugging.
One such tool is called REPL (Read Evaluate Print Loop) that enables developers more code clarity by making it possible to find the source of bugs much more quickly, and ultimately understand the code and flow better.
By using the REPL, it’s much easier to interact with a running Clojure project.
In fact, Clojure as a community promotes a REPL First Development mentality as a best practice (AKA REPL Driven Development).
As a prerequisite to this post, you will need to get REPL setup.
Once you have your REPL up and running, you can start to play around with your code.
One of the bonuses with using REPL is that it enables you a number of different ways to debug your code more efficiently, some of these include:The Stack TraceCode Inspection with Prints & LogsThis post will dive into how to best leverage REPL in these different scenarios, with real code examples.
Stack Trace Debugging using REPL:Since Clojure is compiled to Java bytecode and runs on the JVM, many times, if an exception is thrown, it will be a Java style exception.
The stack trace provides valuable information for you to be able to identify the source of the exception, including where the exception occurred, why it occurred, what was the flow that led to this exception (among other data points).
Reading the exceptions, and probably even more importantly, actually understanding them (while this can be a tedious process) is the key for tracing and tackling the actual issue.
And all that said, it is quite common for exceptions in Clojure to not really “point” to where the actual issue is.
Let’s take a look at this simple example and break it down:In the code above, we have a function named divide that gets two arguments, a and b, and returns the division of a by b.
Pretty simple, right?But what will happen if we try to send to this function b defined as 0?Let’s try…user=> (divide 5 0)java.
lang.
ArithmeticException: Divide by zeroOk, no major surprises, so we’ve got an exception that says we are trying to divide by zero.
Pretty straightforward.
While the exception itself is pretty clear, and we can definitely understand that this function was probably called with 0 in the second argument (b), other than that, there really isn’t much information on where this exception actually originated or what led us to this function.
Of course, this is a simple example, but imagine a complex scenario of nested function calls where the exception happens deep inside the call tree.
That being the case, our most helpful tool is the stack trace.
In order to see the stack trace in the REPL we just need to call the pst function like this: (pst)[Read more here: https://clojuredocs.
org/clojure.
repl/pst]This will give us the stack trace for the last exception:clojure.
core/eval core.
clj: 3105 .
debugging-clojure.
core/eval10602 REPL Inputdebugging-clojure.
core/divide core.
clj: 10 .
java.
lang.
ArithmeticException: Divide by zeroNow we can understand that the exception is in line 10 in the core.
clj file in the divide function.
If our divide function was triggered by another function, we can still understand this from the stack trace.
Consider this example:user=> (my-calc {:1 1 :2 2 :3 0})java.
lang.
ArithmeticException: Divide by zeroWhen calling (pst)we will get:user=> (pst)clojure.
core/eval core.
clj: 3105.
debugging-clojure.
core/eval18992 REPL Inputdebugging-clojure.
core/my-calc core.
clj: 7debugging-clojure.
core/divide core.
clj: 2 .
java.
lang.
ArithmeticException: Divide by zeronilThis methodology will help us to drill down and isolate the issue so we can debug it via the REPL and solve it quickly.
In this example, we can clearly see from the third line of the stack trace that the issue is with the second division:debugging-clojure.
core/my-calc core.
clj: 7We can understand now that in the second division, we are trying to divide by zero even if we don’t have the visibility of what the input of the function actually is.
Inspecting your Code with Prints and Logs:Using prints is a simple way that enables us to inspect the values of certain variables and symbols (which is useful after a function or an operation occurred).
We can add prints within the block execution so we don’t have to wait until the execution of a certain block is performed in order to understand what happened inside.
We can use prints inside a let block to understand the flow better.
In this example, I created a new version of the function my-calc that does a basic calculation:Now lets say we want to inspect what the value of minus is.
In order to do so, an empty binding was created (bind something to the _ symbol) the bound value is then printed:user=> (my-calc 1 2 3)minus is: -413/6 ;the returned valueWe can even use this similar method to inspect threading macros, and because of the fact that threading macros expects to receive a function at each step, it is then possible to manipulate the data flow by passing a function that prints the input and returns the same input — this prevents the data flow from changing.
If that was a mouthful, you can see this represented in the example below:user=> (def m {:body "flow test"})user=> (-> m :body (#(do (println %) %)) (clojure.
string/upper-case) (#(do (println %) %)) (clojure.
string/reverse))Will print to the REPL:flow testFLOW TEST"TSET WOLF" ;the returned valueThe powerful part of using the macros method, is that you can write your own macros based on your specific environment and codebase.
An example, is a macro we wrote at AppsFlyer and is part of an open source library called Mate-clj we released, that gives you the ability to debug your code flow for some core functions and macros out of the box using a simple require.
[Oh, and by the way — you are welcome to contribute too!]Let’s see for example the macro d-> from Mate-clj library.
This macro inspects each step of the threading macro — ->, and automatically populates information in the REPL to tell us what the current step is and what the expected output of this step is:user=> (d-> m :body (clojure.
string/upper-case) (clojure.
string/reverse))The output in the REPL will be:(:body m) : flow test(clojure.
string/upper-case (:body m)) : FLOW TEST(clojure.
string/reverse (clojure.
string/upper-case (:body m))) : TSET WOLF"TSET WOLF" ;the returned valueAs you can see, this macro makes it much easier to understand what the expected flow should look like, and how the threading macro is executed.
Using Logs:Another good method for debugging and better understanding context & flows — is by using logs.
There are several excellent logging libraries that are open source that can be used in order to integrate logs within our code.
We mostly use Timbre.
I will quickly cover the basics of working with the API so that we can reference it easily in our later examples.
First of all, in order to use Timbre in our project, it should be added to the project.
clj file as a dependency:[com.
taoensso/timbre "4.
10.
0"]It can then be used in any namespace by adding this line [taoensso.
timbre :as timbre] under the require of the namespace:(ns my-clj-ns ; Clojure namespace (:require [taoensso.
timbre :as timbre]))Or directly in the REPL:user=> (require '[taoensso.
timbre :as timbre])Great, we can now start using it.
Info:When it comes to Clojure, there are generally a few log level hierarchies that can be used.
The reason we like to work with Timbre is that it provides the ability to print lines depending on the log level and on the environment the code is running on.
For example, info logs can be used both in production and development, while debug logs usually will be used only in development.
A good practice is to use the log level flag to prevent logs such as debug from being printed in production.
user=> (timbre/info "this will print an info!")16:46:45 INFO [debugging-clojure.
core:10] – this will print an info!As you can see, the format of the log can tell us the log level, in this case INFO, provides information about where the log came from — the project name, the namespace and right after the semicolon, the line number in the namespace where the log is printed [debugging-clojure.
core:10] so in this case the project name is debugging-clojure, the namespace is core.
clj and the line number is 10.
Debug:user=> (timbre/debug "this will print debug!")16:48:55 DEBUG [debugging-clojure.
core:1] – this will print debug!Besides using the debug logs with the proper log-level we can use this kind of logs to also print variables.
This provides us more context about the flow we are trying to debug:user=> (def x {:a 1 :b 2})#'debugging-clojure.
core/xuser=> (timbre/debug x)16:49:45 DEBUG [debugging-clojure.
core:1] – {:a 1, :b 2}Warn:Can be used to indicate something is not going as expected, but not causing an error that would lead to an exception or interrupt the flow of our code.
(timbre/warn "Invalid message format, msg is: " output-msg)16:56:44 WARN [debugging-clojure.
core:1] – Invalid message, msg is: {:body "test msg"}Spy:Spy is a bit different from the logs above, as it’s not a regular print line.
Spy wraps function calls in order to monitor the params and the function execution results by plotting them into the REPL.
For example, we can wrap the call of my-calc function and get the output of the function as a log with information about the function, as well as where it was executed.
user=> (timbre/spy (my-calc 1 2 3))13:49:03 DEBUG [debugging-clojure.
core:1] – (my-calc 1 2 3) => 13/6There are more APIs that Timbre provides.
You can refer to the documentation for more informationSumming It All UpLearning a new language is always exciting and fun, and from personal experience, for me learning Clojure has proven a fun ride.
:)I’ve found that a good way to really be able to get a good grasp of a new programming language is by understanding how to debug it properly.
Once you master your Clojure debugging skills you’ll find that you have quickly ramped up your Clojure coding skills as an added bonus.
As a developer by grokking the debugging of a new language you will gain a deeper understanding of your code, better overview on control flows, and achieve much quicker bug detection, and ultimately resolution.
The REPL is a powerful tool that should be native to your development flow, and I highly recommend that you get to know it, and use it regularly.
Safe Debugging!.