Deadlock between FileHandler and ConsoleHandler when using customized formatter

[Daniel Fuchs]

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
>>>
>>
>
>