diff --git a/CHANGELOG.md b/CHANGELOG.md index 92f9773..d749f04 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,7 +6,7 @@ Overall quite happy with the state of Timbre as of this release. No major antici ### Features * Android appender, courtesy of AdamClements. - * Carmine (Redis) appender: query-able, rotating serialized log entries by log level. See appender docstring for details. + * Powerful, high-performance Carmine (Redis) appender: query-able, rotating serialized log entries by log level. See README or appender's docstring for details. (Recommended!) * Appender rate limits now specified in a more flexible format: `[ncalls window-msecs]`, e.g. `[1 2000]` for 1 write / 2000 msecs. * Appender rate limits now also apply (at 1/4 ncalls) to any _particular_ logging arguments in the same time window. This helps prevent a particular logging call from flooding the limiter and preventing other calls from getting through. * `sometimes` macro that executes body with given probability. Useful for sampled logging (e.g. email a report for 0.01% of user logins in production). diff --git a/README.md b/README.md index 6f66834..188242e 100644 --- a/README.md +++ b/README.md @@ -11,6 +11,7 @@ Appender authors: please see [here](https://github.com/ptaoussanis/timbre/issues Logging with Java can be maddeningly, unnecessarily hard. Particularly if all you want is something *simple that works out-the-box*. Timbre brings functional, Clojure-y goodness to all your logging needs. **No XML!** ## What's in the box™? + * [Logs as Clojure values](https://github.com/ptaoussanis/timbre/tree/dev#redis-carmine-appender-v3) (v3+). * Small, uncomplicated **all-Clojure** library. * **Super-simple map-based config**: no arcane XML or properties files! * **Low overhead** with dynamic logging level. @@ -101,6 +102,9 @@ This is the biggest win over Java logging utilities IMO. Here's `timbre/example- :timestamp ; String generated from :timestamp-pattern, :timestamp-locale. :hostname ; String. :ns ; String. + ;; Waiting on http://dev.clojure.org/jira/browse/CLJ-865: + :file ; String. + :line ; Integer. MIDDLEWARE Middleware are fns (applied right-to-left) that transform the map @@ -148,7 +152,7 @@ This is the biggest win over Java logging utilities IMO. Here's `timbre/example- {:doc "Spits to `(:spit-filename :shared-appender-config)` file." :min-level nil :enabled? false :async? false :rate-limit nil :fn (fn [{:keys [ap-config output]}] ; Use any appender args - (when-let [filename (:spit-filename ap-config)] + (when-let [filename (:spit-filename ap-config)]ar (try (spit filename output :append true) (catch java.io.IOException _))))}}}) ``` @@ -169,13 +173,23 @@ For common-case ease-of-use, **all logging utils use a global atom for their con ### Built-in appenders -#### File appender +#### Redis ([Carmine](https://github.com/ptaoussanis/carmine)) appender (v3+) ```clojure -(timbre/set-config! [:appenders :spit :enabled?] true) -(timbre/set-config! [:shared-appender-config :spit-filename] "/path/my-file.log") +;; [com.taoensso/carmine "2.4.0"] ; Add to project.clj deps +;; (:require [taoensso.timbre.appenders (:carmine :as car-appender)]) ; Add to ns + +(timbre/set-config! [:appenders :carmine] (postal-appenders/make-carmine-appender)) ``` +This gives us a high-performance Redis appender: + * **All raw logging args are preserved** in serialized form (**even Throwables!**). + * 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 logging level. + * **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, etc. **Datomic and `core.logic`** also offer interesting opportunities here. + +A simple query utility is provided: `car-appender/query-entries`. + #### Email ([Postal](https://github.com/drewr/postal)) appender ```clojure @@ -193,22 +207,13 @@ For common-case ease-of-use, **all logging utils use a global atom for their con {:from "me@draines.com" :to "foo@example.com"}})) ``` -#### Redis ([Carmine](https://github.com/ptaoussanis/carmine)) appender +#### File appender ```clojure -;; [com.taoensso/carmine "2.4.0"] ; Add to project.clj deps -;; (:require [taoensso.timbre.appenders (:carmine :as car-appender)]) ; Add to ns - -(timbre/set-config! [:appenders :carmine] (postal-appenders/make-carmine-appender)) +(timbre/set-config! [:appenders :spit :enabled?] true) +(timbre/set-config! [:shared-appender-config :spit-filename] "/path/my-file.log") ``` -This gives us an appender that logs serialized entries as follows: - * Logs only the most recent instance of each unique entry. - * Limits the number of entries per level (configurable). - * Sorts entries by date of most recent occurence. - -Entries are serialized with their raw logging arguments and so well suited for Clojure's usual seq tools (`filter`, `map`, `group-by`, etc.). Even exceptions are maintained and queryable later. A simple query utility is provided: `car-appender/query-entries`. - #### Other included appenders A number of 3rd-party appenders are included out-the-box for: Android, IRC, sockets, MongoDB, and rotating files. These are all located in the `taoensso.timbre.appenders.x` namespaces - **please see the relevant docstrings for details**. diff --git a/src/taoensso/timbre.clj b/src/taoensso/timbre.clj index 3843f14..56579e7 100644 --- a/src/taoensso/timbre.clj +++ b/src/taoensso/timbre.clj @@ -114,6 +114,9 @@ :timestamp ; String generated from :timestamp-pattern, :timestamp-locale. :hostname ; String. :ns ; String. + ;; Waiting on http://dev.clojure.org/jira/browse/CLJ-865: + :file ; String. + :line ; Integer. MIDDLEWARE Middleware are fns (applied right-to-left) that transform the map diff --git a/src/taoensso/timbre/appenders/carmine.clj b/src/taoensso/timbre/appenders/carmine.clj index 3cdd111..4aa787b 100644 --- a/src/taoensso/timbre/appenders/carmine.clj +++ b/src/taoensso/timbre/appenders/carmine.clj @@ -4,28 +4,51 @@ (:require [taoensso.carmine :as car] [taoensso.timbre :as timbre])) +(defn- sha48 + "Truncated 160bit SHA hash (48bit Long). Redis can store small collections of + these quite efficiently." + [x] (-> (str x) + (org.apache.commons.codec.digest.DigestUtils/shaHex) + (.substring 0 11) + (Long/parseLong 16))) + +(comment (sha48 {:key "I'm gonna get hashed!"})) + (defn default-keyfn [level] {:pre [(string? level)]} (format "carmine:timbre:default:%s" level)) +(defn default-entry-hash-fn [{:keys [hostname ns args] :as apfn-args}] + ;; We try choose a hashing strategy here that gives a reasonable + ;; definition of 'uniqueness' for general entries. Things like dates + ;; or user ids will still trip us up. `[hostname ns line]` may be another + ;; idea? Waiting on http://dev.clojure.org/jira/browse/CLJ-865. + (or (some #(and (map? %) (:timbre/id %)) args) + [hostname ns args])) + (defn make-carmine-appender "Alpha - subject to change! - Returns a Carmine Redis appender that logs serialized entries as follows: - * Logs only the most recent instance of each unique entry. - * Limits the number of entries per level (configurable). - * Sorts entries by date of most recent occurence. + Returns a Carmine Redis appender: + * All raw logging args are preserved in serialized form (even Throwables!). + * 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 logging level. + * 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, etc. Datomic and `core.logic` + also offer interesting opportunities here. See accompanying `query-entries` fn to return deserialized log entries." - [& [appender-opts {:keys [conn keyfn nentries-by-level] - :or {conn {} - keyfn default-keyfn - nentries-by-level {:trace 20 - :debug 20 + [& [appender-opts {:keys [conn keyfn entry-hash-fn nentries-by-level] + :or {keyfn default-keyfn + entry-hash-fn default-entry-hash-fn + nentries-by-level {:trace 50 + :debug 50 :info 50 :warn 100 - :error 300 - :fatal 500 - :report 500}}}]] - {:pre [(string? (keyfn "debug")) + :error 100 + :fatal 100 + :report 100}}}]] + {:pre [(string? (keyfn "test")) (every? #(contains? nentries-by-level %) timbre/levels-ordered) (every? #(and (integer? %) (<= 0 % 100000)) (vals nentries-by-level))]} @@ -33,36 +56,68 @@ (merge default-appender-opts appender-opts {:fn (fn [{:keys [level instant] :as apfn-args}] - (let [k (keyfn (name level)) - nmax-entries (nentries-by-level level) - ;; Note that we _exclude_ :instant for uniqueness and efficiency - ;; (we'll use it as zset score): - entry (select-keys apfn-args [:level :throwable :args - :profile-stats :hostname :ns]) - udt (.getTime ^java.util.Date instant)] - (car/wcar conn - (car/zadd k udt entry) - (car/zremrangebyrank k 0 (dec (- nmax-entries))))))}))) + (let [entry-hash (sha48 (entry-hash-fn apfn-args)) + entry (select-keys apfn-args [:hostname :ns :args :throwable + :profile-stats]) + k-zset (keyfn (name level)) + k-hash (str k-zset ":entries") + udt (.getTime ^java.util.Date instant) ; Use as zscore + nmax-entries (nentries-by-level level)] + + (when (> nmax-entries 0) + (car/wcar conn + (car/hset k-hash entry-hash entry) + (car/zadd k-zset udt entry-hash) + + (when (< (rand) 0.01) ; Occasionally GC + ;; This is necessary since we're doing zset->entry-hash->entry + ;; rather than zset->entry. We want the former for the control + ;; it gives us over what should constitute a 'unique' entry. + (car/lua + "-- -ive idx used to prune from the right (lowest score first) + local max_idx = (0 - (tonumber(_:nmax-entries)) - 1) + local entries_to_prune = + redis.call('zrange', _:k-zset, 0, max_idx) + redis.call('zremrangebyrank', _:k-zset, 0, max_idx) -- Prune zset + + for i,entry in pairs(entries_to_prune) do + redis.call('hdel', _:k-hash, entry) -- Prune hash + end + return nil" + {:k-zset k-zset + :k-hash k-hash} + {:nmax-entries nmax-entries}))))))}))) ;;;; Query utils (defn query-entries "Alpha - subject to change! Returns latest `n` log entries by level as an ordered vector of deserialized - maps. Normal sequence fns can be used to query/transform entries." + maps. Normal sequence fns can be used to query/transform entries. Datomic and + core.logic are also useful!" [conn level & [n asc? keyfn]] {:pre [(or (nil? n) (and (integer? n) (<= 1 n 100000)))]} - (let [keyfn (or keyfn default-keyfn) - k (keyfn (name level))] - (->> - (car/wcar conn - (if asc? (car/zrange k 0 (if n (dec n) -1) :withscores) - (car/zrevrange k 0 (if n (dec n) -1) :withscores))) - ;; Reconstitute :instant keys from scores: - (partition 2) - (reduce (fn [v [m-entry score]] - (conj v (assoc m-entry :instant (car/as-long score)))) - [])))) + (let [keyfn (or keyfn default-keyfn) + k-zset (keyfn (name level)) + k-hash (str k-zset ":entries") + + entries-zset ; [{:hash _ :level _ :instant _} ...] + (->> + (car/wcar conn + (if asc? (car/zrange k-zset 0 (if n (dec n) -1) :withscores) + (car/zrevrange k-zset 0 (if n (dec n) -1) :withscores))) + (partition 2) ; Reconstitute :level, :instant keys: + (reduce (fn [v [entry-hash score]] + (conj v {:level level + :instant (car/as-long score) + :hash entry-hash})) + [])) + + entries-hash ; [{_} {_} ...] + (car/wcar conn (apply car/hmget k-hash (mapv :hash entries-zset)))] + + (mapv (fn [m1 m2] (-> (merge m1 m2) (dissoc :hash))) + entries-zset entries-hash))) ;;;; Dev/tests @@ -71,6 +126,13 @@ :appenders {:carmine (make-carmine-appender)}} :info "Hello1" "Hello2") - (car/wcar {} (car/del (default-keyfn "info"))) (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/hgetall (default-keyfn "info:entries"))) + + (count (query-entries {} :info 2)) (count (query-entries {} :info 2 :asc)))