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 "zhaoyufei (JIRA)" <ji...@apache.org> on 2016/02/21 11:33:18 UTC
[jira] [Comment Edited] (LOG4J2-1191) Log4j completely hangs in
TcpSocketManager after a while...
[ https://issues.apache.org/jira/browse/LOG4J2-1191?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15155977#comment-15155977 ]
zhaoyufei edited comment on LOG4J2-1191 at 2/21/16 10:32 AM:
-------------------------------------------------------------
very excited to see this issue,
for i have make another similar issue-LOG4J2-1191.
i think the most possibly reason caused above cases is that:
the SoTimeout is default to 0, so it means the SocketAppender will be blocked forever once it can not send or get response from target server.
If all the logEvent that block full of the quene, then the SocketAppender will hang all the time.
was (Author: zhaoyufei):
very excited to see this issue,
for i have make another similar issue-LOG4J2-1191.
i think the most possibly reason caused above cases is that:
the SoTimeout is default to 0, so it means the SocketAppender will be blocked forever once it can not send or get response from target server.
> 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-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org