Cherry Shoe Technologies: Spring boot custom logback configuration

I have a spring boot application (v1.3.1.RELEASE) running on tomcat that needed to be re-factored to use spring boot provided logging tools for more robust and efficient logging.

Environment:
Windows 7
Oracle Java 1.8.0_66
Spring Boot 1.3.1.RELEASE
centos-release-6-8.el6.centos.12.3.x86_64
logback-core-1.1.3

Existing

Application console logs writing to <tomcat_home>/logs/catalina.out
Console log levels controlled via application.properties logging.level.* configuration, i.e.: logging.level.com.cherryshoe.app=DEBUG
Audit log manually written to via a BufferedWriter to a path and filename (This was the biggest driver to the refactoring because of inefficiency)

New Solution
The application is using the "Starters" spring boot jars (i.e. spring-boot-starter-web, spring-boot-starter-data-jpa, spring-boot-starter-security, etc), so Logback is used by default under the covers. Since this was the case, I configured a custom spring-logback.xml file and made it available in the classpath so it would be automatically recognized and loaded.

Below are two solutions that were adequate - the difference between the two is how the application log file cherryshoe-app.log is implemented / configured. The audit log file cherryshoe_audit.log is implemented / configured the same way in both solutions. Pick what suits you best!

Option 1 Summary -

Configure application logs to write to a custom application log file ONLY (not to console) via application.properties and logback-spring.xml configuration

application.properties:

logging.file property configured

logback-spring.xml

FILE appender is the preferred approach because it is provided by spring boot framework for logback and already supports rolling logs with a Size-Based triggering policy (When size is reached, it will roll the log to <filename>.1, <filename>.2, etc)
All appender-ref's to CONSOLE have been disabled. This should be the case for deployment to non-local environments. For local development environments, you can enable it, so you don't have to tail an extra file (the logging.file configured file) during development
Log levels are configured by package
Audit logs are writing to a custom audit log file using a Sized-Based or Time-Based rolling policy

In the java classes, use LoggerFactory.getLogger(getClass()) to write to either application or audit log

application.properties

...
logging.file=./cherryshoe-app.log
...

logback-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <!-- include base.xml to get access to FILE and CONSOLE appenders -->
    <include resource="org/springframework/boot/logging/logback/base.xml" />

    <property name="log_location" value="." />
    <property name="cherryshoe_audit_file_name" value="cherryshoe_audit.log" />
    
    <!-- logger additivity=false ensures logs only goes to appender(s) specified, but not to any appender attached higher in the hierarchy. -->
    
    <!-- Configure an application specific log file (i.e. cherryshoe-app.log) via configuration in application.properties.
            NOTE: This is the preferred, there is a default rollingPolicy configured for FILE, but not for CONSOLE.  We should just
            not use CONSOLE.
            #logging.file=./cherryshoe-app.log
    
        We can limit logs that go to catalina.out for console output by commenting out / removing appender-ref to CONSOLE 
        OR
        override via https://docs.spring.io/spring-boot/docs/current/reference/html/howto-logging.html with FILE appender only
    -->
    <root level="INFO">
        <appender-ref ref="FILE" />
        <!--<appender-ref ref="CONSOLE" />-->
    </root>
    
    <!-- Define logging levels for CONSOLE and FILE which are inherited from base.xml -->    
    <logger name="com.cherryshoe.app" level="DEBUG" additivity="false">
        <appender-ref ref="FILE" />
        <!--<appender-ref ref="CONSOLE" />-->
    </logger>    
        
    <!-- Default Spring logback defines CONSOLE and FILE appenders, we'll make a new appender to support audit logs called "CHERRYSHOE-AUDIT" -->
    <appender name="CHERRYSHOE-AUDIT"
        class="ch.qos.logback.core.rolling.RollingFileAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
        <file>${log_location}/${cherryshoe_audit_file_name}</file>

        <!-- Two choices for rolling appenders, only enable one:  1. Size-Based or 2. Time-Based.-->
        <!-- 1. Size-Based Triggering Policy -->
         <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
             <fileNamePattern>${log_location}/${cherryshoe_audit_file_name}.%i</fileNamePattern>
         </rollingPolicy>
         <triggeringPolicy
             class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
             <maxFileSize>10MB</maxFileSize>
         </triggeringPolicy>

        <!-- 2. Time-Based Rolling Policy - %d is a daily rollover with format yyyy-MM-dd -->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${log_location}/cherryshoe_audit.log.%d</fileNamePattern>
        </rollingPolicy>
    </appender>
    
    <logger name="com.cherryshoe.app.audit" level="INFO" additivity="false">
        <appender-ref ref="CHERRYSHOE-AUDIT"/>
    </logger>
    
</configuration>

application logging in java classes

package com.cherryshoe.app;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

...

private Logger log = LoggerFactory.getLogger(getClass());

...
log.info("Start application logging.");
...

audit logging in java classes

package com.cherryshoe.app.audit;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

...
    private Logger log = LoggerFactory.getLogger(getClass());
...
log.info("Start audit logging.");
...

Option 2 Summary -

Configure application logs to write to a custom application log file ONLY (not to console) via logback-spring.xml configuration

Do not use the Spring boot default FILE appender because it has a Size-Based rolling policy, instead let's use a Time-Based rolling policy by date for the custom application log
All appender-ref's to CONSOLE have been disabled. This should be the case for deployment to non-local environments. For local development environments, you can enable it, so you don't have to tail an extra file (the logging.file configured file) during development
Log levels are configured by package
Audit logs are writing to a custom audit log file using a Sized-Based or Time-Based rolling policy

In the java classes, use LoggerFactory.getLogger(getClass()) to write to either application or audit log

application.properties - no changes needed because logging.path is used in default log configuration only, not with custom logging.

logback-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <!-- include defaults.xml and console-appender.xmlto get access to CONSOLE appender only -->
    <include resource="org/springframework/boot/logging/logback/defaults.xml" />
    <include resource="org/springframework/boot/logging/logback/console-appender.xml" />
    
    <!-- properties used inside this configuration file -->
    <property name="log_location" value="." />
    <property name="cherryshoe_app_file_name" value="cherryshoe-app.log" />
    <property name="cherryshoe_audit_file_name" value="cherryshoe_audit.log" />
    
    <!-- logger additivity=false ensures logs only goes to appender(s) specified, but not to any appender attached higher in the hierarchy. -->
    
    <!-- Cannot override default FILE appender to change it to a Time-Based Rolling Policy, 
    we'll make a new file appender called "CHERRYSHOE-FILE" --> 
    <appender name="CHERRYSHOE-FILE"
        class="ch.qos.logback.core.rolling.RollingFileAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
        <file>${log_location}/${cherryshoe_app_file_name}</file>

        <!-- Time-Based Rolling Policy - %d is a daily rollover with format yyyy-MM-dd -->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${log_location}/${cherryshoe_app_file_name}.%d</fileNamePattern>
        </rollingPolicy>
    </appender>
    
    <root level="INFO">
        <appender-ref ref="CHERRYSHOE-FILE" />
        <!--<appender-ref ref="CONSOLE" />-->
    </root>
    
    <logger name="com.cherryshoe.app" level="DEBUG" additivity="false">
        <appender-ref ref="CHERRYSHOE-FILE" />
        <!--<appender-ref ref="CONSOLE" />-->
    </logger>        
        
    <!-- Define a new appender to support audit logs called "CHERRYSHOE-AUDIT" -->
    <appender name="CHERRYSHOE-AUDIT"
        class="ch.qos.logback.core.rolling.RollingFileAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
        <file>${log_location}/${cherryshoe_audit_file_name}</file>

        <!-- Time-Based Rolling Policy - %d is a daily rollover with format yyyy-MM-dd -->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${log_location}/${cherryshoe_audit_file_name}.%d</fileNamePattern>
        </rollingPolicy>
    </appender>
    
    <logger name="com.cherryshoe.app.audit" level="INFO" additivity="false">
        <appender-ref ref="CHERRYSHOE-AUDIT"/>
    </logger>
    
</configuration>

application logging in java classes

package com.cherryshoe.app;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

...

private Logger log = LoggerFactory.getLogger(getClass());

...
log.info("Start application logging.");
...

audit logging in java classes

package com.cherryshoe.app.audit;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

...

    private Logger log = LoggerFactory.getLogger(getClass());
...
log.info("Start audit logging.");
...

Backup the file by date:
Here's a sample bash script to backup the audit file by date. A cron job should be scheduled for the crurent day to search for the file created yesterday.

#!/bin/bash
# This script will scp the audit log file from YESTERDAY over to the file server for backup purposes
CHERRYSHOE_AUDIT_FILENAME=cherryshoe_audit.log

YESTERDAY=`date +%Y-%m-%d -d yesterday`
YEAR=${YESTERDAY:0:4}
MONTH=${YESTERDAY:5:2}
CHERRYSHOE_AUDIT_FILENAME_YESTERDAY=$CHERRYSHOE_AUDIT_FILENAME.$YESTERDAY

echo $YESTERDAY
echo $CHERRYSHOE_AUDIT_FILENAME_YESTERDAY

if [ -e "$CHERRYSHOE_AUDIT_FILENAME_YESTERDAY" ]
  then
    echo $CHERRYSHOE_AUDIT_FILENAME_YESTERDAY exists
    #TODO SSH mkdir location/$YEAR/$MONTH && SCP file over to fileserver 
else
  echo $CHERRYSHOE_AUDIT_FILENAME_YESTERDAY does not exist
fi

My own additional questions:
Which appender is used when using LoggerFactory.getLogger(getClass())?

Whichever package your class is located, it is going to use the appenders configured there. In the logback-spring.xml file example above - for the com.cherryshoe.app package, a java class that lives there will use the appenders assigned in the logger for that package
You could also explicitly grab the logger by name if you wanted, vs counting on having the class be inside the package described by the name attribute (NOTE: This only worked for me on Windows not on CentOS). In the logback-spring.xml file above I defined the below logger with name "cherryshoeaudit".
```
    <logger name="cherryshoeaudit" level="INFO" additivity="false">
        <appender-ref ref="CHERRYSHOE-AUDIT"/>
    </logger>
```
And retrieved it by name in the java class
```
    private static final String CHERRYSHOE_AUDIT_LOG = "cherryshoeaudit";
    private Logger log = LoggerFactory.getLogger(CHERRYSHOE_AUDIT_LOG );
```
I could also just as easily defined the logger as
```
    <logger name="com.cherryshoe.app.audit" level="INFO" additivity="false">
        <appender-ref ref="CHERRYSHOE-AUDIT"/>
    </logger>
```
and then have a choice of having a java class live inside the package com.cherryshoe.app.audit, or retrieving the logger by name "com.cherryshoe.app.audit" regardless of where the java class lived.

Helpful Links

Tuesday, April 25, 2017

Spring boot custom logback configuration

2 comments: