The Flowers Are Still Standing

24 June 2014

Previously, I blogged about using Logback with Grails. While the contents of that post are mostly accurate, I have uncovered a few issues with that approach, mostly related to the use of the Grails Logback Plugin. The Grails Logback Plugin is intended to only work the logback DSL in grails-app/conf/*Config.groovy. If you attempt to use your own custom logback.xml or logback.groovy, it is ignored, even though Logback may report that it was loaded. My suspicion is that the Grails Logback Plugin plugin is re-initializing Logback after the fact, thus erasing any configuration loaded from the configuration files. Additionally, the Grails Logback Plugin depends on version 1.0.12 of Logback, which is about 3 to 4 release behind the latest release. I arrived at the conclusion that the Grails Logback Plugin was interferring with my configuration files by using the following Logback configuration:

logback.groovy

import static ch.qos.logback.classic.Level.ERROR
import static ch.qos.logback.classic.Level.INFO
import ch.qos.logback.classic.encoder.PatternLayoutEncoder
import ch.qos.logback.core.ConsoleAppender
import ch.qos.logback.core.rolling.FixedWindowRollingPolicy
import ch.qos.logback.core.rolling.RollingFileAppender
import ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy
import ch.qos.logback.core.status.OnConsoleStatusListener

def BASE_DIR = System.getProperty('catalina.base') ?: System.getProperty('user.dir')

statusListener OnConsoleStatusListener
jmxConfigurator('myapp:type=LoggerManager')

appender('STDOUT', ConsoleAppender) {
    encoder(PatternLayoutEncoder) {
        pattern = '%-50(%date{ISO8601} [%thread]) %-5level %logger{50} - %msg%n%rEx'
    }
}

logger('org.codehaus.groovy.grails', ERROR, ['STDOUT'], false)
logger('org.springframework', ERROR, ['STDOUT'], false)
logger('org.hibernate', ERROR, ['STDOUT'], false)
logger('net.sf.ehcache', ERROR, ['STDOUT'], false)
logger('grails.plugin', ERROR, ['STDOUT'], false)
logger('org.grails.plugin', ERROR, ['STDOUT'], false)
logger('grails.app', INFO, ['STDOUT'], false)

root(INFO, ['STDOUT'])

When starting the application with this configuration, the only output reported by Logback is the following:

13:27:25,368 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@61b99295 - Added status listener of type [ch.qos.logback.core.status.OnConsoleStatusListener]
13:27:25,549 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@61b99295 - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
13:27:25,550 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@61b99295 - Naming appender as [STDOUT]

This is very strange, as Logback was not reporting that any loggers were created or that those loggers have been associated with one or more appenders. After some digging through the Logback ch.qos.logback.classic.gaffer.ConfigurationDelegate class, which handles the DSL from the above configuration, I noticed that the most recent version of Logback (1.1.2) has much better output during startup. I decided to change my Grails application to explicitly depend on the latest Logback version:

BuildConfig.groovy

plugins {
    compile ':logback:0.3.1'
}

dependencies {
    compile 'ch.qos.logback:logback-core:1.1.2'
    compile 'ch.qos.logback:logback-classic:1.1.2'
}

After restarting the Grails application, I saw the following output:

13:32:36,412 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - Added status listener of type [ch.qos.logback.core.status.OnConsoleStatusListener]
13:32:36,556 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
13:32:36,557 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - Naming appender as [STDOUT]
13:32:36,981 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - Setting level of logger [org.codehaus.groovy.grails] to ERROR
13:32:36,989 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - Attaching appender named [STDOUT] to Logger[org.codehaus.groovy.grails]
13:32:37,070 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - Setting level of logger [org.springframework] to ERROR
13:32:37,070 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - Attaching appender named [STDOUT] to Logger[org.springframework]
13:32:37,071 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - Setting level of logger [org.hibernate] to ERROR
13:32:37,071 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - Attaching appender named [STDOUT] to Logger[org.hibernate]
13:32:37,071 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - Setting level of logger [net.sf.ehcache] to ERROR
13:32:37,071 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - Attaching appender named [STDOUT] to Logger[net.sf.ehcache]
13:32:37,072 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - Setting level of logger [grails.plugin] to ERROR
13:32:37,072 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - Attaching appender named [STDOUT] to Logger[grails.plugin]
13:32:37,072 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - Setting level of logger [org.grails.plugin] to ERROR
13:32:37,072 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - Attaching appender named [STDOUT] to Logger[org.grails.plugin]
13:32:37,073 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - Setting level of logger [grails.app] to INFO
13:32:37,073 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - Attaching appender named [STDOUT] to Logger[grails.app]
13:32:37,074 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - Setting level of logger [ROOT] to INFO
13:32:37,074 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@55e6490 - Attaching appender named [STDOUT] to Logger[ROOT]

Sweet. Logback appeared to be configured and working as expected. After clicking around my application and not seeing anything log to the console, I became very suspicious that I had solved the problem simply by updating the version of Logback used by the application. I decided to print out the appenders associated with one of the loggers to verify that the ConfigurationDelegate actually set things up properly:

Bootstrap.groovy

def init = { servletContext ->
    println "Appenders = ${LoggerFactory.getLogger('grails.app').aai.appenderList"
}

The code above printed out an empty list. After some head scratching, I determined that the Grails Logback Plugin was somehow overwriting/replacing the Logback configuration set up by the logback.groovy file. I decided to remove the dependency on the Grails Logback Plugin from grails-app/conf/BuildConfig.groovy as I am not using the DSL from grails-app/conf/*Config.groovy. After removing the Grails Logback Plugin entirely, everything worked as expected!

Grails and Logback Revisited