[LOG4J2-1798] InterruptedException on RollingFileManager#rollover()

• Type: Bug
• Status: Resolved
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: 2.7
• Fix Version/s: 2.15.0
• Component/s: Appenders

Environment

Java JDK 1.8 Update 73,
on Windows Server 2008 R2 Standard Service Pack 1

• Assignee: Ralph Goers
• Reporter: Danilo Härtzer
• Created: 24/Jan/17 11:06
• Updated: 05/Dec/21 20:54
• Resolved: 05/Dec/21 20:54

Description

We configured RollingFile-Appenders in the following way (3 different log files for the same log output but with different log levels, rolling each hour):

property.patternLayout=%d [%-5level] [%t] %X %c{1.} - %m%ex%n

# Bildungsvorschriften für Logdateien
property.fileNamePrefix=./log/current-
property.fileNameSuffix=.log
property.filePatternPrefix=./log/%d{yyyy_MM_dd_HH}-
property.filePatternSuffix=.log


# Appenders
###########
appenders=all, info, error
appender.all.type=RollingFile
appender.all.name=all
appender.all.fileName=${fileNamePrefix}all${fileNameSuffix}
appender.all.filePattern=${filePatternPrefix}all${filePatternSuffix}
appender.all.layout.type=PatternLayout
appender.all.layout.pattern=${patternLayout}
appender.all.policies.type=Policies
appender.all.policies.time.type=TimeBasedTriggeringPolicy

appender.info.type=RollingFile
appender.info.name=info
appender.info.fileName=${fileNamePrefix}info${fileNameSuffix}
appender.info.filePattern=${filePatternPrefix}info${filePatternSuffix}
appender.info.layout.type=PatternLayout
appender.info.layout.pattern=${patternLayout}
appender.info.policies.type=Policies
appender.info.policies.time.type=TimeBasedTriggeringPolicy

appender.error.type=RollingFile
appender.error.name=error
appender.error.fileName=${fileNamePrefix}error${fileNameSuffix}
appender.error.filePattern=${filePatternPrefix}error${filePatternSuffix}
appender.error.layout.type=PatternLayout
appender.error.layout.pattern=${patternLayout}
appender.error.policies.type=Policies
appender.error.policies.time.type=TimeBasedTriggeringPolicy

Sometimes for a certain log file the rollover does not work, throwing this exception cause:

2017-01-22 17:06:23,942 Con1 ERROR RollingFileManager ./log/current-error.log Thread interrupted while attempting to check rollover: java.lang.InterruptedException java.lang.InterruptedException
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1302)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at java.util.concurrent.Semaphore.acquire(Semaphore.java:312)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.rollover(RollingFileManager.java:247)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.rollover(RollingFileManager.java:192)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.checkRollover(RollingFileManager.java:175)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at org.apache.logging.log4j.core.appender.RollingFileAppender.append(RollingFileAppender.java:280)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:447)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:432)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:416)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:402)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2091)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1971)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1829)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at org.apache.logging.log4j.jcl.Log4jLog.error(Log4jLog.java:116)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at net.wimpi.telnetd.io.TelnetIO.closeOutput(TelnetIO.java:321)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at net.wimpi.telnetd.io.TerminalIO.close(TerminalIO.java:769)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at net.wimpi.telnetd.net.Connection.close(Connection.java:220)
INFO   | jvm 1    | 2017/01/22 17:06:23 | 	at net.wimpi.telnetd.net.Connection.run(Connection.java:143)

If this happens, it happens again and again on every Rollover-action (if the next hour has been passed and the rollover action is starting again).
After this failure Log4J2 is still logging to the 'old' log file (in this case: ./log/current-error.log).

Issue Links

• is duplicated by: LOG4J2-1826 InterruptedException on RollingFileManager#rollover()