title: Logging statement causes deadlock in simple Java code?
body: <p>I'm having a weird problem with some fairly simple Java code.</p>
  
  <p>I have a class <code>LicenseManager</code>, which controls the licensing of a program, and can be controlled dynamically (new licenses can be issued on demand, etc). <code>LicenseManager</code> 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.</p>
  
  <p>Just looking at the code of <code>LicenseManager</code> by itself, I can't see a single issue in it.</p>
  
  <pre><code>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();
          }
      }
  }
  </code></pre>
  
  <p>And when I run it:</p>
  
  <pre><code>$ 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
  </code></pre>
  
  <p>You'd expect the pie eaters to both die from running out of pies, but instead both threads deadlock.</p>
  
  <p>Interestingly, removing the logging line in <code>useApple</code> (<code>logger.info("Using apple. Apples left: " + apples);</code>) 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):</p>
  
  <pre><code>$ 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)
  </code></pre>
  
  <p>Why? How can I fix this without removing the logging?</p>