(Another) Deadlock in LogManager

[Jeremy Manson]

I made some changes to it back in 2009 or so, and removed a bunch of
locking in favor of non-blocking data structures.  Coming back to it after
4 years, I'm a little bit taken aback at how much more complicated it has
become.  It took me a lot longer than it should have to figure out why any
particular method was acquiring a given lock, and I found the LogContext
API to have added quite a bit of complexity.

I'm not volunteering to do a redesign, though. :)

Jeremy


On Thu, Oct 31, 2013 at 11:08 AM, David M. Lloyd <david.lloyd at redhat.com>wrote:

> Anyone else beginning to get the sense that maybe some brainstorming for a
> more sweeping/complete change to log manager initialization is necessary?
>  I suspect that these deadlocks and init order bugs are just going to keep
> on coming, and every fix seems to add more complexity than the last.
>
>
> On 10/31/2013 12: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)
>>
>>
>
> --
> - DML
>