Deadlock between FileHandler and ConsoleHandler when using customized formatter

[Shi Jun Zhang]

Hi,

We get a deadlock between java.util.logging.FileHandler and 
java.util.logging.ConsoleHandler when we are using a customized 
formatter in these handlers.

Here is the simple test case. 
http://cr.openjdk.java.net/~zhangshj/deadlockInHandlers/deadlockInHandlers.zip

Run "java -Djava.util.logging.config.file=logging.properties 
TestThread", it will hang immediately.

And this is the stack trace in dump file
"Thread-1":
     at java.util.logging.StreamHandler.publish(StreamHandler.java:205)
     - waiting to lock <0x00000000ec52e0c0> (a 
java.util.logging.ConsoleHandler)
     at java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:118)
     at java.util.logging.Logger.log(Logger.java:617)
     at java.util.logging.Logger.doLog(Logger.java:638)
     at java.util.logging.Logger.log(Logger.java:661)
     at java.util.logging.Logger.info(Logger.java:1289)
     at CustomerFormatter.format(CustomerFormatter.java:16)
     at java.util.logging.StreamHandler.publish(StreamHandler.java:210)
     - locked <0x00000000ec51ab90> (a java.util.logging.FileHandler)
     at java.util.logging.FileHandler.publish(FileHandler.java:614)
     - locked <0x00000000ec51ab90> (a java.util.logging.FileHandler)
     at java.util.logging.Logger.log(Logger.java:617)
     at java.util.logging.Logger.doLog(Logger.java:638)
     at java.util.logging.Logger.log(Logger.java:661)
     at java.util.logging.Logger.info(Logger.java:1289)
     at TestThread$1.run(TestThread.java:14)
     at java.lang.Thread.run(Thread.java:724)
"Thread-2":
     at java.util.logging.FileHandler.publish(FileHandler.java:611)
     - waiting to lock <0x00000000ec51ab90> (a 
java.util.logging.FileHandler)
     at java.util.logging.Logger.log(Logger.java:617)
     at java.util.logging.Logger.doLog(Logger.java:638)
     at java.util.logging.Logger.log(Logger.java:661)
     at java.util.logging.Logger.info(Logger.java:1289)
     at CustomerFormatter.format(CustomerFormatter.java:16)
     at java.util.logging.StreamHandler.publish(StreamHandler.java:210)
     - locked <0x00000000ec52e0c0> (a java.util.logging.ConsoleHandler)
     at java.util.logging.ConsoleHandler.publish(ConsoleHandler.java:118)
     at java.util.logging.Logger.log(Logger.java:617)
     at java.util.logging.Logger.doLog(Logger.java:638)
     at java.util.logging.Logger.log(Logger.java:661)
     at java.util.logging.Logger.info(Logger.java:1289)
     at TestThread$1.run(TestThread.java:14)
     at java.lang.Thread.run(Thread.java:724)

The problem is that we use a logger in CustomerFormatter and this causes 
Logger.log call Logger.log itself. As FileHandler.publish and 
StreamHandler.publish is synchronized, but the iteration to call publish 
method for all handlers in Logger.log is not synchronized, the deadlock 
happens.

This violates the Java doc for java.util.logging.Logger that says "All 
methods on Logger are multi-thread safe."

Currently we have 2 workarounds.
First is to add 2 lines in the logging.properties to force 
CustomerFormatter use new instance of FileHandler and ConsoleHandler 
like this,
CustomerFormatter.handlers = java.util.logging.FileHandler, 
java.util.logging.ConsoleHandler
CustomerFormatter.useParentHandlers = false

Second is to synchronize the logger.info call in TestThread test case.

I'm not sure whether we should fix this problem in JDK. The fix I can 
image is to synchronize each call to handler.publish() in Logger.log, 
but I think this would cause performance degradation.

Another solution is to add some documents in Java doc to state that 
Logger is not "so much" multi-thread safe.

Any suggestion or better fix?

-- 
Regards,

Shi Jun Zhang