[
https://issues.apache.org/jira/browse/LOG4J2-1191?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15048499#comment-15048499
]
Wolfgang Grossinger commented on LOG4J2-1191:
---------------------------------------------
When I log asynchrounously, it is right that the application will continue to
respond, but there will be no logging output. This is not really what someone
wants, because if this is wanted, no log4j2 is needed at all.
I think it would be best to implement both things. it is necessary to implement
some timeout to be able to handle problems with TCP correctly, AND it would be
a good behavior not to block other loggers (this is not only a problem with
async loggers, I think when a sync logger blocks, it will also lock other
loggers).
> 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
