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

Merge branch 'dev': v0.6.0.

This commit is contained in:
Peter Taoussanis 2012-07-03 21:18:50 +07:00
parent 7ce65ed924 123f3c51d9
commit 2aa9d4d83f
8 changed files with 384 additions and 98 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

3
.travis.yml
View File

@ -1,9 +1,6 @@
language: clojure
lein: lein2
script: lein2 all test
branches:
only:
- master
jdk:
- openjdk7
- openjdk6

129
README.md
View File

@ -1,9 +1,7 @@
# NOTICE
The Timbre Clojars group was recently changed. Please update your `project.clj` to use:
Current version:
```clojure
[com.taoensso/timbre "{VERSION}"]
[com.taoensso/timbre "0.6.0"]
```
# Timbre, a (sane) logging library for Clojure
@ -16,16 +14,21 @@ Timbre is an attempt to make **simple logging simple** and more **complex loggin
## What's In The Box?
* 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!
* Decent performance (**low overhead**).
* Flexible **fn-centric appender model**.
* Sensible built-in appenders including simple **email appender**.
* Tunable **flood control**.
* **Asynchronous** logging support.
* Tunable **flood control** and **asynchronous** logging support.
* Robust **namespace filtering**.
* Dead-simple, logging-level-aware **logging profiler**.
## Status [![Build Status](https://secure.travis-ci.org/ptaoussanis/timbre.png)](http://travis-ci.org/ptaoussanis/timbre)
## Status [![Build Status](https://secure.travis-ci.org/ptaoussanis/timbre.png?branch=master)](http://travis-ci.org/ptaoussanis/timbre)
Timbre was built in a day after I finally lost my patience trying to configure Log4j. I tried to keep the design simple and sensible but I didn't spend much time thinking about it so there may still be room for improvement. In particular **the configuration and appender formats are still subject to change**.
Tower is still currently *experimental*. It **has not yet been thoroughly tested in production** and its API is subject to change. To run tests against all supported Clojure versions, use:
```bash
lein2 all test
```
## Getting Started
@ -34,14 +37,14 @@ Timbre was built in a day after I finally lost my patience trying to configure L
Depend on Timbre in your `project.clj`:
```clojure
[com.taoensso/timbre "0.5.2"]
[com.taoensso/timbre "0.6.0"]
```
and `require` the library:
and `use` the library:
```clojure
(ns my-app
(:use [timbre.core :as timbre :only (trace debug info warn error fatal spy)])
(:use [taoensso.timbre :as timbre :only (trace debug info warn error fatal spy)]))
```
### Start Logging
@ -50,7 +53,12 @@ By default, Timbre gives you basic print output to `*out*`/`*err*` at a `debug`
```clojure
(info "This will print")
=> 2012-May-28 17:26:11:444 +0700 INFO [timbre.tests] - This will print
=> nil
%> 2012-May-28 17:26:11:444 +0700 INFO [my-app] - This will print
(spy :info (* 5 4 3 2 1))
=> 120
%> 2012-May-28 17:26:14:138 +0700 INFO [my-app] - (* 5 4 3 2 1) 120
(trace "This won't print due to insufficient logging level")
=> nil
@ -60,25 +68,45 @@ There's little overhead for checking logging levels:
```clojure
(time (trace (Thread/sleep 5000)))
=> "Elapsed time: 0.054 msecs"
%> "Elapsed time: 0.054 msecs"
(time (when true))
=> "Elapsed time: 0.051 msecs"
%> "Elapsed time: 0.051 msecs"
```
First-argument exceptions generate a stack trace:
```clojure
(info (Exception. "Oh noes") "arg1" "arg2")
=> 2012-May-28 17:35:16:132 +0700 INFO [timbre.tests] - arg1 arg2
%> 2012-May-28 17:35:16:132 +0700 INFO [my-app] - arg1 arg2
java.lang.Exception: Oh noes
NO_SOURCE_FILE:1 timbre.tests/eval6409
NO_SOURCE_FILE:1 my-app/eval6409
Compiler.java:6511 clojure.lang.Compiler.eval
[...]
<...>
```
### Configuration
Configuring Timbre couldn't be simpler. Let's check out (some of) the defaults:
```clojure
@timbre/config
=>
{:current-level :debug
:ns-whitelist []
:ns-blacklist []
:appenders
{:standard-out { <...> }
:postal { <...> }}
:shared-appender-config
{:timestamp-pattern "yyyy-MMM-dd HH:mm:ss ZZ"
:locale nil
:postal nil}}
```
Easily adjust the current logging level:
```clojure
@ -94,6 +122,11 @@ And the default timestamp formatting for log messages:
(java.util.Locale/GERMAN))
```
Filter logging output by namespaces:
```clojure
(timbre/set-config! [:ns-whitelist] ["some.library.core" "my-app.*"])
```
Enable the standard [Postal](https://github.com/drewr/postal)-based email appender:
```clojure
@ -118,7 +151,7 @@ And make sure emails are sent asynchronously:
### Custom Appenders
Writing a custom appender is easy:
Writing a custom appender is dead-easy:
```clojure
(timbre/set-config!
@ -130,13 +163,67 @@ Writing a custom appender is easy:
:max-message-per-msecs nil ; No rate limiting
:fn (fn [{:keys [ap-config level error? instant timestamp
ns message more] :as args}]
(when-not (:production-mode? ap-config)
(when-not (:my-production-mode? ap-config)
(apply println timestamp "Hello world!" message more)))
```
And because appender fns are just regular Clojure fns, you have *unlimited power*: write to your database, send a message over the network, check some other state (e.g. environment config) before making a choice, etc.
See `(doc timbre/config)` for more information on appenders.
See the `timbre/config` docstring for more information on appenders.
## Profiling
The usual recommendation for Clojure profiling is: use a good **JVM profiler** like [YourKit](http://www.yourkit.com/), [JProfiler](http://www.ej-technologies.com/products/jprofiler/overview.html), or [VisualVM](http://docs.oracle.com/javase/6/docs/technotes/guides/visualvm/index.html).
And these certaily do the job. But as with many Java tools, they can be a little hairy and often heavy-handed - especially when applied to Clojure. Timbre includes an alternative.
Let's add it to our app's `ns` declaration:
```clojure
(ns my-app
(:use [taoensso.timbre :as timbre :only (trace debug info warn error fatal spy)]
[taoensso.timbre.profiling :as profiling :only (p profile)]))
```
Wrap forms that you'd like to profile with the `p` macro and give them a name:
```clojure
(defn my-fn
[]
(let [nums (vec (range 1000))]
(+ (p :fast-sleep (Thread/sleep 1) 10)
(p :slow-sleep (Thread/sleep 2) 32)
(p :add (reduce + nums))
(p :sub (reduce - nums))
(p :mult (reduce * nums))
(p :div (reduce / nums)))))
(my-fn)
=> 42
```
The `profile` macro can now be used to log times for any wrapped forms:
```clojure
(profile :info :Arithmetic (dotimes [n 100] (my-fn)))
=> "Done!"
%> 2012-Jul-03 20:46:17 +0700 INFO [my-app] - Profiling: my-app/Arithmetic
Name Count Min Max Mean Total% Total
my-app/slow-sleep 100 2ms 2ms 2ms 58 232ms
my-app/fast-sleep 100 1ms 1ms 1ms 30 120ms
my-app/div 100 65μs 204μs 90μs 2 9ms
my-app/add 100 32μs 116μs 59μs 1 5ms
my-app/sub 100 30μs 145μs 47μs 1 4ms
my-app/mult 100 33μs 117μs 45μs 1 4ms
Unaccounted 6 25ms
Total 100 403ms
```
It's important to note that Timbre profiling is fully **log-level aware**: if the logging level is insufficient, you won't pay for profiling. Likewise, normal namespace filtering applies. (Performance characteristics for both checks are inherited from Timbre itself).
And since `p` and `profile` **always return their body's result** regardless of whether profiling actually happens or not, it becomes feasible to use profiling more often as part of your normal workflow: just *leave profiling code in production as you do for logging code*.
A **sampling profiler** is also available: `taoensso.timbre.profiling/sampling-profile`.
## Timbre Supports the ClojureWerkz Project Goals

2
project.clj
View File

@ -1,4 +1,4 @@
(defproject com.taoensso/timbre "0.5.2"
(defproject com.taoensso/timbre "0.6.0"
:description "Simple, flexible, all-Clojure logging. No XML!"
:url "https://github.com/ptaoussanis/timbre"
:license {:name "Eclipse Public License"}

140
src/timbre/core.clj → src/taoensso/timbre.clj
View File

@ -1,11 +1,11 @@
(ns timbre.core
(ns taoensso.timbre
"Simple, flexible, all-Clojure logging. No XML!"
{:author "Peter Taoussanis"}
(:require [clojure.string :as str]
[clj-stacktrace.repl :as stacktrace]
[postal.core :as postal])
(:import [java.util Date Locale]
java.text.SimpleDateFormat))
[java.text SimpleDateFormat]))
;;;; Default configuration and appenders
@ -16,7 +16,7 @@
" [" ns "] - " message))
(defn str-println
"Like 'println' but prints all objects to output stream as a single
"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 (str/join \space xs) \newline)))
@ -29,11 +29,17 @@
:doc, :min-level, :enabled?, :async?, :max-message-per-msecs, :fn?
An appender's fn takes a single map argument with keys:
:ap-config, :level, :error?, :instant, :timestamp, :ns, :message, :more
:ap-config, :level, :error?, :instant, :timestamp, :ns, :message, :more,
:profiling-stats (when applicable)
See source code for examples."
(atom {:current-level :debug
;;; Allow log filtering by namespace patterns (e.g. ["my-app.*"]).
;;; Useful for turning off logging in noisy libraries, etc.
:ns-whitelist []
:ns-blacklist []
:appenders
{:standard-out
{:doc "Prints everything to *out*."
@ -63,6 +69,7 @@
:body (if (seq more) (str/join " " more)
"<no additional arguments>")))))}}
;; Will be given to all appenders via :ap-config key
:shared-appender-config
{:timestamp-pattern "yyyy-MMM-dd HH:mm:ss ZZ" ; SimpleDateFormat pattern
:locale nil ; A Locale object, or nil
@ -71,11 +78,14 @@
;; {:from "me@draines.com" :to "foo@example.com"}
:postal nil}}))
(defn set-config! [[k & ks] val] (swap! config assoc-in (cons k ks) val))
(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 (zipmap ordered-levels (range)))
(defn check-level
(defn assert-valid-level
[x] (when-not (some #{x} ordered-levels)
(throw (Exception. (str "Invalid logging level: " x)))))
@ -85,14 +95,6 @@
(defn sufficient-level?
[level] (>= (compare-levels level (:current-level @config)) 0))
;;;; Config helpers
(defn set-config! [[k & ks] val] (swap! config assoc-in (cons k ks) val))
(defn set-level!
[level]
(check-level level)
(set-config! [:current-level] level))
;;;; Appender-fn decoration
(defn- make-timestamp-fn
@ -107,8 +109,8 @@
(comment ((make-timestamp-fn "yyyy-MMM-dd" nil) (Date.)))
(defn- wrap-appender-fn
"Wraps compile-time appender fn with additional capabilities controlled by
compile-time config."
"Wraps compile-time appender fn with additional runtime capabilities
controlled by compile-time config."
[{apfn :fn :keys [async? max-message-per-msecs] :as appender}]
(->
;; Wrap to add compile-time stuff to runtime appender arguments
@ -157,10 +159,13 @@
(when (seq expired-timers)
(apply swap! flood-timers dissoc expired-timers))))))))))))
;;;; Appender-fn caching
;;;; Caching
(def juxt-cache
"Per-level, combined relevant appender-fns:
;;; Appender-fns
(def appenders-juxt-cache
"Per-level, combined relevant appender-fns to allow for fast runtime
appender-fn dispatch:
{:level (juxt wrapped-appender-fn wrapped-appender-fn ...) or nil
...}"
(atom {}))
@ -176,10 +181,10 @@
(comment (relevant-appenders :debug)
(relevant-appenders :trace))
(defn- cache-appenders!
"Prime 'juxt-cache' for fast runtime appender-fn dispatch."
(defn- cache-appenders-juxt!
[]
(->> (zipmap
(->>
(zipmap
ordered-levels
(->> ordered-levels
(map (fn [l] (let [rel-aps (relevant-appenders l)]
@ -188,51 +193,85 @@
(->> ap-ids
(map #(wrap-appender-fn (rel-aps %)))
(apply juxt))))))))
(reset! juxt-cache)))
(reset! appenders-juxt-cache)))
(cache-appenders!) ; Actually cache default appenders now
;;; 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 recache on config change
(cache-appenders-juxt!)
(cache-ns-filter!)
;; Automatically re-cache any time appenders change
(add-watch
config "appender-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!))))
(cache-appenders-juxt!)
(cache-ns-filter!))))
;;;; Define logging macros
(defmacro log
"Dispatches given arguments to relevant appender-fns iff logging level is
sufficient."
{:arglists '([level message & more] [level throwable message & more])}
[level & args]
(check-level level)
`(let [level# ~level]
(when (sufficient-level? level#)
(when-let [juxt-fn# (@juxt-cache level#)] ; Any relevant appenders?
(defmacro logging-enabled?
"Returns true when current logging level is sufficient and current namespace
is unfiltered."
[level]
(assert-valid-level level)
`(and (sufficient-level? ~level) (@ns-filter-cache ~*ns*)))
(defmacro log*
"Prepares given arguments for, and then dispatches to all relevant
appender-fns."
[level base-args & args]
(assert-valid-level level)
`(when-let [juxt-fn# (@appenders-juxt-cache ~level)] ; Any relevant appenders?
(let [[x1# & xs#] (list ~@args)
has-throwable?# (instance? Throwable x1#)
appender-args#
{:level level#
:error? (>= (compare-levels level# :error) 0)
(conj
~base-args ; Allow flexibility to inject exta args
{:level ~level
:error? (>= (compare-levels ~level :error) 0)
:instant (Date.)
:ns (str ~*ns*)
:message (if has-throwable?# (or (first xs#) x1#) x1#)
:more (if has-throwable?#
(conj (vec (rest xs#))
(str "\n" (stacktrace/pst-str x1#)))
(vec xs#))}]
(vec xs#))})]
(juxt-fn# appender-args#)
nil)))))
nil)))
(comment (log :fatal "arg1")
(log :debug "arg1" "arg2")
(log :debug (Exception.) "arg1" "arg2")
(log :debug (Exception.))
(log :trace "arg1"))
(defmacro log
"When logging is enabled, actually logs given arguments with relevant
appender-fns. Generic form of standard level-loggers (trace, info, etc.)."
{:arglists '([level message & more] [level throwable message & more])}
[level & args]
(assert-valid-level level)
`(when (logging-enabled? ~level)
(log* ~level {} ~@args)))
(defmacro spy
"Evaluates expression and logs its form and result. Always returns the result.
@ -240,7 +279,7 @@
([expr] `(spy :debug ~expr))
([level expr]
`(try
(let [r# ~expr] (log ~level '~expr ~expr) r#)
(let [result# ~expr] (log ~level '~expr ~expr) result#)
(catch Exception e#
(log ~level '~expr (str "\n" (stacktrace/pst-str e#)))
(throw e#)))))
@ -262,9 +301,18 @@
;;;; Dev/tests
(comment
(log :fatal "arg1")
(log :debug "arg1" "arg2")
(log :debug (Exception.) "arg1" "arg2")
(log :debug (Exception.))
(log :trace "arg1")
(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"))) ; Minimum overhead +/- 4.5ms
(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))
(info (Exception. "noes!") "bar")

151
src/taoensso/timbre/profiling.clj Normal file
View File

@ -0,0 +1,151 @@
(ns taoensso.timbre.profiling
"Simple all-Clojure profiling adapted from clojure.contrib.profile."
{:author "Peter Taoussanis"}
(:require [taoensso.timbre :as timbre]))
(def ^:dynamic *plog* "{::pname [time1 time2 ...] ...}" nil)
(defmacro prepare-name
"Returns namespaced keyword for given name."
[name]
`(if (and (keyword? ~name) (namespace ~name))
~name
(keyword (str ~*ns*) (clojure.core/name ~name))))
(defmacro p
"When in the context of a *plog* binding, records execution time of named
body. Always returns the body's result."
[name & body]
(let [name (prepare-name name)]
`(if *plog*
(let [start-time# (System/nanoTime)
result# (do ~@body)
elapsed# (- (System/nanoTime) start-time#)]
(swap! *plog* #(assoc % ~name (conj (% ~name []) elapsed#)))
result#)
(do ~@body))))
(defn plog-stats
"{::pname [time1 time2 ...] ...} => {::pname {:min <min-time> ...} ...}"
[plog]
(reduce (fn [m [pname times]]
(let [count (count times)
total (reduce + times)]
(assoc m pname {:count count
:min (apply min times)
:max (apply max times)
:mean (long (/ total count))
:total total})))
{} plog))
(defn fqname
"Like `name` but returns fully-qualified name."
[keyword]
(str (namespace keyword) "/" (name keyword)))
(defn plog-table
"Returns formatted plog stats table for given plog stats."
([stats] (plog-table stats :total))
([stats sort-field]
(let [;; How long entire (profile) body took
total-time (-> stats :meta/total :total)
stats (dissoc stats :meta/total)
;; Sum of (p) times, <= total-time
accounted (reduce + (map :total (vals stats)))
max-name-width (apply max (map (comp count str)
(conj (keys stats) "Unaccounted")))
pattern (str "%" max-name-width "s %6d %9s %10s %9s %7d %1s%n")
s-pattern (.replace pattern \d \s)
perc #(Math/round (/ %1 %2 0.01))
ft (fn [nanosecs]
(let [pow #(Math/pow 10 %)
ok-pow? #(>= nanosecs (pow %))
to-pow #(long (/ nanosecs (pow %)))]
(cond (ok-pow? 9) (str (to-pow 9) "s")
(ok-pow? 6) (str (to-pow 6) "ms")
(ok-pow? 3) (str (to-pow 3) "μs")
:else (str (long nanosecs) "ns"))))]
(with-out-str
(printf s-pattern "Name" "Count" "Min" "Max" "Mean" "Total%" "Total")
(doseq [pname (->> (keys stats)
(sort-by #(- (get-in stats [% sort-field]))))]
(let [{:keys [count min max mean total]} (stats pname)]
(printf pattern (fqname pname) count (ft min) (ft max) (ft mean)
(perc total total-time)
(ft total))))
(let [unacc (- total-time accounted)
unacc-perc (perc unacc total-time)]
(printf s-pattern "Unaccounted" "" "" "" "" unacc-perc (ft unacc))
(printf s-pattern "Total" "" "" "" "" 100 (ft total-time)))))))
(defmacro profile*
"Executes named body with profiling enabled. Body forms wrapped in (p) will be
timed and time stats sent along with `name` to binary `log-fn`. Returns body's
result."
[log-fn name & body]
(let [name (prepare-name name)]
`(binding [*plog* (atom {})]
(let [result# (do ~@body)]
(~log-fn ~name (plog-stats @*plog*))
result#))))
(defmacro profile
"When logging is enabled, executes named body with profiling enabled. Body
forms wrapped in (p) will be timed and time stats logged. Always returns
body's result.
Note that logging appenders will receive both a profiling table string AND the
raw profiling stats under a special :profiling-stats key. One common use is
for db appenders to check for this special key and to log profiling stats to
db in a queryable manner."
[level name & body]
(timbre/assert-valid-level level)
`(if (timbre/logging-enabled? ~level)
(profile*
(fn [name# stats#]
(timbre/log* ~level
{:profile-stats stats#}
(str "Profiling: " (fqname name#))
(str "\n" (plog-table stats#))))
~name
(p :meta/total ~@body))
(do ~@body)))
(defmacro sampling-profile
"Like `profile`, but only enables profiling every 1/`proportion` calls.
Always returns body's result."
[level proportion name & body]
`(if (> ~proportion (rand))
(profile ~level ~name ~@body)
(do ~@body)))
(comment
(profile :info :Sleepy-threads
(Thread/sleep 100) ; Unaccounted
(p :1ms (Thread/sleep 1))
(p :2s (Thread/sleep 2000))
(p :50ms (Thread/sleep 50))
(p :10ms (Thread/sleep 10))
"Result")
(p :hello "Hello, this is a result") ; Falls through (no *plog* context)
(defn my-fn
[]
(let [nums (vec (range 1000))]
(+ (p :fast-sleep (Thread/sleep 1) 10)
(p :slow-sleep (Thread/sleep 2) 32)
(p :add (reduce + nums))
(p :sub (reduce - nums))
(p :mult (reduce * nums))
(p :div (reduce / nums)))))
(profile :info :Arithmetic (dotimes [n 100] (my-fn)))
(sampling-profile :info 0.2 :Sampling-test (p :string "Hello!")))

5
test/test_timbre/timbre.clj Normal file
View File

@ -0,0 +1,5 @@
(ns test-timbre.timbre
(:use [clojure.test]
[taoensso.timbre :as timbre :only (info)]))
(deftest test-nothing) ; TODO

5
test/test_timbre/timbre/profiling.clj Normal file
View File

@ -0,0 +1,5 @@
(ns test-timbre.timbre.profiling
(:use [clojure.test]
[taoensso.timbre :as timbre :only (info)]))
(deftest test-nothing) ; TODO

7
test/timbre/test/core.clj
View File

@ -1,7 +0,0 @@
(ns timbre.test.core
(:use [clojure.test]
[timbre.core :as timbre :only (info)]))
;; TODO Tests (help would be welcome!!)
(deftest test-nothing)