Tuesday, April 25, 2017

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
  1. Application console logs writing to <tomcat_home>/logs/catalina.out
  2. Console log levels controlled via application.properties logging.level.* configuration, i.e.: logging.level.com.cherryshoe.app=DEBUG
  3. 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 -
  1. 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
  2. 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 -
  1. 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
  2. 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

2 comments:

I appreciate your time in leaving a comment!