log.rofl(‘Fun with Groovy metaprogramming’)

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:

import java.util.logging.Logger

Logger.metaClass.fyi = { msg -> delegate.info msg }
Logger.metaClass.omg = { msg -> delegate.severe msg }

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:

Logger log = Logger.getLogger(this.class.name)
log.fyi 'for your information'
log.omg 'oh my goodness'

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:

import java.util.logging.Level

class CustomLevel extends Level {
    CustomLevel(String name, int val) {
        super(name,val)
    }
}

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:

import java.util.logging.Level

println "$Level.INFO: ${Level.INFO.intValue()}"
println "$Level.WARNING: ${Level.WARNING.intValue()}"
println "$Level.SEVERE: ${Level.SEVERE.intValue()}"

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.

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')
}

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.

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?"

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:

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?")
    }
}

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.

log.marketing('Please forgive the mandatory advertising for my book')

GroovyShellTestCase for testing Groovy scripts

I try to keep up with developments in the Groovy and Grails worlds. I really do. I follow most of the core team members on Twitter. I listen to the Grails Podcast when I can. I go to many conferences and attend other talks when I’m not speaking. I try to follow the email lists, though they’re way too high volume. I even have a Google+ account, though I don’t check it very often.

It’s all too much, actually. As I get older, I find that keeping up isn’t just a question of time, it’s a question of energy. Sometimes I’ll manage to catch up on my Twitter feed and am too tired to do much else.

So new developments slip by me. I guess that’s good, since it’s indicative of an active ecosystem, but it can be frustrating at times.

The one that forms the subject of this blog post is pretty trivial and arguably not worth writing about, but I missed it when it first came out so I thought I’d document it here.

Say you have a script in Groovy and you want to test it. You can execute the script programmatically using GroovyShell, and supply any needed variables with an instance of the Binding class.

Here’s a trivial example. I have the following massively complex, powerful script:

z = x + y

Say this is saved in a file called ‘math.groovy‘. Since none of the variables x, y, and z are declared at all in the script (not even using def), they can be accessed through a Binding object.

Binding binding = new Binding()
binding.x = 3; binding.y = 4
GroovyShell shell = new GroovyShell(binding)
shell.execute(new File('math.groovy'))
assert 7 == binding.z

This is easy enough to convert into a test case, as a subclass of GroovyTestCase.

class ScriptTests extends GroovyTestCase {
    void testMath() {
        Binding binding = new Binding()
        binding.x = 3; binding.y = 4
        GroovyShell shell = new GroovyShell(binding)
        shell.evaluate(new File('math.groovy'))
        assertEquals 7, binding.z
    }
}

By extending GroovyTestCase, this entire script can be executed at the command line or inside the Groovy Console without adding any additional library dependencies of any kind (not even JUnit). When I ran it, the result was:

.
Time: 0.037

OK (1 test)

That’s all well and good. I was writing up examples like this for my book (Making Java Groovy, available through the Manning Early Access Program at http://manning.com/kousen) and decided to look at the Groovy API for GroovyTestCase. Lo and behold, what do I stumble upon but a class called GroovyShellTestCase. The class was authored by Alex Tkachman (so you know it’s good :)), presumably back in 2008 if the copyright statement is to be believed. Of course, the copyright could just be a copy-and-paste issue*.

*Which is what I like to call the CAP Design Pattern — how to take an error in one small part of your system and distribute it throughout the entire code base.

The GroovyDocs are a bit thin on that class, but they say (and I quote), “GroovyTestCase, which recreates internal GroovyShell in each setUp()”. The class has a protected field called shell of type GroovyShell, and a method called withBinding with a couple of overloads. For my purposes, I want the overload that takes two arguments, the first being a Map of binding variables, and the second being a closure to be executed. The method executes the closure with the given binding:

protected def withBinding(Map map, Closure closure)

Therefore, if I extend GroovyShellTestCase, I can rewrite my test as:

class ScriptTests extends GroovyShellTestCase {
    void testMath() {
        def result = withBinding( [x:3, y:4] ) {
            shell.evaluate(new File('math.groovy'))
            shell.context.z
        }
        assertEquals 7, result
    }
}

The map supplies x and y to the binding, which is automatically supplied to the instantiated shell. I can get the result by calling the getContext method on the shell (i.e., access the context property) which returns the binding, and then accessing its z property. I’m taking advantage of the fact that the implementation of the withBinding method includes “return closure.call()“, so the last evaluated expression in the closure is returned automatically.

This isn’t a huge deal, but it’s there and presumably it’s been there for a while and I never knew it. Now I know. Even better, now you know. Maybe you’ll have a use case that needs it. I’ve been trying to make sure that all my scripts in my book have test cases, and this gives me a convenient way to write them.

My only disappointment in discovering this is that when I looked for the tests for the GroovyShellTestCase class, I didn’t find any. In the Groovy distribution under src/test/groovy/util, there’s GroovyScriptEngineTest, GroovyTestCaseTest, and even GroovySwingTestCase, but no dedicated class for testing GroovyShellTestCase. Maybe that’s my opportunity to add one and make a (tiny, but useful) contribution to the language. That would be fund to do just to write a class called GroovyShellTestCaseTest. Heck, that’s only one small step away from the palindromic GroovyShellTestCaseTestShell.groovy. 🙂

%d bloggers like this: