(Another) Deadlock in LogManager

[Jeremy Manson]

Hi Daniel.

Thanks for the attention.

The same thought about eliminating the locking on
drainLoggerRefQueueBounded occurred to me, so I took a quick look.
 drainLoggerRefQueueBounded calls ref.dispose(), which calls
node.context.removeLogger(), which is documented to require the LogManager
lock.  I don't fully understand the locking protocols, so maybe there is a
workaround, but that is the prima facie reason for it.

Jeremy


On Thu, Oct 31, 2013 at 11:25 AM, Daniel Fuchs <daniel.fuchs at oracle.com>wrote:

> Hi Jeremy,
>
> Thanks for reporting that.
> Actually I'm not quite sure that drainLoggerRefQueueBounded() needs to
> be synchronized on LogManager.
>
> I'll need to study that - but my gut feeling is that we might
> be able to get rid of that lock (possibly).
> I'll have to study the call chain to see whether there are other
> potential issues down the road.
>
> I have logged https://bugs.openjdk.java.net/**browse/JDK-8027670<https://bugs.openjdk.java.net/browse/JDK-8027670>
>
> best regards,
>
> -- daniel
>
>
> On 10/31/13 6:43 PM, Jeremy Manson wrote:
>
>> Hi folks,
>>
>> This is against a slightly older version of LogManager, but the problem
>> still seems to be there at JDK8 head.  It seems as if the previous fixes
>> didn't go far enough?  See stack traces below.  Anyway, I don't see any
>> open bugs about it, so I'm reporting it.
>>
>> Two obvious fixes suggest themselves to me:
>>
>>   - Lock the LogManager when addLogger(Logger) calls cx.addLocalLogger().
>>   This avoids the lock ordering problem, but adds potential contention
>> overhead.
>>
>>   - Don't call drainLoggerRefQueueBounded() if you are reentrantly calling
>> addLogger().  You could do something as stupid as having a volatile
>> boolean
>> field "calledDrainRecently" that you set on entrance to addLogger and
>> unset
>> on exit (assuming you set it).
>>
>> The first is less sloppy, the second is less overhead.  There are probably
>> third and fourth and fifth options, too.
>>
>> Jeremy
>>
>> Thread 1:
>>      at
>> java.util.logging.LogManager.**drainLoggerRefQueueBounded(**
>> LogManager.java:816)
>>         - waiting to lock <0x1b260998> (a java.util.logging.LogManager)
>>         at java.util.logging.LogManager.**addLogger(LogManager.java:852)
>>         at java.util.logging.LogManager.**demandLogger(LogManager.java:**
>> 398)
>>         at
>> java.util.logging.LogManager$**LoggerContext.demandLogger(**
>> LogManager.java:478)
>>         at
>> java.util.logging.LogManager$**LoggerContext.**processParentHandlers(**
>> LogManager.java:604)
>>         at
>> java.util.logging.LogManager$**LoggerContext.addLocalLogger(**
>> LogManager.java:540)
>>         - locked <0x1b266518> (a java.util.logging.LogManager$**
>> LoggerContext)
>>         at java.util.logging.LogManager.**addLogger(LogManager.java:854)
>>         at java.util.logging.LogManager.**demandLogger(LogManager.java:**
>> 398)
>>         at java.util.logging.Logger.**demandLogger(Logger.java:352)
>>         at java.util.logging.Logger.**getLogger(Logger.java:399)
>>
>> Thread 2:
>> at
>> java.util.logging.LogManager$**LoggerContext.findLogger(**
>> LogManager.java:482)
>>         - waiting to lock <0x1b266518> (a
>> java.util.logging.LogManager$**LoggerContext)
>>         at
>> java.util.logging.LogManager.**setLevelsOnExistingLoggers(**
>> LogManager.java:1362)
>>         - locked <0x1b260998> (a java.util.logging.LogManager)
>>         at
>> java.util.logging.LogManager.**readConfiguration(LogManager.**java:1121)
>>
>>
>