luciano/telemere
1
0
Fork 0
mirror of https://github.com/taoensso/telemere.git synced 2025-12-17 01:51:10 +00:00
Code Issues Projects Releases Packages Wiki Activity Actions 6

[new] Add extra tracing info to signal content

Browse source 
Tracing signals now include:
  :parent {:keys [id uid instant]}
  :root   {:keys [id uid instant]}

The :instant info is undocumented, and useful for advanced cases like
the upcoming Span support for the OpenTelemetry handler.
This commit is contained in:
Peter Taoussanis 2024-08-12 14:34:54 +02:00
parent 8a7e16bf73
commit d635318f73
5 changed files with 120 additions and 64 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

1
resources/signal-docstrings/signal-content.txt
View file

@ -21,6 +21,7 @@ Default signal keys:
`:ctx` --------- ?val of `*ctx*` (arb app-level state) when signal was created `: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 `: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 `:location` ---- ?{:keys [ns file line column]} signal creator callsite
`:ns` ---------- ?str namespace of signal creator callsite, same as (:ns location) `:ns` ---------- ?str namespace of signal creator callsite, same as (:ns location)
`:line` -------- ?int line of signal creator callsite, same as (:line location) `:line` -------- ?int line of signal creator callsite, same as (:line location)

3
resources/signal-docstrings/signal-options.txt
View file

@ -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!) `:let` --------- ?bindings to establish conditionally (iff signal allowed), BEFORE evaluating `:data` and `:msg` (useful!)
`:ctx` --------- Custom ?val to override auto (dynamic `*ctx*`) in signal `: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 `: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) `:elidable?` --- Should signal be subject to compile-time elision? (Default: true)

70
src/taoensso/telemere/impl.cljc
View file

@ -176,21 +176,20 @@
;;;; Tracing (optional flow tracking) ;;;; Tracing (optional flow tracking)
(enc/def* ^:dynamic *trace-parent* "?TraceParent" nil) (enc/def* ^:dynamic *trace-root* "?{:keys [id uid inst]}" nil)
(defrecord TraceParent [id uid]) (enc/def* ^:dynamic *trace-parent* "?{:keys [id uid inst]}" nil)
#?(:clj #?(:clj
(defmacro with-tracing (defmacro cond-binding
"Wraps `form` with tracing iff const boolean `trace?` is true." "Wraps `form` with binding if `bind?` is true."
[trace? id uid form] [bind? bindings body-form]
(if trace? (if bind?
`(binding [*trace-parent* (TraceParent. ~id ~uid)] ~form) `(binding ~bindings ~body-form)
(do form)))) (do body-form))))
(comment (comment
[(enc/qb 1e6 (with-tracing true :id1 :uid1 "form")) ; 257.5 [(enc/qb 1e6 (cond-binding true [*trace-parent* {:id :id1, :uid :uid1, :inst :inst1}] *trace-parent*)) ; 226.18
(macroexpand '(with-tracing false :id1 :uid1 "form")) (macroexpand '(cond-binding true [*trace-parent* {:id :id1, :uid :uid1, :inst :inst1}] *trace-parent*))])
(macroexpand '(with-tracing true :id1 :uid1 "form"))])
;;;; Main types ;;;; Main types
@ -198,7 +197,7 @@
;; Telemere's main public data type, we avoid nesting and duplication ;; Telemere's main public data type, we avoid nesting and duplication
[^long schema inst uid, [^long schema inst uid,
location ns line column file thread, 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] error run-form run-val end-inst run-nsecs]
Object (toString [sig] (str "#" `Signal (into {} sig)))) Object (toString [sig] (str "#" `Signal (into {} sig))))
@ -325,7 +324,7 @@
[#_defaults #_elide? #_allow? #_expansion-id, ; Undocumented [#_defaults #_elide? #_allow? #_expansion-id, ; Undocumented
elidable? location inst uid middleware, elidable? location inst uid middleware,
sample-rate kind ns id level when rate-limit, 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? :event! ; [id] [id level-or-opts] => allowed?
'([id ] '([id ]
@ -335,7 +334,7 @@
[#_defaults #_elide? #_allow? #_expansion-id, [#_defaults #_elide? #_allow? #_expansion-id,
elidable? location inst uid middleware, elidable? location inst uid middleware,
sample-rate kind ns id level when rate-limit, 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? :log! ; [msg] [level-or-opts msg] => allowed?
'([ msg] '([ msg]
@ -344,7 +343,7 @@
[#_defaults #_elide? #_allow? #_expansion-id, [#_defaults #_elide? #_allow? #_expansion-id,
elidable? location inst uid middleware, elidable? location inst uid middleware,
sample-rate kind ns id level when rate-limit, 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]) msg])
:error! ; [error] [id-or-opts error] => given error :error! ; [error] [id-or-opts error] => given error
@ -354,7 +353,7 @@
[#_defaults #_elide? #_allow? #_expansion-id, [#_defaults #_elide? #_allow? #_expansion-id,
elidable? location inst uid middleware, elidable? location inst uid middleware,
sample-rate kind ns id level when rate-limit, 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]) error])
(:trace! :spy!) ; [form] [id-or-opts form] => run result (value or throw) (:trace! :spy!) ; [form] [id-or-opts form] => run result (value or throw)
@ -364,7 +363,7 @@
[#_defaults #_elide? #_allow? #_expansion-id, [#_defaults #_elide? #_allow? #_expansion-id,
elidable? location inst uid middleware, elidable? location inst uid middleware,
sample-rate kind ns id level when rate-limit, 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]) form])
:catch->error! ; [form] [id-or-opts form] => run result (value or throw) :catch->error! ; [form] [id-or-opts form] => run result (value or throw)
@ -374,7 +373,7 @@
[#_defaults #_elide? #_allow? #_expansion-id, rethrow? catch-val, [#_defaults #_elide? #_allow? #_expansion-id, rethrow? catch-val,
elidable? location inst uid middleware, elidable? location inst uid middleware,
sample-rate kind ns id level when rate-limit, 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]) form])
:uncaught->error! ; [] [id-or-opts] => nil :uncaught->error! ; [] [id-or-opts] => nil
@ -384,7 +383,7 @@
[#_defaults #_elide? #_allow? #_expansion-id, [#_defaults #_elide? #_allow? #_expansion-id,
elidable? location inst uid middleware, elidable? location inst uid middleware,
sample-rate kind ns id level when rate-limit, 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)))) (enc/unexpected-arg! macro-id))))
@ -527,11 +526,13 @@
trace? (get opts :trace? (boolean run-form)) trace? (get opts :trace? (boolean run-form))
_ _
(when-not (contains? #{true false nil} trace?) (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? (enc/unexpected-arg! trace?
{:msg "Expected constant (compile-time) `:trace?` boolean" {:msg "Expected constant (compile-time) `:trace?` boolean"
:context `with-tracing})) :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 (get opts :inst :auto)
inst-form (if (= inst-form :auto) `(enc/now-inst*) inst-form) inst-form (if (= inst-form :auto) `(enc/now-inst*) inst-form)
@ -553,7 +554,6 @@
msg-form (parse-msg-form msg-form) msg-form (parse-msg-form msg-form)
ctx-form (get opts :ctx `taoensso.telemere/*ctx*) 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*) middleware-form (get opts :middleware `taoensso.telemere/*middleware*)
kvs-form kvs-form
@ -594,13 +594,13 @@
(Signal. 1 ~'__inst ~'__uid, (Signal. 1 ~'__inst ~'__uid,
~location ~'__ns ~line-form ~column-form ~file-form ~'__thread, ~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_#, ~data-form ~kvs-form msg_#,
run-err# '~run-form run-val# end-inst# run-nsecs#)) run-err# '~run-form run-val# end-inst# run-nsecs#))
`(Signal. 1 ~'__inst ~'__uid, `(Signal. 1 ~'__inst ~'__uid,
~location ~'__ns ~line-form ~column-form ~file-form ~'__thread, ~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, ~data-form ~kvs-form ~msg-form,
~error-form nil nil nil nil)) ~error-form nil nil nil nil))
@ -631,18 +631,22 @@
`(enc/if-not ~allow? ; Allow to throw at call `(enc/if-not ~allow? ; Allow to throw at call
~run-form ~run-form
(let [~'__inst ~inst-form ; Allow to throw at call (let [;;; Allow to throw at call
~'__level ~level-form ; '' ~'__inst ~inst-form
~'__kind ~kind-form ; '' ~'__level ~level-form
~'__id ~id-form ; '' ~'__kind ~kind-form
~'__uid ~uid-form ; '' ~'__id ~id-form
~'__ns ~ns-form ; '' ~'__uid ~uid-form
~'__thread ~thread-form ; '' ~'__ns ~ns-form
~'__thread ~thread-form
~'__root ~root-form
~'__run-result ; Non-throwing (traps) ~'__run-result ; Non-throwing (traps)
~(when run-form ~(when run-form
`(let [t0# (enc/now-nano*)] `(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* (enc/try*
(do (RunResult. ~run-form nil (- (enc/now-nano*) t0#))) (do (RunResult. ~run-form nil (- (enc/now-nano*) t0#)))
(catch :all t# (RunResult. nil t# (- (enc/now-nano*) t0#))))))) (catch :all t# (RunResult. nil t# (- (enc/now-nano*) t0#)))))))

5
src/taoensso/telemere/utils.cljc
View file

@ -520,10 +520,11 @@
(let [af append-fn (let [af append-fn
vf val-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 sample-rate (af " sample: " (vf sample-rate)))
(when uid (af " uid: " (vf uid))) (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)))) #?(:clj (when (and thread incl-thread?) (af " thread: " (vf thread))))
(when data (af " data: " (vf data))) (when data (af " data: " (vf data)))
(when (and kvs incl-kvs?) (af " kvs: " (vf kvs))) (when (and kvs incl-kvs?) (af " kvs: " (vf kvs)))

95
test/taoensso/telemere_tests.cljc
View file

@ -264,8 +264,9 @@
(let [sv1 (with-sig (sig! {:level :info, :run (+ 1 2), :my-k1 :my-v1})) (let [sv1 (with-sig (sig! {:level :info, :run (+ 1 2), :my-k1 :my-v1}))
sv1 ; Ensure instants are printable sv1 ; Ensure instants are printable
(-> sv1 (-> sv1
(update :inst enc/inst->udt) (update-in [:inst] enc/inst->udt)
(update :end-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))))])))]) [(is (= sv1 (read-string (pr-str sv1))))])))])
@ -414,39 +415,87 @@
(deftest _tracing (deftest _tracing
(testing "Tracing" (testing "Tracing"
[(testing "Opts overrides"
[(let [sv (with-sig (sig! {:level :info }))] (is (sm? sv {:parent nil}))) [(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 {: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 :uid0}}))] (is (sm? sv {:parent {:id :submap/nx :uid :uid0}}) "`:parent/uid` can be set via call opt")) (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" (testing "Auto trace {:keys [id uid inst]}s for parent and root"
(let [sv (with-sig (sig! {:level :info, :parent {:id :id0, :uid :uid0}, :run impl/*trace-parent*, :data impl/*trace-parent*}))] [(testing "Tracing enabled"
[(is (sm? sv {:parent {:id :id0, :uid :uid0}})) (let [sv (with-sig (sig! {:level :info, :id :id1, :uid :uid1, :inst t1, :trace? true
(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]}") :run [impl/*trace-parent* impl/*trace-root*],
(is (sm? sv {:data nil}) "`*trace-parent*` not visible to data-form ")])) :data [impl/*trace-parent* impl/*trace-root*]}))]
(testing "Manual call id, uid" [(is (sm? sv {:parent nil, :root {:id :id1, :uid :uid1, :inst t1}}))
(let [sv (with-sig (sig! {:level :info, :parent {:id :id0, :uid :uid0}, :id :id1, :uid :uid1, :run impl/*trace-parent*, :data impl/*trace-parent*}))] (let [[rv1 rv2] (:run-val sv)]
[(is (sm? sv {:parent {:id :id0, :uid :uid0}})) [(is (sm? rv1 {:id :id1, :uid :uid1, :inst t1}) "`*trace-parent*` visible to run-form")
(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? rv2 {:id :id1, :uid :uid1, :inst t1}) "`*trace-root*` visible to run-form")])
(is (sm? sv {:data nil}) "`*trace-parent*` not visible to data-form ")]))
(testing "Tracing can be disabled via call opt" (let [[dv1 dv2] (:data sv)]
(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 (= dv1 nil) "`*trace-parent*` NOT visible to data-form")
[(is (sm? sv {:parent {:id :id0, :uid :uid0}})) (is (= dv2 nil) "`*trace-root*` NOT visible to data-form")])]))
(is (sm? sv {:run-val nil}))]))
(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" (testing "Signal nesting"
(let [[[outer-rv _] [outer-sv]] (let [[[outer-rv _] [outer-sv]]
(with-sigs (with-sigs
(sig! { :level :info, :id :id1, :uid :uid1, (sig! { :level :info, :id :id1, :uid :uid1, :inst t1
:run (with-sigs (sig! {:level :info, :id :id2, :uid :uid2, :run impl/*trace-parent*}))})) :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] [[inner-rv _] [inner-sv]] outer-rv]
[(is (sm? outer-sv {:id :id1, :uid :uid1, :parent nil})) [(is (sm? outer-sv {:id :id1, :uid :uid1, :parent nil}))
(is (sm? inner-rv {:id :id2, :uid :uid2})) (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}})) (is (sm? inner-sv {:parent {:id :id1, :uid :uid1, :inst t1}}))
(is (sm? inner-sv {:run-val {:id :id2, :uid :uid2}}))]))])) (is (sm? inner-sv {:run-val [{:id :id2, :uid :uid2, :inst t2} {:id :id1, :uid :uid1, :inst t1}]}))]))]))
(deftest _sampling (deftest _sampling
;; Capture combined (call * handler) sample rate in Signal when possible ;; Capture combined (call * handler) sample rate in Signal when possible