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

Joern Huxhorn (JIRA) noreply-jira at qos.ch
Sat Jun 13 03:51:10 CEST 2009


    [ http://jira.qos.ch/browse/LBCORE-99?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11159#action_11159 ] 

Joern Huxhorn commented on LBCORE-99:
-------------------------------------

Ralph is absolutely right.

I've changed the patch in LBCORE-97 accordingly.
The guard is now implemented using ThreadLocal<Boolean> and is evaluated before the lock is actually obtained.

We should nevertheless aim to let more appenders extend UnsynchronizedAppenderBase instead of AppenderBase, I think.

> 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 at qtp0-0 - /cbs2/v1.0/ws/cbs2.wsdl"                         
> "32900144 at 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 at qtp0-2 - /cbs2/v1.0/ws/cbs2.wsdl"                         
> "15510444 at 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 at 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 at 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 at 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

        


More information about the logback-dev mailing list