An Architect's View

CFML, Clojure, Software Design, Frameworks and more...

An Architect's View

Real World Clojure - logging

November 1, 2011 ·

Clojure provides a nice, consistent interface for logging via (one of the new, modular contrib libraries). It automatically wraps slf4j, commons logging, log4j and java.util.logging but you can override the implementation, if needed. At World Singles, we wanted to log some levels to a data store (initially MySQL, but later on to MongoDB) so we needed to write a custom log appender. I talked a bit about writing a custom log4j appender in Clojure in an earlier blog post but didn't go beyond a proof of concept. There were a couple of small 'gotchas' that we ran into which I'll cover in here.

First, let me reiterate what we did to get the basic classes generated.

(ns worldsingles.logging.dbappender
  (:import (org.apache.log4j Level))
  (:import (org.apache.log4j.spi LoggingEvent))
  (:gen-class :name worldsingles.logging.DBLogger
              :extends org.apache.log4j.AppenderSkeleton))

;; implement void AppenderSkeleton.append(LoggingEvent event)
(defn -append
  "Append non-DEBUG events to actionLog or log table as appropriate."
  [_ ^LoggingEvent event]
;; implement void Appender.close()
(defn -close [_])

;; implement boolean Appender.requiresLayout()
(defn -requiresLayout [_] false)

The key is the :gen-class directive where we specify the name of the class we want to generate and the name of the class it extends. The leading - on append, close, requiresLayout signifies that the function name should be respected by the Clojure compiler (so it can be called from Java) and the initial anonymous argument (_) represents the unused this argument which is passed implicitly to every Java object method call. We also add the AOT compile directive to our project.clj file:

:aot [worldsingles.logging.dbappender]

Then we run lein compile and in our classes folder we get (amongst other things - see below) worldsingles/logging/DBLogger.class as well as our various worldsingles.logging/dbappender*.class files. We package our Clojure code with lein uberjar and place that JAR file on the classpath of our application server. We have log4j configured like this:

# worldsingles.* namespaces log using the DB appender
log4j.logger.worldsingles = DB

# DB : custom database appender
log4j.appender.DB = worldsingles.logging.DBLogger

When our application starts up, figures out which logging implementation we're using (log4j) and initializes it which loads our compiled DBLogger and we're off to the races. Our -append method uses our persistence abstraction to save the event data and we started out logging to two tables in MySQL (based on a key in the event data) and then added an additional call to save data to MongoDB as well. Over time, we expect to consolidate all of our logging to MongoDB.

(let [now (date/today)
      msg (.getMessage event)
      save-row (resolve (symbol ""))]
  (save-row :logging 
            (if (map? msg) 
              (assoc msg :when now) 
              {:log-entry msg :when now}))

The payload of our logging event can be either a string (legacy logging code in our application) or a Clojure map (more recently structured logging code). We automatically add :when to all log records. The save-row call is part of our persistence abstraction which, as you can see, makes it trivial to write a map to our datastore (in this case, MongoDB). The elided code conditionally makes one of two additional save-row calls to write a map to MySQL (where our two legacy log tables reside).

Now, here are the two 'gotchas' we ran into - and a gripe about a bug in the Clojure compiler:

  • recently changed the way it searches for logging implementations and now it 'prefers' slf4j over log4j. Since slf4j is provided by some middleware we're using, that is found first and although it recognizes log4j is present, it doesn't recognize our custom configuration. The API that offers, to control this search, is a dynamic variable *logger-factory* which you can rebind to anything that satisfies the protocol. Since we want to override the default implementation which searches for a specific logger factory, we alter this variable to refer to the log4j implementation:
    (alter-var-root (var log/*logger-factory*) (constantly (impl/log4j-factory)))
    Since *logger-factory* is bound to the result of calling one of the factory functions, I expected to be able to just alter it to (impl/log4j-factory) but that doesn't work so it took some experimentation to come up with the right incantation here. I think it would be nicer to just be able to set a variable to one of :slf4j, :commons, :log4j, :jul but it does the trick.
  • Because we use logging all over our application, we cannot simply require in our namespace declaration because that would create a circular reference at load time. That's why we resolve the symbol reference at runtime. Figuring our way out of the circular reference took several frustrating hours because it wasn't clear at first how the circularity was caused (the error message referred to a different namespace - which was simply the point at which the compiler spotted the circularity!).
  • As I hinted above, when you AOT compile a Clojure namespace, you currently get more than you expect in the classes folder - potentially lots more! This is caused by the following bug/feature in the Clojure compiler: Enhance AOT compilation process to emit classfiles only for explicitly-specified namespaces. The compiler pulls in a series of transitive dependencies and merrily compiles everything reachable from your AOT compiled namespace! Luckily, since I'm using Leiningen, it cleans up (most of the) unused .class files before packaging the JAR files so it's only a minor nuisance for us right now.

Tags: clojure

5 responses

  • 1 Sebastian Galkin // Nov 1, 2011 at 5:27 AM

    Sean, why are you using gen-class/AOT instead of proxy? Maybe to have a class name to put in the log4j config file?
  • 2 Sean Corfield // Nov 1, 2011 at 11:40 AM

    @Sebastian, yes, log4j requires a (Java) class name in the configuration file:

    log4j.appender.DB = worldsingles.logging.DBLogger

    I think this is a great example of how easy it is to use Clojure to satisfy Java-based APIs.
  • 3 Sebastian Galkin // Nov 1, 2011 at 11:46 AM

    I'm not a big fan of gen-class. I guess you could use proxy and configure log4j programmatically. But of course, that comes at a price too.

    Nice display of Clojure's flexibility for the real world use!
  • 4 Michael // Nov 1, 2011 at 2:45 PM

    One question I have is how do people separate logging configuration in the test environment (where you usually use error or warn logging) vs development environment (where you often use debug logging). We use log4j property files on the classpath.

    Are there any well-known techniques besides programmatic logger configuration?
  • 5 Sean Corfield // Nov 2, 2011 at 11:17 AM

    @Michael, we're using log4j property files in WEB-INF/classes and treating that as part of the environment's configuration rather than part of the deployment.