diff --git a/CHANGELOG.md b/CHANGELOG.md index 45f46c1..207ee15 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -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 :info "hello") => use `. + * 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 * Core: `getHostName` no longer runs on the main thread for better Android compatibility (AdamClements). * 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. -## 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 [API docs]: http://ptaoussanis.github.io/timbre [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 diff --git a/README.md b/README.md index 88fd8ef..395b18e 100644 --- a/README.md +++ b/README.md @@ -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 -[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 -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™? + * [Logs as Clojure values](https://github.com/ptaoussanis/timbre/tree/dev#redis-carmine-appender-v3) (v3+). * Small, uncomplicated **all-Clojure** library. * **Super-simple map-based config**: no arcane XML or properties files! * **Low overhead** with dynamic logging level. @@ -17,19 +21,30 @@ Logging with Java can be maddeningly, unnecessarily hard. Particularly if all yo * Sensible built-in appenders including simple **email appender**. * Tunable **rate limit** and **asynchronous** logging support. * 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**. ## Getting started ### 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 -[com.taoensso/timbre "2.7.1"] ; project.clj -(ns my-app (:require [taoensso.timbre :as timbre - :refer (trace debug info warn error fatal spy with-log-level)])) ; ns +[com.taoensso/timbre "3.0.0-RC1"] ; project.clj + +(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 @@ -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: ```clojure -(info "This will print") -=> nil +(info "This will print") => nil %> 2012-May-28 17:26:11:444 +0700 localhost INFO [my-app] - This will print -(spy :info (* 5 4 3 2 1)) -=> 120 +(spy :info (* 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") -=> nil +(trace "This won't print due to insufficient logging level") => nil ``` -There's little overhead for checking logging levels: - -```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: +First-argument exceptions generate a nicely cleaned-up stack trace using [io.aviso.exception](https://github.com/AvisoNovate/pretty). ```clojure (info (Exception. "Oh noes") "arg1" "arg2") @@ -82,49 +74,140 @@ java.lang.Exception: Oh noes ### 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 -@timbre/config -=> -{:current-level :debug +(def example-config + "APPENDERS + 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 [] - :ns-blacklist [] + An appender's fn takes a single map with keys: + :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" - :timestamp-locale nil + The `example-config` code contains further settings and details. + See also `set-config!`, `merge-config!`, `set-level!`." - :appenders - {:standard-out { <...> } - :spit { <...> } - <...> } + {;;; Control log filtering by namespace patterns (e.g. ["my-app.*"]). + ;;; Useful for turning off logging in noisy libraries, etc. + :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}]] + ;; [] - + (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 -(timbre/set-level! :warn) -``` + * 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. + * 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! )`. (Usual method). + * Via dynamic thread-level binding: `(timbre/with-log-level ...)`. -```clojure -(timbre/set-config! [:timestamp-pattern] "yyyy-MMM-dd HH:mm:ss ZZ") -(timbre/set-config! [:timestamp-locale] (java.util.Locale/GERMAN)) -``` +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). -Filter logging output by namespaces: -```clojure -(timbre/set-config! [:ns-whitelist] ["some.library.core" "my-app.*"]) -``` +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**). ### 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 ```clojure @@ -132,91 +215,11 @@ Filter logging output by namespaces: (timbre/set-config! [:shared-appender-config :spit-filename] "/path/my-file.log") ``` -#### Email ([Postal](https://github.com/drewr/postal)) appender +#### Other included appenders -```clojure -;; [com.draines/postal "1.9.2"] ; Add to project.clj dependencies -;; (:require [taoensso.timbre.appenders (postal :as postal-appender)]) ; Add to ns +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**. -(timbre/set-config! [:appenders :postal] postal-appender/postal-appender) -(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. +Thanks to their respective authors! Just give me a shout if you've got an appender you'd like to have added. ## 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. -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: ```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 :div (reduce / nums))))) -(my-fn) -=> 42 +(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!" +(profile :info :Arithmetic (dotimes [n 100] (my-fn))) => "Done!" %> 2012-Jul-03 20:46:17 +0700 localhost INFO [my-app] - Profiling my-app/Arithmetic Name Calls Min Max MAD Mean Total% Total 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 ``` +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). 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*. diff --git a/project.clj b/project.clj index cf40eb6..e308976 100644 --- a/project.clj +++ b/project.clj @@ -1,23 +1,25 @@ -(defproject com.taoensso/timbre "2.7.1" +(defproject com.taoensso/timbre "3.0.0-RC1" :description "Clojure logging & profiling library" :url "https://github.com/ptaoussanis/timbre" :license {:name "Eclipse Public License" :url "http://www.eclipse.org/legal/epl-v10.html"} :dependencies [[org.clojure/clojure "1.4.0"] [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"]]} :1.5 {:dependencies [[org.clojure/clojure "1.5.1"]]} - :1.6 {:dependencies [[org.clojure/clojure "1.6.0-master-SNAPSHOT"]]} - :dev {:dependencies []} + :1.6 {:dependencies [[org.clojure/clojure "1.6.0-alpha2"]]} + :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"]]}} :aliases {"test-all" ["with-profile" "+test,+1.4:+test,+1.5:+test,+1.6" "expectations"] "test-auto" ["with-profile" "+test" "autoexpect"] "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"] [lein-autoexpect "1.0"] - [lein-ancient "0.4.4"] + [lein-ancient "0.5.4"] [codox "0.6.6"]] :min-lein-version "2.0.0" :global-vars {*warn-on-reflection* true} diff --git a/src/taoensso/timbre.clj b/src/taoensso/timbre.clj index ff71e61..56579e7 100644 --- a/src/taoensso/timbre.clj +++ b/src/taoensso/timbre.clj @@ -1,8 +1,7 @@ -(ns taoensso.timbre - "Simple, flexible, all-Clojure logging. No XML!" +(ns taoensso.timbre "Simple, flexible, all-Clojure logging. No XML!" {:author "Peter Taoussanis"} (:require [clojure.string :as str] - [clj-stacktrace.repl :as stacktrace] + [io.aviso.exception :as aviso-ex] [taoensso.timbre.utils :as utils]) (:import [java.util Date Locale] [java.text SimpleDateFormat])) @@ -12,21 +11,17 @@ (defn str-println "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 (filter identity xs)) \newline)) - (flush)) + [& xs] (print (str (str/join \space (filter identity xs)) \newline)) + (flush)) (defn color-str [color & xs] - (let [ansi-color #(str "\u001b[" (case % :reset "0" :black "30" :red "31" - :green "32" :yellow "33" :blue "34" - :purple "35" :cyan "36" :white "37" - "0") "m")] + (let [ansi-color #(format "\u001b[%sm" + (case % :reset "0" :black "30" :red "31" + :green "32" :yellow "33" :blue "34" + :purple "35" :cyan "36" :white "37" + "0"))] (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-err (java.io.PrintWriter. System/err)) @@ -34,167 +29,200 @@ "Evaluates body with Clojure's default *out* and *err* bindings." [& body] `(binding [*out* default-out *err* default-err] ~@body)) -(defmacro with-err-as-out - "Evaluates body with *err* bound to *out*." +(defmacro with-err-as-out "Evaluates body with *err* bound to *out*." [& 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 - (str separator throwable ; (str throwable) incl. ex-data for Clojure 1.4+ - "\n\n" (stacktrace/pst-str throwable)))) + (str separator + (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` environment variable. When set, overrules dynamically-configurable logging level as a performance optimization (e.g. for use in performance sensitive production environments)." (keyword (System/getenv "TIMBRE_LOG_LEVEL"))) -(def ^:dynamic *current-level* nil) +(def ^:dynamic *level-dynamic* nil) (defmacro with-log-level "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 - "This map atom controls everything about the way Timbre operates. +(def level-atom (atom :debug)) +(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: - :level, :throwable - :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? +(def levels-ordered [:trace :debug :info :warn :error :fatal :report]) +(def ^:private levels-scored (assoc (zipmap levels-ordered (next (range))) nil 0)) - MIDDLEWARE - 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). +(defn error-level? [level] (boolean (#{:error :fatal} level))) ; For appenders, etc. - See source code for examples. See `set-config!`, `merge-config!`, `set-level!` - for convenient config editing." - (atom {:current-level :debug ; See also `with-log-level` +(defn- level-checked-score [level] + (or (levels-scored level) + (throw (Exception. (format "Invalid logging level: %s" level))))) - ;;; Control log filtering by namespace patterns (e.g. ["my-app.*"]). - ;;; Useful for turning off logging in noisy libraries, etc. - :ns-whitelist [] - :ns-blacklist [] +(def ^:private levels-compare (memoize (fn [x y] (- (level-checked-score x) + (level-checked-score y))))) - ;; Fns (applied right-to-left) to transform/filter appender fn args. - ;; Useful for obfuscating credentials, pattern filtering, etc. - :middleware [] +(declare config) +;; Used in macros, must be public: +(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 - :timestamp-pattern "yyyy-MMM-dd HH:mm:ss ZZ" ; SimpleDateFormat pattern - :timestamp-locale nil ; A Locale object, or nil +;;;; Default configuration and appenders - ;; Control :prefix format ; TODO Generalize to output pattern - :prefix-fn - (fn [{:keys [level timestamp hostname ns]}] - (str timestamp " " hostname " " (-> level name str/upper-case) - " [" ns "]")) +(def example-config + "APPENDERS + 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. - ;; Will be provided to all appenders via :ap-config key - :shared-appender-config {} + An appender's fn takes a single map with keys: + :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 - {:standard-out - {:doc "Prints to *out* or *err* as appropriate. Enabled by default." - :min-level nil :enabled? true :async? false :limit-per-msecs nil - :fn (fn [{:keys [error? prefix throwable message]}] - (binding [*out* (if error? *err* *out*)] - (str-println prefix "-" message (stacktrace throwable))))} + 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). - :spit - {:doc "Spits to (:spit-filename :shared-appender-config) file." - :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 _))))}}})) + The `example-config` code contains further settings and details. + See also `set-config!`, `merge-config!`, `set-level!`." + {;;; 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}]] + ;; [] - + (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 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 (defn- wrap-appender-fn "Wraps compile-time appender fn with additional runtime capabilities controlled by compile-time config." - [{apfn :fn :keys [async? limit-per-msecs prefix-fn] :as appender}] - (let [limit-per-msecs (or (:max-message-per-msecs appender) - limit-per-msecs)] ; Backwards-compatibility + [config {apfn :fn :keys [async? rate-limit fmt-output-opts] :as appender}] + (let [rate-limit (or rate-limit ; Backwards comp: + (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 apfn - ;; Per-appender prefix-fn support (cmp. default prefix-fn) - ;; TODO Currently undocumented, candidate for removal - ((fn [apfn] - (if-not prefix-fn - apfn - (fn [apfn-args] - (apfn (assoc apfn-args - :prefix (prefix-fn apfn-args))))))) + ;; Custom appender-level fmt-output-opts + ((fn [apfn] ; Compile-time: + (if-not fmt-output-opts apfn ; Common case (no appender-level fmt opts) + (fn [apfn-args] ; Runtime: + ;; Replace default (juxt-level) output: + (apfn (assoc apfn-args :output + ((:fmt-output-fn config) apfn-args fmt-output-opts))))))) ;; Rate limit support ((fn [apfn] - (if-not limit-per-msecs - apfn - (let [timers (atom {})] ; {:hash last-appended-time-msecs ...} - (fn [{ns :ns [x1 & _] :args :as apfn-args}] - (let [now (System/currentTimeMillis) - hash (str ns "/" x1) ; TODO Alternatives? - limit? (fn [last-msecs] - (and last-msecs (<= (- now last-msecs) - limit-per-msecs)))] - - (when-not (limit? (@timers hash)) - (apfn apfn-args) - (swap! timers assoc hash now)) - - (when (< (rand) 0.001) ; Occasionally garbage collect - (when-let [expired-timers (->> (keys @timers) - (remove #(limit? (@timers %))) - (seq))] - (apply swap! timers dissoc expired-timers))))))))) + ;; Compile-time: + (if-not rate-limit apfn + (let [[ncalls-limit window-ms] rate-limit + limiter-any (utils/rate-limiter ncalls-limit window-ms) + ;; This is a little hand-wavy but it's a decent general + ;; strategy and helps us from making this overly complex to + ;; configure: + limiter-specific (utils/rate-limiter (quot ncalls-limit 4) + window-ms)] + (fn [{:keys [ns args] :as apfn-args}] + ;; Runtime: (test smaller limit 1st): + (when-not (or (limiter-specific (str ns args)) (limiter-any)) + (apfn apfn-args))))))) ;; Async (agent) support ((fn [apfn] - (if-not async? - apfn + ;; Compile-time: + (if-not async? apfn (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 "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.))) -(def get-hostname +(def ^:private get-hostname (utils/memoize-ttl 60000 (fn [] (let [p (promise)] @@ -225,105 +253,130 @@ "Wraps compile-time appender juxt with additional runtime capabilities (incl. middleware) controlled by compile-time config. Like `wrap-appender-fn` but operates on the entire juxt at once." - [juxtfn] + [config juxtfn] (->> ; Wrapping applies per juxt, bottom-to-top 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 ((fn [juxtfn] - (if-let [middleware (seq (:middleware @config))] + ;; Compile-time: + (if-let [middleware (seq (:middleware config))] (let [composed-middleware (apply comp (map (fn [mf] (fn [args] (when args (mf args)))) middleware))] (fn [juxtfn-args] + ;; Runtime: (when-let [juxtfn-args (composed-middleware juxtfn-args)] (juxtfn juxtfn-args)))) juxtfn))) - ;; Add compile-time stuff to runtime appender args + ;; Pre-middleware stuff ((fn [juxtfn] - (let [{ap-config :shared-appender-config - :keys [timestamp-pattern timestamp-locale prefix-fn]} @config + ;; Compile-time: + (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)] - (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)))))))))) +;;;; Config compilation -;;;; Caching - -;;; 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) +(defn- relevant-appenders [appenders level] + (->> appenders (filter #(let [{:keys [enabled? min-level]} (val %)] - (and enabled? (>= (compare-levels level min-level) 0)))) + (and enabled? (>= (levels-compare level min-level) 0)))) (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] (-> (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))) +(def compile-config ; Used in macros, must be public + "Returns {:appenders-juxt { } + :ns-filter (fn relevant-ns? [ns])}." + (memoize + ;; Careful. The presence of fns actually means that inline config's won't + ;; actually be identified as samey. In practice not a major (?) problem + ;; since configs will usually be assigned to a var for which we have proper + ;; identity. + (fn [{:keys [appenders] :as config}] + (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 - -(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!)))) +(comment (compile-config example-config)) ;;;; Logging macros -(defn send-to-appenders! "Implementation detail - subject to change." - [level base-appender-args log-vargs ns throwable message & [juxt-fn file line]] - (when-let [juxt-fn (or juxt-fn (@appenders-juxt-cache level))] +(defmacro logging-enabled? + "Returns true iff current logging level is sufficient and current namespace + 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 (conj (or base-appender-args {}) {:instant (Date.) @@ -334,52 +387,56 @@ :error? (error-level? level) :args log-vargs ; No tools.logging support :throwable throwable - :message message})) + :message message ; Timbre: nil, tools.logging: nil or string + :msg-type msg-type ; Timbre: nnil, tools.logging: nil + })) nil)) -(defmacro logging-enabled? - "Returns true iff current logging level is sufficient and current namespace - unfiltered. The namespace test is runtime, the logging-level test compile-time - iff a compile-time logging level was specified." - [level] - (if compile-time-level - (when (sufficient-level? level) - `(@ns-filter-cache *ns*)) - `(and (sufficient-level? ~level) (@ns-filter-cache *ns*)))) +(defmacro log* "Implementation detail." + {:arglists '([base-appender-args msg-type level & log-args] + [base-appender-args msg-type config level & log-args])} + [base-appender-args msg-type & [s1 s2 :as sigs]] + {:pre [(#{:nil :print-str :format} msg-type)]} + `(let [;;; Support [level & log-args], [config level & log-args] sigs: + s1# ~s1 + default-config?# (or (keyword? s1#) (nil? s1#)) + config# (if default-config?# @config s1#) + level# (if default-config?# s1# ~s2)] -(comment - (def compile-time-level :info) - (def compile-time-level nil) - (macroexpand-1 '(logging-enabled? :debug))) + (when (logging-enabled? level# config#) + (when-let [juxt-fn# (get-in (compile-config config#) + [:appenders-juxt level#])] + (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." - [message-fn level base-appender-args & log-args] - `(when (logging-enabled? ~level) - (when-let [juxt-fn# (@appenders-juxt-cache ~level)] - (let [[x1# & xn# :as xs#] (vector ~@log-args) - 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#) - (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. Takes optional logging config (defaults to + `timbre/@config`.)" + {:arglists '([level & message] [level throwable & message] + [config level & message] [config level throwable & message])} + [& sigs] `(log* {} :print-str ~@sigs)) -(defmacro log "Logs using print-style args." - {:arglists '([level & message] [level throwable & message])} - [level & sigs] `(log* print-str ~level {} ~@sigs)) - -(defmacro logf "Logs using format-style args." - {:arglists '([level fmt & fmt-args] [level throwable fmt & fmt-args])} - [level & sigs] `(log* format ~level {} ~@sigs)) +(defmacro logf + "Logs using format-style args. Takes optional logging config (defaults to + `timbre/@config`.)" + {:arglists '([level fmt & fmt-args] [level throwable fmt & fmt-args] + [config level fmt & fmt-args] [config level throwable fmt & fmt-args])} + [& sigs] `(log* {} :format ~@sigs)) (defmacro log-errors [& body] `(try ~@body (catch Throwable t# (error t#)))) (defmacro log-and-rethrow-errors [& body] @@ -414,18 +471,29 @@ [& sigs#] `(logf ~~level ~@sigs#))))) (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 (defn refer-timbre "Shorthand for: - (require '[taoensso.timbre :as timbre - :refer (trace debug info warn error fatal report spy with-log-level)])" + (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)])" [] - (require '[taoensso.timbre :as timbre - :refer (log trace debug info warn error fatal report spy with-log-level - logf tracef debugf infof warnf errorf fatalf reportf)])) + (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)])) ;;;; Deprecated @@ -437,6 +505,10 @@ {:arglists '([expr] [level expr] [level name expr])} [& 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 (comment @@ -450,15 +522,20 @@ (info "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] ["taoensso.timbre*"]) (info "foo" "bar") (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"))) - (spy (* 6 5 4 3 2 1)) - (spy :debug :factorial6 (* 6 5 4 3 2 1)) + (spy :info (* 6 5 4 3 2 1)) + (spy :info :factorial6 (* 6 5 4 3 2 1)) (info (Exception. "noes!") "bar") (spy (/ 4 0)) @@ -467,12 +544,22 @@ ;; Middleware (info {:name "Robert Paulson" :password "Super secret"}) - (set-config! - [:middleware] - [(fn [{:keys [hostname message] :as args}] - (cond (= hostname "filtered-host") nil ; Filter - (map? message) - (if (contains? message :password) - (assoc args :message (assoc message :password "*****")) - args) - :else args))])) + (set-config! [:middleware] []) + (set-config! [:middleware] + [(fn [{:keys [hostname message args] :as ap-args}] + (if (= hostname "filtered-host") nil ; Filter + (assoc ap-args :args + ;; Replace :password vals in any map args: + (mapv (fn [arg] (if-not (map? arg) arg + (if-not (contains? arg :password) arg + (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"))) diff --git a/src/taoensso/timbre/appenders/android.clj b/src/taoensso/timbre/appenders/android.clj new file mode 100644 index 0000000..fe91bf9 --- /dev/null +++ b/src/taoensso/timbre/appenders/android.clj @@ -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))))}) diff --git a/src/taoensso/timbre/appenders/carmine.clj b/src/taoensso/timbre/appenders/carmine.clj new file mode 100644 index 0000000..4aa787b --- /dev/null +++ b/src/taoensso/timbre/appenders/carmine.clj @@ -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))) diff --git a/src/taoensso/timbre/appenders/irc.clj b/src/taoensso/timbre/appenders/irc.clj index 90aae2d..d4b2993 100644 --- a/src/taoensso/timbre/appenders/irc.clj +++ b/src/taoensso/timbre/appenders/irc.clj @@ -41,6 +41,6 @@ "Needs :irc config map in :shared-appender-config, e.g.: {:host \"irc.example.org\" :port 6667 :nick \"logger\" :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)) - :fn appender-fn}) \ No newline at end of file + :fn appender-fn}) diff --git a/src/taoensso/timbre/appenders/mongo.clj b/src/taoensso/timbre/appenders/mongo.clj index ef9db88..bde6431 100644 --- a/src/taoensso/timbre/appenders/mongo.clj +++ b/src/taoensso/timbre/appenders/mongo.clj @@ -42,5 +42,5 @@ :server {:host \"127.0.0.1\" :port 27017}}") :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}) diff --git a/src/taoensso/timbre/appenders/postal.clj b/src/taoensso/timbre/appenders/postal.clj index a51136e..c8a89eb 100644 --- a/src/taoensso/timbre/appenders/postal.clj +++ b/src/taoensso/timbre/appenders/postal.clj @@ -1,23 +1,47 @@ (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"} (:require [clojure.string :as str] [postal.core :as postal] [taoensso.timbre :as timbre])) -(def postal-appender - {:doc (str "Sends an email using com.draines/postal.\n" - "Needs :postal config map in :shared-appender-config, e.g.: - ^{:host \"mail.isp.net\" :user \"jsmith\" :pass \"sekrat!!1\"} - {:from \"Bob's logger \" :to \"foo@example.com\"}") - :min-level :error :enabled? true :async? true - :limit-per-msecs (* 1000 60 10) ; 1 subject / 10 mins - :fn (fn [{:keys [ap-config prefix throwable args]}] - (when-let [postal-config (:postal ap-config)] - (let [[subject & body] args] - (postal/send-message - (assoc postal-config - ;; TODO Better to just use trunc'd message as subject? - :subject (str prefix " - " (or subject throwable)) - :body (str (str/join \space body) - (timbre/stacktrace throwable "\n")))))))}) +(defn- str-trunc [^String s max-len] + (if (<= (.length s) max-len) s + (.substring s 0 max-len))) + +(comment (str-trunc "Hello this is a long string" 5)) + +(defn make-postal-appender + "Returns a Postal email appender. + A Postal config map can be provided here as an argument, or as a :postal key + in :shared-appender-config. + + (make-postal-appender {:enabled? true} + {:postal-config + ^{:host \"mail.isp.net\" :user \"jsmith\" :pass \"sekrat!!1\"} + {:from \"Bob's logger \" :to \"foo@example.com\"}})" + [& [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)) diff --git a/src/taoensso/timbre/appenders/rotor.clj b/src/taoensso/timbre/appenders/rotor.clj index 7193622..722dfc7 100644 --- a/src/taoensso/timbre/appenders/rotor.clj +++ b/src/taoensso/timbre/appenders/rotor.clj @@ -1,8 +1,8 @@ (ns taoensso.timbre.appenders.rotor + {:author "Yutaka Matsubara"} (:import [java.io File FilenameFilter]) (:require - [clj-stacktrace.repl :as stacktrace] [clojure.java.io :as io] [taoensso.timbre :as t])) @@ -75,6 +75,4 @@ :backlog 5}") :min-level nil :enabled? true - :async? false - :limit-per-msecs nil :fn appender-fn}) diff --git a/src/taoensso/timbre/appenders/socket.clj b/src/taoensso/timbre/appenders/socket.clj index 6bf3668..60443af 100644 --- a/src/taoensso/timbre/appenders/socket.clj +++ b/src/taoensso/timbre/appenders/socket.clj @@ -44,6 +44,5 @@ "Needs :socket config map in :shared-appender-config, e.g.: {:listen-addr :all :port 9000}") - :min-level :trace :enabled? true :async? false - :max-message-per-msecs nil ; no rate limit by default + :min-level :trace :enabled? true :fn appender-fn}) diff --git a/src/taoensso/timbre/frequencies.clj b/src/taoensso/timbre/frequencies.clj deleted file mode 100644 index 01aa90d..0000000 --- a/src/taoensso/timbre/frequencies.clj +++ /dev/null @@ -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]))))))) diff --git a/src/taoensso/timbre/profiling.clj b/src/taoensso/timbre/profiling.clj index 72649cc..eaf43fc 100644 --- a/src/taoensso/timbre/profiling.clj +++ b/src/taoensso/timbre/profiling.clj @@ -41,16 +41,17 @@ [level name & body] `(let [{result# :result stats# :stats} (with-pdata ~level ~@body)] (when stats# - (timbre/log* print-str ~level {:profile-stats stats#} - (str "Profiling " (utils/fq-keyword ~name)) - (str "\n" (format-pdata stats#)))) + (timbre/log* {:profile-stats stats#} :format ~level + "Profiling: %s\n%s" (utils/fq-keyword ~name) + (format-pdata stats#))) result#)) (defmacro sampling-profile - "Like `profile`, but only enables profiling every 1/`proportion` calls." - [level proportion name & body] - `(if-not (> ~proportion (rand)) (do ~@body) - (profile ~level ~name ~@body))) + "Like `profile`, but only enables profiling with given probability." + [level probability name & body] + `(do (assert (<= 0 ~probability 1) "Probability: 0<=p<=1") + (if-not (< (rand) ~probability) (do ~@body) + (profile ~level ~name ~@body)))) (defn pdata-stats "{::pname [time1 time2 ...] ...} => {::pname {:min ...} ...} @@ -62,8 +63,8 @@ (let [count (max 1 (count times)) time (reduce + times) mean (long (/ time count)) - mad (long (/ (reduce + (mapv #(Math/abs (long (- % mean))) - times)) ; Mean absolute deviation + mad (long (/ (reduce + (map #(Math/abs (long (- % mean))) + times)) ; Mean absolute deviation count))] (assoc m pname {:count count :min (apply min times) @@ -75,10 +76,10 @@ (defn format-pdata [stats & [sort-field]] (let [clock-time (-> stats ::clock-time :time) ; How long entire profile body took - stats (dissoc stats ::clock-time) - accounted (reduce + (mapv :time (vals stats))) - max-name-width (apply max (mapv (comp count str) - (conj (keys stats) "Accounted Time"))) + stats (dissoc stats ::clock-time) + accounted (reduce + (map :time (vals stats))) + max-name-width (apply max (map (comp count str) + (conj (keys stats) "Accounted Time"))) pattern (str "%" max-name-width "s %6d %9s %10s %9s %9s %7d %1s%n") s-pattern (.replace pattern \d \s) perc #(Math/round (/ %1 %2 0.01)) diff --git a/src/taoensso/timbre/tools/logging.clj b/src/taoensso/timbre/tools/logging.clj index fea6601..4ee1fff 100644 --- a/src/taoensso/timbre/tools/logging.clj +++ b/src/taoensso/timbre/tools/logging.clj @@ -1,6 +1,7 @@ (ns taoensso.timbre.tools.logging "clojure.tools.logging.impl/Logger implementation" - (:require [taoensso.timbre :as timbre])) + (:require [clojure.tools.logging] + [taoensso.timbre :as timbre])) (deftype Logger [logger-ns] clojure.tools.logging.impl/Logger @@ -9,8 +10,8 @@ ;; tools.logging message may be a string (for `logp`/`logf` calls) or raw ;; argument (for `log` calls). Note that without an :args equivalent for ;; `write!`, the best we can do is `[message]`. This inconsistency means - ;; that :args consumers (like the rate limiter and Postal appender) will - ;; necessarily behave differently under tools.logging. + ;; that :args consumers will necessarily behave differently under + ;; tools.logging. (timbre/send-to-appenders! level {} [message] logger-ns throwable (when (string? message) message)))) diff --git a/src/taoensso/timbre/utils.clj b/src/taoensso/timbre/utils.clj index 9c34adf..fd51214 100644 --- a/src/taoensso/timbre/utils.clj +++ b/src/taoensso/timbre/utils.clj @@ -10,20 +10,61 @@ (let [[name [expr]] (macro/name-with-attributes name sigs)] `(clojure.core/defonce ~name ~expr))) -(defn memoize-ttl - "Like `memoize` but invalidates the cache for a set of arguments after TTL - msecs has elapsed." +(defn memoize-ttl "Low-overhead, common-case `memoize*`." [ttl-ms f] (let [cache (atom {})] (fn [& args] - (let [{:keys [time-cached d-result]} (@cache args) - now (System/currentTimeMillis)] + (when (<= (rand) 0.001) ; GC + (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)) - @d-result - (let [d-result (delay (apply f args))] - (swap! cache assoc args {:time-cached now :d-result d-result}) - @d-result)))))) +(defn rate-limiter + "Returns a `(fn [& [id]])` that returns either `nil` (limit okay) or number of + msecs until next rate limit window (rate limited)." + [ncalls-limit window-ms] + (let [state (atom [nil {}])] ; [ { {[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 "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}}}} {:a {:b {:g :G :c {:c {:f :F}}}}})) -(defn round-to - "Rounds argument to given number of decimal places." +(defn round-to "Rounds argument to given number of decimal places." [places x] (if (zero? places) (Math/round (double x)) @@ -56,11 +96,14 @@ (comment (round-to 0 10) (round-to 2 10.123)) -(defmacro fq-keyword - "Returns namespaced keyword for given name." +(defmacro fq-keyword "Returns namespaced keyword for given name." [name] - `(if (and (keyword? ~name) (namespace ~name)) - ~name + `(if (and (keyword? ~name) (namespace ~name)) ~name (keyword (str ~*ns*) (clojure.core/name ~name)))) (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)))