status-im/timbre
2
0
Fork 0
mirror of https://github.com/status-im/timbre.git synced 2025-02-11 11:16:31 +00:00
Code Issues Projects Releases Wiki Activity

nb - major refactor (see commit msg for details)

Browse Source 
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).
This commit is contained in:
Peter Taoussanis 2013-11-29 14:34:57 +07:00
parent c094f299a5
commit 413b2fd529
2 changed files with 176 additions and 149 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

269
src/taoensso/timbre.clj
View File

@ -22,10 +22,6 @@
"0"))] "0"))]
(str (ansi-color color) (apply str xs) (ansi-color :reset)))) (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-out (java.io.OutputStreamWriter. System/out))
(def default-err (java.io.PrintWriter. System/err)) (def default-err (java.io.PrintWriter. System/err))
@ -41,46 +37,71 @@
(when throwable (when throwable
(str separator (aviso-ex/format-exception 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` "Constant, compile-time logging level determined by the `TIMBRE_LOG_LEVEL`
environment variable. When set, overrules dynamically-configurable logging environment variable. When set, overrules dynamically-configurable logging
level as a performance optimization (e.g. for use in performance sensitive level as a performance optimization (e.g. for use in performance sensitive
production environments)." production environments)."
(keyword (System/getenv "TIMBRE_LOG_LEVEL"))) (keyword (System/getenv "TIMBRE_LOG_LEVEL")))
(def ^:dynamic *current-level* nil) (def ^:dynamic *level-dynamic* nil)
(defmacro with-log-level (defmacro with-log-level
"Allows thread-local config logging level override. Useful for dev & testing." "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 (def level-atom (atom :debug))
"This map atom controls everything about the way Timbre operates. (defn set-level! [level] (reset! level-atom level))
APPENDERS ;;;
(def ^:private levels-ordered [:trace :debug :info :warn :error :fatal :report])
(def ^:private levels-scored (assoc (zipmap levels-ordered (next (range))) nil 0))
(defn error-level? [level] (boolean (#{:error :fatal} level))) ; For appenders, etc.
(defn- level-checked-score [level]
(or (levels-scored level)
(throw (Exception. (format "Invalid logging level: %s" level)))))
(def ^:private levels-compare (memoize (fn [x y] (- (level-checked-score x)
(level-checked-score y)))))
(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))
;;;; Default configuration and appenders
(def example-config
"APPENDERS
An appender is a map with keys: An appender is a map with keys:
:doc, :min-level, :enabled?, :async?, :limit-per-msecs, :fn :doc, :min-level, :enabled?, :async?, :limit-per-msecs, :fn
An appender's fn takes a single map argument with keys: An appender's fn takes a single map with keys:
:level, :throwable :level, :throwable
:message, ; Stringified logging macro args, or nil :args, ; Raw logging macro args (as given to `info`, etc.).
:args, ; Raw logging macro args (`info`, etc.) :message, ; Stringified logging macro args, or nil.
:ap-config ; `shared-appender-config` :default-output ; Output of `fmt-output-fn`, used by built-in appenders.
:prefix ; Output of `prefix-fn` :ap-config ; `shared-appender-config`.
:profile-stats ; From `profile` macro :profile-stats ; From `profile` macro.
And also: :instant, :timestamp, :hostname, :ns, :error? And also: :instant, :timestamp, :hostname, :ns, :error?
MIDDLEWARE MIDDLEWARE
Middleware are fns (applied right-to-left) that transform the map argument Middleware are fns (applied right-to-left) that transform the map
dispatched to appender fns. If any middleware returns nil, no dispatching dispatched to appender fns. If any middleware returns nil, no dispatching
will occur (i.e. the event will be filtered). will occur (i.e. the event will be filtered).
See source code for examples. See `set-config!`, `merge-config!`, `set-level!` The `example-config` code contains more details.
for convenient config editing." See also `set-config!`, `merge-config!`, `set-level!`."
(atom {:current-level :debug ; See also `with-log-level`
;;; Control log filtering by namespace patterns (e.g. ["my-app.*"]). {;;; Control log filtering by namespace patterns (e.g. ["my-app.*"]).
;;; Useful for turning off logging in noisy libraries, etc. ;;; Useful for turning off logging in noisy libraries, etc.
:ns-whitelist [] :ns-whitelist []
:ns-blacklist [] :ns-blacklist []
@ -93,82 +114,55 @@
:timestamp-pattern "yyyy-MMM-dd HH:mm:ss ZZ" ; SimpleDateFormat pattern :timestamp-pattern "yyyy-MMM-dd HH:mm:ss ZZ" ; SimpleDateFormat pattern
:timestamp-locale nil ; A Locale object, or nil :timestamp-locale nil ; A Locale object, or nil
;; Control :prefix format ; TODO Generalize to output pattern :prefix-fn ; DEPRECATED, here for backwards comp
:prefix-fn
(fn [{:keys [level timestamp hostname ns]}] (fn [{:keys [level timestamp hostname ns]}]
(str timestamp " " hostname " " (-> level name str/upper-case) (str timestamp " " hostname " " (-> level name str/upper-case)
" [" ns "]")) " [" ns "]"))
;; Will be provided to all appenders via :ap-config key ;; Default output formatter used by built-in appenders. Custom appenders
:shared-appender-config {} ;; may (but are not required to use) its output (:default-output).
:fmt-output-fn
(fn [{:keys [level throwable message timestamp hostname ns]}]
;; <timestamp> <hostname> <LEVEL> [<ns>] - <message> <throwable>
(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 :appenders
{:standard-out {:standard-out
{:doc "Prints to *out* or *err* as appropriate. Enabled by default." {:doc "Prints to *out*/*err*. Enabled by default."
:min-level nil :enabled? true :async? false :limit-per-msecs nil :min-level nil :enabled? true :async? false :limit-per-msecs nil
:fn (fn [{:keys [error? prefix throwable message]}] :fn (fn [{:keys [error? default-output]}]
(binding [*out* (if error? *err* *out*)] (binding [*out* (if error? *err* *out*)]
(str-println prefix "-" message (stacktrace throwable))))} (str-println default-output)))}
:spit :spit
{:doc "Spits to (:spit-filename :shared-appender-config) file." {:doc "Spits to `(:spit-filename :shared-appender-config)` file."
:min-level nil :enabled? false :async? false :limit-per-msecs nil :min-level nil :enabled? false :async? false :limit-per-msecs nil
:fn (fn [{:keys [ap-config prefix throwable message]}] :fn (fn [{:keys [ap-config default-output]}]
(when-let [filename (:spit-filename ap-config)] (when-let [filename (:spit-filename ap-config)]
(try (spit filename (try (spit filename default-output :append true)
(with-out-str (catch java.io.IOException _))))}}})
(str-println prefix "-" message
(stacktrace throwable)))
:append true)
(catch java.io.IOException _))))}}}))
(utils/defonce* config (atom example-config))
(defn set-config! [ks val] (swap! config assoc-in ks val)) (defn set-config! [ks val] (swap! config assoc-in ks val))
(defn merge-config! [& maps] (apply swap! config utils/merge-deep maps)) (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 ;;;; Appender-fn decoration
(defn- wrap-appender-fn (defn- wrap-appender-fn
"Wraps compile-time appender fn with additional runtime capabilities "Wraps compile-time appender fn with additional runtime capabilities
controlled by compile-time config." 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) (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 (->> ; Wrapping applies per appender, bottom-to-top
apfn 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 ;; Rate limit support
((fn [apfn] ((fn [apfn]
(if-not limit-per-msecs (if-not limit-per-msecs apfn
apfn
(let [timers (atom {})] ; {:hash last-appended-time-msecs ...} (let [timers (atom {})] ; {:hash last-appended-time-msecs ...}
(fn [{ns :ns [x1 & _] :args :as apfn-args}] (fn [{ns :ns [x1 & _] :args :as apfn-args}]
(let [now (System/currentTimeMillis) (let [now (System/currentTimeMillis)
@ -189,8 +183,7 @@
;; Async (agent) support ;; Async (agent) support
((fn [apfn] ((fn [apfn]
(if-not async? (if-not async? apfn
apfn
(let [agent (agent nil :error-mode :continue)] (let [agent (agent nil :error-mode :continue)]
(fn [apfn-args] (send-off agent (fn [_] (apfn apfn-args))))))))))) (fn [apfn-args] (send-off agent (fn [_] (apfn apfn-args)))))))))))
@ -208,7 +201,7 @@
(comment ((make-timestamp-fn "yyyy-MMM-dd" nil) (Date.))) (comment ((make-timestamp-fn "yyyy-MMM-dd" nil) (Date.)))
(def get-hostname (def ^:private get-hostname
(utils/memoize-ttl 60000 (utils/memoize-ttl 60000
(fn [] (fn []
(let [p (promise)] (let [p (promise)]
@ -227,28 +220,53 @@
(->> ; Wrapping applies per juxt, bottom-to-top (->> ; Wrapping applies per juxt, bottom-to-top
juxtfn 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 ;; Middleware transforms/filters support
((fn [juxtfn] ((fn [juxtfn]
;; Compile-time:
(if-let [middleware (seq (:middleware @config))] (if-let [middleware (seq (:middleware @config))]
(let [composed-middleware (let [composed-middleware
(apply comp (map (fn [mf] (fn [args] (when args (mf args)))) (apply comp (map (fn [mf] (fn [args] (when args (mf args))))
middleware))] middleware))]
(fn [juxtfn-args] (fn [juxtfn-args]
;; Runtime:
(when-let [juxtfn-args (composed-middleware juxtfn-args)] (when-let [juxtfn-args (composed-middleware juxtfn-args)]
(juxtfn juxtfn-args)))) (juxtfn juxtfn-args))))
juxtfn))) juxtfn)))
;; Add compile-time stuff to runtime appender args ;; Pre-middleware stuff
((fn [juxtfn] ((fn [juxtfn]
(let [{ap-config :shared-appender-config ;; Compile-time:
:keys [timestamp-pattern timestamp-locale prefix-fn]} @config (let [{ap-config :shared-appender-config} @config]
(fn [juxtfn-args]
timestamp-fn (make-timestamp-fn timestamp-pattern timestamp-locale)] ;; Runtime:
(fn [{:keys [instant] :as juxtfn-args}] (juxtfn (merge juxtfn-args {:ap-config ap-config
(let [juxtfn-args (merge juxtfn-args {:ap-config ap-config :hostname (get-hostname)}))))))))
:timestamp (timestamp-fn instant)
:hostname (get-hostname)})]
(juxtfn (assoc juxtfn-args :prefix (prefix-fn juxtfn-args))))))))))
;;;; Caching ;;;; Caching
@ -264,7 +282,7 @@
(defn- relevant-appenders [level] (defn- relevant-appenders [level]
(->> (:appenders @config) (->> (:appenders @config)
(filter #(let [{:keys [enabled? min-level]} (val %)] (filter #(let [{:keys [enabled? min-level]} (val %)]
(and enabled? (>= (compare-levels level min-level) 0)))) (and enabled? (>= (levels-compare level min-level) 0))))
(into {}))) (into {})))
(comment (relevant-appenders :debug) (comment (relevant-appenders :debug)
@ -273,8 +291,8 @@
(defn- cache-appenders-juxt! [] (defn- cache-appenders-juxt! []
(->> (->>
(zipmap (zipmap
ordered-levels levels-ordered
(->> ordered-levels (->> levels-ordered
(map (fn [l] (let [rel-aps (relevant-appenders l)] (map (fn [l] (let [rel-aps (relevant-appenders l)]
;; Return nil if no relevant appenders ;; Return nil if no relevant appenders
(when-let [ap-ids (keys rel-aps)] (when-let [ap-ids (keys rel-aps)]
@ -319,8 +337,25 @@
;;;; Logging macros ;;;; 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." (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))] (when-let [juxt-fn (or juxt-fn (@appenders-juxt-cache level))]
(juxt-fn (juxt-fn
(conj (or base-appender-args {}) (conj (or base-appender-args {})
@ -332,26 +367,14 @@
:error? (error-level? level) :error? (error-level? level)
:args log-vargs ; No tools.logging support :args log-vargs ; No tools.logging support
:throwable throwable :throwable throwable
:message message})) :message message ; Timbre: nil, tools.logging: nil or string
:msg-type msg-type ; Timbre: nnil, tools.logging: nil
}))
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." (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 (logging-enabled? ~level)
(when-let [juxt-fn# (@appenders-juxt-cache ~level)] (when-let [juxt-fn# (@appenders-juxt-cache ~level)]
(let [[x1# & xn# :as xs#] (vector ~@log-args) (let [[x1# & xn# :as xs#] (vector ~@log-args)
@ -363,21 +386,20 @@
log-vargs# log-vargs#
~(str *ns*) ~(str *ns*)
(when has-throwable?# x1#) (when has-throwable?# x1#)
(when-let [mf# ~message-fn] nil ; Timbre generates msg only after middleware
(when-not (empty? log-vargs#)
(apply mf# log-vargs#)))
juxt-fn# juxt-fn#
~msg-type
(let [file# ~*file*] (when (not= file# "NO_SOURCE_PATH") file#)) (let [file# ~*file*] (when (not= file# "NO_SOURCE_PATH") file#))
;; TODO Waiting on http://dev.clojure.org/jira/browse/CLJ-865: ;; TODO Waiting on http://dev.clojure.org/jira/browse/CLJ-865:
~(:line (meta &form))))))) ~(:line (meta &form)))))))
(defmacro log "Logs using print-style args." (defmacro log "Logs using print-style args."
{:arglists '([level & message] [level throwable & message])} {: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." (defmacro logf "Logs using format-style args."
{:arglists '([level fmt & fmt-args] [level throwable fmt & fmt-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-errors [& body] `(try ~@body (catch Throwable t# (error t#))))
(defmacro log-and-rethrow-errors [& body] (defmacro log-and-rethrow-errors [& body]
@ -412,7 +434,7 @@
[& sigs#] `(logf ~~level ~@sigs#))))) [& sigs#] `(logf ~~level ~@sigs#)))))
(defmacro ^:private def-loggers [] (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 (def-loggers) ; Actually define a logger for each logging level
@ -446,6 +468,10 @@
{:arglists '([expr] [level expr] [level name expr])} {:arglists '([expr] [level expr] [level name expr])}
[& args] `(spy ~@args)) [& 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 ;;;; Dev/tests
(comment (comment
@ -466,8 +492,8 @@
(trace (Thread/sleep 5000)) (trace (Thread/sleep 5000))
(time (dotimes [n 10000] (trace "This won't log"))) ; Overhead 5ms/10ms (time (dotimes [n 10000] (trace "This won't log"))) ; Overhead 5ms/10ms
(time (dotimes [n 5] (info "foo" "bar"))) (time (dotimes [n 5] (info "foo" "bar")))
(spy (* 6 5 4 3 2 1)) (spy :info (* 6 5 4 3 2 1))
(spy :debug :factorial6 (* 6 5 4 3 2 1)) (spy :info :factorial6 (* 6 5 4 3 2 1))
(info (Exception. "noes!") "bar") (info (Exception. "noes!") "bar")
(spy (/ 4 0)) (spy (/ 4 0))
@ -476,12 +502,13 @@
;; Middleware ;; Middleware
(info {:name "Robert Paulson" :password "Super secret"}) (info {:name "Robert Paulson" :password "Super secret"})
(set-config! (set-config! [:middleware] [])
[:middleware] (set-config! [:middleware]
[(fn [{:keys [hostname message] :as args}] [(fn [{:keys [hostname message args] :as ap-args}]
(cond (= hostname "filtered-host") nil ; Filter (if (= hostname "filtered-host") nil ; Filter
(map? message) (assoc ap-args :args
(if (contains? message :password) ;; Replace :password vals in any map args:
(assoc args :message (assoc message :password "*****")) (mapv (fn [arg] (if-not (map? arg) arg
args) (if-not (contains? arg :password) arg
:else args))])) (assoc arg :password "****"))))
args))))]))

4
src/taoensso/timbre/tools/logging.clj
View File

@ -9,8 +9,8 @@
;; tools.logging message may be a string (for `logp`/`logf` calls) or raw ;; tools.logging message may be a string (for `logp`/`logf` calls) or raw
;; argument (for `log` calls). Note that without an :args equivalent for ;; argument (for `log` calls). Note that without an :args equivalent for
;; `write!`, the best we can do is `[message]`. This inconsistency means ;; `write!`, the best we can do is `[message]`. This inconsistency means
;; that :args consumers (like the rate limiter and Postal appender) will ;; that :args consumers will necessarily behave differently under
;; necessarily behave differently under tools.logging. ;; tools.logging.
(timbre/send-to-appenders! level {} [message] logger-ns throwable (timbre/send-to-appenders! level {} [message] logger-ns throwable
(when (string? message) message)))) (when (string? message) message))))