About

LoggingModule provides the following infrastructure:

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.

1.3. Module settings

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.

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.