7.1. Logging

Note

This contents described in this chapter are just guidelines that can be customized as per the business requirements.

7.1.1. Overview

When a system is being operated, logs and messages are output as information sources to analyze the business process usage and

to determine the causes when the system is down or when a business error etc. occurs.

It is important to output the log since effectiveness of analysis improves significantly if it is output at the time of debugging.

If only the behavior is to be checked, it can be done by debugging in IDE or through a simple output such as System.out.println.

However, if the output result is not manually stored, it is not possible to check the results later. This hampers the effectiveness of analysis.

Obtaining the log by implementing logging library is just writing the code to be output.

Log can be verified at any convenient time later on.

Considering operating time, trail and analysis, it is recommended to implement logging library.

There are various log output methods in Java and a number of methods can be selected; however this guideline recommends SLF4J (interface) + Logback (implementation)

due to simplicity of coding, ease of modification and performance.

7.1.1.1. Types of Logs

A typical log at the time of application development is shown below.

Log level	Category	Purpose of output	Output contents
TRACE	Performance log	Measurement of request processing time (Should not be output during production environment operations)	Process start and end time, process elapsed time (ms), Information that can identify the execution process etc. (execution controller + method, request URL etc.).
DEBUG	Debug log	Debug at the time of development (Should not be output during production environment operations)	Optional (Executed query, Input parameter, Return value etc.)
INFO	Access log	Assessing business process volume	Information that can identify access date and time, user (IP address, authentication information) Information that can identify execution process (request URL) etc., information for leaving a trail
INFO	External communication log	Analysis of error that occurs while communicating with external system	Send and receive time, send and receive data etc.
WARN	Business error log	Business error records	Business error occurrence time, Message ID and message corresponding to business error Information necessary for analysis such as input information, exception message etc.
ERROR	System error log	Record the events where it is difficult to continue a system operation	System error occurrence time, Message and message ID corresponding to system error Information necessary for analysis such as input information, exception message etc. Basically, framework is output and business process logic is not output.
ERROR	Monitoring log	Monitoring the occurrence of an exception	Exception occurrence time, Message ID corresponding to system error Use tools for monitoring and keep the output contents to a minimum.

Debug log, Access log, External communication log, Business error log and System error log are output to same file.

In this guideline, the log file that outputs the above mentioned logs is called as application log.

Note

The sequence of log levels of SLF4J or Logback is TRACE < DEBUG < INFO < WARN < ERROR. It does not include FATAL level provided in commons-loggins or Log4J.

7.1.1.2. Output contents of log

It is important to note the points given below for the output contents of log.

1. ID to be output to log

   When log is to be monitored during the operation, it is recommended to include a message ID in the log to be monitored.

   Further, when the business process volume is to be assessed using an access log, the log should be output according to the ID assigned to each business process as explained in Message Management.

   This facilitates overall data compilation.

Note

The readability of log is enhanced by including an ID in the log thereby reducing the time required for primary isolation of failure analysis. Refer to Message Management for log ID structure. However, there is no need to assign an ID to all the logs. ID is not required at the time of debugging. It is recommended when the system is operational so as to isolate the log quickly.

During failure, when a system user is notified by displaying a log ID (or a message ID) on the error screen and the ID is then notified to the call center, for that user, failure analysis becomes easier.

However, note that the vulnerabilities of the system may be exposed if errors are displayed on the screen along with the failure details.

In common library, the mechanism(component) is provided to include the message ID(exception code) into the log and the screen when an exception is occurred. Details refer to “Exception Handling”.

2. Traceability

   To improve the traceability, it is recommended to output a unique track ID (hereafter referred to as X-Track) at request level in each log.

   Example of logs including X-Track is given below.

date:2013-09-06 19:36:31    X-Track:85a437108e9f4a959fd227f07f72ca20        message:[START CONTROLLER] (omitted)
date:2013-09-06 19:36:31    X-Track:85a437108e9f4a959fd227f07f72ca20        message:[END CONTROLLER  ] (omitted)
date:2013-09-06 19:36:31    X-Track:85a437108e9f4a959fd227f07f72ca20        message:[HANDLING TIME   ] (omitted)
date:2013-09-06 19:36:33    X-Track:948c8b9fd04944b78ad8aa9e24d9f263        message:[START CONTROLLER] (omitted)
date:2013-09-06 19:36:33    X-Track:142ff9674efd486cbd1e293e5aa53a78        message:[START CONTROLLER] (omitted)
date:2013-09-06 19:36:33    X-Track:142ff9674efd486cbd1e293e5aa53a78        message:[END CONTROLLER  ] (omitted)
date:2013-09-06 19:36:33    X-Track:142ff9674efd486cbd1e293e5aa53a78        message:[HANDLING TIME   ] (omitted)
date:2013-09-06 19:36:33    X-Track:948c8b9fd04944b78ad8aa9e24d9f263        message:[END CONTROLLER  ] (omitted)
date:2013-09-06 19:36:33    X-Track:948c8b9fd04944b78ad8aa9e24d9f263        message:[HANDLING TIME   ] (omitted)

Logs can be linked together using Track IDs even when the output is irregular.

In the above example, it can be clearly understood that 4th, 8th and 9th rows in the log are pertaining to the same request.

In common library, org.terasoluna.gfw.web.logging.mdc.XTrackMDCPutFilter to be added to MDC is provided by generating a unique key for each request.

XTrackMDCPutFilter sets Track ID in “X-Track” of HTTP response header as well. X-Track is used as a Track ID label in the log.

Refer to About MDC for the usage methods.

3. Log mask

   If personal information, credit card number etc. are output to the log file as is, the information that has security threat should be masked if needed.

7.1.1.3. Log output points

Category	Output points
Performance log	The processing time of business process is measured and it is output after executing business process. Request processing time is measured and log is output when response is returned. It is usually implemented in AOP or Servlet filter. Common library provides org.terasoluna.gfw.web.logging.TraceLoggingInterceptor which outputs processing time of SpringMVC Controller method in TRACE log after the execution of handler method of Controller.
Debug log	When it is necessary to output debug information at the time of development, a suitable log output process is implemented in source code. Common library provides org.terasoluna.gfw.web.logging.HttpSessionEventLoggingListener listener which outputs DEBUG log at the time of HTTP session creation/destruction/attribute addition.
Access log	INFO log is output at the time of receiving a request and returning the response. It is usually implemented in AOP or Servlet filter.
External communication log	INFO log is output before and after external system linking.
Business error log	WARN log is output when business process exception is thrown. It is usually implemented in AOP. In common library, when org.terasoluna.gfw.common.exception.BusinessException is thrown at the time of business process execution, org.terasoluna.gfw.common.exception.BusinessExceptionLoggingInterceptor that outputs WARN log is provided. Refer to Exception Handling for details.
System error log	An ERROR log is output when system exception or unexpected exception occurs. It is usually implemented in AOP or Servlet filter. In common library, org.terasoluna.gfw.web.exception.HandlerExceptionResolverLoggingInterceptor and org.terasoluna.gfw.web.exception.ExceptionLoggingFilter are provided. Refer to Exception Handling for details.
Monitoring log	It is output at the same time as business error log and system error log.

Note

Note that when the log is output, the contents should not be exactly identical to other logs. This is helpful in easily identifying the location of the output.

7.1.2. How to use

The following are required to output the log in SLF4J + Logback.

1. Settings of Logback
2. Calling API of SLF4J

7.1.2.1. Settings of Logback

Logback settings are described in logback.xml under the class path. An example of configuration is shown below.

Refer to Logback Official Manual -Logback Configuration- for the detailed configuration of logback.xml.

Note

Settings of Logback are read automatically as per the rules given below.

1. logback.groovy on class path
2. If file “1” is not found, logback-test.xml on class path
3. If file “2” is not found, logback.xml on class path
4. If file “3” is not found, settings of class which implements com.qos.logback.classic.spi.Configurator interface (Specify a implementation class using ServiceLoader mechanism)
5. If class which implements Configurator interface is not found, settings of BasicConfigurator class (console output)

In this guideline, it is recommended to place logback.xml in the class path. Moreover, apart from automatic reading, it is possible to read programmatically through an APIand specify the configuration file in system properties.

logback.xml

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

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <!-- (1) -->
        <encoder>
            <pattern><![CDATA[date:%d{yyyy-MM-dd HH:mm:ss}\tthread:%thread\tX-Track:%X{X-Track}\tlevel:%-5level\tlogger:%-48logger{48}\tmessage:%msg%n]]></pattern> <!-- (2) -->
        </encoder>
    </appender>

    <appender name="APPLICATION_LOG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> <!-- (3) -->
        <file>${app.log.dir:-log}/projectName-application.log</file> <!-- (4) -->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${app.log.dir:-log}/projectName-application-%d{yyyyMMddHH}.log</fileNamePattern> <!-- (5) -->
            <maxHistory>7</maxHistory> <!-- (6) -->
        </rollingPolicy>
        <encoder>
            <charset>UTF-8</charset> <!-- (7) -->
            <pattern><![CDATA[date:%d{yyyy-MM-dd HH:mm:ss}\tthread:%thread\tX-Track:%X{X-Track}\tlevel:%-5level\tlogger:%-48logger{48}\tmessage:%msg%n]]></pattern>
        </encoder>
    </appender>

    <appender name="MONITORING_LOG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> <!-- (8) -->
        <file>${app.log.dir:-log}/projectName-monitoring.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${app.log.dir:-log}/projectName-monitoring-%d{yyyyMMdd}.log</fileNamePattern>
            <maxHistory>7</maxHistory>
        </rollingPolicy>
        <encoder>
            <charset>UTF-8</charset>
            <pattern><![CDATA[date:%d{yyyy-MM-dd HH:mm:ss}\tX-Track:%X{X-Track}\tlevel:%-5level\tmessage:%msg%n]]></pattern>
        </encoder>
    </appender>

    <!-- Application Loggers -->
    <logger name="com.example.sample"> <!-- (9) -->
        <level value="debug" />
    </logger>

    <!-- TERASOLUNA -->
    <logger name="org.terasoluna.gfw">
        <level value="info" />
    </logger>
    <logger name="org.terasoluna.gfw.web.logging.TraceLoggingInterceptor">
        <level value="trace" />
    </logger>
    <logger name="org.terasoluna.gfw.common.exception.ExceptionLogger">
        <level value="info" />
    </logger>
    <logger name="org.terasoluna.gfw.common.exception.ExceptionLogger.Monitoring" additivity="false"><!-- (10) -->
        <level value="error" />
        <appender-ref ref="MONITORING_LOG_FILE" />
    </logger>

    <!-- 3rdparty Loggers -->
    <logger name="org.springframework">
        <level value="warn" />
    </logger>

    <logger name="org.springframework.web.servlet">
        <level value="info" />
    </logger>

    <!--  REMOVE THIS LINE IF YOU USE JPA
    <logger name="org.hibernate.engine.transaction">
        <level value="debug" />
    </logger>
          REMOVE THIS LINE IF YOU USE JPA  -->
    <!--  REMOVE THIS LINE IF YOU USE MyBatis3
    <logger name="org.springframework.jdbc.datasource.DataSourceTransactionManager">
        <level value="debug" />
    </logger>
          REMOVE THIS LINE IF YOU USE MyBatis3  -->

    <logger name="jdbc.sqltiming">
        <level value="debug" />
    </logger>

    <!-- only for development -->
    <logger name="jdbc.resultsettable">
        <level value="debug" />
    </logger>

    <root level="warn"> <!-- (11) -->
        <appender-ref ref="STDOUT" /> <!-- (12) -->
        <appender-ref ref="APPLICATION_LOG_FILE" />
    </root>

</configuration>

Sr. No.	Description
(1)	Definition of appender is specified to output the log on console. It can be selected whether the output destination is standard output or standard error, however when the destination is not specified, it is considered as standard output.
(2)	The output format for log is specified. If the format is not specified, the message alone is output. Time and message level etc. are output according to the business requirements. Here, LTSV (Labeled Tab Separated Value) of “Label:Value<TAB>Label:Value<TAB>…” format is set.
(3)	Definition for appender is specified to output application log. The appender to be used can also be specified in <logger>, however, here it is referred to root (11) since application log is used by default. RollingFileAppender is commonly used at the time of application log output, however, FileAppender may also be used to implement log rotation using another functions such as logrotate.
(4)	A current file name (File name of log being output) is specified. It should be specified when it is necessary to specify a fixed file name. If <file>log file name</file> is not specified, it is output with the name in pattern (5).
(5)	Name of the file after rotation is specified. Usually, date or time format is widely used. Note that 24 hour clock is not set if HH is mistakenly set as hh.
(6)	The number of remaining files for which rotation is performed is specified.
(7)	A character code of log file is specified.
(8)	It is set so as to output the application log by default.
(9)	The logger name is set so that logger under com.example.sample outputs the log above debug level.
(10)	A monitoring log is set. Refer to Common Settings of Exception Handling. Warning About additivity setting value Specify false. If true(default value) is specified, the same log will be output by upper level logger (for example, root). Concretely speaking, the monitoring log will be output using three appenders(MONITORING_LOG_FILE, STDOUT and APPLICATION_LOG_FILE).
(11)	It is set such that logger without <logger> specification outputs the log of warn level or above.
(12)	It is set in such a way that ConsoleAppender, RollingFileAppender (application logs) are used by default.

Tip

About LTSV(Labeled Tab Separated Value)

LTSV is one of text data formats, and mainly used as the log format.

For log fomart, LTSV is easy to parse using some tools because it has following features.

• It’s easy to split the field compared to other delimiters because tabs is used as field delimiters.
• Even if the field definition (changing the position of field or adding the field or removing the field) is changed, it does not affect to parsing because of including a label(name) in the field.

It is also one of features that there are that pasting on the Excel can format it with the least effort.

The following three items should be set in logback.xml.

Type	Overview
appender	“Location” and “Layout” to be used for output
root	Default “Appender” and the minimum “Log level” to be used for output
logger	“Which logger (package or class etc.)” is to be output at which minimum “log level”

In <appender> element, the “location” and the “layout” to be used for output are defined. It is not used at the time of the log output only by defining the appender. It is used for the first time when it is referred in <logger> element or <root> element. There are two attributes, namely, “name” and “class” and both are mandatory.

Attribute	Overview
name	Name of the appender. It is specified by appender-ref. Any name can be assigned as there is no restriction on assigning the name.
class	FQCN of appender implementation class.

The main appenders that are provided are shown below.

Appender	Overview
ConsoleAppender	Console output
FileAppender	File output
RollingFileAppender	File output (Rolling possible)
AsyncAppender	Asynchronous output. It is used for logging in processes with high performance requirement. (It is necessary to set the output destination in other Appender.)

Refer to Logback Official Manual -Appenders- for detailed Appender types.

7.1.2.2. Basic log output by calling API of SLF4J

Log is output by calling a method according to each log level of SLF4J logger(org.slf4j.Logger).

package com.example.sample.app.welcome;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Controller;
import org.springframework.ui.Model;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RequestMethod;

@Controller
public class HomeController {

    private static final Logger logger = LoggerFactory
            .getLogger(HomeController.class);   // (1)

    @RequestMapping(value = "/", method = { RequestMethod.GET,
            RequestMethod.POST })
    public String home(Model model) {
        logger.trace("This log is trace log."); // (2)
        logger.debug("This log is debug log."); // (3)
        logger.info("This log is info log.");   // (4)
        logger.warn("This log is warn log.");   // (5)
        logger.error("This log is error log."); // (6)
        return "welcome/home";
    }

}

Sr. No.	Description
(1)	Logger is generated from org.slf4j.LoggerFactory. If Class object is set as an argument of getLogger, the logger name acts as an FQCN of that class. In this example, the logger name is “com.example.sample.app.welcome.HomeController”.
(2)	The log of TRACE level is output.
(3)	The log of DEBUG level is output.
(4)	The log of INFO level is output.
(5)	The log of WARN level is output.
(6)	The log of ERROR level is output.

Log output results are shown below. Log level of com.example.sample is DEBUG, hence TRACE log is not output.

date:2013-11-06 20:13:05    thread:tomcat-http--3 X-Track:5844f073b7434b67a875cb85b131e686    level:DEBUG logger:com.example.sample.app.welcome.HomeController    message:This log is debug log.
date:2013-11-06 20:13:05    thread:tomcat-http--3 X-Track:5844f073b7434b67a875cb85b131e686    level:INFO  logger:com.example.sample.app.welcome.HomeController    message:This log is info log.
date:2013-11-06 20:13:05    thread:tomcat-http--3 X-Track:5844f073b7434b67a875cb85b131e686    level:WARN  logger:com.example.sample.app.welcome.HomeController    message:This log is warn log.
date:2013-11-06 20:13:05    thread:tomcat-http--3 X-Track:5844f073b7434b67a875cb85b131e686    level:ERROR logger:com.example.sample.app.welcome.HomeController    message:This log is error log.

The description can be as given below when an argument is to be entered in placeholder of a log message.

int a = 1;
logger.debug("a={}", a);
String b = "bbb";
logger.debug("a={}, b={}", a, b);

The log given below is output.

date:2013-11-06 20:32:45    thread:tomcat-http--3   X-Track:853aa701a401404a87342a574c69efbc    level:DEBUG logger:com.example.sample.app.welcome.HomeController    message:a=1
date:2013-11-06 20:32:45    thread:tomcat-http--3   X-Track:853aa701a401404a87342a574c69efbc    level:DEBUG logger:com.example.sample.app.welcome.HomeController    message:a=1, b=bbb

Warning

Note that string concatenation such as logger.debug("a=" + a + " , b=" + b); should not be carried out.

When the exception is to be caught, ERROR log (WARN log in some cases) is output as shown below. Error message and exception generated are passed to the log method.

public String home(Model model) {
    // omitted

    try {
        throwException();
    } catch (Exception e) {
        logger.error("Exception happened!", e);
        // omitted
    }
    // omitted
}

public void throwException() throws Exception {
    throw new Exception("Test Exception!");
}

Accordingly, stack trace of caused exception is output and the cause of the error can be easily analyzed.

date:2013-11-06 20:38:04    thread:tomcat-http--5   X-Track:11d7dbdf64e44782822c5aea4fc4bb4f    level:ERROR logger:com.example.sample.app.welcome.HomeController    message:Exception happend!
java.lang.Exception: Test Exception!
    at com.example.sample.app.welcome.HomeController.throwException(HomeController.java:40) ~[HomeController.class:na]
    at com.example.sample.app.welcome.HomeController.home(HomeController.java:31) ~[HomeController.class:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_40]
    (omitted)

However, as shown below, when the exception that is caught is wrapped with other exception and is re-thrown at upper level, there is no need to output the log. This is because usually the error log is output at upper level.

try {
    throwException();
} catch (Exception e) {
    throw new SystemException("e.ex.fw.9001", e);
    // no need to log
}

Note

When cause exception is to be passed to a log method, a placeholder cannot be used. Only in this case, the message argument can be concatenated using a string.

try {
    throwException();
} catch (Exception e) {
    // NG => logger.error("Exception happend! [a={} , b={}]", e, a, b);
    logger.error("Exception happend! [a=" + a + " , b=" + b + "]", e);
    // omitted
}

7.1.2.3. Points to be noted for the description of log output

SLF4J Logger internally checks the log level and outputs actual log only for the required levels.

Therefore, the log level check as given below is basically not necessary.

if (logger.isDebugEnabled()) {
    logger.debug("This log is Debug.");
}

if (logger.isDebugEnabled()) {
    logger.debug("a={}", a);
}

However, the log level should be checked in the cases given below to prevent performance degradation.

1. When there are 3 or more arguments

   When arguments of log message are 3 or more, argument array should be passed in the API of SLF4J. Log level should be checked in order to to avoid the cost for generating an array and the array should be generated only when necessary.

   if (logger.isDebugEnabled()) {
       logger.debug("a={}, b={}, c={}", new Object[] { a, b, c });
   }
   

2. When it is necessary to call a method for creating an argument

   When it is necessary to call a method while creating an argument for the log message, the log level should be checked to avoid the method execution cost and the method should be executed only when necessary.

   if (logger.isDebugEnabled()) {
       logger.debug("xxx={}", foo.getXxx());
   }
   

7.1.3. How to extend

Log output specifications are individually defined based on monitoring products and requirements and a case which is individually implemented is assumed. Here, a couple of examples are described below.

1. Uniform management of log messages
2. Integration of output format of log messages

7.1.3.1. Uniform management of log messages

An implementation example which aims to improve maintenance through uniform management of log messages.

Log messages are managed uniformly by consolidating the log messages in another file like a property file and resolving messages at the time of log output.

A method is described as an implementation example wherein the messages corresponding to log ID are output in the property file to enable setting of log ID in the argument of log output method.

Note

A method wherein consolidation is done using enum of Java also exists as a method to manage Log ID and log message, however, a general method wherein the property file is used is introduced in this guideline.

In this implementation example

1. Logger wrapper class
2. Property file

are created.

Here, LogIdBasedLoggeris considered as a Logger wrapper class and log-messages.propertiesis considered as a property file.

• LogIdBasedLogger (Logger wrapper class)

package com.example.sample.common.logger;

import java.text.MessageFormat;
import java.util.Arrays;
import java.util.Locale;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.context.NoSuchMessageException;
import org.springframework.context.support.ResourceBundleMessageSource;

public class LogIdBasedLogger {

    private static final String UNDEFINED_MESSAGE_FORMAT = "UNDEFINED-MESSAGE id:{0} arg:{1}";   // (1)

    private static ResourceBundleMessageSource messageSource = new ResourceBundleMessageSource();// (2)

    static {    // (3)
        messageSource.setDefaultEncoding("UTF-8");          // (4)
        messageSource.setBasenames("i18n/log-messages");    // (5)
    }

    private final Logger logger;

    private LogIdBasedLogger(Class<?> clazz) {
        logger = LoggerFactory.getLogger(clazz);            // (6)
    }

    public static LogIdBasedLogger getLogger(Class<?> clazz) {
        return new LogIdBasedLogger(clazz);
    }

    public boolean isDebugEnabled() {                       // (7)
        return logger.isDebugEnabled();
    }

    public void debug(String format, Object... args) {
        logger.debug(format, args);                         // (8)
    }

    public void info(String id, Object... args) {
        if (logger.isInfoEnabled()) {
            logger.info(createLogMessage(id, args));        // (9)
        }
    }

    public void warn(String id, Object... args) {
        if (logger.isWarnEnabled()) {
            logger.warn(createLogMessage(id, args));        // (9)
        }
    }

    public void error(String id, Object... args) {
        if (logger.isErrorEnabled()) {
            logger.error(createLogMessage(id, args));       // (9)
        }
    }

    public void trace(String id, Object... args) {
        if (logger.isTraceEnabled()) {
            logger.trace(createLogMessage(id, args));       // (9)
        }
    }

    public void warn(String id, Throwable t, Object... args) {
        if (logger.isWarnEnabled()) {
            logger.warn(createLogMessage(id, args), t);     // (9)
        }
    }

    public void error(String id, Throwable t, Object... args) {
        if (logger.isErrorEnabled()) {
            logger.error(createLogMessage(id, args), t);    // (9)
        }
    }

    private String createLogMessage(String id, Object... args) {
        return getMessage(id, args);
    }

    private String getMessage(String id, Object... args) {
        String message;
        try {
            message = messageSource.getMessage(id, args, Locale
                    .getDefault());
        } catch (NoSuchMessageException e) {                // (10)
            message = MessageFormat.format(UNDEFINED_MESSAGE_FORMAT, id, Arrays
                    .toString(args));
        }
        return message;
    }
}

Sr. No.	Description
(1)	A log message when the log ID is not defined. Here, a message same as org.terasoluna.gfw.common.exception.ExceptionLoggeris used as an example.
(2)	An implementation example wherein the log message is fetched by MessageSource. MessageSourcemanaged by message data is stored in staticarea to enhance general versatility. This implementation facilitates the use of Logger wrapper class at any time since dependence on accessibility to DI container is eliminated.
(3)	Generate MessageSourceusing static initializer. In this implementation, log-messages.propertiesplaced in i18nis read.
(4)	Specify a character code to be used while parsing a property file. In this implementation, since property file is in UTF-8 encoding format, UTF-8 is specified. For details, refer Display of messages set in propertiesof Message Management.
(5)	Specify a property file by using setBasenames method considering internationalization. For details of setBasenames, refer Javadoc of setBasenames of ReloadableResourceBundleMessageSource class.
(6)	Use SLF4J in logger wrapper class as well. Logging library implementation is not used directly.
(7)	Determine whether log output of DEBUG level is allowed. For precautions for use, refer Points to be noted for the description of log output.
(8)	In this implementation example, log ID is not used in the log of DEBUG level. Log message of argument is output as it is.
(9)	Output TRACE/INFO/WARN/ERROR level log by fetching the log message corresponding to log ID from the property file.
(10)	If log ID is not described in the property file while calling getMessage, an exception :NoSuchMessageExceptionis generated. Hence, NoSuchMessageExceptionis caught Aand a log message stating “log ID is not defined in the property file” is output.

• log-messages.properties (property file)

i.ab.cd.1001 = This message is Info-Level. {0}
w.ab.cd.2001 = This message is Warn-Level. {0}
e.ab.cd.3001 = This message is Error-Level. {0}
t.ab.cd.4001 = This message is Trace-Level. {0}

Note

In this guideline, since message for screen output and message for log output are managed separately, a new property file is created. However, both the messages can be output in a single file.

File unit should be determined in accordance with the nature of the application and how to manage a method of message.

Execution results are as below.

• Call sample

package com.example.sample.app.welcome;

import org.springframework.stereotype.Controller;
import org.springframework.ui.Model;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RequestMethod;

import com.example.sample.common.logger.LogIdBasedLogger;

@Controller
public class HomeController {

    private static final LogIdBasedLogger logger = LogIdBasedLogger
            .getLogger(HomeController.class);

    @RequestMapping(value = "/", method = { RequestMethod.GET,
            RequestMethod.POST })
    public String home(Model model) {
        logger.debug("debug log");
        logger.info("i.ab.cd.1001","replace_value_1");
        logger.warn("w.ab.cd.2001","replace_value_2");
        logger.error("e.ab.cd.3001","replace_value_3");
        logger.trace("t.ab.cd.4001","replace_value_4");
        logger.info("i.ab.cd.1002","replace_value_5");
        return "welcome/home";
    }
}

• Example of log output

date:2016-05-30 17:34:18.590  thread:http-bio-8080-exec-3  X-Track:e2a65cd9160b48d6aaeb63fe6e751c6b  level:DEBUG  logger:com.example.sample.app.welcome.HomeController   message:debug log
date:2016-05-30 17:34:18.590  thread:http-bio-8080-exec-3  X-Track:e2a65cd9160b48d6aaeb63fe6e751c6b  level:INFO   logger:com.example.sample.app.welcome.HomeController   message:This message is Info-Level. replace_value_1
date:2016-05-30 17:34:18.590  thread:http-bio-8080-exec-3  X-Track:e2a65cd9160b48d6aaeb63fe6e751c6b  level:WARN   logger:com.example.sample.app.welcome.HomeController   message:This message is Warn-Level. replace_value_2
date:2016-05-30 17:34:18.590  thread:http-bio-8080-exec-3  X-Track:e2a65cd9160b48d6aaeb63fe6e751c6b  level:ERROR  logger:com.example.sample.app.welcome.HomeController   message:This message is Error-Level. replace_value_3
date:2016-05-30 17:34:18.590  thread:http-bio-8080-exec-3  X-Track:e2a65cd9160b48d6aaeb63fe6e751c6b  level:TRACE  logger:com.example.sample.app.welcome.HomeController   message:This message is Trace-Level. replace_value_4
date:2016-05-30 17:34:18.590  thread:http-bio-8080-exec-3  X-Track:e2a65cd9160b48d6aaeb63fe6e751c6b  level:INFO   logger:com.example.sample.app.welcome.HomeController   message:UNDEFINED-MESSAGE id:i.ab.cd.1002 arg:[replace_value_5]

7.1.3.2. Integration of output format of log messages

Output format of log messages differs according to log output format as given in the table below..

Hence, log output format must be combined with another format or both the formats must be integrated with individual format in the integration of log format.

In this guideline, an example wherein the format is defined in the log output by business logic and an example wherein both are integrated with the individual format ({Exception code (message ID) or log ID}], {message or log message}) are explained.

Sr. No.	Log output format	Corresponding log	Default format
(1)	Explicitly output log using business logic	Access log, external communication log etc	Nil
(2)	Framework detects the exception and implicitly outputs the log	Business error log, system error log etc	[{Exception code (Message ID)}] {Message}

Note

“Business error log” and “system error log” output at the time of generating an exception are output in the default format of the table given above in accordance with the exception handling system of Common library.

7.1.3.2.1. Integration with the format of the log output by framework after detecting an exception

An implementation example is shown wherein the log output by business logic is coordinated with the format of the log output by framework after detecting an exception.

In this guideline, it is implemented by adding a process to apply format, in Logger wrapper class (LogIdBasedLogger ).

package com.example.sample.common.logger;

import java.text.MessageFormat; // (1)

// omitted

public class LogIdBasedLogger {

    private static final String LOG_MESSAGE_FORMAT = "[{0}] {1}"; // (2)

    // omitted

    private String createLogMessage(String id, String... args) {
        return MessageFormat.format(LOG_MESSAGE_FORMAT, id, getMessage(id,
                args)); // (1)
    }

    // omitted

}

Sr.No.	Description
(1)	Add a process wherein a log message is created based on log message format.
(2)	Define a format. Log ID replaces {0}and log message replaces {1}.

Execution results are as below.

date:2016-05-30 16:32:33.239  thread:http-bio-8080-exec-4  X-Track:4f61314a51524ab3a41832b0ceae7119  level:DEBUG  logger:com.example.sample.app.welcome.HomeController   message:debug log
date:2016-05-30 16:32:33.239  thread:http-bio-8080-exec-4  X-Track:4f61314a51524ab3a41832b0ceae7119  level:INFO   logger:com.example.sample.app.welcome.HomeController   message:[i.ab.cd.1001] This message is Info-Level. replace_value_1
date:2016-05-30 16:32:33.239  thread:http-bio-8080-exec-4  X-Track:4f61314a51524ab3a41832b0ceae7119  level:WARN   logger:com.example.sample.app.welcome.HomeController   message:[w.ab.cd.2001] This message is Warn-Level. replace_value_2
date:2016-05-30 16:32:33.239  thread:http-bio-8080-exec-4  X-Track:4f61314a51524ab3a41832b0ceae7119  level:ERROR  logger:com.example.sample.app.welcome.HomeController   message:[e.ab.cd.3001] This message is Error-Level. replace_value_3
date:2016-05-30 17:34:18.590  thread:http-bio-8080-exec-3  X-Track:4f61314a51524ab3a41832b0ceae7119  level:TRACE  logger:com.example.sample.app.welcome.HomeController   message:[t.ab.cd.4001] This message is Trace-Level. replace_value_4
date:2016-05-30 16:32:33.239  thread:http-bio-8080-exec-4  X-Track:4f61314a51524ab3a41832b0ceae7119  level:INFO   logger:com.example.sample.app.welcome.HomeController   message:[i.ab.cd.1002] UNDEFINED-MESSAGE id:i.ab.cd.1002 arg:[replace_value_5]

7.1.3.2.2. Integration to a unique format

An implementation example wherein the log output by business logic and framework is integrated in a unique format ([{Exception code (message ID) or log ID}], {message or log message}).

7.1.3.2.2.1. Define a format in the log which is output by business logic

An example wherein log output by business logic is output in the format mentioned earlier.

In this guideline, it is implemented by adding a process to apply the format, to Logger wrapper class (LogIdBasedLogger ).

package com.example.sample.common.logger;

import java.text.MessageFormat; // (1)

// omitted

public class LogIdBasedLogger {

    private static final String LOG_MESSAGE_FORMAT = "[{0}], {1}"; // (2)

    // omitted

    private String createLogMessage(String id, String... args) {
        return MessageFormat.format(LOG_MESSAGE_FORMAT, id, getMessage(id,
                args)); // (1)
    }

    // omitted

}

Sr. No.	Description
(1)	Add a process to create log message based on log message format.
(2)	Define a format. ID replaces {0}and log message replaces {1}.

Execution results are as below.

date:2016-05-30 16:32:33.239  thread:http-bio-8080-exec-4  X-Track:4f61314a51524ab3a41832b0ceae7119  level:DEBUG  logger:com.example.sample.app.welcome.HomeController   message:debug log
date:2016-05-30 16:32:33.239  thread:http-bio-8080-exec-4  X-Track:4f61314a51524ab3a41832b0ceae7119  level:INFO   logger:com.example.sample.app.welcome.HomeController   message:[i.ab.cd.1001], This message is Info-Level. replace_value_1
date:2016-05-30 16:32:33.239  thread:http-bio-8080-exec-4  X-Track:4f61314a51524ab3a41832b0ceae7119  level:WARN   logger:com.example.sample.app.welcome.HomeController   message:[w.ab.cd.2001], This message is Warn-Level. replace_value_2
date:2016-05-30 16:32:33.239  thread:http-bio-8080-exec-4  X-Track:4f61314a51524ab3a41832b0ceae7119  level:ERROR  logger:com.example.sample.app.welcome.HomeController   message:[e.ab.cd.3001], This message is Error-Level. replace_value_3
date:2016-05-30 17:34:18.590  thread:http-bio-8080-exec-3  X-Track:4f61314a51524ab3a41832b0ceae7119  level:TRACE  logger:com.example.sample.app.welcome.HomeController   message:[t.ab.cd.4001], This message is Trace-Level. replace_value_4
date:2016-05-30 16:32:33.239  thread:http-bio-8080-exec-4  X-Track:4f61314a51524ab3a41832b0ceae7119  level:INFO   logger:com.example.sample.app.welcome.HomeController   message:[i.ab.cd.1002], UNDEFINED-MESSAGE arg:[replace_value_5]

7.1.3.2.2.2. Changing format of the log output by framework

An example wherein the log output by framework is output in format mentioned earlier.

Bean definition of ExceptionLoggerof applicationContext.xmlis changed to change the format of business error log and system error log.

An example of how to define ExceptionLoggeris given below.

• applicationContext.xml

<!-- Exception Logger. -->
<bean id="exceptionLogger"
    class="org.terasoluna.gfw.common.exception.ExceptionLogger">
    <property name="exceptionCodeResolver" ref="exceptionCodeResolver" />
    <property name="logMessageFormat" value="[{0}], {1}" />    <!-- (1) -->
</bean>

Sr. No.	Description
(1)	Define a format in logMessageFormat. Exception code (message ID) replaces {0}and message replaces {1}.

Execution results are as below..

date:2013-09-19 21:03:06   thread:tomcat-http--3   X-Track:c19eec546b054d54a13658f94292b24f    level:ERROR logger:o.t.gfw.common.exception.ExceptionLogger         message:[e.ad.od.9012], not found item entity. item code [10-123456].
...
// stackTarace omitted

7.1.4. Appendix

7.1.4.1. Using MDC

A cross-sectional log can be output by using MDC (Mapped Diagnostic Context).

Log traceability improves if same information (such as user name or unique request ID) is included in the log to be output in a request.

MDC internally consists of a ThreadLocal map and sets value for the key. The value set in log can be output till it is removed.

The value should be set at the beginning of the request and removed at the time of process termination.

7.1.4.1.1. Basic usage method

An example of using MDC is given below.

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

public class Main {

    private static final Logger logger = LoggerFactory.getLogger(Main.class);

    public static void main(String[] args) {
        String key = "MDC_SAMPLE";
        MDC.put(key, "sample"); // (1)
        try {
            logger.debug("debug log");
            logger.info("info log");
            logger.warn("warn log");
            logger.error("error log");
        } finally {
            MDC.remove(key); // (2)
        }
        logger.debug("mdc removed!");
    }
}

The value added to MDC can be output in log by defining the output format as %X{key name}format in <pattern> of logback.xml.

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern><![CDATA[date:%d{yyyy-MM-dd HH:mm:ss}\tthread:%thread\tmdcSample:%X{MDC_SAMPLE}\tlevel:%-5level\t\tmessage:%msg%n]]></pattern>
    </encoder>
</appender>

Execution results are as follows:

date:2013-11-08 17:45:48    thread:main mdcSample:sample    level:DEBUG     message:debug log
date:2013-11-08 17:45:48    thread:main mdcSample:sample    level:INFO      message:info log
date:2013-11-08 17:45:48    thread:main mdcSample:sample    level:WARN      message:warn log
date:2013-11-08 17:45:48    thread:main mdcSample:sample    level:ERROR     message:error log
date:2013-11-08 17:45:48    thread:main mdcSample:  level:DEBUG     message:mdc removed!

Note

If MDC.clear() is executed, all the added values are deleted.

7.1.4.1.2. Setting value in MDC using Filter

Common library provides org.terasoluna.gfw.web.logging.mdc.AbstractMDCPutFilter as a base class to add/delete values from MDC using filter.

Further, following are provided as implementation classes.

• org.terasoluna.gfw.web.logging.mdc.XTrackMDCPutFilter to set an unique ID for each request in MDC
• org.terasoluna.gfw.security.web.logging.UserIdMDCPutFilter to set authentication user name of Spring Security in MDC

If individual values are to be added to MDC using Filter, it is desirable to implement AbstractMDCPutFilter

based on implementation of org.terasoluna.gfw.web.logging.mdc.XTrackMDCPutFilter.

How to use MDCFilter

Definition of MDCFilter is added to the filter definition of web.xml.

<!-- omitted -->

<!-- (1) -->
<filter>
    <filter-name>MDCClearFilter</filter-name>
    <filter-class>org.terasoluna.gfw.web.logging.mdc.MDCClearFilter</filter-class>
</filter>

<filter-mapping>
    <filter-name>MDCClearFilter</filter-name>
    <url-pattern>/*</url-pattern>
</filter-mapping>

<!-- (2) -->
<filter>
    <filter-name>XTrackMDCPutFilter</filter-name>
    <filter-class>org.terasoluna.gfw.web.logging.mdc.XTrackMDCPutFilter</filter-class>
</filter>
<filter-mapping>
    <filter-name>XTrackMDCPutFilter</filter-name>
    <url-pattern>/*</url-pattern>
</filter-mapping>

<!-- (3) -->
<filter>
    <filter-name>UserIdMDCPutFilter</filter-name>
    <filter-class>org.terasoluna.gfw.security.web.logging.UserIdMDCPutFilter</filter-class>
</filter>
<filter-mapping>
    <filter-name>UserIdMDCPutFilter</filter-name>
    <url-pattern>/*</url-pattern>
</filter-mapping>

<!-- omitted -->

Sr. No.	Description
(1)	MDCClearFilter that clears the contents of MDC is set. Values in MDC added by various MDCPutFilter are deleted by this Filter.
(2)	XTrackMDCPutFilter is set. XTrackMDCPutFilter sets Request ID in key “X-Track”.
(3)	UserIdMDCPutFilter is set. UserIdMDCPutFilter sets User ID in key “USER”.

As shown in the sequence diagram below, MDCClearFilter should be defined prior to each MDCPutFilterto clear the contents of MDC for post-processing.

Request ID and User ID can be output to log by adding %X{X-Track} and %X{USER} in <pattern> of logback.xml.

<!-- omitted -->
<appender name="APPLICATION_LOG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${app.log.dir:-log}/projectName-application.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>${app.log.dir:-log}/projectName-application-%d{yyyyMMdd}.log</fileNamePattern>
        <maxHistory>7</maxHistory>
    </rollingPolicy>
    <encoder>
        <charset>UTF-8</charset>
        <pattern><![CDATA[date:%d{yyyy-MM-dd HH:mm:ss}\tthread:%thread\tUSER:%X{USER}\tX-Track:%X{X-Track}\tlevel:%-5level\tlogger:%-48logger{48}\tmessage:%msg%n]]></pattern>
    </encoder>
</appender>
<!-- omitted -->

Example of log output

date:2013-09-06 23:05:22  thread:tomcat-http--3   USER:   X-Track:97988cc077f94f9d9d435f6f76027428    level:DEBUG logger:o.t.g.w.logging.HttpSessionEventLoggingListener  message:SESSIONID#D7AD1D42D3E77D61DB64E7C8C65CB488 sessionCreated : org.apache.catalina.session.StandardSessionFacade@e51960
date:2013-09-06 23:05:22  thread:tomcat-http--3   USER:anonymousUser  X-Track:97988cc077f94f9d9d435f6f76027428    logger:o.t.gfw.web.logging.TraceLoggingInterceptor      message:[START CONTROLLER] HomeController.home(Locale,Model)
date:2013-09-06 23:05:22  thread:tomcat-http--3   USER:anonymousUser  X-Track:97988cc077f94f9d9d435f6f76027428    level:INFO  logger:c.terasoluna.logging.app.welcome.HomeController  message:Welcome home! The client locale is ja.
date:2013-09-06 23:05:22  thread:tomcat-http--3   USER:anonymousUser  X-Track:97988cc077f94f9d9d435f6f76027428    logger:o.t.gfw.web.logging.TraceLoggingInterceptor      message:[END CONTROLLER  ] HomeController.home(Locale,Model)-> view=home, model={serverTime=2013/09/06 23:05:22 JST}
date:2013-09-06 23:05:22  thread:tomcat-http--3   USER:anonymousUser  X-Track:97988cc077f94f9d9d435f6f76027428    logger:o.t.gfw.web.logging.TraceLoggingInterceptor      message:[HANDLING TIME   ] HomeController.home(Locale,Model)-> 36,508,860 ns

Note

User information to be set in MDC by UserIdMDCPutFilter is created by Spring Security Filter. As mentioned earlier, if UserIdMDCPutFilter is defined in web.xml, user ID is output to log after the completion of a series of Spring Security processes. If user information is to be output to the log immediately after it is generated, the information should be incorporated in Spring Security Filter as shown below by deleting web.xml definition.

The definitions given below are added to spring-security.xml.

<sec:http>
    <!-- omitted -->
    <sec:custom-filter ref="userIdMDCPutFilter" after="ANONYMOUS_FILTER"/> <!-- (1) -->
    <!-- omitted -->
</sec:http>

<!-- (2) -->
<bean id="userIdMDCPutFilter" class="org.terasoluna.gfw.security.web.logging.UserIdMDCPutFilter">
</bean>

Sr. No.	Description
(1)	UserIdMDCPutFilter defined in Bean is added after “ANONYMOUS_FILTER”.
(2)	UserIdMDCPutFilter is defined.

In blank project, UserIdMDCPutFilter is defined in spring-security.xml.

7.1.4.2. Log output related functionalities provided by common library

7.1.4.2.1. HttpSessionEventLoggingListener

org.terasoluna.gfw.web.logging.HttpSessionEventLoggingListener is a listener class that outputs debug log at the time of generating, discarding, activating or deactivating session, and adding or deleting session attributes.

The following should be added to web.xml.

<?xml version="1.0" encoding="UTF-8"?>
<web-app xmlns="http://java.sun.com/xml/ns/javaee" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://java.sun.com/xml/ns/javaee http://java.sun.com/xml/ns/javaee/web-app_3_0.xsd"
    version="3.0">
    <listener>
        <listener-class>org.terasoluna.gfw.web.logging.HttpSessionEventLoggingListener</listener-class>
    </listener>

    <!-- omitted -->
</web-app>

In logback.xml, org.terasoluna.gfw.web.logging.HttpSessionEventLoggingListener is set at debug level as shown below.

<logger
    name="org.terasoluna.gfw.web.logging.HttpSessionEventLoggingListener"> <!-- (1) -->
    <level value="debug" />
</logger>

Debug log as shown below is output.

date:2013-09-06 16:41:33    thread:tomcat-http--3   USER:   X-Track:c004ddb56a3642d5bc5f6b5d884e5db2        level:DEBUG     logger:o.t.g.w.logging.HttpSessionEventLoggingListener  message:SESSIONID#EDC3C240A7A1CCE87146A6BA1321AD0F sessionCreated : org.apache.catalina.session.StandardSessionFacade@f00e0f

When the lifecycle of an object is managed using a Session such as @SessionAttributes etc., it is strongly recommended to use this listener to confirm whether the attributes added to the session are deleted as anticipated.

7.1.4.2.2. TraceLoggingInterceptor

org.terasoluna.gfw.web.logging.TraceLoggingInterceptor is the HandlerInterceptor to output start and termination of Controller process to the log. When the process is terminated, View name returned by the Controller, attributes added to Model and the time required for Controller process are also output.

TraceLoggingInterceptoris added in <mvc:interceptors> of spring-mvc.xml as shown below.

<mvc:interceptors>
    <!-- omitted -->
    <mvc:interceptor>
        <mvc:mapping path="/**" />
        <mvc:exclude-mapping path="/resources/**" />
        <bean
            class="org.terasoluna.gfw.web.logging.TraceLoggingInterceptor">
        </bean>
    </mvc:interceptor>
    <!-- omitted -->
</mvc:interceptors>

By default, WARN log is output if Controller process takes more than 3 seconds.

When the threshold value is to be changed, it is specified in nano seconds in warnHandlingNanos property.

The following settings should be performed if the threshold value is to be changed to 10 seconds (10 * 1000 * 1000 * 1000 nano seconds).

<mvc:interceptors>
    <!-- omitted -->
    <mvc:interceptor>
        <mvc:mapping path="/**" />
        <mvc:exclude-mapping path="/resources/**" />
        <bean
            class="org.terasoluna.gfw.web.logging.TraceLoggingInterceptor">
            <property name="warnHandlingNanos" value="#{10 * 1000 * 1000 * 1000}" />
        </bean>
    </mvc:interceptor>
    <!-- omitted -->
</mvc:interceptors>

In logback.xml, org.terasoluna.gfw.web.logging.TraceLoggingInterceptor is set at trace level as shown below.

<logger name="org.terasoluna.gfw.web.logging.TraceLoggingInterceptor"> <!-- (1) -->
    <level value="trace" />
</logger>

7.1.4.2.3. ExceptionLogger

org.terasoluna.gfw.common.exception.ExceptionLogger is provided as a logger when an exception occurs.

Refer to How to use of Exception Handling for the usage method.