Java Practices->Logging messages

Logging messages

Java's logging facility (see Oracle's overview and API) has two parts: a configuration file, and an API for using logging services. It's a good tool, and is perfectly fine for simple and moderate logging needs. (For complex logging needs, you might consider log4j or some similar tool as an alternative.)

Log entries can be sent to these destinations, as either simple text or as XML:

the console
a file
a stream
memory
a TCP socket on a remote host

The Level class defines seven levels of logging enlightenment:

FINEST, FINER, FINE, CONFIG, INFO, WARNING, SEVERE
ALL and OFF are defined values as well

Here's one style of using these Levels in code, which may be modified as desired:

upon startup, use CONFIG to log configuration parameters
during normal operation, use INFO to log high-level "heartbeat" information
when bugs or critical conditions occur, use SEVERE
debugging information might default to FINE, with FINER and FINEST used occasionally, according to taste.

There's flexibility in how logging levels can be changed at runtime, without the need for a restart:

simply change the configuration file and call LogManager.readConfiguration.
or, change the level in the body of your code, using the logging API; for example, one might automatically increase the logging level in response to unexpected events.

Levels are attached to these items:

an originating logging request (from a single line of code)
a Logger (usually attached to the package containing the above line of code)
a Handler (attached to an application)

The flow of execution for a particular logging request usually proceeds as follows:

logging request of some level is made to logger attached to current package
if the request level is too low for that package's logger {
   discard it
}
otherwise {
   cycle through all handlers {
      if the request level is too low for that handler {
         discard it
      }
      otherwise {
         log the request
      }
   }
}

Here's an example of a logging configuration file:

# Properties file which configures the operation of the JDK
# logging facility.

# The system will look for this config file, first using
# a System property specified at startup:
#
# >java -Djava.util.logging.config.file=myLoggingConfigFilePath
#
# If this property is not specified, then the config file is
# retrieved from its default location at:
#
# JDK_HOME/jre/lib/logging.properties

# Global logging properties.
# ------------------------------------------
# The set of handlers to be loaded upon startup.
# Comma-separated list of class names.
# (? LogManager docs say no comma here, but JDK example has comma.)
handlers=java.util.logging.FileHandler, java.util.logging.ConsoleHandler

# Default global logging level.
# Loggers and Handlers may override this level
.level=INFO

# Loggers
# ------------------------------------------
# Loggers are usually attached to packages.
# Here, the level for each package is specified.
# The global level is used by default, so levels
# specified here simply act as an override.
myapp.ui.level=ALL
myapp.business.level=CONFIG
myapp.data.level=SEVERE

# Handlers
# -----------------------------------------

# --- ConsoleHandler ---
# Override of global logging level
java.util.logging.ConsoleHandler.level=SEVERE
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter

# --- FileHandler ---
# Override of global logging level
java.util.logging.FileHandler.level=ALL

# Naming style for the output file:
# (The output file is placed in the directory
# defined by the "user.home" System property.)
java.util.logging.FileHandler.pattern=%h/java%u.log

# Limiting size of output file in bytes:
java.util.logging.FileHandler.limit=50000

# Number of output files to cycle through, by appending an
# integer to the base file name:
java.util.logging.FileHandler.count=1

# Style of output (Simple or XML):
java.util.logging.FileHandler.formatter=java.util.logging.SimpleFormatter

An application should likely centralize the naming policy for Loggers, since switching naming styles becomes a simple edit in one method, instead of a large number of edits spread throughout the application. Reasons to alter the naming policy might include:

in a shared environment, adding an application name to the Logger name can help distinguish one application's entries from others
adding application version information might be beneficial for debugging

There's a common complaint with the JDK logging config file: a Handler cannot be restricted to a specific Logger. That is, Handlers defined in the config file are global, in the sense that they will be attached to all Loggers. This is particularly annoying in a server environment, since different applications will, by default, output logging statements into the same file. This behavior can be easily changed, but only by using the JDK logging API. Many would prefer to do this directly in the config file.

Here's an example of using the logging API:

package myapp.business;

import java.util.logging.*;

/**
* Demonstrate Java's logging facilities, in conjunction
* with a logging config file.
*/
public final class SimpleLogger {

  public static void main(String... args) {
    SimpleLogger thing = new SimpleLogger();
    thing.doSomething();
  }

  public void doSomething() {
    //Log messages, one for each level
    //The actual logging output depends on the configured
    //level for this package. Calls to "inapplicable"
    //messages are inexpensive.
    logger.finest("this is finest");
    logger.finer("this is finer");
    logger.fine("this is fine");
    logger.config("this is config");
    logger.info("this is info");
    logger.warning("this is a warning");
    logger.severe("this is severe");

    //In the above style, the name of the class and
    //method which has generated a message is placed
    //in the output on a best-efforts basis only.
    //To ensure that this information is always
    //included, use the following "precise log"
    //style instead :
    logger.logp(Level.INFO, this.getClass().toString(), "doSomething", "blah");

    //For the very common task of logging exceptions, there is a
    //method which takes a Throwable :
    Throwable ex = new IllegalArgumentException("Some exception text");
    logger.log(Level.SEVERE, "Some message", ex);

    //There are convenience methods for exiting and
    //entering a method, which are at Level.FINER :
    logger.exiting(this.getClass().toString(), "doSomething");

    //Display user.home directory, if desired.
    //(This is the directory where the log files are generated.)
    //System.out.println("user.home dir: " + System.getProperty("user.home") );
  }

  // PRIVATE

  //This style has no hard-coded literals, and requires the logger
  //to be non-static.
  private final Logger logger=Logger.getLogger(this.getClass().getPackage().getName());

  //This style lets the logger be static, but hard-codes a class literal.
  //private static final Logger logger =
  //  Logger.getLogger(SimpleLogger.class.getPackage().getName())
  //;

  //This style uses a hard-coded literal and should likely be avoided:
  //private static final Logger logger = Logger.getLogger("myapp.business");
}

Example Run 1 , using the config file defined above:

>java -Djava.util.logging.config.file=C:\\Temp\\logging.properties
-cp . myapp.business.SimpleLogger

ConsoleHandler is configured to show only SEVERE messages :

Jan 8, 2003 10:43:47 AM myapp.business.SimpleLogger doSomething
SEVERE: this is severe
Jan 8, 2003 10:43:47 AM myapp.business.SimpleLogger doSomething
SEVERE: Some message
java.lang.IllegalArgumentException: Some exception text
at myapp.business.SimpleLogger.doSomething(SimpleLogger.java:39)
at myapp.business.SimpleLogger.main(SimpleLogger.java:13)

While the FileHandler shows ALL that is sent to it:

Jan 8, 2003 10:43:46 AM myapp.business.SimpleLogger doSomething
CONFIG: this is config
Jan 8, 2003 10:43:47 AM myapp.business.SimpleLogger doSomething
INFO: this is info
Jan 8, 2003 10:43:47 AM myapp.business.SimpleLogger doSomething
WARNING: this is a warning
Jan 8, 2003 10:43:47 AM myapp.business.SimpleLogger doSomething
SEVERE: this is severe
Jan 8, 2003 10:43:47 AM class myapp.business.SimpleLogger doSomething
INFO: blah
Jan 8, 2003 10:43:47 AM myapp.business.SimpleLogger doSomething
SEVERE: Some message
java.lang.IllegalArgumentException: Some exception text
at myapp.business.SimpleLogger.doSomething(SimpleLogger.java:39)
at myapp.business.SimpleLogger.main(SimpleLogger.java:13)

Example Run 2, showing the ConsoleHandler output, using the logging.properties file which ships with the JDK, and which logs only INFO level and above:

>java -cp . myapp.business.SimpleLogger

Jan 8, 2003 10:52:31 AM myapp.business.SimpleLogger doSomething
INFO: this is info
Jan 8, 2003 10:52:31 AM myapp.business.SimpleLogger doSomething
WARNING: this is a warning
Jan 8, 2003 10:52:31 AM myapp.business.SimpleLogger doSomething
SEVERE: this is severe
Jan 8, 2003 10:52:31 AM class myapp.business.SimpleLogger doSomething
INFO: blah
Jan 8, 2003 10:52:31 AM myapp.business.SimpleLogger doSomething
SEVERE: Some message
java.lang.IllegalArgumentException: Some exception text
at myapp.business.SimpleLogger.doSomething(SimpleLogger.java:39)
at myapp.business.SimpleLogger.main(SimpleLogger.java:13)