From 413b2fd529961c343285ea9e3627dc95a3867284 Mon Sep 17 00:00:00 2001 From: Peter Taoussanis Date: Fri, 29 Nov 2013 14:34:57 +0700 Subject: [PATCH] nb - major refactor (see commit msg for details) CHANGES * DEPRECATED: `red`, `green`, `blue` -> use `color-str` instead. * Logging level is now located in `level-atom` rather than `config`. This is in prep for new config types. Old in-config levels will be respected (i.e. change is backwards compatible). * DEPRECATED: config `prefix-fn` has been replaced by the more flexible `fmt-output-fn`. Change is backwards compatible. * Built-in appenders have been simplified using the new `default-output` appender arg. * Per-appender `:prefix` option dropped - was unnecessary. If an appender wants custom output formatting, it can do so w/o using an in-config formatter. FIXES * Messages are now generated _after_ middleware has been applied, allowing better filtering performance and more intuitive behaviour (e.g. changes to args in middleware will now automatically percolate to message content). --- src/taoensso/timbre.clj | 321 ++++++++++++++------------ src/taoensso/timbre/tools/logging.clj | 4 +- 2 files changed, 176 insertions(+), 149 deletions(-) diff --git a/src/taoensso/timbre.clj b/src/taoensso/timbre.clj index 85d03aa..1ee1753 100644 --- a/src/taoensso/timbre.clj +++ b/src/taoensso/timbre.clj @@ -22,10 +22,6 @@ "0"))] (str (ansi-color color) (apply str xs) (ansi-color :reset)))) -(def red (partial color-str :red)) -(def green (partial color-str :green)) -(def yellow (partial color-str :yellow)) - (def default-out (java.io.OutputStreamWriter. System/out)) (def default-err (java.io.PrintWriter. System/err)) @@ -41,134 +37,132 @@ (when throwable (str separator (aviso-ex/format-exception throwable)))) -;;;; Default configuration and appenders +;;;; Logging levels +;; Level precendence: compile-time > dynamic > atom -(def compile-time-level +(def level-compile-time "Constant, compile-time logging level determined by the `TIMBRE_LOG_LEVEL` environment variable. When set, overrules dynamically-configurable logging level as a performance optimization (e.g. for use in performance sensitive production environments)." (keyword (System/getenv "TIMBRE_LOG_LEVEL"))) -(def ^:dynamic *current-level* nil) +(def ^:dynamic *level-dynamic* nil) (defmacro with-log-level "Allows thread-local config logging level override. Useful for dev & testing." - [level & body] `(binding [*current-level* ~level] ~@body)) + [level & body] `(binding [*level-dynamic* ~level] ~@body)) -(utils/defonce* config - "This map atom controls everything about the way Timbre operates. +(def level-atom (atom :debug)) +(defn set-level! [level] (reset! level-atom level)) - APPENDERS - An appender is a map with keys: - :doc, :min-level, :enabled?, :async?, :limit-per-msecs, :fn +;;; - An appender's fn takes a single map argument with keys: - :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` - :profile-stats ; From `profile` macro - And also: :instant, :timestamp, :hostname, :ns, :error? +(def ^:private levels-ordered [:trace :debug :info :warn :error :fatal :report]) +(def ^:private levels-scored (assoc (zipmap levels-ordered (next (range))) nil 0)) - MIDDLEWARE - Middleware are fns (applied right-to-left) that transform the map argument - dispatched to appender fns. If any middleware returns nil, no dispatching - will occur (i.e. the event will be filtered). +(defn error-level? [level] (boolean (#{:error :fatal} level))) ; For appenders, etc. - See source code for examples. See `set-config!`, `merge-config!`, `set-level!` - for convenient config editing." - (atom {:current-level :debug ; See also `with-log-level` +(defn- level-checked-score [level] + (or (levels-scored level) + (throw (Exception. (format "Invalid logging level: %s" level))))) - ;;; Control log filtering by namespace patterns (e.g. ["my-app.*"]). - ;;; Useful for turning off logging in noisy libraries, etc. - :ns-whitelist [] - :ns-blacklist [] +(def ^:private levels-compare (memoize (fn [x y] (- (level-checked-score x) + (level-checked-score y))))) - ;; Fns (applied right-to-left) to transform/filter appender fn args. - ;; Useful for obfuscating credentials, pattern filtering, etc. - :middleware [] +(declare config) +(defn- level-sufficient? [level] + (>= (levels-compare level + (or level-compile-time + *level-dynamic* + (:current-level @config) ; DEPRECATED, here for backwards comp + @level-atom)) 0)) - ;;; Control :timestamp format - :timestamp-pattern "yyyy-MMM-dd HH:mm:ss ZZ" ; SimpleDateFormat pattern - :timestamp-locale nil ; A Locale object, or nil +;;;; Default configuration and appenders - ;; Control :prefix format ; TODO Generalize to output pattern - :prefix-fn - (fn [{:keys [level timestamp hostname ns]}] - (str timestamp " " hostname " " (-> level name str/upper-case) - " [" ns "]")) +(def example-config + "APPENDERS + An appender is a map with keys: + :doc, :min-level, :enabled?, :async?, :limit-per-msecs, :fn - ;; Will be provided to all appenders via :ap-config key - :shared-appender-config {} + An appender's fn takes a single map with keys: + :level, :throwable + :args, ; Raw logging macro args (as given to `info`, etc.). + :message, ; Stringified logging macro args, or nil. + :default-output ; Output of `fmt-output-fn`, used by built-in appenders. + :ap-config ; `shared-appender-config`. + :profile-stats ; From `profile` macro. + And also: :instant, :timestamp, :hostname, :ns, :error? - :appenders - {: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 throwable message]}] - (binding [*out* (if error? *err* *out*)] - (str-println prefix "-" message (stacktrace throwable))))} + MIDDLEWARE + Middleware are fns (applied right-to-left) that transform the map + dispatched to appender fns. If any middleware returns nil, no dispatching + will occur (i.e. the event will be filtered). - :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 throwable message]}] - (when-let [filename (:spit-filename ap-config)] - (try (spit filename - (with-out-str - (str-println prefix "-" message - (stacktrace throwable))) - :append true) - (catch java.io.IOException _))))}}})) + The `example-config` code contains more details. + See also `set-config!`, `merge-config!`, `set-level!`." + {;;; Control log filtering by namespace patterns (e.g. ["my-app.*"]). + ;;; Useful for turning off logging in noisy libraries, etc. + :ns-whitelist [] + :ns-blacklist [] + + ;; Fns (applied right-to-left) to transform/filter appender fn args. + ;; Useful for obfuscating credentials, pattern filtering, etc. + :middleware [] + + ;;; Control :timestamp format + :timestamp-pattern "yyyy-MMM-dd HH:mm:ss ZZ" ; SimpleDateFormat pattern + :timestamp-locale nil ; A Locale object, or nil + + :prefix-fn ; DEPRECATED, here for backwards comp + (fn [{:keys [level timestamp hostname ns]}] + (str timestamp " " hostname " " (-> level name str/upper-case) + " [" ns "]")) + + ;; Default output formatter used by built-in appenders. Custom appenders + ;; may (but are not required to use) its output (:default-output). + :fmt-output-fn + (fn [{:keys [level throwable message timestamp hostname ns]}] + ;; [] - + (format "%s %s %s [%s] - %s%s" + timestamp hostname (-> level name str/upper-case) ns (or message "") + (or (stacktrace throwable "\n") ""))) + + :shared-appender-config {} ; Provided to all appenders via :ap-config key + :appenders + {:standard-out + {:doc "Prints to *out*/*err*. Enabled by default." + :min-level nil :enabled? true :async? false :limit-per-msecs nil + :fn (fn [{:keys [error? default-output]}] + (binding [*out* (if error? *err* *out*)] + (str-println default-output)))} + + :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 default-output]}] + (when-let [filename (:spit-filename ap-config)] + (try (spit filename default-output :append true) + (catch java.io.IOException _))))}}}) + +(utils/defonce* config (atom example-config)) (defn set-config! [ks val] (swap! config assoc-in ks val)) (defn merge-config! [& maps] (apply swap! config utils/merge-deep maps)) -(defn set-level! [level] (set-config! [:current-level] level)) - -;;;; Define and sort logging levels - -(def ^:private ordered-levels [:trace :debug :info :warn :error :fatal :report]) -(def ^:private scored-levels (assoc (zipmap ordered-levels (next (range))) nil 0)) - -(defn error-level? [level] (boolean (#{:error :fatal} level))) - -(defn- checked-level-score [level] - (or (scored-levels level) - (throw (Exception. (str "Invalid logging level: " level))))) - -(def compare-levels - (memoize (fn [x y] (- (checked-level-score x) (checked-level-score y))))) - -(defn sufficient-level? - [level] (>= (compare-levels level (or compile-time-level - *current-level* - (:current-level @config))) 0)) ;;;; Appender-fn decoration (defn- wrap-appender-fn "Wraps compile-time appender fn with additional runtime capabilities controlled by compile-time config." - [{apfn :fn :keys [async? limit-per-msecs prefix-fn] :as appender}] + [{apfn :fn :keys [async? limit-per-msecs] :as appender}] (let [limit-per-msecs (or (:max-message-per-msecs appender) - limit-per-msecs)] ; Backwards-compatibility + limit-per-msecs)] ; Backwards comp (->> ; Wrapping applies per appender, bottom-to-top apfn - ;; Per-appender prefix-fn support (cmp. default prefix-fn) - ;; TODO Currently undocumented, candidate for removal - ((fn [apfn] - (if-not prefix-fn - apfn - (fn [apfn-args] - (apfn (assoc apfn-args - :prefix (prefix-fn apfn-args))))))) - ;; Rate limit support ((fn [apfn] - (if-not limit-per-msecs - apfn + (if-not limit-per-msecs apfn (let [timers (atom {})] ; {:hash last-appended-time-msecs ...} (fn [{ns :ns [x1 & _] :args :as apfn-args}] (let [now (System/currentTimeMillis) @@ -189,8 +183,7 @@ ;; Async (agent) support ((fn [apfn] - (if-not async? - apfn + (if-not async? apfn (let [agent (agent nil :error-mode :continue)] (fn [apfn-args] (send-off agent (fn [_] (apfn apfn-args))))))))))) @@ -208,7 +201,7 @@ (comment ((make-timestamp-fn "yyyy-MMM-dd" nil) (Date.))) -(def get-hostname +(def ^:private get-hostname (utils/memoize-ttl 60000 (fn [] (let [p (promise)] @@ -227,28 +220,53 @@ (->> ; Wrapping applies per juxt, bottom-to-top juxtfn + ;; Post-middleware stuff + ((fn [juxtfn] + ;; Compile-time: + (let [{ap-config :shared-appender-config + :keys [timestamp-pattern timestamp-locale + prefix-fn fmt-output-fn]} @config + timestamp-fn (make-timestamp-fn timestamp-pattern timestamp-locale)] + (fn [juxtfn-args] + ;; Runtime: + (when-let [{:keys [instant msg-type args]} juxtfn-args] + (let [juxtfn-args (if-not msg-type juxtfn-args ; tools.logging + (-> juxtfn-args + (dissoc :msg-type) + (assoc :message + (when-not (empty? args) + (case msg-type + :format (apply format args) + :print-str (apply print-str args) + :nil nil)))))] + (juxtfn + (merge juxtfn-args + {:timestamp (timestamp-fn instant) + ;; DEPRECATED, here for backwards comp: + :prefix (when-let [f prefix-fn] (f juxtfn-args)) + :default-output (when-let [f fmt-output-fn] (f juxtfn-args))})))))))) + ;; Middleware transforms/filters support ((fn [juxtfn] + ;; Compile-time: (if-let [middleware (seq (:middleware @config))] (let [composed-middleware (apply comp (map (fn [mf] (fn [args] (when args (mf args)))) middleware))] (fn [juxtfn-args] + ;; Runtime: (when-let [juxtfn-args (composed-middleware juxtfn-args)] (juxtfn juxtfn-args)))) juxtfn))) - ;; Add compile-time stuff to runtime appender args + ;; Pre-middleware stuff ((fn [juxtfn] - (let [{ap-config :shared-appender-config - :keys [timestamp-pattern timestamp-locale prefix-fn]} @config - - timestamp-fn (make-timestamp-fn timestamp-pattern timestamp-locale)] - (fn [{:keys [instant] :as juxtfn-args}] - (let [juxtfn-args (merge juxtfn-args {:ap-config ap-config - :timestamp (timestamp-fn instant) - :hostname (get-hostname)})] - (juxtfn (assoc juxtfn-args :prefix (prefix-fn juxtfn-args)))))))))) + ;; Compile-time: + (let [{ap-config :shared-appender-config} @config] + (fn [juxtfn-args] + ;; Runtime: + (juxtfn (merge juxtfn-args {:ap-config ap-config + :hostname (get-hostname)})))))))) ;;;; Caching @@ -264,7 +282,7 @@ (defn- relevant-appenders [level] (->> (:appenders @config) (filter #(let [{:keys [enabled? min-level]} (val %)] - (and enabled? (>= (compare-levels level min-level) 0)))) + (and enabled? (>= (levels-compare level min-level) 0)))) (into {}))) (comment (relevant-appenders :debug) @@ -273,8 +291,8 @@ (defn- cache-appenders-juxt! [] (->> (zipmap - ordered-levels - (->> ordered-levels + levels-ordered + (->> levels-ordered (map (fn [l] (let [rel-aps (relevant-appenders l)] ;; Return nil if no relevant appenders (when-let [ap-ids (keys rel-aps)] @@ -319,8 +337,25 @@ ;;;; Logging macros +(defmacro logging-enabled? + "Returns true iff current logging level is sufficient and current namespace + unfiltered. The namespace test is runtime, the logging-level test compile-time + iff a compile-time logging level was specified." + [level] + (if level-compile-time + (when (level-sufficient? level) + `(@ns-filter-cache ~(str *ns*))) + `(and (level-sufficient? ~level) (@ns-filter-cache ~(str *ns*))))) + +(comment (def compile-time-level :info) + (def compile-time-level nil) + (macroexpand-1 '(logging-enabled? :debug))) + (defn send-to-appenders! "Implementation detail - subject to change." - [level base-appender-args log-vargs ns throwable message & [juxt-fn file line]] + [;; Args provided by both Timbre, tools.logging: + level base-appender-args log-vargs ns throwable message + ;; Additional args provided by Timbre only: + & [juxt-fn msg-type file line]] (when-let [juxt-fn (or juxt-fn (@appenders-juxt-cache level))] (juxt-fn (conj (or base-appender-args {}) @@ -332,26 +367,14 @@ :error? (error-level? level) :args log-vargs ; No tools.logging support :throwable throwable - :message message})) + :message message ; Timbre: nil, tools.logging: nil or string + :msg-type msg-type ; Timbre: nnil, tools.logging: nil + })) nil)) -(defmacro logging-enabled? - "Returns true iff current logging level is sufficient and current namespace - unfiltered. The namespace test is runtime, the logging-level test compile-time - iff a compile-time logging level was specified." - [level] - (if compile-time-level - (when (sufficient-level? level) - `(@ns-filter-cache ~(str *ns*))) - `(and (sufficient-level? ~level) (@ns-filter-cache ~(str *ns*))))) - -(comment - (def compile-time-level :info) - (def compile-time-level nil) - (macroexpand-1 '(logging-enabled? :debug))) - (defmacro log* "Implementation detail - subject to change." - [message-fn level base-appender-args & log-args] + [msg-type level base-appender-args & log-args] + {:pre [(#{:nil :print-str :format} msg-type)]} `(when (logging-enabled? ~level) (when-let [juxt-fn# (@appenders-juxt-cache ~level)] (let [[x1# & xn# :as xs#] (vector ~@log-args) @@ -363,21 +386,20 @@ log-vargs# ~(str *ns*) (when has-throwable?# x1#) - (when-let [mf# ~message-fn] - (when-not (empty? log-vargs#) - (apply mf# log-vargs#))) + nil ; Timbre generates msg only after middleware juxt-fn# + ~msg-type (let [file# ~*file*] (when (not= file# "NO_SOURCE_PATH") file#)) ;; TODO Waiting on http://dev.clojure.org/jira/browse/CLJ-865: ~(:line (meta &form))))))) (defmacro log "Logs using print-style args." {:arglists '([level & message] [level throwable & message])} - [level & sigs] `(log* print-str ~level {} ~@sigs)) + [level & sigs] `(log* :print-str ~level {} ~@sigs)) (defmacro logf "Logs using format-style args." {:arglists '([level fmt & fmt-args] [level throwable fmt & fmt-args])} - [level & sigs] `(log* format ~level {} ~@sigs)) + [level & sigs] `(log* :format ~level {} ~@sigs)) (defmacro log-errors [& body] `(try ~@body (catch Throwable t# (error t#)))) (defmacro log-and-rethrow-errors [& body] @@ -412,7 +434,7 @@ [& sigs#] `(logf ~~level ~@sigs#))))) (defmacro ^:private def-loggers [] - `(do ~@(map (fn [level] `(def-logger ~level)) ordered-levels))) + `(do ~@(map (fn [level] `(def-logger ~level)) levels-ordered))) (def-loggers) ; Actually define a logger for each logging level @@ -446,6 +468,10 @@ {:arglists '([expr] [level expr] [level name expr])} [& args] `(spy ~@args)) +(def red "DEPRECATED: Use `color-str` instead." (partial color-str :red)) +(def green "DEPRECATED: Use `color-str` instead." (partial color-str :green)) +(def yellow "DEPRECATED: Use `color-str` instead." (partial color-str :yellow)) + ;;;; Dev/tests (comment @@ -466,8 +492,8 @@ (trace (Thread/sleep 5000)) (time (dotimes [n 10000] (trace "This won't log"))) ; Overhead 5ms/10ms (time (dotimes [n 5] (info "foo" "bar"))) - (spy (* 6 5 4 3 2 1)) - (spy :debug :factorial6 (* 6 5 4 3 2 1)) + (spy :info (* 6 5 4 3 2 1)) + (spy :info :factorial6 (* 6 5 4 3 2 1)) (info (Exception. "noes!") "bar") (spy (/ 4 0)) @@ -476,12 +502,13 @@ ;; Middleware (info {:name "Robert Paulson" :password "Super secret"}) - (set-config! - [:middleware] - [(fn [{:keys [hostname message] :as args}] - (cond (= hostname "filtered-host") nil ; Filter - (map? message) - (if (contains? message :password) - (assoc args :message (assoc message :password "*****")) - args) - :else args))])) + (set-config! [:middleware] []) + (set-config! [:middleware] + [(fn [{:keys [hostname message args] :as ap-args}] + (if (= hostname "filtered-host") nil ; Filter + (assoc ap-args :args + ;; Replace :password vals in any map args: + (mapv (fn [arg] (if-not (map? arg) arg + (if-not (contains? arg :password) arg + (assoc arg :password "****")))) + args))))])) diff --git a/src/taoensso/timbre/tools/logging.clj b/src/taoensso/timbre/tools/logging.clj index fea6601..37376a4 100644 --- a/src/taoensso/timbre/tools/logging.clj +++ b/src/taoensso/timbre/tools/logging.clj @@ -9,8 +9,8 @@ ;; 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. + ;; that :args consumers will necessarily behave differently under + ;; tools.logging. (timbre/send-to-appenders! level {} [message] logger-ns throwable (when (string? message) message))))