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] [Comment Edited] (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 edited comment on LOG4J2-1191 at 11/7/15 11:59 AM:
---------------------------------------------------------------

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


was (Author: ralph.goers@dslextreme.com):
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