The Common Lisp Cookbook – Debugging

Table of Contents

The Common Lisp Cookbook – Debugging

📢 👩‍🎓 ⭐ NEW: learn CLOS in videos! (50% coupon) Get up to speed in CL in this 7h course, by the Cookbook's main contributor, on Udemy. Learn more.

📕 Get the EPUB and PDF

You entered this new world of Lisp and now wonder: how can we debug what’s going on? How is it more interactive than other platforms? What does the interactive debugger bring, apart from stack traces?

Well of course we can use the famous technique of “print debugging”. Let’s just recap a few print functions.

print works, it prints a readable representation of its argument, which means what is printed can be read back in by the Lisp reader. It accepts only one argument.

princ focuses on an aesthetic representation.

(format t "~a" …), with the aesthetic directive, prints a string (in t, the standard output stream) and returns nil, whereas format nil … doesn’t print anything and returns a string. With many format controls we can print several variables at once.

print has this useful debugging feature that it prints and returns the result form it was given as argument. You can intersperse print statements in the middle of your algorithm, it won’t break it.

(+ 2 (print 40))

Logging

Logging is already a good evolution from print debugging ;)

log4cl is the popular, de-facto logging library although it isn’t the only one. Download it:

(ql:quickload "log4cl")

and let’s have a dummy variable:

(defvar *foo* '(:a :b :c))

We can use log4cl with its log nickname, then it is as simple to use as:

(log:info *foo*)
;; <INFO> [13:36:49] cl-user () - *FOO*: (:A :B :C)

We can interleave strings and expressions, with or without format control strings:

(log:info "foo is " *foo*)
;; <INFO> [13:37:22] cl-user () - foo is *FOO*: (:A :B :C)
(log:info "foo is ~{~a~}" *foo*)
;; <INFO> [13:39:05] cl-user () - foo is ABC

With its companion library log4slime, we can interactively change the log level:

It is very handy, when we have a lot of output, to turn off the logging of functions or packages we know to work, and thus narrowing our search to the right area. We can even save this configuration and re-use it in another image, be it on another machine.

We can do all this through commands, keyboard shortcuts and also through a menu or mouse clicks.

"changing the log level with log4slime"

We invite you to read log4cl’s README.

Using the powerful REPL

Part of the joy of Lisp is the excellent REPL. Its existence usually delays the need to use other debugging tools, if it doesn’t annihilate them for the usual routine.

As soon as we define a function, we can try it in the REPL. In Slime, compile a function with C-c C-c (the whole buffer with C-c C-k), switch to the REPL with C-c C-z and try it. Eventually enter the package you are working on with (in-package :your-package) or C-c ~ (slime-sync-package-and-default-directory, which will also change the default working directory to the package definition’s directory).

The feedback is immediate. There is no need to recompile everything, nor to restart any process, nor to create a main function and define command line arguments for use in the shell (which we can of course do later on when needed).

We usually need to create some data to test our function(s). This is a subsequent art of the REPL existence and it may be a new discipline for newcomers. A trick is to write the test data alongside your functions but below a #+nil feature test (or safer, +(or): it is still possible that someone pushed NIL to the *features* list) so that only you can manually compile them:

#+nil
(progn
   (defvar *test-data* nil)
   (setf *test-data* (make-instance 'foo …)))

When you load this file, *test-data* won’t exist, but you can manually create it with C-c C-c.

We can define tests functions like this.

Some do similarly inside #| … |# comments.

All that being said, keep in mind to write unit tests when time comes ;)

Inspect and describe

These two commands share the same goal, printing a description of an object, inspect being the interactive one.

(inspect *foo*)

The object is a proper list of length 3.
0. 0: :A
1. 1: :B

2. 2: :C
> q

We can also, in editors that support it, right-click on any object in the REPL and inspect them (or C-c I on the object to inspect in Slime). We are presented a screen where we can dive deep inside the data structure and even change it.

Let’s have a quick look with a more interesting structure, an object:

(defclass foo ()
    ((a :accessor foo-a :initform '(:a :b :c))
     (b :accessor foo-b :initform :b)))
;; #<STANDARD-CLASS FOO>
(make-instance 'foo)
;; #<FOO {100F2B6183}>

We right-click on the #<FOO object and choose “inspect”. We are presented an interactive pane (in Slime):

"Slime's inspector, a textual window with buttons"

When we click or press enter on the line of slot A, we inspect it further:

#<CONS {100F5E2A07}>
--------------------
A proper list:
0: :A
1: :B
2: :C

In LispWorks, we can use a graphical inspector:

"The LispWorks inspector window"

Trace

trace allows us to see when a function was called, what arguments it received, and the value it returned.

(defun factorial (n)
  (if (plusp n)
    (* n (factorial (1- n)))
    1))

To start tracing a function, just call trace with the function name (or several function names):

(trace factorial)

(factorial 2)
  0: (FACTORIAL 3)
    1: (FACTORIAL 2)
      2: (FACTORIAL 1)
        3: (FACTORIAL 0)
        3: FACTORIAL returned 1
      2: FACTORIAL returned 1
    1: FACTORIAL returned 2
  0: FACTORIAL returned 6
6

(untrace factorial)

To untrace all functions, just evaluate (untrace).

To get a list of currently traced functions, evaluate (trace) with no arguments.

In Slime we have the shortcut C-c M-t to trace or untrace a function.

If you don’t see recursive calls, that may be because of the compiler’s optimizations. Try this before defining the function to be traced:

(declaim (optimize (debug 3)))  ;; or C-u C-c C-c to compile with maximal debug settings.

The output is printed to *trace-output* (see the CLHS).

Trace options

trace accepts options. For example, you can use :break t to invoke the debugger at the start of the function, before it is called (more on break below):

(trace factorial :break t)
(factorial 2)

We can define many things in one call to trace. For instance, options that appear before the first function name to trace are global, they affect all traced functions that we add afterwards. Here, :break t is set for every function that follows: factorial, foo and bar:

(trace :break t factorial foo bar)

On the contrary, if an option comes after a function name, it acts as a local option, only for its preceding function. That’s how we first did. Below foo and bar come after, they are not affected by :break:

(trace factorial :break t foo bar)

But do you actually want to break before the function call or just after it? With :break as with many options, you can choose. These are the options for :break:

:break form  ;; before
:break-after form
:break-all form ;; before and after

form can be any form that evaluates to true.

Note that we explained the trace function of SBCL. Other implementations may have the same feature with another syntax and other option names. For example, in LispWorks it is “:break-on-exit” instead of “:break-after”, and we write (trace (factorial :break t)).

Below are some other options but first, a trick with :break.

Trace options: break

The argument to an option can be any form. Here’s a trick, on SBCL, to get the break window when we are about to call factorial with 0. (sb-debug:arg 0) refers to n, the first argument.

CL-USER> (trace factorial :break (equal 0 (sb-debug:arg 0)))
;; WARNING: FACTORIAL is already TRACE'd, untracing it first.
;; (FACTORIAL)

Running it again:

CL-USER> (factorial 3)
  0: (FACTORIAL 3)
    1: (FACTORIAL 2)
      2: (FACTORIAL 1)
        3: (FACTORIAL 0)

breaking before traced call to FACTORIAL:
   [Condition of type SIMPLE-CONDITION]

Restarts:
 0: [CONTINUE] Return from BREAK.
 1: [RETRY] Retry SLIME REPL evaluation request.
 2: [*ABORT] Return to SLIME's top level.
 3: [ABORT] abort thread (#<THREAD "repl-thread" RUNNING {1003551BC3}>)

Backtrace:
  0: (FACTORIAL 1)
      Locals:
        N = 1   <---------- before calling (factorial 0), n equals 1.

Trace options: trace on conditions, trace if called from another function

:condition enables tracing only if the condition in form evaluates to true.

:condition form
:condition-after form
:condition-all form

If :condition is specified, then trace does nothing unless Form evaluates to true at the time of the call. :condition-after is similar, but suppresses the initial printout, and is tested when the function returns. :condition-all tries both before and after.

:wherein can be super useful:

:wherein Names

If specified, Names is a function name or list of names. trace does nothing unless a call to one of those functions encloses the call to this function (i.e. it would appear in a backtrace.) Anonymous functions have string names like “DEFUN FOO”.

:report Report-Type

If Report-Type is trace (the default) then information is reported by printing immediately. If Report-Type is nil, then the only effect of the trace is to execute other options (e.g. print or break). Otherwise, Report-Type is treated as a function designator and, for each trace event, funcalled with 5 arguments: trace depth (a non-negative integer), a function name or a function object, a keyword (:enter, :exit or :non-local-exit), a stack frame, and a list of values (arguments or return values).

See also :print to enrich the trace output.

It is expected that implementations extend trace with non-standard options. And we didn’t list all available options, so please refer to your implementation’s documentation:

Tracing method invocation

In SBCL, we can use (trace foo :methods t) to trace the execution order of method combination (before, after, around methods). For example:

(trace foo :methods t)

(foo 2.0d0)
  0: (FOO 2.0d0)
    1: ((SB-PCL::COMBINED-METHOD FOO) 2.0d0)
      2: ((METHOD FOO (FLOAT)) 2.0d0)
        3: ((METHOD FOO (T)) 2.0d0)
        3: (METHOD FOO (T)) returned 3
      2: (METHOD FOO (FLOAT)) returned 9
      2: ((METHOD FOO :AFTER (DOUBLE-FLOAT)) 2.0d0)
      2: (METHOD FOO :AFTER (DOUBLE-FLOAT)) returned DOUBLE
    1: (SB-PCL::COMBINED-METHOD FOO) returned 9
  0: FOO returned 9
9

It is also possible in CCL.

See the CLOS section for a tad more information.

Interactive Trace Dialog

Both SLIME and SLY provide an interactive view for traces that features better visualization of traces, and also access to the arguments and return values in their real form, via inspectors, not just the printed representation.

trace-dialog

How it works: (the following instructions are for SLIME)

  1. Select the functions to trace using M-x slime-trace-dialog-toggle-trace bound to C-c M-t.
  2. Evaluate code that calls the traced functions.
  3. Open the trace dialog tool via M-x slime-trace-dialog bound to C-c T.
  4. The list of traced functions appear under Traced specs. Traces are fetched in batches. So use the the [refresh] button to update status information about tracing (number of available traces that can be fetched).
  5. Then use either the [fetch next batch] or [fetch all] buttons to fetch the traces. Traces appear under Traced specs after that, and you can use the SLIME inspector to visualize their data (arguments and return values).
  6. After more code that calls the traced functions is evaluated, repeat the process (go to step 4).

But, that flow can get a bit tedious, because of the separation between updating the status of the traces and fetching them. Sometimes it is better to just fetch the traces without updating the status first. We can do that invoking the command M-x slime-trace-dialog-fetch-traces bound to G. So, instead of steps 4 and 5, just press G to update the user interface.

These are some of the Emacs commands bound to useful keys:

g M-x slime-trace-dialog-fetch-status

Update information on the trace collection and traced specs.

G M-x slime-trace-dialog-fetch-traces

Fetch the next batch of outstanding (not fetched yet) traces. With a C-u prefix argument, repeat until no more outstanding traces.

C-k M-x slime-trace-dialog-clear-fetched-traces

Prompt for confirmation, then clear all traces, both fetched and outstanding.

Finally, the arguments and return values for each trace entry are interactive buttons. Clicking them opens the SLIME inspector on them. Invoking M-RET M-x slime-trace-dialog-copy-down-to-repl returns them to the REPL for manipulation . The number left of each entry indicates its absolute position in the calling order, which might differ from display order in case multiple threads call the same traced function.

M-x slime-trace-dialog-hide-details-mode hides arguments and return values so you can concentrate on the calling logic. Additionally, M-x slime-trace-dialog-autofollow-mode will automatically display additional detail about an entry when the cursor moves over it.

The interactive debugger

Whenever an exceptional situation happens (see error handling), or when you ask for it (using step or break), the interactive debugger pops up.

It presents the error message, the available actions (restarts), and the backtrace. A few remarks:

Compile with maximum debugging information

Usually your compiler will optimize things out and this will reduce the amount of information available to the debugger. For example sometimes we can’t see intermediate variables of computations. We can change the optimization choices with:

(declaim (optimize (speed 0) (space 0) (debug 3)))

and recompile our code. You can achieve the same with a handy shortcut: C-u C-c C-c: the form is compiled with maximum debug settings. You can on the contrary use a negative prefix argument (M--) to compile for speed. And use a numeric argument to set the setting to it (you should read the docstring of slime-compile-defun).

Step

step is an interactive command with similar scope than trace. This:

;; note: we copied factorial over to a file, to have more debug information.
(step (factorial 3))

gives an interactive pane with available actions (restarts) and the backtrace:

Evaluating call:
  (FACTORIAL 3)
With arguments:
  3
   [Condition of type SB-EXT:STEP-FORM-CONDITION]

Restarts:
 0: [STEP-CONTINUE] Resume normal execution   <-------------------- stepping actions
 1: [STEP-OUT] Resume stepping after returning from this function
 2: [STEP-NEXT] Step over call
 3: [STEP-INTO] Step into call
 4: [RETRY] Retry SLIME REPL evaluation request.
 5: [*ABORT] Return to SLIME's top level.
 --more--

Backtrace:
  0: (FACTORIAL 3)     <----------- press Enter to fold/unfold. Fix your code and press "r" to restart it.
      Locals:
        N = 3          <----------- want to check? Move the point here and
                                    press "e" to evaluate code on that frame.

  1: (SB-INT:SIMPLE-EVAL-IN-LEXENV (LET ((SB-IMPL::*STEP-OUT* :MAYBE)) (UNWIND-PROTECT (SB-IMPL::WITH-STEPPING-ENABLED #))) #S(SB-KERNEL:LEXENV :FUNS NIL :VARS NIL :BLOCKS NIL :TAGS NIL :TYPE-RESTRICTIONS ..
  2: (SB-INT:SIMPLE-EVAL-IN-LEXENV (STEP (FACTORIAL 3)) #<NULL-LEXENV>)
  3: (EVAL (STEP (FACTORIAL 3)))
 --more--

(again, be sure you compiled your function with maximum debug settings (see above). Otherwise, your compiler might do optimizations under the hood and you might not see useful information such as local variables, or you might not be able to step at all.)

You have many options here. If you are using Emacs (or any other editor actually), keep in mind that you have a “SLDB” menu that shows you the available actions, in addition to the step window.

NB: let's think about it, this is awesome! We just restarted our program from any point in time. If we work with long-running computations, we don't need to restart it from the start. We can change, re-compile our erroneous code and resume execution from where it is needed to pass, no more.

Stepping is precious. However, if you find yourself inspecting the behaviour of a function a lot, it may be a sign that you need to simplify it and divide it in smaller pieces.

And again, LispWorks has a graphical stepper.

TIP: the slime-breakpoints package adds stepping and breaking buttons to Slime too.

Resume a program execution from anywhere in the stack (demo)

In this video you will find a demo that shows the process explained above: how to fix a buggy function and how to resume the program execution from anywhere in the stack, without running everything from zero again. The video shows it with Emacs and Slime, the Lem editor, both with SBCL.

They key point is to use r (sldb-restart-frame) on a stack frame to restart it.

Break

A call to break makes the program enter the debugger, from which we can inspect the call stack, and do everything described above in the stepper.

Breakpoints in Slime

Look at the SLDB menu, it shows navigation keys and available actions. Of which:

Once we are in a frame and detect a suspicious behavior, we can even re-compile a function at runtime and resume the program execution from where it stopped (using the “step-continue” restart or using r (“restart frame”) on a given stackframe).

See also the Slime-star Emacs extension mentioned above to set breakpoints without code annotations.

Advise and watch

advise and watch are available in some implementations, like CCL (advise and watch) and LispWorks. They do exist in SBCL but are not exported. advise allows to modify a function without changing its source, or to do something before or after its execution, similar to CLOS method combination (before, after, around methods).

watch will signal a condition when a thread attempts to write to an object being watched. It can be coupled with the display of the watched objects in a GUI. For a certain class of bugs (someone is changing this value, but I don’t know who), this can be extremely helpful.

Cross-referencing

Your Lisp can tell you all the places where a function is referenced or called, where a global variable is set, where a macro is expanded, and so on. For example, slime-who-calls (C-c C-w C-c or the Slime > Cross-Reference menu) will show you all the places where a function is called.

See our Emacs page for a complete list of commands.

SLY stepper and SLY stickers

SLY has an improved stepper and a unique feature, stickers. You mark a piece of code, you run your code, SLY captures the results for each sticker and lets you examine the program execution interactively. It allows to see what sticker was captured, or not, so we can see at a glance the code coverage of that function call.

They are a non-intrusive alternative to print and break.

Unit tests

Last but not least, automatic testing of functions in isolation might be what you’re looking for! See the testing section and a list of test frameworks and libraries.

Remote debugging

You can have your software running on a machine over the network, connect to it and debug it from home, from your development environment.

The steps involved are to start a Swank server on the remote machine (Swank is the backend companion of Slime), create an ssh tunnel and connect to the Swank server from our editor. Then we can browse and evaluate code on the running instance transparently.

To test this, let’s define a function that prints forever.

If needed, import the dependencies first:

(ql:quickload '("swank" "bordeaux-threads"))

;; a little common lisp swank demo
;; while this program is running, you can connect to it from
;; another terminal or machine
;; and change the definition of doprint to print something else out!

(require :swank)
(require :bordeaux-threads)

(defparameter *counter* 0)

(defun dostuff ()
  (format t "hello world ~a!~%" *counter*))

(defun runner ()
  (swank:create-server :port 4006)
  (format t "we are past go!~%")
  (bt:make-thread (lambda ()
                    (loop repeat 5 do
                          (sleep 5)
                          (dostuff)
                          (incf *counter*)))
                  :name "do-stuff"))

(runner)

On the server, we can run this code with

sbcl --load demo.lisp

If you check with (bt:all-threads), you’ll see your Swank server running on port 4006, as well as the other thread ready to do stuff:

(#<SB-THREAD:THREAD "do-stuff" RUNNING {10027CEDC3}>
 #<SB-THREAD:THREAD "Swank Sentinel" waiting on:
      #<WAITQUEUE  {10027D0003}>
    {10027CE8B3}>
 #<SB-THREAD:THREAD "Swank 4006" RUNNING {10027CEB63}>
 #<SB-THREAD:THREAD "main thread" RUNNING {1007C40393}>)

We do port forwarding on our development machine:

ssh -L4006:127.0.0.1:4006 username@example.com

this will securely forward port 4006 on the server at example.com to our local computer’s port 4006 (Swank only accepts connections from localhost).

We connect to the running Swank with M-x slime-connect, choosing localhost for the host and port 4006.

We can write new code:

(defun dostuff ()
  (format t "goodbye world ~a!~%" *counter*))
(setf *counter* 0)

and eval it as usual with C-c C-c or M-x slime-eval-region for instance. The output should change.

That’s how Ron Garret debugged the Deep Space 1 spacecraft from the earth in 1999:

We were able to debug and fix a race condition that had not shown up during ground testing. (Debugging a program running on a $100M piece of hardware that is 100 million miles away is an interesting experience. Having a read-eval-print loop running on the spacecraft proved invaluable in finding and fixing the problem.

References

Page source: debugging.md

T
O
C