logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Ralph Goers (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (LOG4J2-1191) Log4j completely hangs in TcpSocketManager after a while...
Date Sat, 07 Nov 2015 12:00:13 GMT

    [ https://issues.apache.org/jira/browse/LOG4J2-1191?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14995177#comment-14995177
] 

Ralph Goers commented on LOG4J2-1191:
-------------------------------------

Gary, attributes can always be specified as events in the configuration. However it seems
he has them as both, which is wrong. It needs to be one or the other.

> 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


Mime
View raw message