DDevelopment & Design

Log4j and MDC in Grails

Log4j provides very useful feature: MDC – mapped diagnostic context. It can be used to store data in context of current thread. It may sound scary a bit but idea is simple. My post is based on post http://burtbeckwith.com/blog/?p=521 from Burt Beckwith’s excellent blog, it’s definitely worth checking if you are interested in Grails. Short background story… Suppose we want to do logging our brand new shopping system and we want to have in each log customer’s shopping basket number. And our system can be used at once by many users who can perform many transactions, actions like adding items and so on. How can we achieve that? Of course we can add basket number in every place where we do some logging but this task would be boring and error-prone.  Instead of this we can use MDC to store variable with basket number in map.  In fact MDC can be treated as map of custom values for current thread that can be used by logger.  How to do that with Grails? Using MDC with Grails is quite simple. All we need to do is to create our own custom filter which works for given urls and puts our data in MDC. Filters in Grails are classes in directory grails-app/conf/* which names end with *Filters.groovy postfix. We can create this class manually or use Grails command:  grails create-filters info.rnowak.App.Basket In result class named BasketFilters will be created in grails-app/conf/info/rnowak/UberApp. Initially filter class looks a little bit empty: class BasketFilters { def filters = { all(controller:'*', action:'*') { before = { } after = { Map model -> } afterView = { Exception e -> } } }} All we need to do is fill empty closures, modify filter properties and put some data into MDC. all is the general name of our filter, as class BasketFilters (plural!) can contain many various filters. You can name it whatever you want, for this post let assume it will be named basketFilter. Another thing is change of filter parameters. According to official documentation (link) we can customize our filter in many ways. You can specify controller to be filtered, its actions, filtered urls and so on. In our example you can stay with default option where filter is applied to every action of every controller. If you are interested in filtering only some urls, use uri parameter with expression describing desired urls to be filtered.Three closures that are already defined in template have their function and they are started in these conditions: before – as name says, it is executed before filtered action takes place after – similarly, it is called after the action afterView – called after rendering of the actions view Ok, so now we know what are these mysterious methods and when they are called. But what can be done within them? In official Grails docs (link again) under section 7.6.3 there is a list of properties that are available to use in filter. With that knowledge, we can proceed to implementing filter. Putting something into MDC in filter What we want to do is quite easy: we want to retrieve basket number from parameters and put it into MDC in our filter: class BasketFilters { def filters = { basketFilter(controller:'*', action:'*') { before = { MDC.put("basketNumber", params.basketNumber ?: "") } after = { Map model -> MDC.remove("basketNumber") } } }} We retrieve basket number from Grails params map and then we put in map under specified key (“basketNumber” in this case), which will be later used in logger conversion pattern. It is important to remove custom value after processing of action to avoid leaks. So we are putting something into MDC. But how make use of it in logs? We can refer to custom data in MDC in conversion patter using syntax: %X{key}, where key is our key we used in filter to put data, like: def conversionPattern = "%d{yyyy-MM-dd HH:mm:ss} %-5p %t [%c{1}] %X{basketNumber} - %m%n" And that’s it :) We’ve put custom data in log4j MDC and successfully used it in logs to display interesting values.
Log4j provides very useful feature: MDC – mapped diagnostic context. It can be used to store data in context of current thread. It may sound scary a bit but idea is simple. My post is based on post http://burtbeckwith.com/blog/?p=521 from Burt Beckwith’s excellent blog, it’s definitely worth checking if you are interested in Grails.

Short background story…

Suppose we want to do logging our brand new shopping system and we want to have in each log customer’s shopping basket number. And our system can be used at once by many users who can perform many transactions, actions like adding items and so on. How can we achieve that? Of course we can add basket number in every place where we do some logging but this task would be boring and error-prone.
Instead of this we can use MDC to store variable with basket number in map.
In fact MDC can be treated as map of custom values for current thread that can be used by logger.

How to do that with Grails?

Using MDC with Grails is quite simple. All we need to do is to create our own custom filter which works for given urls and puts our data in MDC.
Filters in Grails are classes in directory grails-app/conf/* which names end with *Filters.groovy postfix. We can create this class manually or use Grails command: 
grails create-filters info.rnowak.App.Basket
  
In result class named BasketFilters will be created in grails-app/conf/info/rnowak/UberApp. Initially filter class looks a little bit empty: 

class BasketFilters {
    def filters = {
        all(controller:'*', action:'*') {
            before = {

            }
            after = { Map model ->

            }
            afterView = { Exception e ->

            }
        }
    }
}

All we need to do is fill empty closures, modify filter properties and put some data into MDC.

all is the general name of our filter, as class BasketFilters (plural!) can contain many various filters. You can name it whatever you want, for this post let assume it will be named basketFilter.  Another thing is change of filter parameters. According to official documentation (link) we can customize our filter in many ways. You can specify controller to be filtered, its actions, filtered urls and so on. In our example you can stay with default option where filter is applied to every action of every controller. If you are interested in filtering only some urls, use uri parameter with expression describing desired urls to be filtered. Three closures that are already defined in template have their function and they are started in these conditions:

  • before – as name says, it is executed before filtered action takes place
  • after – similarly, it is called after the action
  • afterView – called after rendering of the actions view
Ok, so now we know what are these mysterious methods and when they are called. But what can be done within them? In official Grails docs (link again) under section 7.6.3 there is a list of properties that are available to use in filter.
With that knowledge, we can proceed to implementing filter.

Putting something into MDC in filter

What we want to do is quite easy: we want to retrieve basket number from parameters and put it into MDC in our filter: 
class BasketFilters {
    def filters = {
        basketFilter(controller:'*', action:'*') {
            before = {
                MDC.put("basketNumber", params.basketNumber ?: "")
            }
            after = { Map model ->
                MDC.remove("basketNumber")
            }
        }
    }
}
We retrieve basket number from Grails params map and then we put in map under specified key (“basketNumber” in this case), which will be later used in logger conversion pattern. It is important to remove custom value after processing of action to avoid leaks.

So we are putting something into MDC. But how make use of it in logs?

We can refer to custom data in MDC in conversion patter using syntax: %X{key}, where key is our key we used in filter to put data, like: 
def conversionPattern = "%d{yyyy-MM-dd HH:mm:ss} %-5p %t [%c{1}] %X{basketNumber} - %m%n"

And that’s it :) We’ve put custom data in log4j MDC and successfully used it in logs to display interesting values.

— Previous article

Targi Pracy na MIMUW

Next article —

Context menu or Action buttons ?

You May Also Like
DDevelopment & Design

Grails session timeout without XML

This article shows clean, non hacky way of configuring featureful event listeners for Grails application servlet context. Feat. HttpSessionListener as a Spring bean example with session timeout depending on whether user account is premium or not.

Common approaches

Speaking of session timeout config in Grails, a default approach is to install templates with a command. This way we got direct access to web.xml file. Also more unnecessary files are created. Despite that unnecessary files are unnecessary, we should also remember some other common knowledge: XML is not for humans.

Another, a bit more hacky, way is to create mysterious scripts/_Events.groovy file. Inside of which, by using not less enigmatic closure: eventWebXmlEnd = { filename -> ... }, we can parse and hack into web.xml with a help of XmlSlurper.
Even though lot of Grails plugins do it similar way, still it’s not really straightforward, is it? Besides, where’s the IDE support? Hello!?

Examples of both above ways can be seen on StackOverflow.

Simpler and cleaner way

By adding just a single line to the already generated init closure we have it done:
class BootStrap {


    def init = { servletContext ->    

        servletContext.addListener(OurListenerClass)    

    }    

}

Allrighty, this is enough to avoid XML. Sweets are served after the main course though :)

Listener as a Spring bean

Let us assume we have a requirement. Set a longer session timeout for premium user account.
Users are authenticated upon session creation through SSO.

To easy meet the requirements just instantiate the CustomTimeoutSessionListener as Spring bean at resources.groovy. We also going to need some source of the user custom session timeout. Let say a ConfigService.
beans = {    

    customTimeoutSessionListener(CustomTimeoutSessionListener) {    

        configService = ref('configService')    

    }    

}

With such approach BootStrap.groovy has to by slightly modified. To keep control on listener instantation, instead of passing listener class type, Spring bean is injected by Grails and the instance passed:
class BootStrap {


    def customTimeoutSessionListener


    def init = { servletContext ->    

        servletContext.addListener(customTimeoutSessionListener)

    }    

}

An example CustomTimeoutSessionListener implementation can look like:
import javax.servlet.http.HttpSessionEvent    

import javax.servlet.http.HttpSessionListener    

import your.app.ConfigService    


class CustomTimeoutSessionListener implements HttpSessionListener {    


    ConfigService configService


    @Override    

    void sessionCreated(HttpSessionEvent httpSessionEvent) {    

        httpSessionEvent.session.maxInactiveInterval = configService.sessionTimeoutSeconds

    }    


    @Override    

    void sessionDestroyed(HttpSessionEvent httpSessionEvent) { /* nothing to implement */ }    

}
Having at hand all power of the Spring IoC this is surely a good place to load some persisted user’s account stuff into the session or to notify any other adequate bean about user presence.

Wait, what about the user context?

Honest answer is: that depends on your case. Yet here’s an example of getSessionTimeoutMinutes() implementation using Spring Security:
import org.springframework.security.core.context.SecurityContextHolder    


class ConfigService {


    static final int 3H = 3 * 60 * 60

    static final int QUARTER = 15 * 60


    int getSessionTimeoutSeconds() {    


        String username = SecurityContextHolder.context?.authentication?.principal    

        def account = Account.findByUsername(username)    


        return account?.premium ? 3H : QUARTER

    }    

}
This example is simplified. Does not contain much of defensive programming. Just an assumption that principal is already set and is a String - unique username. Thanks to Grails convention our ConfigService is transactional so the Account domain class can use GORM dynamic finder.
OK, config fetching implementation details are out of scope here anyway. You can get, load, fetch, obtain from wherever you like to. Domain persistence, principal object, role config, external file and so on...

Any gotchas?

There is one. When running grails test command, servletContext comes as some mocked class instance without addListener method. Thus we going to have a MissingMethodException when running tests :(

Solution is typical:
def init = { servletContext ->

    if (Environment.current != Environment.TEST) {    

        servletContext.addListener(customTimeoutSessionListener)    

    }    

}
An unnecessary obstacle if you ask me. Should I submit a Jira issue about that?

TL;DR

Just implement a HttpSessionListener. Create a Spring bean of the listener. Inject it into BootStrap.groovy and call servletContext.addListener(injectedListener).