log4j logging configuration for two locations in Grails 2.3.8

Question

I'd like to log some information from my BootStrap.groovy file to the console and a logfile. The output reports some configuration information and marks the transition from configuration to the execution phase of the application. The problem I have is seeing the desired output only on the console, but not in the log file. My environment consists of

• Grails 2.3.8
• Red Hat Enterprise Linux Workstation release 6.5

I've provided two code snippets to show what I'm doing. They would also be easy to plug into an empty Grails project (no domain classes or controllers need be created to see the behavior I'm seeing). When I run a 'grails run-app' I expect the development section of the environments block to configure BootStrap output to two locations. Besides getting the logging to both locations working, if you have any general suggestions on my log4j configuration that would be appreciated also.

I have modified my BootStrap.groovy:

import grails.util.Environment

class BootStrap {

  def grailsApplication

  def init = { servletContext ->
    log.info """
      tryLoggingInGrails2-3-8 configuration {---------------- ${new Date()}
        environment         : ${Environment.current.name}
        dataSource.username : ${grailsApplication.config?.dataSource?.username}
        dataSource.url      : ${grailsApplication.config?.dataSource?.url}
      ------------------------------------------------------}"""
    }
    def destroy = {
    }
}

In Config.groovy, the log4j configuration section is:

// ----------------------------- Start Config.groovy snippet
// log4j configuration
def catalinaBase = System.getProperty( 'catalina.base' )
if ( !catalinaBase ) catalinaBase = './target'   // just in case
def logDirectory = "${catalinaBase}/logs"
def consoleLevelThreshold = org.apache.log4j.Level.WARN
def fileLevelThreshold = org.apache.log4j.Level.INFO

environments {
  development {
    consoleLevelThreshold = org.apache.log4j.Level.DEBUG
    fileLevelThreshold = org.apache.log4j.Level.DEBUG
  }
}

// Inside the log4j closure, use '${myAppName}' instead of '${appName}'
def myAppName = appName

log4j = {

  appenders {
    // This 'null' prevents the empty stacktrace.log file from being created
    // in the default location, where we may not have permission to write
    // in a production tomcat.
    'null' name: 'stacktrace'

    console name: 'stdoutAppender',
        threshold: consoleLevelThreshold,
        layout: pattern( conversionPattern: '%-5p %c{2} %m%n' )

    file name: 'fileAppender',
        file: "${logDirectory}/${myAppName}.log",
        threshold: fileLevelThreshold,
        layout: pattern( conversionPattern: '%-4r [%t] %-5p %c %d %x - %m%n' ),
        append: false

    file name: 'stacktraceAppender',
        file: "${logDirectory}/${myAppName}_stacktrace.log",
        threshold: org.apache.log4j.Level.ERROR,
        append: false
  } // appenders

  root {
    warn 'fileAppender', 'stdoutAppender'
  }

  error stacktraceAppender: "StackTrace"

  error fileAppender: [
      'grails.app',
      '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'
  ]

  environments {

    development {
      debug additivity: false,
          stdoutAppender: [
              "grails.app.conf.BootStrap"
          ]

      debug additivity: false,
          fileAppender: [
              "grails.app.conf.BootStrap"
          ]
    } // development

    production {
      info additivity: false,
          fileAppender: [
              "grails.app.conf.BootStrap"
          ]
    } // production

  } // environments
}
// ----------------------------- End Config.groovy snippet

Answer 1

I took our logging configuration and tested it with your configuration. It does accomplish what you want. Our logging directory for development mode ends up being under logs and not in target. Also, make sure and add imports for PatternLayout, Level, and Environment at the top of Config.groovy. Maybe you can work backwards from this one.

// If we are running under tomcat, this is the tomcat base
def logHome = "./logs"
environments {
    production {
        logHome = (System.getProperty("catalina.base") ?: ".") + "/logs"
    }
}

// Ensure the log directory exists
new File(logHome).mkdirs()
def applicationName = appName

log4j = {
    def layout = new PatternLayout("%d %-5p %c %x - %m%n")
    def logName = { String baseName -> "${logHome}/${applicationName}-${baseName}.log" }

    // Only configure file appenders if running under tomcat
    appenders {
        console name: 'stdout', layout: pattern(conversionPattern: "%-5p %c{2} - %m%n"), threshold: Level.INFO
        console name: 'stderr', layout: pattern(conversionPattern: "%-5p %c{2} - %m%n"), threshold: Level.ERROR

        // Disable the stacktrace.log file, it's already going to error anyway
        'null' name: 'stacktrace'

        rollingFile name: "errorLog", threshold: Level.ERROR, fileName: logName('error'), layout: layout, immediateFlush: true, maxFileSize: "100MB", maxBackupIndex: 5
        rollingFile name: "infoLog", threshold: Level.INFO, fileName: logName('info'), layout: layout, maxFileSize: "100MB", maxBackupIndex: 5
        rollingFile name: "debugLog", threshold: Level.DEBUG, fileName: logName('debug'), layout: layout, maxFileSize: "100MB", maxBackupIndex: 5
    }

   def infoLogged = [
            'grails.app.conf',
            'grails.app.taglib.com.triu',
            'grails.app.filters.com.triu',
            'grails.app.services.com.triu',
            'grails.app.controllers.com.triu',
            'grails.app.domain',
            'liquibase',
            'grails.plugin.databasemigration'
    ]

    // Mirror logs to stdout and info logging
    environments {
        development {
            info stdout: infoLogged, infoLog: infoLogged
            debug debugLog: infoLogged
        }
        test {
            info stdout: infoLogged, infoLog: infoLogged
        }
        production {
            info infoLog: infoLogged
            error errorLog: infoLogged
            debug debugLog: infoLogged
        }
    }

    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
          'grails.spring',
          'org.springframework',
          'org.hibernate'

    // Per docs, can't put environment blocks inside of root block
    root {
        error 'errorLog', 'stderr'
    }
}

Answer 2

This is really to augment Aaron's answer, but the comments in StackOverflow don't have the rich formatting I wanted to use.

I got some time to revisit this and found a difference in behavior between Grails 2.2.4, which I was using previously, and Grails 2.3.8.

Adding a debugging println to the Config.groovy file after setting logDirectory:

def logDirectory = "${catalinaBase}/logs"
println "logDirectory = ${logDirectory}"

shows under Grails 2.2.4 (probably any version before 2.3.x)

logDirectory = ./target/logs

but under Grails 2.3.8, a "grails run-app" prints

logDirectory = ./target/logs
...
logDirectory = ./target/work/tomcat/logs

Ah ha! Seeing two locations I now remember reading in "What's new in grails 2.3?" that many commands can now be forked into a separate JVM. Previously a "grails run-app" executed with an empty "catalinaBase" value, and my output went into the logfile under the target/logs directory. But with Grails 2.3.8 I didn't realize a second set of logfiles was being created under target/work/tomcat:

tryLoggingInGrails2-3-8$ find . -name *.log -print
./target/logs/tryLoggingInGrails2-3-8.log       (expected file is created, but empty)
./target/logs/tryLoggingInGrails2-3-8_stacktrace.log       (expected file, but empty)
./target/work/tomcat/logs/tryLoggingInGrails2-3-8.log            (unexpected file)
./target/work/tomcat/logs/tryLoggingInGrails2-3-8_stacktrace.log (unexpected file)

and the output I wanted went into the other set of log files, apparently one fork gets a non-null catalinaBase value to work with. I thought I wasn't getting the output from log4j, but it was working; just going into a file I wasn't aware of or looking for.

Aaron's code works because his block of code isn't fooled by this, it looks specifically for the production environment and the destination file is set up as intended:

def logHome = "./logs"
environments {
    production {
        logHome = (System.getProperty("catalina.base") ?: ".") + "/logs"
    }
}