Johnny's dev corner

Logging

Grails logging is described in the docs: http://docs.grails.org/latest/guide/single.html#logging

Grails logging is built on top of logback: http://logback.qos.ch/

Why/What log?

In development and testing I use logs as a supplement to debuggers. The logging is configured to be more verbose.

In production debugging is not available, so logging is your tool for investigating a situation and the configuration is less verbose.

Deciding what goes into the log is continuous learning. What seems appropriate at first will most likely be insufficient for investigation.

Deciding what goes into the log is continuous learning.

Logging levels:

  • trace – use with atomic operations that are called with high frequency.
  • debug – use for most methods, like e.g. data services.
  • info – use for business logic and complex methods relying on underlying logic.

The configuration will then decide what will be logged.

Setting up logging

You will most likely be setting up at least a console logger and a file logger.

In a complex production environment you will most likely want to set up logging to a log-server like logstash/ELK. I have included the configuration here, and might covered setting up ELK in a later post.

In the following paragraphs I will show my standard configuration. I have added some information:

  • tenantId – for use in multi-tenant application. Omitted for single tenant apps.
  • %M – Method name.
  • line – line number within method

Stdout logger configuration in logback.groovy:

appender('STDOUT', ConsoleAppender) {
    encoder(PatternLayoutEncoder) {
        charset = Charset.forName('UTF-8')

        pattern =
                '%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} ' + // Date
                        '%clr(%5X{tenantId}) ' + // tenant
                        '%clr(%5p) ' + // Log level
                        '%clr([%15.15t]){faint} ' + // Thread
                        '%clr(%-50.50(%logger{35}.%M)){cyan} %clr(%4.4line) %clr(.){faint}' + // Logger with method name
                        '%m%n%wex' // Message
    }
}

Rolling file logger. I first try to get applicationPath from the tomcat server configurationPath. If that fails I assume current directory. Logging to console.log.

appender("ROLLING", RollingFileAppender) {
    String applicationPath = null
    try {
        applicationPath = (String) new InitialContext().lookup("java:comp/env/configurationPath")
        System.out.println("applicationPath: ${applicationPath}")
    } catch (Exception e) {
        System.out.println("error getting context: " + e.getMessage())
        applicationPath = "."
        System.out.println("applicationPath: ${applicationPath}")
    }
    String appName = grails.util.Metadata.current.'app.name'
    file = "${applicationPath}/console.log"
    encoder(PatternLayoutEncoder) {
        pattern =
                '%d{yyyy-MM-dd HH:mm:ss.SSS} ' + // Date
                        '%5X{tenantId} ' + // tenant
                        '%5p ' + // Log level
                        '[%15.15t] ' + // Thread
                        '%-50.50(%logger{35}.%M) %4.4line .' + // Logger with method name
                        '%m%n%wex' // Message
    }
    rollingPolicy(FixedWindowRollingPolicy) {
        fileNamePattern = "${applicationPath}/${appName}.%i.log.zip"
        minIndex = 1
        maxIndex = 7
    }
    triggeringPolicy(SizeBasedTriggeringPolicy) {
        maxFileSize = "100MB"
    }
}

Logstash logging. First configure build.gradle:

dependencies {
  runtime "net.logstash.logback:logstash-logback-encoder:5.3"
}

Then logback.groovy:

appender('STASH', LogstashTcpSocketAppender) {
    destination = "elk.prpr.no:4560"
    encoder(LogstashEncoder){
        includeMdcKeyName="loggingId"
        includeMdcKeyName="tenantId"
        customFields='{"@metadata": { "beat": "yourApplicationNameOrId", "type": "doc" } }'
        includeCallerData = true    // Consider Environment.isDevelopmentMode()
    }
    SSLConfiguration tmpSsl = new SSLConfiguration()
    tmpSsl.trustStore = new KeyStoreFactoryBean()
    tmpSsl.trustStore.location = "elk.prpr.no.jks"
    tmpSsl.trustStore.password = "theTrustStorePassword"
    if (tmpSsl.trustStore instanceof LifeCycle)
        tmpSsl.trustStore.start()
    if (tmpSsl instanceof LifeCycle)
        tmpSsl.start()
    ssl = tmpSsl
}

Finally you configure what should be logged:

// I like to have some content in the logs as proof of life
root(INFO, ['STDOUT', 'STASH', 'ROLLING'])
// Our own code "no.prpr" often needs to be more verbose, and dependent on environment
logger("no.prpr", Environment.isDevelopmentMode() ? DEBUG : INFO, ['STDOUT', 'STASH', 'ROLLING'], false)
// Filtering noise from "org.hibernate.orm.deprecation"
logger("org.hibernate.orm.deprecation", ERROR, ['STDOUT', 'STASH', 'ROLLING'], false)

Using loggers

The loggers are injected into classes in grails-app like controllers and services. When you need logging outside grails-app, in e.g. your classes must be annotated with @Slf4j.

Multitenancy logging

When logging in a multitenancy application you need to know which tenant the log is about.

I have already shown in the configuration how to put the tenantId into the log. You make the tenantId available for logging in your tenantresolver.

@Slf4j
@CompileStatic
class PrprTenantResolver implements TenantResolver {

    @Override
    Serializable resolveTenantIdentifier() throws TenantNotFoundException {
        String tenantId = getTenantId()
        log.trace("tenantId == ${tenantId}")
        MDC.put('tenantId', "${tenantId}")
        if (tenantId) {
            tenantId
        } else {
            throw new TenantNotFoundException('Tenant not found')
        }
    }
    String getTenantId() {
        "notImplemented"
    }
}

This sample code is places in src/main/grovvy/no.prpr.tenant.

Hence it is annotated with @Slf4j in order to make the loggers available.

This little bit of code will be called a lot of times. Hence I have used log.trace.

Logging services

Given a Spring security setup with users, roles and groups. We have made the @Service() services to each domain.

For the domain RoleGroup I have a method “assertRoleGroup”. Here I use log.debug.

@CompileStatic
@CurrentTenant
@Service(RoleGroup)
@Transactional
abstract class RoleGroupService implements IRoleGroupService {

    /**
     * asserts existence of rolegroup
     *
     * @param name of group
     * @return the group
     */
    RoleGroup assertRoleGroup(String name) {
        RoleGroup roleGroup = findByName(name)
        if (!roleGroup) {
            roleGroup = save(new RoleGroup(name: name))
        }
        log.debug("RoleGroup ${name} -> ${roleGroup}")
        roleGroup
    }

}

We have also made a higher level class “SecurityMaintenanceService” which uses all the @Services. Here logging is mostly at info level.

@Transactional
@CurrentTenant
class SecurityMaintenanceService {

    UserService userService
    RoleGroupService roleGroupService
    UserRoleGroupService userRoleGroupService

    boolean deleteUser(String username) {
        log.info("deleteUser: ${username}")
        boolean result = false

        User user = userService.findByUsername(username)
        if (user) {
            userRoleGroupService.deleteAll(user)
            userService.delete(user.id)
            result = !userService.findByUsername(username)
        }
        log.info("deleteUser: ${username} == ${result}")
        result
    }
}

Johnny Haugen Sørgård