Postmortem

A simple debug library for Clojure(Script) that features data-oriented logging and tracing

Features

• Postmortem strongly encourages the data-oriented debugging approach
  • Logs are just Clojure data, so you can use DataScript, REBL or whatever tools for more sophisticated log analysis
• Integration with transducers enables various flexible logging strategies
• Instrumentation on vars makes it easier to debug functions without touching their code
• Supports most of Clojure platforms (namely, Clojure, ClojureScript, self-hosted ClojureScript and Babashka)
• Possible to use for debugging multi-threaded programs

Synopsis

(require '[postmortem.core :as pm]
         '[postmortem.xforms :as xf])

(defn sum [n]
  (loop [i n sum 0]
    (pm/dump :sum (xf/take-last 5))
    (if (= i 0)
      sum
      (recur (dec i) (+ i sum)))))

(sum 100) ;=> 5050

(pm/log-for :sum)
;=> [{:n 100, :i 4, :sum 5040}
;    {:n 100, :i 3, :sum 5044}
;    {:n 100, :i 2, :sum 5047}
;    {:n 100, :i 1, :sum 5049}
;    {:n 100, :i 0, :sum 5050}]


(require '[postmortem.instrument :as pi])

(defn broken-factorial [n]
  (cond (= n 0) 1
        (= n 7) (/ (broken-factorial (dec n)) 0) ;; <- BUG HERE!!
        :else (* n (broken-factorial (dec n)))))

(pi/instrument `broken-factorial
               {:xform (comp (xf/take-until :err) (xf/take-last 5))})

(broken-factorial 10)
;; Execution error (ArithmeticException) at user/broken-factorial.
;; Divide by zero

(pm/log-for `broken-factorial)
;=> [{:args (3), :ret 6}
;    {:args (4), :ret 24}
;    {:args (5), :ret 120}
;    {:args (6), :ret 720}
;    {:args (7), :err #error {:cause "Divide by zero" ...}}]

Table of Contents

• Requirements
• Installation
• Usage
  • Basic usage
    • spy>> / log-for
    • reset-key! / completed? / keys
    • logs / stats / reset!
    • spy>
    • dump
  • Integration with transducers
  • Sessions
    • Handling sessions
    • Attaching a transducer
    • void-session
    • Indexed sessions
    • make-unsafe-session
  • Simple logger
  • Instrumentation
• Related works

Requirements

• Clojure 1.8+, or
• ClojureScript 1.10.238+, or
• Babashka v0.10.163+, or
• Planck 2.24.0+, or
• Lumo 1.10.1+

We have only tested on the above environments, but you could possibly use the library on some older versions of the ClojureScript runtimes as well.

Installation

Add the following to your project dev dependencies or the :user profile in ~/.lein/profiles.clj:

Usage

Basic usage

spy>> / log-for

In Postmortem, spy>> and log-for are two of the most fundamental functions. spy>> is for logging data, and log-for is for retrieving logged data.

spy>> is used as follows:

(require '[postmortem.core :as pm])

(defn sum [n]
  (loop [i 0 sum 0]
    (if (> i n)
      sum
      (recur (inc i)
             (pm/spy>> :sum (+ i sum))))))

(spy>> <key> <expr>) stores the value of the <expr> to a log entry for the key <key> each time the spy>> form is evaluated. In the above example, (pm/spy>> :sum (+ i sum)) will store intermediate results of summation for each iteration to the log entry for the key :sum.

(log-for <key>), on the other hand, retrieves all the logged data stored in the log entry for the key <key>. In the following example, (log-for :sum) results in [0 1 3 6 10 15], which corresponds to the intermediate summations from 0 to 5:

(sum 5)
;=> 15

(pm/log-for :sum)
;=> [0 1 3 6 10 15]

Any Clojure data can be used as a log entry key, such as keywords (as in the above examples), symbols, integers, strings or whatever. In fact, you can even use a runtime value as a key, as well as literal values, and thus entry keys can also be used as a handy way to collect and group log data:

(defn f [n]
  (pm/spy>> [:f (even? n)] (inc n)))

(mapv f [1 2 3 4 5])
;=> [2 3 4 5 6]
(pm/log-for [:f true])
;=> [3 5]
(pm/log-for [:f false])
;=> [2 4 6]

reset-key! / completed? / keys

To clear the logged data at the log entry <key>, call (reset-key! <key>):

(pm/log-for :sum)
;=> [0 1 3 6 10 15]

(pm/reset-key! :sum)

(pm/log-for :sum)
;=> nil

Note that once you call log-for for a key k, the log entry for k will be completed. A completed log entry will not be changed anymore until you call reset-key! for the log entry k:

(pm/spy>> :foobar 1)
(pm/spy>> :foobar 2)
(pm/log-for :foobar)
;=> [1 2]

(pm/spy>> :foobar 3)
(pm/spy>> :foobar 4)
(pm/log-for :foobar)
;=> [1 2]

(pm/reset-key! :foobar)

(pm/spy>> :foobar 3)
(pm/spy>> :foobar 4)
(pm/log-for :foobar)
;=> [3 4]

You can check if a log entry has been completed using (completed? <key>):

(pm/spy>> :barbaz 10)
(pm/spy>> :barbaz 20)
(pm/completed? :barbaz)
;=> false

(pm/log-for :barbaz)
;=> [10 20]
(pm/completed? :barbaz)
;=> true

(pm/reset-key! :barbaz)
(pm/completed? :barbaz)
;=> false

If you want to know what log entry keys have been logged so far without completing any log entry, keys suits your desire:

(pm/spy>> :bazqux 10)
(pm/spy>> :quxquux 20)

(pm/keys)
;=> #{:bazqux :quxquux}
(pm/completed? :bazqux)
;=> false
(pm/completed? :quxquux)
;=> false

logs / stats / reset!

You can also logs some data to more than one log entries at once. In such a case, logs is more useful to look into the whole log data than just calling log-for for each log entry:

(defn sum [n]
  (loop [i 0 sum 0]
    (pm/spy>> :i i)
    (if (> i n)
      sum
      (recur (inc i)
             (pm/spy>> :sum (+ i sum))))))

(sum 5)
;=> 15

(pm/logs)
;=> {:i [0 1 2 3 4 5 6],
;    :sum [0 1 3 6 10 15]}

Alternatively, stats helps you grasp how many log items have been stored so far for each log entry key, without seeing the actual log data:

(defn sum [n]
  (loop [i 0 sum 0]
    (pm/spy>> :i i)
    (if (> i n)
      sum
      (recur (inc i)
             (pm/spy>> :sum (+ i sum))))))

(sum 5) ;=> 15

(pm/stats)
;=> {:i 7 :sum 6}

;; As compared to:
;; (pm/logs)
;; => {:i [0 1 2 3 4 5 6],
;      :sum [0 1 3 6 10 15]}

Note that once you call stats, all the log entries will be completed, as with the logs fn.

For those who are using older versions (<= 0.4.0), pm/stats is the new name for pm/frequencies added in 0.4.1. They can be used totally interchangeably. Now pm/stats is recommended for primary use.

Analogous to logs, reset! is useful to clear the whole log data at a time, rather than clearing each individual log entry one by one calling reset-key!:

(pm/logs)
;=> {:i [0 1 2 3 4 5 6],
;    :sum [0 1 3 6 10 15]}

(pm/reset!)

(pm/logs)
;=> {}

spy>

spy>> has a look-alike cousin named spy>. They have no semantic difference, except that spy> is primarily intended to be used in thread-first contexts and therefore takes the log data as its first argument while spy>> is mainly intended to be used in thread-last contexts and therefore takes the log data as its last argument.

For example, the following two expressions behave in exactly the same way:

;; thread-last version
(->> (+ 1 2)
     (pm/spy>> :sum)
     (* 10)
     (pm/spy>> :prod))

;; thread-first version
(-> (+ 1 2)
    (pm/spy> :sum)
    (* 10)
    (pm/spy> :prod))

dump

dump is another convenient tool to take snapshots of the values of local bindings.

(dump <key>) stores a local environment map to the log entry <key>. A local environment map is a map of keywords representing local names in the scope at the callsite, to the values that the corresponding local names are bound to.

The example code below shows how dump logs the values of the local bindings at the callsite (namely, n, i and sum) for each iteration:

(defn sum [n]
  (loop [i 0 sum 0]
    (pm/dump :sum)
    (if (> i n)
      sum
      (recur (inc i) (+ i sum)))))

(sum 5)
;=> 15

(pm/log-for :sum)
;=> [{:n 5, :i 0, :sum 0}
;    {:n 5, :i 1, :sum 0}
;    {:n 5, :i 2, :sum 1}
;    {:n 5, :i 3, :sum 3}
;    {:n 5, :i 4, :sum 6}
;    {:n 5, :i 5, :sum 10}
;    {:n 5, :i 6, :sum 15}]

Integration with transducers

After reading this document so far, you may wonder what if the loop would be repeated millions of times? What if you only need the last few log items out of them?

That's where Postmortem really shines. It achieves extremely flexible customizability of logging strategies by integration with transducers (If you are not familiar with transducers, we recommend that you take a look at the official reference first).

Postmortem's logging operators (spy>>, spy> and dump) are optionally takes a transducer after the log entry key. When you call (spy>> <key> <xform> <expr>), the transducer <xform> controls whether or not the given data will be logged and/or what data will actually be stored.

For example:

(defn sum1 [n]
  (loop [i 0 sum 0]
    (if (> i n)
      sum
      (r