Thursday, November 29, 2012

Log4jdbc+Grails+Tomcat7

As your Grails application grows in size and popularity you will find yourself with performance and concurrency problems to overcome. As part of this process you will likely find yourself debugging the raw sql sent to the database. Hibernate comes with functionality to do this, but it is not very most user friendly. The most popular tool for sql debugging is P6spy, but an up and coming alternative is Log4jdbc. Log4jdbc works similar to P6Spy in that you replace your usual sql driver with one provided by the tool.
 //driverClassName = "org.h2.Driver"
  driverClassName = "net.sf.log4jdbc.DriverSpy"

You then have to make a change to the database connection url. You must add log4jdbc to the protocol component. Log4jdbc should then be able to detect for which driver it is proxying for.
jdbc:log4jdbc:mysql://localhost/mydatabase
Next you need to add appropriately to the logging configuration of your Grails app. Log4jdbc provides lots of options. I like to use jdbcsqltiming; it captures the sql statements, and their duration:
info 'jdbcsqltiming'
If you try the above in your development environment, it should work well. Now we move to trying to add it to a production / staging environment which uses Tomcat7 and MySql. If you simply try to apply the same settings as above, you might see the following error:
ClassNotFoundException net.sf.log4jdbc.DriverSpy
The reason for this is due to how Tomcat7 requires jdbc drivers to be placed in a common lib folder such as $TOMCAT_HOME/lib. So like your typical database driver, log4jdbc's must also be placed in the common lib folder. Unfortunately the log4jdbc driver has a number of logging related dependencies, so you must also place these in the common lib folder. Here is what I added to $TOMCAT_HOME/lib :
commons-logging-1.1.1.jar
jcl-over-slf4j-1.6.2.jar
jul-to-slf4j-1.6.2.jar
log4j-1.2.16.jar
log4jdbc4-1.2.jar
slf-api-1.6.4.jar
slf4j-log4j12-1.6.4.jar
You might see some warnings about your path containing multiple SLF4J bindings, but regardless your application should now be working with sql statements flying into your logs.

Wednesday, November 21, 2012

How to include session id and username in Grails logs

Introduction

It can be very useful in debugging problems to include the session id and the logged in user's username in your logs. Of course you can do it manually in every applicable log, but there is another way, a more Spring/Grails like way.

There is a feature in log4J called Mapped Diagnostic Context (MDC). This enables the storing of thread/request/context specific values in a map, that can be included in log output. To store something in this map you would write code like the following:

import org.apache.log4j.MDC
...
MDC.put("username", username)
This entry in the MDC map can then be referenced in an application's log4J conversion pattern. To add the username defined above you would have a pattern like:
%c{2} %X{username} %m%n

Grails Example

Let's now move to an example of how once could take advantage of MDC in Grails. Firstly, create a filter which will populate the MDC map. Such a filter could look like if you are using Spring Security:

class MyFilters {
  
  def springSecurityService

  def filters = {
    addAdditionalRequestInfoToLogs(controller: '*', action: '*') {
      before = {   
        MDC.clear()     
        MDC.put("sessionId", "[$session.id]")
        // try catch is good here because otherwise an error ends 
        // up creating stackoverflow scenario
        try { 
          def username = springSecurityService.principal?.username
          if (username) MDC.put("username", "[$username]")
        } catch (Exception e) { log.error "$e" }
      }
    }
  }

}

Now you only need to update your logging config and you wil be done. Open up your Config.groovy and track down your existing logging pattern definition. Here is one I have for development:

appenders {
      console name:'stdout', 
              layout: pattern(conversionPattern: '%c{2} %m%n')
    }

Now add references to the data we have put in the MDC:

appenders {
      console 
        name:'stdout', 
        layout: pattern(conversionPattern: '%c{2} %X{sessionId} %X{username} %m%n')
}

And that's it. You should be good to go for more informative logging!

Credits

Tuesday, November 20, 2012

Getting started with Grails functional tests using Geb + Spock

Introduction

There are a number of different functional test frameworks that can be used with Grails. Each of which can be incorporated into the overall test infrastructure of your Grails app by including the relevant plugin:

Grails doesn't hold any opinion on which one to choose. This is fair, and gives developers choice, but it can also be a headache; one has to make the choice of which framework, and also do the necessary setup and configuration. The functional test framework of the day is currently Geb, which builds on top of another functional framework in WebDriver. Geb can be used with the test runners JUnit, TestNG, or Spock. Spock, like Geb is the tool dejour and they are commonly used together. The best thing about Spock tests is that they are easy to read.

New Dependencies in your BuildConfig

To run your functional tests you need to include a number of libraries and plugins in your BuildConfig.groovy. Here is what you typically need to merge in:
grails.project.dependency.resolution = {
  def gebVersion = "0.7.0"
  def seleniumVersion = "2.25.0"
  dependencies {
      // Geb Spock integration
      test "org.codehaus.geb:geb-spock:$gebVersion"
      // Various webdrivers to drive your tests in different browsers
      test "org.seleniumhq.selenium:selenium-firefox-driver:$seleniumVersion"
      test "org.seleniumhq.selenium:selenium-chrome-driver:$seleniumVersion"
      test "org.seleniumhq.selenium:selenium-ie-driver:$seleniumVersion"
      test("org.seleniumhq.selenium:selenium-htmlunit-driver:$seleniumVersion") {
        exclude 'xml-apis'
      }
  }
  plugins {
      test ":geb:0.6.3"
      test ":spock:0.6"
      // Not required, but very useful in speeding up working with functional tests
      compile ":functional-test-development:0.9.3"
      compile ":funky-test-load:0.3.9"
  }
}

Add Geb Config

Create a new file test/functional/GebConfig.groovy Add the following content:
/*
 This is the Geb configuration file.
 
 See: http://www.gebish.org/manual/current/configuration.html
*/

import org.openqa.selenium.htmlunit.HtmlUnitDriver
import org.openqa.selenium.firefox.FirefoxDriver
import org.openqa.selenium.chrome.ChromeDriver

// Use htmlunit as the default
// See: http://code.google.com/p/selenium/wiki/HtmlUnitDriver
driver = { 
 def driver = new HtmlUnitDriver()
 driver.javascriptEnabled = true
 driver
}

environments {

 // run as “grails -Dgeb.env=chrome test-app”
 // See: http://code.google.com/p/selenium/wiki/ChromeDriver
 chrome {
  driver = { new ChromeDriver() }
 }

 // run as “grails -Dgeb.env=firefox test-app”
 // See: http://code.google.com/p/selenium/wiki/FirefoxDriver
 firefox {
  driver = { new FirefoxDriver() }
 }

}

Install Chrome Driver

The above listed chrome-driver library in BuildConfig is not enough to run your tests in Chrome. You also need to install on your development system an OS specific driver that acts as a bridge between what is included by the BuildConfig and the browser itself. You can find this driver here: http://code.google.com/p/selenium/wiki/ChromeDriver
  • Download, unzip the driver suitable for your development machine Place it somewhere nice I put mine in: ~/Dev/apps/chromedriver/
  • Add that folder location to your PATH export PATH=$PATH:~/Dev/apps/chromedriver

Define a Spec

The test specifications and pages are obviously going to be different for each app. I'm including a sample here, but to find out how to write specs and pages for your application consult the very comprehensive Book of Geb.
Sample Spec (test/functional/SignUpSpec.groovy):
import geb.spock.GebReportingSpec
import geb.spock.GebSpec
import spock.lang.*
import pages.*

@Stepwise
class SignUpSpec extends GebSpec {

  def "signup new customer"() {
    when:
    to SignUpFormPage, campaign: 1
    firstName = "Eamonn"
    lastName = "O'Connell"
    username = "eamonn2@stratus5.com"
    password = "x2l43j23lk4mallls"
    passwordConfirmation = "x2l43j23lk4mallls"
    orgName = "eamotest"
    addressLine1 = "GEC"
    city = "Dublin"
    signUpButton.click()

    then:
    at SignUpCompletePage 
  }

}

Sample Page (test/functional/pages/SignUpFormPage.groovy)
package pages

class SignUpFormPage extends geb.Page {

  static at = {
  heading.text() == "Sign Up"
 }
  
  static url = "signUp"

  static content = {
    firstName            { $("#firstName")                         }
    lastName             { $("#lastName")                          }
    username             { $("#username")                          }
    password             { $("input[name=password]")               }
    passwordConfirmation { $("input[name=password2]")              }
    signUpButton         { $("#submit")                            }
    orgName              { $("#orgName")                           }
    addressLine1         { $("input[name='address.addressLine1']") }
    addressLine2         { $("input[name='address.addressLine2']") }
    city                 { $("input[name='address.city']")         }
    county               { $("input[name='address.county']")       }
    zip                  { $("input[name='address.zip']")          }
    tel                  { $("#tel")                               }
  }

}
As you can see from the above defining tests using Specs and Pages is a thing of beauty.

Executing your tests

The typical way of running your grails tests is to run the test-app command like as follows:
grails test-app functional:
This works well enough, but you can find you end up waiting a lot as each test run requires the starting up of an instance of your grails app. An improvement to this process is to use the functional-test-development plugin included in the BuildConfig above. If you have included this plugin, you can run the following command:
grails develop-functional-tests
This will start up an instance of your application, and then display a console prompt with which you can run functional tests with over and over again. You can also restart the running app from the console, and there is a very handy feature where hitting the return key will run the previous test command.
grails funky-test-load
The funky test load plugin is my functional test runner of choice. It is actually inspired in part by the functional-test-development plugin. With it you can run your tests just as you would with the functional-test-development plugin, but it also enables you to also run the same test concurrently. Imagine emulating ten users signing up to your test server with a few keyboard strokes. I find it a real help in being able to reproduce troublesome concurrent issues like optimistic locking errors.

Tip: To run your test with Chrome add -Dgeb.env=chrome to the develop-functional-test console.
You can run into a few hiccups to be aware of:
  • The Grails app that runs is using the test environment, so be sure your Config.groovy is ready for that.
  • The plugin specifies memory settings for the app to run. If you have already specified memory settings in the JAVA_OPTS or GRAILS_OPTS environment variables then it will pull the memory settings from that. Otherwise it will add default ones. Now in my case, I have memory settings defined in JAVA_OPTS, and the plugin's code for parsing was not grabbing all of the settings. I had to hack the plugin a bit to get it working. It could be just how I defined the settings or it could be a bug that might well be fixed by the time you read this.

Credits