Before we begin I must admit to something. There has been many times I have increased the log level on a service only to get nasty messages from server monitors mentioning that I am about to hit the limit of the log partition. Now I have got that off my chest, let's continue from the development side, rather than the administration side, of logging.
The Logging Challenge
In theory, logging should be easy. Choose your framework and call the log handles, right? However, somewhere along the lines things got a bit murky. Just as there are many tools that do similar things in similar or different ways, there are many logging frameworks out there for each language, platform, operating system and so on.I will only say that if you are developing a plugin for a platform, use the logging framework for that platform. Often the logging framework ties into the platform in some way as to provide central logging or information to the user. An example of this would be to use the Eclipse logging framework when creating an Eclipse plugin.
Also, be sure that you have configured your server such that logs are put on their own partition or sent to SYSLOG. If your logging runs away and fills up your partition, you do not want it preventing other critical applications from being able to write to files. I have seen this take down servers many times. Also, be sure to use UDP rather than TCP for ALL SYSLOG messages (this goes against some recommendations but I will not accept any other argument). This is in case the SYSLOG destination is unable to process your request in a timely fashion. I have seen this take down services and servers. You want your processes to keep operating even if logging breaks.
SLF4J
Simple Logging Facade for Java (SLF4J) is a simple logging facade for Java. I am stating the obvious as it is very important. SLF4J is a facade in the sense that it does not contain any true logging implementation. It defines an API and a method of binding to an implementation. This leaves us free to implement our module, library or application without forcing the users into using a particular logging implementation.As an example, if we used log4j in a module, the users of our module would have to use log4j, or at the very least they would have to use a log4j to some other framework converter.
But wait, doesn't Java already have logging covered? Yes it does, in the form of java.util.logging and it is good. The problem is that it is not always what people want to use. As in the Eclipse example, if a module logs to java.util.logging it may completely bypass the intended framework. Fortunately, there is a solution. We will pass java.util.logging to slf4j in the example below.
The Gory Details
We will be using logback for the logging framework and slf4j for the facade. You will notice that the code never mentions logback. Typically it is only when the application is being deployed or in the parent project that the logging framework is included. This makes it easy to change. As we are only working on a sample project, we cannot do this. However, please note that you can very easily modify the POM to contain whatever logging framework you like with a connector to slf4j.Before we look at adding logging, let's look at what other indirect dependencies we have added via our direct dependencies. Maven can help. Open the pom.xml file and select the Dependency Hierarchy tab. In the Resolved Dependencies pane we can see that commons-logging 1.1.1 has come along for the ride. If we select the package we can see our direct dependencies that have included the package. This is shown in the screenshot below.
This is the Apache logging framework. It is quite good but not what we want. Fortunately, we can tell maven to exclude that from the build, however, as our dependencies still requires the API to exist we must substitute it with something else. We will see what to substitute it with later, for now we will exclude it.
Right-Click the commons-logging : 1.1.1 item from the Resolved Dependencies pane and select Exclude Maven Artifact and click OK. That action will add the text in bold to our POM.
<dependency>
<groupId>org.apache.myfaces.core</groupId>
<artifactId>myfaces-impl</artifactId>
<version>2.2.7</version>
<exclusions>
<exclusion>
<artifactId>commons-logging</artifactId>
<groupId>commons-logging</groupId>
</exclusion>
</exclusions>
</dependency>
Happy days! Now we can start adding our own logging framework via the slf4j facade. In order to replace the Apache Commons Logging component we need something that looks like Apache Commons Logging, tastes like Apache Commons Logging and follows the same API as Apache Commons Logging but ultimately directs logging to the slf4j facade.
For this we can use jcl-over-slf4j. The JCL (Jakarta Commons Logging aka Apache Commons Logging) has the same API functions as Apache Commons Logging but backs onto the slf4j facade. We will also add the logback components while we are at it.
<dependency>
<groupid>org.slf4j</groupid>
<artifactid>slf4j-api</artifactid>
<version>1.7.6</version>
</dependency>
<dependency>
<groupid>org.slf4j</groupid>
<artifactid>jcl-over-slf4j</artifactid>
<version>1.7.6</version>
</dependency>
<dependency>
<groupid>ch.qos.logback</groupid>
<artifactid>logback-classic</artifactid>
<version>1.1.2</version>
</dependency>
<dependency>
<groupid>ch.qos.logback</groupid>
<artifactid>logback-core</artifactid>
<version>1.1.2</version>
</dependency>
Now we have to tell logback how we want it to log. To do this we create a file called logback.xml. This is the default file that logback will use for configuration. No code is required.
- Right-Click the src/main/java item.
- Select New > File
- Name the file logback.xml
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator"/>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{35} - %msg%n%ex{15}</pattern>
</encoder>
</appender>
<logger name="net.sf.pbu.ontrack" level="DEBUG" additivity="false">
<appender-ref ref="STDOUT" />
</logger>
<root level="ERROR">
<appender-ref ref="STDOUT" />
</root>
</configuration>
The XML above tells logback to set the default (or root) logging level to ERROR. That way only important items will come to our attention from most packages. A appender is also defined so we can define the format of the log. A second logger is added with a level of DEBUG. This will only log the packages we are creating for this project as we have specified the package net.sf.pbu.ontrack and by default all sub-packages. Powerful stuff.
The pattern can be broken down as follows:
- %d{yyyy-MM-dd HH:mm:ss.SSS}: Prints the full date in international format.
- %thread: Prints the thread id.
- %-5level: Prints the severity justified to the left using padding to make 5 characters.
- %logger{35}: Prints the log handle. This is typically the class name. It the fully qualified class name is greater than 35, it is abbreviated.
- %msg: The message.
- %n: A newline character.
- %ex{15}: Print the exception stack trace only keeping 15 lines of the call stack.
The context listener is used to adjust the logging level of java.util.logging handles to the value configured by logback. This greatly decreases the performance impact of combining java.util.logging with logback.
As we are using the same output for the root log as we are for our package log, one log entry from our package would appear twice. Once from the root logger and once from the non-root logger. This can look rather strange. To avoid this we have set the additivity flag to false. BE CAREFUL. If we wanted to log once to a file and once to standard output, we would have to remove the additivity flag (defaults to true) so we would get a log entry in both outputs.
Once this is done your directory structure should look as follows.
Run the application and we can still see some red text appearing in the console output. This is coming from java.util.logging as found in some of the jetty classes (I went to source code to find this, press F3 while the carrot is over an external class to view information and download the source if it is available). As a general rule, it is a good idea to guide java.util.logging to some other framework if you are not using it. Lets do just that. We will add one more dependency to allow this. Please note, we cannot exclude the java.util.logging using Maven as it is a built-in java library. Instead we will be using using an slf4j to java.util.logging bridge to guide logging to slf4j. This is a slightly different approach to the commons-logging and requires slf4j code.
Update the pom.xml file to include the java.util.logging to slf4j bridge (jul-to-slf4j).
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-api</artifactId>
<version>1.7.6</version>
</dependency>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>jcl-over-slf4j</artifactId>
<version>1.7.6</version>
</dependency>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>jul-to-slf4j</artifactId>
<version>1.7.6</version>
</dependency>
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-classic</artifactId>
<version>1.1.2</version>
</dependency>
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-core</artifactId>
<version>1.1.2</version>
</dependency>
Now we must tell java to guide the traffic over slf4j. We will do this at the very start of the application to ensure no logs are missed. Start-up logs are very important. Edit the Main.java file to include this. We will also add some logging of our own.
package net.sf.pbu.ontrack.main;
import org.eclipse.jetty.server.Server;
import org.eclipse.jetty.webapp.WebAppContext;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.bridge.SLF4JBridgeHandler;
public class Main {
private static final int PORT = 8080;
public static void main(String[] args) throws Exception {
SLF4JBridgeHandler.removeHandlersForRootLogger();
SLF4JBridgeHandler.install();
Logger logger = LoggerFactory.getLogger(Main.class);
WebAppContext webAppContext = new WebAppContext();
webAppContext.setContextPath("/");
webAppContext.setResourceBase("src/main/webapp/");
webAppContext.setDescriptor("src/main/webapp/WEB-INF/web.xml");
Server server = new Server(PORT);
server.setHandler(webAppContext);
logger.info("Starting server on port: " + PORT);
server.start();
logger.info("Server started. Waiting for the server to finish.");
server.join();
}
}
The first line removes the default java.util.logging handler. We want to define our own. The second line installs the slf4j handler in its place. Now we can re-run our application and see the blissful peace of our logging. Also remember, if something bad happens outside our package, we will still know it.
Other Features
Logback contains a rich set of features such as log rollover and many appeander types. Have a look at Maven or the documentation. The slf4j documentation is also worth a read. It is short but sweet.One of the key features of a logging framework that you should implement in production is log rotation. For completeness, in production we could use the following configuration. It will log errors in external packages and information in our delivered product. We have removed the additivity="false" attribute as we now require both log appenders to record the logs as they are pointing to different outputs.
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<contextListener class="ch.qos.logback.classic.jul.LevelChangePropagator"/>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{35} - %msg%n%ex{15}</pattern>
</encoder>
</appender>
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>ontrack.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>ontrack.%d{yyyy-MM-dd}.log</fileNamePattern>
<maxHistory>30</maxHistory>
<timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
<maxFileSize>5MB</maxFileSize>
</timeBasedFileNamingAndTriggeringPolicy>
</rollingPolicy>
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{35} - %msg%n%ex{15}</pattern>
</encoder>
</appender>
<logger name="net.sf.pbu.ontrack" level="INFO">
<appender-ref ref="STDOUT" />
</logger>
<root level="ERROR">
<appender-ref ref="FILE" />
</root>
</configuration>
No comments:
Post a Comment