[Bug classpath/31664] New: Deadlock in java.util.Logger when logging to a logger and its parent

[timoore at redhat dot com]

On FC6 2.6.20-1.2944.fc6 i686 (Sorry, don't know the Classpath version),
there's a deadlock when logging to a logger and its parent from two threads.
>From looking at the source for Classpath .95 java.util.Logger.log(LogRecord), I
think this is what happens:

Thread 1: logs to the child logger
enters the synchronized Log method, gets lock on the child logger
synchronizes on LogManger.getLogManager() result
publishes logs to handlers,
gets parent, repeats, while still holding the lock on the LogManager.
Eventually,
this calls a synchronized method on the parent.

Thread2: logs to parent
synchronized log call
tries to get lock on LogManager... deadlocks.

Here's a test case.

import java.util.logging.Level;
import java.util.logging.Logger;
import java.util.logging.FileHandler;

public class LoggerDeadlock {
    static FileHandler fileHandler;
    static Logger fooLogger = Logger.getLogger("foo");
    static Logger procLogger = Logger.getLogger("foo.proc");
    static {
        try {
            fileHandler  = new FileHandler("/dev/null", 0, 1, true);
        }
        catch (java.io.IOException e) {
        }
        fooLogger.addHandler(fileHandler);
        fooLogger.setLevel(Level.ALL);
        procLogger.addHandler(fileHandler);
        procLogger.setLevel(Level.ALL);
    }
    class HeartBeat {
        long thread1Heartbeat;
        long thread2Heartbeat;
    }
    final HeartBeat heartBeat = new HeartBeat();
    class Thread1Runnable implements Runnable {
        public void run() {
            while (true) {
                fooLogger.log(Level.FINE, "Some message");
                synchronized (LoggerDeadlock.this) {
                    heartBeat.thread1Heartbeat++;
                }
            }
        }
    }

    class Thread2Runnable implements Runnable {
        public void run() {
            while (true) {
                procLogger.log(Level.FINE, "Some other message");
                synchronized (LoggerDeadlock.this) {
                    heartBeat.thread2Heartbeat++;
                }
            }
        }
    }

    public static void main(String[] args) {
        LoggerDeadlock deadBeef = new LoggerDeadlock();
        Thread thread1 = new Thread(deadBeef.new Thread1Runnable());
        Thread thread2 = new Thread(deadBeef.new Thread2Runnable());

        long val1 = 0;
        int thread1DeadCount = 0;
        long val2 = 0;
        int thread2DeadCount = 0;

        thread1.start();
        thread2.start();
        while (true) {
            synchronized (deadBeef) {
                if (val1 == deadBeef.heartBeat.thread1Heartbeat) {
                    thread1DeadCount++;
                } else {
                    val1 = 0;
                    deadBeef.heartBeat.thread1Heartbeat = 0;
                    thread1DeadCount = 0;
                }
                if (val2 == deadBeef.heartBeat.thread2Heartbeat) {
                    thread2DeadCount++;
                } else {
                    val2 = 0;
                    deadBeef.heartBeat.thread2Heartbeat = 0;
                    thread2DeadCount = 0;
                }
            }
            if (thread1DeadCount >= 10) {
                System.out.println("Thread1 has deadlocked.");
                break;

            } else if (thread2DeadCount >= 10) {
                System.out.println("Thread2 has deadlocked.");
                break;
            }
            try {
                Thread.sleep(1000);
            } catch (InterruptedException e) {
            }
        }
    }
}


-- 
           Summary: Deadlock in java.util.Logger when logging to a logger
                    and its parent
           Product: classpath
           Version: unspecified
            Status: UNCONFIRMED
          Severity: normal
          Priority: P3
         Component: classpath
        AssignedTo: unassigned at gcc dot gnu dot org
        ReportedBy: timoore at redhat dot com


http://gcc.gnu.org/bugzilla/show_bug.cgi?id=31664