4

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?

Code-Apprentice
  • 81,660
  • 23
  • 145
  • 268
  • 1
    Sounds like you're looking for a logging library like [log4j](http://logging.apache.org/log4j/). – Beau Grantham Sep 09 '12 at 22:47
  • Sounds like you're trying to use standard Java logging instead of log4j. I'd check out [How to get java Logger output to file by default](http://stackoverflow.com/questions/751736/how-to-get-java-logger-output-to-file-by-default) and see if that answers your question. – spdaley Sep 09 '12 at 22:57
  • @spdaley Thanks for the link. That question is exactly what I'm trying to do. Unfortunately, the answer given doesn't work for me. I have posted an SSCCE to illustrate. – Code-Apprentice Sep 09 '12 at 23:46

2 Answers2

4

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.

João Mendes
  • 1,719
  • 15
  • 32
  • Where can I find some more information about the differences between java.util.logging and log4j? Do you know of any sites with a direct comparison? – Code-Apprentice Sep 09 '12 at 22:55
  • 2
    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 – João Mendes Sep 09 '12 at 22:57
  • Thanks for the information. I will certainly look into log4j. However, my question is still unanswered. I've added some code to my question to illustrate what I'm trying to do with the java.util.logging API. – Code-Apprentice Sep 09 '12 at 23:46
  • @Hovercraft Full Of Eels: Done. Thanks for the suggestion. – João Mendes Sep 10 '12 at 00:09
  • I'll add my answer to your more specific coding problem in a new answer, as it will be easier to read. – João Mendes Sep 10 '12 at 00:09
4

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.

João Mendes
  • 1,719
  • 15
  • 32
  • "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." The HelloWorld example does the exact same thing and works fine. I believe the premature closing of the handler in the finally block is the issue. Let me check that out. – Code-Apprentice Sep 10 '12 at 00:32
  • Okay, I'm a step closer. I was closing the FileHandler prematurely. – Code-Apprentice Sep 10 '12 at 00:34
  • After removing the `handler.close()` call, it works fine. I think your Hashmap code, or something like it, is already implemented inside the java.util.logging API. – Code-Apprentice Sep 10 '12 at 00:36
  • Well, the HelloWorld example calls `getLogger("")` twice and gets the same logger both times, so, not the same. On the other hand, by default, loggers also send their output to the parent handler, so you're probably right, "problem one" was likely to be a non-issue. As for the Hashtable in my code, it's only there so that I don't keep adding the same handler multiple times to the same logger. If you're only adding it to the top level logger (`getLogger("")`), yeah, don't worry about it. – João Mendes Sep 10 '12 at 00:51
  • It also calls `private static Logger theLogger = Logger.getLogger(HelloWorld.class.getName());` which is the logger that is used to actually log messages. So thus it is the same. (The multiple calls to `getLogger("")` in `main()` could be optimized by a reference variable. This is an artifact of the original example which I modified and posted here -- certainly not my preferred coding style.) – Code-Apprentice Sep 10 '12 at 00:57
  • Ah, I see it now. Cool. :) Glad you're wrapping your head around it. – João Mendes Sep 10 '12 at 10:58
  • Yah, every time I go to post a question here, I now remember all the times I've been told to post a SSCCE. So I go back and try to write a small program to recreate the part I'm working on in my main program. This often helps clarify what I'm trying to do and I even sometimes answer my own questions. – Code-Apprentice Sep 10 '12 at 13:52
  • I accepted this answer because it contains the key to solving the issue in my first code example: "you're closing the handler early." It would be nice if this solution was emphasized more. I hesitate to edit your answer because I would be tempted to cut out everything except this one sentence. Some kind of edit may be required to make sure this is clear for anyone who encounters this problem in the future. – Code-Apprentice Sep 10 '12 at 14:44