[ https://issues.apache.org/jira/browse/LOG4J2-1182?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16872143#comment-16872143 ]
Kostiantyn Shchepanovskyi commented on LOG4J2-1182: --------------------------------------------------- Managed to reproduce this issue with log4j 2.11.1, in our case it happens on *"Too many open files"* error when creating new file: # Configure RollingRandomAccessFile: {code:java} <RollingRandomAccessFile name="file" fileName="server.log" filePattern="server-%d{yyyy-MM-dd'T'HH-mm-ss}.log.gz"> <PatternLayout> <pattern>%level{length=1} %date{MMdd-HHmm:ss,SSS} %logger{1.} %message %X %markerSimpleName [%thread]%n</pattern> </PatternLayout> <Policies> <OnStartupTriggeringPolicy/> <SizeBasedTriggeringPolicy size="1 MB"/> </Policies> <DefaultRolloverStrategy max="1000"/> </RollingRandomAccessFile>{code} # Start application, make it log and roll files every couple of minutes. # Dramatically decrease number of file descriptors process can have, by running: {code:java} sudo prlimit -p <pid> --nofile=20{code} # Wait until rollover happens multiple times. Observation: new text files are created, but not gzipped. # Restore process limits: {code:java} sudo prlimit -p <pid> --nofile=4096{code} # Wait for rollover to happen. After these steps, logs are not written to server.log anymore, instead, for each log event we receive exception to stdout: {code:java} Jun 22 11:55:45 dev-game-1 live-game-service: 2019-06-22 11:55:45,483 AsyncAppender-asyncFile ERROR Recovering from StringBuilderEncoder.encode('I 0622-1155:45,482 c.p.l.p.c.ConnectorImpl Channel /10.147.48.94:54622 write: Message{"service":"pt.live.internal.LobbySettingsService","action":"getLobbyTableSettingsResponse","type":"RESPONSE(2)","correlationId":306629,"dataFormat":"PR OTOBUF(1)","data":"<ByteString@40245ccb size=12831>"} {dispatchId=/10.147.48.94:54622, requested_action=getLobbyTableSettingsRequest, requested_service=pt.live.internal.LobbySettingsService} NIO [inio-2] Jun 22 11:55:45 dev-game-1 live-game-service: ') error: org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile /opt/local/live-game-service/log/server.log org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile /opt/local/live-game-service/log/server.log Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.writeToDestination(RollingRandomAccessFileManager.java:142) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.appender.OutputStreamManager.flushBuffer(OutputStreamManager.java:293) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.appender.OutputStreamManager.drain(OutputStreamManager.java:350) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.layout.ByteBufferDestinationHelper.writeToUnsynchronized(ByteBufferDestinationHelper.java:45) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.appender.OutputStreamManager.writeBytes(OutputStreamManager.java:360) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.layout.TextEncoderHelper.writeEncodedText(TextEncoderHelper.java:96) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.layout.TextEncoderHelper.encodeText(TextEncoderHelper.java:65) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:68) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:32) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:220) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:58) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:177) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:170) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:161) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:250) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.appender.AsyncAppender$AsyncThread.callAppenders(AsyncAppender.java:458) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.appender.AsyncAppender$AsyncThread.run(AsyncAppender.java:411) Jun 22 11:55:45 dev-game-1 live-game-service: Caused by: java.io.IOException: Stream Closed Jun 22 11:55:45 dev-game-1 live-game-service: at java.base/java.io.RandomAccessFile.writeBytes(Native Method) Jun 22 11:55:45 dev-game-1 live-game-service: at java.base/java.io.RandomAccessFile.write(RandomAccessFile.java:559) Jun 22 11:55:45 dev-game-1 live-game-service: at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.writeToDestination(RollingRandomAccessFileManager.java:138) Jun 22 11:55:45 dev-game-1 live-game-service: ... 20 more{code} > RandomAccessFile IOException: Stream Closed is back > --------------------------------------------------- > > Key: LOG4J2-1182 > URL: https://issues.apache.org/jira/browse/LOG4J2-1182 > Project: Log4j 2 > Issue Type: Bug > Components: Appenders > Affects Versions: 2.4.1 > Environment: Java 1.8.0_60-b27, OSX 10.11, Jackson 2.6.1, Maven 3.3.3 > Reporter: Ravi Gairola > Priority: Minor > Labels: Rollover > > This error pops up every now and then and looks very similar to LOG4J2-636: > {code:java} > 2015-10-27-23:00:00 2015-10-27 16:00:00,038 scribe-EventScribe ERROR Unable > to write to stream logs/server.log for appender AppLog > 2015-10-27-23:00:00 2015-10-27 16:00:00,038 scribe-EventScribe ERROR An > exception occurred processing Appender AppLog > org.apache.logging.log4j.core.appender.AppenderLoggingException: Error > writing to RandomAccessFile logs/server.log > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:132) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:112) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:136) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:105) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:98) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:152) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:125) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:116) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:378) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:362) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:384) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:379) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:362) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:352) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.Logger.logMessage(Logger.java:143) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1011) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:988) > 2015-10-27-23:00:00 at > org.apache.logging.slf4j.Log4jLogger.error(Log4jLogger.java:318) > 2015-10-27-23:00:00 at > com.nextbit.syncserver.common.EventScribe$Scribe.run(EventScribe.java:142) > 2015-10-27-23:00:00 Caused by: java.io.IOException: Stream Closed > 2015-10-27-23:00:00 at java.io.RandomAccessFile.writeBytes(Native Method) > 2015-10-27-23:00:00 at > java.io.RandomAccessFile.write(RandomAccessFile.java:525) > 2015-10-27-23:00:00 at > org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:129) > 2015-10-27-23:00:00 ... 21 more > {code} > Here's the respective yaml configuration: > {code} > configuration: > monitorInterval: 60 > status: WARN > name: Production Configuration > packages: com.our.packages > appenders: > appender: > - > type: Console > name: CONSOLE > PatternLayout: { pattern: '%d{yyyy-MMM-dd-HH:mm:ss.SSS} > [%p|%c{1}|%t|%X{rid}] %h: %m %n' } > - > type: RollingRandomAccessFile > name: AppLog > fileName: logs/server.log > filePattern: 'logs/server.log.%d{yyyy-MM-dd-HH}.gz' > append: true > PatternLayout: { pattern: '%d{yyyy-MMM-dd-HH:mm:ss.SSS} > [%p|%c{1}|%t|%X{rid}] %h: %m %n' } > TimeBasedTriggeringPolicy: { modulate: true } > DefaultRolloverStrategy: { max: 240 } > loggers: > - { name: com.amazonaws, level: warn } > - { name: org.hibernate, level: warn } > root: > level: info > AppenderRef: { ref: AppLog } > {code} -- This message was sent by Atlassian JIRA (v7.6.3#76005)