Support clojure.tools.logging's debugf, infof, warnf, etc.

[Josh-Tilles]

What do you think about providing equivalents to the standard logging-level fns that automatically do formatting?

At least SOME kind of interpolation would be useful. Right now, I have a bunch of logging expressions in a codebase that are all like (debug (format …message and values to record…)).

[ptaoussanis]

Hi,

Sorry for the delay replying - was travelling the past few weeks. Working through a backlog now, will try get back to you in a couple days!

[ptaoussanis]

Okay, I'd like a little time to think about this if possible - it's not entirely obvious what the best way of implementing this would be since the current log fns are already variadic.

In most cases any extra args are just concatenated into an output string - is there a particular reason you're not happy with that approach?

E.g. (info "User logged in" user-name), etc.

[ataggart]

Alternately, you could just provide an implementation of clojure.tools.logging.impl.LoggerFactory protocol, and then everyone could just call the functions and macros that clojure.tools.logging provides. No need to duplicate everything.

[ptaoussanis]

Hi Alexander,

Alternately, you could just provide an implementation of clojure.tools.logging.impl.LoggerFactory protocol, and then everyone could just call the functions and macros that clojure.tools.logging provides. No need to duplicate everything.

I'm not a big fan of this idea to be honest. There are some significant differences between the tools.logging and Timbre APIs, particularly on the config side. Appender caching, namespace filtering, middleware, rate limiting, etc.: these are all relatively performant and simple with Timbre's current implementation. Trying to patch over the differences between tools.logging and Timbre would require sacrifices for not much inherent benefit from what I can tell (?).

If there's a good reason to provide logp/logf utils, that's something I'm inclined to say would probably be better implemented natively. I'm still open to comment on the usefulness of these utils btw.

Cheers! :-)

[ptaoussanis]

Edited my last comment for unintended abruptness :-)

[ataggart]

clojure.tools.logging intentionally doesn't have a "config side", everything config-related is left to whatever implementation one uses, be it log4j, etc., or timbre.

The most common request I've received is some way to change the logging config from inside the repl, and I've pushed back on it precisely because config is outside the scope of the library. It'd be difficult to make a common api that was both useful and worked consistently across the known logging implementations, which can have pretty complex config rules, multiple appenders, etc. I would welcome a repl-compatible logging implementation.

Notice that nothing in clojure.tools.logging is specific to java-based logging implementations, other than that clojure.tools.logging.impl provides protocol implementations that wrap some known ones; nor does it do any actual logging itself. The lib is essentially an implementation-agnostic api that leverages some clojure-specific features:

• using the current *ns* as the logging namespace by default
• macros to delay execution of messages until they are needed
• convenience features like with-logs, log-capture!
• awareness of the STM
• protocols that are called by the core api to do the real logging work
• some predefined protocol implementations

I strongly encourage you to try to provide a new protocol implementation for clojure.tools.logging simply because if you can't, then the library isn't doing what it's supposed to and I need to fix it. ;)

[ataggart]

BTW, here's a (entirely untested) snippet of code I cobbled together from what you're doing inside log*:

(deftype Logger [logger-ns]
  clojure.tools.logging.impl/Logger
  (enabled? [_ level]
    (logging-enabled? level))
  (write! [_ level throwable message]
    (when-let [appenders (@appenders-juxt-cache level)]
      (appenders {:level level
                  :error? (error-level? level)
                  :instant (Date.)
                  :ns logger-ns
                  :message message
                  :more (when throwable
                          (str "\nStacktrace:\n"
                               (stacktrace/pst-str throwable)))}))))

(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))))

Calling (use-timbre) results in the entire clojure.tools.logging api using timbre as the backing implementation.

[ptaoussanis]

Hi Alexander, thanks for your input - will try get back to you properly in a day or two!

[ptaoussanis]

Hey, sorry about the crazy delay replying to this - ended up coming down with a flu that's had me completely out of action.

Appreciate the clarification on the role of tools.logging here (and for the example!): was clearly making some faulty assumptions :-)

Will definitely try get a clojure.tools.logging.impl/Logger implementation going. Going to experiment a little tonight - will report back to you when I have something to report.

As an aside, thank you for all your awesome work on tools.logging!

[ptaoussanis]

Okay, looks like it should be possible to add both tools.logging support and logf-style loggers. On first examination it seems the best way of doing this will require a breaking change to custom appenders. It's a minor break and corrects something else I was already unhappy with (the :more appender argument) - but want to take some time to think about options and experiment.

The biggest issue I can see will be the difference in the way tools.logging and Timbre appenders receive arguments for logging. tools.logging joins arguments as a single message string before dispatch to appenders. Timbre has historically dispatched the unjoined arguments and allowed appenders to make their own choice about if+how to join.

In most cases this difference is relatively inconsequential, and I'm inclined to match tools.logging's behavior here since it does allow the logp/logf convenience.

My current thinking is to provide the following args to appenders:

• :throwable
• :log-args ; a vector of unjoined args as supplied to the logging fn
• :message ; a pre-joined string (logp/logf style as appropriate) as in tools.logging

Where we hit a problem is in the cases where Timbre actually makes use of the unjoined arguments. For example, both the rate limiter middleware and email appender treat the first logging argument specially (as the hash argument and email subject respectively).

There are also cases (e.g. logging to database) where it's useful for appenders to receive the unjoined arguments. tools.logging doesn`t seem to support this pattern (?), so it's a little unclear what the best way would be to try smooth over the difference.

Will keep thinking about this and experimenting. Would of course also be very happy to get your input if you have any.

Cheers!

[ptaoussanis]

There's an experimental work-in-progress on the dev branch for review: https://github.com/ptaoussanis/timbre/commits/dev

Relevant excerpts (as of the current commit):

(defmacro log*
  "Prepares given arguments for, and then dispatches to all level-relevant
  appender-fns."

  ;; For tools.logging.impl/Logger support
  ([base-appender-args level log-vargs ns throwable message juxt-fn]
     `(when-let [juxt-fn# (or ~juxt-fn (@appenders-juxt-cache ~level))]
        (juxt-fn#
         (conj (or ~base-appender-args {})
           {:instant   (Date.)
            :ns        ~ns
            :level     ~level
            :error?    (error-level? ~level)
            :log-args  ~log-vargs ; NB: no tools.logging support (?)
            :throwable ~throwable
            :message   ~message}))
        true))

  ([base-appender-args level log-args message-fn]
     `(when-let [juxt-fn# (@appenders-juxt-cache ~level)]
        (let [log-vargs# (vector ~@log-args)
              [x1# & xn# :as xs#] log-vargs#
              has-throwable?# (and xn# (instance? Throwable x1#))]
          (log* ~base-appender-args
                ~level
                log-vargs#
                ~(str *ns*)
                (when has-throwable?# x1#)
                (if has-throwable?#
                  (apply ~message-fn xn#)
                  (apply ~message-fn xs#))
                juxt-fn#)))))

(defmacro logp
  "When logging is enabled, actually logs given arguments with level-relevant
  appender-fns using print-style args."
  {: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 args."
  {:arglists '([level fmt & fmt-args] [level throwable fmt & fmt-args])}
  [level & sigs]
  `(when (logging-enabled? ~level)
     (log* {} ~level ~sigs format)))

and

(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]
    (timbre/log* {} level [message] ; TODO Better alternatives?
     logger-ns throwable 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))))

[ataggart]

Just a quick note about the message, it is a single value, but it does not need to be limited to a string. If an appender knows how to persist, say, a map of values, then it can do so when passed one as a message. I think Sean Corfield is doing something with custom appenders for known message objects and pushing them into a database.

[ptaoussanis]

it is a single value, but it does not need to be limited to a string.

Just to clarify: this is true only for log, not logp or logf - is that correct?

[ataggart]

It's true for impl.Logger/write!, which is what matters regarding implementation appenders. But yes, logf and logp are convenience layers for creating a string message.

[ptaoussanis]

@MerelyAPseudonym Timbre 2.0.0-SNAPSHOT is now on Clojars and offers log(p)/logf and info(p)/info(f)-style logging commands along with experimental tools.logging support.

@ataggart Barring any better suggestions, the current implementation is semi-compatible with tools.logging, diverging only in the way multiple/non-string arguments are represented to appenders:

(timbre/logp :info "a")        ; {:message "a" :args ["a"]} goes to appenders
(tools.logging/logp :info "a") ; {:message "a" :args ["a"]} goes to appenders

;; :args necessarily differs
(timbre/logp :info "a" "b" "c")        ; {:message "a b c" :args ["a" "b" "c"]} goes to appenders
(tools.logging/logp :info "a" "b" "c") ; {:message "a b c" :args ["a b c"]} goes to appenders

(timbre/log :info {})        ; {:message nil :args [{}]} goes to appenders
(tools.logging/log :info {}) ; {:message nil :args [{}]} goes to appenders

;; :message differs
(timbre/log :info "a")        ; {:message nil  :args ["a"]} goes to appenders
(tools.logging/log :info "a") ; {:message "a" :args ["a"]} goes to appenders

;; API incompatibility
(timbre/log :info {} {} {})        ; {:message nil :args [{} {} {}]} goes to appenders
(tools.logging/log :info {} {} {}) ; not possible

The only one I see as problematic is the 2nd example since it prevents arg-sensitive features like the rate limiter and email appender from working the same way between Timbre and Timbre-via-tools.logging.

In any case, some compatibility is nicer than no compatibility and am in no rush to make any decisions about this so still going to take time to think about + experiment. Feedback welcome.

Cheers!

[ptaoussanis]

Okay, have decided to go ahead cut a 2.0.0 release with the changes as they currently stand. Thanks again for your input!

[Josh-Tilles]

Oh my gosh, I apologize for not contributing/following up! (I had been experimenting Gmail filters and hadn't noticed all the updates to this issue)

Well, it doesn't seem like there's anything else that needs to be done. And @ptaoussanis, regarding your initial question (about whether it's good enough to just have the extra args concatenated): that probably would have been sufficient, but I didn't know about that functionality at the time. 😐

Thanks for incorporating this feature request, and I'm happy that you see that you feel like the codebase has improved as a result.

[ptaoussanis]

@MerelyAPseudonym No problem, am happy with the outcome either way :-)