[logback-dev] [JIRA] Created: (LBCORE-99) Deadlock in consoleappender using logback in jetty

13 Jun 2009

      Deadlock in consoleappender using logback in jetty
--------------------------------------------------

                 Key: LBCORE-99
                 URL: http://jira.qos.ch/browse/LBCORE-99
             Project: logback-core
          Issue Type: Bug
          Components: Appender
    Affects Versions: 0.9.15
         Environment: Maven 2.1.0 jetty plugin on ubuntu linux.

maven dependencies list ...

			<dependency>
				<groupId>org.slf4j</groupId>
				<artifactId>slf4j-ext</artifactId>
				<version>1.5.8</version>
				<type>jar</type>
			</dependency>
			<dependency>
				<groupId>org.slf4j</groupId>
				<artifactId>jcl-over-slf4j</artifactId>
				<version>1.5.8</version>
			</dependency>
			<dependency>
				<groupId>ch.qos.logback</groupId>
				<artifactId>logback-core</artifactId>
				<version>0.9.15</version>
				<type>jar</type>
			</dependency>
			<dependency>
				<groupId>ch.qos.logback</groupId>
				<artifactId>logback-classic</artifactId>
				<version>0.9.15</version>
				<type>jar</type>
			</dependency>
			<dependency>
				<groupId>commons-logging</groupId>
				<artifactId>commons-logging</artifactId>
				<version>99.0-does-not-exist</version>
			</dependency
            Reporter: Sakib Mehasanewala
            Assignee: Logback dev list

I came across this deadlock while running jetty via plugin in maven to run functional tests...

Found one Java-level deadlock:
============================= 
"Shutdown":                   
  waiting to lock monitor 0xb52073c0 (object 0x7395a770, a ch.qos.logback.core.ConsoleAppender),                                                                              
  which is held by "32900144@qtp0-0 - /cbs2/v1.0/ws/cbs2.wsdl"                         
"32900144@qtp0-0 - /cbs2/v1.0/ws/cbs2.wsdl":                                           
  waiting to lock monitor 0xb5209bfc (object 0x7391a760, a org.mortbay.jetty.webapp.WebAppClassLoader),                                                                       
  which is held by "15510444@qtp0-2 - /cbs2/v1.0/ws/cbs2.wsdl"                         
"15510444@qtp0-2 - /cbs2/v1.0/ws/cbs2.wsdl":                                           
  waiting to lock monitor 0xb52073c0 (object 0x7395a770, a ch.qos.logback.core.ConsoleAppender),                                                                              
  which is held by "32900144@qtp0-0 - /cbs2/v1.0/ws/cbs2.wsdl"                         

Java stack information for the threads listed above:
=================================================== 
"Shutdown":                                         
        at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66)
        - waiting to lock <0x7395a770> (a ch.qos.logback.core.ConsoleAppender)
        at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60)                                                               
        at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)        
        at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)                
        at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:439)   
        at ch.qos.logback.classic.Logger.filterAndLog_2(Logger.java:430)               
        at ch.qos.logback.classic.Logger.info(Logger.java:605)                         
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)                 
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)                                                                                      
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)                                                                              
        at java.lang.reflect.Method.invoke(Method.java:597)                            
        at org.mortbay.log.Slf4jLog.info(Slf4jLog.java:103)                            
        at org.mortbay.log.Log.info(Log.java:132)                                      
        at org.mortbay.jetty.Server$ShutdownHookThread.run(Server.java:550)            
"32900144@qtp0-0 - /cbs2/v1.0/ws/cbs2.wsdl":                                           
        at org.mortbay.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:341)                                                                                   
        - waiting to lock <0x7391a760> (a org.mortbay.jetty.webapp.WebAppClassLoader)  
        at ch.qos.logback.classic.spi.PackagingDataCalculator.loadClass(PackagingDataCalculator.java:232)                                                                     
        at ch.qos.logback.classic.spi.PackagingDataCalculator.bestEffortLoadClass(PackagingDataCalculator.java:257)                                                           
        at ch.qos.logback.classic.spi.PackagingDataCalculator.computeBySTEP(PackagingDataCalculator.java:166)                                                                 
        at ch.qos.logback.classic.spi.PackagingDataCalculator.populateFrames(PackagingDataCalculator.java:97)                                                                 
        at ch.qos.logback.classic.spi.PackagingDataCalculator.calculate(PackagingDataCalculator.java:61)                                                                      
        at ch.qos.logback.classic.spi.ThrowableProxy.calculatePackagingData(ThrowableProxy.java:50)                                                                           
        at ch.qos.logback.classic.pattern.ExtendedThrowableProxyConverter.prepareLoggingEvent(ExtendedThrowableProxyConverter.java:35)                                        
        at ch.qos.logback.classic.pattern.ThrowableProxyConverter.convert(ThrowableProxyConverter.java:142)                                                                   
        at ch.qos.logback.classic.pattern.ThrowableProxyConverter.convert(ThrowableProxyConverter.java:30)                                                                    
        at ch.qos.logback.core.pattern.FormattingConverter.write(FormattingConverter.java:32)                                                                                 
        at ch.qos.logback.core.pattern.PatternLayoutBase.writeLoopOnConverters(PatternLayoutBase.java:110)                                                                    
        at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:132)       
        at ch.qos.logback.classic.PatternLayout.doLayout(PatternLayout.java:51)        
        at ch.qos.logback.core.WriterAppender.subAppend(WriterAppender.java:261)       
        at ch.qos.logback.core.WriterAppender.append(WriterAppender.java:114)          
        at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:87)             
        - locked <0x7395a770> (a ch.qos.logback.core.ConsoleAppender)                  
        at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60)                                                               
        at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)        
        at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)                
        at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:439)   
        at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:393)       
        at ch.qos.logback.classic.Logger.warn(Logger.java:710)                         
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)                 
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)                                                                                      
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)                                                                              
        at java.lang.reflect.Method.invoke(Method.java:597)                            
        at org.mortbay.log.Slf4jLog.warn(Slf4jLog.java:128)                            
        at org.mortbay.log.Log.warn(Log.java:181)                                      
        at org.mortbay.log.Log.unwind(Log.java:216)                                    
        at org.mortbay.log.Log.warn(Log.java:182)                                      
        at org.mortbay.log.Log.unwind(Log.java:216)                                    
        at org.mortbay.log.Log.warn(Log.java:182)                                      
        at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:414)    
        at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216) 
        at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)    
        at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766)    
        at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417)       
        at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)                                                                       
        at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)                                                                                     
        at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)    
        at org.mortbay.jetty.Server.handle(Server.java:320)                            
        at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534)     
        at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:864)                                                                            
        at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:533)                 
        at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:207)            
        at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:403)            
        at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
        at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:522)                                                                                      
"15510444@qtp0-2 - /cbs2/v1.0/ws/cbs2.wsdl":                                           
        at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66)             
        - waiting to lock <0x7395a770> (a ch.qos.logback.core.ConsoleAppender)         
        at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60)                                                               
        at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)        
        at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)                
        at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:439)   
        at ch.qos.logback.classic.Logger.filterAndLog_2(Logger.java:430)               
        at ch.qos.logback.classic.Logger.debug(Logger.java:508)                        
        at sun.reflect.GeneratedMethodAccessor15.invoke(Unknown Source)                
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)                                                                              
        at java.lang.reflect.Method.invoke(Method.java:597)                            
        at org.mortbay.log.Slf4jLog.debug(Slf4jLog.java:73)                            
        at org.mortbay.log.Log.debug(Log.java:90)                                      
        at org.mortbay.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:388)                                                                                   
        - locked <0x7391a760> (a org.mortbay.jetty.webapp.WebAppClassLoader)           
        at org.mortbay.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:341)                                                                                   
        - locked <0x7391a760> (a org.mortbay.jetty.webapp.WebAppClassLoader)           
        at com.sun.org.apache.xerces.internal.parsers.ObjectFactory.findProviderClass(ObjectFactory.java:393)                                                                 
        at com.sun.org.apache.xerces.internal.parsers.ObjectFactory.newInstance(ObjectFactory.java:348)                                                                       
        at com.sun.org.apache.xerces.internal.parsers.ObjectFactory.createObject(ObjectFactory.java:154)                                                                      
        at com.sun.org.apache.xerces.internal.parsers.ObjectFactory.createObject(ObjectFactory.java:97)                                                                       
        at com.sun.org.apache.xerces.internal.parsers.DOMParser.<init>(DOMParser.java:125)                                                                                    
        at com.sun.org.apache.xerces.internal.parsers.DOMParser.<init>(DOMParser.java:109)                                                                                    
        at com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderImpl.<init>(DocumentBuilderImpl.java:115)                                                                   
        at com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderFactoryImpl.newDocumentBuilder(DocumentBuilderFactoryImpl.java:72)                                          
        at com.sun.org.apache.xalan.internal.xsltc.trax.SAX2DOM.<init>(SAX2DOM.java:69)
        - locked <0x912b1278> (a java.lang.Class for com.sun.org.apache.xalan.internal.xsltc.trax.SAX2DOM)                                                                    
        at com.sun.org.apache.xalan.internal.xsltc.runtime.output.TransletOutputHandlerFactory.getSerializationHandler(TransletOutputHandlerFactory.java:187)                 
        at com.sun.org.apache.xalan.internal.xsltc.trax.TransformerImpl.getOutputHandler(TransformerImpl.java:392)                                                            
        at com.sun.org.apache.xalan.internal.xsltc.trax.TransformerImpl.transform(TransformerImpl.java:298)
        at org.springframework.ws.transport.http.WsdlDefinitionHandlerAdapter.handle(WsdlDefinitionHandlerAdapter.java:125)
        at org.springframework.ws.transport.http.MessageDispatcherServlet.doService(MessageDispatcherServlet.java:222)
        at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:613)
        at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:525)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
        at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502)
        at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1124)
        at com.diginsite.services.cbs2.filter.ClearRequestContextFilter.doFilter(ClearRequestContextFilter.java:34)
        at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1115)
        at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:361)
        at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
        at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
        at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766)
        at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417)
        at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
        at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
        at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
        at org.mortbay.jetty.Server.handle(Server.java:320)
        at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534)
        at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:864)
        at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:533)
        at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:207)
        at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:403)
        at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
        at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:522)

Found 1 deadlock.

Heap
 def new generation   total 3904K, used 115K [0x70060000, 0x70490000, 0x727c0000)
  eden space 3520K,   3% used [0x70060000, 0x7007cda8, 0x703d0000)
  from space 384K,   0% used [0x703d0000, 0x703d0000, 0x70430000)
  to   space 384K,   0% used [0x70430000, 0x70430000, 0x70490000)
 tenured generation   total 50668K, used 26395K [0x727c0000, 0x7593b000, 0x90060000)
   the space 50668K,  52% used [0x727c0000, 0x74186f40, 0x74187000, 0x7593b000)
 compacting perm gen  total 20736K, used 20517K [0x90060000, 0x914a0000, 0x94060000)
   the space 20736K,  98% used [0x90060000, 0x914697a0, 0x91469800, 0x914a0000)
    ro space 8192K,  74% used [0x94060000, 0x94658b48, 0x94658c00, 0x94860000)
    rw space 12288K,  58% used [0x94860000, 0x94f73df0, 0x94f73e00, 0x95460000)

-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira

[logback-dev] [JIRA] Created: (LBCORE-99) Deadlock in consoleappender using logback in jetty

Sakib Mehasanewala (JIRA)