[ https://issues.apache.org/jira/browse/LOG4J2-1191?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Remko Popma updated LOG4J2-1191: -------------------------------- Priority: Major (was: Blocker) > 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 > > 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