Initialising timbre does not set the root timbre config binding

[RickMoynihan]

It looks like the duct timbre bindings don’t ever set the root timbre config by calling timbre/set-config!. This is state outside of integrant, but it means that you can’t redirect log4j/jul/etc loggers to the configuration specified in duct.

I’d suggest possibly adding a default key/value in the configuration for :set-config! true, with a that when set triggers the timbre/set-config! side effect when the loggers defmethod is called.

We should also want to capture the value before we do that, and roll it back to the default root binding when halt is called.

I’d imagine most of the time you’d want this behaviour; and if you don’t you could switch it off with :set-config! false.

I'd suggest using the name :set-config! as it's the name of the timbre function for setting the root binding on the *config* var.

[weavejester]

but it means that you can’t redirect log4j/jul/etc loggers to the configuration specified in duct

Can you explain this in a little more detail? What's your specific use-case?

[RickMoynihan]

Sure, basically my app has some dependencies that log with different java logging frameworks (log4j & java.util.logging) and I'd like to configure these to use the configuration we set in duct.

In timbre you can do this by setting timbre as a logging backend to SLF4j by including slf4j-timbre as a dependency and then including the various facade implementations to the other backends:

[org.slf4j/log4j-over-slf4j "1.7.14"]
[org.slf4j/jul-to-slf4j "1.7.14"]
[org.slf4j/jcl-over-slf4j "1.7.14"]

These dependencies re-implement the various log libraries but redirect their logs back into SLF4j.

Anyway I basically wanted set this up also, but ran into a problem which is that logs sent through these frameworks don't pick up the duct config. My PR attempts to fix this by setting the duct logging config to be the root var binding, so these loggers can all see the same configuration.

It does make me think that it might be better for the log config to just trigger this effect on ig/init-keyand set the global taoenso.timbre/*config* that timbre defines.

This would mean users could just use the timbre library directly rather than the duct wrapping protocol.

i.e. we'd call taoenso.timbre/info instead of duct.logger/log.

The disadvantage is that it won't be an explicit referenced value in the system map, but the advantage is that logging will be available globally to all components, and that it will play well with timbre/slf4j and the rest of the java logging ecosystem. Additionally users will be able to use the richer timbre API rather than the duct wrapper. Philosophically it's an implicit global :-( but in practice I think most people want logging to be available everywhere without having to thread extra values through function arguments.

[weavejester]

Ideally we don't want to mix Duct log messages with log messages that follow arbitrary formats. The Duct logging system is data driven, and follows a specific format, so we don't want to end up with a log that's half data, half natural language, as it becomes more difficult to query.

Instead, what we probably want is something that wraps legacy logs. For example:

user=> (timbre/info "test")
17-07-26 22:54:00 localhost INFO [user:1] - :duct.logger.legacy/event "test"

Obviously not as good as an event that's data, but at least it ensures the format is consistent. We could probably achieve this by wrapping the appender.

I don't think we want to encourage use of Timbre directly, however. The Timbre API is richer, but in this case that's a disadvantage, since we want to set up a standardised stream of event data.

[RickMoynihan]

Yeah, I did think about that and planned to raise it as a query, as my java loggers are obviously a lot less structured.

As far as I know the data types that gets sent to java loggers tend to just be string data and the occaisional exception. Defining a legacy format for the appender to print these sounds like a good idea. Perhaps this should be done as another issue?

Returning to the questions I was trying to raise in my previous comment. It seems to me that it's sensible to essentially push the logger down into the timbre config global, which I think would remove the need for the duct TimbreLogger record altogether, or at least make it optional with duct.logger/log becoming just a function with the signature:

(defn log 
  ([level event] ,,,)
  ([level event data] ,,,))

If there's a compeling reason to keep the record around then we could provide the logger as an optional argument and use the global timbre one in the default case.

Returning to the differences between ducts logger and timbres though, it seems the only difference is that ducts forces a 2/3-arg signature of level event data, whilst timbres is level and then variadic.

Whilst not without its drawbacks you could implement this in the appender where the behaviour was like this:

(timbre/info "not-an-event-keyword") ;; :legacy-event "not-an-event-keyword"
(timbre/info :one-event :one-arg) ;; :one-event :one-arg
(timbre/info :event :odd :number :of-arguments) ;; :event [:odd :number :of-arguments]
(timbre/info :event :even :number :of :arguments) ;; :event {:even :number :of :arguments}

If we had the above would we require the duct log at all?

Anyway just throwing some ideas out there... curious what you think.

[weavejester]

The idea of having a string argument triggering a legacy event marker is a good one; but I'm afraid I don't like the idea of using the even/odd number of arguments to determine the type of the associated data.

I'm not certain about having a global logger. Because Integrant can inject the logger dependency into functions that might be nested fairly deeply, perhaps a global logger is not necessary.

I'm currently working on an application that uses Duct, so if there are problems with having a local logger, I should run into them eventually. I'd like to spend some more time using Duct in a real project before making a decision, to see whether a global logger is necessary in practice.

[RickMoynihan]

I really don't like the idea of odd/even arguments either and only intended all of the above as an option for wrapping legacy log data into a single value for your log format, though it seems timbre receives logs as data anyway in :vargs. For the sake of clarity in these issues, I'll continue discussion of the syntax/format of logs on ticket #3.

Returning to issue #1 and the global logger though, for me this is pretty important as I need to support legacy logs, ideally with a single config. It seems to me that timbre itself is intended to work this way, and that I'd wrongly assumed that logger.timbre was just a standard timbre logger with a small wrapper to configure it via duct.

I do question the need for duct to do things differently here and not just go with the grain of timbre, given all the interop advantages etc it brings to the table.

To summarise I think the last thing the ecosystem needs is another logger framework, so I think it would be worth duct.logger.timbre considering:

1. Providing integrant/duct-module init/halt support for initialising/reverting the global timbre/*config*.
2. Providing the more opinionated (duct.logger/log ::event data) interface you've defined (except make it use the global logger)
3. Providing an EDN appender by default, that prints logs as pure EDN data, and can sanely handle legacy java logs, raw timbre/log calls and of course duct format calls. See my comments on issue #3 for a proposal on this.

I think the above might mean the TimbreLogger record and duct Logger protocol become superfluous though as timbre is already pluggable thanks to SLF4j etc, so duct could just choose timbre for itself and provide log as a plain function. Users (or libraries) that used clojure.tools.logging for example could just use it and wire up the SLF4j dependencies and still receive any messages that duct logged via timbre.

Obviously your needs and wishes may be different from mine, but I think something along these lines would allow the maximum amount of flexibility and allow interop with the rest of the ecosystem, and also not lead to us reinventing the logging wheel.

[weavejester]

I certainly agree that we need to support legacy logging, and that using the set-config! global is necessary for that. When I said I wasn't certain about a global logger, I meant in the context of non-legacy logging. I was a little tired when I wrote it, so I don't think I was very clear.

Regarding legacy log support, what about adding some middleware to the global config to wrap logs in a legacy format:

(defn- duct-format? [vargs]
  (and (= (count vargs) 2)
       (keyword? (vargs 0))
       (namespace (vargs 0))))

(defn- legacy-data [{:keys [vargs output-fn] :as data}]
  (let [vargs [::message (if (= (count vargs) 1) (vargs 0) vargs)
        data  (assoc data :vargs vargs)]    
    (assoc data
           :_msg    (delay (pr-str vargs))
           :_output (delay (output-fn data)))))

(defn wrap-legacy [appender]
  (fn [{:keys [vargs] :as data}]
    (if (duct-format? vargs)
      (appender data)
      (appender (legacy-data data)))))

In this case, if we call a timbre logging function with the keyword + data format, it just passes it straight through, otherwise it wraps it. This would allow use of the Timbre logging functions directly, i.e. (timbre/info ::foo {:bar 1}) would work the same as (logger/log logger :info ::foo {:bar 1}).

What I'm not sure about is whether to encourage this as the default; I think I'd prefer to people to first reach for the Duct log macro. This ensures that the format is correct, and that any changes to Timbre in future can be isolated against. I'm not 100% comfortable with having Duct depend directly on Timbre with no indirection, but that said, I can certainly see an argument for it.

How does that sound?

[RickMoynihan]

Ok, looks like we're in agreement about how to handle legacy data as I've just been thinking we should do more or less exactly that (use a middleware that essentially does what the one you've pasted appears to do).

Still not convinced that logger/log needs to take a reference to the logger, though if there are compelling reasons to do it I could be convinced to make it optional.

Obviously passing it allows you to use a different logger to the global one, but I'm not sure that's often useful. Another reason not to pass it is that a common use case for loggers is basically print line debugging with spy etc... If you're doing this is someone elses code you really don't want to have to thread the logger through it.

I do see the utility of the log macro in encouraging the duct format, which is pretty neat; so I think the best thing is to provide it and encourage its use, but present it as being in addition to the timbre stuff. You can't stop users using the timbre one anyway, and I think they should be encouraged to use it if they need its features as it has neat tools like spy etc.

[weavejester]

Still not convinced that logger/log needs to take a reference to the logger, though if there are compelling reasons to do it I could be convinced to make it optional.

I look at this from the opposite direction; there need to be a compelling reason for the log macro not to take a local argument.

A thread-local binding might be useful, and could easily be applied to the handler through middleware. I'm somewhat worried that would make the two-argument form ambiguous, and would require some additional runtime logic (albeit just a keyword? check, which I guess isn't too onerous).

[RickMoynihan]

I look at this from the opposite direction; there need to be a compelling reason for the log macro not to take a local argument.

Usually I'd agree, but here I'm not so sure. At the minute there are only really two games in town when it comes to clojure logging frameworks. clojure.tools.logging and timbre, and I really hope we don't ever see a 3rd. Both of these make use of thread local bindings to the underlying configured logger. And both of these logging systems are already configurable in every way imaginable, and they can already interoperate with either one providing the backend/configuration.

Given that the duct log macro doesn't really do anything beyond provide some consistency in arguments it seems that there's not a lot of utility in letting you swap the duct Logger for another implementation. duct can just pick one, and use it as its interface in to the logging system. If the user or a library wants to use the other framework as their backend then they still can thanks to SLF4j.

I don't think this extra indirection is a big problem, but I think it might lead to extra complexity e.g. it might lead to there being two thread local vars where there only needs to be the one chosen by the backend logging framework. (I could be wrong but I'm assuming you meant adding a new dynamic var in to duct/logger.clj)

I'm not 100% comfortable with having Duct depend directly on Timbre with no indirection, but that said, I can certainly see an argument for it.

Yes logging is an unnecessarily complicated space and I appreciate engineering some insulation against it might be desirable; but as I said I'm not sure it does anything other than add a small amount of extra complexity. I could well be wrong but I think the logging frameworks should provide all the flexibility we need already, and I can't think of a reason to swap things at this level.

[weavejester]

It's not necessarily about supporting more logging systems. Primarily it's about isolating the logging appender used and placing it within the lifecycle of the system. For example, maybe the appender uses an open connection that we want to eventually close with halt!. By passing in the logger directly, we guarantee we're using the logger the system has set up, and that this logger is solely managed by the system.

If we're setting up a global logging configuration, then we're intentionally adding a leak in our abstraction in order for to achieve some convenience. If we're using a global logger that is mutable, we can't guarantee another thread or third-party function hasn't changed our logger. Sometimes convenience can be worth it; sometimes we want to choose "easy" over "simple". However, to my mind, such a concession needs to have a reasonable pay-off to be worth it, and I'm not convinced omitting an argument in the log macro is all that important.

There's also the question of testing. If we're testing in-process, then having a logger passed in as an explicit argument ensures that our tests don't generate spurious log messages, and allows us to test those log messages are actually made, and even to stub or mock the logger.

[RickMoynihan]

Yes they're definitely all considerations, however with logging the Java ecosystem has already settled on singleton global loggers and both timbre and c.t.l both encourage you to use the global one (as only their low level functions let you supply your own one).

I think your right to bring up simple vs easy, and suspect that's where our division lies. I think logging is somewhat an exception to the normal rules though, because it is a cross cutting concern, any function (and certainly any side-effecting code) could conceivably see a log statement at some point, so making that easy is a clear win. Even Haskell allows this trade off with Debug.Trace in pure functions.

I also think the simplicity ship sailed a long time ago on logging, and I think all we can hope for is to try and make it easier. We can't undo the global mechanism everyone else already uses, so we have to have either:

1. one global logger
2. a global logger and local loggers

Personally I think opting for just the global logger is better (and arguably simpler because we can't wish it away), it also aligns with the documentation and expectations of the existing logging ecosystem, and lets us just delegating the explaining of this to timbre.

So whilst I might not be siding on the simplicity of localised loggers, I am siding with user expectations about how logging works.

It's also worth bearing in mind that the ease factors with loggers will likely mean less errors with threading the logger throughout the code, no chance of null pointer exceptions when logging etc. Often logging is only added code when you have a bug, and in those situations it's pragmatic to make as few changes as possible, so you minimise your chance of breaking more things. I'd personally rather not have to refactor code I'm unfamiliar with just to add some log statements.

Regarding testing you can always swap the config with a binding, maybe not as nice as a local argument but really no big deal. It's not often that I want to test my log statements anyway.

[weavejester]

You're making the assumption that we have to have a global logger. In your case that may certainly be true, but so far I've yet to have a need to interface with legacy logging systems. In my case, I can just have local loggers, so you can understand my reticence to replace my local logging system with a global one, when I've yet to encounter any compelling reason to do so.

I do want to make allowances for people who are using tools that have global logging, and as you say, logging can be seen as an exception to the normal rules considering how pervasive it is. However, I don't want to force those who can or even want to use local logging, to switch over to a global logging system.

It may be that as I develop I'll hit roadblocks that mean that it makes sense to switch over to a global logging system, but I don't want to make that decision prematurely.

[RickMoynihan]

Just before reading your response I was thinking that it's actually not that big a deal, once PR #2 is merged I can just use timbre's interface, which is basically what I want.

I think it's fine for duct to support both options in this manner. Might it be worth including a discussion of each option in the README?!