From 5b0f54e5760d233a106110dd82f554bd4497e17b Mon Sep 17 00:00:00 2001 From: Michiel Borkent Date: Mon, 24 Aug 2020 23:45:41 +0200 Subject: [PATCH] [#508, #543] Improve error reporting with stack trace --- .gitignore | 1 + CHANGELOG.md | 4 +- deps.edn | 2 +- project.clj | 2 +- sci | 2 +- script/test | 13 +- src/babashka/main.clj | 190 ++++++++++++++---- test-resources/babashka/file_location1.clj | 8 + test-resources/babashka/file_location2.clj | 7 + .../babashka/file_location_preloads.clj | 5 + test-resources/divide_by_zero.jar | Bin 0 -> 506 bytes test/babashka/error_test.clj | 66 ++++++ test/babashka/main_test.clj | 11 + test/babashka/scripts/divide_by_zero.bb | 7 + 14 files changed, 273 insertions(+), 45 deletions(-) create mode 100644 test-resources/babashka/file_location1.clj create mode 100644 test-resources/babashka/file_location2.clj create mode 100644 test-resources/babashka/file_location_preloads.clj create mode 100644 test-resources/divide_by_zero.jar create mode 100644 test/babashka/error_test.clj create mode 100644 test/babashka/scripts/divide_by_zero.bb diff --git a/.gitignore b/.gitignore index a5bd7bfb..266fb85d 100644 --- a/.gitignore +++ b/.gitignore @@ -29,3 +29,4 @@ org_babashka*.h /bb.pdb /bb.stripped.pdb /.calva +!test-resources/divide_by_zero.jar diff --git a/CHANGELOG.md b/CHANGELOG.md index e42e1c9c..4afef165 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,7 +4,7 @@ For a list of breaking changes, check [here](#breaking-changes) ## Unreleased - +Thanks to for contributing to this release. ### New @@ -15,12 +15,14 @@ For a list of breaking changes, check [here](#breaking-changes) - Expose more transit vars [#525](https://github.com/borkdude/babashka/issues/525) ([@djblue](https://github.com/djblue)) - Add support for `clojure.datafy`, `Datafiable` and `Navigable` [#468](https://github.com/borkdude/babashka/issues/468) - Add support for building and running uberjars [#536](https://github.com/borkdude/babashka/issues/536) +- Print locals and stack trace on exception [#543](https://github.com/borkdude/babashka/issues/543) ### Fixed - Eval metadata on var created with `defn` [borkdude/sci#36](https://github.com/borkdude/sci/issues/36) - Metadata fn on var fails if calling the var itself [borkdude/sci#363](https://github.com/borkdude/sci/issues/363) - Allow re-binding of core vars in with-redefs [borkdude/sci#375](https://github.com/borkdude/sci/issues/375) +- Babashka shows wrong filename when error is from required ns [#508](https://github.com/borkdude/babashka/issues/508) - Fix reading resources from jar files [#528](https://github.com/borkdude/babashka/issues/528) - Switch from canonical to absolute paths in `:file` field on var metadata [#532](https://github.com/borkdude/babashka/issues/532) diff --git a/deps.edn b/deps.edn index 41f044d4..b6f4f825 100644 --- a/deps.edn +++ b/deps.edn @@ -7,7 +7,7 @@ "resources" "sci/resources"], :deps {org.clojure/clojure {:mvn/version "1.10.2-alpha1"}, org.clojure/tools.reader {:mvn/version "1.3.2"}, - borkdude/edamame {:mvn/version "0.0.11-alpha.13"}, + borkdude/edamame {:mvn/version "0.0.11-alpha.14"}, borkdude/graal.locking {:mvn/version "0.0.2"}, borkdude/sci.impl.reflector {:mvn/version "0.0.1"} org.clojure/core.async {:mvn/version "1.1.587"}, diff --git a/project.clj b/project.clj index 2be28265..457d78eb 100644 --- a/project.clj +++ b/project.clj @@ -15,7 +15,7 @@ :resource-paths ["resources" "sci/resources"] :dependencies [[org.clojure/clojure "1.10.2-alpha1"] [org.clojure/tools.reader "1.3.2"] - [borkdude/edamame "0.0.11-alpha.13"] + [borkdude/edamame "0.0.11-alpha.14"] [borkdude/graal.locking "0.0.2"] [org.clojure/tools.cli "1.0.194"] [cheshire "5.10.0"] diff --git a/sci b/sci index f6389378..76207b45 160000 --- a/sci +++ b/sci @@ -1 +1 @@ -Subproject commit f6389378181b24b828566ac5307eca25aadf119e +Subproject commit 76207b456fa44bd792669c765b38f633e474a9e0 diff --git a/script/test b/script/test index 52a179b0..24ddf291 100755 --- a/script/test +++ b/script/test @@ -9,8 +9,10 @@ fi java -version set -eo pipefail -BABASHKA_PRELOADS="" -BABASHKA_CLASSPATH="" +unset BABASHKA_PRELOADS +unset BABASHKA_CLASSPATH +unset BABASHKA_PRELOADS_TEST + echo "running tests part 1" lein test "$@" @@ -19,8 +21,13 @@ export BABASHKA_PRELOADS_TEST=true echo "running tests part 2" lein test :only babashka.main-test/preloads-test +export BABASHKA_PRELOADS='(defn ithrow [] (/ 1 0))' +export BABASHKA_PRELOADS_TEST=true +echo "running tests part 3" +lein test :only babashka.main-test/preloads-file-location-test + export BABASHKA_PRELOADS="(require '[env-ns])" export BABASHKA_CLASSPATH_TEST=true export BABASHKA_CLASSPATH="test-resources/babashka/src_for_classpath_test/env" -echo "running tests part 3" +echo "running tests part 4" lein test :only babashka.classpath-test/classpath-env-test diff --git a/src/babashka/main.clj b/src/babashka/main.clj index 23b11b80..8d854144 100644 --- a/src/babashka/main.clj +++ b/src/babashka/main.clj @@ -33,6 +33,7 @@ [hf.depstar.uberjar :as uberjar] [sci.addons :as addons] [sci.core :as sci] + [sci.impl.callstack :as cs] [sci.impl.namespaces :as sci-namespaces] [sci.impl.unrestrict :refer [*unrestricted*]] [sci.impl.vars :as vars]) @@ -402,21 +403,120 @@ If neither -e, -f, or --socket-repl are specified, then the first argument that {'java.lang.System/exit exit ;; override exit, so we have more control 'System/exit exit}) -(defn error-handler* [^Exception e verbose?] +(defn ruler [title] + (println (apply str "----- " title " " (repeat (- 80 7 (count title)) \-)))) + +(defn split-stacktrace [stacktrace verbose?] + (if verbose? [stacktrace] + (let [stack-count (count stacktrace)] + (if (<= stack-count 10) + [stacktrace] + [(take 5 stacktrace) + (drop (- stack-count 5) stacktrace)])))) + +(defn print-stacktrace + [stacktrace {:keys [:verbose?]}] + (let [stacktrace (cs/format-stacktrace stacktrace) + segments (split-stacktrace stacktrace verbose?) + [fst snd] segments] + (run! println fst) + (when snd + (println "...") + (run! println snd)))) + +(defn error-context [ex opts] + (let [{:keys [:file :line :column]} (ex-data ex)] + (when file + (when-let [content (case file + "" (:expression opts) + "" (:preloads opts) + (let [f (io/file file)] + (or (when (.exists f) (slurp f)) + (and (not (.isAbsolute f)) + (when-let [loader (:loader opts)] + (:source (cp/getResource loader [file] nil)))))))] + (let [matching-line (dec line) + start-line (max (- matching-line 4) 0) + end-line (+ matching-line 6) + [before after] (->> + (clojure.string/split-lines content) + (map-indexed list) + (drop start-line) + (take (- end-line start-line)) + (split-at (inc (- matching-line start-line)))) + snippet-lines (concat before + [[nil (str (clojure.string/join "" (repeat (dec column) " ")) + (str "^--- " (ex-message ex)))]] + after) + indices (map first snippet-lines) + max-size (reduce max 0 (map (comp count str) indices)) + snippet-lines (map (fn [[idx line]] + (if idx + (let [line-number (inc idx)] + (str (format (str "%" max-size "d: ") line-number) line)) + (str (clojure.string/join (repeat (+ max-size 2) " ")) line))) + snippet-lines)] + (clojure.string/join "\n" snippet-lines)))))) + +(defn right-pad [s n] + (let [n (- n (count s))] + (str s (str/join (repeat n " "))))) + +(defn print-locals [locals] + (let [max-name-length (reduce max 0 (map (comp count str) + (keys locals))) + max-name-length (+ max-name-length 2)] + (binding [*print-length* 10 + *print-level* 2] + (doseq [[k v] locals] + (println (str (right-pad (str k ": ") max-name-length) v)))))) + +(defn error-handler* [^Exception e opts] (binding [*out* *err*] (let [d (ex-data e) exit-code (:bb/exit-code d) - sci-error? (identical? :sci/error (:type d)) + sci-error? (isa? (:type d) :sci/error) ex-name (when sci-error? (some-> ^Throwable (ex-cause e) .getClass .getName))] (if exit-code [nil exit-code] - (do (if verbose? - (print-stack-trace e) - (println (str (or ex-name + (do + (ruler "Error") + (println "Type: " (or + ex-name (.. e getClass getName)) - (when-let [m (.getMessage e)] - (str ": " m)) ))) + (when-let [t (:type d)] + (str " / " t))) + (when-let [m (.getMessage e)] + (println (str "Message: " m))) + (let [{:keys [:file :line :column]} d] + (when line + (println (str "Location: " + (when file (str file ":")) + line ":" column"")))) + (println) + (when-let [ec (when sci-error? + (error-context e opts))] + (ruler "Context") + (println ec) + (println)) + (when-let [locals (not-empty (:locals d))] + (ruler "Locals") + (print-locals locals) + (println)) + (when sci-error? + (when-let + [st (let [st (with-out-str + (some-> + d :callstack + cs/stacktrace + (print-stacktrace opts)))] + (when-not (str/blank? st) st))] + (ruler "Stack trace") + (println st))) + (when (:verbose? opts) + (ruler "Exception") + (print-stack-trace e)) (flush) [nil 1]))))) @@ -493,6 +593,11 @@ If neither -e, -f, or --socket-repl are specified, then the first argument that (System/getenv "BABASHKA_CLASSPATH")) _ (when classpath (add-classpath* classpath)) + abs-path (when file + (let [abs-path (.getAbsolutePath (io/file file))] + (vars/bindRoot sci/file abs-path) + (System/setProperty "babashka.file" abs-path) + abs-path)) _ (when jar (add-classpath* jar)) load-fn (fn [{:keys [:namespace :reload]}] @@ -507,16 +612,13 @@ If neither -e, -f, or --socket-repl are specified, then the first argument that (let [res (cp/source-for-namespace loader namespace nil)] (when uberscript (swap! uberscript-sources conj (:source res))) res)))) - _ (when file - (let [abs-path (.getAbsolutePath (io/file file))] - (vars/bindRoot sci/file abs-path) - (System/setProperty "babashka.file" abs-path))) main (if (and jar (not main)) (when-let [res (cp/getResource (cp/loader jar) ["META-INF/MANIFEST.MF"] {:url? true})] (cp/main-ns res)) main) + ;; TODO: pull more of these values to compile time opts {:aliases aliases :namespaces (-> namespaces @@ -557,16 +659,23 @@ If neither -e, -f, or --socket-repl are specified, then the first argument that main)] nil] file (try [[(read-file file)] nil] (catch Exception e - (error-handler* e verbose?)))) + (error-handler* e {:expression expressions + :verbose? verbose? + :preloads preloads + :loader (:loader @cp-state)})))) expression (str/join " " expressions) ;; this might mess with the locations... exit-code ;; handle preloads (if exit-code exit-code (do (when preloads - (try - (sci/eval-string* sci-ctx preloads) - (catch Throwable e - (error-handler* e verbose?)))) + (sci/binding [sci/file ""] + (try + (sci/eval-string* sci-ctx preloads) + (catch Throwable e + (error-handler* e {:expression expression + :verbose? verbose? + :preloads preloads + :loader (:loader @cp-state)}))))) nil)) exit-code (or exit-code @@ -582,28 +691,33 @@ If neither -e, -f, or --socket-repl are specified, then the first argument that nrepl [(start-nrepl! nrepl sci-ctx) 0] uberjar [nil 0] expressions - (try - (loop [] - (let [in (read-next *in*)] - (if (identical? ::EOF in) - [nil 0] ;; done streaming - (let [res [(let [res - (sci/binding [input-var in] - (sci/eval-string* sci-ctx expression))] - (when (some? res) - (if-let [pr-f (cond shell-out println - edn-out prn)] - (if (coll? res) - (doseq [l res - :while (not (pipe-signal-received?))] - (pr-f l)) - (pr-f res)) - (prn res)))) 0]] - (if stream? - (recur) - res))))) - (catch Throwable e - (error-handler* e verbose?))) + (sci/binding [sci/file abs-path] + (try + (loop [] + (let [in (read-next *in*)] + (if (identical? ::EOF in) + [nil 0] ;; done streaming + (let [res [(let [res + (sci/binding [sci/file (or @sci/file "") + input-var in] + (sci/eval-string* sci-ctx expression))] + (when (some? res) + (if-let [pr-f (cond shell-out println + edn-out prn)] + (if (coll? res) + (doseq [l res + :while (not (pipe-signal-received?))] + (pr-f l)) + (pr-f res)) + (prn res)))) 0]] + (if stream? + (recur) + res))))) + (catch Throwable e + (error-handler* e {:expression expression + :verbose? verbose? + :preloads preloads + :loader (:loader @cp-state)})))) uberscript [nil 0] :else [(repl/start-repl! sci-ctx) 0])) 1)] diff --git a/test-resources/babashka/file_location1.clj b/test-resources/babashka/file_location1.clj new file mode 100644 index 00000000..614fcfb7 --- /dev/null +++ b/test-resources/babashka/file_location1.clj @@ -0,0 +1,8 @@ +(ns babashka.file-location1 + (:require [babashka.classpath :as cp])) + +(cp/add-classpath "test-resources") + +(require '[babashka.file-location2 :as f2]) + +(f2/uh-oh) diff --git a/test-resources/babashka/file_location2.clj b/test-resources/babashka/file_location2.clj new file mode 100644 index 00000000..cfe9841e --- /dev/null +++ b/test-resources/babashka/file_location2.clj @@ -0,0 +1,7 @@ +(ns babashka.file-location2) + +(defn ok [] + "ok") + +(defn uh-oh [] + (/ 1 0)) diff --git a/test-resources/babashka/file_location_preloads.clj b/test-resources/babashka/file_location_preloads.clj new file mode 100644 index 00000000..735d485c --- /dev/null +++ b/test-resources/babashka/file_location_preloads.clj @@ -0,0 +1,5 @@ +(ns babashka.file-location-preloads) + +(require 'user) +(user/ithrow) + diff --git a/test-resources/divide_by_zero.jar b/test-resources/divide_by_zero.jar new file mode 100644 index 0000000000000000000000000000000000000000..32b93244917afeaa2e892e16b3865aca2c736ef2 GIT binary patch literal 506 zcmWIWW@Zs#;Nak35LzM;$bbac83Y;9^7HkQbFxB1cp2D_u)D-RhvLg8w8K13pT8b* z;X=4Uh{1&?Obh|u>>M34@8t*sjSvLl0HDEKVB=KL4CVyN`?`iW>U#RQ>4S}i84IF8 z`XCNM*C&Fk&)3n<)6F$FM9*`(P_14uocjo-&AcHH$4~n$Tp3%Hm zx@t?1ho`QFo~I5|_mUS?OH-Id8A4w~7BGT+z-z1-U=DP(71#%iOd<@3z(MvMI|C=! zZwLY&RIHGo3h-uR;$pxR0?4`}frcQ32T(sG91ymHLIT-kA}F>`MAnZIE^wn**+33u N2Evm-TAC5W0{|7}WM%*W literal 0 HcmV?d00001 diff --git a/test/babashka/error_test.clj b/test/babashka/error_test.clj new file mode 100644 index 00000000..e4df4ba3 --- /dev/null +++ b/test/babashka/error_test.clj @@ -0,0 +1,66 @@ +(ns babashka.error-test + (:require + [babashka.test-utils :as tu] + [clojure.java.io :as io] + [clojure.string :as str] + [clojure.test :as t :refer [deftest is]])) + +(deftest stacktrace-from-script-test + (try (tu/bb nil (.getPath (io/file "test" "babashka" "scripts" "divide_by_zero.bb"))) + (catch Exception e + (let [msg (ex-message e) + lines (str/split-lines msg) + lines (drop-while #(not (str/includes? % "clojure.core//")) lines) + matches [#"clojure\.core/" + #"user/foo .*divide_by_zero.bb:2:3" + #"user/foo .*divide_by_zero.bb:1:1" + #"user/bar .*divide_by_zero.bb:5:3" + #"user/bar .*divide_by_zero.bb:4:1" + #"user .*divide_by_zero.bb:7:1"]] + (doseq [[l m] (map vector lines matches)] + (is (re-find m l))))))) + +(deftest stacktrace-from-expr-test + (let [output (try (tu/bb nil " +(defn foo [] (/ 1 0)) +(foo)") + (catch Exception e (ex-message e)))] + (is (str/includes? output "----- Stack trace -------------------------------------------------------------- +clojure.core// - +user/foo - :2:14 +user/foo - :2:1 +user - :3:1")))) + +(deftest context-test + (let [output (try (tu/bb nil " +(defn foo [] (/ 1 0)) +(foo)") + (catch Exception e (ex-message e)))] + (is (str/includes? output "----- Context ------------------------------------------------------------------ +1: +2: (defn foo [] (/ 1 0)) + ^--- Divide by zero +3: (foo)")))) + +(deftest parse-error-context-test + (let [output (try (tu/bb nil "{:a}") + (catch Exception e (ex-message e)))] + (is (str/includes? output "----- Context ------------------------------------------------------------------ +1: {:a} + ^--- The map literal starting with :a contains 1 form(s).")))) + +(deftest jar-error-test + (let [output (try (tu/bb nil "-cp" (.getPath (io/file "test-resources" "divide_by_zero.jar")) "-e" "(require 'foo)") + (catch Exception e (ex-message e)))] + (is (str/includes? output "----- Error -------------------------------------------------------------------- +Type: java.lang.ArithmeticException / :sci/error +Message: Divide by zero +Location: foo.clj:1:10 + +----- Context ------------------------------------------------------------------ +1: (ns foo) (/ 1 0) + ^--- Divide by zero + +----- Stack trace -------------------------------------------------------------- +clojure.core// - +foo - foo.clj:1:10")))) diff --git a/test/babashka/main_test.clj b/test/babashka/main_test.clj index cf89d592..aed4bacd 100644 --- a/test/babashka/main_test.clj +++ b/test/babashka/main_test.clj @@ -527,6 +527,17 @@ (is (apply = res)) (is (str/includes? (first res) "..")))) +(deftest file-location-test + (is (thrown-with-msg? + Exception #"file_location2.clj" + (test-utils/bb nil (.getPath (io/file "test-resources" "babashka" "file_location1.clj")))))) + +(deftest preloads-file-location-test + (when (System/getenv "BABASHKA_PRELOADS_TEST") + (is (thrown-with-msg? + Exception #"preloads" + (test-utils/bb nil (.getPath (io/file "test-resources" "babashka" "file_location_preloads.clj"))))))) + ;;;; Scratch (comment diff --git a/test/babashka/scripts/divide_by_zero.bb b/test/babashka/scripts/divide_by_zero.bb new file mode 100644 index 00000000..cb1e3b8c --- /dev/null +++ b/test/babashka/scripts/divide_by_zero.bb @@ -0,0 +1,7 @@ +(defn foo [] + (/ 1 0)) + +(defn bar [] + (foo)) + +(bar)