Log4J and Clojure Configuration

Clojure, Log4J, and clojure.tools.logging can play nicely together. Here’s a reasonable default configuration.

Update: Consider using clj-logging-config to configure your logs in a more Clojurey way, rather than screwing around with the ugly Java-ish log4j.properties file described here.

  1. If using Leiningen, add

    :dependencies [
                     [log4j/log4j "1.2.16" :exclusions [javax.mail/mail
                                                  javax.jms/jms
                                                  com.sun.jdmk/jmxtools
                                                  com.sun.jmx/jmxri]]
                     [org.clojure/tools.logging "0.2.3"]
    ]
    

    to your project.clj file and rerun lein deps to auto-install the Log4J JAR.

    If not using Leiningen, acquire a Log4J JAR and put it on your classpath.

  2. Create a file called log4j.properties on your classpath and put the following into it:
    # Based on the example properties given at http://logging.apache.org/log4j/1.2/manual.html
    # Set root logger level to DEBUG and its only appender to A1.
    log4j.rootLogger=DEBUG, A1
    
    # A1 is set to be a ConsoleAppender.
    log4j.appender.A1=org.apache.log4j.ConsoleAppender
    
    # A1 uses PatternLayout.
    log4j.appender.A1.layout=org.apache.log4j.PatternLayout
    log4j.appender.A1.layout.ConversionPattern= %-5p %c - %m%n
    

That’s the short version. Read on for the gory details.

Logging philosophy

My logging requirements are simple at the moment. I want to write messages to the console, each tagged with a log level (“INFO”, “WARN”, “ERROR”, etc.) I want to be able to set a log level, and only see log messages of that severity or higher. That’s it. I take this to be the canonical base case of logging that covers 80% of needs. All other logging features (e.g. logging to a file, differentiating by class or namespace) are nice, but much less common, and ought to be handled via configurable deviations from this default case.

clojure.contrib.logging does not presently make it easy to do any of this common base case out of the box. The Lispy façade quickly falls apart; you’re dumped into the deep end of the Java overengineering mire without a life vest when you simply want to change the log level temporarily.

What’s wrong with clojure.contrib.logging’s defaults?

clojure.contrib.logging with no special configuration done prefaces each and every logged line on my system with:

[null] May 16, 2010 1:08:48 PM clojure.contrib.logging$eval__2077$impl_write_BANG___2088 invoke

I have no idea why. This makes it very hard to read the log when logging any nontrivial amount of information.

clojure.contrib.logging’s documentation contains a rather cryptic offhanded remark, with no further explanation: Note: your log configuration should display the name that was passed to the logging implementation, and not perform stack-inspection, otherwise you’ll see something like “fn__72$impl_write_BANG__39__auto____81″ in your logs.

My log configuration? Stack inspection? Why do I need to have a log configuration to just dump strings to the console? Why is the default case to print a verbose and useless header for each line? Isn’t this Javaesque mess — obscure 50 line XML configuration files just to get basic logging functionality working — exactly what we’re trying to avoid?

Log4J with clojure.contrib.logging configuration

Ah, well, there’s nothing for it, I suppose. Better just get a serious logging library and figure out how to configure it. The docs say that clojure.contrib.logging delegates to the first supported logging implementation that it finds. I am apparently using the builtin JDK logger by default, and Apache Commons’ logger is just another wrapper, so I added Log4J to Leiningen’s project.clj and it installed the jar for me.

Now, I get:

     [null] log4j:WARN No appenders could be found for logger (my-project-name).
     [null] log4j:WARN Please initialize the log4j system properly.

Followed by dead silence.

Hm.

I can only imagine that Log4j was never intended to be used without a custom configuration. Odd. Why people design software that comes without reasonable defaults pre-set to cover the common base case is beyond me. I fully understand that strange setups will require customized configuration, but “dumping strings to the console” does not seem like a bizarre edge case for a logging package. A default case of “send all log messages to the black hole unless configured to do otherwise” makes little sense.

So, how hard can it be to configure Log4J for this base case functionality? The “short introduction to log4j” is 19 pages long. Sigh. (The complete manual is proudly described as “over 200 pages.” I sometimes wonder if they overengineer Java libraries on purpose just to drive book sales.)

I do not want to know what a Nested Diagnostic Context is, or the precise semantic distinction between “Loggers,” “Appenders,” and “Layouts.” I don’t care about “Appender Additivity” and “Named Hierarchies,” and I certainly don’t want to write an XML configuration file. I Just want to log tagged strings to the console, and have them print without a bizarre autogenerated header line. That’s it. I fully appreciate that those things will be useful for some people — maybe even for me, when my project grows to become more complex. I have nothing against their existence; but for the base case, one should not need to know of it.

On page 9 of the “short” manual, after a boatload of irrelevant information, we have an answer: there is a class called BasicConfigurator with a static method that does reasonable initialization for logging to the console. We can just do (org.apache.log4j.BasicConfigurator/configure) and get that.

However, we are still getting log messages like:

     [null] 3702 [8633270@qtp-3149669-2] INFO my.namespace - log message

We have to learn something about Layouts now. The thread names generated by Clojure are apparently not very useful, so we’re going to turn them off. And while interesting when profiling, the number of milliseconds since program start is just going to be visual clutter 98% of the time, so I’m going to turn that off, too, until I actually need it.

The result is the log4j.properties file listed above. Just copy and paste it into your classpath. If you want more or different information in your logs, take a look at the PatternLayout API documentation and alter the ConversionPattern line according to your preferences.

The result:

     [null] INFO  my.namespace - log message 

I’m still not sure where the [null] comes from, but overall, it’s very readable.

Clojure posts you might also like:

2 Responses to Log4J and Clojure Configuration

  1. Hi Paul –
    I know it’s a bit late here, but I have run into the same problem with clojure.contrib.logging.

    I can at least explain what the author meant by his cryptic remarks. Log libraries get the “location” (class/method) of the log item from the java stack. In java, this is straightforward because they can just look at the stack when they are called, ignore their own elements at the top of the stack, and figure out who called them.

    In clojure this doesn’t quite work because clojure.contrib.logging is sandwiched between the calling code and log4j. So log4j thinks it’s always clojure.contrib.logging that’s calling it. From a java perspective, that’s exactly right.

    What needs to happen is the log library needs to pop off one extra element off that stack to get the true caller location.

    Unfortunately I don’t see any public API for log4j that lets you tell it how to do that.

    java.util.logging has API Logger.logp() that lets you pass in the location yourself. So I hacked up a version of clojure.contrib.logging that figures it out and passes in the right value. In my version I commented out commons logging support because it chooses it first over the java.util implementation.

    Look around line 180 for “.getStackTrace”. https://github.com/weissjeffm/webui-framework/blob/unify/src/com/redhat/qe/logging.clj

    Hope that helps.