[logback-dev] [JIRA] Commented: (LBCORE-99) Deadlock in consoleappender using logback in jetty
Ralph Goers (JIRA)
noreply-jira at qos.ch
Sat Jun 13 02:32:10 CEST 2009
[ http://jira.qos.ch/browse/LBCORE-99?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11157#action_11157 ]
Ralph Goers commented on LBCORE-99:
-----------------------------------
The situation in the log is:
1. Jetty is using SLF4J
2. The class loader is trying to log
3. The Appender is trying to create an object.
All of these should be OK to do.
This error occurs because AppenderBase locks calls to Appenders. If instead, UnsynchronizedAppenderBase was used and locking was confined to an appropriate granularity (i.e. a lock was not held while creating an object) this problem would not appear.
However, even with that change a StackOverflowException could result due to the class loader logging which in turn invokes the class loader. Logback or SLF4J should prevent this scenario by not letting itself be called recursively (Use a thread local to detect this).
> 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