Implementing logging in a Java application

Question

Disclaimer: I apologize that this question is so long. I have added code as I have explored suggestions made here and done additional research since asking my original question.

I am working on an open source project in Java and want to implement logging in my application to facilitate bug tracking and debugging when/if users report problems with the app. I am looking at the java.util.logging package from the standard Java API. I've already added some logging code when exceptions are caught. For example, I have

Logger.getLogger(FindCardsPanel.class.getName()).log(Level.SEVERE, "Storage I/O error", ex);

The only difference in each line of code is the class name and the message string.

I have read that the proper way to use a logger is using one for each class name string. This makes a little bit of sense since it allows a lot of flexibility in filtering log messages.

My current problem is that all of the logging messages currently go to stderr. I need to write them to a file instead. I have found the FileHandler class which facilitates this. However, since I have dozens of classes, I have dozens of logger names. Do I need to add the FileHandler to each of these? That seems like it will take a lot of work, especially when I decide to add another class to my code base.

I understand that there is some kind of tree hierarchy of loggers. Does this happen automatically? If not, how do I create my own hierarchy? And whether or not it's automatic, where in the hierarchy do I add my FileHandler so that all logging goes to the same file?

Edit:

Based on the link given by @spdaley, I have created the following SSCCE:

LoggingSSCCE.java:

package loggingsscce;

import java.io.IOException;
import java.util.logging.FileHandler;
import java.util.logging.Level;
import java.util.logging.Logger;

public class LoggingSSCCE {
    private static String LOG_FILE_NAME = "loggingsscce.log";

    public static void main(String[] args) throws IOException {
        LoggingSSCCE.initLogger();

        LogTest lta = new LogTestA();
        lta.doLog();

        LogTest ltb = new LogTestB();
        ltb.doLog();
    }

    private static void initLogger() throws IOException {
        FileHandler handler = null;

        try {
            boolean append = true;
            handler = new FileHandler(LoggingSSCCE.LOG_FILE_NAME, append);
            handler.setFormatter(new SimpleFormatter());

            Logger logger = Logger.getLogger("");
            logger.setLevel(Level.ALL);
            logger.addHandler(handler);
        } finally {
            handler.close();
        }
    }
}

LogTest.java:

package loggingsscce;

interface LogTest {
    public void doLog();
}

LogTestA.java:

package loggingsscce;

import java.util.logging.Level;
import java.util.logging.Logger;

class LogTestA implements LogTest {
    @Override
    public void doLog() {
        Logger.getLogger(LogTestA.class.getName()).log(Level.INFO, "LogTestA.doLog()");
    }
}

LogTestB.java:

package loggingsscce;

import java.util.logging.Level;
import java.util.logging.Logger;

class LogTestB implements LogTest {
    @Override
    public void doLog() {
        Logger.getLogger(LogTestA.class.getName()).log(Level.INFO, "LogTestB.doLog()");
    }
}

When I run this in NetBeans, the output window shows

run:
Sep 09, 2012 5:36:56 PM loggingsscce.LogTestA doLog
INFO: LogTestA.doLog()
Sep 09, 2012 5:36:56 PM loggingsscce.LogTestB doLog
INFO: LogTestB.doLog()
BUILD SUCCESSFUL (total time: 0 seconds)

but the "loggingsscce.log" file is empty.

So what am I missing?

Another edit:

I found an example at http://onjava.com/pub/a/onjava/2002/06/19/log.html?page=2 which I modified:

import java.io.IOException;
import java.util.logging.FileHandler;
import java.util.logging.Handler;
import java.util.logging.Level;
import java.util.logging.Logger;
import java.util.logging.LogManager;
import java.util.logging.SimpleFormatter;

public class HelloWorld {
  private static Logger theLogger = Logger.getLogger(HelloWorld.class.getName());

  public static void main( String[] args ) throws IOException {
    Logger rootLogger = Logger.getLogger("");
    Handler handler = new FileHandler("hello.log");

    handler.setFormatter(new SimpleFormatter());
    rootLogger.addHandler(handler);

    // The root logger's handlers default to INFO. We have to
    // crank them up. We could crank up only some of them
    // if we wanted, but we will turn them all up.
    Handler[] handlers = Logger.getLogger( "" ).getHandlers();
    for ( int index = 0; index < handlers.length; index++ ) {
      handlers[index].setLevel( Level.FINE );
    }

    // We also have to set our logger to log finer-grained
    // messages
    theLogger.setLevel(Level.FINE);
    HelloWorld hello = new HelloWorld("Hello world!");
    hello.sayHello();
  }

  private String theMessage;

  public HelloWorld(String message) {
    theMessage = message;
  }

  public void sayHello() {
    theLogger.fine("Hello logging!");
    System.err.println(theMessage);
  }
}

This produces the following output from the command-line:

lib_lab_ref08@LBP-REF87XVMDP1 /e/devel/src/java/stackoverflow
$ javac HelloWorld.java

lib_lab_ref08@LBP-REF87XVMDP1 /e/devel/src/java/stackoverflow
$ java HelloWorld
Sep 09, 2012 6:13:33 PM HelloWorld sayHello
FINE: Hello logging!
Hello world!

lib_lab_ref08@LBP-REF87XVMDP1 /e/devel/src/java/stackoverflow
$ cat hello.log
Sep 09, 2012 6:13:33 PM HelloWorld sayHello
FINE: Hello logging!

lib_lab_ref08@LBP-REF87XVMDP1 /e/devel/src/java/stackoverflow
$

So this single class example works just fine. What is the difference when I have multiple classes in multiple files as in my previous code?

Modifications to LoggingSSCCE class:

I added a static field:

private static FileHandler HANDLER = null;

And changed the initLogger() method:

private static void initLogger() throws IOException {
    LoggingSSCCE.HANDLER = new FileHandler(LoggingSSCCE.LOG_FILE_NAME);
    LoggingSSCCE.HANDLER.setFormatter(new SimpleFormatter());

    Logger logger = Logger.getLogger("");
    logger.setLevel(Level.ALL);
    logger.addHandler(LoggingSSCCE.HANDLER);
}

This works great with the following contents of "loggingsscce.log":

Sep 09, 2012 6:50:16 PM loggingsscce.LogTestA doLog
INFO: LogTestA.doLog()
Sep 09, 2012 6:50:16 PM loggingsscce.LogTestB doLog
INFO: LogTestB.doLog()

I'm still having trouble making this all work in my more complicated Swing project. I suspect my FileHandler is being closed, perhaps by the garbage collector?

Solution 1

Edit:

The problem in your original code is that you're closing the handler early.

Original Text:

I see two problems with your (original) code:

Problem one, you're calling getLogger("") in your init, but calling getLogger(xxx.class.getName()) in your implementations. Each of those loggers is a different logger, and you're only setting the file handler for the "" one.

Problem two, which was being masked by problem one, you're closing the handler early.

Here's something you can try for multiple classes in one file:

LoggingSSCCE.java:

package loggingsscce;

import java.io.IOException;
import java.util.Hashtable;
import java.util.logging.FileHandler;
import java.util.logging.Level;
import java.util.logging.Logger;

public class LoggingSSCCE {
    private static String LOG_FILE_NAME = "loggingsscce.log";
    Hashtable<String, Logger> loggers = new Hastable<String, Logger>();
    FileHandler handler = null;

    public static void main(String[] args) throws IOException {

        LogTest lta = new LogTestA();
        lta.doLog();

        LogTest ltb = new LogTestB();
        ltb.doLog();
    }

    public static Logger getLogger(String loggerName) throws IOException {
        if ( loggers.get(loggerName) != null )
            return loggers.get(loggerName);

        if ( handler == null ) {
            boolean append = true;
            handler = new FileHandler(LoggingSSCCE.LOG_FILE_NAME, append);
            handler.setFormatter(new SimpleFormatter());
        }

        Logger logger = Logger.getLogger(loggerName);
        logger.setLevel(Level.ALL);
        logger.addHandler(handler);
        loggers.put(loggerName, logger);
        return logger;
    }
}

LogTest.java:

package loggingsscce;

interface LogTest {
    public void doLog();
}

LogTestA.java:

package loggingsscce;

import java.util.logging.Level;
import java.util.logging.Logger;

class LogTestA implements LogTest {
    @Override
    public void doLog() {
        LoggingSSCCE.getLogger(LogTestA.class.getName()).log(Level.INFO, "LogTestA.doLog()");
    }
}

LogTestB.java:

package loggingsscce;

import java.util.logging.Level;
import java.util.logging.Logger;

class LogTestB implements LogTest {
    @Override
    public void doLog() {
        LoggingSSCCE.getLogger(LogTestB.class.getName()).log(Level.INFO, "LogTestB.doLog()");
    }
}

If you want this to work for one file per class, or some other criteria, simply modify LoggingSSCCE.getLogger to compute an appropriate file name for each case.

Solution 2

The immediate thing that comes to mind is, take a look at log4j. It's an open source logging framework that's very widely used in all sorts of libraries and applications.

Edit:

java.util.logging is the basic API. It really doesn't do anything you don't tell it to do, explicitly, in code. log4j is a library with full configuration facilities and other goodies. It sits atop java.util.logging and expands it with functionality that is much easier to use than the (relatively) low-level java.util.logging.