Using namespace as log originating class for JUL

Question

When using tools.logging and java.util.logging (JUL in short), by default we get logs prefixed like this:

Oct 23, 2023 2:14:47 PM clojure.tools.logging$eval3668$fn__3671 invoke

Notice that class and method name logged are something completely unhelpful.

The solution recommended by the tools.logging library is that the user should change log appender output format to not print out class and method and to print out the logger name, which is the Clojure namespace name.

That is a possible solution when the authors of the app doing the logging and the author of code that configures JUL are the same person, i.e. the logging is configured and done at app level.

Use Case

I would say that the far more common use case of tools.logging is the use by a library author, who doesn't know which logging solution the end user is using. And at the same time, the end user is unaware of this logging being present in their dependency tree. In this case someone builds a Clojure app and they might have a 100 dependencies. Suddenly they start getting messages as described above in their stderr.

They might want to:
- redirect that to a file
- suppress the messages
- want to know which dependency is generating them

All of these tasks require that the user recognizes that it's JUL logging they are looking at and then configuring the JUL to output logger name to find out the namespace which is doing the logging. They might also want to keep the format with the method name for any Java code they have.

Approach

Use LogRecord class to force classname to Clojure namespace. Example code:

(cond-> (doto (LogRecord. level# ~msg)
                      (.setLoggerName ~ns)
                      (.setMessage ~msg)
                      (.setParameters (object-array ~params))
                      (.setSourceClassName ~ns))
              ~e (doto (.setThrown ~e)))

Benefits

1. Replaces clojure.tools.logging$eval3668$fn__3671 invoke in output with my.lib.namespace. The former string has 0 informational value, the latter enables us to know where to look for the log statement performed.

2. Improves performance. If .setSourceClassName is called, then the logging system won't use reflection to determine caller class and method. That involves walking the stack trace and it's slow.

3. Even with default/no configuration of JUL it gives a hint about where to look for who is making all these messages in stderr, if user is not aware of this logging library/mechanism.

I can produce a PR to affect this change if needed.

Answer 1

I suspect something is wrong in your setup. I'm using Logback over SLF4J in my projects and the logger key in the format always outputs the right namespace. The JUL implementation of the c.t.l logger isn't that different.

Just to be absolutely certain, I created a very bare-bones project with just a single namespace:

(ns app.core
  (:require [clojure.tools.logging :as log]
            [clojure.tools.logging.impl :as log-impl]))

(defn -main []
  (System/setProperty "java.util.logging.SimpleFormatter.format"
                      "[%1$tF %1$tT] [%4$-7s] [%3$s] %5$s %n")
  (binding [log/*logger-factory* (log-impl/jul-factory)]
    (log/info "Hello")))

It depends only on org.clojure/tools.logging {:mvn/version "1.2.4"}.
When it's run with clj -M -m app.core, I see this in the console:

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
[2023-11-05 16:57:41] [INFO   ] [app.core] Hello

As you can see, the readable namespace name is there.

(That was just for a quick test and you shouldn't use c.t.l.impl like that of course. And probably set the format via an actual property or a properties file.)

Comments

The key there is calling System/setProperty tho'. If you omit that, intending to rely on whatever user configuration is provided, you get the original output that the OP is complaining about:

Nov 05, 2023 10:35:35 AM user$eval464$fn__467 invoke
INFO: Hello

With that property set, I get the same as you but without the SLF4J complaints:

[2023-11-05 10:37:35] [INFO   ] [app.core] Hello

---

Yes, but that's the default format for JUL. Other logging libraries have other default formats and perhaps differing defaults for other configuration parameters. IMO that's not something c.t.l should be bothering itself with since it's just a very thin facade over the underlying implementation.

---

Oh, I absolutely agree this isn't an issue c.t.l should care about or address! I just wanted to point out that your "repro" case wasn't an exact repro of the OP's problem -- because you "fixed" the formatting with that setProperty call.

If a library chooses to use c.t.l and users of that library do nothing with logging, they'll get an ugly printout. If the users of that library are doing something explicit with logging, then they're likely already in control of that output.

At work we use log4j2 and have everything bridged into that and we use c.t.l and force c.t.l to use log4j2 -- so if libraries choose to use c.t.l, we don't care because everything is consistent.

I guess there's an underlying philosophical issue of "should (Clojure) libraries use c.t.l in the first  place" or should they be "logging neutral" (and then what would that look like)?

clojure.java.data depends on it but only uses it conditionally -- which in turn is depended on by next.jdbc so that brings logging into a lot of people's programs. java.data does not log by default tho'...

---

As stated the issue is when random lib users start getting these weird log statements into their std.err and they have very little to go on to start looking for the cause. Yes, obviously you can fix the format to elide that information.

I understand that some take the position that this isn't the problem of c.t.l to solve, but I'd argue that the printout is caused by c.t.l macro and more importantly the issue is fixable mainly through a change to c.t.l.

I advocate for this change because:
- there's no negative tradeoff
- the code complexity doesn't really increase
- improves performance (JUL doesn't need to perform reflection to figure out the caller class and method)

I don't really see a downside to this change.