Logging

Configuring Logback in a Web Application

When developing web applications in the past, most of them used Log4J for doing logging. Logging statements in the application utilized the Log4J API to log debugging statements or issues, etc at different logging levels. The general configuration for enabling the logging statements was to put a Log4J configuration file on the server that applied to all the applications that were running on the server. This configuration file will set the logging statement format, logging levels per API, and potential Appenders to determine where to write the output (log files or standard out). It was not a simplistic process to enable different logging levels for an API per application because of the implementation of the logging framework.

With the advent of Logback and a change in the design to how logging was being configured, this was simplified through the following process. Logback is being used in conjunction with SLF4J, SLF4J providing the logging facade and Logback being the logging provider to that facade. This is simply done by including Logback configurations and jars within the application.

In this specific architecture, there are many service endpoints running in their own web application resource and therefore would benefit from an ability to have their own specific logging. This would enable logging levels to be set low or higher for a specific service based on runtime issues or debugging needs. The question with regards to this is if there is a configuration file per web application, then how would we tie the configuration file to the specific web application that is supposed to use it. In this case, we can take advantage of a feature in Logback called File Inclusion. This will allow us to separate parts of the logging configuration and include that separate fragment into the main logging configuration.

Now that we are aware that we can split the configuration into smaller files, we need to determine what requirements we have and what types of files that will produce. One of the initial requirements is the ability to dynamically change the logging levels without redeploying the war (and at this point we are not considering the ability to change the logging framework levels via JMX and the Application Server console). The requirement to dynamically change the logging levels will drive a second requirement, which is the configuration files will need to be placed on the server so that they can be modified outside of the WAR file. The third requirement is driven around the need to tie the configuration on the server to the specific WAR file that will be using it and this can be accomplished by placing a configuration file within the WAR file.

As we look through this general description, the architecture for the logging configuration will require two logging configuration files (one on the server and one within the WAR file). The logging configuration on the server only has the requirement for changing logging levels so we can just put the logger (API) configurations within this file. Since the location of the logging statements and output format won’t need to change dynamically, this configuration will go into the logging file within the WAR.

So our first configuration file will be the file that exists on the server. This will utilize the included element in order to identify that this configuration file is a fragment of a larger configuration. This also provides an appender, but it is the appender for the stdout so that it can be customized for debugging purposes.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
<included>
 
  <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
     <encoder>
    <pattern>%d THREAD:[%thread] %level ID:[%X] %logger - %m%n</pattern>
     </encoder>
  </appender>
 
  <logger name="org.apache.cxf" level="info" additivity="false">
    <appender-ref ref="SampleWebApplication" />
  </logger>
 
  <logger name="org.apache" level="warn" additivity="false">
    <appender-ref ref="SampleWebApplication" />
  </logger>
   
  <logger name="org.hibernate.ejb" level="warn" additivity="false">
    <appender-ref ref="SampleWebApplication" />
  </logger>
 
  <logger name="org.hibernate" level="warn" additivity="false">
    <appender-ref ref="SampleWebApplication" />
  </logger>
 
  <logger name="org.hibernate.sql" level="warn" additivity="false">
    <appender-ref ref="SampleWebApplication" />
  </logger>
 
  <logger name="org.hibernate.type.descriptor.sql.BasicBinder" level="warn" additivity="false">
    <appender-ref ref="SampleWebApplication" />
  </logger>
 
  <logger name="org.quartz" level="warn" additivity="false">
    <appender-ref ref="SampleWebApplication" />
  </logger>
 
  <logger name="org.springframework" level="warn" additivity="false">
    <appender-ref ref="SampleWebApplication" />
  </logger>

  <logger name="org.springframework.transaction" level="warn" additivity="false">
    <appender-ref ref="SampleWebApplication" />
  </logger>
 
  <logger name="com.foo.frmwk.service.interceptor.PolicyPointcutInterceptor" level="info" additivity="false">
    <appender-ref ref="SampleWebApplication" />
  </logger>
 
  <logger name="PerformanceLogger" level="debug" additivity="false">
    <appender-ref ref="SampleWebApplicationPerformance"/>
  </logger>
 
  <logger name="com.foo.service" level="warn" additivity="false">
    <appender-ref ref="SampleWebApplication" />
  </logger>
 
  <logger name="com.foo.frmwk" level="warn" additivity="false">
    <appender-ref ref="SampleWebApplication" />
  </logger>
 
  <logger name="com.foo.frmwk.dao.interceptor" level="warn" additivity="false">
    <appender-ref ref="SampleWebApplication" />
  </logger>

  <root level="warn">
    <appender-ref ref="stdout" />
    <appender-ref ref="SampleWebApplication"/>
  </root>
</included>

This next file is the main logback.xml configuration which exists within the WAR file that is deployed on the server. This configuration file an include for including the previous file that lives on the physical server. It is able to resolve the file because the directory where all the appender logback.xml configurations live on the server is put into the classpath of the application servers start scripts. The other item to mention is the scanPeriod, which sets how often the configuration checks for changes. This allows the logback.xml file on the server to be changed and the WAR’s Logback instance to pickup these changes and reflect them within the log file output. This allows us to add additional loggers as well as changing log levels on the fly.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
<configuration scan="true" scanPeriod="30 seconds">

  <appender name="SampleWebApplication" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>./logs/services/SampleWebApplication.log</file>
    <append>true</append>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <!-- daily rollover -->
      <fileNamePattern>./logs/services/archive/SampleWebApplication%d{yyyy-MM-dd}.log</fileNamePattern>
     
      <!-- keep 30 days worth of history -->
      <maxHistory>10</maxHistory>
    </rollingPolicy>
    <encoder>
      <pattern>%d [%thread] %level %logger - %m%n</pattern>
    </encoder>
  </appender>

  <appender name="SampleWebApplicationPerformance" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>./logs/services/SampleWebApplicationPerformance.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <!-- daily rollover -->
      <fileNamePattern>./logs/services/archive/SampleWebApplicationPerformance%d{yyyy-MM-dd}.log</fileNamePattern>
     
      <!-- keep 30 days worth of history -->
      <maxHistory>10</maxHistory>
    </rollingPolicy>
    <encoder>
      <pattern>%d [%thread] %level %logger - %m%n</pattern>
    </encoder>
  </appender>

  <include resource="SampleWebApplication-logback.xml"/>
 
</configuration>

Share and Enjoy

Evolution of Logging – Log4J to SLF4J to Logback

Logging has always been a very important part of development. One of the current trends is to utilize a framework called SLF4J which takes the place of what commons logging intended to do. SLF4J can be used directly for logging or it can be the wrapper that allows other implementations to be plugged in under the covers. This would allow developers to code logging logic against the SLF4J API and add log4j.jar or logback.jar into the classpath and it would use these logging implementations for generating the logging statements. The following is an example of the simplistic changes that have to be made in order to use SLF4J:

1
2
3
4
 import org.slf4j.Logger; import org.slf4j.LoggerFactory;
</p>
<p>
    private static Logger logger = LoggerFactory.getLogger(Entity.class);

As far as the implementation is concerned, Log4J has been used for quite a while but it’s codebase is stagnant if not dead. In the last 5 years, there has only been a maintenance update. Another new framework has emerged that has been created by the creator of Log4J and it is called Logback. Logback makes many improvements over Log4J and it also simplifies much of the configuration. One of the more powerful features that I will not be taking advantage of is coding the configuration files using Groovy and having the ability to build conditional logging files based on environments or hosts.

Logback also adds additional capabilities to add simplicity and performance to the normal String concatenation that occurs through logging, such as:

1
 logger.info("{} has logged in", userID);

Instead of writing this as:

1
 logger.info(userId + " has logged in");

One of the other nice features is that when an exception is thrown, logback will attempt to identify in the log which jar file contains the class mentioned in that line of the stacktrace. This provides benefits for troubleshooting runtime issues.

Many frameworks or third party applications use other logging frameworks such as commons logging or Log4J. SLF4J provides jar files which are bridges for routing logging requests to from these frameworks onto the SLF4J framework. With the inclusion of the two logback-classic.jar and logback-core.jar, logback becomes that implementation. I will be using logback as the underlining implementation moving forward, as well as providing jcl-over-slf4j.jar and log4j-over-slf4j.jar to bridge the requests through SLF4J.

Another important part of the framework to understand is how logback loads its configuration files. There are two different types of files that can be provided, a logback.xml and a logback-test.xml. So in a maven project, I can supply both of these configurations (one to be used during production and one to use during unit testing.

The following is a code snippet that explains how logback searches for configuration files:

http://logback.qos.ch/manual/configuration.html

Logback can be configured either programmatically or with a configuration script expressed in XML or Groovy format. By the way, existing log4j users can convert their log4j.properties files to logback.xml using our PropertiesTranslator web-application.

Let us begin by discussing the initialization steps that logback follows to try to configure itself:

  1. Logback tries to find a file called logback.groovy in the classpath.
  2. If no such file is found, logback tries to find a file called logback-test.xml in the classpath.
  3. If no such file is found, it checks for the file logback.xml in the classpath..
  4. If neither file is found, logback configures itself automatically using the BasicConfigurator which will cause logging output to be directed to the console.

The fourth and last step is meant to provide a default (but very basic) logging functionality in the absence of a configuration file.

If you would like to read more, I have included resource links.

RESOURCES

http://logback.qos.ch/manual/

http://www.infoq.com/news/2007/08/logback

http://blog.kares.org/2009/10/log4j-logging-without-log4j.html

Share and Enjoy