Logging with `java.util.logging`
July 12th, 2008 by SamJava comes with a built-in logging system java.util.logging which is really quite good. It is very simple to use, highly customisable at runtime and offers incredible extensibility. However, by default it doesn’t allow you to specify the format of your logging messages and this tends to make people angry (the default setting is to print everything to System.err, over 2 lines). In this article I’m going to talk a little bit about why you should use the built-in logging package and show you how to get runtime support for the formatting of log messages.
Unfortunately, SUN did not include the logging package until version 1.4 of Java. As logging is such a critical component of any application, the Apache project came up with log4j, which was succeeded by Logback. In order to try and reconcile these libraries with the in-built logger, commons-logging was released. To further abstract the issue and address some serious issues with commons-logging, SLF4J was released. That means there are now five “standard” APIs for logging in Java (all very similar, but with totally different runtime quirks and not 100% compatible with each other). My advice is to ignore the Apache projects like the plague, and keep it simple by using what already exists in Java. And whatever you do, do not even think about implementing your own logging system (you’d be surprised how many people do!).
If you want to force all your middleware to use the java.util.logging API, SLF4J can be very useful… simply add the jars jcl-over-slf4j-X.jar, log4j-over-slf4j-X.jar and slf4j-jdk14-X.jar to your classpath.
For those who have never used the java.util.logging API before, I’ll show some basic usage. Place something like this in each of your classes that need logging output
private static final Logger log = Logger.getLogger(MyClass.class.getName());(yes, verbose, I know… a Logger.getLoggerForThisClass() static method would be great, SUN, if you’re listening).
You can then create logging messages as easily as
log.fine("you probably won't even have your logger set to output this level")
log.info("this is some information");
log.warning("this is a more serious warning, pay attention");
log.severe("holy potatoes, Batman! Something really *really* bad happened!");which I’m sure you’ll agree is more concise than using System.out.println! However, you get the added bonus of timestamps, thread names, class names and method names in the output… which you can point anywhere.
Runtime configuration is through a single logging.properties file that is specified at JVM startup. Your system will have a default in $JAVA_HOME/lib, but you can specify your own with the parameters java -Djava.util.logging.config.file=/path/to/my/logging.properties.
In the logging.properties file, you can specify “handlers” which direct the logs to different places (console, file or database), filters at many different points (so you only see logs of a certain priority), formatters (to customise the output) and you can even specify these options on a per-package or per-class basis! An example file looks something like this
# the handlers are a comma separated list of outputs, you can add a file or database output
handlers = java.util.logging.ConsoleHandler
# you can filter by level on individual handlers, but let's just print everything
java.util.logging.ConsoleHandler.level = ALL
# this tells the handler to use our custom formatter
java.util.logging.ConsoleHandler.formatter = com.thinktankmaths.logging.CustomFormatter
# you don't need to specify the next line, which demonstrates a very terse log format
com.thinktankmaths.logging.CustomFormatter.format = %L: %m [%C.%M]
# because you name your loggers, you can easily limit the Level of logs that are output
# this logs all messages for anything in your classes, but only "INFO" and above
# for everything else
.level = INFO
com.thinktankmaths.com.level = ALL
your_package_namespace_here.level = ALL
So for the above logging example, you’ll see something like the following on your console (note, this particular format doesn’t have timestamps)
FINE: "you probably won't even have your logger set to output this level" [MyClass.main]
INFO: "this is some information" [MyClass.main]
WARNING: "this is a more serious warning, pay attention" [MyClass.main]
SEVERE: "holy potatoes, Batman! Something really *really* bad happened!" [MyClass.main]
Actually, I lied… you can’t really customise the output at all. Turns out SUN are of the opinion that default output from the logger should stretch across 2 lines, or be XML. Many, many, many people complain about this. It is the biggest pain in the butt about the logger. However, you might notice that in the above config file, the formatting of the output has been set… this is because I have written a custom formatter and set it to be the default.
Below is the source of this magical file. You can safely remove the JCIP annotations if you don’t want them as a dependency but I strongly recommend that you use them to document the thread safety of your classes.
/*
* Created Jul 8, 2008
*
* Copyright ThinkTank Maths Limited 2008
*
* This file is free software: you can redistribute it and/or modify it under
* the terms of the GNU Lesser General Public License as published by the Free
* Software Foundation, either version 3 of the License, or (at your option)
* any later version.
*
* This file is distributed in the hope that it will be useful, but WITHOUT ANY
* WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS
* FOR A PARTICULAR PURPOSE. See the GNU Lesser General Public License for more
* details.
*
* You should have received a copy of the GNU Lesser General Public License
* along with this file. If not, see <http://www.gnu.org/licenses/>.
*/
package com.thinktankmaths.logging;
import java.text.DateFormat;
import java.text.MessageFormat;
import java.text.SimpleDateFormat;
import java.util.Date;
import java.util.logging.Formatter;
import java.util.logging.LogManager;
import java.util.logging.LogRecord;
import net.jcip.annotations.GuardedBy;
import net.jcip.annotations.ThreadSafe;
/**
* A {@link Formatter} that may be customised in a {@code logging.properties}
* file. The syntax of the property
* {@code com.thinktankmaths.logging.TerseFormatter.format}
* specifies the output. A newline will be appended to the string and the
* following special characters will be expanded (case sensitive):-
* <ul>
* <li>{@code %m} - message</li>
* <li>{@code %L} - log level</li>
* <li>{@code %n} - name of the logger</li>
* <li>{@code %t} - a timestamp (in ISO-8601 "yyyy-MM-dd HH:mm:ss Z" format)</li>
* <li>{@code %M} - source method name (if available, otherwise "?")</li>
* <li>{@code %c} - source class name (if available, otherwise "?")</li>
* <li>{@code %C} - source simple class name (if available, otherwise "?")</li>
* <li>{@code %T} - thread ID</li>
* </ul>
* The default format is {@value #DEFAULT_FORMAT}. Curly brace characters are not
* allowed.
*
* @author Samuel Halliday
*/
@ThreadSafe
public class CustomFormatter extends Formatter {
private static final String DEFAULT_FORMAT = "%L: %m [%c.%M %t]";
@GuardedBy("itself")
private final MessageFormat messageFormat;
@GuardedBy("itself")
private final DateFormat dateFormat =
new SimpleDateFormat("yyyy-MM-dd HH:mm:ss Z");
/** */
public CustomFormatter() {
super();
// load the format from logging.properties
String propName = getClass().getName() + ".format";
String format = LogManager.getLogManager().getProperty(propName);
if (format == null || format.trim().length() == 0)
format = DEFAULT_FORMAT;
if (format.contains("{") || format.contains("}"))
throw new IllegalArgumentException("curly braces not allowed");
// convert it into the MessageFormat form
format = format.replace("%L", "{0}").replace("%m", "{1}").replace("%M",
"{2}").replace("%t", "{3}").replace("%c", "{4}").replace("%T", "{5}").
replace("%n", "{6}").replace("%C", "{7}") + "\n";
messageFormat = new MessageFormat(format);
}
@Override
public String format(LogRecord record) {
String[] arguments = new String[8];
// %L
arguments[0] = record.getLevel().toString();
arguments[1] = record.getMessage();
// sometimes the message is empty, but there is a throwable
if (arguments[1] == null || arguments[1].length() == 0) {
Throwable thrown = record.getThrown();
if (thrown != null) {
arguments[1] = thrown.getMessage();
}
}
// %m
arguments[1] = record.getMessage();
// %M
if (record.getSourceMethodName() != null) {
arguments[2] = record.getSourceMethodName();
} else {
arguments[2] = "?";
}
// %t
Date date = new Date(record.getMillis());
synchronized (dateFormat) {
arguments[3] = dateFormat.format(date);
}
// %c
if (record.getSourceClassName() != null) {
arguments[4] = record.getSourceClassName();
} else {
arguments[4] = "?";
}
// %T
arguments[5] = Integer.valueOf(record.getThreadID()).toString();
// %n
arguments[6] = record.getLoggerName();
// %C
int start = arguments[4].lastIndexOf(".") + 1;
if (start > 0 && start < arguments[4].length()) {
arguments[7] = arguments[4].substring(start);
} else {
arguments[7] = arguments[4];
}
synchronized (messageFormat) {
return messageFormat.format(arguments);
}
}
}At the moment this may well be a performance bottleneck if you have lots of log messages and are not making use of all the parameters. However, you should be able to edit the format(LogRecord) method to only obtain the fields that have been requested in the format.
There is one other little thing about the logger that nags me, and that has to do with SUN bug #4827381. The output of the console adapter (the default) is System.err, not System.out… and there is no way to change this without writing your own adapter. If you want to output your logs to stdout, then grab hold of the Java source code, copy all the code from java.util.logging.ConsoleHandler and put it into a new file (with a new package/class name) and edit the reference from System.err to System.out. Bit of a pain.
Adalbert Blumenkohl wrote:
July 12th, 2008 at 8:36 am