Log Raw HTTP Requests/Responses for better Debugging of the REST API (Part 4)

In my previous three blogs, I wrote about creating a REST service, how to exclude properties and to customize the response of the RESTService API.

In this blog, I want to show a simple but effective method to log all requests to REST API.

This kind of logging feature is not part of the core of Grails.
To achieve an http request logging you can either use this plugging or make use of Tomcat’s 7 request dumper filter.

Here I will present the use of Tomcat’s Request Dumper Filter.

Installation of Grails Templates

At first, install the Grails Templates:

grails install-templates

Now various templates, which support enhanced code generation, are installed under /src/templates.

Register the Request Dumper Filter

Navigate to:

/src
   /templates
      /war
         /web.xml

then edit web.xml, add the Tomcat filter and its filter mapping:

    <filter>
        <filter-name>requestdumper</filter-name>
        <filter-class>org.apache.catalina.filters.RequestDumperFilter</filter-class>
    </filter>

    <filter-mapping>
        <filter-name>requestdumper</filter-name>
        <url-pattern>*</url-pattern>
    </filter-mapping>

Bear in mind, that this filter is applied to every url. So every request has to pass this filter.
Which is good for debugging purposes, but rethink its usage, if you want to go into production.

Next edit the log4j configuration in /conf/Config.groovy and add a debug entry and the RequestDumperFilter. This step enables the output in console.

// log4j configuration
log4j = {
    ...
    error  'org.codehaus.groovy.grails.web.servlet',        // controllers
           'org.codehaus.groovy.grails.web.pages',          // GSP
           'org.codehaus.groovy.grails.web.sitemesh',       // layouts
           'org.codehaus.groovy.grails.web.mapping.filter', // URL mapping
           'org.codehaus.groovy.grails.web.mapping',        // URL mapping
           'org.codehaus.groovy.grails.commons',            // core / classloading
           'org.codehaus.groovy.grails.plugins',            // plugins
           'org.codehaus.groovy.grails.orm.hibernate',      // hibernate integration
           'org.springframework',
           'org.hibernate',
           'net.sf.ehcache.hibernate'
   debug   'org.apache.catalina.filters.RequestDumperFilter' 
}

Usage

Start the Grails app, fire a curl command

grails run-app
...
curl -X GET -H "Accept:application/json" http://localhost:8080/RESTService/api/city

and see the logged information of the http request:

|Server running. Browse to http://localhost:8080/RESTService
2014-03-12 17:01:47,998 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4 START TIME        =12-Mrz-2014 19:01:47
2014-03-12 17:01:47,999 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4         requestURI=/RESTService/api/city
2014-03-12 17:01:47,999 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4           authType=null
2014-03-12 17:01:47,999 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4  characterEncoding=utf-8
2014-03-12 17:01:48,000 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4      contentLength=-1
2014-03-12 17:01:48,000 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4        contentType=null
2014-03-12 17:01:48,000 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4        contextPath=/RESTService
2014-03-12 17:01:48,000 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4             cookie=com.springsource.sts.run.embedded=true
2014-03-12 17:01:48,002 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4             header=host=localhost:8080
2014-03-12 17:01:48,003 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4             header=accept=text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
2014-03-12 17:01:48,003 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4             header=connection=keep-alive
2014-03-12 17:01:48,003 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4             header=cookie=com.springsource.sts.run.embedded=true
2014-03-12 17:01:48,003 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4             header=user-agent=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_2) AppleWebKit/537.74.9 (KHTML, like Gecko) Safari/522.0
2014-03-12 17:01:48,003 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4             header=accept-language=de-de
2014-03-12 17:01:48,004 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4             header=cache-control=max-age=0
2014-03-12 17:01:48,004 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4             header=accept-encoding=gzip, deflate
2014-03-12 17:01:48,004 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4             locale=de_DE
2014-03-12 17:01:48,004 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4             method=GET
2014-03-12 17:01:48,005 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4           pathInfo=null
2014-03-12 17:01:48,005 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4           protocol=HTTP/1.1
2014-03-12 17:01:48,005 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4        queryString=null
2014-03-12 17:01:48,005 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4         remoteAddr=0:0:0:0:0:0:0:1
2014-03-12 17:01:48,005 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4         remoteHost=0:0:0:0:0:0:0:1
2014-03-12 17:01:48,006 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4         remoteUser=null
2014-03-12 17:01:48,006 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4 requestedSessionId=null
2014-03-12 17:01:48,006 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4             scheme=http
2014-03-12 17:01:48,006 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4         serverName=localhost
2014-03-12 17:01:48,006 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4         serverPort=8080
2014-03-12 17:01:48,006 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4        servletPath=/api/city
2014-03-12 17:01:48,006 [http-bio-8080-exec-4] INFO  filters.RequestDumperFilter  - http-bio-8080-exec-4           isSecure=false

As you see, with just a few lines of configuration code, we get a lot of various informations about the http request.

Pretty cool and super easy!

Summary

The use of Tomcat’s 7 Request Dumper Filter and its configuration in Grails 2.3.x is shown.
It is nice way to monitor http request traffic to a REST API and a great help for debugging.

HTH
Johannes

Advertisements
This entry was posted in Development, Grails and tagged , , , . Bookmark the permalink.

One Response to Log Raw HTTP Requests/Responses for better Debugging of the REST API (Part 4)

  1. Antonio says:

    Great Article !

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s