Update core appenders

Note Carmine appender output change for `query-entries` util.
This commit is contained in:
Peter Taoussanis 2016-06-20 18:22:05 +07:00
parent e5b95cbd75
commit 682fa62334
5 changed files with 165 additions and 137 deletions

View File

@ -151,10 +151,13 @@ This is the biggest win over Java logging IMO. **All** of Timbre's behaviour is
:context ; *context* value at log time (see `with-context`) :context ; *context* value at log time (see `with-context`)
:profile-stats ; From `profile` macro :profile-stats ; From `profile` macro
**NB** - any keys not specifically documented here should be
considered private / subject to change without notice.
MIDDLEWARE MIDDLEWARE
Middleware are simple (fn [data]) -> ?data fns (applied left->right) that Middleware are simple (fn [data]) -> ?data fns (applied left->right) that
transform the data map dispatched to appender fns. If any middleware returns transform the data map dispatched to appender fns. If any middleware
nil, NO dispatching will occur (i.e. the event will be filtered). returns nil, NO dispatch will occur (i.e. the event will be filtered).
The `example-config` source code contains further settings and details. The `example-config` source code contains further settings and details.
See also `set-config!`, `merge-config!`, `set-level!`." See also `set-config!`, `merge-config!`, `set-level!`."
@ -238,12 +241,14 @@ lein uberjar # Compile jar ''
``` ```
This gives us a high-performance Redis appender: This gives us a high-performance Redis appender:
* **All raw logging args are preserved** in serialized form (**even errors!**) * **All raw logging args are preserved** in serialized form (even errors).
* Only the most recent instance of each **unique entry** is kept (hash fn used to determine uniqueness is configurable) * Configurable number of entries to keep per log level.
* Configurable number of entries to keep per log level * Only the most recent instance of each **unique entry** is kept.
* **Log is just a value**: a vector of Clojure maps: **query+manipulate with standard seq fns**: group-by hostname, sort/filter by ns & severity, explore exception stacktraces, filter by raw arguments, stick into or query with **Datomic**, etc. * Resulting **log is just a Clojure value**: a vector of log entries (maps).
A simple query utility is provided: `car-appender/query-entries`. Clojure has a rich selection of built-in and 3rd party tools for querying values like this.
See also `car-appender/query-entries`.
#### Email ([Postal]) appender #### Email ([Postal]) appender

View File

@ -1,49 +1,69 @@
(ns taoensso.timbre.appenders.carmine (ns taoensso.timbre.appenders.carmine
"Carmine (Redis) appender. Requires https://github.com/ptaoussanis/carmine." "Carmine (Redis) appender.
{:author "Peter Taoussanis"} Requires https://github.com/ptaoussanis/carmine."
{:author "Peter Taoussanis (@ptaoussanis)"}
(:require [taoensso.carmine :as car] (:require [taoensso.carmine :as car]
[taoensso.nippy :as nippy] [taoensso.nippy :as nippy]
[taoensso.timbre :as timbre] [taoensso.timbre :as timbre]
[taoensso.encore :as enc :refer (have have?)])) [taoensso.encore :as enc :refer (have have?)]))
(defn- sha48 (defn- sha48
"Truncated 160bit SHA hash (48bit Long). Redis can store small collections of "Truncated 160bit SHA hash (48bit Long). Redis can store small
these quite efficiently." collections of these quite efficiently."
[x] (-> (str x) [x] (-> (str x)
(org.apache.commons.codec.digest.DigestUtils/shaHex) (org.apache.commons.codec.digest.DigestUtils/shaHex)
(.substring 0 11) (.substring 0 11)
(Long/parseLong 16))) (Long/parseLong 16)))
(comment (sha48 {:key "I'm gonna get hashed!"})) (comment (enc/qb 10000 (sha48 "I'm gonna get hashed!")))
(defn default-keyfn [level] {:pre [(have? string? level)]} (defn default-keyfn [level] (str "timbre:carmine:" (name level)))
(str "carmine:timbre:default:" level)) (def default-nentries-by-level
{:trace 50
:debug 50
:info 50
:warn 100
:error 100
:fatal 100
:report 100})
(defn default-entry-fn "(fn [data])-><db-entry>"
[data]
(let [{:keys [instant level vargs hostname_ timestamp_
context ?err ?ns-str ?file ?line ?msg-fmt profile-stats]}
data]
(enc/assoc-some
{:instant instant
:level level
:vargs vargs
:hostname (force hostname_)
;; :timestamp (force timestamp_)
}
:context context
:?err ?err
:?ns-str ?ns-str
:?file ?file
:?line ?line
:?msg-fmt ?msg-fmt
:profile-stats profile-stats)))
(defn carmine-appender (defn carmine-appender
"Returns a Carmine Redis appender (experimental, subject to change): "Alpha, subject to change.
* All raw logging args are preserved in serialized form (even Throwables!).
* Only the most recent instance of each unique entry is kept (uniqueness Returns a Carmine Redis appender:
determined by data-hash-fn). * All raw logging args are preserved in serialized form (even errors).
* Configurable number of entries to keep per logging level. * Configurable number of entries to keep per logging level.
* Log is just a value: a vector of Clojure maps: query+manipulate with * Only the most recent instance of each unique entry is kept.
standard seq fns: group-by hostname, sort/filter by ns & severity, explore * Resulting log is just a Clojure value: a vector of log entries (maps).
exception stacktraces, filter by raw arguments, etc. Datomic and `core.logic`
also offer interesting opportunities here.
See accompanying `query-entries` fn to return deserialized log entries." See also `query-entries`."
[& [{:keys [conn-opts keyfn nentries-by-level] [& [{:keys [conn-opts keyfn entry-fn nentries-by-level]
:or {keyfn default-keyfn :or {keyfn default-keyfn
nentries-by-level {:trace 50 entry-fn default-entry-fn
:debug 50 nentries-by-level default-nentries-by-level}}]]
:info 50
:warn 100
:error 100
:fatal 100
:report 100}}}]]
{:pre [(have? string? (keyfn "test")) (have? string? (keyfn :info))
(have? [:ks>= timbre/ordered-levels] nentries-by-level) (have? integer? (nentries-by-level :info))
(have? [:and integer? #(<= 0 % 100000)] :in (vals nentries-by-level))]}
{:enabled? true {:enabled? true
:async? false :async? false
@ -52,30 +72,23 @@
:output-fn :inherit :output-fn :inherit
:fn :fn
(fn [data] (fn [data]
(let [{:keys [level instant data-hash-fn]} data (let [{:keys [level instant hash_]} data
entry-hash (sha48 (data-hash-fn data)) entry-hash (sha48 (force hash_))
entry (merge entry (entry-fn data)
{:instant instant
:level level
:?ns-str (:?ns-str data)
:hostname @(:hostname_ data)
:vargs @(:vargs_ data)
:?err @(:?err_ data)}
(when-let [pstats (:profile-stats data)]
{:profile-stats pstats}))
k-zset (keyfn (name level)) k-zset (keyfn level)
k-hash (str k-zset ":entries") k-hash (str k-zset ":entries")
udt (.getTime ^java.util.Date instant) ; Use as zscore udt (.getTime ^java.util.Date instant) ; Use as zscore
nmax-entries (nentries-by-level level)] nmax-entries (long (nentries-by-level level))]
(when (> nmax-entries 0) (when (> nmax-entries 0)
(car/wcar conn-opts (car/wcar conn-opts
(binding [nippy/*final-freeze-fallback* nippy/freeze-fallback-as-str] (binding [nippy/*final-freeze-fallback*
nippy/freeze-fallback-as-str]
(car/hset k-hash entry-hash entry)) (car/hset k-hash entry-hash entry))
(car/zadd k-zset udt entry-hash) (car/zadd k-zset udt entry-hash)
(when (< (rand) 0.01) ; Occasionally GC (when (< ^double (rand) 0.01) ; Occasionally GC
;; This is necessary since we're doing zset->entry-hash->entry ;; This is necessary since we're doing zset->entry-hash->entry
;; rather than zset->entry. We want the former for the control ;; rather than zset->entry. We want the former for the control
;; it gives us over what should constitute a 'unique' entry. ;; it gives us over what should constitute a 'unique' entry.
@ -97,41 +110,39 @@
;;;; Query utils ;;;; Query utils
(defn query-entries (defn query-entries
"Alpha - subject to change! "Alpha, subject to change.
Returns latest `n` log entries by level as an ordered vector of deserialized Returns latest `n` log entries by level as an ordered vector of
maps. Normal sequence fns can be used to query/transform entries. Datomic and deserialized maps."
core.logic are also useful!"
[conn-opts level & [n asc? keyfn]] [conn-opts level & [n asc? keyfn]]
{:pre [(have? [:or nil? [:and integer? #(<= 1 % 100000)]] n)]} (have? [:or nil? integer?] n)
(let [keyfn (or keyfn default-keyfn) (let [keyfn (or keyfn default-keyfn)
k-zset (keyfn (name level)) k-zset (keyfn level)
k-hash (str k-zset ":entries") k-hash (str k-zset ":entries")
entries-zset ; [{:hash _ :level _ :instant _} ...] zset-maps ; [{:level _ :instant _ :entry <hash>} ...]
(->> (let [-kvs
(car/wcar conn-opts (car/wcar conn-opts
(if asc? (car/zrange k-zset 0 (if n (dec n) -1) :withscores) (if asc?
(car/zrevrange k-zset 0 (if n (dec n) -1) :withscores))) (car/zrange k-zset 0 (if n (dec n) -1) :withscores)
(partition 2) ; Reconstitute :level, :instant keys: (car/zrevrange k-zset 0 (if n (dec n) -1) :withscores)))]
(reduce (fn [v [entry-hash score]]
(conj v {:level level
:instant (java.util.Date. (-> score car/as-long long))
:hash entry-hash}))
[]))
entries-hash ; [{_}-or-ex {_}-or-ex ...] (persistent!
(when-let [hashes (seq (mapv :hash entries-zset))] (enc/reduce-kvs
(if-not (next hashes) ; Careful! (fn [acc entry-hash udt-score]
(car/wcar conn-opts :as-pipeline (apply car/hget k-hash hashes)) (conj! acc
(car/wcar conn-opts (apply car/hmget k-hash hashes))))] {:level level
:instant (java.util.Date. (enc/as-int udt-score))
:entry entry-hash}))
(transient [])
-kvs)))
(mapv (fn [m1 m2-or-ex] entries-by-hash ; [<{}-or-ex> <{}-or-ex> ...]
(if (instance? Exception m2-or-ex) (when-let [hashes (seq (map :entry zset-maps))]
;; Should be rare but can happen (e.g. due to faulty Nippy (if (next hashes) ; Careful!
;; extensions or inconsistently-unserializable args): (car/wcar conn-opts (apply car/hmget k-hash hashes))
(-> (assoc m1 :entry-ex m2-or-ex) (dissoc :hash)) (car/wcar conn-opts :as-pipeline (apply car/hget k-hash hashes))))]
(-> (merge m1 m2-or-ex) (dissoc :hash))))
entries-zset entries-hash))) (mapv (fn [zset-m entry] (assoc zset-m :entry entry)) zset-maps entries-by-hash)))
;;;; Deprecated ;;;; Deprecated
@ -144,15 +155,15 @@
(comment (comment
(timbre/with-merged-config {:appenders {:carmine (carmine-appender)}} (timbre/with-merged-config {:appenders {:carmine (carmine-appender)}}
(timbre/info "Hello1" "Hello2")) (timbre/info "foo" "bar"))
(car/wcar {} (car/keys (default-keyfn "*")))
(count (car/wcar {} (car/hgetall (default-keyfn "info:entries"))))
(car/wcar {} (car/del (default-keyfn "info")
(default-keyfn "info:entries")))
(car/wcar {} (car/keys (default-keyfn "*")))
(car/wcar {} (car/hgetall (default-keyfn "info:entries"))) (car/wcar {} (car/hgetall (default-keyfn "info:entries")))
(count (query-entries {} :info 2)) (count (query-entries {} :info 5))
(count (query-entries {} :info 2 :asc))) (count (query-entries {} :info 5 :asc))
(car/wcar {}
(car/del
(default-keyfn "info")
(default-keyfn "info:entries"))))

View File

@ -1,7 +1,7 @@
(ns taoensso.timbre.appenders.core (ns taoensso.timbre.appenders.core
"Core Timbre appenders without any special dependency requirements. "Core Timbre appenders without any special dependency requirements.
These can be aliased into the main Timbre ns for convenience." These can be aliased into the main Timbre ns for convenience."
{:author "Peter Taoussanis"} {:author "Peter Taoussanis (@ptaoussanis)"}
#+clj #+clj
(:require (:require
[clojure.string :as str] [clojure.string :as str]
@ -43,15 +43,17 @@
:output-fn :inherit :output-fn :inherit
:fn :fn
(fn [data] (fn [data]
(let [{:keys [output-fn]} data] (let [{:keys [output_]} data]
#+cljs (println (output-fn data)) #+cljs (println (force output_))
#+clj #+clj
(let [stream (case stream (let [stream
:auto (if (:error? data) *err* *out*) (case stream
:*out* *out* :auto (if (:error? data) *err* *out*)
:*err* *err* :*out* *out*
stream)] :*err* *err*
(binding [*out* stream] (println (output-fn data))))))})) stream)]
(binding [*out* stream] (println (force output_))))))}))
(comment (println-appender)) (comment (println-appender))
@ -77,10 +79,10 @@
:output-fn :inherit :output-fn :inherit
:fn :fn
(fn [data] (fn [data]
(let [{:keys [output-fn]} data] (let [{:keys [output_]} data]
(try ; To allow TTL-memoization of dir creator (try ; To allow TTL-memoization of dir creator
(ensure-spit-dir-exists! fname) (ensure-spit-dir-exists! fname)
(spit fname (str (output-fn data) "\n") :append true) (spit fname (str (force output_) "\n") :append true)
(catch java.io.IOException _))))}) (catch java.io.IOException _))))})
(comment (spit-appender)) (comment (spit-appender))
@ -102,8 +104,7 @@
;; (Ref. https://goo.gl/IZzkQB) to get accurate line numbers in all ;; (Ref. https://goo.gl/IZzkQB) to get accurate line numbers in all
;; browsers w/o the need for Blackboxing? ;; browsers w/o the need for Blackboxing?
[& [{:keys [raw-output?]} ; Undocumented (experimental) [& [opts]]
]]
{:enabled? true {:enabled? true
:async? false :async? false
:min-level nil :min-level nil
@ -126,20 +127,20 @@
js/console.log))] js/console.log))]
(fn [data] (fn [data]
(let [{:keys [level output-fn vargs_]} data (let [logger (level->logger (:level data))]
vargs @vargs_
[v1 vnext] (enc/vsplit-first vargs)
logger (level->logger level)]
(if (or raw-output? (enc/kw-identical? v1 :timbre/raw)) ; Undocumented (if (or (:raw-console? data)
(let [output (output-fn (assoc data (get-in data [:?meta :raw-console?])) ; Undocumented
:msg_ (delay "") (let [output
:?err_ (delay nil))) ((:output-fn data)
;; [<output> <raw-error> <raw-arg1> <raw-arg2> ...]: (assoc data
args (->> vnext (cons @(:?err_ data)) (cons output))] :msg_ ""
:?err nil))
;; (<output> <raw-error> <raw-arg1> <raw-arg2> ...):
args (->> (:vargs data) (cons (:?err data)) (cons output))]
(.apply logger js/console (into-array args))) (.apply logger js/console (into-array args)))
(.call logger js/console (output-fn data)))))) (.call logger js/console (force (:output_ data)))))))
(fn [data] nil))}) (fn [data] nil))})

View File

@ -14,6 +14,8 @@
;; Timbre's `project.clj` to include the necessary dependencies under ;; Timbre's `project.clj` to include the necessary dependencies under
;; the `:test` profile ;; the `:test` profile
;; TODO Please mark any implementation vars as ^:private
(defn example-appender ; Appender constructor (defn example-appender ; Appender constructor
"Docstring to explain any special opts to influence appender construction, "Docstring to explain any special opts to influence appender construction,
etc. Returns the appender map." etc. Returns the appender map."
@ -36,40 +38,47 @@
[100 (enc/ms :hours 1)] ; 100 calls/hour [100 (enc/ms :hours 1)] ; 100 calls/hour
] ]
:output-fn :inherit ; or a custom (fn [data-map]) -> string :output-fn :inherit ; or a custom (fn [data]) -> string
;; The actual appender (fn [data-map]) -> possible side effects ;; The actual appender (fn [data]) -> possible side effects
:fn :fn
(fn [data-map] (fn [data]
(let [;; See `timbre/example-config` for info on all available keys: (let [{:keys
{:keys [instant level ?err_ vargs_ output-fn [instant level output_
config ; Entire Timbre config map in effect ;; ... lots more stuff, see `timbre/example-config`
appender ; Entire appender map in effect ]} data
]}
data-map
?err @?err_ ; An error, or nil ;; You'll often want an output string with ns, timestamp, vargs,
vargs @vargs_ ; Vector of raw logging args ;; etc. A (fn [data]) -> string formatter is provided under the
;; :output-fn data key, defined as:
;; You'll often want an output string with ns, timestamp, vargs, etc.
;; A (fn [data]) -> string formatter is provided under the :output-fn
;; key, defined as:
;; `(or (:output-fn <this appender's map>) ;; `(or (:output-fn <this appender's map>)
;; (:output-fn <user's config map) ;; (:output-fn <user's config map)
;; timbre/default-output-fn)` ;; timbre/default-output-fn)`
;; ;;
;; Users therefore get a standardized way to control appender ouput ;; This gives users a standardized way to control appender
;; formatting for all participating appenders. See ;; ouput formatting for all participating appenders. See
;; `taoensso.timbre/default-output-fn` source for details. ;; `taoensso.timbre/default-output-fn` source for details.
;; ;;
output-str (output-fn data-map)] ;; In general, appenders should try use one of the following for
;; their output string if they can:
;; 1. (force (:output_ data)) ; 1st choice, allows output to be
;; ; cached + shared between
;; ; participating appenders
;; 2. ((:output-fn data) data) ; 2nd choice, if you need to
;; ; modify the `data` arg provided
;; ; to the output-fn
;; 3. Create your own adhoc output from stuff in `data`. This
;; may be necessary if your appender is writing to a db, etc.
;; and requires some unique non-string output format.
;; See `timbre/default-output-fn` for ideas.
;; This is where we produce our logging side effects. In this case output-str (force output_)]
;; we'll just call `println`:
;; This is where we produce our logging side effects.
;; In this case we'll just call `println`:
(println output-str)))})) (println output-str)))}))
(comment (comment
;; Create an example appender with default options: ;; Create an example appender with default options:
(example-appender) (example-appender)

View File

@ -1,6 +1,6 @@
(ns taoensso.timbre.appenders.postal (ns taoensso.timbre.appenders.postal
"Email (Postal) appender. Requires https://github.com/drewr/postal." "Email (Postal) appender. Requires https://github.com/drewr/postal."
{:author "Peter Taoussanis"} {:author "Peter Taoussanis (@ptaoussanis)"}
(:require [clojure.string :as str] (:require [clojure.string :as str]
[io.aviso.exception :as aviso-ex] [io.aviso.exception :as aviso-ex]
[postal.core :as postal] [postal.core :as postal]
@ -23,11 +23,13 @@
:min-level :warn ; Elevated :min-level :warn ; Elevated
:rate-limit [[5 (enc/ms :mins 2)] :rate-limit [[5 (enc/ms :mins 2)]
[50 (enc/ms :hours 24)]] [50 (enc/ms :hours 24)]]
:output-fn :inherit :output-fn (partial timbre/default-output-fn
{:stacktrace-fonts {}})
:fn :fn
(fn [data] (fn [data]
(let [{:keys [output-fn]} data (let [{:keys [output_]} data
output-str (binding [aviso-ex/*fonts* {}] (output-fn data))] output-str (force output_)]
(postal/send-message (postal/send-message
(assoc postal-config (assoc postal-config
:subject (-> output-str :subject (-> output-str