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.

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:

1. log in to my Grails application
2. receive a JSESSIONID cookie in response
3. 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.

Use XMLs not groovy scripts with db migration plugin!

I have 48 domain classes in my Grails 2.1 project and I use Grails Database Migration Plugin 1.2 for a database management. Recently I've noticed that it becomes terribly slow when running application, even if there are no changes to be applied.

I switched do debug logging level for liquibase package and I found that it takes about 15 seconds to parse changelog.groovy and 20 files that were included in it!

Prepare benchmark

I couldn't belive it so I've created two new clean changelogs:

$ grails dbm-generate-changelog changelog.groovy
$ grails dbm-generate-changelog changelog.xml

Both of these changelogs contain 229 change sets. It is enough that you can benchmark parsers for them. Two parsers in question are:

• grails.plugin.databasemigration.GrailsChangeLogParser
• liquibase.parser.core.xml.XMLChangeLogSAXParser

I need to modify a line in my Config.groovy and switch changelog.groovy with changelog.xml for a second test:

grails.plugin.databasemigration.updateOnStart = true
grails.plugin.databasemigration.updateOnStartFileNames = ["changelog.groovy"]
// grails.plugin.databasemigration.updateOnStartFileNames = ["changelog.xml"]

Profile with JProfiler

I want to profile execution time. I use JProfiler from ej-technologies to measure execution times. Please notice that I don't want to benchmark SQL queries performed by liquibase. I am only focused on parse method of these two classes.

Here's how I set up JProfiler:

I switch to CPU Views - Method statistics and I click "Record". Here are results for both parsers:

Results for changelog.groovy

Results for changelog.xml

Analysis

My assumptions were correct: 8 339 ms vs 139 ms. Parsing XML is 60 times faster! I want to jump and sing: "I switch to XML now!", but I have some concerns. I have a production database that I need to be compatible with. And I should rewrite my all groovy changelog files by hand. So it's not so trivial and it's a time consuming and error prone task.

So as much as I want to switch to XML now, I won't. But if you start your adventure with database migration plugin today I have an advice for you: use XML if you start from scratch.

For now I've just submitted a new JIRA issue - GrailsChangeLogParser - parse method is very slow and I hope it can be greatly improved.

Grails render as JSON catch

One of a reasons your controller doesn't render a proper response in JSON format might be wrong package name that you use. It is easy to overlook. Import are on top of a file, you look at your code and everything seems to be fine. Except response is still not in JSON format.

Consider this simple controller:

class RestJsonCatchController {
    def grailsJson() {
        render([first: 'foo', second: 5] as grails.converters.JSON)
    }

    def netSfJson() {
        render([first: 'foo', second: 5] as net.sf.json.JSON)
    }
}

And now, with finger crossed... We have a winner!

$ curl localhost:8080/example/restJsonCatch/grailsJson
{"first":"foo","second":5}
$ curl localhost:8080/example/restJsonCatch/netSfJson
{first=foo, second=5}

As you can see only grails.converters.JSON converts your response to JSON format. There is no such converter for net.sf.json.JSON, so Grails has no converter to apply and it renders Map normally.

Conclusion: always carefully look at your imports if you're working with JSON in Grails!

Edit: Burt suggested that this is a bug. I've submitted JIRA issue here: GRAILS-9622 render as class that is not a codec should throw exception

Inconsistent Dependency Injection to domains with Grails

I've encountered strange behavior with a domain class in my project: services that should be injected were null. I've became suspicious as why is that? Services are injected properly in other domain classes so why this one is different?

Constructors experiment

I've created an experiment. I've created empty LibraryService that should be injected and Book domain class like this:

Book has 4 explicit constructors. I want to check which constructor is injecting dependecies. This is my method that constructs Book objects and I called it in controller:

class BookController {
    def index() {
        constructAndExamineBooks()
    }

    static constructAndExamineBooks() {
        println("Started constructAndExamineBooks")
        Book book1 = new Book().logInjectedService()
        Book book2 = new Book("foo").logInjectedService()
        Book book3 = new Book("foo", 'bar').logInjectedService()
        Book book4 = new Book("foo", 'bar', 100).logInjectedService()
        Book book5 = new Book(author: "foo", title: 'bar')
        println("Finished constructor Book(Map params)")
        book5.logInjectedService()
    }
}

Analysis

Output looks like this:

What do we see?

1. ✔

   Empty constructor injects dependencies.

2. ✔

   Constructor that invokes empty constructor explicitly injects dependencies.

3. ✘

   Constructor that invokes parent's constructor explicitly does not inject dependencies.

4. ✘

   Constructor without any explicit call declared does not call empty constructor thus it does not inject dependencies.

5. ✔

   Constructor provied by Grails with a map as a parameter invokes empty constructor and injects dependencies.

Conclusion

Always explicitily invoke empty constructor in your Grail domain classes to ensure Dependency Injection! I didn't know until today either!

Classloader problem with Java 7 and WebServices in Grails

Our Grails 2.1 application communicates with external SOAP WebServices. It worked fine as we follow Software Guy's advices from this blog post.

Recently, our client required new functionality - export to Excel. We've used Apache POI libraries for export. And our web service communication died. All it gave us was:

Caused by: java.lang.LinkageError: loader constraint violation: when resolving field "DATETIME" the class loader (instance of org/codehaus/groovy/grails/cli/support/GrailsRootLoader) of the referring class, javax/xml/datatype/DatatypeConstants, and the class loader (instance of ) for the field's resolved type, ants, have different Class objects for that type

This message is strange, LinkageError can give you creeps. But read carefully: resolved type, ants? Something is definitely wrong here. After many searches it turned out that Java 7 already contains some conflicting classes from stax-api.jar. To solve this problem there are two thing you need to do:

1. Ensure that your jaxws-rt dependency is runtime, not compile!

   // http://asoftwareguy.com/2012/02/25/web-service-clients-where-grails-lost-its-mojo/
   // Do not remove this dependency. Web services need this to work flawlessly.
   runtime ('com.sun.xml.ws:jaxws-rt:2.1.4')

2. Create dependency report (grails dependency-report), search and exclude all stax-api dependencies other than jaxws-rt like this example:

   compile ('org.apache.poi:poi-ooxml-3.7') {
       excludes 'stax-api'
   }
   compile ('org.apache.poi:poi-ooxml-schemas:3.7') {
       excludes 'stax-api'
   }

How to use mocks in controller tests

Even since I started to write tests for my Grails application I couldn't find many articles on using mocks. Everyone is talking about tests and TDD but if you search for it there isn't many articles.

Today I want to share with you a test with mocks for a simple and complete scenario. I have a simple application that can fetch Twitter tweets and present it to user. I use REST service and I use GET to fetch tweets by id like this: http://api.twitter.com/1/statuses/show/236024636775735296.json. You can copy and paste it into your browser to see a result.

My application uses Grails 2.1 with spock-0.6 for tests. I have TwitterReaderService that fetches tweets by id, then I parse a response into my Tweet class.

TwitterController plays main part here. Users call show action along with id of a tweet. This action is my subject under test. I've implemented some basic functionality. It's easier to focus on it while writing tests.

Let's start writing a test from scratch. Most important thing here is that I use mock for my TwitterReaderService. I do not construct new TwitterReaderService(), because in this test I test only TwitterController. I am not interested in injected service. I know how this service is supposed to work and I am not interested in internals. So before every test I inject a twitterReaderServiceMock into controller:

Now it's time to think what scenarios I need to test. This line from TwitterReaderService is the most important:

You must think of this method like a black box right now. You know nothing of internals from controller's point of view. You're only interested what can be returned for you:

• a TwitterError can be thrown
• null can be returned
• Tweet instance can be returned

This list is your test blueprint. Now answer a simple question for each element: "What do I want my controller to do in this situation?" and you have plan test:

• show action should redirect to index if TwitterError is thrown and inform about error
• show action should redirect to index and inform if tweet is not found
• show action should show found tweet

That was easy and straightforward! And now is the best part: we use twitterReaderServiceMock to mock each of these three scenarios!

In Spock there is a good documentation about interaction with mocks. You declare what methods are called, how many times, what parameters are given and what should be returned. Remember a black box? Mock is your black box with detailed instruction, e.g.: I expect you that if receive exactly one call to readTweet with parameter '1' then you should throw me a TwitterError. Rephrase this sentence out loud and look at this:

This is a valid interaction definition on mock! It's that easy! Here is a complete test that fails for now:

You may notice 0 * _._ notation. It says: I don't want any other mocks or any other methods called. Fail this test if something is called! It's a good practice to ensure that there are no more interactions than you want.

Ok, now I need to implement controller logic to handle TwitterError.

My tests passes! We have two scenarios left. Rule stays the same: TwitterReaderService returns something and we test against it. So this line is the heart of each test, change only returned values after >>:

Here is a complete test for three scenarios and controller that passes it.

The most important thing here is that we've tested controller-service interaction without logic implementation in service! That's why mock technique is so useful. It decouples your dependencies and let you focus on exactly one subject under test. Happy testing!