Deadlock between FileHandler and ConsoleHandler when using customized formatter

[Shi Jun Zhang]

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