Forward - Java Programming - How to Set up Java Logging

!! New !! Logging and LogStdStreams can now roll you console log file when it reaches a given size.
For Log4J logging use LogStdStreams to capture the Console output. For Java Logging see below.

This article covers one way of setting up Java logging. The Java logging package is very flexible and provides for many possible uses. This flexibility sometimes obscures its application. The article will cover how I set up Java Logging for Parallel and includes sample code for the special formatters used.

This is not a tutorial, it is an article on setting up Java Logging to meet specific functional requirements. For tutorial information on the Java Logging API read An Introduction to the Java Logging API and Java Logging Functionality in that order. Then look at the Sun Java Logging Overview

This article assumes you are familiar with the information in those tutorials.

Why is my Java Logging not working!!
Look here for tips and a debugging method to help you sort out the problems.

The Code V1.3

The complete source code, docs and compiled class files are available in this jar file, subject to this licence.

Functional Requirements

The specifications for this logging set-up are

All logging output to be saved in log files. This includes System.out and System.err outputs. Nothing is to be sent to the terminal window.
The logging is to be robust against programming errors and invalid objects.
The application should only log SEVERE level errors (and System.err and System.out) to the default log file.
The user can be instructed to start up the application in such a way so that more detailed logging is performed to a secondary log file.
The detailed logging is output in XML format but in such a way so that it can be easily viewed as a HTML page using an XSL stylesheet.
Only program errors are logged to the default log file. User messages are only logged if detailed logging is enabled.

Redirecting System.err and System.out to a log file.

As discussed in Error Recovery (Rule 1), allowing messages to be written to a terminal window is problematic. There may not be a terminal window attached to this application. Even if there is, it is much more convenient to log errors to a well documented file for later inspection and submission with a fault report.

The default configuration of Java Logging supplies a ConsoleHandler which writes to System.err. This default handler could be replaced with one that would write to a file instead, but that would still leave System.err and System.out going to the terminal. So instead this requirement will be satisfied by using the LogStdStreams class.

It the main application class, a static block is added that redirects all System.err and System.out to the application log file. The standard ConsoleHandler will now also be redirected to this file. The “well documented file” is applicationLog.log in the user's home directory.

package au.com.forward;
import java.util.logging.*;
import java.util.Date;
import java.io.File;
import au.com.forward.utils.LogStdStreams;
import au.com.forward.utils.StringUtils;
import au.com.forward.logging.LoggingSimpleFormatter;

public class ExampleLoggingApplication {

  static {    
    // any errors thrown here are fatal
    String userHome = System.getProperty("user.home",".");
    String FILE_SEPARATOR = System.getProperty("file.separator","/"); 
    String logFileName = userHome+FILE_SEPARATOR+"applicationLog.log";
   
    // set up logging for errors
    LogStdStreams.initializeErrorLogging(logFileName,
        "Log File for ExampleLoggingApplication "+ new Date(), true, true); 
        // redirect System.out as well as System.err and append to existing log
  }

This redirection of System.err to a log file is also necessary due to the bad practice of programmers (including Sun's programmers) of catching exceptions and just writing an error message to System.err. However I find that once I started using LogStdStreams, I found it convenient to write to System.err whenever I wanted to log a critical message to the application log file.

Robust Logging

Next I needed to deal with invalid objects being passed to the logger. Null objects are handled by the default formatter, but objects whose state is not valid and whose toString() method throws an exception are not handled.

For example, if badObject is an object whose toString() method throws an exception, then the following code
Object objs[] = {"string",application.badObject}; logger.log(Level.SEVERE,"Log a badObject {0} {1}",objs);

produces the following message
9/10/2003 15:34:11 au.com.forward.ExampleLoggingApplication main SEVERE: Log a badObject {0} {1}

That is, none of the objects are formatted. There is also a problem if you use a call like

logger.log(Level.SEVERE,"Log some objects",objs);

In the default java.utils.logging.Formatter, the objs are not logged at all. Only the message

9/10/2003 15:34:11 au.com.forward.ExampleLoggingApplication main SEVERE: Log some objects

is logged.

To overcome these problems, I created a new class, RobustFormatter, which extends from java.utils.logging.Formatter and over-rides the formatMessage() method. The code for this new class can be found here. This RobustFormatter is used as the super-class of the LoggingSimpleFormatter and LoggingXMLFormatter classes described below.

The Java logging package makes its best effort to determine the class and method name for each LogRecord. If your application produces a stacktrace with the correct method names and line numbers, then the logger should also. This is because the standand library code uses a stacktrace to find the method name and line number. By default, the Sun javac.exe for Windows includes line and source debugging information. However if you use the Apache Ant javac task, you have to explicitly turn on the debugging using the attributes debug=”on” and debuglevel=”lines,source” E.g.

<javac srcdir="${src}"
         destdir="${build}"
         classpath="xyz.jar"
         debug="on"
         debuglevel="lines,source"/>

Only send SEVERE messages to the default log file.

To ensure that only SEVERE log messages are output to the applicationLog.log, the logging level of the ConsoleHandler has to be set to Level.SEVERE. The default is Level.INFO for both handlers and loggers. At the same the ConsoleHandler's formatter will be set to the new LoggingSimpleFormatter which used the RobustFormatter.

This is achieved by adding the following code to the top of the application's main() method or by calling one of the au.com.forward.logging.Logging initialization methods

      try {
        Handler[] handlers = Logger.getLogger("").getHandlers();
        boolean foundConsoleHandler = false;
        for (int index = 0; index < handlers.length; index++) {
          // set console handler to SEVERE
          if (handlers[index] instanceof ConsoleHandler) {
            handlers[index].setLevel(Level.SEVERE);
            handlers[index].setFormatter(new LoggingSimpleFormatter());
            foundConsoleHandler = true;
          }
        }
        if (!foundConsoleHandler) {
          // no console handler found
          System.err.println("No consoleHandler found, adding one.");
          ConsoleHandler consoleHandler = new ConsoleHandler();
          consoleHandler.setLevel(Level.SEVERE);
          consoleHandler.setFormatter(new LoggingSimpleFormatter());
          Logger.getLogger("").addHandler(consoleHandler);
        }
      } catch (Throwable t) {
        System.err.println("Unexpected Error setting up logging\n" + StringUtils.toString(t));
      }

This code finds the ConsoleHandler and sets its logging level to Level.SEVERE and sets its formatter to LoggingSimpleFormatter. If no ConsoleHandler is found, one is added. This guards against a miss-configured logging.properties file (discussed below). The code for the LoggingSimpleFormatter can be found here.

User controlled Logging

Now that the default ConsoleHandler is configured, the next task is the detailed logging. This detailed logging is used for debugging, both during development and after release. It is controlled by the logging.properties file. When the application is started using the command line

java -Djava.util.logging.config.file=logging.properties au.com.forward.ExampleLoggingApplication

the logging.properties file adds a FiileHandler which uses an XML formatter to write the logging records in XML format.

The following is a first attempt at a logging.properties file (less most of the comments)

# Add a FileHandler
handlers=java.util.logging.FileHandler
# Default global logging level.
.level = SEVERE
# Describes specific configuration info for the Handlers.
# default file output is in user's home directory.
java.util.logging.FileHandler.pattern = %h/applicationLog%u.xml

This configuration file sets up a FileHandler which writes a file, applicationLog0.xml, in XML format (the default formatter for a FileHandler) in the user's home directory. Also by default, the file is rewritten each time the application is run.

Running the application with this logging configuration file (using the command line shown above) produces the following two log files

applicationLog.log

Log File for ExampleLoggingApplication Wed Oct 01 14:01:13 EST 2003
No consoleHandler found, adding one.

applicationLog0.xml

<?xml version="1.0" encoding="windows-1252" standalone="no"?>
<!DOCTYPE log SYSTEM "logger.dtd">
<log>
</log>

So far so good. The logging.properties file overrides the defaults. The file did not specify a ConsoleHandler so the code in main() added one. The logger.dtd file is available from Sun JavaTM Logging Overview - Appendix A. It is reproduced here.

The ExampleLoggingApplication is used to generate some sample logging output. The full source for this example class is here.

First a Logger for this class is added. I always use the full class name as the name of the logger. This ensures unique loggers for the application and, as noted in Appendix I, simplifies logging in static methods.

static final Logger logger = Logger.getLogger("au.com.forward.ExampleLoggingApplication");

then some logger calls are inserted into the class constructor

  public ExampleLoggingApplication() {
    logger.entering(this.getClass().getName(),"<init>");
    // .. constructor code here
    logger.exiting(this.getClass().getName(),"<init>");
  }

and in the main() method

  logger.finer("About to create new ExampleLoggingApplication()");
  ExampleLoggingApplication application = new ExampleLoggingApplication();

To set the logging Level for this class to something other than SEVERE, the following line is added to the bottom of the logging.properties file to set the level for this logger to FINEST

au.com.forward.ExampleLoggingApplication.level = FINEST

Note carefully, the .level which is added to the end of the logger's name in the above line. If you leave the .level out, the statement will be quietly ignored. Re-running the application now produces this XML file. It has a lot of information but is not very readable. The next task is to convert the XML output into a web page using an XSL stylesheet.

Viewing the Detailed Log output as HTML

To convert the XML detailed logging file to HTML format we need to add a reference to the stylesheet in the XML output. This is done by overriding the getHeader() method in the XML formatter class. The new LoggingXMLFormatter class extends from RobustFormatter and as well as adding a stylesheet reference in the header, the new class also simplifies the XML output used for exceptions.

The default XML output for any Throwable has separate tags for each frame in the stack trace. To simplify the XSL stylesheet, the LoggingXMLFormatter places all of the stacktrace inside one <message> element. The source code for LoggingXMLFormatter is here. You may notice that the code for the LoggingXMLForatter class is not quite as paronoid about errors in the LogRecord class as LoggingSimpleFormatter is.

Once the FileHandler is instructed to use the LoggingXMLFormatter class, the XML output can be formatted using logger.xsl (for a more information on XSL, see an XSL Tutorial)

To instruct the FileHandler to use the new LoggingXMLFormatter class, add the following line to the logging.properties file

java.util.logging.FileHandler.formatter = au.com.forward.logging.LoggingXMLFormatter

If the new XML output does not include the XSL reference in its header, check that the au.com.forward.logging.LoggingXMLFormatter.class is on the classpath. If Java cannot find the class, it will just quietly ignore it and use the default XML formattter.

Now opening the applicationLog0.xml file in InternetExplorer V6.0 displays a page like this. If you want to change the display format, you can revise the logger.xsl file.

Logging Program Errors while not logging User Messages

The article on Error Recovery discusses where to put top level try/catch blocks to handle errors that stop part of the application from functioning. Logging of program errors should also take place at these points. This logging should always be enabled.

The example code in Error Recovery - Rule 2 called the method Application.showErrorMessage(t) to display the error or user message. This method should also handle logging of program errors. User informational messages should not be logged as these are not errors. (The user never makes mistakes!)

public void actionPerformed(ActionEvent e) {
   try {
     ...
     // handle action here
     ...
    } catch (Throwable t) {
      // recover from error here
       Application.showErrorMessage(t);
      // if this action is associated with a particular window then use
      // Application.showErrorMessage(window,t);    instead
    }                   
}

Unified Error/Information Messages and Help showed some sample code for the Application.showErrorMessage() method. This needs to be modified slightly to include logging.

  public static void showErrorMessage(Throwable t) {
    // need to catch all errors here
    try {   
    
      if ((t instanceof java.lang.Error) || (t instanceof java.lang.Exception) ) {
         logger.severe("Error in Thread:" + Thread.currentThread().getName()
                        + "\n" + StringUtils.toString(t));
      } else {
         // user message. Only log at Level.FINER or Level.FINEST
         logger.finer("Error in Thread:" + Thread.currentThread().getName()
                       + "\n" + StringUtils.toString(t));
     }
    
     JButton dismiss = new JButton("Continue");
     JButton help = new JButton("Help");    
     JOptionPane messageBox = new JOptionPane("",JOptionPane.INFORMATION_MESSAGE);
      
     String msg =  formatThrowableMessage(t); 
     messageBox.setMessage(msg);
      
      ................

This extra code uses the distinction between errors and user messages proposed by Unified Error/Information Messages and Help to easily decide if a given Throwavble is a program error or a user message. Program errors are always logged, while user messages, which inherit directly from java.lang.Throwable, are only logged if the log level for this class is FINER or FINEST.

This completes the set-up of Java Logging to satisfy the given requirements. The Appendix I gives a couple of tips on using the Logger.entering() and Logger.exiting() methods.

Appendix I - Getting the class name for entering/exiting Java logging methods

Logger.entering() and Logger.exiting() methods both require an explicit class name and method name. You can optionally add argument objects or a return object. For non-static methods, I use this.getClass().getName() to ensure the class name is updated when I inherit from this class. For static methods, the this object is not available. In this case I use logger.getName() which in my code is always the class name. E.g.

public abstract class InternalWindow extends JInternalFrame {

  /**
   *  logger for this class 
   */
  public static final Logger logger = Logger.getLogger("au.com.forward.parallel.gui.InternalWindow");

  // a non-static method 
  public void setWindow(InternalWindow window) {
    // use this.getClass().getName() to show sub-class name
    logger.entering(this.getClass().getName(),"setWindow", window );
    // .... 
    logger.exiting(this.getClass().getName(),"setWindow");
  }

  // a static method 
  public static WorkspaceWindow lookupWindow(String workspaceName, String hostIP)
                                throws WorkspaceWindowException {
    Object[] args = {"workspaceName:",worspaceName, "hostIP:", hostIP}; 
    logger.entering(logger.getName(),"lookupWindow", args);
    
    logger.exiting(logger.getName(),"lookupWindow", window);
    return window;
  }

Java GUI Programming Tips and Guidelines How to Set up Java Logging