(Another) Deadlock in LogManager

[Daniel Fuchs]

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

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