[ http://jira.qos.ch/browse/LBCORE-99?page=com.atlassian.jira.plugin.system.is... ] 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@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