(ns taoensso.telemere "Structured telemetry for Clojure/Script applications. See the GitHub page (esp. Wiki) for info on motivation and design: " {:author "Peter Taoussanis (@ptaoussanis)"} (:refer-clojure :exclude [binding newline]) (:require [taoensso.encore :as enc :refer [binding have have?]] [taoensso.encore.signals :as sigs] [taoensso.telemere.impl :as impl] [taoensso.telemere.utils :as utils] #?(:default [taoensso.telemere.consoles :as consoles]) #?(:clj [taoensso.telemere.streams :as streams]) #?(:clj [taoensso.telemere.files :as files])) #?(:cljs (:require-macros [taoensso.telemere :refer [with-signal with-signals signal! event! log! trace! spy! catch->error! ;; Via `sigs/def-api` without-filters with-kind-filter with-ns-filter with-id-filter with-min-level with-handler with-handler+ with-ctx with-ctx+ with-middleware with-middleware+]]))) (comment (remove-ns 'taoensso.telemere) (:api (enc/interns-overview))) (enc/assert-min-encore-version [3 127 0]) ;;;; TODO ;; - Solution and docs for lib authors ;; - Update Tufte (signal API, config API, signal keys, etc.) ;; - Update Timbre (signal API, config API, signal keys, backport improvements) ;;;; Shared signal API (sigs/def-api {:sf-arity 4 :ct-sig-filter impl/ct-sig-filter :*rt-sig-filter* impl/*rt-sig-filter* :*sig-handlers* impl/*sig-handlers* :lib-dispatch-opts (assoc sigs/default-handler-dispatch-opts :convey-bindings? false)}) ;;;; Aliases (enc/defaliases ;; Encore #?(:clj enc/set-var-root!) #?(:clj enc/update-var-root!) #?(:clj enc/get-env) #?(:clj enc/call-on-shutdown!) enc/chance enc/rate-limiter enc/newline enc/comp-middleware sigs/default-handler-dispatch-opts ;; Impl impl/msg-splice impl/msg-skip #?(:clj impl/with-signal) #?(:clj impl/with-signals) #?(:clj impl/signal!) #?(:clj impl/signal-allowed?) ;; Utils utils/clean-signal-fn utils/format-signal-fn utils/pr-signal-fn utils/error-signal?) ;;;; Help (do (impl/defhelp help:signal-creators :signal-creators) (impl/defhelp help:signal-options :signal-options) (impl/defhelp help:signal-content :signal-content) (impl/defhelp help:environmental-config :environmental-config)) ;;;; Unique ids (def ^:dynamic *uid-fn* "Experimental, subject to change. (fn [root?]) used to generate signal `:uid` values (unique instance ids) when tracing. Relevant only when `otel-tracing?` is false. If `otel-tracing?` is true, uids are instead generated by `*otel-tracer*`. `root?` argument is true iff signal is a top-level trace (i.e. form being traced is unnested = has no parent form). Root-level uids typically need more entropy and so are usually longer (e.g. 32 vs 16 hex chars). Override default by setting one of the following: JVM property: `taoensso.telemere/uid-fn` Env variable: `TAOENSSO_TELEMERE_UID_FN` Classpath resource: `taoensso.telemere/uid-fn` Possible (compile-time) values include: `:uuid` - UUID string (Cljs) or `java.util.UUID` (Clj) `:uuid-str` - UUID string (36/36 chars) `:nano/secure` - nano-style string (21/10 chars) w/ strong RNG `:nano/insecure` - nano-style string (21/10 chars) w/ fast RNG (default) `:hex/insecure` - hex-style string (32/16 chars) w/ strong RNG `:hex/secure` - hex-style string (32/16 chars) w/ fast RNG" (utils/parse-uid-fn impl/uid-kind)) (comment (enc/qb 1e6 (*uid-fn* true) (*uid-fn* false))) ; [79.4 63.53] ;;;; OpenTelemetry #?(:clj (def otel-tracing? "Experimental, subject to change. Feedback welcome! Should Telemere's tracing signal creators (`trace!`, `spy!`, etc.) interop with OpenTelemetry Java [1]? This will affect relevant Telemere macro expansions. Defaults to `true` iff OpenTelemetry Java is present when this namespace is evaluated/compiled. If `false`: 1. Telemere's OpenTelemetry handler will NOT emit to `SpanExporter`s. 2. Telemere and OpenTelemetry will NOT recognize each other's spans. If `true`: 1. Telemere's OpenTelemetry handler WILL emit to `SpanExporter`s. 2. Telemere and OpenTelemetry WILL recognize each other's spans. Override default by setting one of the following to \"true\" or \"false\": JVM property: `taoensso.telemere.otel-tracing` Env variable: `TAOENSSO_TELEMERE_otel-tracing` Classpath resource: `taoensso.telemere.otel-tracing` See also: `otel-get-default-providers`, `*otel-tracer*`, `taoensso.telemere.open-telemere/handler:open-telemetry`. [1] Ref. " impl/enabled:otel-tracing?)) #?(:clj (defn otel-get-default-providers "Experimental, subject to change. Feedback welcome! When OpenTelemetry Java API [1] is present, returns map with keys: :logger-provider - default `io.opentelemetry.api.logs.LoggerProvider` :tracer-provider - default `io.opentelemetry.api.trace.TracerProvider` :via - ∈ #{:sdk-extension-autoconfigure :global} Uses `AutoConfiguredOpenTelemetrySdk` when possible, or `GlobalOpenTelemetry` otherwise. See the relevant OpenTelemetry Java docs for details. [1] Ref. " [] (enc/compile-when impl/present:otel? (or ;; Via SDK autoconfiguration extension (when available) (enc/compile-when io.opentelemetry.sdk.autoconfigure.AutoConfiguredOpenTelemetrySdk (enc/catching :common (let [builder (io.opentelemetry.sdk.autoconfigure.AutoConfiguredOpenTelemetrySdk/builder) sdk (.getOpenTelemetrySdk (.build builder))] {:logger-provider (.getLogsBridge sdk) :tracer-provider (.getTracerProvider sdk) :via :sdk-extension-autoconfigure}))) ;; Via Global (generally not recommended) (let [g (io.opentelemetry.api.GlobalOpenTelemetry/get)] {:logger-provider (.getLogsBridge g) :tracer-provider (.getTracerProvider g) :via :global}))))) #?(:clj (def ^:no-doc otel-default-providers_ (when impl/present:otel? (delay (otel-get-default-providers))))) #?(:clj (def ^:dynamic ^:no-doc *otel-tracer* "OpenTelemetry `Tracer` to use for Telemere's tracing signal creators (`trace!`, `span!`, etc.), ∈ #{nil io.opentelemetry.api.trace.Tracer Delay}. See also `otel-tracing?`, `otel-get-default-providers`." (enc/compile-when impl/enabled:otel-tracing? (delay (when-let [^io.opentelemetry.api.trace.TracerProvider p (get (force otel-default-providers_) :tracer-provider)] (do #_impl/viable-tracer (.get p "Telemere"))))))) (comment (enc/qb 1e6 (force *otel-tracer*))) ; 51.23 ;;;; Signal creators ;; - event! [id ] [id opts/level] ; id + ?level => allowed? ; Sole signal with descending main arg! ;; - log! [msg ] [opts/level msg] ; msg + ?level => allowed? ;; - error! [error] [opts/id error] ; error + ?id => given error ;; - trace! [form ] [opts/id form] ; run + ?id => run result (value or throw) ;; - spy! [form ] [opts/level form] ; run + ?level => run result (value or throw) ;; - catch->error! [form ] [opts/id form] ; run + ?id => run value or ?return ;; - signal! [opts ] ; => allowed? / run result (value or throw) ;; - uncaught->error! [opts/id] ; ?id => nil #?(:clj (defmacro event! "[id] [id level-or-opts] => allowed?" {:doc (impl/signal-docstring :event!) :arglists (impl/signal-arglists :event!)} [& args] (let [opts (impl/signal-opts `event! (enc/get-source &form &env) {:kind :event, :level :info} :id :level :dsc args)] `(impl/signal! ~opts)))) (comment (with-signal (event! ::my-id :info))) #?(:clj (defmacro log! "[msg] [level-or-opts msg] => allowed?" {:doc (impl/signal-docstring :log!) :arglists (impl/signal-arglists :log!)} [& args] (let [opts (impl/signal-opts `log! (enc/get-source &form &env) {:kind :log, :level :info} :msg :level :asc args)] `(impl/signal! ~opts)))) (comment (with-signal (log! :info "My msg"))) #?(:clj (defmacro error! "[error] [error id-or-opts] => error" {:doc (impl/signal-docstring :error!) :arglists (impl/signal-arglists :error!)} [& args] (let [opts (impl/signal-opts `error! (enc/get-source &form &env) {:kind :error, :level :error} :error :id :asc args) error-form (get opts :error)] `(let [~'__error ~error-form] (impl/signal! ~(assoc opts :error '__error)) ~'__error ; Unconditional! )))) (comment (with-signal (throw (error! ::my-id (ex-info "MyEx" {}))))) #?(:clj (defmacro catch->error! "[form] [id-or-opts form] => run value or ?catch-val" {:doc (impl/signal-docstring :catch-to-error!) :arglists (impl/signal-arglists :catch->error!)} [& args] (let [opts (impl/signal-opts `catch->error! (enc/get-source &form &env) {:kind :error, :level :error} ::__form :id :asc args) 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) opts (dissoc opts ::__form :catch-val :catch-sym :rethrow?)] `(enc/try* ~form (catch :all ~catch-sym (impl/signal! ~(assoc opts :error catch-sym)) (if ~rethrow? (throw ~catch-sym) ~catch-val)))))) (comment (with-signal (catch->error! ::my-id (/ 1 0))) (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! (enc/get-source &form &env) {: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 `(catch->error! ~catch-opts (impl/signal! ~opts)) (do `(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! (enc/get-source &form &env) {: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 `(catch->error! ~catch-opts (impl/signal! ~opts)) (do `(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 uncaught JVM errors. See `uncaught->handler!` and `error!` for details." {:arglists (impl/signal-arglists :uncaught->error!)} [& args] (let [msg-form ["Uncaught Throwable on thread: " `(.getName ~(with-meta '__thread {:tag 'java.lang.Thread}))] opts (impl/signal-opts `uncaught->error! (enc/get-source &form &env) {:kind :error, :level :error, :msg msg-form} :error :id :dsc (into ['__throwable] args))] `(uncaught->handler! (fn [~'__thread ~'__throwable] (impl/signal! ~opts)))))) (comment (macroexpand '(uncaught->error! ::my-id))) #?(:clj (defn uncaught->handler! "Sets JVM's global `DefaultUncaughtExceptionHandler` to given (fn handler [`` ``]). See also `uncaught->error!`." [handler] (Thread/setDefaultUncaughtExceptionHandler (reify Thread$UncaughtExceptionHandler (uncaughtException [_ thread throwable] (handler thread throwable)))) nil)) ;;;; Interop #?(:clj (enc/defaliases impl/check-interop streams/with-out->telemere streams/with-err->telemere streams/with-streams->telemere streams/streams->telemere! streams/streams->reset!)) (comment (check-interop)) ;;;; Handlers (enc/defaliases #?(:default consoles/handler:console) #?(:cljs consoles/handler:console-raw) #?(:clj files/handler:file)) ;;;; Init (impl/on-init (enc/set-var-root! sigs/*default-handler-error-fn* (fn [{:keys [error] :as m}] (impl/signal! {:kind :error :level :error :error error :location {:ns "taoensso.encore.signals"} :id :taoensso.encore.signals/handler-error :msg "Error executing wrapped handler fn" :data (dissoc m :error)}))) (enc/set-var-root! sigs/*default-handler-backp-fn* (fn [data] (impl/signal! {:kind :event :level :warn :location {:ns "taoensso.encore.signals"} :id :taoensso.encore.signals/handler-back-pressure :msg "Back pressure on wrapped handler fn" :data data}))) (add-handler! :default/console (handler:console)) #?(:clj (enc/catching (require '[taoensso.telemere.tools-logging]))) ; TL->Telemere #?(:clj (enc/catching (require '[taoensso.telemere.slf4j]))) ; SLF4J->Telemere #?(:clj (enc/catching (require '[taoensso.telemere.open-telemetry]))) ; Telemere->OTel ) ;;;; Flow benchmarks (comment {:last-updated "2024-08-15" :system "2020 Macbook Pro M1, 16 GB memory" :clojure-version "1.12.0-rc1" :java-version "OpenJDK 22"} [(binding [impl/*sig-handlers* nil] (enc/qb 1e6 ; [9.31 16.76 264.12 350.43] (signal! {:level :info, :run nil, :elide? true }) ; 9 (signal! {:level :info, :run nil, :allow? false}) ; 17 (signal! {:level :info, :run nil, :allow? true }) ; 264 (signal! {:level :info, :run nil }) ; 350 )) (binding [impl/*sig-handlers* nil] (enc/qb 1e6 ; [8.34 15.78 999.27 444.08 1078.83] (signal! {:level :info, :run "run", :elide? true }) ; 8 (signal! {:level :info, :run "run", :allow? false}) ; 16 (signal! {:level :info, :run "run", :allow? true }) ; 1000 (signal! {:level :info, :run "run", :trace? false}) ; 444 (signal! {:level :info, :run "run" }) ; 1079 )) ;; For README "performance" table (binding [impl/*sig-handlers* nil] (enc/qb [8 1e6] ; [9.34 347.7 447.71 1086.65] (signal! {:level :info, :elide? true }) ; 9 (signal! {:level :info }) ; 348 (signal! {:level :info, :run "run", :trace? false}) ; 448 (signal! {:level :info, :run "run" }) ; 1087 )) ;; Full bench to handled signals ;; Sync => 4240.6846 (~4.2m/sec) ;; Async dropping => 2421.9176 (~2.4m/sec) (let [runtime-msecs 5000 n-procs (.availableProcessors (Runtime/getRuntime)) fp (enc/future-pool n-procs) c (java.util.concurrent.atomic.AtomicLong. 0) p (promise)] (with-handler ::bench (fn [_] (.incrementAndGet c)) {:async nil} ; Sync #_{:async {:mode :dropping, :n-threads n-procs}} (let [t (enc/after-timeout runtime-msecs (deliver p (.get c)))] (dotimes [_ n-procs] (fp (fn [] (dotimes [_ 6e6] (signal! {:level :info}))))) (/ (double @p) (double runtime-msecs)))))]) ;;;; (comment (with-handler :hid1 (handler:console) {} (log! "Message")) (let [sig (with-signal (event! ::ev-id {:data {:a :A :b :b} :error (ex-info "Ex2" {:b :B} (ex-info "Ex1" {:a :A}))}))] (do (let [hf (handler:file)] (hf sig) (hf))) (do (let [hf (handler:console)] (hf sig) (hf))) #?(:cljs (let [hf (handler:console-raw)] (hf sig) (hf))))) (comment (let [[_ [s1 s2]] (with-signals (trace! ::id1 (trace! ::id2 "form2")))] s1))