Log4j 2
  1. Log4j 2
  2. LOG4J2-679

Log rotation partly failed with error: "Unable to create directory ..."

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Critical Critical
    • Resolution: Fixed
    • Affects Version/s: 2.0-rc1
    • Fix Version/s: 2.0.2
    • Component/s: Appenders
    • Labels:
      None
    • Environment:

      JDK 1.6, tomcat 6,

      Description

      Log rotation partly failed with error: "Unable to create directory ..."

      I am using the following configuration (simplified for the purpose of this ticket):

      <Configuration status="info" name="App1" monitorInterval="60">
        <Properties>
          <Property name="defaultLayout">[%t %d{EEE MMM dd HH:mm:ss z yyyy} &lt;%level{TRACE=6, DEBUG=5, INFO=4, WARN=3, ERROR=2, FATAL=1}&gt;] %m%n</Property>
          <Property name="patternCharset">UTF-8</Property>
          <Property name="logDir">/var/log/app1/</Property>
          <Property name="backupDir">/var/backups/app1/%d{yyyy}/%d{MM}/</Property>
        </Properties>
        <Appenders>
          <RollingRandomAccessFile name="A" fileName="${logDir}A.log" filePattern="${backupDir}A.log-%d{yyyyMMdd}">
            <PatternLayout pattern="${defaultLayout}" charset="${patternCharset}"/>
            <Policies>
              <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
            </Policies>
          </RollingRandomAccessFile>
          <RollingRandomAccessFile name="B" fileName="${logDir}B.log" filePattern="${backupDir}B.log-%d{yyyyMMdd}">
            <PatternLayout pattern="${defaultLayout}" charset="${patternCharset}"/>
            <Policies>
              <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
            </Policies>
          </RollingRandomAccessFile>
      
          <!-- ... additional appenders, only differing in appender-name/log-file-name, where removed for this ticket -->
      
          <RollingRandomAccessFile name="C" fileName="${logDir}Y.log" filePattern="${backupDir}Y.log-%d{yyyyMMdd}">
            <PatternLayout pattern="${defaultLayout}" charset="${patternCharset}"/>
            <Policies>
              <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
            </Policies>
          </RollingRandomAccessFile>
          <RollingRandomAccessFile name="D" fileName="${logDir}Z.log" filePattern="${backupDir}Z.log-%d{yyyyMMdd}">
            <PatternLayout pattern="${defaultLayout}" charset="${patternCharset}"/>
            <Policies>
              <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
            </Policies>
          </RollingRandomAccessFile>
        </Appenders>
        <Loggers>
          <Logger name="A" level="INFO" additivity="false">
            <AppenderRef ref="A"/>
          </Logger>
          <Logger name="B" level="INFO" additivity="false">
            <AppenderRef ref="B"/>
          </Logger>
      
          <!-- ... additional loggers, only differing in logger-name/appender-ref, where removed for this ticket -->
      
          <Logger name="C" level="INFO" additivity="false">
            <AppenderRef ref="C"/>
          </Logger>
          <Logger name="D" level="INFO" additivity="false">
            <AppenderRef ref="D"/>
          </Logger>
        </Loggers>
      </Configuration>
      

      As part of last nights log-rotation, sub-folders "/2014/06/" had to be created on top of the already existing "/var/backups/app1/" folder structure.
      During this log-rotation task, 2 out of ~20 files (all constantly written by the same application) where not rotated in the desired folder "/var/backups/app1/2014/06/" but are still actively used in the base folder. The only hint I could find regarding this issue was the following log output from log4j (matching the rotation time):

      2014-06-24 00:00:00,084 ERROR Unable to create directory /var/backups/app1/2014/06
      2014-06-24 00:00:00,084 ERROR Unable to create directory /var/backups/app1/2014/06

      Strangely all other log-file where correctly rotated to the identical destination directory.
      Until now i was not able to reproduce this behavior in my testing environment but i suspect that there might be an issue with handling multiple log-rotations in parallel for a "to be created" sub-directory.

        Activity

        Hide
        Rene Schoenlein added a comment - - edited

        I am pretty convinced now that this is a race condition in method "execute(final File source, final File destination, final boolean renameEmptyFiles)" of class "org.apache.logging.log4j.core.appender.rolling.action.FileRenameAction".
        My working assumption is, that during parent folder creation it can happen that more than one thread is trying to create the potential non-existing sub-folder structure at the same time.

        ("org.apache.logging.log4j.core.appender.rolling.action.FileRenameAction" RC-1):

        ...
        if (parent != null && !parent.exists()) { <-- parent.exists() might be false for multiple callers
          if (!parent.mkdirs()) { <-- one caller will succeed with TRUE, but for all other threads already past "!parent.exists()" the result will be "FALSE" even if the "to be created" folder structure exists now.
            LOGGER.error("Unable to create directory {}", parent.getAbsolutePath());
            return false;
          }
        }
        ...
        
        Show
        Rene Schoenlein added a comment - - edited I am pretty convinced now that this is a race condition in method "execute(final File source, final File destination, final boolean renameEmptyFiles)" of class "org.apache.logging.log4j.core.appender.rolling.action.FileRenameAction". My working assumption is, that during parent folder creation it can happen that more than one thread is trying to create the potential non-existing sub-folder structure at the same time. ("org.apache.logging.log4j.core.appender.rolling.action.FileRenameAction" RC-1): ... if (parent != null && !parent.exists()) { <-- parent.exists() might be false for multiple callers if (!parent.mkdirs()) { <-- one caller will succeed with TRUE, but for all other threads already past "!parent.exists()" the result will be "FALSE" even if the "to be created" folder structure exists now. LOGGER.error( "Unable to create directory {}" , parent.getAbsolutePath()); return false ; } } ...
        Hide
        Ralph Goers added a comment - - edited

        Unfortunately, File.mkdirs returns no information on why the directory creation failed. Even if we created a version using Java 7's Files.createDirectories method it doesn't look like that would help you since you are using Java 6.

        Your speculation that multiple threads are trying to create the same directory at once could be correct. It would be great to have a test that could prove that that is the case. But just looking at the code you highlighted it is pretty obvious that there is a race condition there.

        Show
        Ralph Goers added a comment - - edited Unfortunately, File.mkdirs returns no information on why the directory creation failed. Even if we created a version using Java 7's Files.createDirectories method it doesn't look like that would help you since you are using Java 6. Your speculation that multiple threads are trying to create the same directory at once could be correct. It would be great to have a test that could prove that that is the case. But just looking at the code you highlighted it is pretty obvious that there is a race condition there.
        Hide
        Remko Popma added a comment -

        How about, instead of looking at the return value of File.mkdirs(), we just check File.exists() again?

        ...
        if (parent != null && !parent.exists()) { <-- parent.exists() might be false for multiple callers
          // multiple threads may call this method, only one of them will get result TRUE, so ignore the result
          parent.mkdirs();
          
          // it doesn't matter if it was this thread's call to mkdirs that succeeded
          // or some other thread, as long as the directory exists, we're happy.
          if (!parent.exists()) {
            LOGGER.error("Unable to create directory {}", parent.getAbsolutePath());
            return false;
          }
        }
        
        Show
        Remko Popma added a comment - How about, instead of looking at the return value of File.mkdirs() , we just check File.exists() again? ... if (parent != null && !parent.exists()) { <-- parent.exists() might be false for multiple callers // multiple threads may call this method, only one of them will get result TRUE, so ignore the result parent.mkdirs(); // it doesn't matter if it was this thread's call to mkdirs that succeeded // or some other thread, as long as the directory exists, we're happy. if (!parent.exists()) { LOGGER.error( "Unable to create directory {}" , parent.getAbsolutePath()); return false ; } }
        Hide
        Rene Schoenlein added a comment -

        If my assumption is correct it should only makes the problem more unlikely. As far as i can tell, it will only fix the problem in cases where only one sub-folder-level needs to be created during log-rotation.

        Assumption: If at least two threads are trying to create a multi-level folder structure from scratch the failing thread will not always fail at the "leaf" of the folder structure but somewhere on the upper level. If this failing thread afterwards checks for File.exists() again, it will still fail if the other thread, also creating the same folder structure, is not finished with the creation yet.

        Show
        Rene Schoenlein added a comment - If my assumption is correct it should only makes the problem more unlikely. As far as i can tell, it will only fix the problem in cases where only one sub-folder-level needs to be created during log-rotation. Assumption: If at least two threads are trying to create a multi-level folder structure from scratch the failing thread will not always fail at the "leaf" of the folder structure but somewhere on the upper level. If this failing thread afterwards checks for File.exists() again, it will still fail if the other thread, also creating the same folder structure, is not finished with the creation yet.
        Hide
        Remko Popma added a comment -

        I think it should work. Based on the source code for File.mkdirs(), I cannot think of a scenario where mkdirs() will return false in the middle of creating a folder structure when the other thread is not finished with creating this same folder structure.

        // java.io.File
        public boolean mkdirs() {
            if (exists()) { return false; }
            if (mkdir()) { return true; }
        
            File canonFile = null;
            try {
                canonFile = getCanonicalFile();
            } catch (IOException e) {
                return false;
            }
            File parent = canonFile.getParentFile();
            return (parent != null && (parent.mkdirs() || parent.exists()) &&
                    canonFile.mkdir());
        }
        
        Show
        Remko Popma added a comment - I think it should work. Based on the source code for File.mkdirs() , I cannot think of a scenario where mkdirs() will return false in the middle of creating a folder structure when the other thread is not finished with creating this same folder structure. // java.io.File public boolean mkdirs() { if (exists()) { return false ; } if (mkdir()) { return true ; } File canonFile = null ; try { canonFile = getCanonicalFile(); } catch (IOException e) { return false ; } File parent = canonFile.getParentFile(); return (parent != null && (parent.mkdirs() || parent.exists()) && canonFile.mkdir()); }
        Hide
        Remko Popma added a comment -

        Fixed in revision 1617298.
        Please verify and close.

        Show
        Remko Popma added a comment - Fixed in revision 1617298. Please verify and close.

          People

          • Assignee:
            Remko Popma
            Reporter:
            Rene Schoenlein
          • Votes:
            1 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development