Wrox Press Java Programming 24-Hour Trainer 2nd (2015)

Lesson 34. Java Logging API

Every Java program performs various functions during its life cycle—for example, it opens files, connects to databases or remote services, or it performs some calculations. Often software developers need to print application-specific messages from various parts of the program. Sometimes developers need to confirm that a program visited a certain method or print the results of intermediate calculations.

Proper reporting of runtime errors is even more important. You may want to print not only the error messages, but also the messages that inform about the control flow of the program (for example, an order has been placed or cancelled). If your Java application server won’t start, the first place to check is its log files, which may have a description of an issue, or at least you can see at which stage the launch process stopped working.

Until now, in most of the code samples in this book (except graphical user interface applications) I’ve used the tried and true method System.out.println(), but this approach has several issues:

1. It’s not easy to “turn off” multiple informational println() calls when the application goes into quality assurance (QA) or production. You need to find and comment out these statements that are sprinkled through your application code. And if a bug is reported in the production application, you need to uncomment several println() statements and potentially add more of them.

2. There is no trace of what’s happened in the application after it’s complete.

3. If one of many users of a server-side Java application calls the support team about an issue, the support personnel needs to be able to quickly identify and analyze the messages related to this particular user’s interaction—when the issue happened and in which software module it occurred.

Replacing println() statements with a Java Logging application programming interface (API) or a third-party logging framework addresses these issues, and you should use in all applications both on the server and the client sides. Logging is used both in development and production. The logging messages can be directed to the end users as well.

There are many Java logging frameworks. But the majority of this lesson is dedicated to the Java Logging API, which is a part of Java SE.

Java Logging API

The Java Logging API is implemented in the package java.util.logging. The two main classes of the logging API are Logger and Handle. An application obtains an instance of the Logger object, which creates an instance of the LogRecord and gives it to a Handler object for publishing. The Java Logging API includes several types of handlers, and the default one is ConsoleHandler that publishes messages on the system console.

For a simple application, you can create one global logger that takes care of all message logging. In more complex applications, you can create a hierarchy of loggers where each package or class has its own logger.

The Java Logging API enables you to group messages by different levels. For example, you can assign the INFO level to the messages that do not report errors, and you can assign serious error messages the SEVERE level. These are the logging levels defined in the class Level:

1. SEVERE

2. WARNING

3. INFO

4. CONFIG

5. FINE

6. FINER

7. FINEST

The order of these levels is important as these levels represent ordered integers. SEVERE is the highest number and FINEST is the lowest. The default logging level is INFO, which means that all log messages marked as INFO, and the higher levels (WARNING and SEVERE) will be logged. If you change the default logging level to WARNING, then only the messages of the levels WARNING and SEVERE are logged.

The levels FINE, FINER, and FINEST are used to create log records with more descriptive messages. To turn on all logging levels, set the level to Level.ALL, and to turn the logging off set the level to Level.OFF. For more details of the logging level refer to Oracle javadoc for the classLevel. Regardless of what level you decide to use, make sure that the log messages are informative.

You can set the log level on both the Logger and the Handler objects. You do this programmatically or in a configuration file. The latter allows you to change the default level during the run time for a deployed application. One logger object can have several handlers that publish messages to different destinations, and each of the handlers can have a different log level.

Writing lots of logging messages can affect the performance of your application. When you change the default log level you minimize the performance burden in applications that are deployed in production. I explain how you set and change log levels a bit later, but for now let’s create a very basic logging application.

Hello World with the Java Logging API

Everyone starts learning Java by writing a simple program that prints Hello World on the system console using the following statement:

System.out.println("Hello World");

It’s time to replace this statement with the Java Logging API.

Hello World with a Global Logger

Start with creating an Eclipse Java project called Lesson34. In it, create a new class HelloLoggingWorld in a package com.lesson34. In the main() method of this class you’re going to use the Logger object to greet the world as follows:

package com.lesson34;

import java.util.logging.Logger;

public class HelloWorldGlobalLogger {

private static Logger logger =

Logger.getGlobal();

public static void main(String[] args) {

logger.fine("Hello fine world!");

logger.info("Hello info world!");

logger.severe("Hello severe world!");

}

Although an application can have a hierarchy of loggers, this simple program uses a single global logger obtained by calling the method getGlobal(). The program starts with initializing the logger variable with the Logger object. Then the program invokes three methods on this logger: fine(), info(), and severe(). The names of the methods correspond to the logging levels. But if you run this program, only two messages are printed on the system console:

Jan 28, 2015 11:27:17 AM com.lesson34.HelloWorldGlobalLogger main

INFO: Hello info world!

Jan 28, 2015 11:27:17 AM com.lesson34.HelloWorldGlobalLogger main

SEVERE: Hello severe world

Because the default logging level is INFO, the message of the FINE level was not printed. By default the log records published on the console include the date and time, the name of the class, the level, and the message.

Hello World with a Class-Level Logger

The application can have more than one logger, all of which are children of the global logger. For example, you can create a class-level logger identified by a hierarchical name that looks similar to a fully qualified class name. You can create a Java class that creates the logger specifically for this class:

private static Logger logger =

Logger.getLogger("com.lesson34.HelloWorldClassLogger");

To avoid hardcoding the class name (it can be moved to a different package) you can ask Java to obtain a fully qualified class name, as shown here:

private static Logger helloLogger =

Logger.getLogger(HelloWorldClassLogger.class.getName());

The following program purposely divides by zero just to show the use of the class-level logger:

package com.lesson34;

import java.util.logging.Logger;

public class HelloWorldClassLogger {

private static Logger helloLogger =

Logger.getLogger(HelloWorldClassLogger.class.getName());

public static void main(String[] args) {

helloLogger.info("Trying to divide by zero");

try{

int result = 25/0;

} catch(ArithmeticException e){

helloLogger.severe("Division by zero");

}

The output of this program is shown here:

Jan 28, 2015 2:54:26 PM com.lesson34.HelloWorldClassLogger main

INFO: Trying to divide by zero

Jan 28, 2015 2:54:26 PM com.lesson34.HelloWorldClassLogger main

SEVERE: Division by zero

Software developers often create a separate logger not only for each class but also for each package. But the procedure remains the same; just specify the name of the package as the logger name:

private static Logger logger = Logger.getLogger(

HelloWorldClassLogger.class.getPackage().getName());

Using Handlers and Setting Log Levels

The Logger object doesn’t log messages on its own. It creates a LogRecord and passes it to a Handler object for publication to a specified destination. So far the log messages from the code examples have been sent to the system console because the Java Logging API uses a ConsoleHandlerobject by default. It was a ConsoleHandler that printed the log messages.

To set the logging level, you need to call a method setLevel(); for example, to set the FINE logger level you need to call a method setLevel(Level.FINE). You can set the severity level of the log messages on both the logger and the handler, and they don’t have to be the same. For example, you may want to record only SEVERE messages in the log file, while sending to the console messages of the level INFO and higher.

You can also log one message under different logging level without changing the current level by using the method log():

log(Level.FINE, "Hello fine world");

You can assign one or more handlers to the Logger objects so the log messages are published in one or more destinations. The Java Logging API supports the following handlers:

· ConsoleHandler: A handler for writing log records to the System.err object (by default it points at the same device as System.out).

· FileHandler: A handler that writes log records either to a single file or to a set of rotating log files.

· StreamHandler: A handler for writing log records to an OutputStream.

· SocketHandler: A handler that writes log records to local or remote Transmission Control Protocol (TCP) ports.

· MemoryHandler: A handler that buffers log records in memory.

To assign a handler(s) to a logger object you need to create an instance of one of the previously listed handlers and add it to the Logger object by invoking the method addHandler():

FileHandler helloFileHandler

helloFindHandler = new FileHandler("helloWorld.log");

helloLogger.addHandler(helloFileHandler);

Now write yet another small program that publishes log messages on the console and in a log file. The logger that you’ve used in the previous examples internally created an instance of the ConsoleHandler class that published messages on the system console. Now you’re adding another handler, FileHandler, to write log messages into a file, so you have the logs in the system console as well as in a file. To make this example more interesting, publish only WARNING and SEVERE messages in a file and have the console get the messages of the level FINE and above.

Create the directory named logs in the root of your Eclipse project, and see whether the following program HelloWorldHandlers properly publishes messages in the log file and system console:

package com.lesson34;

import java.io.IOException;

import java.util.logging.ConsoleHandler;

import java.util.logging.FileHandler;

import java.util.logging.Level;

import java.util.logging.Logger;

public class HelloWorldHandlers {

private static Logger helloLogger =

Logger.getLogger(HelloWorldClassLogger.class.getName());

public static void main(String[] args) {

FileHandler helloFileHandler;

try {

helloFileHandler = new FileHandler("logs/helloWorld.log");

helloLogger.addHandler(helloFileHandler);

helloFileHandler.setLevel(Level.WARNING);

} catch (SecurityException se) {

System.out.println(se.getMessage());

} catch (IOException ioe) {

System.out.println(ioe.getMessage());

}

helloLogger.fine("Hello from fine world");

helloLogger.info("Trying to divide by zero");

try{

int result = 25/0;

} catch(Exception e){

helloLogger.severe("Division by zero");

}

The program HelloWorldHandlers adds a FileHandler to the logger to publish messages to the file logs/helloWorld.log. You can create and assign a Formatter object to the handler to format the output in a way that fits your needs. XMLFormatter is the default formatter for FileHandler. Having log files in the XML format allows writing programs that can read and parse log files, which can be pretty useful for large log files.

Creating an instance of the FileHandler may throw SecurityException if access to log files was protected by Java Security Manager, which is not the case in our example.

Run HelloWorldHandlers and it creates a file helloWorld.log in the logs directory of your Eclipse project (you may need to refresh the project view to see it). Here’s the content of this log file:

<?xml version="1.0" encoding="UTF-8" standalone="no"?>

<!DOCTYPE log SYSTEM "logger.dtd">

<log>

<logger>com.lesson34.HelloWorldClassLogger</logger>

<level>SEVERE</level>

<class>com.lesson34.HelloWorldHandlers</class>

<message>Division by zero</message>

</record>

</log>

The preceding file contains only the SEVERE message, which is correct. At the same time, the ConsoleHandler also printed INFO messages on the system console:

Jan 28, 2015 5:20:38 PM com.lesson34.HelloWorldHandlers main

INFO: Trying to divide by zero

Jan 28, 2015 5:20:38 PM com.lesson34.HelloWorldHandlers main

SEVERE: Division by zero

Avoiding Duplicate Log Messages

The program HelloWorldHandlers uses a default console handler of the global logger to publish messages on the console. If you add an instance of the ConsoleHandler object to helloLogger, you have two console handlers: one on the class level and one global. This results in displaying duplicate messages on the console because the global logger is a parent of helloLogger, and all handlers in this hierarchy are invoked. If you want to turn the parent loggers off, use the method setUseParentHandlers():

helloLogger.setUseParentHandlers(false);

But why was the FINE level message “Hello from fine world” not displayed on the console? Invoking helloLogger.setLevel(Level.FINE) from HelloWorldHandlers won’t help. The reason is that the Java Runtime Environment (JRE) comes with the configuration file logging.properties, which may supersede the log levels set in the program.

The File logging.properties

If you open the directory jre/lib in your Java distribution, you find the file logging.properties, which sets various logging properties including these:

.level= INFO

java.util.logging.ConsoleHandler.level = INFO

The first one restricts the default global level across all loggers, and the second limits the messages that are printed on the console. Both levels default to INFO. If you change these values to FINE or ALL, the program HelloWorldHandlers starts publishing FINE messages on the console.

Each application can have its own logging properties file that you can pass as the Java Virtual Machine (JVM) parameter from the command line, for example:

java -Djava.util.logging.config.file="myLogging.properties" MyApp

You can also load the application-specific logging properties file programmatically as follows:

LogManager.getLogManager().readConfiguration(

newFileInputStream("mylogging.properties"));

If your program creates named loggers, you can override the log levels in your log.properties file; for example:

com.lesson34.HelloWorldClassLogger.level=ALL

More About Logging with FileHandler

Writing log messages into files is the most common practice. The FileHandler class has several overloaded constructors. To work with log files in the append mode (log records are being added to the existing file), use a two-argument constructor:

helloFileHandler = new FileHandler("logs/helloWorld.log", true);

To avoid littering your disk space by tons of log files, you can create rotating log files. You can specify the maximum file size and maximum number of log files. A new file is created as soon as the current log file reaches a specified size. When the new log file is maxed out, another one is created. If the number of the allowed log files is reached the oldest log file is replaced with a new one, and log records are directed there.

For example, the following code snippet creates a FileHandler object that initially creates a log file named helloWorld.log.0, and as soon as its size grows to 1000 bytes, the handler renames the log file into helloWorld.log.1 and creates a new one named helloWorld.log.0 and so on. ThisFileHandler creates not more than three files in total, and logging is done in the append mode:

helloFileHandler =

new FileHandler("logs/helloWorld.log", 1000, 3, true);

You see this code in action while working on the assignment from the “Try It” section of this lesson.

Formatters and Filters

Formatters allow you to change the format of logging messages and filters (in addition to log levels), so the handlers can decide if they are interested in a particular LogRecord. You can assign formatters to the log handlers. Filters can be assigned to both loggers and handlers.

Formatters

You can format log messages using classes SimpleFormatter or XMLFormatter included in with Java Development Kit (JDK) , or create your own custom formatter. By default, console handlers use SimpleFormatter, and file handlers use XMLFormatter.

SimpleFormatter outputs the time-stamp, class name, method name, level, log message, and possible exception. XMLFormatter outputs messages in a form of an XML structure as XML-formatted messages as you’ve seen in the section on log handlers.

To create a custom formatter, declare a class the extends an abstract class Formatter and override its method format(). You can implement any formatting you like. Just prepare a String with the required content and let the method format() return it. The following example shows a simple custom formatter that doesn’t print a timestamp and uses the symbols ==> as a separator between the fields of the LogRecord:

package com.lesson34;

import java.util.Date;

import java.util.logging.Formatter;

import java.util.logging.LogRecord;

public class MyFormatter extends Formatter {

@Override

public String format(LogRecord logRecord) {

return logRecord.getSourceClassName()+"==>"

+ logRecord.getSourceMethodName()+"==>"

+ logRecord.getMessage()+"\n";

}

Open your logging.properties file and assign this class to be a formatter for the console handler:

java.util.logging.ConsoleHandler.formatter=com.lesson34.MyFormatter

Now if you run the HelloWorldHandlers (or any other sample from this lesson), the output of the logger should look like this:

com.lesson34.HelloWorldHandlers==>main==>Hello from the fine world

com.lesson34.HelloWorldHandlers==>main==>Trying to divide by zero

com.lesson34.HelloWorldHandlers==>main==>Division by zero

Invoking the method setFormatter() on the handler object is an alternative to specifying a formatter to a handler from the command line.

Filters

With filters, you can program application logic to decide if a particular LogRecord should be logged. If you don’t want to publish a particular LogRecord, simply return false and it won’t be published. Otherwise, return true. Filter is an interface with a single method isLoggable(). Remember functional interfaces from Lesson 13? You can implement a filter with a lambda expression.

The following example generates random prices for stocks, but it logs only those prices that are greater than $60:

package com.lesson34;

import java.util.logging.Filter;

import java.util.logging.Level;

import java.util.logging.Logger;

public class StockQuotePublisher {

private static Logger stockLogger =

Logger.getLogger(StockQuotePublisher.class.getName());

// A lambda expression

static Filter expensiveStocks = (logRecord) -> {

Object[] parameters = logRecord.getParameters();

double price = ((Double)parameters[0]).doubleValue();

return ( price > 60) ? true: false;

};

public static void main(String args[]){

stockLogger.setFilter(expensiveStocks);

getPrice("IBM");

getPrice("MSFT");

getPrice("AAPL");

getPrice("CAT");

getPrice("VZ");

}

private static double getPrice(String stockSymbol){

double price = Math.random()*100;

stockLogger.log(Level.INFO, stockSymbol + ":"

+ price, price);

return price;

}

The method getPrice()generates prices in the range between 0 and 100. This method logs messages using a different logging API—the method log()—which has several overloaded versions. In this case, I use the version with three arguments: level, message, and an object. The last argument can be any object; it’s considered a parameter of the LogRecord. Even though it seems that you log the price value of the primitive double, Java knows that an object is required and uses the autoboxing feature to create an instance of the Double wrapper.

The program calls getPrice() from the main() method for five different stocks. If you didn’t apply a filter, all generated prices would be published on the console. But the class StockQuotePublisher declares a lambda expression expensiveStocks that implements the functional interface Filter , which returns true only if the stock price is greater than 60. This filter is assigned to the logger:

stockLogger.setFilter(expensiveStocks);

You can assign a filter to a Handler the same way you assign it to a Logger object. Log filters go one step further than log levels: they offer data-driven logging. Running StockQuotePublisher produces different results on each run because of the random price generation. But none of the published log records show a price lower than 60. Here’s a sample console output:

Jan 29, 2015 8:29:29 PM com.lesson34.StockQuotePublisher getPrice

INFO: AAPL:92.09444632063976

Jan 29, 2015 8:29:29 PM com.lesson34.StockQuotePublisher getPrice

INFO: VZ:85.58149465560332

Logging Frameworks

Although the Java Logging API is a good solution for small and mid-size applications, it may present a performance bottleneck in high-load multiuser applications where adding a couple of hundred milliseconds for publishing each message is not acceptable. There are numerous open-source logging frameworks on the market, which you can easily learn if you’re familiar with the Java Logging API.

Apache Log4J 2 is the most popular framework used in commercial Java applications. It’s a newer version of Log4J. Log4J also has a logger object. Appenders perform the same role as handlers. Layouts are similar to formatters. A log record is represented by a log event in Log4J. Whereas the Java Logging API allows file rotation by size only, Log4J supports file rotation by date/time.

But Log4J 2 also supports asynchronous loggers and appenders, which can make it an order of magnitude faster than the Java Logging API. Log4J 2 is the right choice for high-performance logging. To see how many messages Log4J 2 can publish per second, see the statistics on low-latency logging.

The second popular logging framework is called Logback. It’s similar to Log4J as it was founded by the same developer. Logback is faster than Log4J, but Log4J 2 asynchronous logging is faster than Logback’s. Start your next project with one of these frameworks, and if your application requires some special logging features, see if there is a framework that offer them out of the box.

To minimize the dependency of any particular logging framework, it is recommended to use an abstraction layer that will allow you to easily switch logging frameworks, if need be. Simple Logging Facade for Java (SLFJ) is the most popular implementation of such a layer. SLFJ allows you to decouple the logging API from a particular implementation. For example, no matter what logging framework you use, creating a Logger object and publishing an INFO-level message looks the same in SLFJ:

Logger logger = LoggerFactory.getLogger(HelloWorld.class);

logger.info("Hello World");

With SLFJ you’re not afraid that you picked the wrong logging framework; you can easily change it without modifying even one line of code. SLFJ logging levels include ERROR, WARN, INFO, DEBUG, and TRACE, which correspond to the SEVERE, WARNING, INFO, FINE,FINER levels of the Java Logging API or similar levels in other frameworks. Watch this video to see how easy it is to switch from one logging framework to another.

To add SLFJ you need to add two JARs to your project: one with the SLFJ API, and another that binds a particular logging framework to SLFJ. In Lesson 36, you’ll learn how to automate getting required JARs from public repositories of binaries. If you decide to try using SLFJ with the Java Logging API, you can find the required two JARs in Maven Central by searching for the following artifacts: slf4j-api and slf4j-jdk14.

But no matter what logging framework you choose, the sooner you stop using System.out.println() the better.

Try It

In this excercise, you create, configure, and use an application-specific logging.properties file. You also use a rotating file handler to control the size and number of your log files.

Lesson Requirements

You should have Java installed.

NOTE You can download the code and resources for this “Try It” from the book’s web page at www.wrox.com/go/javaprog24hr2e. You can find them in the Lesson34 folder in the download.

Step-by-Step

1. Copy the file logging.properties from your jre/lib directory into the root directory of the project Lesson34. Rename this file to myLogging.properties. I’m assuming that you previously created the logs directory.

2. Set the levels of the logger and the console handler to FINE in myLogging.properties:

3. .level= FINE

4. java.util.logging.ConsoleHandler.level = FINE

5. In Eclipse create a package tryit and copy the file HelloWorldHandlers.java there. Rename this file and refactor the code so it uses the class name RotatingFilesLogger.

6. Open the Run Configurations window for the class RotatingFilesLogger, select the Arguments tab, and add the following JRE property in the VM Arguments text field:

7. -Djava.util.logging.config.file="myLogging.properties"

8. Modify the line in RotatingFilesHandler to direct the log records to the file logs/rotating.log.

9. Run the RotatingFilesLogger program. It should publish FINE, INFO, and SEVERE messages into Eclipse console view regardless of the settings in the JRE’s global logging.properties file. This version of the program also creates a log file rotating.log in the logs directory. We implement file rotation in the next step.

10.Modify the line that creates FileHandler to use the constructor for rotating files in the append mode:

11. helloFileHandler =

12. new FileHandler("logs/rotating.log", 1000, 3, true);

13. Run the program several times and monitor the content of the logs directory. After several runs you should see the files named like rotating.log.0, rotating.log.1, and rotating.log.2 there. The numeric suffix will never go higher than 2 as the logger creates and rotates only three log files. The name of the newest log file always has the suffix 0.

TIP Please select the videos for Lesson 34 online at www.wrox.com/go/javaprog24hr2e. You will also be able to download the code and resources for this lesson from the website.