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
