[logback-dev] [JIRA] Commented: (LBCORE-99) Deadlock in consoleappender using logback in jetty
Ceki Gulcu (JIRA)
noreply-jira at qos.ch
Sat Jun 13 17:08:10 CEST 2009
[ http://jira.qos.ch/browse/LBCORE-99?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=11166#action_11166 ]
Ceki Gulcu commented on LBCORE-99:
----------------------------------
Here is a very rough view of what happens when logback writes out to a single appender.
LoggingEvent event = createLoggingEvent();
Appender.doAppend(event) {
lock(this); // lock the appender
populateCertainPartsByMagic(event);
String s = format(event);
writeOutToTarget(s);
unlock(this);
}
This bug (LBCORE-99) could be solved in several ways.
As Ralph suggests:
LoggingEvent event = createLoggingEvent();
Appender.doAppend(event) {
populateCertainPartsByMagic(event);
String s = format(event);
lock(this); // lock the appender
writeOutToTarget(s);
unlock(this);
}
As suggested by Joern
LoggingEvent event = createLoggingEvent();
populateCertainPartsByMagic(event);
Appender.doAppend(event) {
lock(this); // lock the appender
String s = format(event);
writeOutToTarget(s);
unlock(this);
}
There are cons to each approach as there are pros, e.g. the resolution of this bug.
> 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: Ceki Gulcu
>
> 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