CODEWITHSUNDEEP
grailslog4j
Gene Golovchinsky
Gene Golovchinsky

Reputation: 6131

log4j duplicate logging grails

I am logging from my grails 1.3.7 application and am seeing essentially duplicate records in the log:

12/07/25 23:57:39 TRACE querium.SearchService: setting snippet for posting 1855803974 [null] 54: document 1534340330 [632]
25 Jul 2012 23:57:39,943     7851 TRACE pool-1-thread-1 SearchService:? gene 60258782 - setting snippet for posting 1855803974 [null] 54: document 1534340330 [632]

My logging is configured like this:

appenders {
    // appender for usage tracking
    appender new org.apache.log4j.RollingFileAppender(
        name:"usageAppender",
        maxFileSize:"100KB",
        maxBackupIndex: 10000,
        file:"usage.log",   // "/tmp/logs/usage.log",
        layout:pattern(conversionPattern: '%d{DATE} %5p %c{1}:%L - %m%n')
    )
    appender new org.apache.log4j.RollingFileAppender(
        name:"querium",
        maxFileSize:"1000KB",
        maxBackupIndex: 10000,
        file:"querium.log",   // "/tmp/logs/querium.log",
        layout:pattern(conversionPattern: '%d{DATE} %8X{memoryused} %5p %t %c{1}:%L %X{username} %X{request} - %m%n')
    )
    console name:'stdout', layout:pattern(conversionPattern: '%d{DATE} %8X{memoryused} %5p %t %c{1}:%L %X{username} %X{request} - %m%n')
}
root {
    error 'querium', 'stdout'
}

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' 

warn  'org.mortbay.log'
debug 'grails.app.service'
trace 'grails.app.service.backgroundservice'
error 'org.hibernate.SQL'
trace 'grails.app.controller.com.fxpal.querium.UiController'
trace 'grails.app.controller.com.fxpal.querium.CommentController'
warn  'grails.app.controller.com.fxpal.querium.TopicController'
off 'grails.app.service.com.fxpal.redis.RedisService'
trace 'grails.app.service.com.fxpal.querium.SearchService'
debug   'com.fxpal.cloudwork.docubrowse.SearchDocubrowse'
off 'grails.app.service.com.fxpal.proxy.ProxyService'

debug 'org.codehaus.groovy.grails.plugins.springsecurity.*'
debug 'com.fxpal.querium.CiteSeerDocumentParser'

debug 'com.fxpal.querium.LoggingFilters'
    info 'usageAppender':'usage.gui'

The correct data is going to the usageAppender. Can someone practiced in this arcana figure out why I am getting doubled records, but slightly different, records for the rest of the logging?

EDITED 26 JUL 2012: Added rest of logging configuration.

Upvotes: 0

Views: 1368

Answers (1)

Ian Roberts
Ian Roberts

Reputation: 122364

The output you are seeing looks like there are two different console appenders attached to your root logger (or possibly one attached to the root logger and another one attached somewhere further down the logger tree). The second line you're seeing is your own stdout logger format but the first line is consistent with a pattern layout of

%d{yy/MM/dd HH:mm:ss} %p %c{1}: %m%n

which is not the Grails default format. Checking the code for the Grails log4j DSL parser I notice that it does not reset the logging configuration before it starts processing the DSL. Thus I suspect you have a stray log4j.properties or log4j.xml file somewhere on your classpath (either in src/java or similar, or buried inside one of the JAR files that your app depends on) which is creating this extra appender before the DSL parser runs. You can determine this in your BootStrap.init by doing

this.getClass().getClassLoader().getResources("log4j.properties").each {
  println it
}

(and likewise for log4j.xml). If it turns out to be inside a JAR and you can't easily excise it you could try calling LogManager.loggerRepository.resetConfiguration() as the very first thing in your log4j closure (before your own appenders section).

Upvotes: 1

Related Questions