It’s probably not necessary to start this article with a mini-lecture on why logging, like unit-testing, is a Good Thing, so all I will say is logging is important not only during development but also invaluable in diagnosing runtime problems, once a solution is delivered and running. From here on I’m going to assume you’re convinced.
So, you know you should be logging, but how? And which of the many logging frameworks should you use? This article sets out to answer the first question, showing you how to get started logging in Java, using the NetBeans IDE, and offers an opinion on the answer to the second question.
There are several well-established ways to do logging in Java but the best approach I have come across so far is to use slf4j (the Simple Logging Facade for Java) for all logging statements in source code. The slf4j facade interfaces are completely independent of any specific logging implementation. The binding between the slf4j facade interfaces and a concrete logger implementation is done statically when the application jar is compiled: there is no runtime trickery involved (e.g. using class-loaders).
This approach allows you to replace one logging implementation with another without altering any of your logging code, just by binding to a different concrete logger (i.e. referencing a different logger implementation jar).
Splitting the logging job into two in this way means you need two references in your Java project, in order to use slf4j:
- a reference to the slf4j API itself, which provides the interfaces you will use exclusively in your logging code.
- a reference to a concrete logging implementation, which your logging code will call via the slf4j facade.
As the slf4j interfaces must be bound to a concrete logger implementation, you need to choose which logger to use. I have chosen Logback, which appears to be an improved version of log4j, one of the more efficient Java logging solutions.
This article describes what you need to do to start logging using this combination. I’m going to assume that you understand the value of logging, and know a little about log statements and logging levels: these are common to all modern logging frameworks, so I won’t cover them in detail.
Logger Libraries
Download slf4j and logback. Extract the distribution archives to wherever you keep your libraries. Then, in NetBeans, create libraries (via Tools/Libraries) for both distributions.
- For slf4j, include the slf4j-api.jar. The precise name of the jar file will depend on the version you download: mine is slf4j-api-1.5.0.jar
- For logback, you need logback-core.jar and logback-classic.jar. Again, precise file name depends on version e.g. logback-core-0.9.9.jar
You could create a combined library as a convenience for simple projects, if you know that you will frequently want to use the same concrete logger with the facade. However, bear in mind that for projects which build libraries or components used in other projects, you should only reference the slf4j library: the logger implementation binding should be done by the application which uses your component.
The source code for this tutorial assumes two NetBeans libraries, one for slf4j and the other for logback.
Adding Logging To Your Code
In your NetBeans application project, add references to the slf4j and logback libraries. To start logging from your code, you need to do the following things:
- Initialise a logger reference in every class you wish to log from.
- Add Import statements for the required slf4j types
- Add logging statements to your code.
Refer to the source code with this article. Look first at the Main class: the first declaration in the class is for the logger:
private static final Logger _log = LoggerFactory.getLogger(Main.class);
Notice that this logger is declared static: this is because Main houses the static main() application method, so the logger must be static for it to be referenced from the main method. Above, in the imports section, you will see the two imports necessary to use slf4j:
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
Now open the slf4j-sample-lib project, a trivial sample library which the main application references. Look at the StringReverser class, and notice that the logger is declared slightly differently:
private final Logger _log = LoggerFactory.getLogger(this.getClass().getName());
This is a non-static declaration: only non-static methods will have access to this logger. If you look carefully at the declaration, you’ll spot that this one is portable: it doesn’t contain the class name explicitly. This declaration can therefore be pasted without modification into any class, but remember that this is non-static, so will not be usable from any static methods in the class.
As the static logger is usable from everywhere (non-static and static contexts), wouldn’t it be convenient to have that declaration added automatically in every new class you create? Perfectly possible, in NetBeans. To include the logger declaration in your NetBeans source code template, go to Tools / Templates, open the Java branch and select Java class and click Open in Editor. You’ll see the Java class template source, complete with template parameters for the class name and some other stuff I’ll ignore here. All we need to do is add a single line to the class skeleton:
public class ${name}
{
private static final Logger _log = LoggerFactory.getLogger(${name}.class);
}
If you save the changes to your template and create a new class in NetBeans, you’ll see the logger declaration with the correct class name parameter value has been added to the source. You could even add the necessary import statements to the template.
But the overhead of including the logger declaration is low (just one simple line), and NetBeans will take care of the imports for you (use Fix Imports with Ctrl-Shift-I), so you may decide it’s not worth adding these lines to your templates.
Static versus Non-static Loggers
There’s one more difference between static and non-static loggers which you should at least be aware of. If you declare the logger static, there will be exactly one instance of the logger retrieved for the class, shared across all instances. As the logger reference is shared, memory is allocated just once and the logger is initialised just once, rather than once per object. This is not usually a problem, but you should be aware that the same logger reference will be shared across every instance of the class.
When declared non-static, every instance of your class will incur the memory and initialisation cost for the logger reference variable. For the vast majority of classes this will not be a significant overhead, but again you should be aware of the tradeoff. Note that within the same application, retrieving a logger by a given name will always return the same logger object: using a non-static logger reference does not mean that every instance of a class gets a new logger object of its own.
For a complete account of this issue, you should consult the slf4j documentation which covers this. Read this section of the online documentation.
Logging Statements
As I said in the introduction, I’m assuming you are somewhat familiar with logging. If not, go back and read the material on the slf4 and logback sites, and follow-up the references there.
Use the logger method appropriate to the level you wish to log at, for example:
_log.info(“‘{}’ reversed is ‘{}’”, instance.getValue(), instance.reverseValue());
Possibly the most important piece of advise I can give here is to consider the cost of logging carefully, especially debug-level logging. The actual call to the logger object is not usually the dominant cost in debug logging: you are likely to be constructing moderately large strings to output, and the cost of preparing these may be where you incur the biggest cost. Consider a line such as this:
_log.debug(“Debugging string: “ + ExpensiveGetter());
The runtime cost of constructing the string argument to this logging statement will always be incurred, whether the log-level is set to debug or to some other (less-detailed) level. Clearly that’s an undesirable, and fortunately there is a very simple coding idiom we can use to avoid this cost:
if (_log.isDebugEnabled())
{
_log.debug(“Debugging string: “ + ExpensiveGetter());
}
Simply guard the debug log statements with a test for the current (runtime) level of the logger. This does add a little source code; it is possible to reduce simple statements like the one above to a one-liner but I generally avoid this, valuing clarity over concision.
The cost of the debug statement will now be reduced to a simple boolean test, which is much more acceptable.
Configuring Logback
If you build and run the sample project accompanying this piece, you’ll see the log statements are written to the console. This is the default behaviour for most logging solutions, logback included. In most production situations you will probably want to direct your log messages somewhere else, to a file for example.
In common with other logger implementations (such as log4j) the logback subsystem can be controlled through an XML configuration file. For a complete treatment of the options and syntax, you’ll need to refer to the logback documentation and in this article I’ll give a superficial account of a simple but usable configuration.
Here is the configuration file:
<?xml version=”1.0″ encoding=”UTF-8″?>
<!–
Document : logback.xml
Created on : 25 February 2008, 22:40
Author : Roger
Description:
Configuration for logback logging framework.
For this file to be read by logback at runtime, it must be placed
on the classpath.
–>
<configuration>
<appender class=”ch.qos.logback.core.rolling.RollingFileAppender” name=”RootFileAppender”>
<file>application-log.txt</file>
<append>true</append>
<filter class=”ch.qos.logback.classic.filter.ThresholdFilter”>
<level>debug</level>
</filter>
<rollingPolicy class=”ch.qos.logback.core.rolling.FixedWindowRollingPolicy”>
<fileNamePattern>application-log.%i</fileNamePattern>
<maxIndex>2</maxIndex>
</rollingPolicy>
<triggeringPolicy class=”ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy”>
<maxFileSize>100000</maxFileSize>
</triggeringPolicy>
<layout class=”ch.qos.logback.classic.PatternLayout”>
<pattern>%d{yyyy-MM-dd HH:mm:ss},%p,%c,%F,%L,%C{1},%M %m%n</pattern>
</layout>
</appender>
<root>
<level value=”debug”/>
<appender-ref ref=”RootFileAppender”/>
</root>
</configuration>
Although this is quite a simple configuration file, there’s a lot of information in there and to understand it all fully you will need to study the logback documentation. I’ll skim over the most important bits here and leave the rest to you.
Appenders are the part of the logging engine which actually write the log messages somewhere. You can choose from many different appenders – my favourite is the RollingFileAppender which writes to a text file and ‘rolls-over’ to a new file once the existing file passes a certain size, declared in the triggeringPolicy element. The file element declares the filename, and the rollingPolicy/fileNamePattern declares the filename pattern to use for old log files, as the file rolls-over.
Layouts define the format of the messages written to the log appender. I’ve gone with a standard pattern which appears in the logback documentation: please consult the logback documentation on format strings to discover all the options here. Essentially, every log statement will include the date and time, and the origin of the log message, including the line number.
So the net effect of this configuration is that logback will write all log activity out to the file application-log.txt in the working directory, rolling the file when it reaches the size limit I have set (roughly 100k).
Logback and the Classpath
As explained in the logback documentation, if you want to configure logback with an XML file then the file must be present on the classpath of the application, otherwise logback will not find it and will fall-back to console logging.
If you examine the source code accompanying this piece you’ll see that I have placed the logback.xml file in the root of the source folder (src). In the NetBeans project, this is the ‘default package’: the name of anything placed here will have no namespace prefix. When NetBeans builds a Java application, it will compile any Java sources it finds in src and all its subdirectories, and will also by default include everything it finds in the root folder in the jar file. To prove this to yourself, go into the src folder, create an arbitrary file, say ‘fred.txt’, and rebuild the project. Now open the NetBeans Files view (Ctrl-2 will open this if it’s not already visible), locate the ‘dist’ folder and open the tree until you locate the slf4j-sample.jar file. The NetBeans file view allows you to browse the jar file contents – just open the tree to the next level:
And there are the two files, logback.xml and fred.txt, packed into the root of the jar. We don’t need fred, so delete the file and rebuild the jar.
So the source hierarchy in NetBeans contributes to the runtime classpath, and the ‘dist’ folder is where NetBeans writes out all artifacts resulting from a build. As the NetBeans documentation (and the generated readme) tells you, you can distribute your application by zipping-up and publishing the contents of the dist folder.
Let’s run the application. Open a terminal window in the dist folder and type:
java -jar slf4j-sample.jar
The program should run, but nothing should be written out to the console. Instead, an application-log.txt file should appear in the dist directory. Open that file and you will see the result of the logging statements. Logback has obviously located the configuration file and applied the settings.
If you’re thinking ‘job done’ at this point, not so fast! Just consider how logback has located and loaded the XML file. The logback XML file is packed into the (executable) jar file which is the main artifact generated by the build. When the Java runtime runs this jar it first examines the jar’s manifest (the MANIFEST.MF file in the META-INF folder inside the jar), which looks like this (from the sample application jar):
Manifest-Version: 1.0
Ant-Version: Apache Ant 1.7.1
Created-By: 11.0-b15 (Sun Microsystems Inc.)
Main-Class: slf4jsample.Main
Class-Path: lib/logback-classic-0.9.9.jar lib/logback-core-0.9.9.jar l
ib/slf4j-api-1.5.0.jar lib/slf4j-sample-lib.jar
X-COMMENT: Main-Class will be added automatically by build
The runtime looks for the entry point of the program (the qualified name of the class containing the main method) and initialises the classpath from the Class-Path setting. Implicitly, ‘.’ (the root of the jar structure) is also on the runtime classpath.
What this means is that when the logback system goes looking for logback.xml it will find the copy in the jar file. Consider the function of the logback.xml file: the users of the application will almost certainly want to configure the log behaviour themselves rather than accept the settings you have baked-in to the copy of logback.xml inside the jar file.
So, we want to distribute our default logback.xml file but not have it baked-in to the jar file: what to do? Having it in the source classpath is convenient because it appears in the NetBeans project view so we can view and edit it from inside the IDE. However, we don’t want it packed into the jar, but we do want it on the runtime classpath. How can we satisfy all of these constraints?
We can achieve this with two simple steps:
- To prevent NetBeans including the XML file from the jar file, we exclude logback.xml from the list of source artifacts that NetBeans considers as jar contents.
- Add a step to the build process which copies logback.xml into the dist folder, placing it next to the jar file.
For step (1), open the NetBeans project properties dialog and navigate to the Packaging subsection, below Build. Add “logback.xml” to the list of Excluded files:
If you rebuild the application, then use a zip tool or archive manager to open the resulting jar file, you’ll see that the logback.xml file is no longer included. There is more help on excluding content from your jar in this page of the NetBeans documentation.
For step (2) we need to arrange for the logback.xml file to be copied into the dist folder during the build process. To do this, we will add a very simple custom build-step to the NetBeans build process. As you probably know, NetBeans uses Apache Ant as the build engine, and the IDE generates the Ant script automatically. I’m not going to go into much detail concerning what you can do with custom build steps – I suggest you read the well-commented Ant scripts, and look at this section of the NetBeans documentation.
There are standard stages in the build process where we can add tasks (‘targets’ in Ant-speak) to the NetBeans build. The build.xml file (in the project root) contains a comment describing these. All we want NetBeans to do is copy the logback.xml file into the dist folder after it has finished building the jar file, so we will add a -post-jar target to copy the file:
<target name=”-post-jar” >
<copy file=”${src.dir}/logback.xml” todir=”${dist.dir}”/>
</target>
Add this target at the end of build.xml, just before the close-tag for
. Now rebuild the project, and take a look in the dist directory: you should see that logback.xml has been copied there. Now you’re ready to zip the dist folder and distribute your solution.
That’s the end of this little piece. You should know enough now to add straightforward, high-performance logging to your own projects. But there’s a lot more to learn: to go further, study the slf4j and logback documentation, follow the examples, and experiment.
