[ http://jira.qos.ch/browse/LBCORE-99?page=com.atlassian.jira.plugin.system.is... ] Ceki Gulcu commented on LBCORE-99: ---------------------------------- For the record, Thread "32900144@qtp0-0 - /cbs2/v1.0/ws/cbs2.wsdl" invokes o.m.jetty.servlet.ServletHandler.handle(ServletHandler.java:414) as a consequence, a few lines down the stack trace o.m.log.Slf4jLog.warn(Slf4jLog.java:128) is invoked and as a consequence, a few lines further c.q.l.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60) is invoked. This latest call causes the thread to obtain a lock on "<0x7395a770> (a ch.qos.logback.core.ConsoleAppender)" During the logging process, PackagingDataCalculator.calculate is invoked, this causes the thread to invoke o.m.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:341) which attempts to obtain a lock on "<0x7391a760> (o.m.jetty.webapp.WebAppClassLoader)" which is already in possession of thread "15510444@qtp0-2" discussed below Thread "15510444@qtp0-2 - /cbs2/v1.0/ws/cbs2.wsdl" invokes org.mortbay.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:341) which obtains a lock on <0x7391a760> (a o.m.jetty.webapp.WebAppClassLoader) as a consequence, a few lines further o.m.log.Slf4jLog.debug(Slf4jLog.java:73) is invoked as a result, c.q.l.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:60) is invoked, this latest call attempts to lock <0x7395a770> (a c.q.l.core.ConsoleAppender) which is already in possession of thread "32900144@qtp0-0" as discussed above. The bug is an illustration of deadlocks occurring when a logback component, during the process of logging, invokes a service which does logging itself. There are two cheap and immediate ways to get rid of this *particular* bug. 1) reduce logging verbosity for the "org.mortbay.log" logger, which is the sole logger used by Jetty. This can be done by setting the level of "org.mortbay.log" logger to any level above or equal to INFO, that is INFO, WARN and ERROR. 2) disable the addition of packaging information in stack traces output by ConsoleAppender. This can be accomplished by adding "%ex" to the end of conversion pattern. For example, if the configuration snippet for ConsoleAppender is <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern>%-5r [%thread] %level - %msg%n</Pattern> </layout> </appender> then, change it to: <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <!-- note the addition of %ex at the end --> <Pattern>%-5r [%thread] %level - %msg%n%ex</Pattern> </layout> </appender> Of course, while these two solutions are cheap and yield immediate results, they are intellectually unsatisfactory. Reducing the locking granularity in AppenderBase would most probably get rid of the problem. Strictly speaking, as far as FileAppender and co. are concerned, the lock needs to be active only while writing to the file. In a similar fashion, the scope of lock could be reduced in many other appenders, with DBAppender as one notable exception.
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