Preserve stack trace when errors occur #1322

pinkfrog9 · 2022-07-17T14:22:41Z

How to reproduce,

In a simple define a bb task as

(defn some-task [] (nil))

Run from the command line, the output is:

The text was updated successfully, but these errors were encountered:

borkdude · 2022-07-17T14:23:06Z

Thanks!

lread · 2022-08-06T18:26:33Z

As promised on Slack a few days ago, my related experience.
Hopefully, it helps! Lemme know.

My bb tasks typically delegate to bb scripts with -mains.
When I hit an exception running a task, to diagnose, I find myself invoking the script instead.

Minimal repro

Empty dir with:

bb.edn:

{:paths ["."]
 :tasks {atask {:task some-script/-main
                :doc "testing 123"}}}

some_script.clj:

(ns some-script)

(defn -main[& _args]
  (println "something bad is about to happen")
  (/ 1 0))

(when (= *file* (System/getProperty "babashka.file"))
  (apply -main *command-line-args*))

❯ bb --version
babashka v0.9.161

Invoke Task

❯ bb atask
something bad is about to happen
----- Error --------------------------------------------------------------------
Type:     java.lang.ArithmeticException
Message:  Divide by zero

Observation: succinct error, maybe I need to use --debug to pinpoint.

Invoke Task with --debug

❯ bb --debug atask

 ;; deps

(ns user-b3a54edc-6b16-4f7a-b338-cf37d7a57095 )
(require '[babashka.tasks #_#_:refer [log]])
(when-not (resolve 'clojure)
  ;; we don't use refer so users can override this
  (intern *ns* 'clojure babashka.tasks/clojure))

(when-not (resolve 'shell)
  (intern *ns* 'shell babashka.tasks/shell))

(when-not (resolve 'current-task)
  (intern *ns* 'current-task babashka.tasks/current-task))

(when-not (resolve 'run)
  (intern *ns* 'run babashka.tasks/run))

(when-not (resolve 'exec)
  (intern *ns* 'exec @(var babashka.tasks/exec)))

nil

(when-not (resolve 'some-script/-main) (require (quote some-script)))
(def atask (binding [
  babashka.tasks/*task* '{:name atask, :task some-script/-main, :doc "testing 123"}]
  nil
(apply some-script/-main *command-line-args*))) atask


something bad is about to happen
----- Error --------------------------------------------------------------------
Type:     java.lang.ArithmeticException
Message:  Divide by zero

----- Exception ----------------------------------------------------------------
java.lang.ArithmeticException: Divide by zero
 at clojure.lang.Numbers.divide (Numbers.java:190)
    clojure.core$_SLASH_.invokeStatic (core.clj:1029)
    clojure.core$_SLASH_.invoke (core.clj:1022)
    sci.impl.analyzer$return_call$reify__5211.eval (analyzer.cljc:1205)
    sci.impl.analyzer$return_do$reify__4236.eval (analyzer.cljc:139)
    sci.impl.fns$fun$arity_0__3012.doInvoke (fns.cljc:83)
    clojure.lang.RestFn.invoke (RestFn.java:397)
    clojure.lang.AFn.applyToHelper (AFn.java:152)
    clojure.lang.RestFn.applyTo (RestFn.java:132)
    clojure.core$apply.invokeStatic (core.clj:667)
    clojure.core$apply.invoke (core.clj:662)
    sci.lang.Var.invoke (lang.cljc:178)
    sci.impl.analyzer$return_call$reify__5211.eval (analyzer.cljc:1205)
    sci.impl.analyzer$return_do$reify__4236.eval (analyzer.cljc:139)
    sci.impl.evaluator$eval_try.invokeStatic (evaluator.cljc:123)
    sci.impl.analyzer$analyze_try$reify__4959.eval (analyzer.cljc:774)
    sci.impl.analyzer$return_do$reify__4236.eval (analyzer.cljc:139)
    sci.impl.evaluator$eval_let.invokeStatic (evaluator.cljc:71)
    sci.impl.analyzer$analyze_let_STAR_$reify__4874.eval (analyzer.cljc:507)
    sci.impl.evaluator$eval_def.invokeStatic (evaluator.cljc:75)
    sci.impl.analyzer$analyze_def$reify__4891.eval (analyzer.cljc:573)
    sci.impl.interpreter$eval_form.invokeStatic (interpreter.cljc:39)
    sci.impl.interpreter$eval_string_STAR_.invokeStatic (interpreter.cljc:61)
    sci.core$eval_string_STAR_.invokeStatic (core.cljc:261)
    babashka.main$exec$fn__31015$fn__31016.invoke (main.clj:955)
    babashka.main$exec$fn__31015.invoke (main.clj:955)
    babashka.main$exec.invokeStatic (main.clj:945)
    babashka.main$main.invokeStatic (main.clj:1052)
    babashka.main$main.doInvoke (main.clj:1027)
    clojure.lang.RestFn.applyTo (RestFn.java:137)
    clojure.core$apply.invokeStatic (core.clj:667)
    babashka.main$_main.invokeStatic (main.clj:1085)
    babashka.main$_main.doInvoke (main.clj:1077)
    clojure.lang.RestFn.applyTo (RestFn.java:137)
    babashka.main.main (:-1)

Observation: Stacktrace does not really help me find what threw.

Invoke Script

bb some_script.clj
something bad is about to happen
----- Error --------------------------------------------------------------------
Type:     java.lang.ArithmeticException
Message:  Divide by zero
Location: /Users/lee/proj/oss/-verify/bb-ex/some_script.clj:5:3

----- Context ------------------------------------------------------------------
1: (ns some-script)
2: 
3: (defn -main[& _args]
4:   (println "something bad is about to happen")
5:   (/ 1 0))
     ^--- Divide by zero
6: 
7: (when (= *file* (System/getProperty "babashka.file"))
8:   (apply -main *command-line-args*))

----- Stack trace --------------------------------------------------------------
clojure.core//     - <built-in>
some-script        - /Users/lee/proj/oss/-verify/bb-ex/some_script.clj:5:3
clojure.core/apply - <built-in>
some-script        - /Users/lee/proj/oss/-verify/bb-ex/some_script.clj:8:3

Observation: Ok, good stuff I can pinpoint what threw.

Invoke Script with --debug

Let's see if --debug gives us more:

❯ bb --debug some_script.clj
something bad is about to happen
----- Error --------------------------------------------------------------------
Type:     java.lang.ArithmeticException
Message:  Divide by zero
Location: /Users/lee/proj/oss/-verify/bb-ex/some_script.clj:5:3

----- Context ------------------------------------------------------------------
1: (ns some-script)
2: 
3: (defn -main[& _args]
4:   (println "something bad is about to happen")
5:   (/ 1 0))
     ^--- Divide by zero
6: 
7: (when (= *file* (System/getProperty "babashka.file"))
8:   (apply -main *command-line-args*))

----- Stack trace --------------------------------------------------------------
clojure.core//     - <built-in>
some-script        - /Users/lee/proj/oss/-verify/bb-ex/some_script.clj:5:3
clojure.core/apply - <built-in>
some-script        - /Users/lee/proj/oss/-verify/bb-ex/some_script.clj:8:3

----- Exception ----------------------------------------------------------------
clojure.lang.ExceptionInfo: Divide by zero
{:type :sci/error, :line 5, :column 3, :message "Divide by zero", :sci.impl/callstack #object[clojure.lang.Volatile 0x629d210f {:status :ready, :val ({:line 8, :column 3, :ns #object[sci.lang.Namespace 0x54517d60 "some-script"], :file "/Users/lee/proj/oss/-verify/bb-ex/some_script.clj", :sci.impl/f-meta {:name apply, :arglists ([f args] [f x args] [f x y args] [f x y z args] [f a b c d & args]), :doc "Applies fn f to the argument list formed by prepending intervening arguments to args.", :sci/built-in true, :ns #object[sci.lang.Namespace 0x20670936 "clojure.core"]}} {:line 5, :column 3, :ns #object[sci.lang.Namespace 0x54517d60 "some-script"], :file "/Users/lee/proj/oss/-verify/bb-ex/some_script.clj", :sci.impl/f-meta {:name /, :arglists ([x] [x y] [x y & more]), :doc "If no denominators are supplied, returns 1/numerator,\n  else returns numerator divided by all of the denominators.", :sci/built-in true, :ns #object[sci.lang.Namespace 0x20670936 "clojure.core"], :sci.impl/inlined #object[clojure.core$_SLASH_ 0x336d770e "clojure.core$_SLASH_@336d770e"]}})}], :file "/Users/lee/proj/oss/-verify/bb-ex/some_script.clj"}
 at sci.impl.utils$rethrow_with_location_of_node.invokeStatic (utils.cljc:122)
    sci.impl.analyzer$return_call$reify__5211.eval (analyzer.cljc:1205)
    sci.impl.analyzer$return_do$reify__4236.eval (analyzer.cljc:139)
    sci.impl.fns$fun$arity_0__3012.doInvoke (fns.cljc:83)
    clojure.lang.RestFn.invoke (RestFn.java:397)
    clojure.lang.AFn.applyToHelper (AFn.java:152)
    clojure.lang.RestFn.applyTo (RestFn.java:132)
    clojure.core$apply.invokeStatic (core.clj:667)
    clojure.core$apply.invoke (core.clj:662)
    sci.lang.Var.invoke (lang.cljc:178)
    sci.impl.analyzer$return_call$reify__5211.eval (analyzer.cljc:1205)
    sci.impl.analyzer$return_if$reify__4922.eval (analyzer.cljc:666)
    sci.impl.interpreter$eval_form.invokeStatic (interpreter.cljc:39)
    sci.impl.interpreter$eval_string_STAR_.invokeStatic (interpreter.cljc:61)
    sci.core$eval_string_STAR_.invokeStatic (core.cljc:261)
    babashka.main$exec$fn__31015$fn__31016.invoke (main.clj:955)
    babashka.main$exec$fn__31015.invoke (main.clj:955)
    babashka.main$exec.invokeStatic (main.clj:945)
    babashka.main$main.invokeStatic (main.clj:1052)
    babashka.main$main.doInvoke (main.clj:1027)
    clojure.lang.RestFn.applyTo (RestFn.java:137)
    clojure.core$apply.invokeStatic (core.clj:667)
    babashka.main$_main.invokeStatic (main.clj:1085)
    babashka.main$_main.doInvoke (main.clj:1077)
    clojure.lang.RestFn.applyTo (RestFn.java:137)
    babashka.main.main (:-1)

Observation: There might be more info there, but maybe not especially helpful in pinpointing what threw. Probably more helpful in debugging sci than what went wrong for me (which is what --debug is likely mainly for anyway).

borkdude · 2022-09-02T19:16:10Z

New output:

$ clojure -M:babashka/dev atask
something bad is about to happen
----- Error --------------------------------------------------------------------
Type:     java.lang.ArithmeticException
Message:  Divide by zero
Location: /private/tmp/repro/./some_script.clj:5:3

----- Context ------------------------------------------------------------------
1: (ns some-script)
2:
3: (defn -main[& _args]
4:   (println "something bad is about to happen")
5:   (/ 1 0))
     ^--- Divide by zero
6:
7: (when (= *file* (System/getProperty "babashka.file"))
8:   (apply -main *command-line-args*))

----- Stack trace --------------------------------------------------------------
clojure.core//                            - <built-in>
some-script                               - /private/tmp/repro/./some_script.clj:5:3
clojure.core/apply                        - <built-in>
user-3c03b7fb-8838-4952-9029-97543977ba89 - <expr>:28:1

lread · 2022-09-02T19:18:31Z

Noice!

This reverts commit 6e92c99.

borkdude · 2022-09-02T19:42:00Z

I cheered to soon, some tests fail with this fix...

borkdude · 2022-09-02T20:31:56Z

All good now

This reverts commit 6e92c99.

borkdude added the PR welcome label Jul 27, 2022

borkdude mentioned this issue Jul 29, 2022

Next release checklist #1210

Closed

2 tasks

borkdude self-assigned this Sep 2, 2022

borkdude closed this as completed in 6e92c99 Sep 2, 2022

borkdude added a commit that referenced this issue Sep 2, 2022

Revert "Fix #1322: improve error location"

9b24355

This reverts commit 6e92c99.

borkdude reopened this Sep 2, 2022

borkdude closed this as completed in 6cdc002 Sep 2, 2022

borkdude added a commit that referenced this issue Sep 6, 2022

Fix #1322: improve error location

da37b7a

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

GitHub Sponsors

Preserve stack trace when errors occur #1322

Preserve stack trace when errors occur #1322

pinkfrog9 commented Jul 17, 2022

borkdude commented Jul 17, 2022

lread commented Aug 6, 2022

borkdude commented Sep 2, 2022

lread commented Sep 2, 2022

borkdude commented Sep 2, 2022

borkdude commented Sep 2, 2022

Preserve stack trace when errors occur #1322

Preserve stack trace when errors occur #1322

Comments

pinkfrog9 commented Jul 17, 2022

borkdude commented Jul 17, 2022

lread commented Aug 6, 2022

Minimal repro

Invoke Task

Invoke Task with --debug

Invoke Script

Invoke Script with --debug

borkdude commented Sep 2, 2022

lread commented Sep 2, 2022

borkdude commented Sep 2, 2022

borkdude commented Sep 2, 2022