Logging
Goal
- Learn about the various available Java logging frameworks and their histories.
- Understand how logging frameworks work in Java.
- Know how to integrate SLF4J and Logback into a program.
- Discover and use the Clogr library.
Concepts
- adapter pattern
- Apache Commons Logging (JCL)
- appender (Logback)
- binding (SLF4J)
- bridge pattern
- concern
- Concern Separation Aspect Registrar (Csar; /zɑːr/)
- cross-cutting concern
- Csar Logging Registrion (Clogr)
- facade pattern
java.util.logging
(JUL)- layout (Logback)
- log
- log level
- Log4j
- Logback
- logger
- logging bridge
- logging framework
- rolling policy
- root logger
- Simple Logging Facade for Java (SLF4J)
- stack trace
- triggering policy
Library
ch.qos.logback.classic.Level
ch.qos.logback.classic.Logger
ch.qos.logback.classic.encoder.PatternLayoutEncoder
ch.qos.logback.core.ConsoleAppender
ch.qos.logback.core.FileAppender
ch.qos.logback.core.rolling.FixedWindowRollingPolicy
ch.qos.logback.core.rolling.RollingFileAppender<E>
ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy<E>
io.clogr.Clogged
io.clogr.Clogged.getLogger()
io.clogr.LoggingConcern
io.clogr.LoggingConcern.setLogLevel(org.slf4j.event.Level level)
io.clogr.logback.LogbackLoggingConcern
io.clogr.logback.LogbackLoggingConcern.configure(InputStream inputStream)
java.util.logging
org.slf4j.Logger
org.slf4j.Logger.info(String msg)
org.slf4j.LoggerFactory
org.slf4j.bridge.SLF4JBridgeHandler
Dependencies
Lesson
The purpose of a computer program is to process some input data and provide some resulting output data. But the result output data may not be the only useful data a program produces. It's common to want to have a persistent record of what actions a program performed. A log of actions is useful for everything from auditing (e.g. finding out who deleted the secret recipe from the database), to debugging (e.g. investigating why a list of animals leaves out all the birds), to simply helping a new developer understand the flow of the program logic.
You've been adding logging
capability to some extent in your programs already. Likely you have by started adding a multitude of lines all over your program that look like the following:
Using System.out.println(…)
for debugging has quite a few drawbacks:
- Selectivity: How do you turn them off—or at least some of them?
- Location: They get printed on the user's console; what if we want to store them in a file?
- Severity: How do we tell the debugging messages from normal status information?
These are the reasons why logging frameworks were invented. These are libraries that allow you to use a consistent interface throughout your program to indicate logging information. These frameworks are flexible and allow configurations that address the needs listed above.
Evolution of Logging in Java
Logging frameworks in Java have had an interesting history. Because various libraries have to interact, it would be best if they all used the same framework. In recent years this is becoming possible, but it wasn't always so easy. There moreover remain several gotchas.
System.out.println(…)
Writing to the console used to be the only way to easily log information. There are now many true logging options, but unfortunately many developers still use this approach for quick-and-dirty logging even though they know better.
Log4j
The first real logging framework for Java was Log4j, an open-source project written by Ceki Gülcü and which is now part of the Apache Software Foundation. The first version, log4j 1, introduced ideas such as loggers
and log levels
, which you'll learn about later in the lesson. The latest upgrade to the series is currently Log4j 2.
JUL
Sun, the company that invented and was controlling Java at the time, recognized the need for a logging framework and decided to add an official one as part of the the JDK in the java.util.logging
package. Referred to simply as java.util.logging
(JUL), the JDK's logging infrastructure was similar to Log4j but incompatible with it.
SLF4J
By this point some projects were using Log4j and others were using JUL. So the original author of Log4j decided to create another framework, the Simple Logging Facade for Java (SLF4J). Instead of another logging implementation, this library instead set forth a set of interfaces to simplify and standardize access to any logging implementation.
Using SLF4J a developer could program an application to the SLF4J interfaces and the application could work with either Log4j or JUL, depending on how the developer decided to configuration the application. To make this work, SLFJ provided an adapter library for Log4j and another for JUL, so that the one SLF4J interface could work with either.
Many developers have seen the benefit of working with a single logging interface, so many projects have recently switched from other logging frameworks to SLF4J.
Logback
The creator of Log4j decided to create one more logging framework: Logback. Ceki intended Logback to be the successor to Log4j, although the Apache Software Foundation would probably prefer that log4j 1.x users upgrade to Log4j 2. One benefit of Logback is that it is a direct implementation of the SLF4J interfaces; no adapter libraries are needed.
Apache Commons Logging
The Apache Software Foundation also released its own logging library named Apache Commons Logging. Because this library was once named Jakarta Commons Logging, it is often abbreviated JCL.
SLF4J
Log Level
All the logging frameworks have the idea of a log level. This is the importance or severity of the log messages. You can think of them simply as categories of messages that can be logged, but they do have a set order or priority. Here are the log levels recognized by SLF4J, in order from highest priority to the lowest:
Besides indicating the purpose of the message, the use of log levels allows the logging of different log levels to be turned on or off across the entire application by updating the application configuration.
Loggers
A org.slf4j.Logger
is the main logger interface through which you will write log messages. It provides equivalent logging methods corresponding to each of the log levels above. For example, all messages sent through one the Logger.info(String msg)
method will be logged with the INFO
log level.
The simplest way to log a message is just to pass a string to the log method you are using:
Many times you will want to format your string. SLF4J accepts a very simple message template format in which each occurrence of {}
is replaced with a following argument.
If you provide a Throwable
as an extra argument to the logging method,SLF4J will log a stack trace of the object—the complete contents of the stack (i.e. the identity of every method recursively calling another method) at the time the exception or error was thrown.
Logger Factories
Before you can use a logger, you have to get one from the org.slf4j.LoggerFactory
. At the fundamental level, loggers are given names, and groups of related loggers share the same name. This allows loggers to be turned on or off as a group. It also allows loggers to be arranged in a tree hierarchy, changing settings for entire branches of loggers. It is common practice to name the logger based upon the class doing the logging. Therefore SLF4J has provided a logger factory method that takes a Class
as a parameter; a logger name will be determined automatically.
Once you get the logger, you can use it within the acquired scope or store it in an instance variable of your class.
Logging Configuration
Dependencies
You'll notice that the Maven artifact ID for the main SLF4J library is slf4j-api
. This is because SLF4J is primarily a set of facade interfaces. To get them to work, you'll also need to include an actual logging implementation as a dependency.
Adapters
If you use Logback as your SLF4J implementation, then you have nothing further to do. But if you use another logging framework such as Log4J, you'll need to include a single SLF4J binding as a dependency as well. An SLF4J binding is no other than the adapter design pattern, converting an existing logging framework to work with the SLF4J API. For additional details, see SLF4J user manual.
Here are some of the most common SLF4J bindings:
- log4j 1
org.slf4j:slf4j-log4j12
- JUL
org.slf4j:slf4j-jdk14
- JCL
org.slf4j:slf4j-jcl
Bridges
If one of the libraries you are using has not been upgraded to use SLF4J, it may be written directly to the API of some other framework. You'll need to exclude the actual implementation in Maven, and then include one of SLF4J's logging bridges that route calls to the other framework back to SLF4J (and in turn on to the other underlying framework). The following diagram shows various bridges SLF4J provides designed for converting legacy APIs. For more in depth coverage, see Bridging legacy APIs.
Here are some of the most common SLF4J bridges:
- log4j 1
org.slf4j:log4j-over-slf4j
- JUL
org.slf4j:jul-to-slf4j
- JCL
org.slf4j:jcl-over-slf4j
For example suppose that one of your project's dependencies uses JUL, while another uses JCL. You prefer to use SLF4J as your logging API, coupled with Logback as the implementation, as recommended in this lesson. To prevent the libraries you use from logging information to a separate location, you essentially reroute their output to SLF4J by including the appropriate SLF4J bridge libraries in your POM, as shown in the figure.
Configuration Files
Many logging frameworks allow configuration through use of a configuration file apart from the main program code. Logback for example allows many configuration options typically placed inside a logback.xml
file, placed in the classpath. In a typical maven configuration, an appropriate location for the static configuration file would be src/main/resources/logback.xml
. If no configuration file is provided, Logback provides a default configuration equivalent to that in the following figure. See The logback manual, Chapter 3: Logback configuration for full details.
Setting Log Level
Most logging implementation default to a reasonable log level. As you saw from the configuration above, default simple logger in Logback defaults to DEBUG
, which means that DEBUG
information, general INFO
messages, and anything more severe will be logged; while TRACE
messages will be discarded.
Explicitly setting a log level depends on which logging implementation you are using. In Logback, you can set the log level as part of the configuration file (as shown in Configuration Files, above). You can exclude both DEBUG
and TRACE
messages, for example, by setting <root level="INFO">
in the configuration.
You may also set Logback's debug level programmatically, using the ch.qos.logback.classic.Level
class to indicate the log level. The following example shows how you would set Logback's log level to WARN
. It involves setting the log level of the top-level ch.qos.logback.classic.Logger
—the root logger in the tree of named loggers.
Layouts
The format of the resulting log output in Logback is governed by a layout. By default Logback uses a ch.qos.logback.classic.encoder.PatternLayoutEncoder
layout, which specifies the format of each line using a specified pattern. Most of the time you can simply provide a logback.xml
file containing your custom pattern, as shown below. See The logback manual, Chapter 6: Layouts for documentation on the different pattern options.
Appenders
Logback uses an appender to specify a destination of the logging output. The examples above use a ch.qos.logback.core.ConsoleAppender
to log information to the console using stdout. It is common for an application to also log information to a file, and this can be done using a ch.qos.logback.core.FileAppender
. The following example installs a file appender in addition to the appender to stdout.
File appenders can have a complex configuration. In order to keep a log file from growing too large, a rolling policy can specify how the current log file can be rolled over
into a series of historical log files which are eventually deleted. A triggering policy determines what will cause the log file to roll.
The figure below provides an extensive example of programmatic configuration to add a ch.qos.logback.core.rolling.RollingFileAppender<E>
to whatever configuration has already been set up (e.g. in a logback.xml
file), using a log file .foobar/foobar.log
in the user's home directory. The triggering policy ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy<E>
is configured roll the log file when it reaches 5MB. The rolling policy ch.qos.logback.core.rolling.FixedWindowRollingPolicy
is set up to store old log files using the filename format foobar.log.1.zip
, foobar.log.2.zip
, and foobar.log.3.zip
before finally deleting them. The extension .zip
indicating that Logback should automatically compress the rolled logs. Play close attention to setting the context and parent of the added configuration elements, as well as the need to start
each of the elements.
More extensive documentation on appender configurations can be found in The logback manual, Chapter 4: Appenders.
Clogr
SLF4J goes a long way towards providing a consistent API across logging frameworks, but there are still areas that can be improved such as setting the logging level, as discussed above. Notably most logging implementations by default assume that there will only be one logging configuration on the JVM. Those that allows different configurations often require a complicated setup on a web server. See Logging separation for a discussion for Logback.
The Csar Logging Registrion (Clogr) library, an open-source project by GlobalMentor, Inc., smooths some of the rough edges still present with logging in the Java language. Csar uses the existing SLF4J logger API while adding utilities and log configuration flexibility. The main dependency io.clogr:clogr
provides the primary access for retrieving loggers and compartmentalizing configurations. Other Clogr dependencies such as io.clogr:clogr-logback
provide additional support for individual logging frameworks.
Loggers via Clogr
The easiest way to acquire an SLF4J logger is to implement io.clogr.Clogged
for every class needing access to a logger. The implementing class may then call Clogged.getLogger()
to retrieve a Logger
instance for that class. In a default configuration this is effectively the same as calling LoggerFactory.getLogger(getClass())
in the implementing class. The power lies in Clogr's ability to switch to local, compartmentalized log configurations per specific threads if so configured, as explained below.
Setting the Clogr Log Level
You saw above that SLF4J provides no general API for setting the log level programmatically. Clogr rectifies this situation via the io.clogr.LoggingConcern
class, which represents the logging configuration for a particular context. The Clogr.getLoggingConcern()
method retrieves the appropriate logging concern. If you have included the appropriate Clogr dependency for your logging framework (such as io.clogr:clogr-logback
), LoggingConcern.setLogLevel(org.slf4j.event.Level level)
will set the log level for the root logger of the logging implementation you are using.
Compartmentalized Configurations
Using the Concern Separation Aspect Registrar (Csar; pronounced /zɑːr/), Clogr has the ability to have multiple logging configurations existing at the same time on the same JVM for any application. The Clogged.getLogger()
method discussed above will via Csar determine the correct LoggingConcern
in effect for that context. Csar even allows the same code to run in the presence of different logging contexts. The following example, which depends on io.clogr:clogr-logback
, uses the default Logback implementation as configured above. One section of code, however, uses a specially configured LogbackLoggingConcern
. The configuration is loaded from a packaged resource named other-config.xml
using LogbackLoggingConcern.configure(InputStream inputStream)
.
Review
Summary
- Don't use
System.out.println(…)
for logging purposes. - Use SLF4J for your logging API.
- Use Logback for your SLF4J implementation.
- Use Clogr to make SLF4J access easier and more flexible.
Gotchas
- If you perform manual formatting in your log message strings, this could negatively affect application performance, as you may be formatting messages for low-priority messages that never wind up getting logged.
- Don't install an SLF4J bridge for the logging framework you are using as your main SLF4J implementation.
- If you log an error at different levels in the call stack, such as location where the error occurred and later where the error was displayed, you will wind up with multiple messages in the log output, which may mislead you into thinking that more than one error occurred.
- Saving static references to loggers can prevent context-based logging configurations from functioning correctly. Avoid static loggers, especially in libraries.
In the Real World
- Most projects are migrating to SLF4J. You should do the same.
- Try to log each error at one place, preferably high in the hierarchy so as to provide more information about the semantics and context of what went wrong.
Think About It
- If a
System.out.println(…)
remains in your code, ask yourself whether it is part of the application's primary purpose to communicate information with the user via the console at this point; if not, replace theSystem.out.println(…)
with a call to a logger method.
Self Evaluation
- Why is using
System.out.println(…)
for logging so problematic? - How is SLF4J different from the other logging frameworks? What benefits does this bring?
Task
Implement logging in your Booker
program.
- Use SLF4J coupled with Logback.
- Bridge JUL (used by Guava) to SLF4J.
- Create a static configuration in
logback.xml
.- In addition to logging to the console, use a file-based log file to appear in
.booker/booker.log
relative to the user's home directory. - When the file grows to 200KB, roll over to a single
booker.log.old.1.zip
file. - Default to the
INFO
log level.
- In addition to logging to the console, use a file-based log file to appear in
- Convert all your
System.out.println(…)
statements throughout the application to equivalent logging statements, unless they are specifically for communication to the user. This includes all messages generated in your unit tests. NoSystem.out.println(…)
statement should appear at any place in your code, except where your code explicitly desires to communicate with the user through the console as part of the application's main functionality. Include at least one log message at each log level to illustrate your logging configuration is working.
Implement a --debug command-line flag, with a -d alias, and use this flag, if present, to programmatically set the log level to DEBUG
.
booker list [--debug] [--locale <locale>] [--name <name>] [--type (book|periodical)]
booker load-snapshot [--debug] [--locale <locale>]
booker purchase --isbn <ISBN> [--debug] [--locale <locale>]
booker -h | --help
Option | Alias | Description |
---|---|---|
list | Lists all available publications. | |
load-snapshot | Loads the snapshot list of publications into the current repository. | |
purchase | Removes a single copy of the book identified by ISBN from stock. | |
--debug | -d | Includes debug information in the logs. |
--help | -h | Prints out a help summary of available switches. |
--isbn | Identifies a book, for example for the purchase command. | |
--locale | -l | Indicates the locale to use in the program, overriding the system default. The value is in language tag format. |
--name | -n | Indicates a filter by name for the list command. |
--type | -t | Indicates the type of publication to list, either book or periodical. If not present, all publications will be listed. |
See Also
- The Java Logging Mess (Java Code Geeks - Bozhidar Bozhanov)
- Java Logging Overview (Oracle - Java™ Tech Note Guides)
- Java Logging Basics (Ultimate Guide to Logging)
References
Resources
- Apache Software Foundation
- Apache log4j 1
- Apache Log4j 2
- Simple Logging Facade for Java (SLF4J)
- Logback
- Apache Commons Logging (JCL)
- Concern Separation Aspect Registrar (Csar)
- Csar Logging Registrion (Clogr)
Acknowledgments
- SLF4J API bindings diagram from SLF4J user manual, copyright © 2004-2016 QOS.ch, and licensed under MIT.
- SLF4J API bridging diagram from SLF4J: Bridging legacy APIs, copyright © 2004-2016 QOS.ch, and licensed under MIT.
- Some symbols are from Font Awesome by Dave Gandy.