Design question... log message callback

Questions & Help How to?
1

Over the past several years, I’ve adopted a log message callback strategy in most of my software. My idea is that I don’t want to pollute my library code with logging details or dependencies. So I implement a callback which the library code calls any time it wants to log a message.

The consumer of the library, defines the callback, and determines what to do with the log message. Forward it to an actual logging library, or ignore, etc. The comsumer is the one which imports the logging dependencies.

This strategy has worked well for my in other languages, C#, Python, Ruby, etc. Now I’m trying to implement it in Clojure. Each library or namepace can define its own callback. I didn’t really know how to implement this, so I asked ChatGPT-4o. This is what it suggested:

(ns my-library.clients.salesforce)

(def ^:private ^clojure.lang.Atom log-callback (atom nil))

(defn set-log-callback!
  [^clojure.lang.IFn callback]
  (reset! log-callback callback))

(defn- log-message
  [^clojure.lang.Keyword level ^String message ^clojure.lang.PersistentArrayMap data]
  (when-let [callback @log-callback]
    (callback level message data)))

;; ...

I’m using mount for my database, so it suggested I create something to set the loggers.

;; in my-library.core

;; Define a component that sets up logging callbacks for all namespaces
(mount/defstate logging-setup
  :start (do
           (salesforce/set-log-callback! salesforce-log-message)
           (servicenow/set-log-callback! servicenow-log-message))
  :stop  (do
           (salesforce/set-log-callback! nil)
           (servicenow/set-log-callback! nil)))

Does this make sense? Is the idomatic for Clojure?

2

First off, it isn’t idiomatic to provide type hints for everything like that. Type hints are intended to resolve reflection warnings around Java interop and are otherwise pretty much ignored – so it’s very weird to see type hints for things like Atom, IFn, and Keyword, etc since you would never need to use those.

Second, this feels very weirdly stateful and, since you have mutable state in every namespace that needs to log, it feels very imperative/procedural.

This might follow on from using Mount in the first place since it is essentially stateful and you’ll find plenty of people who dislike it to varying degrees.

Do you really want/need logging to behave differently across multiple packages? That seems like a strange requirement to me. Do you really want users to have to explicitly call a bunch of mutating “setters” at startup, once for each package, to have a consistent logging experience?

In Clojure, it’s more idiomatic to either:

  • pass everything through the call stack, including callbacks, or
  • use a dynamic var and have the caller use binding around code that needs the var bound to a particular value

However, even the latter is somewhat frowned on (especially, if it’s going to cause users of libraries to bind a whole bunch of dynamic vars to whatever is their chosen logging style).

Since Clojure is hosted on the JVM, libraries that actually do logging often defer to org.clojure/tools.logging which can be bound to any of the myriad underlying Java logging libraries – which can all be configured outside the program on a per-package basis if needed.

1 Like
3

I had no idea. I’ve been adding type hints to all my Clojure code and didn’t realize it’s for Java interop warnings. In Python I add type hints everywhere for mypy and figured Clojure did something similar. I’ll definitely stop using them in Clojure now.

I see. Are you more of a fan of stuartsierra/Component for the database and web server?

All of my stuff runs on Google Cloud, so I have custom code (Java interop) which does the structured logging. It’s custom because I have to include things like a resource type, log name, and I add extra information like source location details, http request details, tracking details (session, etc.).

I’m not sure there’s a way to achieve all of that via configuration. But I’ll look into it.

The log message callback was a way for me to allow the logging details to be changed later. Say if we moved to AWS instead of GCP. Only the place where the callback is defined would need to change.

On the other hand, I digress. I can see where just using org.clojure/tools.logging simplifies things and is more idiomatic…

Thank you for your feedback Sean. I appreciate it!

4

Yes, we use this very heavily at work. I like that you get a transparent, self-contained “system”, and you can easily have multiple instances as needed, with mock components as needed, without any changes to your non-test code (we have some specific tests where we spin up multiple “systems” in a single JVM so can test aspects of collaboration between them).

The dependencies are all explicit in your code: systems, or subsystems, are passed through the call tree (which makes it easier to test functions, since tests can control what those “system” components are). There’s no mutable state in namespaces or global vars.

A logging Component, as part of your “system” would allow for easily swapping it out consistently across any deployed service and would also allow for different behavior in tests for example. But you can get a long way with clojure.tools.logging since you could provide your own logger factory if you really needed something other than bridging to Java logging.

For development, I use VS Code / Calva + Portal, and I have clojure.tools.logging wired up in my REPL so all logging goes into Portal (as well as to the underlying logger).

5

I think Sean is on the money here. Logging in the JVM world is a bit of a mess and I also found it hard to find a solution I liked. Initially, I used timbre for all my logging, but didn’t like having a dependency on timbre for my libraries, which I wanted to make available to others who would likely have different logging preferences. I now use org.clojure/tools.logging in my libraries and just let the application using the lib determine what logging framework they want to use. I still sometimes use timbre at the app level, but recently, I’ve been using log4j2 more. Both are configured using an xml file, so I have the power I need and anyone using my lib can use whatever they want.

I also switched from using Component to Integrant to manage my system. I didn’t mind component, but something about integrant just clicks for me and so it is my current preference. Could be worth looking at as another alternative to mount.

6

At work we configure log4j2 with a properties file because we don’t want to deal with XML :slight_smile: and that was one of the things we really like about log4j2.

7

That is a good point. I must look at that myself as I’m no fan of XML. In fact, the only real reason I’m using it is because when I was working out how to use it, I found a simple example which was based on an XML config. Logging is one of those irritating requirements which everyone wants, but nobody wants to spend any real time on!

1 Like
8

Seancorfield mentioned dynamic variables. I don’t know if this is recommended in general. But it may be the answer you are looking for.

I experimented a bit with it. It would look like this:

(def ^:dynamic log-callback nil) ; Disable logging by default.

(defmacro log [message]
  `(if log-callback
     (let [fn-name# (-> (ex-info "" {})
                        Throwable->map :trace first first str (clojure.string/split #"\$") last)]
       (log-callback
        fn-name#
        (str fn-name# ": " ~message)))))

(defn foo []
  (log "Doing Foo."))

(defn bar []
  (log "Doing Bar."))

(defn example []
  (foo)  
  (bar)
  (println "Hello World!"))

(defn main []

  (println "Log nothing:")
  (example)
  (println "Log everything:")
  (binding [log-callback
            (fn [function message]
              (println message))]
    (example))
  (println "Log only bar:")
  (binding [log-callback
            (fn [function message]
              (if (= function "bar") (println message)))]
    (example))
  )

(main)

I looks very complicated. If you only want a simple mechanism for logging, you would not need the macro. Just defining a logging callback as (fn [message] nil) will work. But I wanted to show you a bit more what the benefit of dynamic variables is.

I must admit, I have never used such a mechanism in Clojure. I come from C++. That was the way how I did logging in C++. I have no idea if all this makes sense in Clojure. I personally don’t log so much in Clojure. If I want to investigate things, I use the REPL. Adding log messages for me looks like an extra effort just for the hypothetic case that in the future I could need them.

In case you want to implement a logging mechanism, what is important, that you don’t create the message in cases, where the logging is disabled. The solution that you proposed is very bad. Sorry for saying that! The problem is, that when you call the function log-message, then you have already created the message. Creating log messages is very expensive. Many people prefer to have hundreds or thousands of log messages in their code. Even if you have disabled the log-callback, these thousands and thousands of strings are created. You should not do that. When you making log-message a macro, you don’t have that problem. My solution is also not optimal. Of course you should not do premature optimisation. If it works, then good! But you quickly run into performance problems, so I just want to warn you in advance.

And my opinion about type hints in Python: Clojure and Python are dynamically typed languages. That is what made Python popular. If you use type hints you deny this. I see very often that people who don’t use types feel guilty of that. That is a wrong feeling. If you want types, please use languages that are statically typed! If you use types in Python, you forgo the benefits of Python. There is nothing wrong with statically typed languages. You cannot make a language grow with dynamic typing, see how happy everybody is and then change the whole language by introducing static typing. That is what many people nowadays try, when using type hints. But that step would destroy everything that made Clojure and Python good. Type hints were very controversial in Python.

9

This topic was automatically closed 182 days after the last reply. New replies are no longer allowed.