Logging and Debugging in Clojure – Followup (Complete Tracing)

Ayal Gelles / December 17th, 2009 § 3 comments

Following some interesting comments on our previous blog post we thought it would be appropriate to emphasize the added value of our logging approach (which we now realize we should call “complete tracing”) compared to the others mentioned. To demonstrate, let’s observe some simple code for manipulating sets. As background, a partition is defined to be a set of mutually disjoint sets. Each of the sets in a partition is usually called a class. For example: If this is the partition #{#{1 2} #{3 4 5}} then #{1 2} is a class. What makes this a partition is that no two classes share a member.

Now, consider the following functions that carry out the task of “linking” two simple elements (the ones that belong to the classes which are inside the partition) to a given partition:

(defn add-to-class [partition class el]
  (conj (disj partition class) (conj class el)))

(defn containing-class [partition el]
  (first (for [class partition :when (some #{el} class)] class)))

(defn link-elements-in-partition [partition el1 el2]
  (let [c1 (containing-class partition el1)
        c2 (containing-class partition el2)]
    (cond

      (and (not c1) (not c2)) ; neither are in any class (we add it to c1)
      (conj partition #{el1 el2})

      (and c1 (not c2)) ; el1 was found in a class (c1) while el2 was not (we add it to c2)
      (add-to-class partition c1 el2)

      (and c2 (not c1)) ; el2 was found in a class (c2) while el1 was not
      (add-to-class partition c2 el1)

      (and (and c1 c2) (not= c2 c2)) ; both were found in different classes (we join them)
      (conj (disj partition c1 c2) (union c1 c2))

      :else
      partition)))

For example, (link-elements-in-partition #{#{1 2} #{3} #{4 5}} 2 3) should return #{#{1 2 3} #{4 5}}) and (link-elements-in-partition #{#{1 2} #{3 4 5}} 3 2) should return #{1 2 3 4 5}. Yet if you try to run this code it returns #{#{1 2} #{3 4 5}}. There is a bug.

Let us examine the output of the clojure-contrib trace library (after re-defining the functions with “deftrace”) and see if it can help us find the source of the problem.

TRACE t32800: (link-elements-in-partition #{#{1 2} #{3 4 5}} 3 2)
TRACE t32801: | (containing-class #{#{1 2} #{3 4 5}} 3)
TRACE t32801: | => #{3 4 5}
TRACE t32802: | (containing-class #{#{1 2} #{3 4 5}} 2)
TRACE t32802: | => #{1 2}
TRACE t32800: => #{#{1 2} #{3 4 5}}
Hmmm… not much information to work with. The problem must be somewhere in the big “cond” clause and the “trace” just doesn’t dig in to it.
This is where code walking comes in handy. By merely using defn-ctrace instead of deftrace you get our complete internal tracing functionality. Then, run the following code:
(start-complete-tracing)
(link-elements-in-partition #{#{1 2} #{3 4 5}} 3 2)
(end-complete-tracing-and-print-org-mode)
That last function prints a string value that represents the trace tree, the format of this string is designed for use with emacs’ org-mode, which gives really great subtree expand/collapse capabilities. Here is the full result: http://gist.github.com/260408

Just to quickly see how it would have helped us solve the issue, here is a snippet of the complete tracing result (from within the cond expression), with lines slightly re-ordered to give a similar effect to using org-mode.

**** (and (and c1 c2) (not= c2 c2))
**** `=> Result:
false
***** (and c1 c2)
***** `=> Result:
#{1 2}
****** c1
****** `=> Result:
#{3 4 5}
****** c2
****** `=> Result:
#{1 2}
***** (not= c2 c2)
***** `=> Result:
false
****** c2
****** `=> Result:
#{1 2}
****** c2
****** `=> Result:
#{1 2}

It is obvious that the top condition in this subtree should have evaluated “true” – and it is also obvious that the reason it fails to do so is the (not= c2 c2) part of it. Tracing even into that expression leaves no room for doubt – it was a typo, it should have been (not= c1 c2).

This library has already saved us days of debugging time and we are continuing to develop it – fixing bugs, adding support for more forms (you’d want to see a different form of tracing for if, do, cond, and, etc), writing some emacs utils and cleaning up the code. If you want to dive into some alpha stage code, feel free to take a look at http://github.com/theWE/thewe/blob/master/robot/ctrace.clj. We will continue to polish this project in the upcoming period of time and plan to properly package it and release it at the proper time.

This website uses IntenseDebate comments, but they are not currently loaded because either your browser doesn't support JavaScript, or they didn't load fast enough.

§ 3 Responses to “Logging and Debugging in Clojure – Followup (Complete Tracing)”