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

Reply via email to