How to log in Spring with SLF4J and Logback

strawbingo

于 2015-04-14 18:51:53 发布

阅读量1k

点赞数

In this post I will present how to log in a Spring based application with the help of Simple Logging Facade for Java (SLF4J) and Logback. For demonstration I will use the application presented in the post Tutorial – REST API design and implementation in Java with Jersey and Spring, to which I wil…

1. Introduction

1.1. Simple Logging Facade for Java(SL4J)

The SLF4J serves as a simple facade or abstraction for various logging frameworks, such as java.util.logging, logback and log4j. SLF4J allows the end-user to plug in the desired logging framework atdeploymenttime. Note that SLF4J-enabling your library/application implies the addition of only a single mandatory dependency, namely slf4j-api-x.x.x.jar.

1.2. Logback

From Logback’s official documentation:

“Logback is intended as a successor to the popular log4j project, picking up where log4j leaves off.

Logback’s architecture is sufficiently generic so as to apply under different circumstances. At present time, logback is divided into three modules, logback-core, logback-classic and logback-access.

The logback-core module lays the groundwork for the other two modules. The logback-classic module can be assimilated to a significantly improved version of log4j. Moreover, logback-classic natively implements the SLF4J APIso that you can readily switch back and forth between logback and other logging frameworks such as log4j or java.util.logging (JUL).

The logback-access module integrates with Servlet containers, such as Tomcat and Jetty, to provide HTTP-access log functionality. Note that you could easily build your own module on top of logback-core.”

1.3. Spring

Spring is using by default Jakarta Commons Logging, but in the blog postLogging Dependencies in Springfrom Spring.io it says “if we could turn back the clock and start Spring now as a new project it would use a different logging dependency. Probably the first choice would be the Simple Logging Facade for Java (SLF4J)“

2. Configuration

To use SLF4J with Spring you need to replace thecommons-loggingdependency with theSLF4J-JCL bridge. Once you have done that, then logging calls from within Spring will be translated into logging calls to the SLF4J API, so if other libraries in your application use that API, then you have a single place to configure and manage logging.

2.1. Spring

2.1.1. Excludecommons-logging

To switch off commons-logging, the commons-logging dependency mustn’t be present in the classpath at runtime. If you are using maven like me, you can simply exclude it from the spring-context artifact:

<dependency>	<groupId>org.springframework</groupId>	<artifactId>spring-context</artifactId>	<version>${spring.version}</version>	<exclusions>	 <exclusion>		<groupId>commons-logging</groupId>		<artifactId>commons-logging</artifactId>	 </exclusion>	</exclusions>			</dependency>

2.1.2. Required libraries

Because I am using LogBack, which implements SLF4J directly, you will need to depend on two libraries (jcl-over-slf4jandlogback):

<!-- LogBack dependencies --> <dependency>	<groupId>ch.qos.logback</groupId>	<artifactId>logback-classic</artifactId>	<version>${logback.version}</version></dependency><dependency>										<groupId>org.slf4j</groupId>					<artifactId>jcl-over-slf4j</artifactId>	 	<version>${jcloverslf4j.version}</version></dependency>

Note:You might also want to exclude the

slf4j-apidepedency from other external dependencies, besides Spring, to avoid having more than one version of that API on the classpath.

Code tip:

All dependencies required for the projects can be found on GitHub in the pom.xmlfile.

2.2. Logback

To configure Logback all you have to do is place the filelogback.xmlin the classpath.

2.1. logback.xml

<?xml version="1.0" encoding="UTF-8"?><configuration>	<appender name="consoleAppender" class="ch.qos.logback.core.ConsoleAppender">		<encoder>			<Pattern>.%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg %n			</Pattern>		</encoder>		<filter class="ch.qos.logback.classic.filter.ThresholdFilter">			<level>TRACE</level>		</filter>	</appender>	<appender name="dailyRollingFileAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">		<File>c:/tmp/rest-demo.log</File>		<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">			<!-- daily rollover -->			<FileNamePattern>rest-demo.%d{yyyy-MM-dd}.log</FileNamePattern>			<!-- keep 30 days' worth of history -->			<maxHistory>30</maxHistory>					</rollingPolicy>		<encoder>			<Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{35} - %msg %n</Pattern>		</encoder>		 	</appender>	<appender name="minuteRollingFileAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">		<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">			<!-- rollover every minute -->			<FileNamePattern>c:/tmp/minutes/rest-demo-minute.%d{yyyy-MM-dd_HH-mm}.log</FileNamePattern>			<!-- keep 30 minutes' worth of history -->			<maxHistory>30</maxHistory>					</rollingPolicy>		<encoder>			<Pattern>%-4relative [%thread] %-5level %logger{35} - %msg %n</Pattern>		</encoder>		 	</appender>		<logger name="org.codingpedia" additivity="false">		<level value="DEBUG" />		<appender-ref ref="dailyRollingFileAppender"/>		<appender-ref ref="minuteRollingFileAppender"/>		<appender-ref ref="consoleAppender" />	</logger>	<root>		<level value="INFO" />		<appender-ref ref="consoleAppender" />	</root></configuration>

Logback uses

appenders

, which are components Logback delegates the task of writing logging events to.

2.1.1. ConsoleAppender

As the name says it, this appender logs to the console. It has an encoder property –encodersare responsible for transforming an incoming event into a byte array andwriting out the resulting byte array onto the appropriate OutputStream.

Note:Until logback version 0.9.19, many appenders relied on the Layout instances to control the format of log output. Since then encoders are the standard – encoders are assigned the type of ch.qos.logback.classic.encoder.PatternLayoutEncoderby default.

ThePatternLayoutEncoderwraps instances ofPatternLayout– this takes a logging event and returns a String, which you can customize by using PatternLayout’s conversion pattern.

From Logaback’s documentation:

“The conversion pattern of PatternLayout is closely related to the conversion pattern of the printf() function in the C programming language. A conversion pattern is composed of literal text and format control expressions calledconversion specifiers. You are free to insert any literal text within the conversion pattern. Each conversion specifier starts with a percent sign ‘%’ and is followed by optional format modifiers, a conversion word and optional parameters between braces. The conversion word controls the data field to convert, e.g. logger name, level, date or thread name. The format modifiers control field width, padding, and left or right justification.”

You can find below a short explanation of the the conversion specifiers used in the example:

%d{HH:mm:ss.SSS}– Used to output the date of the logging event.
%thread- outputs the name of the thread that generated the logging event
%-5level– means the level of the logging event should be left justified to a width of five characters
%logger{36}– outputs the name of the logger at the origin of the logging event. It takes an integer as parameter. This specifies the length the converter’s algorithm will shorten the logger name to.
%msg– outputs the application-supplied message associated with the logging event.
%n– outputs the platform dependent line separator character or characters.
%relative– outputs the number of milliseconds elapsed since the start of the application until the creation of the logging event

The result looks something like this:

10:12:51.012 [qtp231719230-45] DEBUG o.c.d.r.util.LoggingResponseFilter

1	10:12:51.012 [qtp231719230-45] DEBUG o.c.d.r.util.LoggingResponseFilter

102662 [qtp1790106082-48] DEBUG o.c.d.r.dao.PodcastDao.getPodcasts

1	102662 [qtp1790106082-48] DEBUG o.c.d.r.dao.PodcastDao.getPodcasts

2.1.2. RollingFileAppender

TheRollingFileAppender extends FileAppender with the capability to rollover log files. In the example, the RollingFileAppender will log to a file namedrest-demo.log file and, once a certain condition (every day and every minute) is met, change its logging target to another file.

There are two important sub-components that interact withRollingFileAppender. The first RollingFileAppendersub-component, namely RollingPolicy, is responsible for undertaking the actions required for a rollover. A second sub-component of RollingFileAppender, namely TriggeringPolicy, will determine if and exactly when rollover occurs. Thus, RollingPolicyis responsible for the whatand TriggeringPolicyis responsible for the when.

To be of any use, aRollingFileAppendermust have both aRollingPolicyand a TriggeringPolicyset up. However, if its RollingPolicyalso implements the TriggeringPolicyinterface, then only the former needs to be specified explicitly – this is exactly the case in the example, where TimeBasedRollingPolicyis used. This assumes the responsibility for rollover as well as for the triggering of said rollover, by implementingbothRollingPolicyand TriggeringPolicy interfaces.

In the example the rollover occurs daily and every minute. For the “daily”-appender, the file property is set torest-demo.log: During today (March 21th, 2014), logging will go to the filec:/temp/rest-demo.log. At midnight, the rest-demo.log will be renamed toc:/rest-demo.2014-03-21.logand a newc:/temp/rest-demo.logwill be created and for the rest of March 22th logging output will be redirected to rest-demo.log.

Note:

The fileproperty in

RollingFileAppender (the parent of TimeBasedRollingPolicy) can be either set or omitted. By setting the file property of the containing FileAppender, you can decouple the location of the active log file and the location of the archived log files.

3. Integration in code

To use SLF4J in code is pretty easy – you just have to get a logger, and then on that logger you can log messages at the different logging levels (TRACE, DEBUG, INFO, WARN, ERROR).

For demonstration purposes I created a special logging filter LoggingResponseFilter (didn’t want the REST facade cluttered with logging code) in the REST content, that will log

input– the HTTP method used + the relative path called of the REST resource
output– a pretty print of the response entities in JSON format

package org.codingpedia.demo.rest.util;import java.io.IOException;import javax.ws.rs.container.ContainerRequestContext;import javax.ws.rs.container.ContainerResponseContext;import javax.ws.rs.container.ContainerResponseFilter;import org.codehaus.jackson.map.ObjectMapper;import org.slf4j.Logger;import org.slf4j.LoggerFactory;public class LoggingResponseFilter	implements ContainerResponseFilter {private static final Logger logger = LoggerFactory.getLogger(LoggingResponseFilter.class);public void filter(ContainerRequestContext requestContext,	ContainerResponseContext responseContext) throws IOException {	String method = requestContext.getMethod();	logger.debug("Requesting " + method + " for path " + requestContext.getUriInfo().getPath());	Object entity = responseContext.getEntity();	if (entity != null) {	logger.debug("Response " + new ObjectMapper().writerWithDefaultPrettyPrinter().writeValueAsString(entity));	}}}

So you I am just getting the “LoggingResponseFilter ” logger and on that, I will log messages at DEBUG level and upwards.

Well, that’s it! I would like to use this opportunity once again to thank the people who have developed and documented these wonderful frameworks. To name a few Dave Syer, Ceki Gülcü, Sébastien Pennec, Carl Harris . Thank you guys and keep up the good work!