Setting Clojure’s Log Level

Clojure.contrib.logging doesn’t have any way to set the log level. This is obviously a problem if you want to make use of various log levels (debug, warn, etc.) to separate different logging depths. Here’s a function to set the logging level on my default clojure.contrib.logging setup:

Update (Feb 2012): I suggest that you use clj-logging-config for all new projects, and bypass this mess entirely! What’s below is here for historical purposes only.

;;; This version works when (impl-get-log "") returns an org.apache.commons.logging.impl.Jdk14Logger
(use 'clojure.contrib.logging)
(defn set-log-level! [level]
  "Sets the root logger's level, and the level of all of its Handlers, to level.
   Level should be one of the constants defined in java.util.logging.Level."
  (let [logger (.getLogger (impl-get-log ""))]
    (.setLevel logger level)
    (doseq [handler (.getHandlers logger)]
      (. handler setLevel level))))
;;; This version works when (impl-get-log "") returns a java.util.logging.LogManager$RootLogger
(use 'clojure.contrib.logging)
(defn set-log-level! [level]
  "Sets the root logger's level, and the level of all of its Handlers, to level.
   Level should be one of the constants defined in java.util.logging.Level."
  (let [logger (impl-get-log "")]
    (.setLevel logger level)
    (doseq [handler (.getHandlers logger)]
      (. handler setLevel level))))


This log level setting function works with a standard out-of-the-box clojure.contrib.logger on my system — depending on what logging libraries it finds on your classpath, as per the docs, it may not work for you. In particular, you need to be using clojure.contrib.logger to wrap an Apache Commons Logging instance, which in turn wraps a java.util.logging instance. This is the way my system works without any configuration; YMMV. Hopefully, something like this will be assimilated into a universal wrapper in the next clojure.contrib.logging.

For the gory details of how this was constructed…

Changing log levels

I needed to log some data in my Clojure app. I looked through clojure-contrib and found clojure.contrib.logging. It provides a unified logging wrapper for Apache commons-logging, log4j, and java.util.logging.

The spy macro looks particularly useful for debugging intermediate functions without complicating their code with a bunch of logging cruft: just wrap them in a single tiny spy call, and you’re set.

Unfortunately, spy logs at the :debug level, and my logger by default seems to be set to :info level. No problem, I thought, I’ll just increase the log level to :debug… Hm… Turns out that there’s no simple way to do that.

clojure.contrib.logging presently includes nothing at all for setting the debug level, in fact, a curious omission of obvious and very basic functionality. So we dig.

Setting the log level must be done in the underlying logging library, since there’s no clojure.commons.logging wrapper. Looking at *impl-name*, it seems that I’m using org.apache.commons.logging.

Apache Commons Logging

OK, great. Let’s take a look at the Commons Logging docs. The Commons Logging User Guide sounds like a good place to start. Surely changing the log level is a very common task that will be prominently addressed there… Perhaps even in the Quick Start guide.

Hmm, nope, nothing about changing the log level, but there is a somewhat disturbing reference to “a simple commons-logging.properties file”, conjuring up long-ago memories of Java overengineering and bloat — an entire configuration file, just to temporarily change the log level?? Surely not… Also mildly disturbingly, there are references to “the underlying logging system”. Commons Logging seems to be, itself, just an abstraction around some other logging system. So I’m using two layers of logging wrappers now.

Well, let’s see what Clojure thinks we’re using:

> (log/impl-get-log "user")
#<Jdk14Logger org.apache.commons.logging.impl.Jdk14Logger@13e168>

Now we’re getting somewhere. Let’s look at Jdk14Logger’s JavaDocs: the getLogger() – “Return the native Logger instance we are using” method looks promising.

java.util.logging.Logger

> (.. (log/impl-get-log "user") getLogger)
#<Logger java.util.logging.Logger@1a32f73>

java.util.logging.Logger! Aha! Let’s see what we can do with that… “The log level … may also be dynamically changed by calls on the Logger.setLevel method.” Finally!

This being Java, setLevel() naturally requires an entire object to wrap the integer specifying the log level, with the integer in turn standing in for what we would call a symbol in Lisp (and being referenced symbolically through constants in the Level class.) Ugh. And confusingly, the log level constants in that class are named FINE, FINER, FINEST, INFO, OFF, SEVERE, and WARNING, which do not correspond to the :debug, :info, :warn, :error levels used by Clojure and Apache Commons Logging.

Let’s see what we’re at now:

user> (use 'clojure.contrib.logging)
nil
user> (warn "foo") ; -> WARNING: foo
nil
user> (info "foo") ; -> INFO: foo
nil
user> (debug "foo") ; nothing printed
nil
user> (.. (impl-get-log "user") getLogger getLevel)
nil
;;
;; Nil? WTF?
;;
user> (.. (impl-get-log "user") getLogger )
#<Logger java.util.logging.Logger@197952>
;;
;; Yep, we're using the right object...
;;
user> (.. (impl-get-log "user") getLogger getName)
"user"
;;
;; and we have the logger for the correct namespace...
;; it has a getParent() method - maybe it inherits?
;;
user> (.. (impl-get-log "user") getLogger getParent)
#<RootLogger java.util.logging.LogManager$RootLogger@1c2df08>
user> (.. (impl-get-log "user") getLogger getParent getLevel)
#<Level INFO>
;;
;; AHA. it does.
;;

So we’ve finally tracked down where the log level is set. According to the Javadocs, a logger with a null log level will inherit its parent’s log level, and changing the parent with setLevel() will also affect any children that are inheriting. The docs tell us that we can get the root logger by asking for the “” (empty string) name, so we can simply modify that:

(defn set-log-level! [level]
"Sets the root logger level."
  (.setLevel (.getLogger (log/impl-get-log "")) level))

But all is not well:

user> (.. (impl-get-log "") getLogger getLevel)
#<Level FINE>
user> (debug "foobar") ;; prints nothing
nil
user> (set-log-level! java.util.logging.Level/FINER)
nil
user> (debug "foobar") ;; prints nothing
nil
user> (set-log-level! java.util.logging.Level/FINEST)
nil
user> (debug "foobar") ;; prints nothing
nil
user> (set-log-level! java.util.logging.Level/ALL)
nil
user> (debug "foobar") ;; prints nothing
nil

Err… ok. Maybe that’s the wrong method? Maybe it’s not actually setting it?

user> (.. (impl-get-log "user") isDebugEnabled)
true
user> (.. (impl-get-log "") isDebugEnabled)
true
user> (log :debug "asdf") ;; prints nothing
nil
user> (debug "asdf") ;; prints nothing
nil
;;
;; Maybe printing directly to the Java object rather than going through contrib.logger will help?
;;
user> (. (impl-get-log "user") debug  "foo bar") ;; prints nothing
nil
user> (. (impl-get-log "") debug  "foo bar") ;; prints nothing
nil
user> (. (impl-get-log "user") warn  "foo bar") ;; prints "WARNING: foo bar"
nil

WTF.

Digging even further into the docs, we find:

On each logging call the Logger initially performs a cheap check of the request level (e.g. SEVERE or FINE) against the effective log level of the logger. If the request level is lower than the log level, the logging call returns immediately.

After passing this initial (cheap) test, the Logger will allocate a LogRecord to describe the logging message. It will then call a Filter (if present) to do a more detailed check on whether the record should be published. If that passes it will then publish the LogRecord to its output Handlers. By default, loggers also publish to their parent’s Handlers, recursively up the tree.

Great, more Filters of some kind (beyond the log level check filter), a LogRecord object to wrap a string, and an inherited tree of Handlers. All to write a simple level-bound log message to STDERR. (And this is the simple logging library. I shudder to think of log4j’s internals.)

user> (..  (impl-get-log "") getLogger getFilter)
nil
user> (..  (impl-get-log "user") getLogger getFilter)
nil
user> (..  (impl-get-log "") getLogger getHandlers)
#<Handler[] [Ljava.util.logging.Handler;@23f019>
user> (first (..  (impl-get-log "") getLogger getHandlers))
#<ConsoleHandler java.util.logging.ConsoleHandler@829d91>
user> (.. (first (..  (impl-get-log "") getLogger getHandlers)) getLevel)
#<Level INFO>
user> 

So... in the "simple" logger package, we have two. seperate. levels. of filtering on the log level, which are entirely uncoordinated. And no mention in the documentation of what exactly these "Filters" and "Handlers" do, or that they can also discard log messages. Certainly no mention at the logger's setLevel() method docs that your setting might be overruled by a "Handler" in some other part of the object tree. (Now, why did I ever stop coding in Java, again...?)

The working function to set the log level

user> (defn set-log-level! [level]
  "Sets the root logger's level, and the level of all of its Handlers, to level."
  (let [logger (.getLogger (impl-get-log ""))]
    (.setLevel logger level)
    (doseq [handler (.getHandlers logger)]
      (. handler setLevel level))))
#'user/set-log-level!
user> (set-log-level! java.util.logging.Level/ALL)
nil
user> (debug "foo bar") ;; FINALLY prints "FINE: foo bar". Not quite what I wanted ("FINE"?), but close enough.
nil
user> (spy (str "abc" "def")) ;; -> " FINE: (str "abc" "def") => abcdef". cool.
"abcdef"

So there you have it. You can now adjust your clojure.contrib.logger log level at runtime — at least for clojure.contrib.logger wrapping Apache Commons Logging wrapping a java.util.logging logger. No doubt log4j requires its own unique set of black magic. I hope a future version of clojure.contrib.logger will include a universal loglevel-setting function — I’ll gladly donate this code to it.

9 Responses to Setting Clojure’s Log Level

  1. Hi Paul

    Is it possible to provide separate category for clojure posts? I wanted to add your blog to Planet Clojure. Please write to me via mail?

  2. if result of
    (..(clojure.contrib.logging/impl-get-log “user”) getLogger)
    will be something like
    #
    instead of
    java.util.logging.Logger stuff, here are some snippets that might be useful
    http://gist.github.com/361124

    basically there is no need to mess with handlers, but you should call getRootLogger

  3. Alternately, you could have submitted an assembla ticket and I would have added the omitted functionality. Things won’t improve if you don’t tell the maintainers.

  4. Hey Paul,
    What about making set-log-level! a multimethod that looked at the resulting log object class and called the proper implementation to set the log level? Just a thought …
    take care,
    Mike