Log messages lost in few specific situations

I am using java.util.logging to do all the logging of my application.

Until recently, I was using the logging facility without any specific configuration. Everything worked as expected, all the logs were visible in the console (stderr)

Now, I wanted to customize the configuration for my logs. I want the logs to be displayed on the console, but I want them to be written in a file, too. I came up with the following solution :

public static void main(String[] args) {
    System.setProperty("java.util.logging.config.file", "log.config");
    Logger defLogger = Logger.getLogger("fr.def"); // all loggers I use begin by "fr.def"
    defLogger.setLevel(Level.ALL);
    defLogger.addHandler(new ConsoleHandler());
    defLogger.addHandler(new FileHandler());
    // real code here ...

Here is the content of the log.config file :

java.util.logging.FileHandler.formatter=java.util.logging.SimpleFormatter
java.util.logging.FileHandler.count=10
java.util.logging.FileHandler.pattern=logs/visiodef2.%g.log

This solution mostly works : I can see the logs in the console, and in the files too. Except that, in some situations, some log messages are simply lost (for both the console and the file). Examples of situations where logs are lost :

• on a shutdown hook of the JVM
• on the default uncaught exception handler
• on the EDT's exception handler
• on the windowClosing event of the main JFrame开发者_运维知识库 (configured with the default close operation EXIT_ON_CLOSE)

There is no other configuration than what is described above. The log level is not involved : I can see some INFO logs, but some of the lost logs are SEVERE.

I also tried to add a shutdown hook to flush all the Handlers, but with no success.

So, the question : is it safe to configure my logging the way I do ? Can you see any reason why some logs can be lost ?

---

I found the problem. And this is weird.

Actually, my problem is not related at all with the fact that the log happens in an exception handler or in a Frame event. The problem is that the garbage collector destroys the "fr.def" logger a few seconds after it is created ! Thus, the FileHandler is destroyed too. The GC can do it because the LogManager only keeps weak references to the Loggers it creates.

The javadoc of Logger.getLogger doesn't tell anything about that, but the javadoc of LogManager.addLogger, which is called by the former, explicitly says that :

The application should retain its own reference to the Logger object to avoid it being garbage collected. The LogManager may only retain a weak reference.

So, the workaround was to keep a reference to the object returned by Logger.getLogger("fr.def").

Edit

It seems that the choice of using weak references came from this bug report.

---

If you dig into LogManager source, you'll see it installs its own shutdown hook LogManager.Cleaner that closes all logger handlers.

Since all shutdown hooks run concurrently there is a race between your hook and one registered by logging. If logging finishes first you will get no output.

There is no clean way around that. If you don't want to change your source, you could hack some sort of non-portable pre-shutdown hook like this: https://gist.github.com/735322

Alternatively use Logger.getAnonymousLogger() which is not registered with LogManager thus not closed in shutdown hook. You will have to add your own handlers and call Logger#setUseParentHandlers(false) to avoid duplicated messages.