The Flowers Are Still Standing

24 March 2014

The other day, I decided to attempt to switch a Grails application from using Log4j (the built-in option) for logging to Logback. The core Grails development team maintains a Grails Logback Plugin that appeared to be just what I needed. I started by modifying my Grails application’s pom.xml file to reference the Grails Logback Plugin:

pom.xml

<dependency>
    <groupId>org.grails.plugins</groupId>
    <artifactId>logback</artifactId>			(1)
    <version>0.3.1</version>
    <scope>compile</scope>
</dependency>

1 Note that the plugin is a binary plugin, so I did not need to specify the packaging as zip. If you are not using Maven support with your Grails application (or are using a version of Grails that did not yet support Maven POM files), you can include the Grails Logback Plugin in the dependencies block of your grails-app/conf/BuildConfig.groovy and NOT in the plugins block.

Additionally, I added the following global exclusions to grails-app/conf/BuildConfig.groovy, per the plugin’s instructions:

grails-app/conf/BuildConfig.groovy

// inherit Grails' default dependencies
inherits("global") {
    excludes 'grails-plugin-log4j', 'log4j'		(1)
}

1	If any other dependencies have a runtime dependency on `log4j`, you will need to remove it from the global excludes.

Follow the instructions, they said

In my first attempt at getting this working, I next moved on to changing the log4j closure in grails-app/conf/Config.groovy to logback, as the documentation suggests. Subsequent digging uncovered that the Grails Logback Plugin only initializes Logback using the DSL from grails-app/conf/Config.groovy if the application has been deployed as a WAR file to a container. What this means in practical terms is that when running a Grails application locally using the run-app command, you have no control over the Logback configuration via the DSL and thus every log statement gets printed using the default level, which is DEBUG (more on this in a bit…).

Back to my first attempt. With grails-app/conf/Config.groovy modified, I attempted to run my application, after performing the requisite clean called out by the documentation, but ran into compile errors related to code that was directly importing and using Log4j. I fixed these by switching any code that explicitly imported and used the Log4J Logger class to use the SLF4J Logger instead. I next ran into some AST transformation errors with classes that had the Groovy logging @Log4j annotation present. I switched these to use the SLF4J logging annotation (@SLF4J). The last issue that I encountered in my attempts to get the application to compile and start was related to something that Grails automatically puts in grails-app/conf/Config.groovy when generating a new application (NOTE: the application in question was built using Grails version 2.3.5). By default, when you generate a new application, the following gets added to the configuration:

grails-app/conf/Config.groovy

environments {
    development {
        grails.logging.jul.usebridge = true
    }
    production {
        grails.logging.jul.usebridge = false
    }
}

which enables the use of the SLF4J JUL bridge in the local environment. If you run the application with grails.logging.jul.usebridge = true AND have excluded the grails-plugin-log4j dependency, you will see the following error upon application start up:

| Error 2014-03-11 12:43:41,282 [localhost-startStop-1] ERROR o.c.g.g.w.c.GrailsContextLoader  - Error initializing the application: org.slf4j.bridge.SLF4JBridgeHandler
java.lang.NoClassDefFoundError: org.slf4j.bridge.SLF4JBridgeHandler
    at LogbackGrailsPlugin$_closure2.doCall(LogbackGrailsPlugin.groovy:45) ~[logback-0.3.1.jar:na]
    at grails.spring.BeanBuilder.invokeBeanDefiningClosure(BeanBuilder.java:756) ~[grails-spring-2.3.5.jar:2.3.5]
    at grails.spring.BeanBuilder.beans(BeanBuilder.java:584) ~[grails-spring-2.3.5.jar:2.3.5]
    at grails.spring.BeanBuilder.invokeMethod(BeanBuilder.java:527) ~[grails-spring-2.3.5.jar:2.3.5]
    at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_51]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_51]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_51]
    at java.lang.Thread.run(Thread.java:744) [na:1.7.0_51]
Message: org.slf4j.bridge.SLF4JBridgeHandler
    Line | Method
->>   45 | doCall                    in LogbackGrailsPlugin$_closure2
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
|    756 | invokeBeanDefiningClosure in grails.spring.BeanBuilder
|    584 | beans . . . . . . . . . . in     ''
|    527 | invokeMethod              in     ''
|    262 | run . . . . . . . . . . . in java.util.concurrent.FutureTask
|   1145 | runWorker                 in java.util.concurrent.ThreadPoolExecutor
|    615 | run . . . . . . . . . . . in java.util.concurrent.ThreadPoolExecutor$Worker
^    744 | run                       in java.lang.Thread

The fix for this is to ensure that org.slf4j:jul-to-slf4j:1.7.5 is included as a runtime dependency. If you are using an older version of Grails, check the lib directory of the Grails installation to determine the proper version of SLF4J to use. Also note that if you have any dependencies that require Log4J, you may also need to add that dependency to the classpath or remove it from the global excludes to get your application to start.

Using Logback with grails run-app

Let’s get back to the issue of the DSL only being used when the application is deployed as a WAR file. If you take a look at the plugin descriptor for the Grails Logback Plugin, you will notice this little snippet:

LogbackGrailsPlugin.groovy

def doWithSpring = {
    if (application.config?.grails?.logging?.jul?.usebridge) {					(1)
        LogManager.logManager.readConfiguration new ByteArrayInputStream(".level=INFO".bytes)
        SLF4JBridgeHandler.install()
    }

    if (application.warDeployed) {								(2)
        // only initialize here if deployed as a war since doWithWebDescriptor isn't called
        initLogging application
    }
}

1	`grails.logging.jul.usebridge` is set to `true` by default in `*Config.groovy` when creating a new Grails application/plugin in 2.3.x and above.
2	`warDeployed` comes from an entry in `application.properties` that is added by Grails when the WAR file is built using the `grails war` command.

Based on the code above, it appears that the DSL is only loaded when the WAR is deployed. This explains why no matter how many changes I made to the DSL, none of those changes were getting picked up. Being familiar with Logback, I knew that if you put a logback.groovy file on the classpath, Logback would automatically find and use it for configuration instead of the DSL. To test this theory, I put a new logback.groovy file in grails-app/conf to ensure it was on the classpath. I also added the following the grails-app/conf/BootStrap.groovy to verify which configuration Logback had selected:

grails-app/conf/BootStrap.groovy

def init = { servletContext ->
    StatusPrinter.print((LoggerContext) LoggerFactory.getILoggerFactory())		(1)
}

1	Useful line of code to enable Logback to print out which (if any) configuration file it loaded.

After another application restart, I noticed that Logback was still not picking up my configuration. I did a quick check of target/classes to confirm a suspicion that Grails had compiled my logback.groovy file instead of treating it like a non-source file. Sure enough, I found logback.class in target\classes. This meant that I would need to come up with a creative way to get Grails to get an un-compiled version of the file on the classpath. My first thought was to put some logic in grails-app/conf/BuildConfig.groovy to set the logback.configurationFile system property supported by Logback to the un-compiled version of logback.groovy:

grails-app/conf/BuildConfig.groovy

/*
 * If the application is being run locally, set the Logback configuration file
 * system property.  This is necessary as Grails will attempt to compile the .groovy
 * file instead of simply adding it to the classpath "as is".  There is a corresponding
 * event handler in 'scripts/Events.groovy' that takes care of making sure that the
 * Groovy configuration file makes it into the WAR in its un-compiled state.
 */
if(new File("${basedir}/grails-app/conf/logback.groovy").exists()) {
    System.setProperty('logback.configurationFile', "${basedir}/grails-app/conf/logback.groovy")		(1)
}

1	This is a programmatic way to force Logback to use the Groovy-based configuration file. This could also be set as an JVM argument (`-Dlogback.configurationFile=…`).

After adding this code and restarting the application, Logback finally found and loaded by custom configuration file. This little trick works great when running the application using the run-app command, but I knew that I would have the same issue when building the WAR file. To address getting the logback.groovy file in to the built WAR file as an un-compiled configuration file, I added the following to scripts/Events.groovy:

scripts/Events.groovy

eventCreateWarStart = { warName, stagingDir ->
    ant.copy file:"${basedir}/grails-app/conf/logback.groovy", todir: "${stagingDir}/WEB-INF/classes"
}

When Grails starts the process of building the WAR file, this script will now copy over the un-compiled logback.groovy file to classes folder in the WAR. This will guarantee that the file is on the classpath for Logback to find at runtime in its un-compiled form. After making this change, I built the WAR file and extracted it to verify the results. Everything looked good.

In retrospect, I could have easily just ditched the Grails Logback Plugin in favor of directly using the Logback dependencies, but I still would have encountered the issue with Grails compiling the logback.groovy file. In addition I also would have lost support for the automatic log property injection in controllers, tag libraries, etc that Grails provides via an AST transformation. In my spare time, I might attempt to make some modifications to the Grails Logback Plugin to handle using the DSL in non-WAR-deployed scenarios, which would elminate the need for a logback.groovy file.

Grails and Logback

Follow the instructions, they said

Using Logback with grails run-app