From 7b09d1a562a73c550a3ddaba78f80871dc936960 Mon Sep 17 00:00:00 2001 From: Peter Taoussanis Date: Wed, 15 May 2013 20:09:36 +0700 Subject: [PATCH] BREAKING: Refactor Timbre for integration with clojure.tools.logging & logf macros BREAKING CHANGES: * Custom appenders that rely on the :more argument will no longer function correctly. * Stacktraces are no longer automatically generated at the `log`-macro level, but are left as an appender implementation detail. A :throwable appender argument has been added along with a `stacktrace` fn. MIGRATION GUIDE: * :message is now a string of all arguments as joined by `logp`/`logf`. Appenders that need unjoined logging arguments (i.e. raw arguments as given to `logp`/`logf`) should use the new :log-args vector. MOTIVATION: The :more argument was always kind of manky. By joining logging arguments at the `log`-macro level, we simplify appender implementations and allow the use of different joining strategies like `logp` and `logf`. This approach also fits better with the `tools.logging` API, allowing a cleaner Logger implementation. --- README.md | 9 +- src/taoensso/timbre.clj | 169 ++++++++++++++--------- src/taoensso/timbre/appenders/irc.clj | 14 +- src/taoensso/timbre/appenders/postal.clj | 13 +- src/taoensso/timbre/frequencies.clj | 9 +- src/taoensso/timbre/profiling.clj | 9 +- src/taoensso/timbre/tools/logging.clj | 24 ++++ 7 files changed, 153 insertions(+), 94 deletions(-) create mode 100644 src/taoensso/timbre/tools/logging.clj diff --git a/README.md b/README.md index c4b96cd..2c25996 100644 --- a/README.md +++ b/README.md @@ -6,9 +6,7 @@ Current [semantic](http://semver.org/) version: # Timbre, a (sane) Clojure logging & profiling library -Logging with Java can be maddeningly, unnecessarily hard. Particularly if all you want is something *simple that works out-the-box*. [tools.logging](https://github.com/clojure/tools.logging) helps, but it doesn't save you from the mess of logger dependencies and configuration hell. - -Timbre is an attempt to make **simple logging simple** and more **complex logging reasonable**. No XML! +Logging with Java can be maddeningly, unnecessarily hard. Particularly if all you want is something *simple that works out-the-box*. Timbre is an attempt to make **simple logging simple** and more **complex logging reasonable**. No XML! ## What's In The Box? * Small, uncomplicated **all-Clojure** library. @@ -18,6 +16,7 @@ Timbre is an attempt to make **simple logging simple** and more **complex loggin * Sensible built-in appenders including simple **email appender**. * Tunable **rate limit** and **asynchronous** logging support. * Robust **namespace filtering**. + * **[tools.logging](https://github.com/clojure/tools.logging)** support (optional). * Dead-simple, logging-level-aware **logging profiler**. ## Getting Started @@ -171,9 +170,9 @@ Writing a custom appender is dead-easy: :enabled? true :async? false :limit-per-msecs nil ; No rate limit - :fn (fn [{:keys [ap-config level prefix message more] :as args}] + :fn (fn [{:keys [ap-config level prefix throwable message] :as args}] (when-not (:my-production-mode? ap-config) - (apply println prefix "Hello world!" message more))) + (println prefix "Hello world!" message))) ``` And because appender fns are just regular Clojure fns, you have *unlimited power*: write to your database, send a message over the network, check some other state (e.g. environment config) before making a choice, etc. diff --git a/src/taoensso/timbre.clj b/src/taoensso/timbre.clj index adba0b5..044559f 100644 --- a/src/taoensso/timbre.clj +++ b/src/taoensso/timbre.clj @@ -38,6 +38,10 @@ "Evaluates body with *err* bound to *out*." [& body] `(binding [*err* *out*] ~@body)) +(defn stacktrace [throwable & [separator]] + (when throwable + (str (when-let [s separator] s) (stacktrace/pst-str throwable)))) + ;;;; Default configuration and appenders (utils/defonce* config @@ -48,10 +52,12 @@ :doc, :min-level, :enabled?, :async?, :limit-per-msecs, :fn An appender's fn takes a single map argument with keys: - :level, :message, :more ; From all logging macros (`info`, etc.) - :profiling-stats ; From `profile` macro - :ap-config ; `shared-appender-config` - :prefix ; Output of `prefix-fn` + :level, :throwable + :message, ; Stringified logging macro args, or nil + :args, ; Raw logging macro args (`info`, etc.) + :ap-config ; `shared-appender-config` + :prefix ; Output of `prefix-fn` + :profiling-stats ; From `profile` macro And also: :instant, :timestamp, :hostname, :ns, :error? MIDDLEWARE @@ -89,18 +95,19 @@ {:standard-out {:doc "Prints to *out* or *err* as appropriate. Enabled by default." :min-level nil :enabled? true :async? false :limit-per-msecs nil - :fn (fn [{:keys [error? prefix message more]}] + :fn (fn [{:keys [error? prefix throwable message]}] (binding [*out* (if error? *err* *out*)] - (apply str-println prefix "-" message more)))} + (str-println prefix "-" message (stacktrace throwable))))} :spit {:doc "Spits to (:spit-filename :shared-appender-config) file." :min-level nil :enabled? false :async? false :limit-per-msecs nil - :fn (fn [{:keys [ap-config prefix message more]}] + :fn (fn [{:keys [ap-config prefix throwable message]}] (when-let [filename (:spit-filename ap-config)] (try (spit filename - (with-out-str (apply str-println prefix "-" - message more)) + (with-out-str + (str-println prefix "-" message + (stacktrace throwable))) :append true) (catch java.io.IOException _))))}}})) @@ -137,6 +144,7 @@ apfn ;; Per-appender prefix-fn support (cmp. default prefix-fn) + ;; TODO Currently undocumented, candidate for removal ((fn [apfn] (if-not prefix-fn apfn @@ -148,30 +156,23 @@ ((fn [apfn] (if-not limit-per-msecs apfn - (let [;; {:hash last-appended-time-msecs ...} - flood-timers (atom {})] - - (fn [{:keys [ns message] :as apfn-args}] + (let [timers (atom {})] ; {:hash last-appended-time-msecs ...} + (fn [{ns :ns [x1 & _] :args :as apfn-args}] (let [now (System/currentTimeMillis) - hash (str ns "/" message) - allow? (fn [last-msecs] - (or (not last-msecs) - (> (- now last-msecs) limit-per-msecs)))] + hash (str ns "/" x1) + limit? (fn [last-msecs] + (and last-msecs (<= (- now last-msecs) + limit-per-msecs)))] - (when (allow? (@flood-timers hash)) + (when-not (limit? (@timers hash)) (apfn apfn-args) - (swap! flood-timers assoc hash now)) + (swap! timers assoc hash now)) - ;; Occassionally garbage-collect all expired timers. Note - ;; that due to snapshotting, garbage-collection can cause - ;; some appenders to re-append prematurely. - (when (< (rand) 0.001) - (let [timers-snapshot @flood-timers - expired-timers - (->> (keys timers-snapshot) - (filter #(allow? (timers-snapshot %))))] - (when (seq expired-timers) - (apply swap! flood-timers dissoc expired-timers)))))))))) + (when (< (rand) 0.001) ; Occasionally garbage collect + (when-let [expired-timers (->> (keys @timers) + (remove #(limit? (@timers %))) + (seq))] + (apply swap! timers dissoc expired-timers))))))))) ;; Async (agent) support ((fn [apfn] @@ -303,37 +304,60 @@ [level] (and (sufficient-level? level) (@ns-filter-cache *ns*))) (defmacro log* - "Prepares given arguments for, and then dispatches to all level-relevant - appender-fns." - [level base-args & sigs] - `(when-let [juxt-fn# (@appenders-juxt-cache ~level)] ; Any relevant appenders? - (let [[x1# & xs#] (list ~@sigs) + "Implementation detail - subject to change.. + Prepares given arguments for, and then dispatches to all level-relevant + appender-fns. " - has-throwable?# (instance? Throwable x1#) - appender-args# - (conj - ~base-args ; Allow flexibility to inject exta args - {:level ~level - :error? (error-level? ~level) - :instant (Date.) - :ns ~(str *ns*) - :message (if has-throwable?# (or (first xs#) x1#) x1#) - :more (if has-throwable?# - (conj (vec (rest xs#)) - (str "\nStacktrace:\n" - (stacktrace/pst-str x1#))) - (vec xs#))})] + ;; For tools.logging.impl/Logger support + ([base-appender-args level log-vargs ns throwable message juxt-fn] + `(when-let [juxt-fn# (or ~juxt-fn (@appenders-juxt-cache ~level))] + (juxt-fn# + (conj (or ~base-appender-args {}) + {:instant (Date.) + :ns ~ns + :level ~level + :error? (error-level? ~level) + :args ~log-vargs ; No native tools.logging support + :throwable ~throwable + :message ~message})) + true)) - (juxt-fn# appender-args#) - nil))) + ([base-appender-args level log-args message-fn] + `(when-let [juxt-fn# (@appenders-juxt-cache ~level)] + (let [[x1# & xn# :as xs#] (vector ~@log-args) + has-throwable?# (and xn# (instance? Throwable x1#)) + log-vargs# (vec (if has-throwable?# xn# xs#))] + (log* ~base-appender-args + ~level + log-vargs# + ~(str *ns*) + (when has-throwable?# x1#) + (when-let [mf# ~message-fn] (apply mf# log-vargs#)) + juxt-fn#))))) (defmacro log "When logging is enabled, actually logs given arguments with level-relevant - appender-fns. Generic form of standard level-loggers (trace, info, etc.)." - {:arglists '([level message & more] [level throwable message & more])} + appender-fns." + {:arglists '([level & args] [level throwable & args])} [level & sigs] `(when (logging-enabled? ~level) - (log* ~level {} ~@sigs))) + (log* {} ~level ~sigs nil))) + +(defmacro logp + "When logging is enabled, actually logs given arguments with level-relevant + appender-fns using print-style :message." + {:arglists '([level & message] [level throwable & message])} + [level & sigs] + `(when (logging-enabled? ~level) + (log* {} ~level ~sigs print-str))) + +(defmacro logf + "When logging is enabled, actually logs given arguments with level-relevant + appender-fns using format-style :message." + {:arglists '([level fmt & fmt-args] [level throwable fmt & fmt-args])} + [level & sigs] + `(when (logging-enabled? ~level) + (log* {} ~level ~sigs format))) (defmacro spy "Evaluates named expression and logs its result. Always returns the result. @@ -342,9 +366,9 @@ ([level expr] `(spy ~level '~expr ~expr)) ([level name expr] `(try - (let [result# ~expr] (log ~level ~name result#) result#) + (let [result# ~expr] (logp ~level ~name result#) result#) (catch Exception e# - (log ~level '~expr (str "\n" (stacktrace/pst-str e#))) + (logp ~level '~expr (str "\n" (stacktrace/pst-str e#))) (throw e#))))) (defmacro s ; Alias @@ -353,14 +377,19 @@ (defmacro ^:private def-logger [level] (let [level-name (name level)] - `(defmacro ~(symbol level-name) - ~(str "Log given arguments at " (str/capitalize level-name) " level.") - ~'{:arglists '([message & more] [throwable message & more])} - [& sigs#] - `(log ~~level ~@sigs#)))) + `(do + (defmacro ~(symbol level-name) + ~(str "Log given arguments at " level " level using print-style args.") + ~'{:arglists '([& message] [throwable & message])} + [& sigs#] `(logp ~~level ~@sigs#)) -(defmacro ^:private def-loggers - [] `(do ~@(map (fn [level] `(def-logger ~level)) ordered-levels))) + (defmacro ~(symbol (str level-name "f")) + ~(str "Log given arguments at " level " level using format-style args.") + ~'{:arglists '([fmt & fmt-args] [throwable fmt & fmt-args])} + [& sigs#] `(logf ~~level ~@sigs#))))) + +(defmacro ^:private def-loggers [] + `(do ~@(map (fn [level] `(def-logger ~level)) ordered-levels))) (def-loggers) ; Actually define a logger for each logging level @@ -380,13 +409,15 @@ ;;;; Dev/tests (comment - (log :fatal "arg1") - (log :debug "arg1" "arg2") - (log :debug (Exception.) "arg1" "arg2") - (log :debug (Exception.)) - (log :trace "arg1") + (info) + (info "a") + (info "a" "b" "c") + (info "a" (Exception. "b") "c") + (info (Exception. "a") "b" "c") + (logp (or nil :info) "Booya") - (log (or nil :info) "Booya") + (info "a%s" "b") + (infof "a%s" "b") (set-config! [:ns-blacklist] []) (set-config! [:ns-blacklist] ["taoensso.timbre*"]) @@ -410,4 +441,4 @@ (if (contains? message :password) (assoc args :message (assoc message :password "*****")) args) - :else args))])) + :else args))])) \ No newline at end of file diff --git a/src/taoensso/timbre/appenders/irc.clj b/src/taoensso/timbre/appenders/irc.clj index 3d74277..90aae2d 100644 --- a/src/taoensso/timbre/appenders/irc.clj +++ b/src/taoensso/timbre/appenders/irc.clj @@ -20,19 +20,21 @@ (defn ensure-conn [conf] (swap! conn #(or % (connect conf)))) -(defn send-message [{:keys [message prefix chan] :as config}] +(defn send-message [{:keys [prefix throwable message chan] :as config}] (let [conn (ensure-conn config) - lines (str/split message #"\n")] + lines (-> (str message (timbre/stacktrace throwable "\n")) + (str/split #"\n"))] (irclj/message conn chan prefix (first lines)) (doseq [line (rest lines)] (irclj/message conn chan ">" line)))) -(defn appender-fn [{:keys [ap-config prefix message]}] +(defn appender-fn [{:keys [ap-config prefix throwable message]}] (when-let [irc-config (:irc ap-config)] (send-message (assoc irc-config - :prefix prefix - :message message)))) + :prefix prefix + :throwable throwable + :message message)))) (def irc-appender {:doc (str "Sends IRC messages using irclj.\n" @@ -41,4 +43,4 @@ :name \"My Logger\" :chan \"#logs\"") :min-level :info :enabled? true :async? false :limit-per-msecs nil :prefix-fn (fn [{:keys [level]}] (-> level name str/upper-case)) - :fn appender-fn}) + :fn appender-fn}) \ No newline at end of file diff --git a/src/taoensso/timbre/appenders/postal.clj b/src/taoensso/timbre/appenders/postal.clj index 28f4079..9971d41 100644 --- a/src/taoensso/timbre/appenders/postal.clj +++ b/src/taoensso/timbre/appenders/postal.clj @@ -12,10 +12,11 @@ {:from \"Bob's logger \" :to \"foo@example.com\"}") :min-level :error :enabled? true :async? true :limit-per-msecs (* 1000 60 10) ; 1 subject / 10 mins - :fn (fn [{:keys [ap-config prefix message more]}] + :fn (fn [{:keys [ap-config prefix throwable args]}] (when-let [postal-config (:postal ap-config)] - (postal/send-message - (assoc postal-config - :subject (str prefix " - " message) - :body (if (seq more) (str/join " " more) - "")))))}) + (let [[subject & body] args] + (postal/send-message + (assoc postal-config + :subject (str prefix " - " subject) + :body (str (str/join \space body) + (timbre/stacktrace throwable "\n")))))))}) \ No newline at end of file diff --git a/src/taoensso/timbre/frequencies.clj b/src/taoensso/timbre/frequencies.clj index 3fd25eb..d161db4 100644 --- a/src/taoensso/timbre/frequencies.clj +++ b/src/taoensso/timbre/frequencies.clj @@ -28,10 +28,11 @@ (let [name (utils/fq-keyword name)] `(let [{result# :result stats# :stats} (with-fdata ~level ~@body)] (when stats# - (timbre/log* ~level - {:frequency-stats stats#} - (str "Frequencies " ~name) - (str "\n" (format-fdata stats#)))) + (timbre/log* {:frequency-stats stats#} + ~level + [(str "Frequencies " ~name) + (str "\n" (format-fdata stats#))] + print-str)) result#))) (defmacro sampling-log-frequencies diff --git a/src/taoensso/timbre/profiling.clj b/src/taoensso/timbre/profiling.clj index 80e57dc..1c1f475 100644 --- a/src/taoensso/timbre/profiling.clj +++ b/src/taoensso/timbre/profiling.clj @@ -29,10 +29,11 @@ (let [name (utils/fq-keyword name)] `(let [{result# :result stats# :stats} (with-pdata ~level ~@body)] (when stats# - (timbre/log* ~level - {:profile-stats stats#} - (str "Profiling " ~name) - (str "\n" (format-pdata stats#)))) + (timbre/log* {:profile-stats stats#} + ~level + [(str "Profiling " ~name) + (str "\n" (format-pdata stats#))] + print-str)) result#))) (defmacro sampling-profile diff --git a/src/taoensso/timbre/tools/logging.clj b/src/taoensso/timbre/tools/logging.clj new file mode 100644 index 0000000..d90a1b1 --- /dev/null +++ b/src/taoensso/timbre/tools/logging.clj @@ -0,0 +1,24 @@ +(ns taoensso.timbre.tools.logging + "clojure.tools.logging.impl/Logger implementation" + (:require [taoensso.timbre :as timbre])) + +(deftype Logger [logger-ns] + clojure.tools.logging.impl/Logger + (enabled? [_ level] (timbre/logging-enabled? level)) + (write! [_ level throwable message] + ;; tools.logging message may be a string (for `logp`/`logf` calls) or raw + ;; argument (for `log` calls). Note that without an :args equivalent for + ;; `write!`, the best we can do is `[message]`. This inconsistency means + ;; that :args consumers (like the rate limiter and Postal appender) will + ;; necessarily behave differently under tools.logging. + (timbre/log* {} level [message] logger-ns throwable + (when (string? message) message) nil))) + +(deftype LoggerFactory [] + clojure.tools.logging.impl/LoggerFactory + (name [_] "Timbre") + (get-logger [_ logger-ns] (->Logger logger-ns))) + +(defn use-timbre [] + (alter-var-root clojure.tools.logging/*logger-factory* + (constantly (->LoggerFactory)))) \ No newline at end of file