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.1.0.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.default-minimum-duration

int

Number of milliseconds a method should take before it will be logged.

75

logging.method.configuration

MethodLogConfiguration.class

Advanced 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.excluded-path-patterns

Collection<String>

Path patterns that should be excluded from request logging.

logging.request.included-path-patterns

Collection<String>

Path patterns that should be included for request logging.

all

logging.request.servlet-name-filter-mappings

Collection<String>

Servlet names to which the request logger should be applied (if filter).

logging.request.url-filter-mappings

Collection<String>

Servlet URL patterns to which the request logger should be applied (if filter).

/*

logging.request.logger-level-threshold

LoggerLevelThreshold.class

Configure custom log levels depending on request duration.

null

logging.request.configuration

RequestLoggerConfiguration.class

Advanced configuration settings for request logging.

null

logging.request-response.enabled

boolean

Should request/response debug logging be possible?

false

logging.request-response.paused

boolean

Should request/response debug logging be paused?

false

logging.request-response.max-entries

int

Number of request/response log entries that should be kept in memory.

100

logging.request-response.excluded-path-patterns

Collection<String>

Path patterns that should be excluded from request/response logging.

/debug/**,/across/**,/**/login

logging.request-response.included-path-patterns

Collection<String>

Path patterns that should be included for request/response logging.

all

logging.request-response.servlet-name-filter-mappings

Collection<String>

Servlet names to which the request/response logger should be applied (if filter).

logging.request-response.url-filter-mappings

Collection<String>

Servlet URL patterns to which the request/response logger should be applied (if filter).

/*

logging.request-response.configuration

RequestResponseLogConfiguration.class

Advanced configuration settings for request/response debug logging.

null

2. What’s new in this version?

1.1.0.RELEASE

  • switched to @ConfigurationProperties for settings - allow settings via application.properties

  • request/response debug logging changes now also writes request parameters

    • the logger is now paused by default (it has a performance impact when enabled)

    • request parameters are now also returned (any parameter name containing password will have its value masked)

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. Activating method logging will activate the module specific logging configurations. Modules can define one or more MethodLogger instances reponsible for logging certain types of method calls (eg. repository calls). Most modules create a single MethodLogger with the same name as the module itself.

Example logging all methods with a duration of 75ms or more
logging.method.enabled=true
logging.method.default-minimum-duration=75

More advanced configuration can be done by manually setting an MethodLogConfiguration instance. The MethodLogConfiguration allows you to configure the minimum duration for method calls on a global or per-MethodLogger level.

Enabling method logging manually 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
Method logging has a performance impact and 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 through using a servlet filter. This can be altered by setting the logging.request.logger property.

Additionally there are some properties to finetune the request logging, or you can create your own RequestLoggerConfiguration instance. Advanced configuration can be used to specify:

  • 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 - through properties
logging.request.excluded-path-patterns=/across/**
Enabling request logging for all requests except static resources - manually
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.

Warning
Using the request/response debug logging has a negative impact on performance and can cause side effects in rare cases. Use it only 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, performance impact will be negligable. The active state can be controlled through the logging.requestResponse.paused property or at runtime via the debug controllers.

Configuration of request/response logging can be done through properties.

Activating request/response logging
logging.request-response.enabled=true

Different properties allow you to customize parameters like maximum log entries to keep (defaults to 100), or the paths to include for logging. More advanced configuration can be done through specifying a RequestResponseLogConfiguration instance (logging.requestResponse.configuration property).

Additional configuration options include:

  • 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.