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'

This commit is contained in:
Peter Taoussanis 2013-12-01 20:08:25 +07:00
parent a8ebec06d5 8993e78e6d
commit 34394319c2
15 changed files with 836 additions and 569 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

36
CHANGELOG.md
View File

@ -1,3 +1,34 @@
## v3.0.0-RC1 / 2013-11-30
Major update, non-breaking though users with custom appenders are encouraged to view the _Changes_ section below. This version polishes up the codebase and general design. Tightened up a few aspects of how appenders and appender middleware work. Also finally added facilities for ad hoc (non-atom) logging configuration.
Overall quite happy with the state of Timbre as of this release. No major anticipated improvements/changes from here (modulo bugs).
### Features
* Android appender, courtesy of AdamClements.
* 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).
* `log` and `logf` macros now take an optional logging config map as their first argument: `(log :info "hello") => use @timbre/config`, `(log <config> :info "hello") => use <config>`.
* Appenders can now specify an optional `:fmt-output-opts` that'll get passed to `fmt-output-fn` for any special formatting requirements they may have (e.g. the Postal email appender provides an arg to suppress ANSI colors in stacktrace output).
### Changes
* EXPERIMENTAL: stacktraces now formatted with `io.aviso/pretty` rather than clj-stacktrace. Feedback on this (esp. coloring) welcome!
* DEPRECATED: `red`, `green`, `blue` -> use `color-str` instead.
* DEPRECATED: config `prefix-fn` has been replaced by the more flexible `fmt-output-fn`. Change is backwards compatible.
* REMOVED: Per-appender `:prefix` option dropped - was unnecessary. If an appender wants custom output formatting, it can do so w/o using an in-config formatter.
* Update `refer-timbre` (add profiling, logf variations, etc.).
* DEPRECATED: atom logging level is now located in `level-atom` rather than `config`. Old in-config levels will be respected (i.e. change is backwards compatible).
* DEPRECATED: appender rate limits are now specified as `:rate-limit [ncalls window-msecs]` rather than `:limit-per-msecs ncalls`. Change is backwards compatible.
* Built-in appenders have been simplified using the new `default-output` appender arg.
* Postal appender now generates a more useful subject in most cases.
### Fixes
* [#38] Broken namespace filter (mlb-).
* [unreported] Messages are now generated _after_ middleware has been applied, allowing better filtering performance and more intuitive behaviour (e.g. changes to args in middleware will now automatically percolate to message content).
## v2.6.3 → v2.7.1 ## v2.6.3 → v2.7.1
* Core: `getHostName` no longer runs on the main thread for better Android compatibility (AdamClements). * Core: `getHostName` no longer runs on the main thread for better Android compatibility (AdamClements).
* Profiling: added `defnp` macro. * Profiling: added `defnp` macro.
@ -46,11 +77,8 @@
* **BREAKING**: Stacktraces are no longer automatically generated at the `log`-macro level. Stacktraces are now left as an appender implementation detail. A `:throwable` appender argument has been added along with a `stacktrace` fn. * **BREAKING**: Stacktraces are no longer automatically generated at the `log`-macro level. Stacktraces are now left as an appender implementation detail. A `:throwable` appender argument has been added along with a `stacktrace` fn.
## For older versions please see the [commit history][] ### For older versions please see the [commit history][]
[commit history]: https://github.com/ptaoussanis/timbre/commits/master [commit history]: https://github.com/ptaoussanis/timbre/commits/master
[API docs]: http://ptaoussanis.github.io/timbre [API docs]: http://ptaoussanis.github.io/timbre
[Taoensso libs]: https://www.taoensso.com/clojure-libraries [Taoensso libs]: https://www.taoensso.com/clojure-libraries
[Nippy GitHub]: https://github.com/ptaoussanis/nippy
[Nippy CHANGELOG]: https://github.com/ptaoussanis/carmine/blob/master/CHANGELOG.md
[Nippy API docs]: http://ptaoussanis.github.io/nippy

307
README.md
View File

@ -1,14 +1,18 @@
**[API docs](http://ptaoussanis.github.io/timbre/)** | **[CHANGELOG](https://github.com/ptaoussanis/timbre/blob/master/CHANGELOG.md)** | [contact & contributing](#contact--contributing) | [other Clojure libs](https://www.taoensso.com/clojure-libraries) | [Twitter](https://twitter.com/#!/ptaoussanis) | current [semantic](http://semver.org/) version: **[API docs](http://ptaoussanis.github.io/timbre/)** | **[CHANGELOG](https://github.com/ptaoussanis/timbre/blob/master/CHANGELOG.md)** | [contact & contributing](#contact--contribution) | [other Clojure libs](https://www.taoensso.com/clojure-libraries) | [Twitter](https://twitter.com/#!/ptaoussanis) | current [semantic](http://semver.org/) version:
```clojure ```clojure
[com.taoensso/timbre "2.7.1"] ; See CHANGELOG for breaking changes since 1.x [com.taoensso/timbre "3.0.0-RC1"] ; Non-breaking upgrade - see CHANGELOG for details
[com.taoensso/timbre "2.7.1"] ; Stable
``` ```
Appender authors: please see [here](https://github.com/ptaoussanis/timbre/issues/41) about migrating Timbre 2.x appenders to 3.x's recommended style.
# Timbre, a (sane) Clojure logging & profiling library # Timbre, a (sane) Clojure logging & profiling library
Logging with Java can be maddeningly, unnecessarily hard. Particularly if all you want is something *simple that works out-the-box*. Timbre is an attempt to make **simple logging simple** and more **complex logging reasonable**. 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.
@ -17,19 +21,30 @@ Logging with Java can be maddeningly, unnecessarily hard. Particularly if all yo
* Sensible built-in appenders including simple **email appender**. * Sensible built-in appenders including simple **email appender**.
* Tunable **rate limit** and **asynchronous** logging support. * Tunable **rate limit** and **asynchronous** logging support.
* Robust **namespace filtering**. * Robust **namespace filtering**.
* **[tools.logging](https://github.com/clojure/tools.logging) support** (optional). * [tools.logging](https://github.com/clojure/tools.logging) support (optional, useful when integrating with legacy logging systems).
* Dead-simple, logging-level-aware **logging profiler**. * Dead-simple, logging-level-aware **logging profiler**.
## Getting started ## Getting started
### Dependencies ### Dependencies
Add the necessary dependency to your [Leiningen](http://leiningen.org/) `project.clj` and `require` the library in your ns: Add the necessary dependency to your [Leiningen](http://leiningen.org/) `project.clj` and use the supplied ns-import helper:
```clojure ```clojure
[com.taoensso/timbre "2.7.1"] ; project.clj [com.taoensso/timbre "3.0.0-RC1"] ; project.clj
(ns my-app (:require [taoensso.timbre :as timbre
:refer (trace debug info warn error fatal spy with-log-level)])) ; ns (ns my-app (:require [taoensso.timbre :as timbre])) ; Your ns
(timbre/refer-timbre) ; Provides useful Timbre aliases in this ns
```
The `refer-timbre` call is a convenience fn that executes:
```clojure
(require '[taoensso.timbre :as timbre
:refer (log trace debug info warn error fatal report
logf tracef debugf infof warnf errorf fatalf reportf
spy logged-future with-log-level)])
(require '[taoensso.timbre.utils :refer (sometimes)])
(require '[taoensso.timbre.profiling :as profiling :refer (pspy profile defnp)])
``` ```
### Logging ### Logging
@ -37,39 +52,16 @@ Add the necessary dependency to your [Leiningen](http://leiningen.org/) `project
By default, Timbre gives you basic print output to `*out*`/`*err*` at a `debug` logging level: By default, Timbre gives you basic print output to `*out*`/`*err*` at a `debug` logging level:
```clojure ```clojure
(info "This will print") (info "This will print") => nil
=> nil
%> 2012-May-28 17:26:11:444 +0700 localhost INFO [my-app] - This will print %> 2012-May-28 17:26:11:444 +0700 localhost INFO [my-app] - This will print
(spy :info (* 5 4 3 2 1)) (spy :info (* 5 4 3 2 1)) => 120
=> 120
%> 2012-May-28 17:26:14:138 +0700 localhost INFO [my-app] - (* 5 4 3 2 1) 120 %> 2012-May-28 17:26:14:138 +0700 localhost INFO [my-app] - (* 5 4 3 2 1) 120
(trace "This won't print due to insufficient logging level") (trace "This won't print due to insufficient logging level") => nil
=> nil
``` ```
There's little overhead for checking logging levels: First-argument exceptions generate a nicely cleaned-up stack trace using [io.aviso.exception](https://github.com/AvisoNovate/pretty).
```clojure
(time (trace (Thread/sleep 5000)))
%> "Elapsed time: 0.054 msecs"
(time (when false))
%> "Elapsed time: 0.051 msecs"
```
And _no_ overhead when using a compile-time logging level (set `TIMBRE_LOG_LEVEL` environment variable):
```clojure
(time (dotimes [_ 1000000000] (trace (Thread/sleep 5000))))
%> "Elapsed time: 387.159 msecs"
(time (dotimes [_ 1000000000] nil))
%> "Elapsed time: 389.231 msecs"
```
First-argument exceptions generate a stack trace:
```clojure ```clojure
(info (Exception. "Oh noes") "arg1" "arg2") (info (Exception. "Oh noes") "arg1" "arg2")
@ -82,49 +74,140 @@ java.lang.Exception: Oh noes
### Configuration ### Configuration
Configuring Timbre couldn't be simpler. Let's check out (some of) the defaults: This is the biggest win over Java logging utilities IMO. Here's `timbre/example-config` (also Timbre's default config):
```clojure ```clojure
@timbre/config (def example-config
=> "APPENDERS
{:current-level :debug An appender is a map with keys:
:doc ; (Optional) string.
:min-level ; (Optional) keyword, or nil (no minimum level).
:enabled? ; (Optional).
:async? ; (Optional) dispatch using agent (good for slow appenders).
:rate-limit ; (Optional) [ncalls-limit window-ms].
:fmt-output-opts ; (Optional) extra opts passed to `fmt-output-fn`.
:fn ; (fn [appender-args-map]), with keys described below.
:ns-whitelist [] An appender's fn takes a single map with keys:
:ns-blacklist [] :level ; Keyword.
:error? ; Is level an 'error' level?.
:throwable ; java.lang.Throwable.
:args ; Raw logging macro args (as given to `info`, etc.).
:message ; Stringified logging macro args, or nil.
:output ; Output of `fmt-output-fn`, used by built-in appenders
; as final, formatted appender output. Appenders may (but
; are not obligated to) use this as their output.
:ap-config ; Contents of config's :shared-appender-config key.
:profile-stats ; From `profile` macro.
:instant ; java.util.Date.
: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 [] ; As of Timbre 1.4.0, see source for details MIDDLEWARE
Middleware are fns (applied right-to-left) that transform the map
dispatched to appender fns. If any middleware returns nil, no dispatching
will occur (i.e. the event will be filtered).
:timestamp-pattern "yyyy-MMM-dd HH:mm:ss ZZ" The `example-config` code contains further settings and details.
:timestamp-locale nil See also `set-config!`, `merge-config!`, `set-level!`."
:appenders {;;; Control log filtering by namespace patterns (e.g. ["my-app.*"]).
{:standard-out { <...> } ;;; Useful for turning off logging in noisy libraries, etc.
:spit { <...> } :ns-whitelist []
<...> } :ns-blacklist []
:shared-appender-config {}} ;; 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
;; Output formatter used by built-in appenders. Custom appenders may (but are
;; not required to use) its output (:output). Extra per-appender opts can be
;; supplied as an optional second (map) arg.
:fmt-output-fn
(fn [{:keys [level throwable message timestamp hostname ns]}
;; Any extra appender-specific opts:
& [{:keys [nofonts?] :as appender-fmt-output-opts}]]
;; <timestamp> <hostname> <LEVEL> [<ns>] - <message> <throwable>
(format "%s %s %s [%s] - %s%s"
timestamp hostname (-> level name str/upper-case) ns (or message "")
(or (stacktrace throwable "\n" (when nofonts? {})) "")))
:shared-appender-config {} ; Provided to all appenders via :ap-config key
:appenders
{:standard-out
{:doc "Prints to *out*/*err*. Enabled by default."
:min-level nil :enabled? true :async? false :rate-limit nil
:fn (fn [{:keys [error? output]}] ; Use any appender args
(binding [*out* (if error? *err* *out*)]
(str-println output)))}
:spit
{: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)]ar
(try (spit filename output :append true)
(catch java.io.IOException _))))}}})
``` ```
Easily adjust the current logging level: A few things to note:
```clojure * Appenders are trivial to write & configure - **they're just fns**. It's Timbre's job to dispatch useful args to appenders when appropriate, it's their job to do something interesting with them.
(timbre/set-level! :warn) * Being 'just fns', appenders have basically limitless potential: write to your database, send a message over the network, check some other state (e.g. environment config) before making a choice, etc.
```
And the default timestamp formatting for log messages: The **logging level** may be set:
* At compile-time: (`TIMBRE_LOG_LEVEL` environment variable).
* Via an atom: `(timbre/set-level! <level>)`. (Usual method).
* Via dynamic thread-level binding: `(timbre/with-log-level <level> ...)`.
```clojure A compile-time level offers _zero-overhead_ performance since it'll cause insufficient logging calls to disappear completely at compile-time. Usually you won't need/want to bother: Timbre offers very decent performance with runtime level checks (~15msecs/10k checks on my Macbook Air).
(timbre/set-config! [:timestamp-pattern] "yyyy-MMM-dd HH:mm:ss ZZ")
(timbre/set-config! [:timestamp-locale] (java.util.Locale/GERMAN))
```
Filter logging output by namespaces: For common-case ease-of-use, **all logging utils use a global atom for their config**. This is configurable with `timbre/set-config!`, `timbre/merge-config!`. The lower-level `log` and `logf` macros also take an optional first-arg config map for greater flexibility (e.g. **during testing**).
```clojure
(timbre/set-config! [:ns-whitelist] ["some.library.core" "my-app.*"])
```
### Built-in appenders ### Built-in appenders
#### Redis ([Carmine](https://github.com/ptaoussanis/carmine)) appender (v3+)
```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))
```
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
;; [com.draines/postal "1.9.2"] ; Add to project.clj deps
;; (:require [taoensso.timbre.appenders (postal :as postal-appender)]) ; Add to ns
(timbre/set-config! [:appenders :postal]
(postal-appender/make-postal-appender
{:enabled? true
:rate-limit [1 60000] ; 1 msg / 60,000 msecs (1 min)
:async? true ; Don't block waiting for email to send
}
{:postal-config
^{:host "mail.isp.net" :user "jsmith" :pass "sekrat!!1"}
{:from "me@draines.com" :to "foo@example.com"}}))
```
#### File appender #### File appender
```clojure ```clojure
@ -132,91 +215,11 @@ Filter logging output by namespaces:
(timbre/set-config! [:shared-appender-config :spit-filename] "/path/my-file.log") (timbre/set-config! [:shared-appender-config :spit-filename] "/path/my-file.log")
``` ```
#### Email ([Postal](https://github.com/drewr/postal)) appender #### Other included appenders
```clojure 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**.
;; [com.draines/postal "1.9.2"] ; Add to project.clj dependencies
;; (:require [taoensso.timbre.appenders (postal :as postal-appender)]) ; Add to ns
(timbre/set-config! [:appenders :postal] postal-appender/postal-appender) Thanks to their respective authors! Just give me a shout if you've got an appender you'd like to have added.
(timbre/set-config! [:shared-appender-config :postal]
^{:host "mail.isp.net" :user "jsmith" :pass "sekrat!!1"}
{:from "me@draines.com" :to "foo@example.com"})
;; Rate limit to one email per message per minute
(timbre/set-config! [:appenders :postal :limit-per-msecs] 60000)
;; Make sure emails are sent asynchronously
(timbre/set-config! [:appenders :postal :async?] true)
```
#### IRC ([irclj](https://github.com/flatland/irclj)) appender
```clojure
;; [irclj "0.5.0-alpha2"] ; Add to project.clj dependencies
;; (:require [taoensso.timbre.appenders (irc :as irc-appender)]) ; Add to ns
(timbre/set-config! [:appenders :irc] irc-appender/irc-appender)
(timbre/set-config! [:shared-appender-config :irc]
{:host "irc.example.org"
:port 6667
:nick "logger"
:name "Logger"
:chan "#logs"})
```
#### Socket ([server-socket](https://github.com/technomancy/server-socket)) appender
Listens on the specified interface (use :all for all interfaces, defaults to localhost if unspecified) and port. Connect with either of:
```
telnet localhost 9000
netcat localhost 9000
```
```clojure
;; [server-socket "1.0.0"] ; Add to project.clj dependencies
;; (:require [taoensso.timbre.appenders (socket :as socket-appender)]) ; Add to ns
(timbre/set-config! [:appenders :socket] socket-appender/socket-appender)
(timbre/set-config! [:shared-appender-config :socket]
{:listen-addr :all
:port 9000})
```
#### MongoDB ([congomongo](https://github.com/aboekhoff/congomongo)) appender
```clojure
;; [congomongo "0.4.1"] ; Add to project.clj dependencies
;; (:require [taoensso.timbre.appenders (mongo :as mongo-appender)]) ; Add to ns
(timbre/set-config! [:appenders :mongo] mongo-appender/mongo-appender)
(timbre/set-config! [:shared-appender-config :mongo]
{:db "logs"
:collection "myapp"
:server {:host "127.0.0.1" :port 27017}})
```
### Custom appenders
Writing a custom appender is dead-easy:
```clojure
(timbre/set-config!
[:appenders :my-appender]
{:doc "Hello-world appender"
:min-level :debug
:enabled? true
:async? false
:limit-per-msecs nil ; No rate limit
:fn (fn [{:keys [ap-config level prefix throwable message] :as args}]
(when-not (:my-production-mode? ap-config)
(println prefix "Hello world!" message)))
```
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 the `timbre/config` docstring for more information on appenders.
## Profiling ## Profiling
@ -224,12 +227,6 @@ The usual recommendation for Clojure profiling is: use a good **JVM profiler** l
And these certainly 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. And these certainly 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
(:require [taoensso.timbre.profiling :as profiling :refer (p profile)])
```
Wrap forms that you'd like to profile with the `p` macro and give them a name: Wrap forms that you'd like to profile with the `p` macro and give them a name:
```clojure ```clojure
@ -243,15 +240,13 @@ Wrap forms that you'd like to profile with the `p` macro and give them a name:
(p :mult (reduce * nums)) (p :mult (reduce * nums))
(p :div (reduce / nums))))) (p :div (reduce / nums)))))
(my-fn) (my-fn) => 42
=> 42
``` ```
The `profile` macro can now be used to log times for any wrapped forms: The `profile` macro can now be used to log times for any wrapped forms:
```clojure ```clojure
(profile :info :Arithmetic (dotimes [n 100] (my-fn))) (profile :info :Arithmetic (dotimes [n 100] (my-fn))) => "Done!"
=> "Done!"
%> 2012-Jul-03 20:46:17 +0700 localhost INFO [my-app] - Profiling my-app/Arithmetic %> 2012-Jul-03 20:46:17 +0700 localhost INFO [my-app] - Profiling my-app/Arithmetic
Name Calls Min Max MAD Mean Total% Total Name Calls Min Max MAD Mean Total% Total
my-app/slow-sleep 100 2ms 2ms 31μs 2ms 57 231ms my-app/slow-sleep 100 2ms 2ms 31μs 2ms 57 231ms
@ -264,6 +259,8 @@ The `profile` macro can now be used to log times for any wrapped forms:
Total 100 405ms Total 100 405ms
``` ```
You can also use the `defnp` macro to conveniently wrap whole fns.
It's important to note that Timbre profiling is fully **logging-level aware**: if the level is insufficient, you *won't pay for profiling*. Likewise, normal namespace filtering applies. (Performance characteristics for both checks are inherited from Timbre itself). It's important to note that Timbre profiling is fully **logging-level aware**: if the 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*. 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*.

14
project.clj
View File

@ -1,23 +1,25 @@
(defproject com.taoensso/timbre "2.7.1" (defproject com.taoensso/timbre "3.0.0-RC1"
:description "Clojure logging & profiling library" :description "Clojure logging & profiling library"
:url "https://github.com/ptaoussanis/timbre" :url "https://github.com/ptaoussanis/timbre"
:license {:name "Eclipse Public License" :license {:name "Eclipse Public License"
:url "http://www.eclipse.org/legal/epl-v10.html"} :url "http://www.eclipse.org/legal/epl-v10.html"}
:dependencies [[org.clojure/clojure "1.4.0"] :dependencies [[org.clojure/clojure "1.4.0"]
[org.clojure/tools.macro "0.1.5"] [org.clojure/tools.macro "0.1.5"]
[clj-stacktrace "0.2.7"]] [io.aviso/pretty "0.1.6"]]
:profiles {:1.4 {:dependencies [[org.clojure/clojure "1.4.0"]]} :profiles {:1.4 {:dependencies [[org.clojure/clojure "1.4.0"]]}
:1.5 {:dependencies [[org.clojure/clojure "1.5.1"]]} :1.5 {:dependencies [[org.clojure/clojure "1.5.1"]]}
:1.6 {:dependencies [[org.clojure/clojure "1.6.0-master-SNAPSHOT"]]} :1.6 {:dependencies [[org.clojure/clojure "1.6.0-alpha2"]]}
:dev {:dependencies []} :dev {:dependencies [[com.draines/postal "1.11.1"]
[com.taoensso/carmine "2.4.0"]
[org.clojure/tools.logging "0.2.6"]]}
:test {:dependencies [[expectations "1.4.56"]]}} :test {:dependencies [[expectations "1.4.56"]]}}
:aliases {"test-all" ["with-profile" "+test,+1.4:+test,+1.5:+test,+1.6" "expectations"] :aliases {"test-all" ["with-profile" "+test,+1.4:+test,+1.5:+test,+1.6" "expectations"]
"test-auto" ["with-profile" "+test" "autoexpect"] "test-auto" ["with-profile" "+test" "autoexpect"]
"start-dev" ["with-profile" "+dev,+test,+bench" "repl" ":headless"] "start-dev" ["with-profile" "+dev,+test,+bench" "repl" ":headless"]
"codox" ["with-profile" "+test" "doc"]} "codox" ["with-profile" "+dev,+test" "doc"]}
:plugins [[lein-expectations "0.0.8"] :plugins [[lein-expectations "0.0.8"]
[lein-autoexpect "1.0"] [lein-autoexpect "1.0"]
[lein-ancient "0.4.4"] [lein-ancient "0.5.4"]
[codox "0.6.6"]] [codox "0.6.6"]]
:min-lein-version "2.0.0" :min-lein-version "2.0.0"
:global-vars {*warn-on-reflection* true} :global-vars {*warn-on-reflection* true}

613
src/taoensso/timbre.clj
View File

@ -1,8 +1,7 @@
(ns taoensso.timbre (ns taoensso.timbre "Simple, flexible, all-Clojure logging. No XML!"
"Simple, flexible, all-Clojure logging. No XML!"
{:author "Peter Taoussanis"} {:author "Peter Taoussanis"}
(:require [clojure.string :as str] (:require [clojure.string :as str]
[clj-stacktrace.repl :as stacktrace] [io.aviso.exception :as aviso-ex]
[taoensso.timbre.utils :as utils]) [taoensso.timbre.utils :as utils])
(:import [java.util Date Locale] (:import [java.util Date Locale]
[java.text SimpleDateFormat])) [java.text SimpleDateFormat]))
@ -12,21 +11,17 @@
(defn str-println (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." atomic string. This is faster and avoids interleaving race conditions."
[& xs] [& xs] (print (str (str/join \space (filter identity xs)) \newline))
(print (str (str/join \space (filter identity xs)) \newline)) (flush))
(flush))
(defn color-str [color & xs] (defn color-str [color & xs]
(let [ansi-color #(str "\u001b[" (case % :reset "0" :black "30" :red "31" (let [ansi-color #(format "\u001b[%sm"
:green "32" :yellow "33" :blue "34" (case % :reset "0" :black "30" :red "31"
:purple "35" :cyan "36" :white "37" :green "32" :yellow "33" :blue "34"
"0") "m")] :purple "35" :cyan "36" :white "37"
"0"))]
(str (ansi-color color) (apply str xs) (ansi-color :reset)))) (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-out (java.io.OutputStreamWriter. System/out))
(def default-err (java.io.PrintWriter. System/err)) (def default-err (java.io.PrintWriter. System/err))
@ -34,167 +29,200 @@
"Evaluates body with Clojure's default *out* and *err* bindings." "Evaluates body with Clojure's default *out* and *err* bindings."
[& body] `(binding [*out* default-out *err* default-err] ~@body)) [& body] `(binding [*out* default-out *err* default-err] ~@body))
(defmacro with-err-as-out (defmacro with-err-as-out "Evaluates body with *err* bound to *out*."
"Evaluates body with *err* bound to *out*."
[& body] `(binding [*err* *out*] ~@body)) [& body] `(binding [*err* *out*] ~@body))
(defn stacktrace [throwable & [separator]] (defn stacktrace "Default stacktrace formatter for use by appenders, etc."
[throwable & [separator stacktrace-fonts]]
(when throwable (when throwable
(str separator throwable ; (str throwable) incl. ex-data for Clojure 1.4+ (str separator
"\n\n" (stacktrace/pst-str throwable)))) (if-let [fonts stacktrace-fonts]
(binding [aviso-ex/*fonts* fonts] (aviso-ex/format-exception throwable))
(aviso-ex/format-exception throwable)))))
;;;; Default configuration and appenders (comment (stacktrace (Exception. "foo") nil {}))
(def compile-time-level ;;;; Logging levels
;; Level precendence: compile-time > dynamic > atom
(def level-compile-time
"Constant, compile-time logging level determined by the `TIMBRE_LOG_LEVEL` "Constant, compile-time logging level determined by the `TIMBRE_LOG_LEVEL`
environment variable. When set, overrules dynamically-configurable logging environment variable. When set, overrules dynamically-configurable logging
level as a performance optimization (e.g. for use in performance sensitive level as a performance optimization (e.g. for use in performance sensitive
production environments)." production environments)."
(keyword (System/getenv "TIMBRE_LOG_LEVEL"))) (keyword (System/getenv "TIMBRE_LOG_LEVEL")))
(def ^:dynamic *current-level* nil) (def ^:dynamic *level-dynamic* nil)
(defmacro with-log-level (defmacro with-log-level
"Allows thread-local config logging level override. Useful for dev & testing." "Allows thread-local config logging level override. Useful for dev & testing."
[level & body] `(binding [*current-level* ~level] ~@body)) [level & body] `(binding [*level-dynamic* ~level] ~@body))
(utils/defonce* config (def level-atom (atom :debug))
"This map atom controls everything about the way Timbre operates. (defn set-level! [level] (reset! level-atom level))
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: (def levels-ordered [:trace :debug :info :warn :error :fatal :report])
:level, :throwable (def ^:private levels-scored (assoc (zipmap levels-ordered (next (range))) nil 0))
: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 (defn error-level? [level] (boolean (#{:error :fatal} level))) ; For appenders, etc.
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!` (defn- level-checked-score [level]
for convenient config editing." (or (levels-scored level)
(atom {:current-level :debug ; See also `with-log-level` (throw (Exception. (format "Invalid logging level: %s" level)))))
;;; Control log filtering by namespace patterns (e.g. ["my-app.*"]). (def ^:private levels-compare (memoize (fn [x y] (- (level-checked-score x)
;;; Useful for turning off logging in noisy libraries, etc. (level-checked-score y)))))
:ns-whitelist []
:ns-blacklist []
;; Fns (applied right-to-left) to transform/filter appender fn args. (declare config)
;; Useful for obfuscating credentials, pattern filtering, etc. ;; Used in macros, must be public:
:middleware [] (defn level-sufficient? [level ; & [config] ; Deprecated
]
(>= (levels-compare level
(or level-compile-time
*level-dynamic*
;; Deprecate config-specified level:
;;(:current-level (or config @config)) ; Don't need compile here
(:current-level @config) ; DEPRECATED, here for backwards comp
@level-atom)) 0))
;;; Control :timestamp format ;;;; Default configuration and appenders
:timestamp-pattern "yyyy-MMM-dd HH:mm:ss ZZ" ; SimpleDateFormat pattern
:timestamp-locale nil ; A Locale object, or nil
;; Control :prefix format ; TODO Generalize to output pattern (def example-config
:prefix-fn "APPENDERS
(fn [{:keys [level timestamp hostname ns]}] An appender is a map with keys:
(str timestamp " " hostname " " (-> level name str/upper-case) :doc ; (Optional) string.
" [" ns "]")) :min-level ; (Optional) keyword, or nil (no minimum level).
:enabled? ; (Optional).
:async? ; (Optional) dispatch using agent (good for slow appenders).
:rate-limit ; (Optional) [ncalls-limit window-ms].
:fmt-output-opts ; (Optional) extra opts passed to `fmt-output-fn`.
:fn ; (fn [appender-args-map]), with keys described below.
;; Will be provided to all appenders via :ap-config key An appender's fn takes a single map with keys:
:shared-appender-config {} :level ; Keyword.
:error? ; Is level an 'error' level?
:throwable ; java.lang.Throwable.
:args ; Raw logging macro args (as given to `info`, etc.).
:message ; Stringified logging macro args, or nil.
:output ; Output of `fmt-output-fn`, used by built-in appenders
; as final, formatted appender output. Appenders may (but
; are not obligated to) use this as their output.
:ap-config ; Content of config's :shared-appender-config key.
:profile-stats ; From `profile` macro.
:instant ; java.util.Date.
: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.
:appenders MIDDLEWARE
{:standard-out Middleware are fns (applied right-to-left) that transform the map
{:doc "Prints to *out* or *err* as appropriate. Enabled by default." dispatched to appender fns. If any middleware returns nil, no dispatching
:min-level nil :enabled? true :async? false :limit-per-msecs nil will occur (i.e. the event will be filtered).
:fn (fn [{:keys [error? prefix throwable message]}]
(binding [*out* (if error? *err* *out*)]
(str-println prefix "-" message (stacktrace throwable))))}
:spit The `example-config` code contains further settings and details.
{:doc "Spits to (:spit-filename :shared-appender-config) file." See also `set-config!`, `merge-config!`, `set-level!`."
: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 _))))}}}))
{;;; 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
:prefix-fn ; DEPRECATED, here for backwards comp
(fn [{:keys [level timestamp hostname ns]}]
(str timestamp " " hostname " " (-> level name str/upper-case)
" [" ns "]"))
;; Output formatter used by built-in appenders. Custom appenders may (but are
;; not required to use) its output (:output). Extra per-appender opts can be
;; supplied as an optional second (map) arg.
:fmt-output-fn
(fn [{:keys [level throwable message timestamp hostname ns]}
;; Any extra appender-specific opts:
& [{:keys [nofonts?] :as appender-fmt-output-opts}]]
;; <timestamp> <hostname> <LEVEL> [<ns>] - <message> <throwable>
(format "%s %s %s [%s] - %s%s"
timestamp hostname (-> level name str/upper-case) ns (or message "")
(or (stacktrace throwable "\n" (when nofonts? {})) "")))
:shared-appender-config {} ; Provided to all appenders via :ap-config key
:appenders
{:standard-out
{:doc "Prints to *out*/*err*. Enabled by default."
:min-level nil :enabled? true :async? false :rate-limit nil
:fn (fn [{:keys [error? output]}] ; Use any appender args
(binding [*out* (if error? *err* *out*)]
(str-println output)))}
:spit
{: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)]
(try (spit filename output :append true)
(catch java.io.IOException _))))}}})
(utils/defonce* config (atom example-config))
(defn set-config! [ks val] (swap! config assoc-in ks val)) (defn set-config! [ks val] (swap! config assoc-in ks val))
(defn merge-config! [& maps] (apply swap! config utils/merge-deep maps)) (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 compile-time-level
*current-level*
(:current-level @config))) 0))
;;;; Appender-fn decoration ;;;; Appender-fn decoration
(defn- wrap-appender-fn (defn- wrap-appender-fn
"Wraps compile-time appender fn with additional runtime capabilities "Wraps compile-time appender fn with additional runtime capabilities
controlled by compile-time config." controlled by compile-time config."
[{apfn :fn :keys [async? limit-per-msecs prefix-fn] :as appender}] [config {apfn :fn :keys [async? rate-limit fmt-output-opts] :as appender}]
(let [limit-per-msecs (or (:max-message-per-msecs appender) (let [rate-limit (or rate-limit ; Backwards comp:
limit-per-msecs)] ; Backwards-compatibility (if-let [x (:max-message-per-msecs appender)] [1 x]
(when-let [x (:limit-per-msecs appender)] [1 x])))]
(assert (or (nil? rate-limit) (vector? rate-limit)))
(->> ; Wrapping applies per appender, bottom-to-top (->> ; Wrapping applies per appender, bottom-to-top
apfn apfn
;; Per-appender prefix-fn support (cmp. default prefix-fn) ;; Custom appender-level fmt-output-opts
;; TODO Currently undocumented, candidate for removal ((fn [apfn] ; Compile-time:
((fn [apfn] (if-not fmt-output-opts apfn ; Common case (no appender-level fmt opts)
(if-not prefix-fn (fn [apfn-args] ; Runtime:
apfn ;; Replace default (juxt-level) output:
(fn [apfn-args] (apfn (assoc apfn-args :output
(apfn (assoc apfn-args ((:fmt-output-fn config) apfn-args fmt-output-opts)))))))
:prefix (prefix-fn apfn-args)))))))
;; Rate limit support ;; Rate limit support
((fn [apfn] ((fn [apfn]
(if-not limit-per-msecs ;; Compile-time:
apfn (if-not rate-limit apfn
(let [timers (atom {})] ; {:hash last-appended-time-msecs ...} (let [[ncalls-limit window-ms] rate-limit
(fn [{ns :ns [x1 & _] :args :as apfn-args}] limiter-any (utils/rate-limiter ncalls-limit window-ms)
(let [now (System/currentTimeMillis) ;; This is a little hand-wavy but it's a decent general
hash (str ns "/" x1) ; TODO Alternatives? ;; strategy and helps us from making this overly complex to
limit? (fn [last-msecs] ;; configure:
(and last-msecs (<= (- now last-msecs) limiter-specific (utils/rate-limiter (quot ncalls-limit 4)
limit-per-msecs)))] window-ms)]
(fn [{:keys [ns args] :as apfn-args}]
(when-not (limit? (@timers hash)) ;; Runtime: (test smaller limit 1st):
(apfn apfn-args) (when-not (or (limiter-specific (str ns args)) (limiter-any))
(swap! timers assoc hash now)) (apfn apfn-args)))))))
(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 ;; Async (agent) support
((fn [apfn] ((fn [apfn]
(if-not async? ;; Compile-time:
apfn (if-not async? apfn
(let [agent (agent nil :error-mode :continue)] (let [agent (agent nil :error-mode :continue)]
(fn [apfn-args] (send-off agent (fn [_] (apfn apfn-args))))))))))) (fn [apfn-args] ; Runtime:
(send-off agent (fn [_] (apfn apfn-args)))))))))))
(defn- make-timestamp-fn (defn- make-timestamp-fn
"Returns a unary fn that formats instants using given pattern string and an "Returns a unary fn that formats instants using given pattern string and an
@ -210,7 +238,7 @@
(comment ((make-timestamp-fn "yyyy-MMM-dd" nil) (Date.))) (comment ((make-timestamp-fn "yyyy-MMM-dd" nil) (Date.)))
(def get-hostname (def ^:private get-hostname
(utils/memoize-ttl 60000 (utils/memoize-ttl 60000
(fn [] (fn []
(let [p (promise)] (let [p (promise)]
@ -225,105 +253,130 @@
"Wraps compile-time appender juxt with additional runtime capabilities "Wraps compile-time appender juxt with additional runtime capabilities
(incl. middleware) controlled by compile-time config. Like `wrap-appender-fn` (incl. middleware) controlled by compile-time config. Like `wrap-appender-fn`
but operates on the entire juxt at once." but operates on the entire juxt at once."
[juxtfn] [config juxtfn]
(->> ; Wrapping applies per juxt, bottom-to-top (->> ; Wrapping applies per juxt, bottom-to-top
juxtfn juxtfn
;; Post-middleware stuff
((fn [juxtfn]
;; Compile-time:
(let [{ap-config :shared-appender-config
:keys [timestamp-pattern timestamp-locale
prefix-fn fmt-output-fn]} config
timestamp-fn (when timestamp-pattern
(make-timestamp-fn timestamp-pattern timestamp-locale))]
(fn [juxtfn-args]
;; Runtime:
(when-let [{:keys [instant msg-type args]} juxtfn-args]
(let [juxtfn-args (if-not msg-type juxtfn-args ; tools.logging
(-> juxtfn-args
(dissoc :msg-type)
(assoc :message
(when-not (empty? args)
(case msg-type
:format (apply format args)
:print-str (apply print-str args)
:nil nil)))))
juxtfn-args (assoc juxtfn-args :timestamp (timestamp-fn instant))
juxtfn-args (assoc juxtfn-args
;; DEPRECATED, here for backwards comp:
:prefix (when-let [f prefix-fn] (f juxtfn-args))
:output (when-let [f fmt-output-fn] (f juxtfn-args)))]
(juxtfn juxtfn-args)))))))
;; Middleware transforms/filters support ;; Middleware transforms/filters support
((fn [juxtfn] ((fn [juxtfn]
(if-let [middleware (seq (:middleware @config))] ;; Compile-time:
(if-let [middleware (seq (:middleware config))]
(let [composed-middleware (let [composed-middleware
(apply comp (map (fn [mf] (fn [args] (when args (mf args)))) (apply comp (map (fn [mf] (fn [args] (when args (mf args))))
middleware))] middleware))]
(fn [juxtfn-args] (fn [juxtfn-args]
;; Runtime:
(when-let [juxtfn-args (composed-middleware juxtfn-args)] (when-let [juxtfn-args (composed-middleware juxtfn-args)]
(juxtfn juxtfn-args)))) (juxtfn juxtfn-args))))
juxtfn))) juxtfn)))
;; Add compile-time stuff to runtime appender args ;; Pre-middleware stuff
((fn [juxtfn] ((fn [juxtfn]
(let [{ap-config :shared-appender-config ;; Compile-time:
:keys [timestamp-pattern timestamp-locale prefix-fn]} @config (let [{ap-config :shared-appender-config} config]
(fn [juxtfn-args]
;; Runtime:
(juxtfn (merge juxtfn-args {:ap-config ap-config
:hostname (get-hostname)}))))))))
timestamp-fn (make-timestamp-fn timestamp-pattern timestamp-locale)] ;;;; Config compilation
(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 (defn- relevant-appenders [appenders level]
(->> appenders
;;; 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 %)] (filter #(let [{:keys [enabled? min-level]} (val %)]
(and enabled? (>= (compare-levels level min-level) 0)))) (and enabled? (>= (levels-compare level min-level) 0))))
(into {}))) (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] (defn- ns-match? [ns match]
(-> (str "^" (-> (str match) (.replace "." "\\.") (.replace "*" "(.*)")) "$") (-> (str "^" (-> (str match) (.replace "." "\\.") (.replace "*" "(.*)")) "$")
re-pattern (re-find (str ns)) boolean)) re-pattern (re-find (str ns)) boolean))
(defn- cache-ns-filter! [] (def compile-config ; Used in macros, must be public
(->> "Returns {:appenders-juxt {<level> <wrapped-juxt or nil>}
(let [{:keys [ns-whitelist ns-blacklist]} @config] :ns-filter (fn relevant-ns? [ns])}."
(memoize (memoize
(fn relevant-ns? [ns] ;; Careful. The presence of fns actually means that inline config's won't
(and (or (empty? ns-whitelist) ;; actually be identified as samey. In practice not a major (?) problem
(some (partial ns-match? ns) ns-whitelist)) ;; since configs will usually be assigned to a var for which we have proper
(or (empty? ns-blacklist) ;; identity.
(not-any? (partial ns-match? ns) ns-blacklist)))))) (fn [{:keys [appenders] :as config}]
(reset! ns-filter-cache))) (assert (map? appenders))
{:appenders-juxt
(zipmap levels-ordered
(->> levels-ordered
(map (fn [l] (let [rel-aps (relevant-appenders appenders l)]
;; Return nil if no relevant appenders
(when-let [ap-ids (keys rel-aps)]
(->> ap-ids
(map #(wrap-appender-fn config (rel-aps %)))
(apply juxt)
(wrap-appender-juxt config))))))))
:ns-filter
(let [{:keys [ns-whitelist ns-blacklist]} config]
(if (and (empty? ns-whitelist) (empty? ns-blacklist))
(fn relevant-ns? [ns] true)
(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)))))))})))
;;; Prime initial caches and re-cache on config change (comment (compile-config example-config))
(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!))))
;;;; Logging macros ;;;; Logging macros
(defn send-to-appenders! "Implementation detail - subject to change." (defmacro logging-enabled?
[level base-appender-args log-vargs ns throwable message & [juxt-fn file line]] "Returns true iff current logging level is sufficient and current namespace
(when-let [juxt-fn (or juxt-fn (@appenders-juxt-cache level))] unfiltered. The namespace test is runtime, the logging-level test compile-time
iff a compile-time logging level was specified."
[level & [config]]
(if level-compile-time
(when (level-sufficient? level)
`(let [ns-filter# (:ns-filter (compile-config (or ~config @config)))]
(ns-filter# ~(str *ns*))))
`(and (level-sufficient? ~level)
(let [ns-filter# (:ns-filter (compile-config (or ~config @config)))]
(ns-filter# ~(str *ns*))))))
(comment (def compile-time-level :info)
(def compile-time-level nil)
(macroexpand-1 '(logging-enabled? :debug)))
(defn send-to-appenders! "Implementation detail."
[;; Args provided by both Timbre, tools.logging:
level base-appender-args log-vargs ns throwable message
;; Additional args provided by Timbre only:
& [juxt-fn msg-type file line]]
(when-let [juxt-fn (or juxt-fn (get-in (compile-config @config)
[:appenders-juxt level]))]
(juxt-fn (juxt-fn
(conj (or base-appender-args {}) (conj (or base-appender-args {})
{:instant (Date.) {:instant (Date.)
@ -334,52 +387,56 @@
:error? (error-level? level) :error? (error-level? level)
:args log-vargs ; No tools.logging support :args log-vargs ; No tools.logging support
:throwable throwable :throwable throwable
:message message})) :message message ; Timbre: nil, tools.logging: nil or string
:msg-type msg-type ; Timbre: nnil, tools.logging: nil
}))
nil)) nil))
(defmacro logging-enabled? (defmacro log* "Implementation detail."
"Returns true iff current logging level is sufficient and current namespace {:arglists '([base-appender-args msg-type level & log-args]
unfiltered. The namespace test is runtime, the logging-level test compile-time [base-appender-args msg-type config level & log-args])}
iff a compile-time logging level was specified." [base-appender-args msg-type & [s1 s2 :as sigs]]
[level] {:pre [(#{:nil :print-str :format} msg-type)]}
(if compile-time-level `(let [;;; Support [level & log-args], [config level & log-args] sigs:
(when (sufficient-level? level) s1# ~s1
`(@ns-filter-cache *ns*)) default-config?# (or (keyword? s1#) (nil? s1#))
`(and (sufficient-level? ~level) (@ns-filter-cache *ns*)))) config# (if default-config?# @config s1#)
level# (if default-config?# s1# ~s2)]
(comment (when (logging-enabled? level# config#)
(def compile-time-level :info) (when-let [juxt-fn# (get-in (compile-config config#)
(def compile-time-level nil) [:appenders-juxt level#])]
(macroexpand-1 '(logging-enabled? :debug))) (let [[x1# & xn# :as xs#] (if default-config?#
(vector ~@(next sigs))
(vector ~@(nnext sigs)))
has-throwable?# (instance? Throwable x1#)
log-vargs# (vec (if has-throwable?# xn# xs#))]
(send-to-appenders!
level#
~base-appender-args
log-vargs#
~(str *ns*)
(when has-throwable?# x1#)
nil ; Timbre generates msg only after middleware
juxt-fn#
~msg-type
(let [file# ~*file*] (when (not= file# "NO_SOURCE_PATH") file#))
;; TODO Waiting on http://dev.clojure.org/jira/browse/CLJ-865:
~(:line (meta &form))))))))
(defmacro log* "Implementation detail - subject to change." (defmacro log
[message-fn level base-appender-args & log-args] "Logs using print-style args. Takes optional logging config (defaults to
`(when (logging-enabled? ~level) `timbre/@config`.)"
(when-let [juxt-fn# (@appenders-juxt-cache ~level)] {:arglists '([level & message] [level throwable & message]
(let [[x1# & xn# :as xs#] (vector ~@log-args) [config level & message] [config level throwable & message])}
has-throwable?# (instance? Throwable x1#) [& sigs] `(log* {} :print-str ~@sigs))
log-vargs# (vec (if has-throwable?# xn# xs#))]
(send-to-appenders!
~level
~base-appender-args
log-vargs#
~(str *ns*)
(when has-throwable?# x1#)
(when-let [mf# ~message-fn]
(when-not (empty? log-vargs#)
(apply mf# log-vargs#)))
juxt-fn#
(let [file# ~*file*] (when (not= file# "NO_SOURCE_PATH") file#))
;; TODO Waiting on http://dev.clojure.org/jira/browse/CLJ-865:
~(:line (meta &form)))))))
(defmacro log "Logs using print-style args." (defmacro logf
{:arglists '([level & message] [level throwable & message])} "Logs using format-style args. Takes optional logging config (defaults to
[level & sigs] `(log* print-str ~level {} ~@sigs)) `timbre/@config`.)"
{:arglists '([level fmt & fmt-args] [level throwable fmt & fmt-args]
(defmacro logf "Logs using format-style args." [config level fmt & fmt-args] [config level throwable fmt & fmt-args])}
{:arglists '([level fmt & fmt-args] [level throwable fmt & fmt-args])} [& sigs] `(log* {} :format ~@sigs))
[level & sigs] `(log* format ~level {} ~@sigs))
(defmacro log-errors [& body] `(try ~@body (catch Throwable t# (error t#)))) (defmacro log-errors [& body] `(try ~@body (catch Throwable t# (error t#))))
(defmacro log-and-rethrow-errors [& body] (defmacro log-and-rethrow-errors [& body]
@ -414,18 +471,29 @@
[& sigs#] `(logf ~~level ~@sigs#))))) [& sigs#] `(logf ~~level ~@sigs#)))))
(defmacro ^:private def-loggers [] (defmacro ^:private def-loggers []
`(do ~@(map (fn [level] `(def-logger ~level)) ordered-levels))) `(do ~@(map (fn [level] `(def-logger ~level)) levels-ordered)))
(def-loggers) ; Actually define a logger for each logging level (def-loggers) ; Actually define a logger for each logging level
(defn refer-timbre (defn refer-timbre
"Shorthand for: "Shorthand for:
(require '[taoensso.timbre :as timbre (require
:refer (trace debug info warn error fatal report spy with-log-level)])" '[taoensso.timbre :as timbre
:refer (log trace debug info warn error fatal report
logf tracef debugf infof warnf errorf fatalf reportf
spy logged-future with-log-level)])
(require '[taoensso.timbre.utils :refer (sometimes)])
(require
'[taoensso.timbre.profiling :as profiling :refer (pspy profile defnp)])"
[] []
(require '[taoensso.timbre :as timbre (require
:refer (log trace debug info warn error fatal report spy with-log-level '[taoensso.timbre :as timbre
logf tracef debugf infof warnf errorf fatalf reportf)])) :refer (log trace debug info warn error fatal report
logf tracef debugf infof warnf errorf fatalf reportf
spy logged-future with-log-level)])
(require '[taoensso.timbre.utils :refer (sometimes)])
(require
'[taoensso.timbre.profiling :as profiling :refer (pspy profile defnp)]))
;;;; Deprecated ;;;; Deprecated
@ -437,6 +505,10 @@
{:arglists '([expr] [level expr] [level name expr])} {:arglists '([expr] [level expr] [level name expr])}
[& args] `(spy ~@args)) [& args] `(spy ~@args))
(def red "DEPRECATED: Use `color-str` instead." (partial color-str :red))
(def green "DEPRECATED: Use `color-str` instead." (partial color-str :green))
(def yellow "DEPRECATED: Use `color-str` instead." (partial color-str :yellow))
;;;; Dev/tests ;;;; Dev/tests
(comment (comment
@ -450,15 +522,20 @@
(info "a%s" "b") (info "a%s" "b")
(infof "a%s" "b") (infof "a%s" "b")
(info {} "a")
(log {} :info "a")
(log example-config :info "a")
(set-config! [:ns-blacklist] []) (set-config! [:ns-blacklist] [])
(set-config! [:ns-blacklist] ["taoensso.timbre*"]) (set-config! [:ns-blacklist] ["taoensso.timbre*"])
(info "foo" "bar") (info "foo" "bar")
(trace (Thread/sleep 5000)) (trace (Thread/sleep 5000))
(time (dotimes [n 10000] (trace "This won't log"))) ; Overhead 5ms/10ms (time (dotimes [n 10000] (trace "This won't log"))) ; Overhead 5ms->15ms
(time (dotimes [n 10000] (when false)))
(time (dotimes [n 5] (info "foo" "bar"))) (time (dotimes [n 5] (info "foo" "bar")))
(spy (* 6 5 4 3 2 1)) (spy :info (* 6 5 4 3 2 1))
(spy :debug :factorial6 (* 6 5 4 3 2 1)) (spy :info :factorial6 (* 6 5 4 3 2 1))
(info (Exception. "noes!") "bar") (info (Exception. "noes!") "bar")
(spy (/ 4 0)) (spy (/ 4 0))
@ -467,12 +544,22 @@
;; Middleware ;; Middleware
(info {:name "Robert Paulson" :password "Super secret"}) (info {:name "Robert Paulson" :password "Super secret"})
(set-config! (set-config! [:middleware] [])
[:middleware] (set-config! [:middleware]
[(fn [{:keys [hostname message] :as args}] [(fn [{:keys [hostname message args] :as ap-args}]
(cond (= hostname "filtered-host") nil ; Filter (if (= hostname "filtered-host") nil ; Filter
(map? message) (assoc ap-args :args
(if (contains? message :password) ;; Replace :password vals in any map args:
(assoc args :message (assoc message :password "*****")) (mapv (fn [arg] (if-not (map? arg) arg
args) (if-not (contains? arg :password) arg
:else args))])) (assoc arg :password "****"))))
args))))])
;; fmt-output-opts
(-> (merge example-config
{:appenders
{:fmt-output-opts-test
{:min-level :error :enabled? true
:fmt-output-opts {:nofonts? true}
:fn (fn [{:keys [output]}] (str-println output))}}})
(log :report (Exception. "Oh noes") "Hello")))

33
src/taoensso/timbre/appenders/android.clj Normal file
View File

@ -0,0 +1,33 @@
(ns taoensso.timbre.appenders.android
"Android LogCat appender. Depends on the android runtime. This is a
configuration for the timbre logging library"
{:author "Adam Clements"}
(:require [taoensso.timbre :as timbre]))
(def logcat-appender
{:doc (str "Appends to Android logcat. Obviously only works if "
"running within the Android runtime (device or emulator)."
"You may want to disable std-out to prevent printing nested "
"timestamps, etc.")
:min-level :debug
:enabled? true
:prefix-fn :ns
:fn (fn [{:keys [level prefix throwable message]}]
(if throwable
(case level
:trace (android.util.Log/d prefix message throwable)
:debug (android.util.Log/d prefix message throwable)
:info (android.util.Log/i prefix message throwable)
:warn (android.util.Log/w prefix message throwable)
:error (android.util.Log/e prefix message throwable)
:fatal (android.util.Log/e prefix message throwable)
:report (android.util.Log/i prefix message throwable))
(case level
:trace (android.util.Log/d prefix message)
:debug (android.util.Log/d prefix message)
:info (android.util.Log/i prefix message)
:warn (android.util.Log/w prefix message)
:error (android.util.Log/e prefix message)
:fatal (android.util.Log/e prefix message)
:report (android.util.Log/i prefix message))))})

138
src/taoensso/timbre/appenders/carmine.clj Normal file
View File

@ -0,0 +1,138 @@
(ns taoensso.timbre.appenders.carmine
"Carmine (Redis) appender. Requires https://github.com/ptaoussanis/carmine."
{:author "Peter Taoussanis"}
(: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:
* 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 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 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))]}
(let [default-appender-opts {:enabled? true :min-level nil}]
(merge default-appender-opts appender-opts
{:fn
(fn [{:keys [level instant] :as apfn-args}]
(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. 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-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
(comment
(timbre/log {:timestamp-pattern "yyyy-MMM-dd HH:mm:ss ZZ"
:appenders {:carmine (make-carmine-appender)}}
:info "Hello1" "Hello2")
(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)))

4
src/taoensso/timbre/appenders/irc.clj
View File

@ -41,6 +41,6 @@
"Needs :irc config map in :shared-appender-config, e.g.: "Needs :irc config map in :shared-appender-config, e.g.:
{:host \"irc.example.org\" :port 6667 :nick \"logger\" {:host \"irc.example.org\" :port 6667 :nick \"logger\"
:name \"My Logger\" :chan \"#logs\"") :name \"My Logger\" :chan \"#logs\"")
:min-level :info :enabled? true :async? false :limit-per-msecs nil :min-level :info :enabled? true
:prefix-fn (fn [{:keys [level]}] (-> level name str/upper-case)) :prefix-fn (fn [{:keys [level]}] (-> level name str/upper-case))
:fn appender-fn}) :fn appender-fn})

2
src/taoensso/timbre/appenders/mongo.clj
View File

@ -42,5 +42,5 @@
:server {:host \"127.0.0.1\" :server {:host \"127.0.0.1\"
:port 27017}}") :port 27017}}")
:min-level :warn :enabled? true :async? true :min-level :warn :enabled? true :async? true
:max-message-per-msecs 1000 ; 1 entry / sec :rate-limit [1 1000] ; 1 entry / sec
:fn appender-fn}) :fn appender-fn})

58
src/taoensso/timbre/appenders/postal.clj
View File

@ -1,23 +1,47 @@
(ns taoensso.timbre.appenders.postal (ns taoensso.timbre.appenders.postal
"Email appender. Depends on https://github.com/drewr/postal." "Email appender. Requires https://github.com/drewr/postal."
{:author "Peter Taoussanis"} {:author "Peter Taoussanis"}
(:require [clojure.string :as str] (:require [clojure.string :as str]
[postal.core :as postal] [postal.core :as postal]
[taoensso.timbre :as timbre])) [taoensso.timbre :as timbre]))
(def postal-appender (defn- str-trunc [^String s max-len]
{:doc (str "Sends an email using com.draines/postal.\n" (if (<= (.length s) max-len) s
"Needs :postal config map in :shared-appender-config, e.g.: (.substring s 0 max-len)))
^{:host \"mail.isp.net\" :user \"jsmith\" :pass \"sekrat!!1\"}
{:from \"Bob's logger <me@draines.com>\" :to \"foo@example.com\"}") (comment (str-trunc "Hello this is a long string" 5))
:min-level :error :enabled? true :async? true
:limit-per-msecs (* 1000 60 10) ; 1 subject / 10 mins (defn make-postal-appender
:fn (fn [{:keys [ap-config prefix throwable args]}] "Returns a Postal email appender.
(when-let [postal-config (:postal ap-config)] A Postal config map can be provided here as an argument, or as a :postal key
(let [[subject & body] args] in :shared-appender-config.
(postal/send-message
(assoc postal-config (make-postal-appender {:enabled? true}
;; TODO Better to just use trunc'd message as subject? {:postal-config
:subject (str prefix " - " (or subject throwable)) ^{:host \"mail.isp.net\" :user \"jsmith\" :pass \"sekrat!!1\"}
:body (str (str/join \space body) {:from \"Bob's logger <me@draines.com>\" :to \"foo@example.com\"}})"
(timbre/stacktrace throwable "\n")))))))}) [& [appender-opts {:keys [postal-config subject-len]
:or {subject-len 150}}]]
(let [default-appender-opts
{:enabled? true
:min-level :warn
:async? true ; Slow!
:rate-limit [5 (* 1000 60 2)] ; 5 calls / 2 mins
:fmt-output-opts {:nofonts? true} ; Disable ANSI-escaped stuff
}]
(merge default-appender-opts appender-opts
{:fn
(fn [{:keys [ap-config output]}]
(when-let [postal-config (or postal-config (:postal ap-config))]
(postal/send-message
(assoc postal-config
:subject (-> (str output)
(str/trim)
(str-trunc subject-len)
(str/replace #"\s+" " "))
:body output))))})))
(def postal-appender "DEPRECATED: Use `make-postal-appender` instead."
(make-postal-appender))

4
src/taoensso/timbre/appenders/rotor.clj
View File

@ -1,8 +1,8 @@
(ns taoensso.timbre.appenders.rotor (ns taoensso.timbre.appenders.rotor
{:author "Yutaka Matsubara"}
(:import (:import
[java.io File FilenameFilter]) [java.io File FilenameFilter])
(:require (:require
[clj-stacktrace.repl :as stacktrace]
[clojure.java.io :as io] [clojure.java.io :as io]
[taoensso.timbre :as t])) [taoensso.timbre :as t]))
@ -75,6 +75,4 @@
:backlog 5}") :backlog 5}")
:min-level nil :min-level nil
:enabled? true :enabled? true
:async? false
:limit-per-msecs nil
:fn appender-fn}) :fn appender-fn})

3
src/taoensso/timbre/appenders/socket.clj
View File

@ -44,6 +44,5 @@
"Needs :socket config map in :shared-appender-config, e.g.: "Needs :socket config map in :shared-appender-config, e.g.:
{:listen-addr :all {:listen-addr :all
:port 9000}") :port 9000}")
:min-level :trace :enabled? true :async? false :min-level :trace :enabled? true
:max-message-per-msecs nil ; no rate limit by default
:fn appender-fn}) :fn appender-fn})

84
src/taoensso/timbre/frequencies.clj
View File

@ -1,84 +0,0 @@
(ns taoensso.timbre.frequencies
"DEPRECATED.
Frequency logger for Timbre. ALPHA quality."
{:author "Peter Taoussanis"}
(:require [clojure.string :as str]
[taoensso.timbre :as timbre]
[taoensso.timbre.utils :as utils]))
(def ^:dynamic *fdata* "{::fname {form-value frequency}}" nil)
(defmacro with-fdata
[level & body]
`(if-not (timbre/logging-enabled? ~level)
{:result (do ~@body)}
(binding [*fdata* (atom {})]
{:result (do ~@body) :stats @*fdata*})))
(declare format-fdata)
(defmacro log-frequencies
"When logging is enabled, executes named body with frequency counting enabled.
Body forms wrapped in (fspy) will have their result frequencies logged. Always
returns body's result.
Note that logging appenders will receive both a formatted frequencies string
AND the raw frequency stats under a special :frequency-stats key (useful for
queryable db logging)."
[level name & body]
(let [name (utils/fq-keyword name)]
`(let [{result# :result stats# :stats} (with-fdata ~level ~@body)]
(when stats#
(timbre/log* print-str ~level {:frequency-stats stats#}
(str "Frequencies " ~name)
(str "\n" (format-fdata stats#))))
result#)))
(defmacro sampling-log-frequencies
"Like `log-frequencies`, but only enables frequency counting every
1/`proportion` calls. Always returns body's result."
[level proportion name & body]
`(if-not (> ~proportion (rand))
(do ~@body)
(log-frequencies ~level ~name ~@body)))
(defmacro fspy
"Frequency spy. When in the context of a *fdata* binding, records the frequency
of each enumerated result. Always returns the body's result."
[name & body]
(let [name (utils/fq-keyword name)]
`(if-not *fdata*
(do ~@body)
(let [name# ~name
result# (try (do ~@body) (catch Throwable t# {::throwable t#}))
throwable# (and (map? result#) (::throwable result#))]
(swap! *fdata* #(assoc-in % [name# (or throwable# result#)]
(inc (get-in % [name# (or throwable# result#)] 0))))
(if throwable# (throw throwable#) result#)))))
(defmacro f [name & body] `(fspy name ~@body)) ; Alias
(defn format-fdata
[stats]
(let [sorted-fnames (sort (keys stats))
sorted-fvals (fn [form-stats] (reverse (sort-by form-stats
(keys form-stats))))]
(str/join "\n"
(for [fname sorted-fnames]
(let [form-stats (stats fname)
sorted-fvs (sorted-fvals form-stats)]
(str fname " "
(str/join " "
(mapv (fn [v] (vector v (get form-stats v 0)))
sorted-fvs))))))))
(comment (format-fdata {:name1 {:a 10 :b 4 :c 20}
:name2 {33 8 12 2 false 6}}))
(comment
(with-fdata :info
(vec (repeatedly 20 (fn [] (fspy :rand-nth (rand-nth [:a :b :c]))))))
(log-frequencies
:info :my-frequencies
(vec (repeatedly 20 (fn [] (fspy :rand-nth (rand-nth [:a :b :c])))))))

27
src/taoensso/timbre/profiling.clj
View File

@ -41,16 +41,17 @@
[level name & body] [level name & body]
`(let [{result# :result stats# :stats} (with-pdata ~level ~@body)] `(let [{result# :result stats# :stats} (with-pdata ~level ~@body)]
(when stats# (when stats#
(timbre/log* print-str ~level {:profile-stats stats#} (timbre/log* {:profile-stats stats#} :format ~level
(str "Profiling " (utils/fq-keyword ~name)) "Profiling: %s\n%s" (utils/fq-keyword ~name)
(str "\n" (format-pdata stats#)))) (format-pdata stats#)))
result#)) result#))
(defmacro sampling-profile (defmacro sampling-profile
"Like `profile`, but only enables profiling every 1/`proportion` calls." "Like `profile`, but only enables profiling with given probability."
[level proportion name & body] [level probability name & body]
`(if-not (> ~proportion (rand)) (do ~@body) `(do (assert (<= 0 ~probability 1) "Probability: 0<=p<=1")
(profile ~level ~name ~@body))) (if-not (< (rand) ~probability) (do ~@body)
(profile ~level ~name ~@body))))
(defn pdata-stats (defn pdata-stats
"{::pname [time1 time2 ...] ...} => {::pname {:min <min-time> ...} ...} "{::pname [time1 time2 ...] ...} => {::pname {:min <min-time> ...} ...}
@ -62,8 +63,8 @@
(let [count (max 1 (count times)) (let [count (max 1 (count times))
time (reduce + times) time (reduce + times)
mean (long (/ time count)) mean (long (/ time count))
mad (long (/ (reduce + (mapv #(Math/abs (long (- % mean))) mad (long (/ (reduce + (map #(Math/abs (long (- % mean)))
times)) ; Mean absolute deviation times)) ; Mean absolute deviation
count))] count))]
(assoc m pname {:count count (assoc m pname {:count count
:min (apply min times) :min (apply min times)
@ -75,10 +76,10 @@
(defn format-pdata [stats & [sort-field]] (defn format-pdata [stats & [sort-field]]
(let [clock-time (-> stats ::clock-time :time) ; How long entire profile body took (let [clock-time (-> stats ::clock-time :time) ; How long entire profile body took
stats (dissoc stats ::clock-time) stats (dissoc stats ::clock-time)
accounted (reduce + (mapv :time (vals stats))) accounted (reduce + (map :time (vals stats)))
max-name-width (apply max (mapv (comp count str) max-name-width (apply max (map (comp count str)
(conj (keys stats) "Accounted Time"))) (conj (keys stats) "Accounted Time")))
pattern (str "%" max-name-width "s %6d %9s %10s %9s %9s %7d %1s%n") pattern (str "%" max-name-width "s %6d %9s %10s %9s %9s %7d %1s%n")
s-pattern (.replace pattern \d \s) s-pattern (.replace pattern \d \s)
perc #(Math/round (/ %1 %2 0.01)) perc #(Math/round (/ %1 %2 0.01))

7
src/taoensso/timbre/tools/logging.clj
View File

@ -1,6 +1,7 @@
(ns taoensso.timbre.tools.logging (ns taoensso.timbre.tools.logging
"clojure.tools.logging.impl/Logger implementation" "clojure.tools.logging.impl/Logger implementation"
(:require [taoensso.timbre :as timbre])) (:require [clojure.tools.logging]
[taoensso.timbre :as timbre]))
(deftype Logger [logger-ns] (deftype Logger [logger-ns]
clojure.tools.logging.impl/Logger clojure.tools.logging.impl/Logger
@ -9,8 +10,8 @@
;; tools.logging message may be a string (for `logp`/`logf` calls) or raw ;; tools.logging message may be a string (for `logp`/`logf` calls) or raw
;; argument (for `log` calls). Note that without an :args equivalent for ;; argument (for `log` calls). Note that without an :args equivalent for
;; `write!`, the best we can do is `[message]`. This inconsistency means ;; `write!`, the best we can do is `[message]`. This inconsistency means
;; that :args consumers (like the rate limiter and Postal appender) will ;; that :args consumers will necessarily behave differently under
;; necessarily behave differently under tools.logging. ;; tools.logging.
(timbre/send-to-appenders! level {} [message] logger-ns throwable (timbre/send-to-appenders! level {} [message] logger-ns throwable
(when (string? message) message)))) (when (string? message) message))))

75
src/taoensso/timbre/utils.clj
View File

@ -10,20 +10,61 @@
(let [[name [expr]] (macro/name-with-attributes name sigs)] (let [[name [expr]] (macro/name-with-attributes name sigs)]
`(clojure.core/defonce ~name ~expr))) `(clojure.core/defonce ~name ~expr)))
(defn memoize-ttl (defn memoize-ttl "Low-overhead, common-case `memoize*`."
"Like `memoize` but invalidates the cache for a set of arguments after TTL
msecs has elapsed."
[ttl-ms f] [ttl-ms f]
(let [cache (atom {})] (let [cache (atom {})]
(fn [& args] (fn [& args]
(let [{:keys [time-cached d-result]} (@cache args) (when (<= (rand) 0.001) ; GC
now (System/currentTimeMillis)] (let [instant (System/currentTimeMillis)]
(swap! cache
(fn [m] (reduce-kv (fn [m* k [dv udt :as cv]]
(if (> (- instant udt) ttl-ms) m*
(assoc m* k cv))) {} m)))))
(let [[dv udt] (@cache args)]
(if (and dv (< (- (System/currentTimeMillis) udt) ttl-ms)) @dv
(locking cache ; For thread racing
(let [[dv udt] (@cache args)] ; Retry after lock acquisition!
(if (and dv (< (- (System/currentTimeMillis) udt) ttl-ms)) @dv
(let [dv (delay (apply f args))
cv [dv (System/currentTimeMillis)]]
(swap! cache assoc args cv)
@dv)))))))))
(if (and time-cached (< (- now time-cached) ttl-ms)) (defn rate-limiter
@d-result "Returns a `(fn [& [id]])` that returns either `nil` (limit okay) or number of
(let [d-result (delay (apply f args))] msecs until next rate limit window (rate limited)."
(swap! cache assoc args {:time-cached now :d-result d-result}) [ncalls-limit window-ms]
@d-result)))))) (let [state (atom [nil {}])] ; [<pull> {<id> {[udt-window-start ncalls]}}]
(fn [& [id]]
(when (<= (rand) 0.001) ; GC
(let [instant (System/currentTimeMillis)]
(swap! state
(fn [[_ m]]
[nil (reduce-kv
(fn [m* id [udt-window-start ncalls]]
(if (> (- instant udt-window-start) window-ms) m*
(assoc m* id [udt-window-start ncalls]))) {} m)]))))
(->
(let [instant (System/currentTimeMillis)]
(swap! state
(fn [[_ m]]
(if-let [[udt-window-start ncalls] (m id)]
(if (> (- instant udt-window-start) window-ms)
[nil (assoc m id [instant 1])]
(if (< ncalls ncalls-limit)
[nil (assoc m id [udt-window-start (inc ncalls)])]
[(- (+ udt-window-start window-ms) instant) m]))
[nil (assoc m id [instant 1])]))))
(nth 0)))))
(comment
(def rl (rate-limit 10 10000))
(repeatedly 10 #(rl (rand-nth [:a :b :c])))
(rl :a)
(rl :b)
(rl :c))
(defn merge-deep-with ; From clojure.contrib.map-utils (defn merge-deep-with ; From clojure.contrib.map-utils
"Like `merge-with` but merges maps recursively, applying the given fn "Like `merge-with` but merges maps recursively, applying the given fn
@ -45,8 +86,7 @@
(comment (merge-deep {:a {:b {:c {:d :D :e :E}}}} (comment (merge-deep {:a {:b {:c {:d :D :e :E}}}}
{:a {:b {:g :G :c {:c {:f :F}}}}})) {:a {:b {:g :G :c {:c {:f :F}}}}}))
(defn round-to (defn round-to "Rounds argument to given number of decimal places."
"Rounds argument to given number of decimal places."
[places x] [places x]
(if (zero? places) (if (zero? places)
(Math/round (double x)) (Math/round (double x))
@ -56,11 +96,14 @@
(comment (round-to 0 10) (comment (round-to 0 10)
(round-to 2 10.123)) (round-to 2 10.123))
(defmacro fq-keyword (defmacro fq-keyword "Returns namespaced keyword for given name."
"Returns namespaced keyword for given name."
[name] [name]
`(if (and (keyword? ~name) (namespace ~name)) `(if (and (keyword? ~name) (namespace ~name)) ~name
~name
(keyword (str ~*ns*) (clojure.core/name ~name)))) (keyword (str ~*ns*) (clojure.core/name ~name))))
(comment (map #(fq-keyword %) ["foo" :foo :foo/bar])) (comment (map #(fq-keyword %) ["foo" :foo :foo/bar]))
(defmacro sometimes "Executes body with probability e/o [0,1]."
[probability & body]
`(do (assert (<= 0 ~probability 1) "Probability: 0 <= p <= 1")
(when (< (rand) ~probability) ~@body)))