Log4j 2
  1. Log4j 2
  2. LOG4J2-738

RollingFileManager deadlock if async action thread fails to start

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0-rc1
    • Fix Version/s: 2.0.1
    • Component/s: Appenders
    • Labels:
      None
    • Environment:

      amazon linux

      Description

      The symptom we're seeing is a thread stuck trying to acquire the semaphore in RollingFileManager.rollover(). It looks like the RollingFileManager can fail to release the semaphore if there is an exception during thread start for the async path in the rollover() method.

      I think this is the relevant chunk of code:

                      if (success && descriptor.getAsynchronous() != null) {
                          LOGGER.debug("RollingFileManager executing async {}", descriptor.getAsynchronous());
                          thread = new Thread(new AsyncAction(descriptor.getAsynchronous(), this));
                          thread.start();
                      }
                      return true;
                  }
                  return false;
              } finally {
                  if (thread == null) {
                      semaphore.release();
                  }
              }
      

      So, if thread start fails (because of OOM), the 'thread' variable will be != null and so the semaphore won't be released.

        Activity

        Timothy Stack created issue -
        Gary Gregory made changes -
        Field Original Value New Value
        Description The symptom we're seeing is a thread stuck trying to acquire the semaphore in RollingFileManager.rollover(). It looks like the RollingFileManager can fail to release the semaphore if there is an exception during thread start for the async path in the rollover() method.

        I think this is the relevant chunk of code:

                        if (success && descriptor.getAsynchronous() != null) {
                            LOGGER.debug("RollingFileManager executing async {}", descriptor.getAsynchronous());
                            thread = new Thread(new AsyncAction(descriptor.getAsynchronous(), this));
                            thread.start();
                        }
                        return true;
                    }
                    return false;
                } finally {
                    if (thread == null) {
                        semaphore.release();
                    }
                }

        So, if thread start fails (because of OOM), the 'thread' variable will be != null and so the semaphore won't be released.
        The symptom we're seeing is a thread stuck trying to acquire the semaphore in RollingFileManager.rollover(). It looks like the RollingFileManager can fail to release the semaphore if there is an exception during thread start for the async path in the rollover() method.

        I think this is the relevant chunk of code:
        {code:java}
                        if (success && descriptor.getAsynchronous() != null) {
                            LOGGER.debug("RollingFileManager executing async {}", descriptor.getAsynchronous());
                            thread = new Thread(new AsyncAction(descriptor.getAsynchronous(), this));
                            thread.start();
                        }
                        return true;
                    }
                    return false;
                } finally {
                    if (thread == null) {
                        semaphore.release();
                    }
                }
        {code}
        So, if thread start fails (because of OOM), the 'thread' variable will be != null and so the semaphore won't be released.
        Hide
        Gary Gregory added a comment -

        Can you test this on your set up:

                    if (thread == null || !thread.isAlive()) {
                        semaphore.release();
                    }
        
        Show
        Gary Gregory added a comment - Can you test this on your set up: if (thread == null || !thread.isAlive()) { semaphore.release(); }
        Hide
        Gary Gregory added a comment -
        commit -m "[LOG4J2-738] RollingFileManager deadlock if async action thread fails to start." C:/vcs/svn/apache/log4j2/trunk-alt/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java C:/vcs/svn/apache/log4j2/trunk-alt/src/changes/changes.xml
            Sending        C:/vcs/svn/apache/log4j2/trunk-alt/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java
            Sending        C:/vcs/svn/apache/log4j2/trunk-alt/src/changes/changes.xml
            Transmitting file data ...
            Committed revision 1613171.
        

        Please verify, comment, and resolve or close as appropriate.

        Thank you!
        Gary

        Show
        Gary Gregory added a comment - commit -m "[LOG4J2-738] RollingFileManager deadlock if async action thread fails to start." C:/vcs/svn/apache/log4j2/trunk-alt/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java C:/vcs/svn/apache/log4j2/trunk-alt/src/changes/changes.xml Sending C:/vcs/svn/apache/log4j2/trunk-alt/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java Sending C:/vcs/svn/apache/log4j2/trunk-alt/src/changes/changes.xml Transmitting file data ... Committed revision 1613171. Please verify, comment, and resolve or close as appropriate. Thank you! Gary
        Gary Gregory made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Fix Version/s 2.0.1 [ 12327381 ]
        Resolution Fixed [ 1 ]
        Hide
        Timothy Stack added a comment -

        Sorry, it's a hard bug to reproduce, but we think the fix is working, thanks!

        Show
        Timothy Stack added a comment - Sorry, it's a hard bug to reproduce, but we think the fix is working, thanks!
        Timothy Stack made changes -
        Status Resolved [ 5 ] Closed [ 6 ]
        Transition Time In Source Status Execution Times Last Executer Last Execution Date
        Open Open Resolved Resolved
        20h 20m 1 Gary Gregory 24/Jul/14 17:01
        Resolved Resolved Closed Closed
        7h 19m 1 Timothy Stack 25/Jul/14 00:20

          People

          • Assignee:
            Unassigned
            Reporter:
            Timothy Stack
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development