From 5c85860b3ee425eca6ff68f9479942c9893dea8b Mon Sep 17 00:00:00 2001 From: Peter Taoussanis Date: Fri, 29 Mar 2024 13:58:19 +0100 Subject: [PATCH] [new] Extend `trace!`, `spy!` for easier catching --- resources/signal-docstrings/spy!.txt | 3 + resources/signal-docstrings/trace!.txt | 3 + src/taoensso/telemere.cljc | 74 +++++++++++++++++-------- src/taoensso/telemere/impl.cljc | 42 ++++++++++++-- test/taoensso/telemere_tests.cljc | 76 ++++++++++++++++---------- 5 files changed, 141 insertions(+), 57 deletions(-) diff --git a/resources/signal-docstrings/spy!.txt b/resources/signal-docstrings/spy!.txt index 08e6771..e61f7b4 100644 --- a/resources/signal-docstrings/spy!.txt +++ b/resources/signal-docstrings/spy!.txt @@ -30,6 +30,9 @@ Tips: - Execution of `form` arg may trigger additional (nested) signals. Each signal's `:parent` key will indicate its immediate parent. + - Can be useful to wrap with `catch->error!`: + (catch->error! ::error-id (spy! ...)). + ---------------------------------------- [1] See `help:signal-handling` docstring [2] See `help:signal-content` docstring diff --git a/resources/signal-docstrings/trace!.txt b/resources/signal-docstrings/trace!.txt index 43dc17a..a98f3e0 100644 --- a/resources/signal-docstrings/trace!.txt +++ b/resources/signal-docstrings/trace!.txt @@ -30,6 +30,9 @@ Tips: - Execution of `form` arg may trigger additional (nested) signals. Each signal's `:parent` key will indicate its immediate parent. + - Can be useful to wrap with `catch->error!`: + (catch->error! ::error-id (trace! ...)). + - Default level is `:info`, not `:trace`! The name "trace" in "trace signal" refers to the general action of tracing program flow rather than to the common logging level of the same name. diff --git a/src/taoensso/telemere.cljc b/src/taoensso/telemere.cljc index 4410e89..59de39b 100644 --- a/src/taoensso/telemere.cljc +++ b/src/taoensso/telemere.cljc @@ -233,28 +233,6 @@ (comment (with-signal (throw (error! ::my-id (ex-info "MyEx" {}))))) -#?(:clj - (defmacro trace! - "[form] [id-or-opts form] => run result (value or throw)" - {:doc (impl/signal-docstring :trace!) - :arglists (impl/signal-arglists :trace!)} - [& args] - (let [opts (impl/signal-opts `trace! {:kind :trace, :level :info, :msg ::impl/spy} :run :id :asc args)] - (enc/keep-callsite `(impl/signal! ~opts))))) - -(comment (with-signal (trace! ::my-id (+ 1 2)))) - -#?(:clj - (defmacro spy! - "[form] [level-or-opts form] => run result (value or throw)" - {:doc (impl/signal-docstring :spy!) - :arglists (impl/signal-arglists :spy!)} - [& args] - (let [opts (impl/signal-opts `spy! {:kind :spy, :level :info, :msg ::impl/spy} :run :level :asc args)] - (enc/keep-callsite `(impl/signal! ~opts))))) - -(comment (with-signal (spy! :info (+ 1 2)))) - #?(:clj (defmacro catch->error! "[form] [id-or-opts form] => run value or ?catch-val" @@ -262,7 +240,7 @@ :arglists (impl/signal-arglists :catch->error!)} [& args] (let [opts (impl/signal-opts `catch->error! {:kind :error, :level :error} ::__form :id :asc args) - rethrow? (if (contains? opts :catch-val) false (get opts :rethrow?)) + rethrow? (if (contains? opts :catch-val) false (get opts :rethrow? true)) catch-val (get opts :catch-val) catch-sym (get opts :catch-sym '__caught-error) ; Undocumented form (get opts ::__form) @@ -270,7 +248,7 @@ (enc/keep-callsite `(enc/try* ~form - (catch :any ~catch-sym + (catch :all ~catch-sym (impl/signal! ~(assoc opts :error catch-sym)) (if ~rethrow? (throw ~catch-sym) ~catch-val))))))) @@ -279,6 +257,54 @@ (with-signal (catch->error! { :msg_ ["Error:" __caught-error]} (/ 1 0))) (with-signal (catch->error! {:catch-sym my-err :msg_ ["Error:" my-err]} (/ 1 0)))) +#?(:clj + (defmacro trace! + "[form] [id-or-opts form] => run result (value or throw)" + {:doc (impl/signal-docstring :trace!) + :arglists (impl/signal-arglists :trace!)} + [& args] + (let [opts + (impl/signal-opts `trace! + {:location (enc/get-source &form &env) ; For catch-opts + :kind :trace, :level :info, :msg `impl/default-trace-msg} + :run :id :asc args) + + ;; :catch->error currently undocumented + [opts catch-opts] (impl/signal-catch-opts opts)] + + (if catch-opts + (enc/keep-callsite `(catch->error! ~catch-opts (impl/signal! ~opts))) + (enc/keep-callsite `(impl/signal! ~opts)))))) + +(comment + (with-signal (trace! ::my-id (+ 1 2))) + (let [[_ [s1 s2]] + (with-signals + (trace! {:id :id1, :catch->error :id2} + (throw (ex-info "Ex1" {}))))] + [s2])) + +#?(:clj + (defmacro spy! + "[form] [level-or-opts form] => run result (value or throw)" + {:doc (impl/signal-docstring :spy!) + :arglists (impl/signal-arglists :spy!)} + [& args] + (let [opts + (impl/signal-opts `spy! + {:location (enc/get-source &form &env) ; For catch-opts + :kind :spy, :level :info, :msg `impl/default-trace-msg} + :run :level :asc args) + + ;; :catch->error currently undocumented + [opts catch-opts] (impl/signal-catch-opts opts)] + + (if catch-opts + (enc/keep-callsite `(catch->error! ~catch-opts (impl/signal! ~opts))) + (enc/keep-callsite `(impl/signal! ~opts)))))) + +(comment (with-signal :force (spy! :info (+ 1 2)))) + #?(:clj (defmacro uncaught->error! "Uses `uncaught->handler!` so that `error!` will be called for diff --git a/src/taoensso/telemere/impl.cljc b/src/taoensso/telemere/impl.cljc index 245bede..df92702 100644 --- a/src/taoensso/telemere/impl.cljc +++ b/src/taoensso/telemere/impl.cljc @@ -169,6 +169,16 @@ ;; Leave user to delay-wrap when appropriate (document) :else msg-form)))) +(defn default-trace-msg + [form value error nsecs] + (if error + (str form " !> " (enc/ex-type error)) + (str form " => " value))) + +(comment + (default-trace-msg "(+ 1 2)" 3 nil 12345) + (default-trace-msg "(+ 1 2)" nil (Exception. "Ex") 12345)) + ;;;; Tracing (optional flow tracking) (enc/def* ^:dynamic *trace-parent* "?TraceParent" nil) @@ -342,8 +352,8 @@ run-err (.-error run-result) run-val (.-value run-result) msg_ - (if (enc/identical-kw? msg_ ::spy) - (delay (str run-form " => " (or run-err run-val))) + (if (fn? msg_) ; Undocumented, handy for `trace!`/`spy!`, etc. + (delay (msg_ run-form run-val run-err run-nsecs)) msg_)] (Signal. 1 inst uid, @@ -468,11 +478,35 @@ arg-order))] (if (or (= num-args 1) (map? extra-val-or-opts)) - (let [opts extra-val-or-opts] (conj {:defaults defaults, main-key main-val } opts)) - (let [extra-val extra-val-or-opts] {:defaults defaults, main-key main-val, extra-key extra-val}))))) + (let [opts extra-val-or-opts] (merge defaults {main-key main-val} opts)) + (let [extra-val extra-val-or-opts] (merge defaults {main-key main-val, extra-key extra-val})))))) (comment (signal-opts `signal! {:level :info} :id :level :dsc [::my-id {:level :warn}])) +#?(:clj + (defn signal-catch-opts + "For use within `trace!` and `spy!`, etc." + [main-opts] + (let [catch-id-or-opts (get main-opts :catch->error) + main-opts (dissoc main-opts :catch->error) + catch-opts + (when catch-id-or-opts + (let [base ; Inherit some opts from main + (enc/assoc-some {} + :location (get main-opts :location) + :id (get main-opts :id))] + (cond + (true? catch-id-or-opts) (do base) + (map? catch-id-or-opts) (conj base catch-id-or-opts) + :else (conj base {:id catch-id-or-opts}))))] + + [main-opts catch-opts]))) + +(comment + (signal-catch-opts {:id :main-id, :catch->error true}) + (signal-catch-opts {:id :main-id, :catch->error :error-id}) + (signal-catch-opts {:id :main-id, :catch->error {:id :error-id}})) + ;;;; Signal macro #?(:clj diff --git a/test/taoensso/telemere_tests.cljc b/test/taoensso/telemere_tests.cljc index c9b7541..2a1fcca 100644 --- a/test/taoensso/telemere_tests.cljc +++ b/test/taoensso/telemere_tests.cljc @@ -27,9 +27,9 @@ #?(:clj (do (defmacro ws [form] `(impl/-with-signals (fn [] ~form) {})) - (defmacro wsf [form] `(impl/-with-signals (fn [] ~form) {:force-msg? true})) - (defmacro wst [form] `(impl/-with-signals (fn [] ~form) {:trap-errors? true})) - (defmacro ws1 [form] `(let [[_# [s1#]] (impl/-with-signals (fn [] ~form) {:force-msg? true})] s1#)))) + (defmacro wsf [form] `(impl/-with-signals (fn [] ~form) {:force-msg? true})) + (defmacro wst [form] `(impl/-with-signals (fn [] ~form) {:force-msg? true, :trap-errors? true})) + (defmacro ws1 [form] `(let [[_# [s1#]] (impl/-with-signals (fn [] ~form) {:force-msg? true})] s1#)))) (def ^:dynamic *dynamic-var* nil) @@ -430,13 +430,17 @@ (deftest _common-signals [#?(:clj (testing "signal-opts" - [(is (= (impl/signal-opts `signal! {:level :info} :id :level :dsc [::my-id ]) {:defaults {:level :info}, :id ::my-id})) - (is (= (impl/signal-opts `signal! {:level :info} :id :level :dsc [::my-id :warn ]) {:defaults {:level :info}, :id ::my-id, :level :warn})) - (is (= (impl/signal-opts `signal! {:level :info} :id :level :dsc [::my-id {:level :warn}]) {:defaults {:level :info}, :id ::my-id, :level :warn})) + [(is (= (impl/signal-opts `signal! {:level :info} :id :level :dsc [::my-id ]) {:level :info, :id ::my-id})) + (is (= (impl/signal-opts `signal! {:level :info} :id :level :dsc [::my-id :warn ]) {:level :warn, :id ::my-id})) + (is (= (impl/signal-opts `signal! {:level :info} :id :level :dsc [::my-id {:level :warn}]) {:level :warn, :id ::my-id})) - (is (= (impl/signal-opts `signal! {:level :info} :id :level :asc [ ::my-id]) {:defaults {:level :info}, :id ::my-id})) - (is (= (impl/signal-opts `signal! {:level :info} :id :level :asc [:warn ::my-id]) {:defaults {:level :info}, :id ::my-id, :level :warn})) - (is (= (impl/signal-opts `signal! {:level :info} :id :level :asc [{:level :warn} ::my-id]) {:defaults {:level :info}, :id ::my-id, :level :warn}))])) + (is (= (impl/signal-opts `signal! {:level :info} :id :level :asc [ ::my-id]) {:level :info, :id ::my-id})) + (is (= (impl/signal-opts `signal! {:level :info} :id :level :asc [:warn ::my-id]) {:level :warn, :id ::my-id})) + (is (= (impl/signal-opts `signal! {:level :info} :id :level :asc [{:level :warn} ::my-id]) {:level :warn, :id ::my-id})) + + (is (= (impl/signal-catch-opts {:id :main-id, :location {:ns "ns"}, :catch->error true}) [{:id :main-id, :location {:ns "ns"}} {:location {:ns "ns"}, :id :main-id}])) + (is (= (impl/signal-catch-opts {:id :main-id, :location {:ns "ns"}, :catch->error :error-id}) [{:id :main-id, :location {:ns "ns"}} {:location {:ns "ns"}, :id :error-id}])) + (is (= (impl/signal-catch-opts {:id :main-id, :location {:ns "ns"}, :catch->error {:id :error-id}}) [{:id :main-id, :location {:ns "ns"}} {:location {:ns "ns"}, :id :error-id}]))])) (testing "event!" ; id + ?level => allowed? [(let [[rv [sv]] (ws (tel/event! :id1 ))] [(is (= rv true)) (is (sm? sv {:kind :event, :line :submap/ex, :level :info, :id :id1}))]) @@ -456,37 +460,51 @@ (let [[rv [sv]] (ws (tel/log! {:level :warn} "msg"))] [(is (= rv true)) (is (sm? sv {:kind :log, :line :submap/ex, :msg_ "msg", :level :warn}))]) (let [[rv [sv]] (ws (tel/log! {:allow? false} "msg"))] [(is (= rv nil)) (is (nil? sv))])]) + (testing "catch->error!" ; form + ?id => run value or ?return + [(let [[[rv re] [sv]] (wst (tel/catch->error! (+ 1 2)))] [(is (= rv 3)) (is (nil? sv))]) + (let [[[rv re] [sv]] (wst (tel/catch->error! (ex1!)))] [(is (= re ex1)) (is (sm? sv {:kind :error, :line :submap/ex, :level :error, :error ex1-pred, :id nil}))]) + (let [[[rv re] [sv]] (wst (tel/catch->error! :id1 (ex1!)))] [(is (= re ex1)) (is (sm? sv {:kind :error, :line :submap/ex, :level :error, :error ex1-pred, :id :id1}))]) + (let [[[rv re] [sv]] (wst (tel/catch->error! {:id :id1} (ex1!)))] [(is (= re ex1)) (is (sm? sv {:kind :error, :line :submap/ex, :level :error, :error ex1-pred, :id :id1}))]) + (let [[[rv re] [sv]] (wst (tel/catch->error! {:rethrow? false} (ex1!)))] [(is (= re nil)) (is (sm? sv {:kind :error, :line :submap/ex, :level :error, :error ex1-pred, :id nil}))]) + (let [[[rv re] [sv]] (wst (tel/catch->error! {:catch-val :foo} (ex1!)))] [(is (= rv :foo)) (is (sm? sv {:kind :error, :line :submap/ex, :level :error, :error ex1-pred, :id nil}))]) + (let [[[rv re] [sv]] (wst (tel/catch->error! {:catch-val :foo} (+ 1 2)))] [(is (= rv 3)) (is (nil? sv))]) + (let [[[rv re] [sv]] (wst (tel/catch->error! {:catch-val :foo ; Overrides `:rethrow?` + :rethrow? true} (+ 1 2)))] [(is (= rv 3)) (is (nil? sv))]) + + (let [[rv [sv]] (ws (tel/catch->error! {:catch-val nil + :catch-sym my-err + :data {:my-err my-err}} (ex1!)))] + [(is (= rv nil)) (is (sm? sv {:kind :error, :data {:my-err ex1-pred}}))])]) + (testing "trace!" ; run + ?id => run result (value or throw) [(let [[rv [sv]] (wsf (tel/trace! (+ 1 2)))] [(is (= rv 3)) (is (sm? sv {:kind :trace, :line :submap/ex, :level :info, :id nil, :msg_ "(+ 1 2) => 3"}))]) (let [[rv [sv]] (ws (tel/trace! {:msg nil} (+ 1 2)))] [(is (= rv 3)) (is (sm? sv {:kind :trace, :line :submap/ex, :level :info, :id nil, :msg_ nil}))]) (let [[rv [sv]] (ws (tel/trace! :id1 (+ 1 2)))] [(is (= rv 3)) (is (sm? sv {:kind :trace, :line :submap/ex, :level :info, :id :id1}))]) (let [[rv [sv]] (ws (tel/trace! {:id :id1} (+ 1 2)))] [(is (= rv 3)) (is (sm? sv {:kind :trace, :line :submap/ex, :level :info, :id :id1}))]) - (let [[[_ re] [sv]] (wst (tel/trace! :id1 (ex1!)))] [(is (= re ex1)) (is (sm? sv {:kind :trace, :line :submap/ex, :level :info, :id :id1, :error ex1-pred}))]) - (let [[rv [sv]] (ws (tel/trace! {:allow? false} (+ 1 2)))] [(is (= rv 3)) (is (nil? sv))])]) + (let [[[_ re] [sv]] (wst (tel/trace! :id1 (ex1!)))] [(is (= re ex1)) (is (sm? sv {:kind :trace, :line :submap/ex, :level :info, :id :id1, :error ex1-pred, + :msg_ #?(:clj "(ex1!) !> clojure.lang.ExceptionInfo" + :cljs "(ex1!) !> cljs.core/ExceptionInfo")}))]) + (let [[rv [sv]] (ws (tel/trace! {:allow? false} (+ 1 2)))] [(is (= rv 3)) (is (nil? sv))]) + (let [[[_ ] [sv1 sv2]] + (wst (tel/trace! {:id :id1, :catch->error :id2} (ex1!)))] + [(is (sm? sv1 {:kind :trace, :line :submap/ex, :level :info, :id :id1})) + (is (sm? sv2 {:kind :error, :line :submap/ex, :level :error, :id :id2})) + (is (= (:location sv1) (:location sv2)) "Error inherits exact same location")])]) (testing "spy" ; run + ?level => run result (value or throw) [(let [[rv [sv]] (wsf (tel/spy! (+ 1 2)))] [(is (= rv 3)) (is (sm? sv {:kind :spy, :line :submap/ex, :level :info, :msg_ "(+ 1 2) => 3"}))]) (let [[rv [sv]] (wsf (tel/spy! {:msg nil} (+ 1 2)))] [(is (= rv 3)) (is (sm? sv {:kind :spy, :line :submap/ex, :level :info, :msg_ nil}))]) (let [[rv [sv]] (ws (tel/spy! :warn (+ 1 2)))] [(is (= rv 3)) (is (sm? sv {:kind :spy, :line :submap/ex, :level :warn}))]) (let [[rv [sv]] (ws (tel/spy! {:level :warn} (+ 1 2)))] [(is (= rv 3)) (is (sm? sv {:kind :spy, :line :submap/ex, :level :warn}))]) - (let [[[_ re] [sv]] (wst (tel/spy! :warn (ex1!)))] [(is (= re ex1)) (is (sm? sv {:kind :spy, :line :submap/ex, :level :warn, :error ex1-pred}))]) - (let [[rv [sv]] (ws (tel/spy! {:allow? false} (+ 1 2)))] [(is (= rv 3)) (is (nil? sv))])]) - - (testing "catch->error!" ; form + ?id => run value or ?return - [(let [[rv [sv]] (ws (tel/catch->error! (+ 1 2)))] [(is (= rv 3)) (is (nil? sv))]) - (let [[rv [sv]] (ws (tel/catch->error! (ex1!)))] [(is (= rv nil)) (is (sm? sv {:kind :error, :line :submap/ex, :level :error, :error ex1-pred, :id nil}))]) - (let [[rv [sv]] (ws (tel/catch->error! :id1 (ex1!)))] [(is (= rv nil)) (is (sm? sv {:kind :error, :line :submap/ex, :level :error, :error ex1-pred, :id :id1}))]) - (let [[rv [sv]] (ws (tel/catch->error! {:id :id1} (ex1!)))] [(is (= rv nil)) (is (sm? sv {:kind :error, :line :submap/ex, :level :error, :error ex1-pred, :id :id1}))]) - (let [[[_ re] [sv]] (wst (tel/catch->error! {:rethrow? true} (ex1!)))] [(is (= re ex1)) (is (sm? sv {:kind :error, :line :submap/ex, :level :error, :error ex1-pred, :id nil}))]) - (let [[rv [sv]] (ws (tel/catch->error! {:catch-val :foo} (ex1!)))] [(is (= rv :foo)) (is (sm? sv {:kind :error, :line :submap/ex, :level :error, :error ex1-pred, :id nil}))]) - (let [[rv [sv]] (ws (tel/catch->error! {:catch-val :foo} (+ 1 2)))] [(is (= rv 3)) (is (nil? sv))]) - (let [[rv [sv]] (ws (tel/catch->error! {:catch-val :foo ; Overrides `:rethrow?` - :rethrow? true} (+ 1 2)))] [(is (= rv 3)) (is (nil? sv))]) - - (let [[rv [sv]] (ws (tel/catch->error! {:catch-val nil - :catch-sym my-err - :data {:my-err my-err}} (ex1!)))] - [(is (= rv nil)) (is (sm? sv {:kind :error, :data {:my-err ex1-pred}}))])]) + (let [[[_ re] [sv]] (wst (tel/spy! :warn (ex1!)))] [(is (= re ex1)) (is (sm? sv {:kind :spy, :line :submap/ex, :level :warn, :error ex1-pred, + :msg_ #?(:clj "(ex1!) !> clojure.lang.ExceptionInfo" + :cljs "(ex1!) !> cljs.core/ExceptionInfo")}))]) + (let [[rv [sv]] (ws (tel/spy! {:allow? false} (+ 1 2)))] [(is (= rv 3)) (is (nil? sv))]) + (let [[[_ ] [sv1 sv2]] + (wst (tel/spy! {:id :id1, :catch->error :id2} (ex1!)))] + [(is (sm? sv1 {:kind :spy, :line :submap/ex, :level :info, :id :id1})) + (is (sm? sv2 {:kind :error, :line :submap/ex, :level :error, :id :id2})) + (is (= (:location sv1) (:location sv2)) "Error inherits exact same location")])]) #?(:clj (testing "uncaught->error!"