BREAKING: Refactor Timbre for integration with clojure.tools.logging & logf macros

BREAKING CHANGES:
* Custom appenders that rely on the :more argument will no longer function correctly.
* Stacktraces are no longer automatically generated at the `log`-macro level, but are
left as an appender implementation detail. A :throwable appender argument has been added
along with a `stacktrace` fn.

MIGRATION GUIDE:
* :message is now a string of all arguments as joined by `logp`/`logf`. Appenders that
need unjoined logging arguments (i.e. raw arguments as given to `logp`/`logf`) should
use the new :log-args vector.

MOTIVATION:
The :more argument was always kind of manky.

By joining logging arguments at the `log`-macro level, we simplify appender
implementations and allow the use of different joining strategies like `logp` and
`logf`.

This approach also fits better with the `tools.logging` API, allowing a cleaner
Logger implementation.

README.md

@@ -6,9 +6,7 @@ Current [semantic](http://semver.org/) version:
 
 # 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*. [tools.logging](https://github.com/clojure/tools.logging) helps, but it doesn't save you from the mess of logger dependencies and configuration hell.
+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!
-
-Timbre is an attempt to make **simple logging simple** and more **complex logging reasonable**. No XML!
 
 ## What's In The Box?
  * Small, uncomplicated **all-Clojure** library.
@@ -18,6 +16,7 @@ Timbre is an attempt to make **simple logging simple** and more **complex loggin
  * 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).
  * Dead-simple, logging-level-aware **logging profiler**.
 
 ## Getting Started
@@ -171,9 +170,9 @@ Writing a custom appender is dead-easy:
   :enabled?  true
   :async?    false
   :limit-per-msecs nil ; No rate limit
-  :fn (fn [{:keys [ap-config level prefix message more] :as args}]
+  :fn (fn [{:keys [ap-config level prefix throwable message] :as args}]
         (when-not (:my-production-mode? ap-config)
-          (apply println prefix "Hello world!" message more)))
+          (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.

src/taoensso/timbre.clj

@@ -38,6 +38,10 @@
   "Evaluates body with *err* bound to *out*."
   [& body] `(binding [*err* *out*] ~@body))
 
+(defn stacktrace [throwable & [separator]]
+  (when throwable
+    (str (when-let [s separator] s) (stacktrace/pst-str throwable))))
+
 ;;;; Default configuration and appenders
 
 (utils/defonce* config
@@ -48,10 +52,12 @@
         :doc, :min-level, :enabled?, :async?, :limit-per-msecs, :fn
 
       An appender's fn takes a single map argument with keys:
-        :level, :message, :more ; From all logging macros (`info`, etc.)
+        :level, :throwable
-        :profiling-stats        ; From `profile` macro
+        :message,        ; Stringified logging macro args, or nil
-        :ap-config              ; `shared-appender-config`
+        :args,           ; Raw logging macro args (`info`, etc.)
-        :prefix                 ; Output of `prefix-fn`
+        :ap-config       ; `shared-appender-config`
+        :prefix          ; Output of `prefix-fn`
+        :profiling-stats ; From `profile` macro
         And also: :instant, :timestamp, :hostname, :ns, :error?
 
     MIDDLEWARE
@@ -89,18 +95,19 @@
          {: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 message more]}]
+           :fn (fn [{:keys [error? prefix throwable message]}]
                  (binding [*out* (if error? *err* *out*)]
-                   (apply str-println prefix "-" message more)))}
+                   (str-println prefix "-" message (stacktrace throwable))))}
 
           :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 message more]}]
+           :fn (fn [{:keys [ap-config prefix throwable message]}]
                  (when-let [filename (:spit-filename ap-config)]
                    (try (spit filename
-                              (with-out-str (apply str-println prefix "-"
+                              (with-out-str
-                                                   message more))
+                                (str-println prefix "-" message
+                                             (stacktrace throwable)))
                               :append true)
                         (catch java.io.IOException _))))}}}))
 
@@ -137,6 +144,7 @@
      apfn
 
      ;; Per-appender prefix-fn support (cmp. default prefix-fn)
+     ;; TODO Currently undocumented, candidate for removal
      ((fn [apfn]
         (if-not prefix-fn
           apfn
@@ -148,30 +156,23 @@
      ((fn [apfn]
         (if-not limit-per-msecs
           apfn
-          (let [;; {:hash last-appended-time-msecs ...}
+          (let [timers (atom {})] ; {:hash last-appended-time-msecs ...}
-                flood-timers (atom {})]
+            (fn [{ns :ns [x1 & _] :args :as apfn-args}]
-
-            (fn [{:keys [ns message] :as apfn-args}]
               (let [now    (System/currentTimeMillis)
-                    hash   (str ns "/" message)
+                    hash   (str ns "/" x1)
-                    allow? (fn [last-msecs]
+                    limit? (fn [last-msecs]
-                             (or (not last-msecs)
+                             (and last-msecs (<= (- now last-msecs)
-                                 (> (- now last-msecs) limit-per-msecs)))]
+                                                 limit-per-msecs)))]
 
-                (when (allow? (@flood-timers hash))
+                (when-not (limit? (@timers hash))
                   (apfn apfn-args)
-                  (swap! flood-timers assoc hash now))
+                  (swap! timers assoc hash now))
 
-                ;; Occassionally garbage-collect all expired timers. Note
+                (when (< (rand) 0.001) ; Occasionally garbage collect
-                ;; that due to snapshotting, garbage-collection can cause
+                  (when-let [expired-timers (->> (keys @timers)
-                ;; some appenders to re-append prematurely.
+                                                 (remove #(limit? (@timers %)))
-                (when (< (rand) 0.001)
+                                                 (seq))]
-                  (let [timers-snapshot @flood-timers
+                    (apply swap! timers dissoc expired-timers)))))))))
-                        expired-timers
-                        (->> (keys timers-snapshot)
-                             (filter #(allow? (timers-snapshot %))))]
-                    (when (seq expired-timers)
-                      (apply swap! flood-timers dissoc expired-timers))))))))))
 
      ;; Async (agent) support
      ((fn [apfn]
@@ -303,37 +304,60 @@
   [level] (and (sufficient-level? level) (@ns-filter-cache *ns*)))
 
 (defmacro log*
-  "Prepares given arguments for, and then dispatches to all level-relevant
+  "Implementation detail - subject to change..
-  appender-fns."
+  Prepares given arguments for, and then dispatches to all level-relevant
-  [level base-args & sigs]
+  appender-fns. "
-  `(when-let [juxt-fn# (@appenders-juxt-cache ~level)] ; Any relevant appenders?
-     (let [[x1# & xs#] (list ~@sigs)
 
-           has-throwable?# (instance? Throwable x1#)
+  ;; For tools.logging.impl/Logger support
-           appender-args#
+  ([base-appender-args level log-vargs ns throwable message juxt-fn]
-           (conj
+     `(when-let [juxt-fn# (or ~juxt-fn (@appenders-juxt-cache ~level))]
-            ~base-args ; Allow flexibility to inject exta args
+        (juxt-fn#
-            {:level   ~level
+         (conj (or ~base-appender-args {})
-             :error?  (error-level? ~level)
+           {:instant   (Date.)
-             :instant (Date.)
+            :ns        ~ns
-             :ns      ~(str *ns*)
+            :level     ~level
-             :message (if has-throwable?# (or (first xs#) x1#) x1#)
+            :error?    (error-level? ~level)
-             :more    (if has-throwable?#
+            :args      ~log-vargs ; No native tools.logging support
-                        (conj (vec (rest xs#))
+            :throwable ~throwable
-                              (str "\nStacktrace:\n"
+            :message   ~message}))
-                                   (stacktrace/pst-str x1#)))
+        true))
-                        (vec xs#))})]
 
-       (juxt-fn# appender-args#)
+  ([base-appender-args level log-args message-fn]
-       nil)))
+     `(when-let [juxt-fn# (@appenders-juxt-cache ~level)]
+        (let [[x1# & xn# :as xs#] (vector ~@log-args)
+              has-throwable?# (and xn# (instance? Throwable x1#))
+              log-vargs# (vec (if has-throwable?# xn# xs#))]
+          (log* ~base-appender-args
+                ~level
+                log-vargs#
+                ~(str *ns*)
+                (when has-throwable?# x1#)
+                (when-let [mf# ~message-fn] (apply mf# log-vargs#))
+                juxt-fn#)))))
 
 (defmacro log
   "When logging is enabled, actually logs given arguments with level-relevant
-  appender-fns. Generic form of standard level-loggers (trace, info, etc.)."
+  appender-fns."
-  {:arglists '([level message & more] [level throwable message & more])}
+  {:arglists '([level & args] [level throwable & args])}
   [level & sigs]
   `(when (logging-enabled? ~level)
-     (log* ~level {} ~@sigs)))
+     (log* {} ~level ~sigs nil)))
+
+(defmacro logp
+  "When logging is enabled, actually logs given arguments with level-relevant
+  appender-fns using print-style :message."
+  {:arglists '([level & message] [level throwable & message])}
+  [level & sigs]
+  `(when (logging-enabled? ~level)
+     (log* {} ~level ~sigs print-str)))
+
+(defmacro logf
+  "When logging is enabled, actually logs given arguments with level-relevant
+  appender-fns using format-style :message."
+  {:arglists '([level fmt & fmt-args] [level throwable fmt & fmt-args])}
+  [level & sigs]
+  `(when (logging-enabled? ~level)
+     (log* {} ~level ~sigs format)))
 
 (defmacro spy
   "Evaluates named expression and logs its result. Always returns the result.
@@ -342,9 +366,9 @@
   ([level expr] `(spy ~level '~expr ~expr))
   ([level name expr]
      `(try
-        (let [result# ~expr] (log ~level ~name result#) result#)
+        (let [result# ~expr] (logp ~level ~name result#) result#)
         (catch Exception e#
-          (log ~level '~expr (str "\n" (stacktrace/pst-str e#)))
+          (logp ~level '~expr (str "\n" (stacktrace/pst-str e#)))
           (throw e#)))))
 
 (defmacro s ; Alias
@@ -353,14 +377,19 @@
 
 (defmacro ^:private def-logger [level]
   (let [level-name (name level)]
-    `(defmacro ~(symbol level-name)
+    `(do
-       ~(str "Log given arguments at " (str/capitalize level-name) " level.")
+       (defmacro ~(symbol level-name)
-       ~'{:arglists '([message & more] [throwable message & more])}
+         ~(str "Log given arguments at " level " level using print-style args.")
-       [& sigs#]
+         ~'{:arglists '([& message] [throwable & message])}
-       `(log ~~level ~@sigs#))))
+         [& sigs#] `(logp ~~level ~@sigs#))
 
-(defmacro ^:private def-loggers
+       (defmacro ~(symbol (str level-name "f"))
-  [] `(do ~@(map (fn [level] `(def-logger ~level)) ordered-levels)))
+         ~(str "Log given arguments at " level " level using format-style args.")
+         ~'{:arglists '([fmt & fmt-args] [throwable fmt & fmt-args])}
+         [& sigs#] `(logf ~~level ~@sigs#)))))
+
+(defmacro ^:private def-loggers []
+  `(do ~@(map (fn [level] `(def-logger ~level)) ordered-levels)))
 
 (def-loggers) ; Actually define a logger for each logging level
 
@@ -380,13 +409,15 @@
 ;;;; Dev/tests
 
 (comment
-  (log :fatal "arg1")
+  (info)
-  (log :debug "arg1" "arg2")
+  (info "a")
-  (log :debug (Exception.) "arg1" "arg2")
+  (info "a" "b" "c")
-  (log :debug (Exception.))
+  (info "a" (Exception. "b") "c")
-  (log :trace "arg1")
+  (info (Exception. "a") "b" "c")
+  (logp (or nil :info) "Booya")
 
-  (log (or nil :info) "Booya")
+  (info  "a%s" "b")
+  (infof "a%s" "b")
 
   (set-config! [:ns-blacklist] [])
   (set-config! [:ns-blacklist] ["taoensso.timbre*"])
@@ -410,4 +441,4 @@
             (if (contains? message :password)
               (assoc args :message (assoc message :password "*****"))
               args)
-            :else args))]))
+            :else args))]))

src/taoensso/timbre/appenders/irc.clj

@@ -20,19 +20,21 @@
 (defn ensure-conn [conf]
   (swap! conn #(or % (connect conf))))
 
-(defn send-message [{:keys [message prefix chan] :as config}]
+(defn send-message [{:keys [prefix throwable message chan] :as config}]
   (let [conn (ensure-conn config)
-        lines (str/split message #"\n")]
+        lines (-> (str message (timbre/stacktrace throwable "\n"))
+                  (str/split #"\n"))]
     (irclj/message conn chan prefix (first lines))
     (doseq [line (rest lines)]
       (irclj/message conn chan ">" line))))
 
-(defn appender-fn [{:keys [ap-config prefix message]}]
+(defn appender-fn [{:keys [ap-config prefix throwable message]}]
   (when-let [irc-config (:irc ap-config)]
     (send-message
      (assoc irc-config
-       :prefix prefix
+       :prefix    prefix
-       :message message))))
+       :throwable throwable
+       :message   message))))
 
 (def irc-appender
   {:doc (str "Sends IRC messages using irclj.\n"
@@ -41,4 +43,4 @@
               :name \"My Logger\" :chan \"#logs\"")
    :min-level :info :enabled? true :async? false :limit-per-msecs nil
    :prefix-fn (fn [{:keys [level]}] (-> level name str/upper-case))
-   :fn appender-fn})
+   :fn appender-fn})

src/taoensso/timbre/appenders/postal.clj

@@ -12,10 +12,11 @@
              {:from \"Bob's logger <me@draines.com>\" :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 message more]}]
+   :fn (fn [{:keys [ap-config prefix throwable args]}]
          (when-let [postal-config (:postal ap-config)]
-           (postal/send-message
+           (let [[subject & body] args]
-            (assoc postal-config
+             (postal/send-message
-              :subject (str prefix " - " message)
+              (assoc postal-config
-              :body    (if (seq more) (str/join " " more)
+                :subject (str prefix " - " subject)
-                           "<no additional arguments>")))))})
+                :body    (str (str/join \space body)
+                              (timbre/stacktrace throwable "\n")))))))})

src/taoensso/timbre/frequencies.clj

@@ -28,10 +28,11 @@
   (let [name (utils/fq-keyword name)]
     `(let [{result# :result stats# :stats} (with-fdata ~level ~@body)]
        (when stats#
-         (timbre/log* ~level
+         (timbre/log* {:frequency-stats stats#}
-                      {:frequency-stats stats#}
+                      ~level
-                      (str "Frequencies " ~name)
+                      [(str "Frequencies " ~name)
-                      (str "\n" (format-fdata stats#))))
+                       (str "\n" (format-fdata stats#))]
+                      print-str))
        result#)))
 
 (defmacro sampling-log-frequencies

src/taoensso/timbre/profiling.clj

@@ -29,10 +29,11 @@
   (let [name (utils/fq-keyword name)]
     `(let [{result# :result stats# :stats} (with-pdata ~level ~@body)]
        (when stats#
-         (timbre/log* ~level
+         (timbre/log* {:profile-stats stats#}
-                      {:profile-stats stats#}
+                      ~level
-                      (str "Profiling " ~name)
+                      [(str "Profiling " ~name)
-                      (str "\n" (format-pdata stats#))))
+                       (str "\n" (format-pdata stats#))]
+                      print-str))
        result#)))
 
 (defmacro sampling-profile

src/taoensso/timbre/tools/logging.clj

@@ -0,0 +1,24 @@
+(ns taoensso.timbre.tools.logging
+  "clojure.tools.logging.impl/Logger implementation"
+  (:require [taoensso.timbre :as timbre]))
+
+(deftype Logger [logger-ns]
+  clojure.tools.logging.impl/Logger
+  (enabled? [_ level] (timbre/logging-enabled? level))
+  (write! [_ level throwable message]
+    ;; 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.
+    (timbre/log* {} level [message] logger-ns throwable
+      (when (string? message) message) nil)))
+
+(deftype LoggerFactory []
+  clojure.tools.logging.impl/LoggerFactory
+  (name [_] "Timbre")
+  (get-logger [_ logger-ns] (->Logger logger-ns)))
+
+(defn use-timbre []
+  (alter-var-root clojure.tools.logging/*logger-factory*
+                  (constantly (->LoggerFactory))))