[
https://issues.apache.org/jira/browse/LOG4J2-1191?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15033448#comment-15033448
]
Wolfgang Grossinger commented on LOG4J2-1191:
---------------------------------------------
I asked operating to do that if possible but I can't promise... Please note,
that this issue addresses 2 problems: The first problem is that the TCP
communication seems not to work properly. The second and in my opinion the much
bigger problem is, that there is no timeout and you can't specify that timeout
in log4j2 and/or the exceptionhandling doesn't work properly. It is absolutely
not ok that log4j2 hangs here.
> 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
