Consider reporting exception cause(s)

[lread]

Issue

When an uncaught exception occurs, babashka displays the exception but not the cause(s).
This can make troubleshooting difficult.

Realworld Context

We were diagnosing an Etaoin issue.
If Bashashka shared the root cause of the thrown exception, our job would have been easier.

Exploring Current Behaviour

We'll explore current behaviour with a test.clj:

(ns test)

(defn fn3 []
  (throw (ex-info "fn3 badnesss happened" {:fn3 :data})))

(defn fn2 []
  (try
    (fn3)
    (catch Exception ex
      (throw (ex-info "fn2 wrapping ex" {:fn2 :data} ex)))))

(defn fn1 []
  (try
    (fn2)
    (catch Exception ex
      (throw (ex-info "fn1 wrapping ex" {:fn1 :data} ex)))))

(fn1)

Babashka Behaviour

❯ bb --version
babashka v1.2.174

Default

❯ bb test.clj
----- Error --------------------------------------------------------------------
Type:     clojure.lang.ExceptionInfo
Message:  fn1 wrapping ex
Data:     {:fn1 :data}
Location: /home/lee/proj/oss/-play/bb-cause/test.clj:16:7

----- Context ------------------------------------------------------------------
12: (defn fn1 []
13:   (try
14:     (fn2)
15:     (catch Exception ex
16:       (throw (ex-info "fn1 wrapping ex" {:fn1 :data} ex)))))
          ^--- fn1 wrapping ex
17: 
18: (fn1)

----- Stack trace --------------------------------------------------------------
test/fn1 - /home/lee/proj/oss/-play/bb-cause/test.clj:16:7
test/fn1 - /home/lee/proj/oss/-play/bb-cause/test.clj:12:1
test     - /home/lee/proj/oss/-play/bb-cause/test.clj:18:1

We get info on the exception but no info on the cause(s).

With --debug

Does --debug provide more info?

❯ bb --debug test.clj
----- Error --------------------------------------------------------------------
Type:     clojure.lang.ExceptionInfo
Message:  fn1 wrapping ex
Data:     {:fn1 :data}
Location: /home/lee/proj/oss/-play/bb-cause/test.clj:16:7

----- Context ------------------------------------------------------------------
12: (defn fn1 []
13:   (try
14:     (fn2)
15:     (catch Exception ex
16:       (throw (ex-info "fn1 wrapping ex" {:fn1 :data} ex)))))
          ^--- fn1 wrapping ex
17: 
18: (fn1)

----- Stack trace --------------------------------------------------------------
test/fn1 - /home/lee/proj/oss/-play/bb-cause/test.clj:16:7
test/fn1 - /home/lee/proj/oss/-play/bb-cause/test.clj:12:1
test     - /home/lee/proj/oss/-play/bb-cause/test.clj:18:1

----- Exception ----------------------------------------------------------------
clojure.lang.ExceptionInfo: fn1 wrapping ex
{:type :sci/error, :line 16, :column 7, :message "fn1 wrapping ex", :sci.impl/callstack #object[clojure.lang.Volatile 0x566d2f95 {:status :ready, :val ({:line 18, :column 1, :ns #object[sci.lang.Namespace 0x4d886fb6 "test"], :file "/home/lee/proj/oss/-play/bb-cause/test.clj", :sci.impl/f-meta {:name fn1, :ns #object[sci.lang.Namespace 0x4d886fb6 "test"], :file "/home/lee/proj/oss/-play/bb-cause/test.clj", :arglists ([]), :line 12, :column 1}} {:line 18, :column 1, :ns #object[sci.lang.Namespace 0x4d886fb6 "test"], :file "/home/lee/proj/oss/-play/bb-cause/test.clj", :sci.impl/f-meta {:name fn1, :ns #object[sci.lang.Namespace 0x4d886fb6 "test"], :file "/home/lee/proj/oss/-play/bb-cause/test.clj", :arglists ([]), :line 12, :column 1}} {:line 16, :column 7, :ns #object[sci.lang.Namespace 0x4d886fb6 "test"], :file "/home/lee/proj/oss/-play/bb-cause/test.clj", :special true})}], :file "/home/lee/proj/oss/-play/bb-cause/test.clj"}
 at sci.impl.utils$rethrow_with_location_of_node.invokeStatic (utils.cljc:129)
    sci.impl.analyzer$analyze_throw$reify__4264.eval (analyzer.cljc:968)
    sci.impl.evaluator$eval_try$fn__3570.invoke (evaluator.cljc:97)
    clojure.lang.PersistentVector.reduce (PersistentVector.java:343)
    clojure.core$reduce.invokeStatic (core.clj:6885)
    sci.impl.evaluator$eval_try.invokeStatic (evaluator.cljc:103)
    sci.impl.analyzer$analyze_try$reify__4256.eval (analyzer.cljc:951)
    sci.impl.fns$fun$arity_0__1162.invoke (fns.cljc:106)
    sci.lang.Var.invoke (lang.cljc:198)
    sci.impl.analyzer$return_call$reify__4496.eval (analyzer.cljc:1402)
    sci.impl.interpreter$eval_form.invokeStatic (interpreter.cljc:40)
    sci.impl.interpreter$eval_string_STAR_.invokeStatic (interpreter.cljc:62)
    sci.core$eval_string_STAR_.invokeStatic (core.cljc:270)
    babashka.main$exec$fn__31074$fn__31112$fn__31113.invoke (main.clj:1042)
    babashka.main$exec$fn__31074$fn__31112.invoke (main.clj:1042)
    babashka.main$exec$fn__31074.invoke (main.clj:1032)
    clojure.lang.AFn.applyToHelper (AFn.java:152)
    clojure.lang.AFn.applyTo (AFn.java:144)
    clojure.core$apply.invokeStatic (core.clj:667)
    clojure.core$with_bindings_STAR_.invokeStatic (core.clj:1990)
    clojure.core$with_bindings_STAR_.doInvoke (core.clj:1990)
    clojure.lang.RestFn.invoke (RestFn.java:425)
    babashka.main$exec.invokeStatic (main.clj:824)
    babashka.main$main.invokeStatic (main.clj:1155)
    babashka.main$main.doInvoke (main.clj:1124)
    clojure.lang.RestFn.applyTo (RestFn.java:137)
    clojure.core$apply.invokeStatic (core.clj:667)
    babashka.main$_main$f__31186__auto____31196.invoke (main.clj:1194)
    clojure.lang.AFn.run (AFn.java:22)
    java.lang.Thread.run (Thread.java:1589)
    com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine (PlatformThreads.java:775)
    com.oracle.svm.core.posix.thread.PosixPlatformThreads.pthreadStartRoutine (PosixPlatformThreads.java:203)

Applying --debug gives us more inner details, but not on the exception cause(s).

Clojure Behaviour

Let's take a look at what Clojure does.

❯ clojure --version
Clojure CLI version 1.11.1.1252

Default

❯ clojure -M test.clj                
Execution error (ExceptionInfo) at test/fn3 (test.clj:4).
fn3 badnesss happened

Full report at:
/tmp/clojure-2455531978435573272.edn

Clojure reports on the root cause only by default (with full report to a file).
The Clojure core team feels that the root cause is typically most interesting part of the exception.
What it does not give you is the context that the exception and other causes would provide.

With --report stderr

Let's tell Clojure to send the full report to the terminal instead:

❯ clojure -M --report stderr test.clj
{:clojure.main/message
 "Execution error (ExceptionInfo) at test/fn3 (test.clj:4).\nfn3 badnesss happened\n",
 :clojure.main/triage
 {:clojure.error/class clojure.lang.ExceptionInfo,
  :clojure.error/line 4,
  :clojure.error/cause "fn3 badnesss happened",
  :clojure.error/symbol test/fn3,
  :clojure.error/source "test.clj",
  :clojure.error/phase :execution},
 :clojure.main/trace
 {:via
  [{:type clojure.lang.Compiler$CompilerException,
    :message
    "Syntax error macroexpanding at (/home/lee/proj/oss/-play/bb-cause/test.clj:18:1).",
    :data
    {:clojure.error/phase :execution,
     :clojure.error/line 18,
     :clojure.error/column 1,
     :clojure.error/source
     "/home/lee/proj/oss/-play/bb-cause/test.clj"},
    :at [clojure.lang.Compiler load "Compiler.java" 7665]}
   {:type clojure.lang.ExceptionInfo,
    :message "fn1 wrapping ex",
    :data {:fn1 :data},
    :at [test$fn1 invokeStatic "test.clj" 16]}
   {:type clojure.lang.ExceptionInfo,
    :message "fn2 wrapping ex",
    :data {:fn2 :data},
    :at [test$fn2 invokeStatic "test.clj" 10]}
   {:type clojure.lang.ExceptionInfo,
    :message "fn3 badnesss happened",
    :data {:fn3 :data},
    :at [test$fn3 invokeStatic "test.clj" 4]}],
  :trace
  [[test$fn3 invokeStatic "test.clj" 4]
   [test$fn3 invoke "test.clj" 3]
   [test$fn2 invokeStatic "test.clj" 8]
   [test$fn2 invoke "test.clj" 6]
   [test$fn1 invokeStatic "test.clj" 14]
   [test$fn1 invoke "test.clj" 12]
   [test$eval149 invokeStatic "test.clj" 18]
   [test$eval149 invoke "test.clj" 18]
   [clojure.lang.Compiler eval "Compiler.java" 7194]
   [clojure.lang.Compiler load "Compiler.java" 7653]
   [clojure.lang.Compiler loadFile "Compiler.java" 7591]
   [clojure.main$load_script invokeStatic "main.clj" 475]
   [clojure.main$script_opt invokeStatic "main.clj" 535]
   [clojure.main$script_opt invoke "main.clj" 530]
   [clojure.main$main invokeStatic "main.clj" 664]
   [clojure.main$main doInvoke "main.clj" 616]
   [clojure.lang.RestFn applyTo "RestFn.java" 137]
   [clojure.lang.Var applyTo "Var.java" 705]
   [clojure.main main "main.java" 40]],
  :cause "fn3 badnesss happened",
  :data {:fn3 :data},
  :phase :execution}}

Execution error (ExceptionInfo) at test/fn3 (test.clj:4).
fn3 badnesss happened

Cool, the report shows all of the causes under :via giving us full context.

Proposals

There are a many viable ways to address this issue, think of the following options as initial ideas.

Option 1 - Do nothing

Always an option, right?

Option 2 - Add a causes section

Summarize all causes, a mockup of a terse report:

----- Causes --------------------------------------------------------------
usr/fn2 - /home/lee/proj/oss/-play/bb-cause/test.clj:10:7
 clojure.lang.ExceptionInfo "fn2 wrapping ex" {:fn2 :data}
usr/fn3 - /home/lee/proj/oss/-play/bb-cause/test.clj:4:3
 clojure.lang.ExceptionInfo "fn3 wrapping ex" {:fn3 :data}

Option 3 - Show the exception and its root cause

Perhaps the most interesting parts of an exception are the exception and its root cause.

Bb is already showing the exception.
It could by default also show the root cause, with the context if possible.

----- Root Cause ---------------------------------------------------------------
Type:     clojure.lang.ExceptionInfo
Message:  fn3 badnesss happened
Data:     {:fn3 :data}
Location: /home/lee/proj/oss/-play/bb-cause/test.clj:4:3

----- Root Cause Context -------------------------------------------------------
01: (ns test)
02:
03: (defn fn3 []
04:   (throw (ex-info "fn3 badnesss happened" {:fn3 :data})))
      ^--- fn3 badness happened
05:
06: (defn fn2 []
07:   (try

Note: if the root cause came from some Java lib, we'd not show the context.

The user might also be interested in other causes, so other options might come into play, but I think maybe showing the exception and root cause might typically be enough info.

Option 4 - Offer full edn report like Clojure does

Mimic Clojure edn report (in a way that makes sense for bb).
Write report to tmp file with option to spit it to terminal.

Option 5 - Spit out causes for --debug

Also spit out info on exception causes when user invokes bb with --debug.

Option n -

There are many ways to solve this, could convert this to a discussion if that makes sense.

[borkdude]

I want to display info about the root cause a try.

[borkdude]

Experimental commit in https://github.com/babashka/babashka/tree/issue-1515
It's probably not the final thing yet. Showing the root context isn't possible since only the stacktrace is preserved when you request that with ^:sci/stacktrace:

(ns test)

(defn fn3 []
  (throw (ex-info "fn3 badnesss happened" {:fn3 :data})))

(defn fn2 []
  (try
    (fn3)
    (catch ^:sci/error Exception ex
      (throw (ex-info "fn2 wrapping ex" {:fn2 :data} ex)))))

(defn fn1 []
  (try
    (fn2)
    (catch ^:sci/error Exception ex
      (throw (ex-info "fn1 wrapping ex" {:fn1 :data} ex)))))

(fn1)