status-im
/
timbre
mirror of https://github.com/status-im/timbre.git
2
0
Fork 0
Code Issues Projects Releases Wiki Activity

Carmine appender: add configurable hash fn

This commit is contained in:
Peter Taoussanis 2013-12-01 16:49:31 +07:00
parent 05326dcfae
commit 136d3553ba
4 changed files with 123 additions and 53 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
CHANGELOG.md
View File

@ -6,7 +6,7 @@ Overall quite happy with the state of Timbre as of this release. No major antici
### Features ### Features
* Android appender, courtesy of AdamClements. * 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 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. * 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). * `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).

37
README.md
View File

@ -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!** 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™? ## 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. * Small, uncomplicated **all-Clojure** library.
* **Super-simple map-based config**: no arcane XML or properties files! * **Super-simple map-based config**: no arcane XML or properties files!
* **Low overhead** with dynamic logging level. * **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. :timestamp ; String generated from :timestamp-pattern, :timestamp-locale.
:hostname ; String. :hostname ; String.
:ns ; String. :ns ; String.
;; Waiting on http://dev.clojure.org/jira/browse/CLJ-865:
:file ; String.
:line ; Integer.
MIDDLEWARE MIDDLEWARE
Middleware are fns (applied right-to-left) that transform the map 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." {:doc "Spits to `(:spit-filename :shared-appender-config)` file."
:min-level nil :enabled? false :async? false :rate-limit nil :min-level nil :enabled? false :async? false :rate-limit nil
:fn (fn [{:keys [ap-config output]}] ; Use any appender args :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) (try (spit filename output :append true)
(catch java.io.IOException _))))}}}) (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 ### Built-in appenders
#### File appender #### Redis ([Carmine](https://github.com/ptaoussanis/carmine)) appender (v3+)
```clojure ```clojure
(timbre/set-config! [:appenders :spit :enabled?] true) ;; [com.taoensso/carmine "2.4.0"] ; Add to project.clj deps
(timbre/set-config! [:shared-appender-config :spit-filename] "/path/my-file.log") ;; (: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 #### Email ([Postal](https://github.com/drewr/postal)) appender
```clojure ```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"}})) {:from "me@draines.com" :to "foo@example.com"}}))
``` ```
#### Redis ([Carmine](https://github.com/ptaoussanis/carmine)) appender #### File appender
```clojure ```clojure
;; [com.taoensso/carmine "2.4.0"] ; Add to project.clj deps (timbre/set-config! [:appenders :spit :enabled?] true)
;; (:require [taoensso.timbre.appenders (:carmine :as car-appender)]) ; Add to ns (timbre/set-config! [:shared-appender-config :spit-filename] "/path/my-file.log")
(timbre/set-config! [:appenders :carmine] (postal-appenders/make-carmine-appender))
``` ```
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 #### 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**. 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**.

3
src/taoensso/timbre.clj
View File

@ -114,6 +114,9 @@
:timestamp ; String generated from :timestamp-pattern, :timestamp-locale. :timestamp ; String generated from :timestamp-pattern, :timestamp-locale.
:hostname ; String. :hostname ; String.
:ns ; String. :ns ; String.
;; Waiting on http://dev.clojure.org/jira/browse/CLJ-865:
:file ; String.
:line ; Integer.
MIDDLEWARE MIDDLEWARE
Middleware are fns (applied right-to-left) that transform the map Middleware are fns (applied right-to-left) that transform the map

134
src/taoensso/timbre/appenders/carmine.clj
View File

@ -4,28 +4,51 @@
(:require [taoensso.carmine :as car] (:require [taoensso.carmine :as car]
[taoensso.timbre :as timbre])) [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)]} (defn default-keyfn [level] {:pre [(string? level)]}
(format "carmine:timbre:default:%s" 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 (defn make-carmine-appender
"Alpha - subject to change! "Alpha - subject to change!
Returns a Carmine Redis appender that logs serialized entries as follows: Returns a Carmine Redis appender:
* Logs only the most recent instance of each unique entry. * All raw logging args are preserved in serialized form (even Throwables!).
* Limits the number of entries per level (configurable). * Only the most recent instance of each unique entry is kept (hash fn used
* Sorts entries by date of most recent occurence. 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." See accompanying `query-entries` fn to return deserialized log entries."
[& [appender-opts {:keys [conn keyfn nentries-by-level] [& [appender-opts {:keys [conn keyfn entry-hash-fn nentries-by-level]
:or {conn {} :or {keyfn default-keyfn
keyfn default-keyfn entry-hash-fn default-entry-hash-fn
nentries-by-level {:trace 20 nentries-by-level {:trace 50
:debug 20 :debug 50
:info 50 :info 50
:warn 100 :warn 100
:error 300 :error 100
:fatal 500 :fatal 100
:report 500}}}]] :report 100}}}]]
{:pre [(string? (keyfn "debug")) {:pre [(string? (keyfn "test"))
(every? #(contains? nentries-by-level %) timbre/levels-ordered) (every? #(contains? nentries-by-level %) timbre/levels-ordered)
(every? #(and (integer? %) (<= 0 % 100000)) (vals nentries-by-level))]} (every? #(and (integer? %) (<= 0 % 100000)) (vals nentries-by-level))]}
@ -33,36 +56,68 @@
(merge default-appender-opts appender-opts (merge default-appender-opts appender-opts
{:fn {:fn
(fn [{:keys [level instant] :as apfn-args}] (fn [{:keys [level instant] :as apfn-args}]
(let [k (keyfn (name level)) (let [entry-hash (sha48 (entry-hash-fn apfn-args))
nmax-entries (nentries-by-level level) entry (select-keys apfn-args [:hostname :ns :args :throwable
;; Note that we _exclude_ :instant for uniqueness and efficiency :profile-stats])
;; (we'll use it as zset score): k-zset (keyfn (name level))
entry (select-keys apfn-args [:level :throwable :args k-hash (str k-zset ":entries")
:profile-stats :hostname :ns]) udt (.getTime ^java.util.Date instant) ; Use as zscore
udt (.getTime ^java.util.Date instant)] nmax-entries (nentries-by-level level)]
(car/wcar conn
(car/zadd k udt entry) (when (> nmax-entries 0)
(car/zremrangebyrank k 0 (dec (- nmax-entries))))))}))) (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 ;;;; 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 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]] [conn level & [n asc? keyfn]]
{:pre [(or (nil? n) (and (integer? n) (<= 1 n 100000)))]} {:pre [(or (nil? n) (and (integer? n) (<= 1 n 100000)))]}
(let [keyfn (or keyfn default-keyfn) (let [keyfn (or keyfn default-keyfn)
k (keyfn (name level))] k-zset (keyfn (name level))
(->> k-hash (str k-zset ":entries")
(car/wcar conn
(if asc? (car/zrange k 0 (if n (dec n) -1) :withscores) entries-zset ; [{:hash _ :level _ :instant _} ...]
(car/zrevrange k 0 (if n (dec n) -1) :withscores))) (->>
;; Reconstitute :instant keys from scores: (car/wcar conn
(partition 2) (if asc? (car/zrange k-zset 0 (if n (dec n) -1) :withscores)
(reduce (fn [v [m-entry score]] (car/zrevrange k-zset 0 (if n (dec n) -1) :withscores)))
(conj v (assoc m-entry :instant (car/as-long score)))) (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 ;;;; Dev/tests
@ -71,6 +126,13 @@
:appenders {:carmine (make-carmine-appender)}} :appenders {:carmine (make-carmine-appender)}}
:info "Hello1" "Hello2") :info "Hello1" "Hello2")
(car/wcar {} (car/del (default-keyfn "info")))
(car/wcar {} (car/keys (default-keyfn "*"))) (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))) (count (query-entries {} :info 2 :asc)))