[
https://issues.apache.org/jira/browse/LOG4J2-1182?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16872143#comment-16872143
]
Kostiantyn Shchepanovskyi edited comment on LOG4J2-1182 at 6/25/19 8:13 AM:
----------------------------------------------------------------------------
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.
Steps to reproduce:
# 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}
was (Author: kshchepanovskyi):
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.
Steps to reproduce:
# 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)
