Deadlock between FileHandler and ConsoleHandler when using customized formatter

[Daniel Fuchs]

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