LoggingModule

Copyright © 2014-2015
Copies of this document may be made for your own use and for distribution to others, provided that you do not charge any fee for such copies and further provided that each copy contains this Copyright Notice, whether distributed in print or electronically.

About

LoggingModule provides the following infrastructure:

a debug controller for configuring Logback loggers at runtime
supporting infrastructure to enable method call logging of beans
general purpose web request logging
detailed web request/response logging for debugging purposes

Module website: https://foreach.atlassian.net/wiki/display/AX/LoggingModule

1. General information

1.1. Artifact

<dependencies>
    <dependency>
        <groupId>com.foreach.across.modules</groupId>
        <artifactId>logging-module</artifactId>
        <version>1.0.1.RELEASE</version>
    </dependency>
</dependencies>

1.2. Module dependencies

Module	Type	Description
AcrossWebModule	optional	Activates support for request logging and request/response debug logging.
DebugWebModule	optional	Enables the debug controllers for logger management and request/response logging.
ApplicationInfoModule	extension	Will use the configured application instance id as applicationInstanceId.

Module

Type

Description

AcrossWebModule

optional

Activates support for request logging and request/response debug logging.

DebugWebModule

optional

Enables the debug controllers for logger management and request/response logging.

ApplicationInfoModule

extension

Will use the configured application instance id as applicationInstanceId.

1.3. Module settings

Property Type Description Default

Property	Type	Description	Default
logging.method.enabled	`boolean`	Should method logging extensions in modules be loaded?	false
logging.method.configuration	`MethodLogConfiguration.class`	Configuration settings for method logging.	null
logging.request.logger	`RequestLogger.class`	Should request logging be disabled, or enabled as filter or servlet?	RequestLogger.FILTER
logging.request.configuration	`RequestLoggerConfiguration.class`	Configuration settings for request logging.	All requests will be logged.
logging.requestResponse.enabled	`boolean`	Should request/response debug logging be possible?	false
logging.requestResponse.paused	`boolean`	Should request/response debug logging be paused?	false
logging.requestResponse.configuration	`RequestResponseLogConfiguration.class`	Configuration settings for request/response debug logging.	All requests will be logged.

logging.method.enabled

boolean

Should method logging extensions in modules be loaded?

false

logging.method.configuration

MethodLogConfiguration.class

Configuration settings for method logging.

null

logging.request.logger

RequestLogger.class

Should request logging be disabled, or enabled as filter or servlet?

RequestLogger.FILTER

logging.request.configuration

RequestLoggerConfiguration.class

Configuration settings for request logging.

All requests will be logged.

logging.requestResponse.enabled

boolean

Should request/response debug logging be possible?

false

logging.requestResponse.paused

boolean

Should request/response debug logging be paused?

false

logging.requestResponse.configuration

RequestResponseLogConfiguration.class

Configuration settings for request/response debug logging.

All requests will be logged.

2. What’s new in this version?

1.0.0.RELEASE

Initial public release available on Maven central.

3. Logger management

Note	Only available if DebugWebModule is present.

LoggingModule adds a debug controller giving an overview of all Logback configured loggers and appenders. The log level for any logger can be changed at runtime. The controller can be accessed through debug web menu item Logging → Logger overview.

4. Method logging

LoggingModule provides some basic infrastructure that allows other Across modules to enable method logging. All method calls with a duration longer than a configured minimum will be logged. Method logging is achieved by enhancing the beans using AOP.

If method logging is enabled, LoggingModule will scan all other modules for an extension configuration class called MethodLoggingConfiguration. This configuration class should be located in the extensions package relative to the module class. The configuration will usually provide a MethodLogger bean that extends MethodLoggerAdapter. Due to possible limitations of the proxying mechanism, it is the responsibility of the modules to define support for method logging.

Using method logging can be a useful alternative for finding performance bottlenecks if more specialized profiling tools are not available.

4.1. Configuration

Method logging must be activated when configuring the LoggingModule. This should be done by setting a valid configuration (logging.method.configuration property) and enabling method logging (logging.method.enabled property). The MethodLogConfiguration allows you to configure the minimum duration for method calls on a global or per-MethodLogger level. Most modules create a single MethodLogger with the same name as the module itself.

Enabling method logging for all methods exceeding 15ms

LoggingModule loggingModule = new LoggingModule();
loggingModule.setProperty( LoggingModuleSettings.METHOD_LOG_ENABLED, true );
MethodLogConfiguration methodLogConfiguration = MethodLogConfiguration.all( 15 );
loggingModule.setProperty( LoggingModuleSettings.METHOD_LOG_CONFIGURATION, methodLogConfiguration );

Warning

Enabling global method logging with a very small minimum duration can result in huge log files on a busy system.

4.2. Logging output

A method log entry is a simple tab-separated log message sent to a SLF4J logger. The logger name is com.foreach.across.modules.logging.method.MethodLogger suffixed with the method logger name (eg: com.foreach.across.modules.logging.method.MethodLogger.MyModule).

A tab-separated log message contains the following fields:

Method level
Method being executed
Duration (ms)

Note	Using tab-separated output makes it very easy to import log-files for analysis in external tools like Microsoft Excel.

4.2.1. Method level

Method level attempts to give an indication about possible optimization targets. A method level of 1 means this is the first logged method to exceed the minimum duration. In other words: the method call is not composed of other methods that match the logging rules and have exceeded the minimum duration. When investigating performance, the lowest method level calls are usually a good place to start.

The method level calculation is considered experimental.

4.2.2. Logback configuration

The following section provides a common Logback example for configuration of method logging, and the resulting output.

Example logback configuration for method logging with request logging enabled

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
	<appender name="methods" class="ch.qos.logback.core.ConsoleAppender">
		<encoder>
			<pattern>%d{ISO8601}\t[%X{requestId}]\t%t\t%logger{0}\t%m%n</pattern>
		</encoder>
	</appender>

	<logger name="com.foreach.across.modules.logging.method.MethodLogger" level="info" additivity="false">
		<appender-ref ref="methods"/>
	</logger>
</configuration>

Example log statement

2015-08-29 16:47:53,662	[3b0d69cb-9e99-4c02-ae44-65a192f0e0d9]	http-apr-8079-exec-6	MyModule	1	mymodule.services.SomeService.createItem	163

Table 1. Anatomy of the log statement
Timestamp	2015-08-29 16:47:53,662
Request id	3b0d69cb-9e99-4c02-ae44-65a192f0e0d9
Thread	http-apr-8079-exec-6
Logger	MyModule
Method level	1
Method	mymodule.services.SomeService.createItem
Duration	163

4.3. Creating a method logger

A module can support method logging by providing an extension configuration called MethodLoggingConfiguration. The configuration will only be loaded if method logging on the LoggingModule is enabled.

Most often it is enough for a module to define a single MethodLoggerAdapter bean that defines all methods to be intercepted for logging. The adapter class ensures that the LoggingModule configuration features are supported and the log messages are in the right format.

com.mymodule.extensions.MethodLoggingConfiguration

@Configuration
@EnableAspectJAutoProxy(proxyTargetClass = true)
@SuppressWarnings("unused")
public class MethodLoggingConfiguration
{
	@Bean
	public MethodExecutionLogger methodExecutionLogger() {
		return new MethodExecutionLogger();
	}

	@Aspect
	static class MethodExecutionLogger extends MethodLoggerAdapter
	{
		public MethodExecutionLogger() {
			super( MyModule.NAME );
		}

		@Around("serviceMethod() || repositoryMethod()")
		@Override
		protected Object proceedAndLogExecutionTime( ProceedingJoinPoint point ) throws Throwable {
			return super.proceedAndLogExecutionTime( point );
		}

		@Pointcut("execution(* com.mymodule.services...(..))")
		public void serviceMethod() {
		}

		@Pointcut("execution(* com.mymodule.repositories...(..))")
		public void repositoryMethod() {
		}
	}
}

5. Request logging

Note	Only available if AcrossWebModule is present.

In a web context the LoggingModule will register a servlet filter that logs request information. Every request will get a unique id assigned and attributes like the handler name, request url and request mapping will be logged if they can be determined.

5.1. Configuration

By default request logging for all requests is enabled. This can be altered by setting the logging.request.logger property. Additionally you can finetune the request logging through a RequestLoggerConfiguration instance (logging.request.configuration property). Through the configuration instance you can configure:

to which servlets the filter should apply (defaults to all)
the path patterns that requests should match before they are logged
the log level threshold that allows you to configure different log levels to be used when requests exceed certain durations

Enabling request logging for all requests except static resources

LoggingModule loggingModule = new LoggingModule();
RequestLoggerConfiguration requestLoggerConfiguration = RequestLoggerConfiguration.allRequests();
requestLoggerConfiguration.setExcludedPathPatterns( Arrays.asList( "/across/**" ) );
loggingModule.setProperty( LoggingModuleSettings.REQUEST_LOGGER_CONFIGURATION, requestLoggerConfiguration );

Warning

The RequestLogger.INTERCEPTOR option can be used to enable request logging without the use of the servlet filter. Though it still works, this option is no longer actively supported.

5.2. MDC attributes

The RequestLoggerFilter adds two attributes to the MDC:

requestId: A generated id that uniquely identifies the request. By adding the requestId to every log appender, log statements can be traced back to a specific request.
applicationInstanceId: A configured value identifying the application instance. Only if the ApplicationInfoModule is active.

5.3. Request-Reference

The unique requestId is added to every response as a Request-Reference header.

5.4. Logging output

A request log entry is a tab-separated log message sent to the SLF4J logger named com.foreach.across.modules.logging.request.RequestLogger. The tab-separated log message contains the following fields:

Remote address
HTTP method
URL
Servlet path
Best matching request mapping
Handler name
View name
HTTP status code
Duration (ms)

Depending on the application configuration or type of request, certain fields might not be available. In that case a field-dependent default value (either empty, 0 or null) will be output, but the position of the field will always exist so tab-based parsing does not fail.

5.4.1. Logback configuration

The following section provides a common Logback example for configuration of request logging, and the resulting output.

Example logback configuration for request logging

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
	<appender name="pages" class="ch.qos.logback.core.ConsoleAppender">
		<encoder>
			<pattern>%d{ISO8601}\t[%X{requestId}]\t%t\t%level\t%m%n</pattern>
		</encoder>
	</appender>

	<logger name="com.foreach.across.modules.logging.request.RequestLogger" level="debug" additivity="false">
		<appender-ref ref="pages"/>
	</logger>
</configuration>

Example log statement

2015-11-02 12:58:15,212	[5f18be5e-5b64-4c3a-9843-740f16c32641]	http-apr-8080-exec-4	DEBUG	127.0.0.1	GET	http://localhost:8080/logging/debug/across/browser/info/0	/debug/across/browser/info/0	/debug/across/browser/info/{index}	AcrossInfoController.showContextInfo(List,int,Model)	th/debugweb/layouts/acrossBrowser	200	784

Table 2. Anatomy of the log statement
Timestamp	2015-11-02 12:58:15,212
Request id	5f18be5e-5b64-4c3a-9843-740f16c32641
Thread	http-apr-8080-exec-4
Log level	DEBUG
Remote address	127.0.0.1
HTTP method	GET
Request URL	http://localhost:8080/logging/debug/across/browser/info/0
Servlet path	/debug/across/browser/info/0
Request mapping	/debug/across/browser/info/{index}
Handler name	AcrossInfoController.showContextInfo(List,int,Model)
View name	th/debugweb/layouts/acrossBrowser
HTTP status code	200
Duration	784

6. Request/response debug logging

Note	Only available if AcrossWebModule is present.

LoggingModule also supports a detailed request/response logging for debugging purposes. It can be used to log the full request and response, including body and headers. Request/response debug logging will wrap the incoming request and outgoing response. Be aware this could cause side effects in some rare cases.

The purpose of request/response logging is mainly for temporary debugging of specific requests, preferably in a non-production environment. LoggingModule comes with a set of debug controllers that allow you to view the logs and change the logging settings for specific request paths.

6.1. Configuration

Before request/response logging is possible, it should first be enabled (logging.requestResponse.enabled property).

If request/response logging is enabled, it can still be either active or paused. If logging is not active, no data will be stored and requests/responses will not be wrapped. The active state can be controlled through the logging.requestResponse.paused property or at runtime via the debug controllers.

Advanced configuration is done through a RequestResponseLogConfiguration instance (logging.requestResponse.configuration property). Log entries are only kept in memory and the configuration allows you to set the maximum to be kept (defaults to 100). Additionally you have the following configuration options:

to which servlets the filter should apply (defaults to all)
the path patterns that requests should match before they are logged

If DebugWebModule is present, the debug controllers allow runtime modifications of the path patterns as well.

Enabling request/response logging for all api requests

LoggingModule loggingModule = new LoggingModule();
loggingModule.setProperty( LoggingModuleSettings.REQUEST_RESPONSE_LOG_ENABLED, true );
RequestResponseLogConfiguration logConfiguration = new RequestResponseLogConfiguration();
logConfiguration.setIncludedPathPatterns( Arrays.asList( "/api/**" ) );
loggingModule.setProperty( LoggingModuleSettings.REQUEST_RESPONSE_LOG_CONFIGURATION, logConfiguration );

6.2. Debug controllers

Note	Only available if DebugWebModule is present.

If request/response debug logging is enabled, LoggingModule adds a subsection Request - response to the Logging section. The Settings controller allows you to update the path settings that requests should match before their details are logged. The Overview controller allows you to pause/activate the logging, as well as browse all log entries.