diff --git a/resources/signal-docstrings/signal-content.txt b/resources/signal-docstrings/signal-content.txt index 8caaf62..87cb7ec 100644 --- a/resources/signal-docstrings/signal-content.txt +++ b/resources/signal-docstrings/signal-content.txt @@ -21,6 +21,7 @@ Default signal keys: `:ctx` --------- ?val of `*ctx*` (arb app-level state) when signal was created `:parent` ------ ?{:keys [id uid]} of parent signal, present in nested signals when tracing +`:root` -------- ?{:keys [id uid]} of root signal, present in nested signals when tracing `:location` ---- ?{:keys [ns file line column]} signal creator callsite `:ns` ---------- ?str namespace of signal creator callsite, same as (:ns location) `:line` -------- ?int line of signal creator callsite, same as (:line location) diff --git a/resources/signal-docstrings/signal-options.txt b/resources/signal-docstrings/signal-options.txt index 13f884b..9bb4696 100644 --- a/resources/signal-docstrings/signal-options.txt +++ b/resources/signal-docstrings/signal-options.txt @@ -15,7 +15,8 @@ Signal options (shared by all signal creators): `:let` --------- ?bindings to establish conditionally (iff signal allowed), BEFORE evaluating `:data` and `:msg` (useful!) `:ctx` --------- Custom ?val to override auto (dynamic `*ctx*`) in signal -`:parent` ------ Custom ?{:keys [id uid]} to override auto (dynamic) parent signal info in signal +`:parent` ------ Custom ?{:keys [id uid]} to override auto (dynamic) parent signal tracing info +`:root` -------- Custom ?{:keys [id uid]} to override auto (dynamic) root signal tracing info `:location` ---- Custom ?{:keys [ns line column file]} to override auto signal creator callsite location `:elidable?` --- Should signal be subject to compile-time elision? (Default: true) diff --git a/src/taoensso/telemere/impl.cljc b/src/taoensso/telemere/impl.cljc index b26f752..150c010 100644 --- a/src/taoensso/telemere/impl.cljc +++ b/src/taoensso/telemere/impl.cljc @@ -176,21 +176,20 @@ ;;;; Tracing (optional flow tracking) -(enc/def* ^:dynamic *trace-parent* "?TraceParent" nil) -(defrecord TraceParent [id uid]) +(enc/def* ^:dynamic *trace-root* "?{:keys [id uid inst]}" nil) +(enc/def* ^:dynamic *trace-parent* "?{:keys [id uid inst]}" nil) #?(:clj - (defmacro with-tracing - "Wraps `form` with tracing iff const boolean `trace?` is true." - [trace? id uid form] - (if trace? - `(binding [*trace-parent* (TraceParent. ~id ~uid)] ~form) - (do form)))) + (defmacro cond-binding + "Wraps `form` with binding if `bind?` is true." + [bind? bindings body-form] + (if bind? + `(binding ~bindings ~body-form) + (do body-form)))) (comment - [(enc/qb 1e6 (with-tracing true :id1 :uid1 "form")) ; 257.5 - (macroexpand '(with-tracing false :id1 :uid1 "form")) - (macroexpand '(with-tracing true :id1 :uid1 "form"))]) + [(enc/qb 1e6 (cond-binding true [*trace-parent* {:id :id1, :uid :uid1, :inst :inst1}] *trace-parent*)) ; 226.18 + (macroexpand '(cond-binding true [*trace-parent* {:id :id1, :uid :uid1, :inst :inst1}] *trace-parent*))]) ;;;; Main types @@ -198,7 +197,7 @@ ;; Telemere's main public data type, we avoid nesting and duplication [^long schema inst uid, location ns line column file thread, - sample-rate, kind id level, ctx parent, data kvs msg_, + sample-rate, kind id level, ctx parent root, data kvs msg_, error run-form run-val end-inst run-nsecs] Object (toString [sig] (str "#" `Signal (into {} sig)))) @@ -325,7 +324,7 @@ [#_defaults #_elide? #_allow? #_expansion-id, ; Undocumented elidable? location inst uid middleware, sample-rate kind ns id level when rate-limit, - ctx parent trace?, do let data msg error run & kvs]}]) + ctx parent root trace?, do let data msg error run & kvs]}]) :event! ; [id] [id level-or-opts] => allowed? '([id ] @@ -335,7 +334,7 @@ [#_defaults #_elide? #_allow? #_expansion-id, elidable? location inst uid middleware, sample-rate kind ns id level when rate-limit, - ctx parent trace?, do let data msg error #_run & kvs]}]) + ctx parent root trace?, do let data msg error #_run & kvs]}]) :log! ; [msg] [level-or-opts msg] => allowed? '([ msg] @@ -344,7 +343,7 @@ [#_defaults #_elide? #_allow? #_expansion-id, elidable? location inst uid middleware, sample-rate kind ns id level when rate-limit, - ctx parent trace?, do let data msg error #_run & kvs]} + ctx parent root trace?, do let data msg error #_run & kvs]} msg]) :error! ; [error] [id-or-opts error] => given error @@ -354,7 +353,7 @@ [#_defaults #_elide? #_allow? #_expansion-id, elidable? location inst uid middleware, sample-rate kind ns id level when rate-limit, - ctx parent trace?, do let data msg error #_run & kvs]} + ctx parent root trace?, do let data msg error #_run & kvs]} error]) (:trace! :spy!) ; [form] [id-or-opts form] => run result (value or throw) @@ -364,7 +363,7 @@ [#_defaults #_elide? #_allow? #_expansion-id, elidable? location inst uid middleware, sample-rate kind ns id level when rate-limit, - ctx parent trace?, do let data msg error run & kvs]} + ctx parent root trace?, do let data msg error run & kvs]} form]) :catch->error! ; [form] [id-or-opts form] => run result (value or throw) @@ -374,7 +373,7 @@ [#_defaults #_elide? #_allow? #_expansion-id, rethrow? catch-val, elidable? location inst uid middleware, sample-rate kind ns id level when rate-limit, - ctx parent trace?, do let data msg error #_run & kvs]} + ctx parent root trace?, do let data msg error #_run & kvs]} form]) :uncaught->error! ; [] [id-or-opts] => nil @@ -384,7 +383,7 @@ [#_defaults #_elide? #_allow? #_expansion-id, elidable? location inst uid middleware, sample-rate kind ns id level when rate-limit, - ctx parent trace?, do let data msg error #_run & kvs]}]) + ctx parent root trace?, do let data msg error #_run & kvs]}]) (enc/unexpected-arg! macro-id)))) @@ -527,11 +526,13 @@ trace? (get opts :trace? (boolean run-form)) _ (when-not (contains? #{true false nil} trace?) - ;; Not much motivation to support runtime `trace?` form, but easy - ;; to add support later if desired (enc/unexpected-arg! trace? - {:msg "Expected constant (compile-time) `:trace?` boolean" - :context `with-tracing})) + {:msg "Expected constant (compile-time) `:trace?` boolean" + :context `signal!})) + + parent-form (get opts :parent (when trace? `taoensso.telemere.impl/*trace-parent*)) + root-form (get opts :root (when trace? `(or taoensso.telemere.impl/*trace-root* + {:id ~'__id, :uid ~'__uid, :inst ~'__inst}))) inst-form (get opts :inst :auto) inst-form (if (= inst-form :auto) `(enc/now-inst*) inst-form) @@ -552,9 +553,8 @@ let-form (or let-form '[]) msg-form (parse-msg-form msg-form) - ctx-form (get opts :ctx `taoensso.telemere/*ctx*) - parent-form (get opts :parent (when trace? `taoensso.telemere.impl/*trace-parent*)) - middleware-form (get opts :middleware `taoensso.telemere/*middleware*) + ctx-form (get opts :ctx `taoensso.telemere/*ctx*) + middleware-form (get opts :middleware `taoensso.telemere/*middleware*) kvs-form (not-empty @@ -594,13 +594,13 @@ (Signal. 1 ~'__inst ~'__uid, ~location ~'__ns ~line-form ~column-form ~file-form ~'__thread, - ~sample-rate-form, ~'__kind ~'__id ~'__level, ~ctx-form ~parent-form, + ~sample-rate-form, ~'__kind ~'__id ~'__level, ~ctx-form ~parent-form ~'__root, ~data-form ~kvs-form msg_#, run-err# '~run-form run-val# end-inst# run-nsecs#)) `(Signal. 1 ~'__inst ~'__uid, ~location ~'__ns ~line-form ~column-form ~file-form ~'__thread, - ~sample-rate-form, ~'__kind ~'__id ~'__level, ~ctx-form ~parent-form, + ~sample-rate-form, ~'__kind ~'__id ~'__level, ~ctx-form ~parent-form ~'__root, ~data-form ~kvs-form ~msg-form, ~error-form nil nil nil nil)) @@ -631,18 +631,22 @@ `(enc/if-not ~allow? ; Allow to throw at call ~run-form - (let [~'__inst ~inst-form ; Allow to throw at call - ~'__level ~level-form ; '' - ~'__kind ~kind-form ; '' - ~'__id ~id-form ; '' - ~'__uid ~uid-form ; '' - ~'__ns ~ns-form ; '' - ~'__thread ~thread-form ; '' + (let [;;; Allow to throw at call + ~'__inst ~inst-form + ~'__level ~level-form + ~'__kind ~kind-form + ~'__id ~id-form + ~'__uid ~uid-form + ~'__ns ~ns-form + ~'__thread ~thread-form + ~'__root ~root-form ~'__run-result ; Non-throwing (traps) ~(when run-form `(let [t0# (enc/now-nano*)] - (with-tracing ~trace? ~'__id ~'__uid + (cond-binding ~trace? + [*trace-root* ~'__root + *trace-parent* {:id ~'__id, :uid ~'__uid, :inst ~'__inst}] (enc/try* (do (RunResult. ~run-form nil (- (enc/now-nano*) t0#))) (catch :all t# (RunResult. nil t# (- (enc/now-nano*) t0#))))))) diff --git a/src/taoensso/telemere/utils.cljc b/src/taoensso/telemere/utils.cljc index e9ed3bb..86daf7c 100644 --- a/src/taoensso/telemere/utils.cljc +++ b/src/taoensso/telemere/utils.cljc @@ -520,10 +520,11 @@ (let [af append-fn vf val-fn] - (let [{:keys [uid parent data kvs ctx #?(:clj thread) sample-rate]} signal] + (let [{:keys [uid parent root data kvs ctx #?(:clj thread) sample-rate]} signal] (when sample-rate (af " sample: " (vf sample-rate))) (when uid (af " uid: " (vf uid))) - (when parent (af " parent: " (vf parent))) + (when parent (af " parent: " (vf (dissoc parent :inst)))) + (when (and parent root) (af " root: " (vf (dissoc root :inst)))) #?(:clj (when (and thread incl-thread?) (af " thread: " (vf thread)))) (when data (af " data: " (vf data))) (when (and kvs incl-kvs?) (af " kvs: " (vf kvs))) diff --git a/test/taoensso/telemere_tests.cljc b/test/taoensso/telemere_tests.cljc index 83682e1..d6f9276 100644 --- a/test/taoensso/telemere_tests.cljc +++ b/test/taoensso/telemere_tests.cljc @@ -264,8 +264,9 @@ (let [sv1 (with-sig (sig! {:level :info, :run (+ 1 2), :my-k1 :my-v1})) sv1 ; Ensure instants are printable (-> sv1 - (update :inst enc/inst->udt) - (update :end-inst enc/inst->udt))] + (update-in [:inst] enc/inst->udt) + (update-in [:end-inst] enc/inst->udt) + (update-in [:root :inst] enc/inst->udt))] [(is (= sv1 (read-string (pr-str sv1))))])))]) @@ -414,39 +415,87 @@ (deftest _tracing (testing "Tracing" - [(let [sv (with-sig (sig! {:level :info }))] (is (sm? sv {:parent nil}))) - (let [sv (with-sig (sig! {:level :info, :parent {:id :id0}}))] (is (sm? sv {:parent {:id :id0 :uid :submap/nx}}) "`:parent/id` can be set via call opt")) - (let [sv (with-sig (sig! {:level :info, :parent {:uid :uid0}}))] (is (sm? sv {:parent {:id :submap/nx :uid :uid0}}) "`:parent/uid` can be set via call opt")) + [(testing "Opts overrides" + [(let [sv (with-sig (sig! {:level :info }))] (is (sm? sv {:parent nil}))) + (let [sv (with-sig (sig! {:level :info, :parent {:id :id1, :foo :bar}}))] (is (sm? sv {:parent {:id :id1 :uid :submap/nx, :foo :bar}}) "Manual `:parent/id`")) + (let [sv (with-sig (sig! {:level :info, :parent {:uid :uid1, :foo :bar}}))] (is (sm? sv {:parent {:id :submap/nx :uid :uid1, :foo :bar}}) "Manual `:parent/uid`")) + (let [sv (with-sig (sig! {:level :info, :root {:id :id1, :foo :bar}}))] (is (sm? sv {:root {:id :id1 :uid :submap/nx, :foo :bar}}) "Manual `:root/id`")) + (let [sv (with-sig (sig! {:level :info, :root {:uid :uid1, :foo :bar}}))] (is (sm? sv {:root {:id :submap/nx :uid :uid1, :foo :bar}}) "Manual `:root/uid`"))]) - (testing "Auto call id, uid" - (let [sv (with-sig (sig! {:level :info, :parent {:id :id0, :uid :uid0}, :run impl/*trace-parent*, :data impl/*trace-parent*}))] - [(is (sm? sv {:parent {:id :id0, :uid :uid0}})) - (is (sm? sv {:run-val {:id nil, :uid (get sv :uid ::nx)}}) "`*trace-parent*` visible to run-form, bound to call's auto {:keys [id uid]}") - (is (sm? sv {:data nil}) "`*trace-parent*` not visible to data-form ")])) + (testing "Auto trace {:keys [id uid inst]}s for parent and root" + [(testing "Tracing enabled" + (let [sv (with-sig (sig! {:level :info, :id :id1, :uid :uid1, :inst t1, :trace? true + :run [impl/*trace-parent* impl/*trace-root*], + :data [impl/*trace-parent* impl/*trace-root*]}))] - (testing "Manual call id, uid" - (let [sv (with-sig (sig! {:level :info, :parent {:id :id0, :uid :uid0}, :id :id1, :uid :uid1, :run impl/*trace-parent*, :data impl/*trace-parent*}))] - [(is (sm? sv {:parent {:id :id0, :uid :uid0}})) - (is (sm? sv {:run-val {:id :id1, :uid :uid1}}) "`*trace-parent*` visible to run-form, bound to call's auto {:keys [id uid]}") - (is (sm? sv {:data nil}) "`*trace-parent*` not visible to data-form ")])) + [(is (sm? sv {:parent nil, :root {:id :id1, :uid :uid1, :inst t1}})) + (let [[rv1 rv2] (:run-val sv)] + [(is (sm? rv1 {:id :id1, :uid :uid1, :inst t1}) "`*trace-parent*` visible to run-form") + (is (sm? rv2 {:id :id1, :uid :uid1, :inst t1}) "`*trace-root*` visible to run-form")]) - (testing "Tracing can be disabled via call opt" - (let [sv (with-sig (sig! {:level :info, :parent {:id :id0, :uid :uid0}, :id :id1, :uid :uid1, :run impl/*trace-parent*, :data impl/*trace-parent*, :trace? false}))] - [(is (sm? sv {:parent {:id :id0, :uid :uid0}})) - (is (sm? sv {:run-val nil}))])) + (let [[dv1 dv2] (:data sv)] + [(is (= dv1 nil) "`*trace-parent*` NOT visible to data-form") + (is (= dv2 nil) "`*trace-root*` NOT visible to data-form")])])) + + (testing "Tracing disabled" + (let [sv (with-sig (sig! {:level :info, :id :id1, :uid :uid1, :inst t1, :trace? false + :run [impl/*trace-parent* impl/*trace-root*], + :data [impl/*trace-parent* impl/*trace-root*]}))] + + [(is (sm? sv {:parent nil, :root nil})) + (let [[rv1 rv2] (:run-val sv)] + [(is (= rv1 nil) "`*trace-parent*` visible to run-form") + (is (= rv2 nil) "`*trace-root*` visible to run-form")]) + + (let [[dv1 dv2] (:data sv)] + [(is (= dv1 nil) "`*trace-parent*` NOT visible to data-form") + (is (= dv2 nil) "`*trace-root*` NOT visible to data-form")])]))]) + + (testing "Manual trace {:keys [id uid inst]}s for parent and root" + [(testing "Tracing enabled" + (let [sv (with-sig (sig! {:level :info, :id :id1, :uid :uid1, :inst t1, :trace? true, + :parent {:id :id2, :uid :uid2, :inst t2}, + :root {:id :id3, :uid :uid3, :inst t3} + :run [impl/*trace-parent* impl/*trace-root*], + :data [impl/*trace-parent* impl/*trace-root*]}))] + + [(is (sm? sv {:parent {:id :id2, :uid :uid2, :inst t2}, :root {:id :id3, :uid :uid3, :inst t3}})) + (let [[rv1 rv2] (:run-val sv)] + [(is (sm? rv1 {:id :id1, :uid :uid1, :inst t1}) "`*trace-parent*` visible to run-form") + (is (sm? rv2 {:id :id3, :uid :uid3, :inst t3}) "`*trace-root*` visible to run-form")]) + + (let [[dv1 dv2] (:data sv)] + [(is (= dv1 nil) "`*trace-parent*` NOT visible to data-form") + (is (= dv2 nil) "`*trace-root*` NOT visible to data-form")])])) + + (testing "Tracing disabled" + (let [sv (with-sig (sig! {:level :info, :id :id1, :uid :uid1, :inst t1, :trace? false, + :parent {:id :id2, :uid :uid2, :inst t2}, + :root {:id :id3, :uid :uid3, :inst t3} + :run [impl/*trace-parent* impl/*trace-root*], + :data [impl/*trace-parent* impl/*trace-root*]}))] + + [(is (sm? sv {:parent {:id :id2, :uid :uid2, :inst t2}, :root {:id :id3, :uid :uid3, :inst t3}})) + (let [[rv1 rv2] (:run-val sv)] + [(is (= rv1 nil) "`*trace-parent*` visible to run-form") + (is (= rv2 nil) "`*trace-root*` visible to run-form")]) + + (let [[dv1 dv2] (:data sv)] + [(is (= dv1 nil) "`*trace-parent*` NOT visible to data-form") + (is (= dv2 nil) "`*trace-root*` NOT visible to data-form")])]))]) (testing "Signal nesting" (let [[[outer-rv _] [outer-sv]] (with-sigs - (sig! { :level :info, :id :id1, :uid :uid1, - :run (with-sigs (sig! {:level :info, :id :id2, :uid :uid2, :run impl/*trace-parent*}))})) + (sig! { :level :info, :id :id1, :uid :uid1, :inst t1 + :run (with-sigs (sig! {:level :info, :id :id2, :uid :uid2, :inst t2, :run [impl/*trace-parent* impl/*trace-root*]}))})) [[inner-rv _] [inner-sv]] outer-rv] - [(is (sm? outer-sv {:id :id1, :uid :uid1, :parent nil})) - (is (sm? inner-rv {:id :id2, :uid :uid2})) - (is (sm? inner-sv {:parent {:id :id1, :uid :uid1}})) - (is (sm? inner-sv {:run-val {:id :id2, :uid :uid2}}))]))])) + [(is (sm? outer-sv {:id :id1, :uid :uid1, :parent nil})) + (is (sm? inner-rv [{:id :id2, :uid :uid2, :inst t2} {:id :id1, :uid :uid1, :inst t1}])) + (is (sm? inner-sv {:parent {:id :id1, :uid :uid1, :inst t1}})) + (is (sm? inner-sv {:run-val [{:id :id2, :uid :uid2, :inst t2} {:id :id1, :uid :uid1, :inst t1}]}))]))])) (deftest _sampling ;; Capture combined (call * handler) sample rate in Signal when possible