Recently I saw a post by someone (I think it was @jbarnette, but it was retweeted to me) suggesting that there should be some alternate log levels, like fyi, omg, or even wtf. I thought that was pretty funny, but then it occurred to me I could probably implement them using Groovy metaprogramming.
As a first attempt, consider the following simple example that adds the fyi and omg methods to java.util.logging.Logger:
[sourcecode language=”groovy”]
import java.util.logging.Logger
Logger.metaClass.fyi = { msg -> delegate.info msg }
Logger.metaClass.omg = { msg -> delegate.severe msg }
[/sourcecode]
For those who haven’t used Groovy much, the metaClass property is associated with every class in Groovy, and allows you to add methods and properties to the class. Here the fyi method is defined by assigning it to a one-argument closure whose implementation is to invoke the (existing) info method in Logger, with the msg argument. Likewise, omg is assigned to the severe method. Therefore, an invocation like:
[sourcecode language=”groovy”]
Logger log = Logger.getLogger(this.class.name)
log.fyi ‘for your information’
log.omg ‘oh my goodness’
[/sourcecode]
results in
Dec 12, 2011 10:09:02 PM java_util_logging_Logger$info call
INFO: for your information
Dec 12, 2011 10:09:02 PM java_util_logging_Logger$severe call
SEVERE: oh my goodness
The methods work, but the output isn’t really what I want. The messages get passed through, but the output shows INFO and SEVERE rather than FYI and OMG.
It turns out it takes a bit of work to define a custom log level. Levels are defined using the java.util.logging.Level class, which predefines levels like Level.INFO, Level.WARNING, and Level.SEVERE. The Level class has a protected constructor which can be used to make new levels. I therefore adding a class called CustomLevel, as follows:
[sourcecode language=”groovy”]
import java.util.logging.Level
class CustomLevel extends Level {
CustomLevel(String name, int val) {
super(name,val)
}
}
[/sourcecode]
Each level gets an integer value. On my Windows 7 system (sorry) using JDK 1.6, the actual values of some of the defined levels are:
[sourcecode language=”groovy”]
import java.util.logging.Level
println "$Level.INFO: ${Level.INFO.intValue()}"
println "$Level.WARNING: ${Level.WARNING.intValue()}"
println "$Level.SEVERE: ${Level.SEVERE.intValue()}"
[/sourcecode]
INFO: 800
WARNING: 900
SEVERE: 1000
My second attempt was then to define a Groovy category, so that I could replace a couple of the existing levels in a controlled fashion.
[sourcecode language=”groovy”]
import java.util.logging.Level
import java.util.logging.Logger
class SlangCategory {
static String fyi(Logger self, String msg) {
return self.log(new CustomLevel(‘FYI’,Level.INFO.intValue()),msg)
}
static String lol(Logger self, String msg) {
return self.log(new CustomLevel(‘LOL’,Level.WARNING.intValue()),msg)
}
}
Logger log = Logger.getLogger(this.class.name)
use(SlangCategory) {
log.fyi ‘this seems okay’
log.lol(‘snicker’)
}
[/sourcecode]
Each of the logging methods in the Logger class (like info() or warning()) delegate to the log() method, which takes two arguments — an instance of Level, and a message String. I therefore used the category to replace the INFO and WARNING levels with FYI and LOL. The output is now:
Dec 12, 2011 10:20:29 PM sun.reflect.NativeMethodAccessorImpl invoke0
FYI: this seems okay
Dec 12, 2011 10:20:29 PM sun.reflect.NativeMethodAccessorImpl invoke0
LOL: snicker
Once again, this is just replacing existing levels, though it does at least have the new level name in the output string.
To really do this right, though, I wanted to be able to define new levels arbitrarily without having to hardwire them. That meant overriding the methodMissing method in the metaClass, using what Jeff Brown describes as the “intercept, cache, invoke” pattern for metaprogramming. Here’s the result, which I’ll explain after the code.
[sourcecode language=”groovy”]
import java.util.logging.*
Logger.metaClass.methodMissing = { String name, args ->
def impl = { Object… varArgs ->
int val = Level.WARNING.intValue() +
(Level.SEVERE.intValue() – Level.WARNING.intValue()) * Math.random()
def level = new CustomLevel(name.toUpperCase(),val)
delegate.log(level,varArgs[0])
}
Logger.metaClass."$name" = impl
impl(args)
}
Logger log = Logger.getLogger(this.class.name)
log.wtf ‘no effin way’
log.whoa ‘dude, seriously’
log.rofl "you’re kidding, right?"
[/sourcecode]
The methodMissing method of the metaClass takes two arguments: the name of the method, and the arguments passed to it. Whenever you invoke a method that doesn’t exist, methodMissing gets invoked. That’s the “intercept” part.
The implementation is to define a closure that takes any number of arguments. Inside the closure, I computed a random value between Level.WARNING and Level.SEVERE, and then used that value to instantiate a custom level. The defined level and the new value were used in the log method on the closure’s delegate property (in this case, the logger) to log the message at the new level.
Finally, the "$name" method to the metaClass (which evaluates the name variable — otherwise the method added would just be called name) is assigned to the impl closure. That’s the “cache” part. Finally, the implementation is called, which is the “invoke” part.
Now I can use a log level with whatever name I want. The output of this script is
Dec 12, 2011 10:31:35 PM sun.reflect.NativeMethodAccessorImpl invoke0
WTF: no effin way
Dec 12, 2011 10:31:35 PM sun.reflect.NativeMethodAccessorImpl invoke0
WHOA: dude, seriously
Dec 12, 2011 10:31:35 PM sun.reflect.NativeMethodAccessorImpl invoke0
ROFL: you're kidding, right?
The demos are nice, but this really ought to be tested. I’m reasonably comfortable with this level (snicker) of metaprogramming, but I’d feel a lot better if I had a real test for it.
That took a fair amount of digging. It turns out that the inimitable Dierk Koenig (lead author of Groovy in Action, known as #regina on Twitter; second edition available now through the Manning Early Access Program) wrote a class called groovy.lang.GroovyLogTestCase. That class has a static method called stringLog. The GroovyDocs say:
“Execute the given Closure with the according level for the Logger that is qualified by the qualifier and return the log output as a String. Qualifiers are usually package or class names. Existing log level and handlers are restored after execution.”
It took me a while figure out how to use that, but eventually I got it to work. It automatically captures the console appender output, so the resulting test looks like this:
[sourcecode language=”groovy”]
import java.util.logging.Level
import java.util.logging.Logger
class LoggingTests extends GroovyLogTestCase {
String baseDir = ‘src/main/groovy/metaprogramming’
void testWithoutCustomLevel() {
def result = stringLog(Level.INFO, without_custom_levels.class.name) {
GroovyShell shell = new GroovyShell()
shell.evaluate(new File("$baseDir/without_custom_levels.groovy"))
}
assert result.contains(‘INFO: for your information’)
assert result.contains(‘SEVERE: oh my goodness’)
}
void testSlangCategory() {
def result = stringLog(Level.INFO, use_slang_category.class.name) {
GroovyShell shell = new GroovyShell()
shell.evaluate(new File("$baseDir/use_slang_category.groovy"))
}
assert result.contains(‘FYI: this seems okay’)
assert result.contains(‘LOL: snicker’)
}
void testEMC() {
def result = stringLog(Level.INFO, use_emc.class.name) {
GroovyShell shell = new GroovyShell()
shell.evaluate(new File("$baseDir/use_emc.groovy"))
}
assert result.contains(‘WTF: no effin way’)
assert result.contains(‘WHOA: dude, seriously’)
assert result.contains("ROFL: you’re kidding, right?")
}
}
[/sourcecode]
I should mention a couple of minor points. First, the class associated with a script has the same name as the file containing it, so the classes in the stringLog method are the script names. Second, in case you were wondering, the emc part of the script name stands for ExpandoMetaClass.
I spent a very pleasant evening working on this, and learned a few things:
1. Groovy metaprogramming is fun,
2. Now I know how to use GroovyLogTestCase, which is not at all well documented, and
3. I’ll go to all sorts of trouble to avoid working on what I’m supposed to be working on, especially if it involves a joke. 🙂
I added all this to my book’s source code. What book, you ask? Why, Making Java Groovy, available through the Manning Early Access Program (MEAP) at http://manning.com/kousen. I don’t know, however, if I’ll have room in the text to include all this.
[sourcecode language=”groovy”]
log.marketing(‘Please forgive the mandatory advertising for my book’)
[/sourcecode]
Leave a Reply