[
https://issues.apache.org/jira/browse/LOG4J2-1191?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15033895#comment-15033895
]
Mikael Ståldal commented on LOG4J2-1191:
----------------------------------------
If I understand it correctly, the default behaviour of Log4j 2 is synchronous
by design. This means that {{Appender.append()}} should be blocking, and if you
use a SocketAppender and the remote system isn't responding then it will block
indefinitely.
But you can decouple your application from this by wrapping the potentially
blocking appender with AsyncAppender, or use async loggers.
You do use async loggers, and if I understand it correctly they do protect your
application from being blocked, but one appender blocks all the others.
We could add some timeout to SocketAppender. However, for consistency, that
would require us to review all appenders in {{log4j-core}} and add similar
timeouts to all of them which can potentially block indefinitely (there are
several of those).
Or we could consider change the behaviour of async loggers so that one hanging
appender does not block others.
(Appenders hanging on shutdown is another, but related, story, see
[https://issues.apache.org/jira/browse/LOG4J2-1209].)
> Log4j completely hangs in TcpSocketManager after a while...
> -----------------------------------------------------------
>
> Key: LOG4J2-1191
> URL: https://issues.apache.org/jira/browse/LOG4J2-1191
> Project: Log4j 2
> Issue Type: Bug
> Affects Versions: 2.4.1
> Reporter: Wolfgang Grossinger
> Priority: Blocker
>
> We are currently logging with Log4j2 to a file and want to replace this/add
> logging over Logstash via TCP/IP. When we do this (we add an according Socket
> appender) the logging just hangs after a while. There are 2 problems at the
> moment:
> 1.) The communication to Logstash is blocket - this may be because of Log4j2,
> because of a Java Library, because of Lostash etc. (we are still investiging
> about this)
> 2.) The second problem is definitely a problem with Log4j2: when this problem
> occurs, NOTHING is logged at all -> the whole logging just stops, no logging
> to a file, no logging to sysout, nothing. If the logging is not async, the
> whole application hangs. What we would expect is, that a failure in one
> appender does neither harm other appenders or at least loggers and does not
> kill the whole application.
> Log4j2 - Config:
> {code:xml}
> <?xml version="1.0" encoding="UTF-8"?>
> <Configuration monitorInterval="300" packages="at.gv.bmi.zps.logging">
> <Appenders>
> <RollingFile name="LOGAPPENDER"
> fileName="/log/appl/e/zps/srv/zpssrv-${sys:ServerName}.log"
>
> filePattern="/log/appl/e/zps/srv/zpssrv-${sys:ServerName}.log.%d{yyyy-MM-dd}-%i.log.gz"
> bufferedIO="true">
> <RegexFilter
> regex=".*:Request.*|.*:Response.*|.*:Security.*"
> onMatch="DENY" onMismatch="ACCEPT" />
> <PatternLayout charset="UTF-8">
> <charset>UTF-8</charset>
> <pattern>ZPS O ZPSSRV 1.24.0-SNAPSHOT
> %X{transactionId} %d{yyyy-MM-dd HH:mm:ss.SSS} ${sys:ServerName} %-5level
> [Thread: %t] %logger{36} - %msg%n</pattern>
> </PatternLayout> <Policies>
> <TimeBasedTriggeringPolicy interval="1"
> modulate="true" />
> <SizeBasedTriggeringPolicy size="300 MB" />
> </Policies>
> </RollingFile>
> <RollingFile name="MESSAGEAPPENDER"
> fileName="/log/appl/e/zps/srv/messages-zpssrv-${sys:ServerName}.log"
>
> filePattern="/log/appl/e/zps/srv/messages-zpssrv-${sys:ServerName}.log.%d{yyyy-MM-dd}-%i.log.gz"
> bufferedIO="true">
> <PatternLayout charset="UTF-8">
> <charset>UTF-8</charset>
> <pattern>ZPS O ZPSSRV 1.24.0-SNAPSHOT
> %X{transactionId} %d{yyyy-MM-dd HH:mm:ss.SSS} ${sys:ServerName} %-5level
> [Thread: %t] %logger{36} - %msg%n</pattern>
> </PatternLayout>
> <Policies>
> <TimeBasedTriggeringPolicy interval="1"
> modulate="true" />
> <SizeBasedTriggeringPolicy size="300 MB" />
> </Policies>
> </RollingFile>
> <RollingFile name="ERRORAPPENDER"
> fileName="/log/appl/e/zps/srv/zpssrv-${sys:ServerName}.log-ERR"
>
> filePattern="/log/appl/e/zps/srv/zpssrv-${sys:ServerName}.log-ERR.%d{yyyy-MM-dd}-%i.log"
> bufferedIO="false">
> <PatternLayout charset="UTF-8">
> <charset>UTF-8</charset>
> <pattern>ZPS O ZPSSRV 1.24.0-SNAPSHOT
> %X{transactionId} %d{yyyy-MM-dd HH:mm:ss.SSS} LOCAL %-5level [Thread: %t]
> %logger{36} - %msg%n</pattern>
> </PatternLayout>
> <Policies>
> <SizeBasedTriggeringPolicy size="400 MB" />
> </Policies>
> </RollingFile>
> <RollingFile name="LOGSTASH-FAILOVERAPPENDER"
> fileName="/log/appl/e/zps/srv/zpssrv-${sys:ServerName}.log-LFO"
>
> filePattern="/log/appl/e/zps/srv/zpssrv-${sys:ServerName}.log-LFO.%d{yyyy-MM-dd}-%i.log"
> bufferedIO="true" ignoreExceptions="false">
> <PatternLayout charset="UTF-8">
> <charset>UTF-8</charset>
> <pattern>ZPS O ZPSSRV 1.24.0-SNAPSHOT
> %X{transactionId} %d{yyyy-MM-dd HH:mm:ss.SSS} ${sys:ServerName} %-5level
> [Thread: %t] %logger{36} - %msg%n</pattern>
> </PatternLayout>
> <Policies>
> <SizeBasedTriggeringPolicy size="400 MB" />
> </Policies>
> </RollingFile>
> <Socket name="LOGSTASHAPPENDER" host="10.1.10.40"
> port="9401" ignoreExceptions="false"
> connectTimeoutMillis="5000" reconnectionDelayMillis="5000">
> <PatternLayout charset="UTF-8">
> <charset>UTF-8</charset>
> <pattern>ZPS O ZPSSRV 1.24.0-SNAPSHOT
> %X{transactionId} %d{yyyy-MM-dd HH:mm:ss.SSS} ${sys:ServerName} %-5level
> [Thread: %t] %logger{36} - %msg%n</pattern>
> </PatternLayout>
> </Socket>
> <Failover name="LFOAPPENDER" primary="LOGSTASHAPPENDER"
> ignoreExceptions="false">
> <Failovers>
> <AppenderRef ref="LOGSTASH-FAILOVERAPPENDER" />
> </Failovers>
> </Failover>
> <RollingFile name="LOGSTASH-FAILOVERAPPENDER-TEST"
> fileName="/log/appl/e/zps/srv/zpssrv-${sys:ServerName}.log-LFO-TEST"
>
> filePattern="/log/appl/e/zps/srv/zpssrv-${sys:ServerName}.log-LFO-TEST.%d{yyyy-MM-dd}-%i.log"
> bufferedIO="true" ignoreExceptions="false">
> <PatternLayout charset="UTF-8">
> <charset>UTF-8</charset>
> <pattern>ZPS O ZPSSRV 1.24.0-SNAPSHOT
> %X{transactionId} %d{yyyy-MM-dd HH:mm:ss.SSS} ${sys:ServerName} %-5level
> [Thread: %t] %logger{36} - %msg%n</pattern>
> </PatternLayout>
> <Policies>
> <SizeBasedTriggeringPolicy size="400 MB" />
> </Policies>
> </RollingFile>
> <Socket name="LOGSTASHAPPENDER-TEST" host="10.101.13.55"
> port="9401" ignoreExceptions="false"
> connectTimeoutMillis="5000" reconnectionDelayMillis="5000">
> <PatternLayout charset="UTF-8">
> <charset>UTF-8</charset>
> <pattern>ZPS O ZPSSRV 1.24.0-SNAPSHOT
> %X{transactionId} %d{yyyy-MM-dd HH:mm:ss.SSS} ${sys:ServerName} %-5level
> [Thread: %t] %logger{36} - %msg%n</pattern>
> </PatternLayout>
> </Socket>
>
> <Failover name="LFOAPPENDER-TEST"
> primary="LOGSTASHAPPENDER-TEST" ignoreExceptions="false">
> <Failovers>
> <AppenderRef
> ref="LOGSTASH-FAILOVERAPPENDER-TEST" />
> </Failovers>
> </Failover>
>
> </Appenders>
> <Loggers>
> <AsyncLogger name="MESSAGELOGGER" level="debug"
> additivity="false" errorRef="ERRORAPPENDER">
> <AppenderRef ref="MESSAGEAPPENDER" />
> </AsyncLogger>
> <AsyncLogger name="LOGSTASH" level="debug"
> additivity="false" errorRef="ERRORAPPENDER">
> <AppenderRef ref="LFOAPPENDER-TEST" />
> <AppenderRef ref="LFOAPPENDER" />
> </AsyncLogger>
> <logger name="org.apache.commons.digester" level="INFO" />
> <logger name="at.gv.bmi.zps.model.shared.validations"
> level="INFO" />
> <logger name="org.apache.camel" level="INFO" />
> <logger name="at.gv.bmi.zps.context" level="INFO" />
> <logger name="org.apache.ojb" level="ERROR" />
> <logger name="org.apache.fop" level="ERROR" />
> <logger name="org.apache.xmlgraphics" level="ERROR" />
> <logger name="org.docx4j" level="ERROR" />
> <logger name="docx4jcustom" level="ERROR" />
> <logger name="at.gv.bmi.commons.access.CacheAccessor"
> level="ERROR" />
> <logger name="at.gv.bmi.zps.docprocessing.RenderFactory"
> level="OFF" />
> <AsyncRoot level="debug" errorRef="ERRORAPPENDER">
> <AppenderRef ref="LOGAPPENDER" />
> </AsyncRoot>
>
> </Loggers>
> </Configuration>
> {code}
> WebSphere Trace on z/OS:
> {noformat}
> 3XMTHREADINFO "AsyncLoggerConfig-1" J9VMThread:0x00000000267D3200,
> j9thread_t:0x0000004808D170D0, java/lang/Thread:0x000000008CA2C408, state:R,
> prio=5
> 3XMJAVALTHREAD (java/lang/Thread getId:0x5F9, isDaemon:true)
> 3XMTHREADINFO1 (native thread ID:0x29CB1200, native priority:0x5,
> native policy:UNKNOWN, vmstate:R, vm thread flags:0x00000001)
> 3XMCPUTIME CPU usage total: 7.916000000 secs
> 3XMHEAPALLOC Heap bytes allocated since last GC cycle=0 (0x0)
> 3XMTHREADINFO3 Java callstack:
> 4XESTACKTRACE at
> java/net/SocketOutputStream.socketWrite0(Native Method)
> 4XESTACKTRACE at
> java/net/SocketOutputStream.socketWrite(SocketOutputStream.java:125(Compiled
> Code))
> 4XESTACKTRACE at
> java/net/SocketOutputStream.write(SocketOutputStream.java:171(Compiled Code))
> 4XESTACKTRACE at
> org/apache/logging/log4j/core/net/TcpSocketManager.write(TcpSocketManager.java:131(Compiled
> Code))
> 5XESTACKTRACE (entered lock:
> org/apache/logging/log4j/core/net/TcpSocketManager§0x000000008F435390, entry
> count: 1)
> 4XESTACKTRACE at
> org/apache/logging/log4j/core/appender/OutputStreamManager.write(OutputStreamManager.java:136(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/logging/log4j/core/appender/AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:105(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/logging/log4j/core/config/AppenderControl.tryCallAppender(AppenderControl.java:152(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/logging/log4j/core/config/AppenderControl.callAppender0(AppenderControl.java:125(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/logging/log4j/core/config/AppenderControl.callAppenderPreventRecursion(AppenderControl.java:116(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/logging/log4j/core/config/AppenderControl.callAppender(AppenderControl.java:84(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/logging/log4j/core/appender/FailoverAppender.callAppender(FailoverAppender.java:123(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/logging/log4j/core/appender/FailoverAppender.append(FailoverAppender.java:115(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/logging/log4j/core/config/AppenderControl.tryCallAppender(AppenderControl.java:152(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/logging/log4j/core/config/AppenderControl.callAppender0(AppenderControl.java:125(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/logging/log4j/core/config/AppenderControl.callAppenderPreventRecursion(AppenderControl.java:116(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/logging/log4j/core/config/AppenderControl.callAppender(AppenderControl.java:84(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/logging/log4j/core/config/LoggerConfig.callAppenders(LoggerConfig.java:390(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/logging/log4j/core/async/AsyncLoggerConfig.asyncCallAppenders(AsyncLoggerConfig.java:121(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigHelper.java:208(Compiled
> Code))
> 4XESTACKTRACE at
> org/apache/logging/log4j/core/async/AsyncLoggerConfigHelper$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigHelper.java:194(Compiled
> Code))
> 4XESTACKTRACE at
> com/lmax/disruptor/BatchEventProcessor.run(BatchEventProcessor.java:120)
> 4XESTACKTRACE at
> java/util/concurrent/ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1157(Compiled
> Code))
> 4XESTACKTRACE at
> java/util/concurrent/ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:627)
> 4XESTACKTRACE at java/lang/Thread.run(Thread.java:801(Compiled
> Code))
> {noformat}
> Trace when we stop/kill the application after it hangs:
> {noformat}
> ExtendedMessage: BBOO0222I: WSVR0024I: Server SERVANT PROCESS WASE216
> stopped
>
> Trace: 2015/11/03 16:27:59.873 02 t=BC9130 c=UNK key=P8 tag= (13007002)
>
>
> ThreadId: 00000048
>
>
> FunctionName: com.lmax.disruptor.FatalExceptionHandler
>
>
> SourceId: com.lmax.disruptor.FatalExceptionHandler
>
>
> Category: SEVERE
>
>
> ExtendedMessage: Exception processing: 1833
> org.apache.logging.log4j.core.async.AsyncLoggerConfigHelper$Log4jEventWrapper§376ed871java.lang.InterruptedException
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2029)
>
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2064)
>
> at
> com.lmax.disruptor.BlockingWaitStrategy.waitFor(BlockingWaitStrategy.java:45)
>
> at
> com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:55)
>
> at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:115)
>
>
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1157)
>
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:627)
>
> at java.lang.Thread.run(Thread.java:801)
>
>
>
>
>
> Exception in thread "AsyncLoggerConfig-1" java.lang.RuntimeException:
> java.lang.InterruptedException
>
>
>
>
> at
> com.lmax.disruptor.FatalExceptionHandler.handleEventException(FatalExceptionHandler.java:45)
>
> at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:139)
>
>
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1157)
>
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:627)
>
> at java.lang.Thread.run(Thread.java:801)
>
>
>
>
>
> Caused by: java.lang.InterruptedException
>
>
>
>
>
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2029)
>
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2064)
>
> at
> com.lmax.disruptor.BlockingWaitStrategy.waitFor(BlockingWaitStrategy.java:45)
>
> at
> com.lmax.disruptor.ProcessingSequenceBarrier.waitFor(ProcessingSequenceBarrier.java:55)
>
> at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:115)
>
>
>
>
>
> ... 3 more
>
>
>
>
>
> java.lang.InterruptedException
>
>
>
>
>
> at java.lang.Thread.sleep(Native Method)
>
>
> at java.lang.Thread.sleep(Thread.java:925)java.lang.InterruptedException
>
>
> at at.bmi.util.SendDataHTTP.run(SendDataHTTP.java:43)
>
>
> at java.lang.Thread.run(Thread.java:801)
>
>
>
> at java.lang.Thread.sleep(Native Method)
>
> at java.lang.Thread.sleep(Thread.java:925)
>
> at at.bmi.util.SendDataNagios.run(SendDataNagios.java:42)
>
> at java.lang.Thread.run(Thread.java:801)
>
>
>
> Exception in thread "AsyncLogger-1" java.lang.NoClassDefFoundError:
> org.apache.logging.log4j.message.ObjectMessage
>
>
> at
> org.apache.logging.log4j.message.AbstractMessageFactory.newMessage(AbstractMessageFactory.java:38)
>
> at
> org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:994)
>
> at
> org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:949)
>
> at
> org.apache.logging.log4j.spi.AbstractLogger.error(AbstractLogger.java:382)
>
> at
> at.gv.bmi.zps.logging.ZpsLogExceptionHandler.handleEventException(ZpsLogExceptionHandler.java:15)
>
> at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:139)
>
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1157)
>
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:627)
>
> at java.lang.Thread.run(Thread.java:801)
>
>
>
> Caused by: java.lang.ClassNotFoundException:
> org.apache.logging.log4j.message.ObjectMessage
>
>
> at java.net.URLClassLoader.findClass(URLClassLoader.java:600)
>
> at
> com.ibm.ws.bootstrap.ExtClassLoader.authorizedFindClass(ExtClassLoader.java:261)
>
> at com.ibm.ws.bootstrap.ExtClassLoader.findClass(ExtClassLoader.java:238)
>
> at java.lang.ClassLoader.loadClassHelper(ClassLoader.java:772)
>
> at java.lang.ClassLoader.loadClass(ClassLoader.java:749)
>
> at com.ibm.ws.bootstrap.ExtClassLoader.loadClass(ExtClassLoader.java:133)
>
> at java.lang.ClassLoader.loadClass(ClassLoader.java:726)
>
> at
> com.ibm.ws.classloader.ProtectionClassLoader.loadClass(ProtectionClassLoader.java:62)
>
> at
> com.ibm.ws.classloader.ProtectionClassLoader.loadClass(ProtectionClassLoader.java:58)
>
> at
> com.ibm.ws.classloader.CompoundClassLoader.loadClass(CompoundClassLoader.java:585)
>
> at java.lang.ClassLoader.loadClass(ClassLoader.java:726)
>
> at
> com.ibm.ws.classloader.CompoundClassLoader.loadClass(CompoundClassLoader.java:585)
>
> at java.lang.ClassLoader.loadClass(ClassLoader.java:726)
>
> ... 9 more
>
> {noformat}
> Kind regards,
> Wolfgang
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-dev-h...@logging.apache.org
