grails – Team Blog

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.

Grails with Spock unit test + IntelliJ IDEA = No thread-bound request found

During my work with Grails project using Spock test in IntelliJ IDEA I've encountered this error:

java.lang.IllegalStateException: No thread-bound request found: Are you referring to request attributes outside of an actual web request, or processing a request outside of the originally receiving thread? If you are actually operating within a web request and still receive this message, your code is probably running outside of DispatcherServlet/DispatcherPortlet: In this case, use RequestContextListener or RequestContextFilter to expose the current request.
 at org.springframework.web.context.request.RequestContextHolder.currentRequestAttributes(RequestContextHolder.java:131)
 at org.codehaus.groovy.grails.plugins.web.api.CommonWebApi.currentRequestAttributes(CommonWebApi.java:205)
 at org.codehaus.groovy.grails.plugins.web.api.CommonWebApi.getParams(CommonWebApi.java:65)
... // and few more lines of stacktrace ;)

It occurred when I tried to debug one of test from IDEA level. What is interesting, this error does not happen when I'm running all test using grails test-app for instance.

So what was the issue? With little of reading and tip from Tomek Kalkosiński (http://refaktor.blogspot.com/) it turned out that our test was missing @TestFor annotation and adding it solved all problems. This annotation, according to Grails docs (link), indicates Spock what class is being tested and implicitly creates field with given type in test class. It is somehow strange as problematic test had explicitly and "manually" created field with proper controller type. Maybe there is a problem with mocking servlet requests?

Spock basics

Spock (homepage) is like its authors say 'testing and specification framework'. Spock combines very elegant and natural syntax with the powerful capabilities. And what is most important it is easy to use.

One note at the very beginning: I assume that you are already familiar with principles of Test Driven Development and you know how to use testing framework like for example JUnit.

So how can I start?

Writing spock specifications is very easy. We need basic configuration of Spock and Groovy dependencies (if you are using mavenized project with Eclipse look to my previous post: Spock, Java and Maven). Once we have everything set up and running smooth we can write our first specs (spec or specification is equivalent for test class in other frameworks like JUnit of TestNG). What is great with Spock is fact that we can use it to test both Groovy projects and pure Java projects or even mixed projects.

Let's go!

Every spec class must inherit from spock.lang.Specification class. Only then test runner will recognize it as test class and start tests. We will write few specs for this simple class: User class and few tests not connected with this particular class.

We start with defining our class:

import spock.lang.*

class UserSpec extends Specification {

}

Now we can proceed to defining test fixtures and test methods.

All activites we want to perform before each test method, are to be put in def setup() {...} method and everything we want to be run after each test should be put in def cleanup() {...} method (they are equivalents for JUnit methods with @Before and @After annotations).

It can look like this:

class UserSpec extends Specification {
    User user
    Document document

    def setup() {
        user = new User()
        document = DocumentTestFactory.createDocumentWithTitle("doc1")
    }

    def cleanup() {

    }
}

Of course we can use field initialization for instantiating test objects:

class UserSpec extends Specification {
    User user = new User()
    Document document = DocumentTestFactory.createDocumentWithTitle("doc1")

    def setup() {

    }

    def cleanup() {

    }
}

What is more readable or preferred? It is just a matter of taste because according to Spock docs behaviour is the same in these two cases.

It is worth mentioning that JUnit @BeforeClass/@AfterClass are also present in Spock as def setupSpec() {...} and def cleanupSpec() {...}. They will be runned before first test and after last test method.

First tests

In Spock every method in specification class, expect setup/cleanup, is treated by runner as a test method (unless you annotate it with @Ignore).

Very interesting feature of Spock and Groovy is ability to name methods with full sentences just like regular strings:

class UserSpec extends Specification {
    // ...

    def "should assign coment to user"() {
        // ...
    }
}

With such naming convention we can write real specification and include details about specified behaviour in method name, what is very convenient when reading test reports and analyzing errors. Test method (also called feature method) is logically divided into few blocks, each with its own purpose. Blocks are defined like labels in Java (but they are transformed with Groovy AST transform features) and some of them must be put in code in specific order. Most basic and common schema for Spock test is:

class UserSpec extends Specification {
    // ...

    def "should assign coment to user"() {
        given:
            // do initialization of test objects
        when:
            // perform actions to be tested
        then:
            // collect and analyze results
    }
}

But there are more blocks like:

setup
expect
where
cleanup

In next section I am going to describe each block shortly with little examples.

given block

This block is used to setup test objects and their state. It has to be first block in test and cannot be repeated. Below is little example how can it be used:

class UserSpec extends Specification {
    // ...
    
    def "should add project to user and mark user as project's owner"() {
        given:
            User user = new User()
            Project project = ProjectTestFactory.createProjectWithName("simple project")
        // ...
    }
}

In this code given block contains initialization of test objects and nothing more. We create simple user without any specified attributes and project with given name. In case when some of these objects could be reused in more feature methods, it could be worth putting initialization in setup method.

when and then blocks

When block contains action we want to test (Spock documentation calls it 'stimulus'). This block always occurs in pair with then block, where we are verifying response for satisfying certain conditions. Assume we have this simple test case:

class UserSpec extends Specification {
    // ...
    
    def "should assign user to comment when adding comment to user"() {
        given:
            User user = new User()
            Comment comment = new Comment()
        when:
            user.addComment(comment)
        then:
            comment.getUserWhoCreatedComment().equals(user)
    }

    // ...
}

In when block there is a call of tested method and nothing more. After we are sure our action was performed, we can check for desired conditions in then block. Then block is very well structured and its every line is treated by Spock as boolean statement. That means, Spock expects that we write instructions containing comparisons and expressions returning true or false, so we can create then block with such statements:

user.getName() == "John"
user.getAge() == 40
!user.isEnabled()

Each of lines will be treated as single assertion and will be evaluated by Spock. Sometimes we expect that our method throws an exception under given circumstances. We can write test for it with use of thrown method:

class CommentSpec extends Specification {
    def "should throw exception when adding null document to comment"() {
        given:
            Comment comment = new Comment()
        when:
            comment.setCommentedDocument(null)
        then:
            thrown(RuntimeException)
    }
}

In this test we want to make sure that passing incorrect parameters is correctly handled by tested method and that method throws an exception in response. In case you want to be certain that method does not throw particular exception, simply use notThrown method.

expect block

Expect block is primarily used when we do not want to separate when and then blocks because it is unnatural. It is especially useful for simple test (and according to TDD rules all test should be simple and short) with only one condition to check, like in this example (it is simple but should show the idea):

def "should create user with given name"() {
    given:
        User user = UserTestFactory.createUser("john doe")
    expect:
        user.getName() == "john doe"
}

More blocks!

That were very simple tests with standard Spock test layout and canonical divide into given/when/then parts. But Spock offers more possibilities in writing tests and provides more blocks.

setup/cleanup blocks

These two blocks have the very same functionality as the def setup and def cleanup methods in specification. They allow to perform some actions before test and after test. But unlike these methods (which are shared between all tests) blocks work only in methods they are defined in.

where - easy way to create readable parameterized tests

Very often when we create unit tests there is a need to "feed" them with sample data to test various cases and border values. With Spock this task is very easy and straighforward. To provide test data to feature method, we need to use where block. Let's take a look at little the piece of code:

def "should successfully validate emails with valid syntax"() {
    expect:
        emailValidator.validate(email) == true
    where:
        email << [ "test@test.com", "foo@bar.com" ]
}

In this example, Spock creates variable called email which is used when calling method being tested. Internally feature method is called once, but framework iterates over given values and calls expect/when block as many times as there are values (however, if we use @Unroll annotation Spock can create separate run for each of given values, more about it in one of next examples). Now, lets assume that we want our feature method to test both successful and failure validations. To achieve that goal we can create few parameterized variables for both input parameter and expected result. Here is a little example:

def "should perform validation of email addresses"() {
    expect:
        emailValidator.validate(email) == result
    where:
        email << [ "WTF", "@domain", "foo@bar.com" "a@test" 
        result << [ false, false, true, false ]
}

Well, it looks nice, but Spock can do much better. It offers tabular format of defining parameters for test what is much more readable and natural. Lets take a look:

def "should perform validation of email addresses"() {
    expect:
        emailValidator.validate(email) == result
    where:
        email           | result
        "WTF"           | false
        "@domain"       | false
        "foo@bar.com"   | true
        "a@test"        | false
}

In this code, each column of our "table" is treated as a separate variable and rows are values for subsequent test iterations. Another useful feature of Spock during parameterizing test is its ability to "unroll" each parameterized test. Feature method from previous example could be defined as (the body stays the same, so I do not repeat it):

@Unroll("should validate email #email")
def "should perform validation of email addresses"() {
    // ...
}

With that annotation, Spock generate few methods each with its own name and run them separately. We can use symbols from where blocks in @Unroll argument by preceding it with '#' sign what is a signal to Spock to use it in generated method name.

What next?

Well, that was just quick and short journey through Spock and its capabilities. However, with that basic tutorial you are ready to write many unit tests. In one of my future posts I am going to describe more features of Spock focusing especially on its mocking abilities.

Error generating web.xml file with IntelliJ IDEA

If you use IntelliJ IDEA for your Grails development you might encounter this error running integration tests:

Error Error generating web.xml file (Use --stacktrace to see the full trace)

The reason for this is that IDEA adds classpath by default on creating integration test run configuration. Unfortunately, sometimes it causes strange errors like this one. Follow these steps to resolve:

Open Run → Edit Configurations... (or press Alt-Shift-F10)
Select your configuration that fails
Uncheck Add --classpath checkbox
You are done! Run.

Simple trick to DRY your Grails controller

Grails controllers are not very DRY. It's easy to find duplicated code fragments in default generated controller. Take a look at code sample below. It is duplicated four times in show, edit, update and delete actions:

class BookController {
    def show() {
       def bookInstance = Book.get(params.id)
       if (!bookInstance) {
            flash.message = message(code: 'default.not.found.message', args: [message(code: 'book.label', default: 'Book'), params.id])
            redirect(action: "list")
            return
        }
        [bookInstance: bookInstance]
    }
}

Why is it duplicated?

There is a reason for that duplication, though. If you move this snippet to a method, it can redirect to "list" action, but it can't prevent controller from further execution. After you call redirect, response status changes to 302, but after method exits, controller still runs subsequent code.

Solution

At TouK we've implemented a simple trick to resolve that situation:

wrap everything with a simple withStoppingOnRender method,
whenever you want to render or redirect AND stop controller execution - throw EndRenderingException.

We call it Big Return - return from a method and return from a controller at once. Here is how it works:

class BookController {
    def show(Long id) {
        withStoppingOnRender {
            Book bookInstance = Book.get(id)
            validateInstanceExists(bookInstance)
            [bookInstance: bookInstance]
        }
    }

    protected Object withStoppingOnRender(Closure closure) {
        try {
            return closure.call()
        } catch (EndRenderingException e) {}
    }

    private void validateInstanceExists(Book instance) {
        if (!instance) {
            flash.message = message(code: 'default.not.found.message', args: [message(code: 'book.label', default: 'Book'), params.id])
            redirect(action: "list")
            throw new EndRenderingException()
        }
    }
}

class EndRenderingException extends RuntimeException {}

Example usage

For simple CRUD controllers, you can use this solution and create some BaseController class for your controllers. We use withStoppingOnRender in every controller so code doesn't look like a spaghetti, we follow DRY principle and code is self-documented. Win-win-win! Here is a more complex example:

class DealerController {
    @Transactional
    def update() {
        withStoppingOnRender {
            Dealer dealerInstance = Dealer.get(params.id)
            validateInstanceExists(dealerInstance)
            validateAccountInExternalService(dealerInstance)
            checkIfInstanceWasConcurrentlyModified(dealerInstance, params.version)
            dealerInstance.properties = params
            saveUpdatedInstance(dealerInstance)
            redirectToAfterUpdate(dealerInstance)
        }
    }
}

New HTTP Logger Grails plugin

I've wrote a new Grails plugin - httplogger. It logs:

request information (url, headers, cookies, method, body),
grails dispatch information (controller, action, parameters),
response information (elapsed time and body).

It is mostly useful for logging your REST traffic. Full HTTP web pages can be huge to log and generally waste your space. I suggest to map all of your REST controllers with the same path in UrlMappings, e.g. /rest/ and configure this plugin with this path.

Here is some simple output just to give you a taste of it.

17:16:00,331 INFO  filters.LogRawRequestInfoFilter  - << #1 GET http://localhost:8080/riddle/rest/index?username=admin&search=foo
17:16:00,340 INFO  filters.LogRawRequestInfoFilter  - << #1 headers Cookie: 'JSESSIONID=DF4EA5725AC4A4990281BD96963739B0; splashShown1.6=1', Accept-Language: 'en-US,en;q=0.8,pl;q=0.6', X-MyHeader: 'null'
17:16:00,342 INFO  filters.LogGrailsUrlsInfoFilter  - << #1 dispatched to rest/index with parsed params [username:[admin], search:[foo]].
17:16:00,731 INFO  filters.LogOutputResponseFilter  - >> #1 returned 200, took 405 ms.
17:16:00,745 INFO  filters.LogOutputResponseFilter  - >> #1 responded with '{count:0}'

17:18:55,799 INFO  filters.LogRawRequestInfoFilter  - << #2 POST http://localhost:8080/riddle/rest/login
17:18:55,799 INFO  filters.LogRawRequestInfoFilter  - << #2 headers Cookie: 'JSESSIONID=DF4EA5725AC4A4990281BD96963739B0; splashShown1.6=1', Accept-Language: 'en-US,en;q=0.8,pl;q=0.6', X-MyHeader: 'null'
17:18:55,800 INFO  filters.LogRawRequestInfoFilter  - << #2 body: 'username=admin&password=password'
17:18:55,801 INFO  filters.LogOutputResponseFilter  - >> #2 returned 404, took 3 ms.
17:18:55,802 INFO  filters.LogOutputResponseFilter  - >> #2 responded with ''

Official plugin information can be found on Grails plugins website here: http://grails.org/plugins/httplogger or you can browse code on github: TouK/grails-httplogger.

New HTTP Logger Grails plugin

I've wrote a new Grails plugin - httplogger. It logs:

request information (url, headers, cookies, method, body),
grails dispatch information (controller, action, parameters),
response information (elapsed time and body).

Here is some simple output just to give you a taste of it.

17:16:00,331 INFO  filters.LogRawRequestInfoFilter  - << #1 GET http://localhost:8080/riddle/rest/index?username=admin&search=foo
17:16:00,340 INFO  filters.LogRawRequestInfoFilter  - << #1 headers Cookie: 'JSESSIONID=DF4EA5725AC4A4990281BD96963739B0; splashShown1.6=1', Accept-Language: 'en-US,en;q=0.8,pl;q=0.6', X-MyHeader: 'null'
17:16:00,342 INFO  filters.LogGrailsUrlsInfoFilter  - << #1 dispatched to rest/index with parsed params [username:[admin], search:[foo]].
17:16:00,731 INFO  filters.LogOutputResponseFilter  - >> #1 returned 200, took 405 ms.
17:16:00,745 INFO  filters.LogOutputResponseFilter  - >> #1 responded with '{count:0}'

17:18:55,799 INFO  filters.LogRawRequestInfoFilter  - << #2 POST http://localhost:8080/riddle/rest/login
17:18:55,799 INFO  filters.LogRawRequestInfoFilter  - << #2 headers Cookie: 'JSESSIONID=DF4EA5725AC4A4990281BD96963739B0; splashShown1.6=1', Accept-Language: 'en-US,en;q=0.8,pl;q=0.6', X-MyHeader: 'null'
17:18:55,800 INFO  filters.LogRawRequestInfoFilter  - << #2 body: 'username=admin&password=password'
17:18:55,801 INFO  filters.LogOutputResponseFilter  - >> #2 returned 404, took 3 ms.
17:18:55,802 INFO  filters.LogOutputResponseFilter  - >> #2 responded with ''

Official plugin information can be found on Grails plugins website here: http://grails.org/plugins/httplogger or you can browse code on github: TouK/grails-httplogger.

Thought static method can’t be easy to mock, stub nor track? Wrong!

No matter why, no matter is it a good idea. Sometimes one just wants to check or it’s necessary to be done. Mock a static method, woot? Impossibru!

In pure Java world Read more

How to keep session in HttpBuilder with cookies

In my real-world scenario I have a REST service for AJAX purposes. It renders data series for graphs. I want to test it with groovy's excellent HttpBuilder. There is a problem though - these requests are only available for already logged in users.

In this post I present a complete solution to maintain a session state between HttpBuilder's requests.

Session in HttpBuilder

First of all a quick reminder about session. Session is a simulation of state for HTTP requests, which are stateless by its nature. Once you log in you receive a unique cookie (one or more) that identifies you for sequential requests. Every time you send request you send this cookie along. This way server recognizes you and matches you to your session, which is kept on server. Cookie gets invlid once you log out or it times out, for example after 20 minutes of inactivity. Next time you visit a page you get a new, unique cookie.

In order to keep session alive in HttpBuilder I need to:

log in to my Grails application
receive a JSESSIONID cookie in response
store that cookie and send it along with every subsenquential request

I've created RestConnector class that wraps up HttpBuilder. It's main improvement is that it keeps received cookie in a list.

package eu.spoonman.connectors.RestConnector

import groovyx.net.http.Method
import groovyx.net.http.ContentType
import groovyx.net.http.HTTPBuilder
import groovyx.net.http.HttpResponseDecorator

class RestConnector {
    private String baseUrl
    private HTTPBuilder httpBuilder
    private List<String> cookies

    RestConnector(String url) {
        this.baseUrl = url
        this.httpBuilder = initializeHttpBuilder()
        this.cookies = []
    }

    public def request(Method method, ContentType contentType, String url, Map<String, Serializable> params) {
        debug("Send $method request to ${this.baseUrl}$url: $params")
        httpBuilder.request(method, contentType) { request ->
            uri.path = url
            uri.query = params
            headers['Cookie'] = cookies.join(';')
        }
    }

    private HTTPBuilder initializeHttpBuilder() {
        def httpBuilder = new HTTPBuilder(baseUrl)

        httpBuilder.handler.success = { HttpResponseDecorator resp, reader ->
            resp.getHeaders('Set-Cookie').each {
                //[Set-Cookie: JSESSIONID=E68D4799D4D6282F0348FDB7E8B88AE9; Path=/frontoffice/; HttpOnly]
                String cookie = it.value.split(';')[0]
                debug("Adding cookie to collection: $cookie")
                cookies.add(cookie)
            }
            debug("Response: ${reader}")
            return reader
        }
        return httpBuilder
    }


    private debug(String message) {
        System.out.println(message) //for Gradle
    }
}

A few things to notice in a class above. Constructor sets base URL and creates HttpBuilder instance that can be reused. Next, there is a handler on successful request that checks if I receive any cookie. It adds received cookies to list. Finally, there is a request method that calls HttpBuilder#request but it adds cookies to HTTP headers so server can recognize me as a logged in user.

Sending cookies with every request is a core component in here. It simulates browser's behavior and maintains session.

How to use it?

I will show you how to use this utility class it in Spock test below. It is fairly simple.

First I login to my application and I ensure that I receive a cookie in return, which is equivalent to being logged in. Then I send a request with that cookie sent in HTTP header. This is a Spock test that implements it:

package eu.spoonman.specs.rest

import eu.spoonman.connectors.RestConnector.RestConnector
import groovyx.net.http.ContentType
import groovyx.net.http.Method
import spock.lang.Shared
import spock.lang.Specification
import spock.lang.Stepwise

@Stepwise
class RestChartSpec extends Specification {
    @Shared
    RestConnector restConnector

    def setupSpec() {
        restConnector = new RestConnector('http://localhost:8080')
    }

    def "should login as test"() {
        given:
            Map params = [j_username: 'test', j_password: 'test']
        when:
            restConnector.request(Method.POST, ContentType.ANY, '/frontoffice/j_spring_security_check', params)
        then:
            !(restConnector.cookies.empty)
    }

    def "should allow access to chart data series"() {
        given:
            Map params = [days: 14]
        when:
            Map result = restConnector.request(Method.POST, ContentType.JSON, "frontoffice/chart/series", params)
        then:
            result != null
            result.series.size() > 0
    }
}

I create a new RestConnector instance in setupSpec with my application's base URL. Please notice that it has @Shared annotation so it's shared between tests.

@Stepwise is crucial annotation for this specification. It means that Spock executes tests exactly in order they're defined. I need to ensure that login is executed first. I also need to assert that I receive a cookie and list is not empty. I could move this step into setupSpec method too, but I prefer it to be a first test in a specification.

Second test is always executed after login thus it sends cookies within request headers. This is exactly what I wanted to achieve.