[LOG4J2-679] Log rotation partly failed with error: "Unable to create directory ..."

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

Environment

JDK 1.6, tomcat 6,

• Assignee: Remko Popma
• Reporter: Rene Schoenlein
• Created: 24/Jun/14 13:50
• Updated: 11/Aug/14 14:38
• Resolved: 11/Aug/14 14:38

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.