Logging statement causes deadlock in simple Java code?

Question

I'm having a weird problem with some fairly simple Java code.

I have a class LicenseManager, which controls the licensing of a program, and can be controlled dynamically (new licenses can be issued on demand, etc). LicenseManager of course needs to be thread safe, as such, it uses a big lock. However it has one more lock that it uses around controlling apples, which I believe is somehow involved in this deadlock, but I can't really see how. The program also installs a logging handler to support an enterprise logging feature.

Just looking at the code of LicenseManager by itself, I can't see a single issue in it.

import java.util.logging.*;

public class Main {
    public static final LicenseManager licenseManager = new LicenseManager();

    static class LicenseManager {
        private static final Logger logger =
                Logger.getLogger(LicenseManager.class.getName());

        class InsufficientApplesException extends RuntimeException {};
        class InsufficientPiesException extends RuntimeException {};

        private int apples = 10;
        private int pies = 10;
        private boolean enterpriseLoggingEnabled = true;

        // Apples have high contention; so they get their own lock.
        private final Object appleLock = new Object();

        void useApple() {
            checkExpired();
            synchronized (appleLock) {
                logger.info("Using apple. Apples left: " + apples);
                if (apples == 0) throw new InsufficientApplesException();
                apples--;
            }
        }

        /* Examples. There are lots of other operations like this
         * on LicenseManager. We don't have time to prove that
         * they are commutative, so we just use the main object lock
         * around them all. The exception is when we find one with high
         * contention, for example apples. */
        synchronized void usePear() {checkExpired(); /*...*/}
        synchronized void checkExpired() {}

        synchronized void usePie() {
            checkExpired();
            logger.info("Using pie. Pies left: " + pies);
            if (pies == 0) throw new InsufficientPiesException();
            boolean reallyCanUsePie = true; // do expensive pie computation
            if (reallyCanUsePie) {
                useApple(); /* using a pie requires an apple.
                             * TODO: stop putting apples in the pumpkin pie */
                pies--;
            }
        }

        synchronized boolean isEnterpriseLoggingEnabled() {
            return enterpriseLoggingEnabled;
        }
    }

    public static void main(String[] args) {
        // Install enterprise log handler on the root logger
        Logger.getLogger("").addHandler(new Handler() {
            @Override
            public void publish(LogRecord lr) {
                if (licenseManager.isEnterpriseLoggingEnabled())
                    System.out.println("ENTERPRISE ALERT! [" 
                            + lr.getLevel() + "] " + lr.getMessage());
            }
            @Override public void flush() {}
            @Override public void close() throws SecurityException {}
        });

        // Simulate fat user
        new Thread() {
            @Override
            public void run() {
                while (true) {
                    licenseManager.usePie();
                }
            }
        }.start();

        // Simulate fat albeit healthy user
        while (true) {
            licenseManager.useApple();
        }
    }
}

And when I run it:

$ java Main
Apr 25, 2013 3:23:19 PM Main$LicenseManager useApple
INFO: Using apple. Apples left: 10
Apr 25, 2013 3:23:19 PM Main$LicenseManager usePie
INFO: Using pie. Pies left: 10
ENTERPRISE ALERT! [INFO] Using pie. Pies left: 10

You'd expect the pie eaters to both die from running out of pies, but instead both threads deadlock.

Interestingly, removing the logging line in useApple (logger.info("Using apple. Apples left: " + apples);) makes the deadlock not happen (you don't see the log spammed with "using pie", because all the apples so happened to be gone before any pie could be used):

$ java Main
Exception in thread "main" Main$LicenseManager$InsufficientApplesException
    at Main$LicenseManager.useApple(Main.java:24)
    at Main.main(Main.java:79)
Apr 25, 2013 3:23:42 PM Main$LicenseManager usePie
INFO: Using pie. Pies left: 10
ENTERPRISE ALERT! [INFO] Using pie. Pies left: 10
Exception in thread "Thread-1" Main$LicenseManager$InsufficientApplesException
    at Main$LicenseManager.useApple(Main.java:24)
    at Main$LicenseManager.usePie(Main.java:43)
    at Main$2.run(Main.java:72)

Why? How can I fix this without removing the logging?

Answer 1

The problem is that your log.info() calls ends up in the Handler's publish() method where licenseManager.isEnterpriseLoggingEnabled() needs a lock on the licenseManager.

So this code can't complete:

   synchronized (appleLock) {
       //this line requires a lock on license manager, and this lock is not 
       //available because is hold by the other thread waiting to get the appleLock
       logger.info("Using apple. Apples left: " + apples);

       if (apples == 0) throw new InsufficientApplesException();
       apples--;
  }

One easy way to get rid of the deadlock is to remove the synchronization on isEnterpriseLoggingEnabled() method. It doesn't seem to be needed as enterpriseLoggingEnabled property is readonly.