Deadlock between FileHandler and ConsoleHandler when using customized formatter
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.z... 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
On 11/28/2013 08:53 AM, Shi Jun Zhang wrote:
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.
Hello Shi Jun Zhang, Why do you use Logger.log in the CustomerFormatter? What are you achieving by it? Do you want to re-route and re-format messages destined for one handler to some other Logger and consequently handler? On 11/28/2013 08:53 AM, Shi Jun Zhang wrote:
This violates the Java doc for java.util.logging.Logger that says "All methods on Logger are multi-thread safe."
I don't know for sure, but I think that "multi-thread-safe" does not imply "dead-lock-safe". It would be good if java logging used less locks and be less deadlock-prone though. So we should see if it is possible to remove some locks, not to add more locking... Regards, Peter
Hi Shi Jun Zhang, I agree with Peter. It is strange that CustomFormatter calls Logger.log. This looks like the source of the deadlock. The Logger API can be customized in many ways - and when you can plugin custom classes and objects you can introduce new opportunity for deadlocks. Concerning the Javadoc - I don't know whether that could be satisfactorily improved. In JDK 8, we have a new annotation, @implNote - which can give non normative hints on what the implementation does under the hood. I am not sure whether documenting the locking mechanism that j.u.l uses behind the scenes would be appropriate - or even feasible. I am afraid that trying to describe every lock that is involved in every possible case along every possible code path would be hard to achieve. I believe the fact that Handler.publish() is usually synchronized is kind of natural: by which I mean that I would naively expect it, given that you wouldn't want one message to overlap with the next. Maybe that could be documented. best regards, -- daniel On 11/28/13 1:13 PM, Peter Levart wrote:
On 11/28/2013 08:53 AM, Shi Jun Zhang wrote:
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.
Hello Shi Jun Zhang,
Why do you use Logger.log in the CustomerFormatter? What are you achieving by it? Do you want to re-route and re-format messages destined for one handler to some other Logger and consequently handler?
On 11/28/2013 08:53 AM, Shi Jun Zhang wrote:
This violates the Java doc for java.util.logging.Logger that says "All methods on Logger are multi-thread safe."
I don't know for sure, but I think that "multi-thread-safe" does not imply "dead-lock-safe". It would be good if java logging used less locks and be less deadlock-prone though. So we should see if it is possible to remove some locks, not to add more locking...
Regards, Peter
On 11/29/2013 1:21 AM, Daniel Fuchs wrote:
Hi Shi Jun Zhang,
I agree with Peter. It is strange that CustomFormatter calls Logger.log. This looks like the source of the deadlock.
Hi Daniel, I explained why we call Logger.log in CustomerFormatter in another mail replied to Peter, CustomerFormatter is complicated and we add some debug logging info in it. When we enable the debug level in logging, the deadlock happens. This is the source of the deadlock.
The Logger API can be customized in many ways - and when you can plugin custom classes and objects you can introduce new opportunity for deadlocks.
In my understanding, usually we should not get deadlock between 2 locks in JDK if we don't violate any Java spec or Java API doc.
Concerning the Javadoc - I don't know whether that could be satisfactorily improved. In JDK 8, we have a new annotation, @implNote - which can give non normative hints on what the implementation does under the hood. I am not sure whether documenting the locking mechanism that j.u.l uses behind the scenes would be appropriate - or even feasible. I am afraid that trying to describe every lock that is involved in every possible case along every possible code path would be hard to achieve.
I think it would be useful to document the locking mechanism with @implNote annotation. However, this problem also happens in OpenJDK 7, and even Oracle JDK 6.
I believe the fact that Handler.publish() is usually synchronized is kind of natural: by which I mean that I would naively expect it, given that you wouldn't want one message to overlap with the next. Maybe that could be documented.
best regards,
-- daniel
On 11/28/13 1:13 PM, Peter Levart wrote:
On 11/28/2013 08:53 AM, Shi Jun Zhang wrote:
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.
Hello Shi Jun Zhang,
Why do you use Logger.log in the CustomerFormatter? What are you achieving by it? Do you want to re-route and re-format messages destined for one handler to some other Logger and consequently handler?
On 11/28/2013 08:53 AM, Shi Jun Zhang wrote:
This violates the Java doc for java.util.logging.Logger that says "All methods on Logger are multi-thread safe."
I don't know for sure, but I think that "multi-thread-safe" does not imply "dead-lock-safe". It would be good if java logging used less locks and be less deadlock-prone though. So we should see if it is possible to remove some locks, not to add more locking...
Regards, Peter
-- Regards, Shi Jun Zhang
On 11/29/13 7:19 AM, Shi Jun Zhang wrote:
On 11/29/2013 1:21 AM, Daniel Fuchs wrote:
Hi Shi Jun Zhang,
I agree with Peter. It is strange that CustomFormatter calls Logger.log. This looks like the source of the deadlock.
Hi Daniel,
I explained why we call Logger.log in CustomerFormatter in another mail replied to Peter, CustomerFormatter is complicated and we add some debug logging info in it. When we enable the debug level in logging, the deadlock happens. This is the source of the deadlock. Hi Shi Jun Zhang,
Since CustomFormatter returns a message string that will be printed in the log, would it be possible for you to add the debug information in that string (for instance at the end of the string - or at the beginning) rather than calling Logger.log from within CustomFormatter, (and hence from within Handler.publish)? best regards, -- daniel
The Logger API can be customized in many ways - and when you can plugin custom classes and objects you can introduce new opportunity for deadlocks.
In my understanding, usually we should not get deadlock between 2 locks in JDK if we don't violate any Java spec or Java API doc.
Concerning the Javadoc - I don't know whether that could be satisfactorily improved. In JDK 8, we have a new annotation, @implNote - which can give non normative hints on what the implementation does under the hood. I am not sure whether documenting the locking mechanism that j.u.l uses behind the scenes would be appropriate - or even feasible. I am afraid that trying to describe every lock that is involved in every possible case along every possible code path would be hard to achieve.
I think it would be useful to document the locking mechanism with @implNote annotation. However, this problem also happens in OpenJDK 7, and even Oracle JDK 6.
I believe the fact that Handler.publish() is usually synchronized is kind of natural: by which I mean that I would naively expect it, given that you wouldn't want one message to overlap with the next. Maybe that could be documented.
best regards,
-- daniel
On 11/28/13 1:13 PM, Peter Levart wrote:
On 11/28/2013 08:53 AM, Shi Jun Zhang wrote:
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.
Hello Shi Jun Zhang,
Why do you use Logger.log in the CustomerFormatter? What are you achieving by it? Do you want to re-route and re-format messages destined for one handler to some other Logger and consequently handler?
On 11/28/2013 08:53 AM, Shi Jun Zhang wrote:
This violates the Java doc for java.util.logging.Logger that says "All methods on Logger are multi-thread safe."
I don't know for sure, but I think that "multi-thread-safe" does not imply "dead-lock-safe". It would be good if java logging used less locks and be less deadlock-prone though. So we should see if it is possible to remove some locks, not to add more locking...
Regards, Peter
On 11/29/2013 5:25 PM, Daniel Fuchs wrote:
On 11/29/13 7:19 AM, Shi Jun Zhang wrote:
On 11/29/2013 1:21 AM, Daniel Fuchs wrote:
Hi Shi Jun Zhang,
I agree with Peter. It is strange that CustomFormatter calls Logger.log. This looks like the source of the deadlock.
Hi Daniel,
I explained why we call Logger.log in CustomerFormatter in another mail replied to Peter, CustomerFormatter is complicated and we add some debug logging info in it. When we enable the debug level in logging, the deadlock happens. This is the source of the deadlock. Hi Shi Jun Zhang,
Since CustomFormatter returns a message string that will be printed in the log, would it be possible for you to add the debug information in that string (for instance at the end of the string - or at the beginning) rather than calling Logger.log from within CustomFormatter, (and hence from within Handler.publish)?
best regards,
-- daniel
Hi Daniel, Yes, this would be another workaround and we already have several workarounds. We'd like to see whether this problem could be solved in JDK level but not in application, or add some Java spec/doc indicating the usage like this could cause possible deadlock. -- Regards, Shi Jun Zhang
The Logger API can be customized in many ways - and when you can plugin custom classes and objects you can introduce new opportunity for deadlocks.
In my understanding, usually we should not get deadlock between 2 locks in JDK if we don't violate any Java spec or Java API doc.
Concerning the Javadoc - I don't know whether that could be satisfactorily improved. In JDK 8, we have a new annotation, @implNote - which can give non normative hints on what the implementation does under the hood. I am not sure whether documenting the locking mechanism that j.u.l uses behind the scenes would be appropriate - or even feasible. I am afraid that trying to describe every lock that is involved in every possible case along every possible code path would be hard to achieve.
I think it would be useful to document the locking mechanism with @implNote annotation. However, this problem also happens in OpenJDK 7, and even Oracle JDK 6.
I believe the fact that Handler.publish() is usually synchronized is kind of natural: by which I mean that I would naively expect it, given that you wouldn't want one message to overlap with the next. Maybe that could be documented.
best regards,
-- daniel
On 11/28/13 1:13 PM, Peter Levart wrote:
On 11/28/2013 08:53 AM, Shi Jun Zhang wrote:
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.
Hello Shi Jun Zhang,
Why do you use Logger.log in the CustomerFormatter? What are you achieving by it? Do you want to re-route and re-format messages destined for one handler to some other Logger and consequently handler?
On 11/28/2013 08:53 AM, Shi Jun Zhang wrote:
This violates the Java doc for java.util.logging.Logger that says "All methods on Logger are multi-thread safe."
I don't know for sure, but I think that "multi-thread-safe" does not imply "dead-lock-safe". It would be good if java logging used less locks and be less deadlock-prone though. So we should see if it is possible to remove some locks, not to add more locking...
Regards, Peter
On 11/29/13 10:49 AM, Shi Jun Zhang wrote:
On 11/29/2013 5:25 PM, Daniel Fuchs wrote:
On 11/29/13 7:19 AM, Shi Jun Zhang wrote:
On 11/29/2013 1:21 AM, Daniel Fuchs wrote:
Hi Shi Jun Zhang,
I agree with Peter. It is strange that CustomFormatter calls Logger.log. This looks like the source of the deadlock.
Hi Daniel,
I explained why we call Logger.log in CustomerFormatter in another mail replied to Peter, CustomerFormatter is complicated and we add some debug logging info in it. When we enable the debug level in logging, the deadlock happens. This is the source of the deadlock. Hi Shi Jun Zhang,
Since CustomFormatter returns a message string that will be printed in the log, would it be possible for you to add the debug information in that string (for instance at the end of the string - or at the beginning) rather than calling Logger.log from within CustomFormatter, (and hence from within Handler.publish)?
best regards,
-- daniel
Hi Daniel,
Yes, this would be another workaround and we already have several workarounds. We'd like to see whether this problem could be solved in JDK level but not in application, or add some Java spec/doc indicating the usage like this could cause possible deadlock.
I'll have a look at what happens in Handler.publish (and subclasses) but I wouldn't put too much hope into that. As seen from the traces, the CustomFormatter, by calling Logger.log, is causing the lock inversion which is at the root of the deadlock. To fix that deadlock, the formatter would need to be called from outside the handler lock. However, removing or just moving the lock around might well introduce new unknown issues - so it will need to be carefully anaIyzed, and I am not sure it can/should be attempted in a minor JDK release. best regards -- daniel
On 29/11/2013 10:08, Daniel Fuchs wrote:
However, removing or just moving the lock around might well introduce new unknown issues - so it will need to be carefully anaIyzed, and I am not sure it can/should be attempted in a minor JDK release.
Yes, we have to be very careful as the logging code has a history of biting the hand of those that try to improve it. For various reasons, it seems there is a lot of code that has subtle dependencies on the implementation, on the initialization in particular. In any case, you are to be applauded for tackling the synchronization issues and it would be a good project to re-examine all of this in JDK 9 to see how it would be simplified. On documenting the locking details in an @implNote (which seems to be one of the suggestions here) then we also need to be careful as I think we need some flexibility to change some of this going forward. -Alan
On 11/29/13 4:56 PM, Alan Bateman wrote:
On 29/11/2013 10:08, Daniel Fuchs wrote:
However, removing or just moving the lock around might well introduce new unknown issues - so it will need to be carefully anaIyzed, and I am not sure it can/should be attempted in a minor JDK release.
Yes, we have to be very careful as the logging code has a history of biting the hand of those that try to improve it. For various reasons, it seems there is a lot of code that has subtle dependencies on the implementation, on the initialization in particular. In any case, you are to be applauded for tackling the synchronization issues and it would be a good project to re-examine all of this in JDK 9 to see how it would be simplified.
On documenting the locking details in an @implNote (which seems to be one of the suggestions here) then we also need to be careful as I think we need some flexibility to change some of this going forward.
Yes - that's a two edged sword indeed. We certainly don't want to set that in stone... On the other hand I empathizes with developers who struggle to find out what they can - and can't do - when extending j.u.l APIs... Anyway, if usage of the 'synchronized' keyword never appears in the Javadoc I guess that's for good reasons... Thanks Alan, -- daniel
-Alan
On 11/30/2013 12:05 AM, Daniel Fuchs wrote:
On 11/29/13 4:56 PM, Alan Bateman wrote:
On 29/11/2013 10:08, Daniel Fuchs wrote:
However, removing or just moving the lock around might well introduce new unknown issues - so it will need to be carefully anaIyzed, and I am not sure it can/should be attempted in a minor JDK release.
Yes, we have to be very careful as the logging code has a history of biting the hand of those that try to improve it. For various reasons, it seems there is a lot of code that has subtle dependencies on the implementation, on the initialization in particular. In any case, you are to be applauded for tackling the synchronization issues and it would be a good project to re-examine all of this in JDK 9 to see how it would be simplified.
On documenting the locking details in an @implNote (which seems to be one of the suggestions here) then we also need to be careful as I think we need some flexibility to change some of this going forward.
Yes - that's a two edged sword indeed. We certainly don't want to set that in stone... On the other hand I empathizes with developers who struggle to find out what they can - and can't do - when extending j.u.l APIs...
Anyway, if usage of the 'synchronized' keyword never appears in the Javadoc I guess that's for good reasons...
Thanks Alan,
-- daniel
-Alan
Hi Daniel, This thread is silent for several days, do you have any finding in Handler.publish? -- Regards, Shi Jun Zhang
On 12/05/2013 07:54 AM, Shi Jun Zhang wrote:
On 11/30/2013 12:05 AM, Daniel Fuchs wrote:
On 11/29/13 4:56 PM, Alan Bateman wrote:
On 29/11/2013 10:08, Daniel Fuchs wrote:
However, removing or just moving the lock around might well introduce new unknown issues - so it will need to be carefully anaIyzed, and I am not sure it can/should be attempted in a minor JDK release.
Yes, we have to be very careful as the logging code has a history of biting the hand of those that try to improve it. For various reasons, it seems there is a lot of code that has subtle dependencies on the implementation, on the initialization in particular. In any case, you are to be applauded for tackling the synchronization issues and it would be a good project to re-examine all of this in JDK 9 to see how it would be simplified.
On documenting the locking details in an @implNote (which seems to be one of the suggestions here) then we also need to be careful as I think we need some flexibility to change some of this going forward.
Yes - that's a two edged sword indeed. We certainly don't want to set that in stone... On the other hand I empathizes with developers who struggle to find out what they can - and can't do - when extending j.u.l APIs...
Anyway, if usage of the 'synchronized' keyword never appears in the Javadoc I guess that's for good reasons...
Thanks Alan,
-- daniel
-Alan
Hi Daniel,
This thread is silent for several days, do you have any finding in Handler.publish?
Hi Shi Jun Zhang, I have looked at this, creating a prototype. It re-arranged synchronization in a way so that all Formatter methods are invoked out of synchronized sections. I haven't come forward with this yet, because of two issues: - Formatter implementations would suddenly be called multi-threaded. Currently they are invoked from within Handler-instance synchronized sections. - Formatter would have to be invoked optimistically to obtain head and tail strings, so it could happen that a head, for example, would be requested concurrently multiple times, but only one of returned heads would be written to stream then. The 1st thing seems problematic. I can imagine there exist Formatters that are not thread-safe (for example, using single instance of MessageFormat, which is not multi-threaded) and now just happen to work as a consequence of current StreamHandler implementation detail, but would break if called multi-threaded. One way to remedy this is to add a boolean property to Formatter API, say Formatter.isMultiThreaded(), and arrange so that appropriate instances return appropriate values also considering backwards-compatibility... So all-in-all this is not a simple patch and I doubt it can be made for JDK8. In JDK9, I think, it will be possible to re-visit this issue, so It would be good to file it as a BUG or RFI. Regards, Peter
Shi Jun Zhang, This problem is like hooking up your sink drain to your sink faucet. Even if it you can get it to work you still would not want to use it. In your code example you could just pre-pend the thread name to the formatter string and return it. However, if you really, really, really, want to attempt this type of trick you have to use JDK8 and create a custom Filter to generate log records. If you use a filter, you can ditch the thread local in favor of checking the source class of the log record to determine the proper action. Or if you are using a JDK prior to JDK8 then install the filter on the logger instead of the handler to avoid the locking. Peter, Daniel, An optimistic tail string would break all formatters that write out summary statistics (num of records, min millis, and max mills). Instead of changing the formatter synchronization, I think a more useful solution would be to create an AsyncHandler that would disconnect user code from the act of publishing log records. Then all of handler and formatter locking fall rights into the nice biased locking scenario. Jason
Hi Shi Jun Zhang,
I have looked at this, creating a prototype. It re-arranged synchronization in a way so that all Formatter methods are invoked out of synchronized sections. I haven't come forward with this yet, because of two issues: - Formatter implementations would suddenly be called multi-threaded. Currently they are invoked from within Handler-instance synchronized sections. - Formatter would have to be invoked optimistically to obtain head and tail strings, so it could happen that a head, for example, would be requested concurrently multiple times, but only one of returned heads would be written to stream then.
The 1st thing seems problematic. I can imagine there exist Formatters that are not thread-safe (for example, using single instance of MessageFormat, which is not multi-threaded) and now just happen to work as a consequence of current StreamHandler implementation detail, but would break if called multi-threaded.
One way to remedy this is to add a boolean property to Formatter API, say Formatter.isMultiThreaded(), and arrange so that appropriate instances return appropriate values also considering backwards-compatibility...
So all-in-all this is not a simple patch and I doubt it can be made for JDK8. In JDK9, I think, it will be possible to re-visit this issue, so It would be good to file it as a BUG or RFI.
Regards, Peter
On 12/6/2013 12:53 AM, Jason Mehrens wrote:
Shi Jun Zhang,
This problem is like hooking up your sink drain to your sink faucet. Even if it you can get it to work you still would not want to use it. In your code example you could just pre-pend the thread name to the formatter string and return it.
Hi Jason, This would work and we already have several workarounds including this one.
However, if you really, really, really, want to attempt this type of trick you have to use JDK8 and create a custom Filter to generate log records. If you use a filter, you can ditch the thread local in favor of checking the source class of the log record to determine the proper action. Or if you are using a JDK prior to JDK8 then install the filter on the logger instead of the handler to avoid the locking.
I don't see how Filter can avoid the deadlock, Handler.isLoggable() is still called inside Handler.publish(). As long as we call Logger.log inside itself with 2 or more handlers in root logger, the deadlock would happen.
Peter, Daniel,
An optimistic tail string would break all formatters that write out summary statistics (num of records, min millis, and max mills). Instead of changing the formatter synchronization, I think a more useful solution would be to create an AsyncHandler that would disconnect user code from the act of publishing log records. Then all of handler and formatter locking fall rights into the nice biased locking scenario.
Peter, I think you are misunderstanding this problem. This deadlock is not related to the formatter synchronization, we can make CustomerFormatter.format not synchronized and not call super.format, the deadlock still happens.
Jason
Hi Shi Jun Zhang,
I have looked at this, creating a prototype. It re-arranged synchronization in a way so that all Formatter methods are invoked out of synchronized sections. I haven't come forward with this yet, because of two issues: - Formatter implementations would suddenly be called multi-threaded. Currently they are invoked from within Handler-instance synchronized sections. - Formatter would have to be invoked optimistically to obtain head and tail strings, so it could happen that a head, for example, would be requested concurrently multiple times, but only one of returned heads would be written to stream then.
The 1st thing seems problematic. I can imagine there exist Formatters that are not thread-safe (for example, using single instance of MessageFormat, which is not multi-threaded) and now just happen to work as a consequence of current StreamHandler implementation detail, but would break if called multi-threaded.
One way to remedy this is to add a boolean property to Formatter API, say Formatter.isMultiThreaded(), and arrange so that appropriate instances return appropriate values also considering backwards-compatibility...
So all-in-all this is not a simple patch and I doubt it can be made for JDK8. In JDK9, I think, it will be possible to re-visit this issue, so It would be good to file it as a BUG or RFI.
Regards, Peter
-- Regards, Shi Jun Zhang
On 12/09/2013 08:02 AM, Shi Jun Zhang wrote:
Peter,
I think you are misunderstanding this problem. This deadlock is not related to the formatter synchronization, we can make CustomerFormatter.format not synchronized and not call super.format, the deadlock still happens.
I'm not saying that your formatters are explicitly synchronized - all formatters are currently effectively synchronized by LogHandlers. The Formatter is invoked from within LogHandler's publish() method which is synchronized (on LogHandler.this). If formatters were invoked out of this synchronized section, there would be no danger of deadlocks when using Logger.log from within custom formatters. But then other issues would arise as a consequence of non-multithreaded formatters being invoked concurrently... Regards, Peter
On 12/09/2013 09:28 AM, Peter Levart wrote:
On 12/09/2013 08:02 AM, Shi Jun Zhang wrote:
Peter,
I think you are misunderstanding this problem. This deadlock is not related to the formatter synchronization, we can make CustomerFormatter.format not synchronized and not call super.format, the deadlock still happens.
I'm not saying that your formatters are explicitly synchronized - all formatters are currently effectively synchronized by LogHandlers. The Formatter is invoked from within LogHandler's publish() method which is synchronized (on LogHandler.this). If formatters were invoked out of this synchronized section, there would be no danger of deadlocks when using Logger.log from within custom formatters. But then other issues would arise as a consequence of non-multithreaded formatters being invoked concurrently...
Regards, Peter
I think the best solution to your problem (or a work-around if you say so) was suggested by Jason Mehrens few messages ago - decoupling of user code from publishing of log records - by creating an AsyncLogHandler that is just feeding a FIFO queue with log records which are processed by a background thread by pop-ing them out of queue and sticking them in the actual LogHandler.publish(). If the queue is unbouded or large enough so that it never fills up, there's no danger of dead-locks even if you invoke Logger.log from custom formatters in such background publishing thread. Regards, Peter
On 12/9/2013 4:40 PM, Peter Levart wrote:
On 12/09/2013 09:28 AM, Peter Levart wrote:
On 12/09/2013 08:02 AM, Shi Jun Zhang wrote:
Peter,
I think you are misunderstanding this problem. This deadlock is not related to the formatter synchronization, we can make CustomerFormatter.format not synchronized and not call super.format, the deadlock still happens.
I'm not saying that your formatters are explicitly synchronized - all formatters are currently effectively synchronized by LogHandlers. The Formatter is invoked from within LogHandler's publish() method which is synchronized (on LogHandler.this). If formatters were invoked out of this synchronized section, there would be no danger of deadlocks when using Logger.log from within custom formatters. But then other issues would arise as a consequence of non-multithreaded formatters being invoked concurrently...
Regards, Peter
I think the best solution to your problem (or a work-around if you say so) was suggested by Jason Mehrens few messages ago - decoupling of user code from publishing of log records - by creating an AsyncLogHandler that is just feeding a FIFO queue with log records which are processed by a background thread by pop-ing them out of queue and sticking them in the actual LogHandler.publish(). If the queue is unbouded or large enough so that it never fills up, there's no danger of dead-locks even if you invoke Logger.log from custom formatters in such background publishing thread.
Regards, Peter
Hi Peter, Would the following situation happen if we use AsyncLogHandler? Some error happens and it causes the jvm crashes or System.exit() is called, however the related log record which contains important message is still in the queue and not printed. If so, I think it's unacceptable. -- Regards, Shi Jun Zhang
On 12/09/2013 10:50 AM, Shi Jun Zhang wrote:
On 12/9/2013 4:40 PM, Peter Levart wrote:
On 12/09/2013 09:28 AM, Peter Levart wrote:
On 12/09/2013 08:02 AM, Shi Jun Zhang wrote:
Peter,
I think you are misunderstanding this problem. This deadlock is not related to the formatter synchronization, we can make CustomerFormatter.format not synchronized and not call super.format, the deadlock still happens.
I'm not saying that your formatters are explicitly synchronized - all formatters are currently effectively synchronized by LogHandlers. The Formatter is invoked from within LogHandler's publish() method which is synchronized (on LogHandler.this). If formatters were invoked out of this synchronized section, there would be no danger of deadlocks when using Logger.log from within custom formatters. But then other issues would arise as a consequence of non-multithreaded formatters being invoked concurrently...
Regards, Peter
I think the best solution to your problem (or a work-around if you say so) was suggested by Jason Mehrens few messages ago - decoupling of user code from publishing of log records - by creating an AsyncLogHandler that is just feeding a FIFO queue with log records which are processed by a background thread by pop-ing them out of queue and sticking them in the actual LogHandler.publish(). If the queue is unbouded or large enough so that it never fills up, there's no danger of dead-locks even if you invoke Logger.log from custom formatters in such background publishing thread.
Regards, Peter
Hi Peter,
Would the following situation happen if we use AsyncLogHandler? Some error happens and it causes the jvm crashes or System.exit() is called, however the related log record which contains important message is still in the queue and not printed. If so, I think it's unacceptable.
You could install a shutdown-hook that would make sure the remaining queue is flushed before completing the VM exit... Regards, Peter
On 12/9/2013 8:04 PM, Peter Levart wrote:
On 12/09/2013 10:50 AM, Shi Jun Zhang wrote:
On 12/9/2013 4:40 PM, Peter Levart wrote:
On 12/09/2013 09:28 AM, Peter Levart wrote:
On 12/09/2013 08:02 AM, Shi Jun Zhang wrote:
Peter,
I think you are misunderstanding this problem. This deadlock is not related to the formatter synchronization, we can make CustomerFormatter.format not synchronized and not call super.format, the deadlock still happens.
I'm not saying that your formatters are explicitly synchronized - all formatters are currently effectively synchronized by LogHandlers. The Formatter is invoked from within LogHandler's publish() method which is synchronized (on LogHandler.this). If formatters were invoked out of this synchronized section, there would be no danger of deadlocks when using Logger.log from within custom formatters. But then other issues would arise as a consequence of non-multithreaded formatters being invoked concurrently...
Regards, Peter
I think the best solution to your problem (or a work-around if you say so) was suggested by Jason Mehrens few messages ago - decoupling of user code from publishing of log records - by creating an AsyncLogHandler that is just feeding a FIFO queue with log records which are processed by a background thread by pop-ing them out of queue and sticking them in the actual LogHandler.publish(). If the queue is unbouded or large enough so that it never fills up, there's no danger of dead-locks even if you invoke Logger.log from custom formatters in such background publishing thread.
Regards, Peter
Hi Peter,
Would the following situation happen if we use AsyncLogHandler? Some error happens and it causes the jvm crashes or System.exit() is called, however the related log record which contains important message is still in the queue and not printed. If so, I think it's unacceptable.
You could install a shutdown-hook that would make sure the remaining queue is flushed before completing the VM exit...
Regards, Peter
But shutdown hook will not be executed if VM crashes or exit abnormally. -- Regards, Shi Jun Zhang
On 12/9/2013 4:28 PM, Peter Levart wrote:
On 12/09/2013 08:02 AM, Shi Jun Zhang wrote:
Peter,
I think you are misunderstanding this problem. This deadlock is not related to the formatter synchronization, we can make CustomerFormatter.format not synchronized and not call super.format, the deadlock still happens.
I'm not saying that your formatters are explicitly synchronized - all formatters are currently effectively synchronized by LogHandlers. The Formatter is invoked from within LogHandler's publish() method which is synchronized (on LogHandler.this). If formatters were invoked out of this synchronized section, there would be no danger of deadlocks when using Logger.log from within custom formatters. But then other issues would arise as a consequence of non-multithreaded formatters being invoked concurrently...
Regards, Peter
Hi Peter, We have thought about moving formatter out of the synchronized section of Handler.publish(), it can avoid the deadlock. However, we can reproduce the similar deadlock by extending the Writer in Handler and using logger in the customized Writer. -- Regards, Shi Jun Zhang
On 12/09/2013 09:51 AM, Shi Jun Zhang wrote:
On 12/9/2013 4:28 PM, Peter Levart wrote:
On 12/09/2013 08:02 AM, Shi Jun Zhang wrote:
Peter,
I think you are misunderstanding this problem. This deadlock is not related to the formatter synchronization, we can make CustomerFormatter.format not synchronized and not call super.format, the deadlock still happens.
I'm not saying that your formatters are explicitly synchronized - all formatters are currently effectively synchronized by LogHandlers. The Formatter is invoked from within LogHandler's publish() method which is synchronized (on LogHandler.this). If formatters were invoked out of this synchronized section, there would be no danger of deadlocks when using Logger.log from within custom formatters. But then other issues would arise as a consequence of non-multithreaded formatters being invoked concurrently...
Regards, Peter
Hi Peter,
We have thought about moving formatter out of the synchronized section of Handler.publish(), it can avoid the deadlock. However, we can reproduce the similar deadlock by extending the Writer in Handler and using logger in the customized Writer.
That's right. And the remedy for that situation would also be what Jason Mehrens suggested - asynchronous publishing. Regards, Peter
On 12/9/13 9:58 AM, Peter Levart wrote:
On 12/09/2013 09:51 AM, Shi Jun Zhang wrote:
On 12/9/2013 4:28 PM, Peter Levart wrote:
On 12/09/2013 08:02 AM, Shi Jun Zhang wrote:
Peter,
I think you are misunderstanding this problem. This deadlock is not related to the formatter synchronization, we can make CustomerFormatter.format not synchronized and not call super.format, the deadlock still happens.
I'm not saying that your formatters are explicitly synchronized - all formatters are currently effectively synchronized by LogHandlers. The Formatter is invoked from within LogHandler's publish() method which is synchronized (on LogHandler.this). If formatters were invoked out of this synchronized section, there would be no danger of deadlocks when using Logger.log from within custom formatters. But then other issues would arise as a consequence of non-multithreaded formatters being invoked concurrently...
Regards, Peter
Hi Peter,
We have thought about moving formatter out of the synchronized section of Handler.publish(), it can avoid the deadlock. However, we can reproduce the similar deadlock by extending the Writer in Handler and using logger in the customized Writer.
That's right. And the remedy for that situation would also be what Jason Mehrens suggested - asynchronous publishing.
Hi, I agree with Peter & Jason - asynchronous publishing seems like a good solution. I believe the LogManager will close all handlers on exiting, so you might want to make sure that your asynchronous handler flushes the queue before quitting - which could still be tricky if flushing the queue produces new log messages for the queue - and also because you will want Handler.close() to wait until the queue is empty. Anyway - the best advice still is IMHO - don't call Logger.log while publishing a log message. This should save you from a lot of issues, like the one you encountered - but also possible stack overflows etc... best regards, -- daniel
Regards, Peter
On 12/09/2013 11:12 AM, Daniel Fuchs wrote:
On 12/9/13 9:58 AM, Peter Levart wrote:
On 12/09/2013 09:51 AM, Shi Jun Zhang wrote:
On 12/9/2013 4:28 PM, Peter Levart wrote:
On 12/09/2013 08:02 AM, Shi Jun Zhang wrote:
Peter,
I think you are misunderstanding this problem. This deadlock is not related to the formatter synchronization, we can make CustomerFormatter.format not synchronized and not call super.format, the deadlock still happens.
I'm not saying that your formatters are explicitly synchronized - all formatters are currently effectively synchronized by LogHandlers. The Formatter is invoked from within LogHandler's publish() method which is synchronized (on LogHandler.this). If formatters were invoked out of this synchronized section, there would be no danger of deadlocks when using Logger.log from within custom formatters. But then other issues would arise as a consequence of non-multithreaded formatters being invoked concurrently...
Regards, Peter
Hi Peter,
We have thought about moving formatter out of the synchronized section of Handler.publish(), it can avoid the deadlock. However, we can reproduce the similar deadlock by extending the Writer in Handler and using logger in the customized Writer.
That's right. And the remedy for that situation would also be what Jason Mehrens suggested - asynchronous publishing.
Hi,
I agree with Peter & Jason - asynchronous publishing seems like a good solution. I believe the LogManager will close all handlers on exiting, so you might want to make sure that your asynchronous handler flushes the queue before quitting - which could still be tricky if flushing the queue produces new log messages for the queue - and also because you will want Handler.close() to wait until the queue is empty.
You're right, Daniel. There already is a global shut-down hook installed in LogManager that close()s all active handlers when VM is shutting down. Shi Jun Zhang, here's a quick mock-up of a prototype AsyncHandler that might work for you: http://cr.openjdk.java.net/~plevart/misc/jul.AsyncHandler/AsyncHandler.java Regards, Peter
Anyway - the best advice still is IMHO - don't call Logger.log while publishing a log message. This should save you from a lot of issues, like the one you encountered - but also possible stack overflows etc...
best regards,
-- daniel
Regards, Peter
On 12/9/2013 10:01 PM, Peter Levart wrote:
On 12/09/2013 11:12 AM, Daniel Fuchs wrote:
On 12/9/13 9:58 AM, Peter Levart wrote:
On 12/09/2013 09:51 AM, Shi Jun Zhang wrote:
On 12/9/2013 4:28 PM, Peter Levart wrote:
On 12/09/2013 08:02 AM, Shi Jun Zhang wrote:
Peter,
I think you are misunderstanding this problem. This deadlock is not related to the formatter synchronization, we can make CustomerFormatter.format not synchronized and not call super.format, the deadlock still happens.
I'm not saying that your formatters are explicitly synchronized - all formatters are currently effectively synchronized by LogHandlers. The Formatter is invoked from within LogHandler's publish() method which is synchronized (on LogHandler.this). If formatters were invoked out of this synchronized section, there would be no danger of deadlocks when using Logger.log from within custom formatters. But then other issues would arise as a consequence of non-multithreaded formatters being invoked concurrently...
Regards, Peter
Hi Peter,
We have thought about moving formatter out of the synchronized section of Handler.publish(), it can avoid the deadlock. However, we can reproduce the similar deadlock by extending the Writer in Handler and using logger in the customized Writer.
That's right. And the remedy for that situation would also be what Jason Mehrens suggested - asynchronous publishing.
Hi,
I agree with Peter & Jason - asynchronous publishing seems like a good solution. I believe the LogManager will close all handlers on exiting, so you might want to make sure that your asynchronous handler flushes the queue before quitting - which could still be tricky if flushing the queue produces new log messages for the queue - and also because you will want Handler.close() to wait until the queue is empty.
You're right, Daniel. There already is a global shut-down hook installed in LogManager that close()s all active handlers when VM is shutting down.
Shi Jun Zhang, here's a quick mock-up of a prototype AsyncHandler that might work for you:
http://cr.openjdk.java.net/~plevart/misc/jul.AsyncHandler/AsyncHandler.java
Regards, Peter
Thanks Peter for your prototype. I would like to see this AsyncHandler to be added into Java 8 or 9. However we will not use this in our stable product as we already have several other low risk workarounds.
Anyway - the best advice still is IMHO - don't call Logger.log while publishing a log message. This should save you from a lot of issues, like the one you encountered - but also possible stack overflows etc...
Yes, I totally agree this, so I suggest documenting this and let other Java developers not face this problem again.
best regards,
-- daniel
Regards, Peter
-- Regards, Shi Jun Zhang
On 11/28/2013 8:13 PM, Peter Levart wrote:
On 11/28/2013 08:53 AM, Shi Jun Zhang wrote:
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.
Hello Shi Jun Zhang,
Why do you use Logger.log in the CustomerFormatter? What are you achieving by it? Do you want to re-route and re-format messages destined for one handler to some other Logger and consequently handler?
Hi Peter, This happens in a real complicated application and I simply the test case. There is some complicated logic in the CustomerFormatter and we add some debug log messages in CustomerFormatter.format() method. As CustomerFormatter.format() method is called in Logger.log, there would be an infinite recursion if we do nothing, then we have to add some check to break the recursion. The things we are doing here are 1) using CustomerFormatter as logger formatter and logging in an application. 2) logging some debug information in CustomerFormatter.
On 11/28/2013 08:53 AM, Shi Jun Zhang wrote:
This violates the Java doc for java.util.logging.Logger that says "All methods on Logger are multi-thread safe."
I don't know for sure, but I think that "multi-thread-safe" does not imply "dead-lock-safe". It would be good if java logging used less locks and be less deadlock-prone though. So we should see if it is possible to remove some locks, not to add more locking...
Regards, Peter
I agree that we need less locks in java logging, java logging is getting more complicated and getting more deadlock recently. -- Regards, Shi Jun Zhang
participants (5)
-
Alan Bateman
-
Daniel Fuchs
-
Jason Mehrens
-
Peter Levart
-
Shi Jun Zhang