You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by "Jan (JIRA)" <ji...@apache.org> on 2017/01/18 13:54:26 UTC

[jira] [Commented] (LOG4J2-1182) RandomAccessFile IOException: Stream Closed is back

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

Jan commented on LOG4J2-1182:
-----------------------------

We had the same issue recently with version 2.5:
{noformat}
15.01.17 23:24:58:212 ws.OurClass      [http-bio-9001-exec-5868       ]  ERROR - A general error has occurred: Error writing to stream D:/path/to/logFile.log
org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to stream D:/path/to/logFile.log
    at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:126) ~[log4j-core-2.5.jar:2.5]
    at org.apache.logging.log4j.core.appender.FileManager.write(FileManager.java:102) ~[log4j-core-2.5.jar:2.5]
    at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.write(RollingFileManager.java:94) ~[log4j-core-2.5.jar:2.5]
    at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:136) ~[log4j-core-2.5.jar:2.5]
    at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:114) [log4j-core-2.5.jar:2.5]
    at org.apache.logging.log4j.core.appender.RollingFileAppender.append(RollingFileAppender.java:88) [log4j-core-2.5.jar:2.5]
    at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:152) [log4j-core-2.5.jar:2.5]
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:125) [log4j-core-2.5.jar:2.5]
    at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:116) [log4j-core-2.5.jar:2.5]
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84) [log4j-core-2.5.jar:2.5]
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:390) [log4j-core-2.5.jar:2.5]
    at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:378) [log4j-core-2.5.jar:2.5]
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:362) [log4j-core-2.5.jar:2.5]
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:352) [log4j-core-2.5.jar:2.5]
    at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63) [log4j-core-2.5.jar:2.5]
    at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:147) [log4j-core-2.5.jar:2.5]
    at org.apache.log4j.Category.maybeLog(Category.java:440) [log4j-1.2-api-2.5.jar:2.5]
    at org.apache.log4j.Category.error(Category.java:214) [log4j-1.2-api-2.5.jar:2.5]
    [...]
    at sun.reflect.GeneratedMethodAccessor77.invoke(Unknown Source) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.7.0_80]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[?:1.7.0_80]
    at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:180) [cxf-api-2.6.14.jar:2.6.14]
    at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96) [cxf-api-2.6.14.jar:2.6.14]
    at org.apache.cxf.jaxws.AbstractJAXWSMethodInvoker.invoke(AbstractJAXWSMethodInvoker.java:178) [cxf-rt-frontend-jaxws-2.6.14.jar:2.6.14]
    at org.apache.cxf.jaxws.JAXWSMethodInvoker.invoke(JAXWSMethodInvoker.java:67) [cxf-rt-frontend-jaxws-2.6.14.jar:2.6.14]
    at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:75) [cxf-api-2.6.14.jar:2.6.14]
    at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:57) [cxf-api-2.6.14.jar:2.6.14]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [?:1.7.0_80]
    at java.util.concurrent.FutureTask.run(FutureTask.java:262) [?:1.7.0_80]
    at org.apache.cxf.workqueue.SynchronousExecutor.execute(SynchronousExecutor.java:37) [cxf-api-2.6.14.jar:2.6.14]
    at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:106) [cxf-api-2.6.14.jar:2.6.14]
    at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:263) [cxf-api-2.6.14.jar:2.6.14]
    at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) [cxf-api-2.6.14.jar:2.6.14]
    at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:240) [cxf-rt-transports-http-2.6.14.jar:2.6.14]
    at org.apache.openejb.server.cxf.CxfWsContainer.onMessage(CxfWsContainer.java:86) [openejb-cxf-4.7.1.jar:4.7.1]
    at org.apache.openejb.server.webservices.WsServlet.service(WsServlet.java:98) [openejb-webservices-4.7.1.jar:4.7.1]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303) [catalina.jar:7.0.55]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.55]
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat7-websocket.jar:7.0.55]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [catalina.jar:7.0.55]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.55]
    at org.apache.logging.log4j.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:71) [log4j-web-2.5.jar:2.5]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241) [catalina.jar:7.0.55]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208) [catalina.jar:7.0.55]
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220) [catalina.jar:7.0.55]
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122) [catalina.jar:7.0.55]
    at org.apache.tomee.catalina.OpenEJBValve.invoke(OpenEJBValve.java:44) [tomee-catalina-1.7.1.jar:1.7.1]
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501) [catalina.jar:7.0.55]
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171) [catalina.jar:7.0.55]
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) [catalina.jar:7.0.55]
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950) [catalina.jar:7.0.55]
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116) [catalina.jar:7.0.55]
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408) [catalina.jar:7.0.55]
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1070) [tomcat-coyote.jar:7.0.55]
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611) [tomcat-coyote.jar:7.0.55]
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316) [tomcat-coyote.jar:7.0.55]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [?:1.7.0_80]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [?:1.7.0_80]
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-coyote.jar:7.0.55]
    at java.lang.Thread.run(Thread.java:745) [?:1.7.0_80]
Caused by: java.io.IOException: Stream Closed
    at java.io.FileOutputStream.writeBytes(Native Method) ~[?:1.7.0_80]
    at java.io.FileOutputStream.write(FileOutputStream.java:345) ~[?:1.7.0_80]
    at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) ~[?:1.7.0_80]
    at java.io.BufferedOutputStream.write(BufferedOutputStream.java:126) ~[?:1.7.0_80]
    at org.apache.logging.log4j.core.appender.OutputStreamManager.write(OutputStreamManager.java:123) ~[log4j-core-2.5.jar:2.5]
    ... 63 more
{noformat}
Up to now this happened only once.
Obviously it happened during rollover, because the size of the last written log file is equal to the specified limit of 10 MB.
Here is the config:
{noformat}
<?xml version="1.0" encoding="UTF-8" ?>
<Configuration status="info" monitorInterval="30">
    <Appenders>
        <RollingFile name="root-appender" fileName="D:/path/to/logFile.log" filePattern="D:/path/to/logFile-%d{MM-dd-yyyy}-%i.log.gz"
                     ignoreExceptions="false">
            <PatternLayout>
                <Pattern>%d{dd.MM.yy HH:mm:ss:SSS} %-25.25c{2} [%-30.30t] %6p - %m%n</Pattern>
            </PatternLayout>
            <SizeBasedTriggeringPolicy size="10 MB"/>
            <DefaultRolloverStrategy max="8"/>
        </RollingFile>

        <RollingFile name="app-appender" fileName="D:/path/to/logFile2.log" filePattern="D:/path/to/logFile2-%d{MM-dd-yyyy}-%i.log.gz"
                     ignoreExceptions="false">
            <PatternLayout>
                <Pattern>%d{dd.MM.yy HH:mm:ss:SSS} %-25.25c{2} [%-30.30t] %6p - %m%n</Pattern>
            </PatternLayout>
            <SizeBasedTriggeringPolicy size="10 MB"/>
            <DefaultRolloverStrategy max="8"/>
        </RollingFile>

        <!--Console name="console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss,SSS} %-25.25c{2} [%-30.30t] %6p - %m%n"/>
        </Console-->
    </Appenders>
    <Loggers>
        <Logger name="our.package.app" level="debug">
            <AppenderRef ref="app-appender" />
        </Logger>
        <Logger name="our.package.customers" level="debug">
            <AppenderRef ref="app-appender" />
        </Logger>
        <Logger name="our.package.app.processing" level="warn">
            <AppenderRef ref="app-appender" />
        </Logger>
        <Logger name="our.package.app.util" level="warn">
            <AppenderRef ref="app-appender" />
        </Logger>
        <Root level="debug">
            <AppenderRef ref="root-appender" />
            <AppenderRef ref="console" />
        </Root>
    </Loggers>
</Configuration>
{noformat}

> 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
(v6.3.4#6332)

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org