-
-
Notifications
You must be signed in to change notification settings - Fork 171
/
timbre.clj
451 lines (369 loc) · 16.1 KB
/
timbre.clj
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
(ns taoensso.timbre
"Simple, flexible, all-Clojure logging. No XML!"
{:author "Peter Taoussanis"}
(:require [clojure.string :as str]
[clj-stacktrace.repl :as stacktrace]
[taoensso.timbre.utils :as utils])
(:import [java.util Date Locale]
[java.text SimpleDateFormat]))
;;;; Public utils
(defn str-println
"Like `println` but prints all objects to output stream as a single
atomic string. This is faster and avoids interleaving race conditions."
[& xs]
(print (str/join \space (filter identity xs)) \newline)
(flush))
(defn color-str [color & xs]
(let [ansi-color #(str "\u001b[" (case % :reset "0" :black "30" :red "31"
:green "32" :yellow "33" :blue "34"
:purple "35" :cyan "36" :white "37"
"0") "m")]
(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))
(defmacro with-default-outs
"Evaluates body with Clojure's default *out* and *err* bindings."
[& body] `(binding [*out* default-out *err* default-err] ~@body))
(defmacro with-err-as-out
"Evaluates body with *err* bound to *out*."
[& body] `(binding [*err* *out*] ~@body))
(defn stacktrace [throwable & [separator]]
(when throwable
(str separator throwable ; (str throwable) incl. ex-data for Clojure 1.4+
"\n\n" (stacktrace/pst-str throwable))))
;;;; Default configuration and appenders
(def ^:dynamic *current-level* nil)
(defmacro with-log-level
"Allows thread-local config logging level override. Useful for dev & testing."
[level & body] `(binding [*current-level* ~level] ~@body))
(utils/defonce* config
"This map atom controls everything about the way Timbre operates.
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`
:profiling-stats ; From `profile` macro
And also: :instant, :timestamp, :hostname, :ns, :error?
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).
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`
;;; 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
;; Control :prefix format
:prefix-fn
(fn [{:keys [level timestamp hostname ns]}]
(str timestamp " " hostname " " (-> level name str/upper-case)
" [" ns "]"))
;; Will be provided to all appenders via :ap-config key
:shared-appender-config {}
: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))))}
: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 _))))}}}))
(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 *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}]
(let [limit-per-msecs (or (:max-message-per-msecs appender)
limit-per-msecs)] ; Backwards-compatibility
(->> ; 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
(let [timers (atom {})] ; {:hash last-appended-time-msecs ...}
(fn [{ns :ns [x1 & _] :args :as apfn-args}]
(let [now (System/currentTimeMillis)
hash (str ns "/" x1)
limit? (fn [last-msecs]
(and last-msecs (<= (- now last-msecs)
limit-per-msecs)))]
(when-not (limit? (@timers hash))
(apfn apfn-args)
(swap! timers assoc hash now))
(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]
(if-not async?
apfn
(let [agent (agent nil :error-mode :continue)]
(fn [apfn-args] (send-off agent (fn [_] (apfn apfn-args)))))))))))
(defn- make-timestamp-fn
"Returns a unary fn that formats instants using given pattern string and an
optional Locale."
[^String pattern ^Locale locale]
(let [format (if locale
(SimpleDateFormat. pattern locale)
(SimpleDateFormat. pattern))]
(fn [^Date instant] (.format ^SimpleDateFormat format instant))))
(comment ((make-timestamp-fn "yyyy-MMM-dd" nil) (Date.)))
(def get-hostname
(utils/memoize-ttl
60000 (fn [] (try (.. java.net.InetAddress getLocalHost getHostName)
(catch java.net.UnknownHostException _
"UnknownHost")))))
(defn- wrap-appender-juxt
"Wraps compile-time appender juxt with additional runtime capabilities
(incl. middleware) controlled by compile-time config. Like `wrap-appender-fn`
but operates on the entire juxt at once."
[juxtfn]
(->> ; Wrapping applies per juxt, bottom-to-top
juxtfn
;; Middleware transforms/filters support
((fn [juxtfn]
(if-let [middleware (seq (:middleware @config))]
(let [composed-middleware
(apply comp (map (fn [mf] (fn [args] (when args (mf args))))
middleware))]
(fn [juxtfn-args]
(when-let [juxtfn-args (composed-middleware juxtfn-args)]
(juxtfn juxtfn-args))))
juxtfn)))
;; Add compile-time stuff to runtime appender args
((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))))))))))
;;;; Caching
;;; Appender-fns
(def appenders-juxt-cache
"Per-level, combined level-relevant appender-fns to allow for fast runtime
appender-fn dispatch:
{:level (wrapped-juxt wrapped-appender-fn wrapped-appender-fn ...) or nil
...}"
(atom {}))
(defn- relevant-appenders [level]
(->> (:appenders @config)
(filter #(let [{:keys [enabled? min-level]} (val %)]
(and enabled? (>= (compare-levels level min-level) 0))))
(into {})))
(comment (relevant-appenders :debug)
(relevant-appenders :trace))
(defn- cache-appenders-juxt! []
(->>
(zipmap
ordered-levels
(->> ordered-levels
(map (fn [l] (let [rel-aps (relevant-appenders l)]
;; Return nil if no relevant appenders
(when-let [ap-ids (keys rel-aps)]
(->> ap-ids
(map #(wrap-appender-fn (rel-aps %)))
(apply juxt)
(wrap-appender-juxt))))))))
(reset! appenders-juxt-cache)))
;;; Namespace filter
(def ns-filter-cache "@ns-filter-cache => (fn relevant-ns? [ns] ...)"
(atom (constantly true)))
(defn- ns-match? [ns match]
(-> (str "^" (-> (str match) (.replace "." "\\.") (.replace "*" "(.*)")) "$")
re-pattern (re-find (str ns)) boolean))
(defn- cache-ns-filter! []
(->>
(let [{:keys [ns-whitelist ns-blacklist]} @config]
(memoize
(fn relevant-ns? [ns]
(and (or (empty? ns-whitelist)
(some (partial ns-match? ns) ns-whitelist))
(or (empty? ns-blacklist)
(not-any? (partial ns-match? ns) ns-blacklist))))))
(reset! ns-filter-cache)))
;;; Prime initial caches and re-cache on config change
(cache-appenders-juxt!)
(cache-ns-filter!)
(add-watch
config "config-cache-watch"
(fn [key ref old-state new-state]
(when (not= (dissoc old-state :current-level)
(dissoc new-state :current-level))
(cache-appenders-juxt!)
(cache-ns-filter!))))
;;;; Define logging macros
(defn logging-enabled?
"Returns true when current logging level is sufficient and current namespace
is unfiltered."
[level] (and (sufficient-level? level) (@ns-filter-cache *ns*)))
(defmacro log*
"Implementation detail - subject to change..
Prepares given arguments for, and then dispatches to all level-relevant
appender-fns. "
;; 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}))
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?# (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]
(when-not (empty? log-vargs#)
(apply mf# log-vargs#)))
juxt-fn#)))))
(defmacro log
"When logging is enabled, actually logs given arguments with level-relevant
appender-fns using print-style :message."
{:arglists '([level & args] [level throwable & args])}
[level & sigs]
`(when (logging-enabled? ~level)
(log* {} ~level ~sigs nil)))
(defmacro logp {:arglists '([level & message] [level throwable & message])}
[& sigs] `(log ~@sigs)) ; Alias
(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.
Defaults to :debug logging level and unevaluated expression as name."
([expr] `(spy :debug ~expr))
([level expr] `(spy ~level '~expr ~expr))
([level name expr]
`(try
(let [result# ~expr] (logp ~level ~name result#) result#)
(catch Exception e#
(logp ~level '~expr (str "\n" (stacktrace/pst-str e#)))
(throw e#)))))
(defmacro s ; Alias
{:arglists '([expr] [level expr] [level name expr])}
[& args] `(spy ~@args))
(defmacro ^:private def-logger [level]
(let [level-name (name level)]
`(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 ~(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
(defmacro log-errors [& body]
`(try ~@body (catch Exception e# (error e#))))
(defmacro log-and-rethrow-errors [& body]
`(try ~@body (catch Exception e# (error e#) (throw e#))))
(defmacro logged-future [& body]
`(future (log-errors ~@body)))
(comment (log-errors (/ 0))
(log-and-rethrow-errors (/ 0))
(logged-future (/ 0)))
;;;; Dev/tests
(comment
(info)
(info "a")
(info "a" "b" "c")
(info "a" (Exception. "b") "c")
(info (Exception. "a") "b" "c")
(logp (or nil :info) "Booya")
(info "a%s" "b")
(infof "a%s" "b")
(set-config! [:ns-blacklist] [])
(set-config! [:ns-blacklist] ["taoensso.timbre*"])
(info "foo" "bar")
(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))
(info (Exception. "noes!") "bar")
(spy (/ 4 0))
(with-log-level :trace (trace "foo"))
(with-log-level :debug (trace "foo"))
;; 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))]))