Log4J the Groovy Way

While developing around, now or then one wants something printed out at the console of his/her IDE. Well, with Groovy, it's easy: println "Hello World!". But when it comes to some serious development and logging you must meet some requirements:

• keep log statements in code for faster switching them on/off
• timestamps for profiling
• log log... who's logging?
• a log file for tracing down errors
• well, and so on...

One of many good log-solutions: log4j

At work our company is using log4j as part of JBoss Application Server, so I'm used to it. Sometime ago before I was developing with Groovy I stumbled upon an article at grovvy zone: Groovy and Log4j

In fact, this article made me finally getting started with Groovy, after following the community silently for months. Well I developed a bit around, every day with new cool and 'Groovy' features, but shortly after that I started another groovy project and so this went to background since yesterday, when I was about to implement logging for my project. So I digged out my code and polished it up a bit and voilá, here is my solution with log4j.

Why I'm telling you to use log4j? I don't. I don't want to show up any pros and cons. I just want to provide a simple and groovy solution to address logging requirements, for this example with log4j. So get your project equipped with log4j and start your engines, ladies and gentlemen...

The groovy way

From the mentioned article I first came up with this solution to test log4j:

package log4jimport org.apache.log4j.*class HelloWorldNoLog {  public static String PATTERN = "%d{ABSOLUTE} %-5p [%c{1}] %m%n"  static void main(args) {    def simple = new PatternLayout(PATTERN)    BasicConfigurator.configure(new ConsoleAppender(simple))    LogManager.rootLogger.level = Level.INFO    Logger log = Logger.getInstance(HelloWorldNoLog.class)    def name = "World"    log.info "Hello $name!"    log.warn "Groovy " + "logging " + "ahead..."    def x = 42    log.setLevel Level.DEBUG    if (log.isDebugEnabled()) {      log.debug "debug statement for var x: " + x    }  }}

gives you:

23:01:40,062 INFO  [HelloWorldNoLog] Hello World!23:01:40,078 WARN  [HelloWorldNoLog] Groovy logging ahead...23:01:40,078 DEBUG [HelloWorldNoLog] debug statement for var x: 42 

Nice, simple but not groovy enough IMHO, in fact there are some more or less ugly things here:

• You have bootstrap code, but that is normally not a real problem
• You need an instance of a Logger object and you must provide your class
• You better check if a level is enabled for trace, debug (and info) before logging
• You have + joined Strings instead of GString like in the first code example for multiple parameters

The real groovy way

Well, wouldn't it be easier to just have:

package log4jclass HelloWorldLog {   static void main(args) {      def name = "World"      Log.info "Hello $name!"      Log.warn "Groovy ", "logging ", "arrived!"      def x = 42      Log.setLevel "debug"      Log.debug "debug statement for var x: ", x   }}

to give you:

23:10:46,359 INFO  [HelloWorldLog] Hello World!23:10:46,359 WARN  [HelloWorldLog] Groovy logging arrived!23:10:46,375 DEBUG [HelloWorldLog] debug statement for var x: 42

Pretty groovy, hm? But what happened here? Where is all the code? Let's clear some things up: as 'Log.info...' starts with a capital letter, it must be a Class in the same package. By having this class in your packages, you eliminate the need for:

• The boilerplate code
• Getting an instance of Logger
• Providing a class ;-)
• Checking if a level is enabled
• An enum for level changing and thus no import of log4j needed

What is really needed for this are only three things: log4j library in the classpath, Log helper class and an import when you log something (can also be a static import...). Okay okay, on next page comes the magic class...

Log.groovy

package log4jimport org.apache.log4j.*class Log {  public static String PATTERN = "%d{ABSOLUTE} %-5p [%c{1}] %m%n"  public static Level LEVEL = Level.INFO  private static boolean initialized = false  private static Logger logger() {    def caller = Thread.currentThread().stackTrace.getAt(42)    if (!initialized) basic()    return Logger.getInstance(caller.className)  }  static basic() {    def simple = new PatternLayout(PATTERN)    BasicConfigurator.configure(new ConsoleAppender(simple))    LogManager.rootLogger.level = LEVEL    initialized = true  }  static setLevel(level) {    def Level l = null    if (level instanceof Level) {      l = level    } else if (level instanceof String) {      l = (Level."${level.toUpperCase()}")?: null    }    if (l) LogManager.rootLogger.level = l  }  static trace(Object... messages) { log("Trace", null, messages) }  static trace(Throwable t, Object... messages) { log("Trace", t, messages) }    static debug(Object... messages) { log("Debug", null, messages) }  static debug(Throwable t, Object... messages) { log("Debug", t, messages) }  static info(Object... messages) { log("Info", null, messages) }  static info(Throwable t, Object... messages) { log("Info", t, messages) }  static warn(Object... messages) { log("Warn", null, messages) }  static warn(Throwable t, Object... messages) { log("Warn", t, messages) }  static error(Object... messages) { log("Error", null, messages) }  static error(Throwable t, Object... messages) { log("Error", t, messages) }  static fatal(Object... messages) { log("Fatal", null, messages) }  static fatal(Throwable t, Object... messages) { log("Fatal", t, messages) }  private static log(String level, Throwable t, Object... messages) {    if (messages) {      def log = logger()      if (level.equals("Warn") || level.equals("Error") || level.equals("Fatal") || log."is${level}Enabled" ()) {        log."${level.toLowerCase()}" (messages.join(), t)      }    }  }}

When you call any of the methods trace, debug, and so on (with or without a Throwable) a common method log() is called with the level as first letter uppercase String (note the usage of varargs too):

private static log(String level, Throwable t, Object... messages) {  if (messages) {    def log = logger()    if (level.equals("Warn") || level.equals("Error") || level.equals("Fatal") || log."is${level}Enabled" ()) {      log."${level.toLowerCase()}" (messages.join(), t)    }  }}

• The method gets itself a logger first (still no need for a Class ;-)
• It then checks if the level is warn, error, or fatal to log directly
• Otherwise the method isTraceEnabled, isDebugEnable or isInfoEnabled is called (that's why the first letter is uppercase)
• Logging itself takes place with the level lowercased as a dynamic method invocation
• The messages are joined automatically (you may use comma here to support multiple ways of logging)

Now for the Logger object, this method does all the magic:

  private static Logger logger() {    def caller = Thread.currentThread().stackTrace.getAt(42)    if (!initialized) basic()    return Logger.getInstance(caller.className)  }

Notes:

• To get the Class for the log4j logger use the stacktrace of the current Thread
• As the stackpath to this method does not vary internally the caller can be found at a fixed position
• So the Logger instance is been created by using the plain classname

The rest is only setLevel here. So long so groovy.

What's next

Well, I think this is a pretty slim solution for easy logging, but after all it's only a basic example. From this point one could extend this in many (groovy) ways, for example:

• Support log4j.xml for configuration (from classpath or user dir)
• Allow Appenders, Categories and the rest
• Or create a DSL for configuration like this one (just wrote it up, untested!):

def log4jDSL = {  configuration(debug: false) {    appender(name: "file", type: "DailyRolling") {      errorHandler (type: "OnlyOnce")      params() {        File "groovy.log"        Append false        DatePattern ".yyyy-MM-dd"        Threshold "debug"        layout (type: "PatternLayout") {          param (type: "ConversationPattern", value: "%d %-5p [%c] %m%n")        }      }    }    category(name: "org.codehaus") {      priority (value: "debug")    }    root() {      appenders() {        file()      }    }  }}

Conclusion

For me this is a clean approach and it can be extended and used wherever Groovy and logging comes into place. With a little more effort you may read xmls or groovy markup and end up with a rock solid yet configurable solution for your Groovy utils package (Well, you may use it as Category as well, as its static...)

I hope you enjoyed my first post as much as I enjoyed writing up this tip or trick!

With greetings, Gerhard Balthasar

About me

I'm from Germany and I am Groovy addicted since I tried it one month ago as mentioned. I'm working at a medium J2EE software company in Ludwigsburg near Stuttgart and meanwhile I introduced Groovy for helping with some developing tasks successfully there ;-)

Edit

Based upon the comment from Ronald, I updated the relevant parts of this story (see comments for details)