[jira] [Created] (LOG4J2-636) IOException: Stream Closed RollingRandomAccessFile

Discussion:

Adrian Wilford (JIRA)

2014-05-14 12:49:14 UTC

Adrian Wilford created LOG4J2-636:
-------------------------------------

Summary: IOException: Stream Closed RollingRandomAccessFile
Key: LOG4J2-636
URL: https://issues.apache.org/jira/browse/LOG4J2-636
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-rc1
Environment: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
Reporter: Adrian Wilford

After some time, RollingRandomAccessFile can no longer write logging events.

2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more

--
This message was sent by Atlassian JIRA
(v6.2#6252)

Adrian Wilford (JIRA)

2014-05-14 12:53:14 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-636?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Adrian Wilford updated LOG4J2-636:
----------------------------------

Description:
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).

2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more

was:
After some time, RollingRandomAccessFile can no longer write logging events.

2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more

Post by Adrian Wilford (JIRA)
IOException: Stream Closed RollingRandomAccessFile
--------------------------------------------------
Key: LOG4J2-636
URL: https://issues.apache.org/jira/browse/LOG4J2-636
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-rc1
Environment: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
Reporter: Adrian Wilford
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).
2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more

--
This message was sent by Atlassian JIRA
(v6.2#6252)

Remko Popma (JIRA)

2014-05-16 10:31:59 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-636?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13998855#comment-13998855 ]

Remko Popma commented on LOG4J2-636:
------------------------------------

Could you post your full configuration? Also, does the application just use the Logger interface (the debug(), info(), warn() etc methods) or does it do anything more complex?

--
This message was sent by Atlassian JIRA
(v6.2#6252)

Remko Popma (JIRA)

2014-05-16 10:31:59 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-636?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Remko Popma updated LOG4J2-636:
-------------------------------

Description:
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).

{code}
2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more
{code}

was:
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).

2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more

Post by Adrian Wilford (JIRA)
IOException: Stream Closed RollingRandomAccessFile
--------------------------------------------------
Key: LOG4J2-636
URL: https://issues.apache.org/jira/browse/LOG4J2-636
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-rc1
Environment: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
Reporter: Adrian Wilford
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).
{code}
2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more
{code}

--
This message was sent by Atlassian JIRA
(v6.2#6252)

Remko Popma (JIRA)

2014-05-21 02:33:38 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-636?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14004238#comment-14004238 ]

Remko Popma commented on LOG4J2-636:
------------------------------------

One explanation I can think of is that in your application one thread has shut down the logging subsystem while other threads are still logging. Is it possible that this is happening?

Another explanation is that this is a problem in the rollover logic. As far as I can tell the rollover logic looks fine (closes the file and creates a new file inside a synchronized block).

Post by Adrian Wilford (JIRA)
IOException: Stream Closed RollingRandomAccessFile
--------------------------------------------------
Key: LOG4J2-636
URL: https://issues.apache.org/jira/browse/LOG4J2-636
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-rc1
Environment: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
Reporter: Adrian Wilford
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).
{code}
2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more
{code}

--
This message was sent by Atlassian JIRA
(v6.2#6252)

Adrian Wilford (JIRA)

2014-05-26 12:58:01 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-636?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14008817#comment-14008817 ]

Adrian Wilford commented on LOG4J2-636:
---------------------------------------

Here is the config file:
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="TRACE" monitorInterval="30">
<Appenders>
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout pattern="%d{yyyy/MM/dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
</Console>
<RollingRandomAccessFile name="RollingRandomAccessFile" fileName="logs/CALEEBaskets.log"
filePattern="logs/CALEEBaskets.$${date:yyyy-MM}/CALEEBaskets-%d{MM-dd-yyyy}-%i.log.gz">
<PatternLayout pattern="%d{yyyy/MM/dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
<Policies>
<OnStartupTriggeringPolicy />
<TimeBasedTriggeringPolicy />
<SizeBasedTriggeringPolicy size="250 MB"/>
</Policies>
</RollingRandomAccessFile>
</Appenders>
<Loggers>
<Root level="debug">
<AppenderRef ref="Console"/>
<AppenderRef ref="RollingRandomAccessFile"/>
</Root>
</Loggers>
</Configuration>

Post by Adrian Wilford (JIRA)
IOException: Stream Closed RollingRandomAccessFile
--------------------------------------------------
Key: LOG4J2-636
URL: https://issues.apache.org/jira/browse/LOG4J2-636
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-rc1
Environment: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
Reporter: Adrian Wilford
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).
{code}
2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more
{code}

--
This message was sent by Atlassian JIRA
(v6.2#6252)

Adrian Wilford (JIRA)

2014-05-26 13:00:03 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-636?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14008818#comment-14008818 ]

Adrian Wilford commented on LOG4J2-636:
---------------------------------------

p.s. I don't know how to "shut down the logging subsystem", so I think that it is unlikely that my code is doing that

Post by Adrian Wilford (JIRA)
IOException: Stream Closed RollingRandomAccessFile
--------------------------------------------------
Key: LOG4J2-636
URL: https://issues.apache.org/jira/browse/LOG4J2-636
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-rc1
Environment: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
Reporter: Adrian Wilford
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).
{code}
2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more
{code}

--
This message was sent by Atlassian JIRA
(v6.2#6252)

Adrian Wilford (JIRA)

2014-05-26 13:04:02 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-636?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14008821#comment-14008821 ]

Adrian Wilford commented on LOG4J2-636:
---------------------------------------

this is the line of code that generates the error:

logger.debug("insert order: ID: " + orderId);

Post by Adrian Wilford (JIRA)
IOException: Stream Closed RollingRandomAccessFile
--------------------------------------------------
Key: LOG4J2-636
URL: https://issues.apache.org/jira/browse/LOG4J2-636
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-rc1
Environment: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
Reporter: Adrian Wilford
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).
{code}
2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more
{code}

--
This message was sent by Atlassian JIRA
(v6.2#6252)

Adrian Wilford (JIRA)

2014-05-26 13:06:01 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-636?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14008821#comment-14008821 ]

Adrian Wilford edited comment on LOG4J2-636 at 5/26/14 1:04 PM:
----------------------------------------------------------------

this is the line of code that generates the error:

logger.debug("insert order: ID: " + orderId);

and this is how I instantiate logger:

private static org.apache.logging.log4j.Logger logger = LogManager.getLogger(OrderLoggingDAL.class.getName());

was (Author: adrianwilford):
this is the line of code that generates the error:

logger.debug("insert order: ID: " + orderId);

Post by Adrian Wilford (JIRA)
IOException: Stream Closed RollingRandomAccessFile
--------------------------------------------------
Key: LOG4J2-636
URL: https://issues.apache.org/jira/browse/LOG4J2-636
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-rc1
Environment: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
Reporter: Adrian Wilford
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).
{code}
2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more
{code}

--
This message was sent by Atlassian JIRA
(v6.2#6252)

Remko Popma (JIRA)

2014-05-26 13:06:01 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-636?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14008822#comment-14008822 ]

Remko Popma commented on LOG4J2-636:
------------------------------------

I see that the configuration has a monitorInterval so it may reload the configuration if the config file has been modified.
Could it be that the config file was modified while your application was running?

Post by Adrian Wilford (JIRA)
IOException: Stream Closed RollingRandomAccessFile
--------------------------------------------------
Key: LOG4J2-636
URL: https://issues.apache.org/jira/browse/LOG4J2-636
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-rc1
Environment: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
Reporter: Adrian Wilford
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).
{code}
2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more
{code}

--
This message was sent by Atlassian JIRA
(v6.2#6252)

Adrian Wilford (JIRA)

2014-05-26 13:08:01 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-636?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14008824#comment-14008824 ]

Adrian Wilford commented on LOG4J2-636:
---------------------------------------

Yes, I did do that.
I changed it from trace to debug and saved the configuration file.

Post by Adrian Wilford (JIRA)
IOException: Stream Closed RollingRandomAccessFile
--------------------------------------------------
Key: LOG4J2-636
URL: https://issues.apache.org/jira/browse/LOG4J2-636
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-rc1
Environment: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
Reporter: Adrian Wilford
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).
{code}
2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more
{code}

--
This message was sent by Atlassian JIRA
(v6.2#6252)

Adrian Wilford (JIRA)

2014-05-26 13:10:01 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-636?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14008824#comment-14008824 ]

Adrian Wilford edited comment on LOG4J2-636 at 5/26/14 1:08 PM:
----------------------------------------------------------------

Yes, I did do that.
I changed it from trace to debug and saved the configuration file.

We find this feature very useful...

Unless it is causing the error...?

was (Author: adrianwilford):
Yes, I did do that.
I changed it from trace to debug and saved the configuration file.

Post by Adrian Wilford (JIRA)
IOException: Stream Closed RollingRandomAccessFile
--------------------------------------------------
Key: LOG4J2-636
URL: https://issues.apache.org/jira/browse/LOG4J2-636
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-rc1
Environment: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
Reporter: Adrian Wilford
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).
{code}
2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more
{code}

--
This message was sent by Atlassian JIRA
(v6.2#6252)

Remko Popma (JIRA)

2014-05-26 16:03:03 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-636?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14008930#comment-14008930 ]

Remko Popma commented on LOG4J2-636:
------------------------------------

I suspect the configuration reload might be causing the error, yes. Thanks for that information, now I have a starting point for investigation.

Post by Adrian Wilford (JIRA)
IOException: Stream Closed RollingRandomAccessFile
--------------------------------------------------
Key: LOG4J2-636
URL: https://issues.apache.org/jira/browse/LOG4J2-636
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-rc1
Environment: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
Reporter: Adrian Wilford
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).
{code}
2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more
{code}

--
This message was sent by Atlassian JIRA
(v6.2#6252)

Remko Popma (JIRA)

2014-06-20 05:01:31 UTC

Permalink

Post by Adrian Wilford (JIRA)
IOException: Stream Closed RollingRandomAccessFile
--------------------------------------------------
Key: LOG4J2-636
URL: https://issues.apache.org/jira/browse/LOG4J2-636
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-rc1
Environment: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
Reporter: Adrian Wilford
Labels: Rollover
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).
{code}
2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more
{code}

--
This message was sent by Atlassian JIRA
(v6.2#6252)

Remko Popma (JIRA)

2014-07-11 07:03:05 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-636?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Remko Popma reassigned LOG4J2-636:
----------------------------------

Assignee: Remko Popma

Post by Adrian Wilford (JIRA)
IOException: Stream Closed RollingRandomAccessFile
--------------------------------------------------
Key: LOG4J2-636
URL: https://issues.apache.org/jira/browse/LOG4J2-636
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-rc1
Environment: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
Reporter: Adrian Wilford
Assignee: Remko Popma
Labels: Rollover
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).
{code}
2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more
{code}

--
This message was sent by Atlassian JIRA
(v6.2#6252)

Remko Popma (JIRA)

2014-09-21 13:20:33 UTC

Permalink

Post by Adrian Wilford (JIRA)
IOException: Stream Closed RollingRandomAccessFile
--------------------------------------------------
Key: LOG4J2-636
URL: https://issues.apache.org/jira/browse/LOG4J2-636
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-rc1
Environment: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
Reporter: Adrian Wilford
Assignee: Remko Popma
Labels: Rollover
Fix For: 2.1
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).
{code}
2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more
{code}

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-22 10:13:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-636?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14008817#comment-14008817 ]

Remko Popma edited comment on LOG4J2-636 at 9/22/14 10:12 AM:
--------------------------------------------------------------

Here is the config file:
{code}
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="TRACE" monitorInterval="30">
<Appenders>
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout pattern="%d{yyyy/MM/dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
</Console>
<RollingRandomAccessFile name="RollingRandomAccessFile" fileName="logs/CALEEBaskets.log"
filePattern="logs/CALEEBaskets.$${date:yyyy-MM}/CALEEBaskets-%d{MM-dd-yyyy}-%i.log.gz">
<PatternLayout pattern="%d{yyyy/MM/dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
<Policies>
<OnStartupTriggeringPolicy />
<TimeBasedTriggeringPolicy />
<SizeBasedTriggeringPolicy size="250 MB"/>
</Policies>
</RollingRandomAccessFile>
</Appenders>
<Loggers>
<Root level="debug">
<AppenderRef ref="Console"/>
<AppenderRef ref="RollingRandomAccessFile"/>
</Root>
</Loggers>
</Configuration>
{code}

was (Author: adrianwilford):
Here is the config file:
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="TRACE" monitorInterval="30">
<Appenders>
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout pattern="%d{yyyy/MM/dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
</Console>
<RollingRandomAccessFile name="RollingRandomAccessFile" fileName="logs/CALEEBaskets.log"
filePattern="logs/CALEEBaskets.$${date:yyyy-MM}/CALEEBaskets-%d{MM-dd-yyyy}-%i.log.gz">
<PatternLayout pattern="%d{yyyy/MM/dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
<Policies>
<OnStartupTriggeringPolicy />
<TimeBasedTriggeringPolicy />
<SizeBasedTriggeringPolicy size="250 MB"/>
</Policies>
</RollingRandomAccessFile>
</Appenders>
<Loggers>
<Root level="debug">
<AppenderRef ref="Console"/>
<AppenderRef ref="RollingRandomAccessFile"/>
</Root>
</Loggers>
</Configuration>

Post by Adrian Wilford (JIRA)
IOException: Stream Closed RollingRandomAccessFile
--------------------------------------------------
Key: LOG4J2-636
URL: https://issues.apache.org/jira/browse/LOG4J2-636
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-rc1
Environment: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
Reporter: Adrian Wilford
Assignee: Remko Popma
Labels: Rollover
Fix For: 2.1
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).
{code}
2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more
{code}

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-22 13:01:34 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-636?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Remko Popma resolved LOG4J2-636.
--------------------------------
Resolution: Cannot Reproduce

I initially thought this was caused by a concurrency issue but I now think I was on the wrong track...

I now think this was caused by a similar problem as what caused LOG4J2-392: incorrect shutdown caused the RollingRandomAccessFileManager to be stopped multiple times. Managers keep track of a ref count, and will not close the stream until the ref count is zero. If the RandomAccessFileManager is stopped multiple times, the ref count becomes zero prematurely and the file is closed even though it is still in use.

I think that one of the fixes in this area may have addressed the problem: I am unable to reproduce this issue with the current code on the master branch. This is what I did to try to reproduce the issue:

* Use the configuration above, with monitorInterval="5" (5 seconds)
* Logging is synchronous (don't configure the Log4jContextSelector to use async loggers)
* Create a test app that starts 10 threads that each do nothing but log in an eternal loop.
* Let the main thread modify the config file's lastModifiedTime every second to trigger reconfiguration

I confirmed that reconfiguration is taking place but everything is working correctly and the above error does not occur.

Below is the code I used. It does not reproduce the issue, so I will mark this issue as "Resolved - Can't Reproduce". Please reopen this issue if the problem still occurs in version 2.0.2 or later.

{code}
public static void main() {
final File config = new File("./log4j2.xml");
System.setProperty("log4j.configurationFile",
"file://" + config.getAbsolutePath().replaceAll("\\\\", "/"));

final Logger logger = LogManager.getLogger("ReloadTest");

final LoggerContext context = (LoggerContext) LogManager.getContext();
final int[] reconfigCount = new int[1];
final ConfigurationListener listener = new ConfigurationListener() {
public void onChange(Reconfigurable reconfigurable) {
reconfigCount[0]++;
context.getConfiguration().removeListener(this);
context.getConfiguration().addListener(this);
}
};
context.getConfiguration().addListener(listener);

final int numThreads = 10;
ExecutorService executor = Executors.newFixedThreadPool(numThreads);
for (int i = 0; i < numThreads; i++) {
executor.submit(new Runnable() {
public void run() {
while (true) {
logger.info("Reconfig count is " + reconfigCount[0]);
}
}
});
}
for (int i = 0; i < 100; i++) {
Thread.sleep(1000);
config.setLastModified(System.currentTimeMillis());
reconfigCount[0]++;
}
}
{code}

Post by Adrian Wilford (JIRA)
IOException: Stream Closed RollingRandomAccessFile
--------------------------------------------------
Key: LOG4J2-636
URL: https://issues.apache.org/jira/browse/LOG4J2-636
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-rc1
Environment: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
Reporter: Adrian Wilford
Assignee: Remko Popma
Labels: Rollover
Fix For: 2.1
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).
{code}
2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more
{code}

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Remko Popma (JIRA)

2014-09-22 13:04:33 UTC

Permalink

[ https://issues.apache.org/jira/browse/LOG4J2-636?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14143165#comment-14143165 ]

Remko Popma edited comment on LOG4J2-636 at 9/22/14 1:03 PM:
-------------------------------------------------------------

I initially thought this was caused by a concurrency issue but I now think I was on the wrong track...

I now think this was caused by a similar problem as what caused LOG4J2-392: incorrect shutdown caused the RollingRandomAccessFileManager to be stopped multiple times. Managers keep track of a ref count, and will not close the stream until the ref count is zero. If the RandomAccessFileManager is stopped multiple times, the ref count becomes zero prematurely and the file is closed even though it is still in use.

I think that one of the fixes in this area may have addressed the problem: I am unable to reproduce this issue with the current code on the master branch. This is what I did to try to reproduce the issue:

* Use the configuration above, with monitorInterval="5" (5 seconds)
* Logging is synchronous (don't configure the Log4jContextSelector to use async loggers)
* Create a test app that starts 10 threads that each do nothing but log in an eternal loop.
* Let the main thread modify the config file's lastModifiedTime every second to trigger reconfiguration

I confirmed that reconfiguration is taking place but everything is working correctly and the above error does not occur.

Below is the code I used. It does not reproduce the issue, so I will mark this issue as "Resolved - Can't Reproduce". Please reopen this issue if the problem still occurs in version 2.0.2 or later.

{code}
import java.io.File;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.core.LoggerContext;
import org.apache.logging.log4j.core.config.ConfigurationListener;
import org.apache.logging.log4j.core.config.Reconfigurable;

public class ReloadTest {

public static void main() {
final File config = new File("./log4j2.xml");
System.setProperty("log4j.configurationFile",
"file://" + config.getAbsolutePath().replaceAll("\\\\", "/"));

final Logger logger = LogManager.getLogger("ReloadTest");

final LoggerContext context = (LoggerContext) LogManager.getContext();
final int[] reconfigCount = new int[1];
final ConfigurationListener listener = new ConfigurationListener() {
public void onChange(Reconfigurable reconfigurable) {
reconfigCount[0]++;
context.getConfiguration().removeListener(this);
context.getConfiguration().addListener(this);
}
};
context.getConfiguration().addListener(listener);

final int numThreads = 10;
ExecutorService executor = Executors.newFixedThreadPool(numThreads);
for (int i = 0; i < numThreads; i++) {
executor.submit(new Runnable() {
public void run() {
while (true) {
logger.info("Reconfig count is " + reconfigCount[0]);
}
}
});
}
for (int i = 0; i < 100; i++) {
Thread.sleep(1000);
config.setLastModified(System.currentTimeMillis());
reconfigCount[0]++;
}
}
}
{code}

was (Author: ***@yahoo.com):
I initially thought this was caused by a concurrency issue but I now think I was on the wrong track...

I now think this was caused by a similar problem as what caused LOG4J2-392: incorrect shutdown caused the RollingRandomAccessFileManager to be stopped multiple times. Managers keep track of a ref count, and will not close the stream until the ref count is zero. If the RandomAccessFileManager is stopped multiple times, the ref count becomes zero prematurely and the file is closed even though it is still in use.

I think that one of the fixes in this area may have addressed the problem: I am unable to reproduce this issue with the current code on the master branch. This is what I did to try to reproduce the issue:

* Use the configuration above, with monitorInterval="5" (5 seconds)
* Logging is synchronous (don't configure the Log4jContextSelector to use async loggers)
* Create a test app that starts 10 threads that each do nothing but log in an eternal loop.
* Let the main thread modify the config file's lastModifiedTime every second to trigger reconfiguration

I confirmed that reconfiguration is taking place but everything is working correctly and the above error does not occur.

Below is the code I used. It does not reproduce the issue, so I will mark this issue as "Resolved - Can't Reproduce". Please reopen this issue if the problem still occurs in version 2.0.2 or later.

{code}
public static void main() {
final File config = new File("./log4j2.xml");
System.setProperty("log4j.configurationFile",
"file://" + config.getAbsolutePath().replaceAll("\\\\", "/"));

final Logger logger = LogManager.getLogger("ReloadTest");

final LoggerContext context = (LoggerContext) LogManager.getContext();
final int[] reconfigCount = new int[1];
final ConfigurationListener listener = new ConfigurationListener() {
public void onChange(Reconfigurable reconfigurable) {
reconfigCount[0]++;
context.getConfiguration().removeListener(this);
context.getConfiguration().addListener(this);
}
};
context.getConfiguration().addListener(listener);

final int numThreads = 10;
ExecutorService executor = Executors.newFixedThreadPool(numThreads);
for (int i = 0; i < numThreads; i++) {
executor.submit(new Runnable() {
public void run() {
while (true) {
logger.info("Reconfig count is " + reconfigCount[0]);
}
}
});
}
for (int i = 0; i < 100; i++) {
Thread.sleep(1000);
config.setLastModified(System.currentTimeMillis());
reconfigCount[0]++;
}
}
{code}

Post by Adrian Wilford (JIRA)
IOException: Stream Closed RollingRandomAccessFile
--------------------------------------------------
Key: LOG4J2-636
URL: https://issues.apache.org/jira/browse/LOG4J2-636
Project: Log4j 2
Issue Type: Bug
Components: Appenders
Affects Versions: 2.0-rc1
Environment: Linux 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux
Reporter: Adrian Wilford
Assignee: Remko Popma
Labels: Rollover
Fix For: 2.1
After some time, RollingRandomAccessFile can no longer write logging events (have not run out of disk space).
{code}
2014-05-13 10:05:18,284 ERROR Unable to write to stream logs/CALEEBaskets.log for appender RollingRandomAccessFile
2014-05-13 10:05:18,284 ERROR An exception occurred processing Appender RollingRandomAccessFile org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to RandomAccessFile logs/CALEEBaskets.log
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:109)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.write(RollingRandomAccessFileManager.java:90)
at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:129)
at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:120)
at org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender.append(RollingRandomAccessFileAppender.java:96)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:97)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:425)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:406)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:367)
at org.apache.logging.log4j.core.Logger.log(Logger.java:112)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:338)
at com.corticalSystems.CALEE.algorithms.baskets.persistence.orderLogging.OrderLoggingDAL.createNewOrder(OrderLoggingDAL.java:163)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.sendNewOrder(ConstituentLogicThread.java:1087)
at com.corticalSystems.CALEE.algorithms.baskets.logic.ConstituentLogicThread.run(ConstituentLogicThread.java:1587)
at java.lang.Thread.run(Thread.java:744)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.writeBytes0(Native Method)
at java.io.RandomAccessFile.writeBytes(RandomAccessFile.java:520)
at java.io.RandomAccessFile.write(RandomAccessFile.java:550)
at org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager.flush(RollingRandomAccessFileManager.java:106)
... 14 more
{code}

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)