[JIRA] Created: (LBCORE-96) Deadlock when running on multiple core processors
Deadlock when running on multiple core processors ------------------------------------------------- Key: LBCORE-96 URL: http://jira.qos.ch/browse/LBCORE-96 Project: logback-core Issue Type: Bug Components: Appender Affects Versions: 0.9.15 Environment: Windows Vista quad core Apache Tomcat 6.0.18 JDK 1.6 Reporter: Lars Feistner Assignee: Logback dev list As Robert Dale mentioned on 23/Mar/09 04:05 PM I'm getting that deadlock in logback core (0.9.14 and 0.9.15). No console plugin or socket appenders, just plain RollingFileAppender. I am getting the deadlock using ConsoleAppender. see attached thread dump: 2009-04-06 11:49:45 Full thread dump Java HotSpot(TM) Client VM (11.0-b12 mixed mode, sharing): "http-8084-5" daemon prio=6 tid=0x04700c00 nid=0xc54 in Object.wait() [0x05d1f000..0x05d1fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-4" daemon prio=6 tid=0x04700000 nid=0xe24 in Object.wait() [0x05c7f000..0x05c7fbe8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-3" daemon prio=6 tid=0x04700400 nid=0x134c waiting for monitor entry [0x05c2f000..0x05c2fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "Thread-10" daemon prio=6 tid=0x046ff800 nid=0x122c runnable [0x05bdf000..0x05bdfb68] java.lang.Thread.State: RUNNABLE at sun.net.dns.ResolverConfigurationImpl.notifyAddrChange0(Native Method) at sun.net.dns.ResolverConfigurationImpl$AddressChangeListener.run(ResolverConfigurationImpl.java:125) "http-8084-2" daemon prio=6 tid=0x046ff400 nid=0x17f4 waiting for monitor entry [0x05b8f000..0x05b8fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "TP-Monitor" daemon prio=6 tid=0x04a17400 nid=0x830 in Object.wait() [0x05b3f000..0x05b3fce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable.run(ThreadPool.java:565) - locked <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor4" daemon prio=6 tid=0x0497a000 nid=0x11dc runnable [0x05a8f000..0x05a8fd68] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e0a9b0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.jk.common.ChannelSocket.accept(ChannelSocket.java:306) at org.apache.jk.common.ChannelSocket.acceptConnections(ChannelSocket.java:660) at org.apache.jk.common.ChannelSocket$SocketAcceptor.runIt(ChannelSocket.java:870) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690) at java.lang.Thread.run(Thread.java:619) "TP-Processor3" daemon prio=6 tid=0x04979c00 nid=0xfe8 in Object.wait() [0x05a3f000..0x05a3f9e8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor2" daemon prio=6 tid=0x04982800 nid=0x10bc in Object.wait() [0x059ef000..0x059efa68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor1" daemon prio=6 tid=0x04982000 nid=0x131c in Object.wait() [0x0599f000..0x0599fae8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "http-8084-1" daemon prio=6 tid=0x04917000 nid=0x15f4 runnable [0x0594f000..0x0594fb68] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:260) at java.io.BufferedOutputStream.write(BufferedOutputStream.java:105) - locked <0x2395d280> (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:430) - locked <0x23951d08> (a java.io.PrintStream) at org.apache.tomcat.util.log.SystemLogHandler.write(SystemLogHandler.java:166) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272) at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276) at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122) - locked <0x23b1c1f0> (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212) at ch.qos.logback.core.WriterAppender.writerWrite(WriterAppender.java:245) 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 <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:92) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "http-8084-Acceptor-0" daemon prio=6 tid=0x049c2400 nid=0x129c runnable [0x058bf000..0x058bfbe8] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23a40168> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.tomcat.util.net.DefaultServerSocketFactory.acceptSocket(DefaultServerSocketFactory.java:61) at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:310) at java.lang.Thread.run(Thread.java:619) "ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=6 tid=0x051c9800 nid=0x152c waiting on condition [0x0452f000..0x0452fc68] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1579) at java.lang.Thread.run(Thread.java:619) "Thread-1" daemon prio=2 tid=0x04638c00 nid=0x1360 in Object.wait() [0x044df000..0x044dfce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon.nextTask(ClockDaemon.java:328) - locked <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:362) at java.lang.Thread.run(Thread.java:619) "ElementEventQueue.QProcessor-1" daemon prio=6 tid=0x050f2800 nid=0x17d0 in Object.wait() [0x0442f000..0x0442fd68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b81398> (a java.lang.Object) at java.lang.Object.wait(Object.java:485) at org.apache.jcs.engine.control.event.ElementEventQueue.take(ElementEventQueue.java:181) - locked <0x23b81398> (a java.lang.Object) at org.apache.jcs.engine.control.event.ElementEventQueue.access$300(ElementEventQueue.java:35) at org.apache.jcs.engine.control.event.ElementEventQueue$QProcessor.run(ElementEventQueue.java:245) "Low Memory Detector" daemon prio=6 tid=0x0215c800 nid=0x1370 runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "CompilerThread0" daemon prio=10 tid=0x02156400 nid=0x758 waiting on condition [0x00000000..0x0433f890] java.lang.Thread.State: RUNNABLE "Attach Listener" daemon prio=10 tid=0x02155400 nid=0x14f4 waiting on condition [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" daemon prio=10 tid=0x0214ac00 nid=0x151c runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Finalizer" daemon prio=8 tid=0x02143000 nid=0x430 in Object.wait() [0x0424f000..0x0424fce8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116) - locked <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x02141000 nid=0x510 in Object.wait() [0x0091f000..0x0091fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e7e8> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:485) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) - locked <0x2394e7e8> (a java.lang.ref.Reference$Lock) "main" prio=6 tid=0x0020a800 nid=0xef4 runnable [0x0025f000..0x0025fe28] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e18dc0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.catalina.core.StandardServer.await(StandardServer.java:389) at org.apache.catalina.startup.Catalina.await(Catalina.java:642) at org.apache.catalina.startup.Catalina.start(Catalina.java:602) 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.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288) at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413) "VM Thread" prio=10 tid=0x0213fc00 nid=0xdc0 runnable "VM Periodic Task Thread" prio=10 tid=0x0215dc00 nid=0x1128 waiting on condition JNI global references: 781 i also attach my logback configuration: <?xml version="1.0" encoding="UTF-8"?> <configuration debug="true"> <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> Operator %X{client}: %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> <!-- <appender name="file" class="ch.qos.logback.core.FileAppender" > <File>imsm-debug.log</File> <Append>false</Append> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> --> <logger name="net.sf.jguard.core" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.authorization" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.filters" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.ext" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.jee" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.ehcache" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.util" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.jguard" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBUserImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBGroupImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBOperatorImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBInstitutionImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="org.apache.jcs" additivity="false"> <level value="WARN" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <root> <!-- The following level element is not necessary since the --> <!-- level of the root level is set to DEBUG by default. --> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </root> </configuration> -- 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
[ http://jira.qos.ch/browse/LBCORE-96?page=com.atlassian.jira.plugin.system.is... ] Ralph Goers commented on LBCORE-96: ----------------------------------- The attached thread dump does NOT show a deadlock. Thread http-8084-1 is running. This thread dump does show the contention over the appender lock. This issue is a duplicate of LBCORE-62.
Deadlock when running on multiple core processors -------------------------------------------------
Key: LBCORE-96 URL: http://jira.qos.ch/browse/LBCORE-96 Project: logback-core Issue Type: Bug Components: Appender Affects Versions: 0.9.15 Environment: Windows Vista quad core Apache Tomcat 6.0.18 JDK 1.6 Reporter: Lars Feistner Assignee: Logback dev list
As Robert Dale mentioned on 23/Mar/09 04:05 PM I'm getting that deadlock in logback core (0.9.14 and 0.9.15). No console plugin or socket appenders, just plain RollingFileAppender. I am getting the deadlock using ConsoleAppender. see attached thread dump: 2009-04-06 11:49:45 Full thread dump Java HotSpot(TM) Client VM (11.0-b12 mixed mode, sharing): "http-8084-5" daemon prio=6 tid=0x04700c00 nid=0xc54 in Object.wait() [0x05d1f000..0x05d1fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-4" daemon prio=6 tid=0x04700000 nid=0xe24 in Object.wait() [0x05c7f000..0x05c7fbe8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-3" daemon prio=6 tid=0x04700400 nid=0x134c waiting for monitor entry [0x05c2f000..0x05c2fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "Thread-10" daemon prio=6 tid=0x046ff800 nid=0x122c runnable [0x05bdf000..0x05bdfb68] java.lang.Thread.State: RUNNABLE at sun.net.dns.ResolverConfigurationImpl.notifyAddrChange0(Native Method) at sun.net.dns.ResolverConfigurationImpl$AddressChangeListener.run(ResolverConfigurationImpl.java:125) "http-8084-2" daemon prio=6 tid=0x046ff400 nid=0x17f4 waiting for monitor entry [0x05b8f000..0x05b8fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "TP-Monitor" daemon prio=6 tid=0x04a17400 nid=0x830 in Object.wait() [0x05b3f000..0x05b3fce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable.run(ThreadPool.java:565) - locked <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor4" daemon prio=6 tid=0x0497a000 nid=0x11dc runnable [0x05a8f000..0x05a8fd68] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e0a9b0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.jk.common.ChannelSocket.accept(ChannelSocket.java:306) at org.apache.jk.common.ChannelSocket.acceptConnections(ChannelSocket.java:660) at org.apache.jk.common.ChannelSocket$SocketAcceptor.runIt(ChannelSocket.java:870) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690) at java.lang.Thread.run(Thread.java:619) "TP-Processor3" daemon prio=6 tid=0x04979c00 nid=0xfe8 in Object.wait() [0x05a3f000..0x05a3f9e8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor2" daemon prio=6 tid=0x04982800 nid=0x10bc in Object.wait() [0x059ef000..0x059efa68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor1" daemon prio=6 tid=0x04982000 nid=0x131c in Object.wait() [0x0599f000..0x0599fae8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "http-8084-1" daemon prio=6 tid=0x04917000 nid=0x15f4 runnable [0x0594f000..0x0594fb68] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:260) at java.io.BufferedOutputStream.write(BufferedOutputStream.java:105) - locked <0x2395d280> (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:430) - locked <0x23951d08> (a java.io.PrintStream) at org.apache.tomcat.util.log.SystemLogHandler.write(SystemLogHandler.java:166) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272) at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276) at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122) - locked <0x23b1c1f0> (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212) at ch.qos.logback.core.WriterAppender.writerWrite(WriterAppender.java:245) 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 <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:92) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "http-8084-Acceptor-0" daemon prio=6 tid=0x049c2400 nid=0x129c runnable [0x058bf000..0x058bfbe8] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23a40168> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.tomcat.util.net.DefaultServerSocketFactory.acceptSocket(DefaultServerSocketFactory.java:61) at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:310) at java.lang.Thread.run(Thread.java:619) "ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=6 tid=0x051c9800 nid=0x152c waiting on condition [0x0452f000..0x0452fc68] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1579) at java.lang.Thread.run(Thread.java:619) "Thread-1" daemon prio=2 tid=0x04638c00 nid=0x1360 in Object.wait() [0x044df000..0x044dfce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon.nextTask(ClockDaemon.java:328) - locked <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:362) at java.lang.Thread.run(Thread.java:619) "ElementEventQueue.QProcessor-1" daemon prio=6 tid=0x050f2800 nid=0x17d0 in Object.wait() [0x0442f000..0x0442fd68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b81398> (a java.lang.Object) at java.lang.Object.wait(Object.java:485) at org.apache.jcs.engine.control.event.ElementEventQueue.take(ElementEventQueue.java:181) - locked <0x23b81398> (a java.lang.Object) at org.apache.jcs.engine.control.event.ElementEventQueue.access$300(ElementEventQueue.java:35) at org.apache.jcs.engine.control.event.ElementEventQueue$QProcessor.run(ElementEventQueue.java:245) "Low Memory Detector" daemon prio=6 tid=0x0215c800 nid=0x1370 runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "CompilerThread0" daemon prio=10 tid=0x02156400 nid=0x758 waiting on condition [0x00000000..0x0433f890] java.lang.Thread.State: RUNNABLE "Attach Listener" daemon prio=10 tid=0x02155400 nid=0x14f4 waiting on condition [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" daemon prio=10 tid=0x0214ac00 nid=0x151c runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Finalizer" daemon prio=8 tid=0x02143000 nid=0x430 in Object.wait() [0x0424f000..0x0424fce8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116) - locked <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x02141000 nid=0x510 in Object.wait() [0x0091f000..0x0091fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e7e8> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:485) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) - locked <0x2394e7e8> (a java.lang.ref.Reference$Lock) "main" prio=6 tid=0x0020a800 nid=0xef4 runnable [0x0025f000..0x0025fe28] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e18dc0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.catalina.core.StandardServer.await(StandardServer.java:389) at org.apache.catalina.startup.Catalina.await(Catalina.java:642) at org.apache.catalina.startup.Catalina.start(Catalina.java:602) 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.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288) at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413) "VM Thread" prio=10 tid=0x0213fc00 nid=0xdc0 runnable "VM Periodic Task Thread" prio=10 tid=0x0215dc00 nid=0x1128 waiting on condition JNI global references: 781 i also attach my logback configuration: <?xml version="1.0" encoding="UTF-8"?> <configuration debug="true"> <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> Operator %X{client}: %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> <!-- <appender name="file" class="ch.qos.logback.core.FileAppender" > <File>imsm-debug.log</File> <Append>false</Append> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> --> <logger name="net.sf.jguard.core" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.authorization" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.filters" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.ext" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.jee" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.ehcache" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.util" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.jguard" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBUserImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBGroupImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBOperatorImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBInstitutionImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="org.apache.jcs" additivity="false"> <level value="WARN" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <root> <!-- The following level element is not necessary since the --> <!-- level of the root level is set to DEBUG by default. --> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </root> </configuration>
-- 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
[ http://jira.qos.ch/browse/LBCORE-96?page=com.atlassian.jira.plugin.system.is... ] Ceki Gulcu commented on LBCORE-96: ---------------------------------- The configuration file has redundant appender references (appender-ref elements). See "appender additivity" in http://logback.qos.ch/manual/architecture.html . Please let me know if removing redundant references solves this issue.
Deadlock when running on multiple core processors -------------------------------------------------
Key: LBCORE-96 URL: http://jira.qos.ch/browse/LBCORE-96 Project: logback-core Issue Type: Bug Components: Appender Affects Versions: 0.9.15 Environment: Windows Vista quad core Apache Tomcat 6.0.18 JDK 1.6 Reporter: Lars Feistner Assignee: Logback dev list
As Robert Dale mentioned on 23/Mar/09 04:05 PM I'm getting that deadlock in logback core (0.9.14 and 0.9.15). No console plugin or socket appenders, just plain RollingFileAppender. I am getting the deadlock using ConsoleAppender. see attached thread dump: 2009-04-06 11:49:45 Full thread dump Java HotSpot(TM) Client VM (11.0-b12 mixed mode, sharing): "http-8084-5" daemon prio=6 tid=0x04700c00 nid=0xc54 in Object.wait() [0x05d1f000..0x05d1fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-4" daemon prio=6 tid=0x04700000 nid=0xe24 in Object.wait() [0x05c7f000..0x05c7fbe8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-3" daemon prio=6 tid=0x04700400 nid=0x134c waiting for monitor entry [0x05c2f000..0x05c2fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "Thread-10" daemon prio=6 tid=0x046ff800 nid=0x122c runnable [0x05bdf000..0x05bdfb68] java.lang.Thread.State: RUNNABLE at sun.net.dns.ResolverConfigurationImpl.notifyAddrChange0(Native Method) at sun.net.dns.ResolverConfigurationImpl$AddressChangeListener.run(ResolverConfigurationImpl.java:125) "http-8084-2" daemon prio=6 tid=0x046ff400 nid=0x17f4 waiting for monitor entry [0x05b8f000..0x05b8fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "TP-Monitor" daemon prio=6 tid=0x04a17400 nid=0x830 in Object.wait() [0x05b3f000..0x05b3fce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable.run(ThreadPool.java:565) - locked <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor4" daemon prio=6 tid=0x0497a000 nid=0x11dc runnable [0x05a8f000..0x05a8fd68] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e0a9b0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.jk.common.ChannelSocket.accept(ChannelSocket.java:306) at org.apache.jk.common.ChannelSocket.acceptConnections(ChannelSocket.java:660) at org.apache.jk.common.ChannelSocket$SocketAcceptor.runIt(ChannelSocket.java:870) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690) at java.lang.Thread.run(Thread.java:619) "TP-Processor3" daemon prio=6 tid=0x04979c00 nid=0xfe8 in Object.wait() [0x05a3f000..0x05a3f9e8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor2" daemon prio=6 tid=0x04982800 nid=0x10bc in Object.wait() [0x059ef000..0x059efa68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor1" daemon prio=6 tid=0x04982000 nid=0x131c in Object.wait() [0x0599f000..0x0599fae8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "http-8084-1" daemon prio=6 tid=0x04917000 nid=0x15f4 runnable [0x0594f000..0x0594fb68] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:260) at java.io.BufferedOutputStream.write(BufferedOutputStream.java:105) - locked <0x2395d280> (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:430) - locked <0x23951d08> (a java.io.PrintStream) at org.apache.tomcat.util.log.SystemLogHandler.write(SystemLogHandler.java:166) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272) at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276) at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122) - locked <0x23b1c1f0> (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212) at ch.qos.logback.core.WriterAppender.writerWrite(WriterAppender.java:245) 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 <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:92) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "http-8084-Acceptor-0" daemon prio=6 tid=0x049c2400 nid=0x129c runnable [0x058bf000..0x058bfbe8] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23a40168> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.tomcat.util.net.DefaultServerSocketFactory.acceptSocket(DefaultServerSocketFactory.java:61) at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:310) at java.lang.Thread.run(Thread.java:619) "ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=6 tid=0x051c9800 nid=0x152c waiting on condition [0x0452f000..0x0452fc68] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1579) at java.lang.Thread.run(Thread.java:619) "Thread-1" daemon prio=2 tid=0x04638c00 nid=0x1360 in Object.wait() [0x044df000..0x044dfce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon.nextTask(ClockDaemon.java:328) - locked <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:362) at java.lang.Thread.run(Thread.java:619) "ElementEventQueue.QProcessor-1" daemon prio=6 tid=0x050f2800 nid=0x17d0 in Object.wait() [0x0442f000..0x0442fd68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b81398> (a java.lang.Object) at java.lang.Object.wait(Object.java:485) at org.apache.jcs.engine.control.event.ElementEventQueue.take(ElementEventQueue.java:181) - locked <0x23b81398> (a java.lang.Object) at org.apache.jcs.engine.control.event.ElementEventQueue.access$300(ElementEventQueue.java:35) at org.apache.jcs.engine.control.event.ElementEventQueue$QProcessor.run(ElementEventQueue.java:245) "Low Memory Detector" daemon prio=6 tid=0x0215c800 nid=0x1370 runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "CompilerThread0" daemon prio=10 tid=0x02156400 nid=0x758 waiting on condition [0x00000000..0x0433f890] java.lang.Thread.State: RUNNABLE "Attach Listener" daemon prio=10 tid=0x02155400 nid=0x14f4 waiting on condition [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" daemon prio=10 tid=0x0214ac00 nid=0x151c runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Finalizer" daemon prio=8 tid=0x02143000 nid=0x430 in Object.wait() [0x0424f000..0x0424fce8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116) - locked <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x02141000 nid=0x510 in Object.wait() [0x0091f000..0x0091fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e7e8> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:485) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) - locked <0x2394e7e8> (a java.lang.ref.Reference$Lock) "main" prio=6 tid=0x0020a800 nid=0xef4 runnable [0x0025f000..0x0025fe28] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e18dc0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.catalina.core.StandardServer.await(StandardServer.java:389) at org.apache.catalina.startup.Catalina.await(Catalina.java:642) at org.apache.catalina.startup.Catalina.start(Catalina.java:602) 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.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288) at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413) "VM Thread" prio=10 tid=0x0213fc00 nid=0xdc0 runnable "VM Periodic Task Thread" prio=10 tid=0x0215dc00 nid=0x1128 waiting on condition JNI global references: 781 i also attach my logback configuration: <?xml version="1.0" encoding="UTF-8"?> <configuration debug="true"> <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> Operator %X{client}: %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> <!-- <appender name="file" class="ch.qos.logback.core.FileAppender" > <File>imsm-debug.log</File> <Append>false</Append> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> --> <logger name="net.sf.jguard.core" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.authorization" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.filters" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.ext" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.jee" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.ehcache" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.util" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.jguard" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBUserImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBGroupImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBOperatorImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBInstitutionImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="org.apache.jcs" additivity="false"> <level value="WARN" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <root> <!-- The following level element is not necessary since the --> <!-- level of the root level is set to DEBUG by default. --> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </root> </configuration>
-- 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
[ http://jira.qos.ch/browse/LBCORE-96?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn updated LBCORE-96: -------------------------------- Attachment: AppenderBaseLock.patch Hi guys, Our webapp running on a 4-core solaris is suffering* the same problem as described in http://jira.qos.ch/browse/LBCORE-63 and http://jira.qos.ch/browse/LBCORE-96 and I think I have an idea about the reason behind this. Threading policy has changed from 1.5 to 1.6. I can't give you a reference for this, it's purely based on observation. In 1.5, a thread waiting for a lock was somewhat preferred by the VM over threads that would arrive at the wait() at a later time. In 1.6, however, a thread that releases synchronization is much more likely to immediately obtain the object lock again if it's in a consumer/producer loop. for(;;) { synchronized(obj) { // thread is likely to reobtain lock } } The same is the case for wait/notifyAll combinations. One can not assume that a longer waiting thread will likely obtain the lock after notifyAll. This is documented in http://java.sun.com/javase/6/docs/api/java/lang/Object.html#notifyAll() so the changed behavior between 1.5 and 1.6 is perfectly legal. My assumption is that the perceived deadlock, which is actually a congestion/starvation problem, occurs if one thread is logging "like crazy" while the other thread is sluggish as hell because he can't obtain the lock. This should be solvable by using a fair ReentrantLock (See http://java.sun.com/javase/6/docs/api/java/util/concurrent/locks/ReentrantLo...) )
From the javadoc: "The constructor for this class accepts an optional fairness parameter. When set true, under contention, locks favor granting access to the longest-waiting thread. Otherwise this lock does not guarantee any particular access order. Programs using fair locks accessed by many threads may display lower overall throughput (i.e., are slower; often much slower) than those using the default setting, but have smaller variances in times to obtain locks and guarantee lack of starvation."
The guaranteed lack of starvation is what we are looking for, I think, This is something that pure synchronization simply can't provide. I'd suggest to give the attached patch a try, I can't do so myself because I can't risk our webapp and I have no other chance to test this right now. I'll crosspost this to both tickets cause I'm not sure which one is more "active" right now. * The webapp shows that behavior in case of either console, file and/or lilith/socket appenders. It's just much more likely to happen with the lilith/socket appender in place since it takes significantly longer to send events over the wire than just writing them to disk or console.
Deadlock when running on multiple core processors -------------------------------------------------
Key: LBCORE-96 URL: http://jira.qos.ch/browse/LBCORE-96 Project: logback-core Issue Type: Bug Components: Appender Affects Versions: 0.9.15 Environment: Windows Vista quad core Apache Tomcat 6.0.18 JDK 1.6 Reporter: Lars Feistner Assignee: Logback dev list Attachments: AppenderBaseLock.patch
As Robert Dale mentioned on 23/Mar/09 04:05 PM I'm getting that deadlock in logback core (0.9.14 and 0.9.15). No console plugin or socket appenders, just plain RollingFileAppender. I am getting the deadlock using ConsoleAppender. see attached thread dump: 2009-04-06 11:49:45 Full thread dump Java HotSpot(TM) Client VM (11.0-b12 mixed mode, sharing): "http-8084-5" daemon prio=6 tid=0x04700c00 nid=0xc54 in Object.wait() [0x05d1f000..0x05d1fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-4" daemon prio=6 tid=0x04700000 nid=0xe24 in Object.wait() [0x05c7f000..0x05c7fbe8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-3" daemon prio=6 tid=0x04700400 nid=0x134c waiting for monitor entry [0x05c2f000..0x05c2fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "Thread-10" daemon prio=6 tid=0x046ff800 nid=0x122c runnable [0x05bdf000..0x05bdfb68] java.lang.Thread.State: RUNNABLE at sun.net.dns.ResolverConfigurationImpl.notifyAddrChange0(Native Method) at sun.net.dns.ResolverConfigurationImpl$AddressChangeListener.run(ResolverConfigurationImpl.java:125) "http-8084-2" daemon prio=6 tid=0x046ff400 nid=0x17f4 waiting for monitor entry [0x05b8f000..0x05b8fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "TP-Monitor" daemon prio=6 tid=0x04a17400 nid=0x830 in Object.wait() [0x05b3f000..0x05b3fce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable.run(ThreadPool.java:565) - locked <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor4" daemon prio=6 tid=0x0497a000 nid=0x11dc runnable [0x05a8f000..0x05a8fd68] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e0a9b0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.jk.common.ChannelSocket.accept(ChannelSocket.java:306) at org.apache.jk.common.ChannelSocket.acceptConnections(ChannelSocket.java:660) at org.apache.jk.common.ChannelSocket$SocketAcceptor.runIt(ChannelSocket.java:870) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690) at java.lang.Thread.run(Thread.java:619) "TP-Processor3" daemon prio=6 tid=0x04979c00 nid=0xfe8 in Object.wait() [0x05a3f000..0x05a3f9e8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor2" daemon prio=6 tid=0x04982800 nid=0x10bc in Object.wait() [0x059ef000..0x059efa68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor1" daemon prio=6 tid=0x04982000 nid=0x131c in Object.wait() [0x0599f000..0x0599fae8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "http-8084-1" daemon prio=6 tid=0x04917000 nid=0x15f4 runnable [0x0594f000..0x0594fb68] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:260) at java.io.BufferedOutputStream.write(BufferedOutputStream.java:105) - locked <0x2395d280> (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:430) - locked <0x23951d08> (a java.io.PrintStream) at org.apache.tomcat.util.log.SystemLogHandler.write(SystemLogHandler.java:166) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272) at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276) at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122) - locked <0x23b1c1f0> (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212) at ch.qos.logback.core.WriterAppender.writerWrite(WriterAppender.java:245) 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 <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:92) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "http-8084-Acceptor-0" daemon prio=6 tid=0x049c2400 nid=0x129c runnable [0x058bf000..0x058bfbe8] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23a40168> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.tomcat.util.net.DefaultServerSocketFactory.acceptSocket(DefaultServerSocketFactory.java:61) at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:310) at java.lang.Thread.run(Thread.java:619) "ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=6 tid=0x051c9800 nid=0x152c waiting on condition [0x0452f000..0x0452fc68] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1579) at java.lang.Thread.run(Thread.java:619) "Thread-1" daemon prio=2 tid=0x04638c00 nid=0x1360 in Object.wait() [0x044df000..0x044dfce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon.nextTask(ClockDaemon.java:328) - locked <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:362) at java.lang.Thread.run(Thread.java:619) "ElementEventQueue.QProcessor-1" daemon prio=6 tid=0x050f2800 nid=0x17d0 in Object.wait() [0x0442f000..0x0442fd68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b81398> (a java.lang.Object) at java.lang.Object.wait(Object.java:485) at org.apache.jcs.engine.control.event.ElementEventQueue.take(ElementEventQueue.java:181) - locked <0x23b81398> (a java.lang.Object) at org.apache.jcs.engine.control.event.ElementEventQueue.access$300(ElementEventQueue.java:35) at org.apache.jcs.engine.control.event.ElementEventQueue$QProcessor.run(ElementEventQueue.java:245) "Low Memory Detector" daemon prio=6 tid=0x0215c800 nid=0x1370 runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "CompilerThread0" daemon prio=10 tid=0x02156400 nid=0x758 waiting on condition [0x00000000..0x0433f890] java.lang.Thread.State: RUNNABLE "Attach Listener" daemon prio=10 tid=0x02155400 nid=0x14f4 waiting on condition [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" daemon prio=10 tid=0x0214ac00 nid=0x151c runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Finalizer" daemon prio=8 tid=0x02143000 nid=0x430 in Object.wait() [0x0424f000..0x0424fce8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116) - locked <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x02141000 nid=0x510 in Object.wait() [0x0091f000..0x0091fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e7e8> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:485) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) - locked <0x2394e7e8> (a java.lang.ref.Reference$Lock) "main" prio=6 tid=0x0020a800 nid=0xef4 runnable [0x0025f000..0x0025fe28] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e18dc0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.catalina.core.StandardServer.await(StandardServer.java:389) at org.apache.catalina.startup.Catalina.await(Catalina.java:642) at org.apache.catalina.startup.Catalina.start(Catalina.java:602) 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.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288) at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413) "VM Thread" prio=10 tid=0x0213fc00 nid=0xdc0 runnable "VM Periodic Task Thread" prio=10 tid=0x0215dc00 nid=0x1128 waiting on condition JNI global references: 781 i also attach my logback configuration: <?xml version="1.0" encoding="UTF-8"?> <configuration debug="true"> <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> Operator %X{client}: %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> <!-- <appender name="file" class="ch.qos.logback.core.FileAppender" > <File>imsm-debug.log</File> <Append>false</Append> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> --> <logger name="net.sf.jguard.core" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.authorization" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.filters" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.ext" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.jee" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.ehcache" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.util" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.jguard" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBUserImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBGroupImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBOperatorImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBInstitutionImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="org.apache.jcs" additivity="false"> <level value="WARN" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <root> <!-- The following level element is not necessary since the --> <!-- level of the root level is set to DEBUG by default. --> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </root> </configuration>
-- 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
[ http://jira.qos.ch/browse/LBCORE-96?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn commented on LBCORE-96: ------------------------------------- I just did a test using the above example and it looks good with the patch applied. Without the patch, threads are executed unevenly. 2009-05-19 22:21:49,481 DEBUG [pool-2-thread-1] [MAIN] - [EX2] 54803 2009-05-19 22:21:49,481 DEBUG [pool-4-thread-1] [MAIN] - [EX4] 54803 2009-05-19 22:21:49,481 DEBUG [pool-2-thread-1] [EX2] 54803 2009-05-19 22:21:49,481 DEBUG [pool-2-thread-1] [MAIN] - [EX2] 54803 2009-05-19 22:21:49,481 DEBUG [pool-4-thread-1] [EX4] 54803 2009-05-19 22:21:49,481 DEBUG [pool-3-thread-1] [EX3] 54803 2009-05-19 22:21:49,481 DEBUG [pool-1-thread-1] [MAIN] - [EX1] 54805 2009-05-19 22:21:49,481 DEBUG [pool-5-thread-1] [EX5] 54803 2009-05-19 22:21:49,482 DEBUG [pool-5-thread-1] [MAIN] - [EX5] 54804 2009-05-19 22:21:49,481 DEBUG [pool-4-thread-1] [MAIN] - [EX4] 54803 2009-05-19 22:21:49,482 DEBUG [pool-1-thread-1] [EX1] 54806 2009-05-19 22:21:49,481 DEBUG [pool-2-thread-1] [EX2] 54803 2009-05-19 22:21:49,481 DEBUG [pool-3-thread-1] [MAIN] - [EX3] 54803 2009-05-19 22:21:49,482 DEBUG [pool-5-thread-1] [EX5] 54804 2009-05-19 22:21:49,482 DEBUG [pool-4-thread-1] [EX4] 54804 2009-05-19 22:21:49,482 DEBUG [pool-1-thread-1] [MAIN] - [EX1] 54806 2009-05-19 22:21:49,482 DEBUG [pool-2-thread-1] [MAIN] - [EX2] 54804 2009-05-19 22:21:49,482 DEBUG [pool-3-thread-1] [EX3] 54804 2009-05-19 22:21:49,482 DEBUG [pool-5-thread-1] [MAIN] - [EX5] 54804 2009-05-19 22:21:49,482 DEBUG [pool-3-thread-1] [MAIN] - [EX3] 54804 2009-05-19 22:21:49,482 DEBUG [pool-1-thread-1] [EX1] 54806 2009-05-19 22:21:49,482 DEBUG [pool-1-thread-1] [MAIN] - [EX1] 54806 2009-05-19 22:21:49,482 DEBUG [pool-4-thread-1] [MAIN] - [EX4] 54804 With the patch they are running evenly as I'd expect it. 2009-05-19 22:03:14,520 DEBUG [pool-5-thread-1] [EX5] 5900 2009-05-19 22:03:14,520 DEBUG [pool-4-thread-1] [EX4] 5925 2009-05-19 22:03:14,520 DEBUG [pool-1-thread-1] [EX1] 5936 2009-05-19 22:03:14,520 DEBUG [pool-3-thread-1] [MAIN] - [EX3] 5925 2009-05-19 22:03:14,520 DEBUG [pool-2-thread-1] [EX2] 5926 2009-05-19 22:03:14,520 DEBUG [pool-5-thread-1] [MAIN] - [EX5] 5900 2009-05-19 22:03:14,520 DEBUG [pool-4-thread-1] [MAIN] - [EX4] 5925 2009-05-19 22:03:14,521 DEBUG [pool-1-thread-1] [MAIN] - [EX1] 5937 2009-05-19 22:03:14,521 DEBUG [pool-3-thread-1] [EX3] 5926 2009-05-19 22:03:14,521 DEBUG [pool-2-thread-1] [MAIN] - [EX2] 5927 2009-05-19 22:03:14,521 DEBUG [pool-5-thread-1] [EX5] 5901 2009-05-19 22:03:14,521 DEBUG [pool-4-thread-1] [EX4] 5926 2009-05-19 22:03:14,521 DEBUG [pool-1-thread-1] [EX1] 5937 What do you think?
Deadlock when running on multiple core processors -------------------------------------------------
Key: LBCORE-96 URL: http://jira.qos.ch/browse/LBCORE-96 Project: logback-core Issue Type: Bug Components: Appender Affects Versions: 0.9.15 Environment: Windows Vista quad core Apache Tomcat 6.0.18 JDK 1.6 Reporter: Lars Feistner Assignee: Logback dev list Attachments: AppenderBaseLock.patch
As Robert Dale mentioned on 23/Mar/09 04:05 PM I'm getting that deadlock in logback core (0.9.14 and 0.9.15). No console plugin or socket appenders, just plain RollingFileAppender. I am getting the deadlock using ConsoleAppender. see attached thread dump: 2009-04-06 11:49:45 Full thread dump Java HotSpot(TM) Client VM (11.0-b12 mixed mode, sharing): "http-8084-5" daemon prio=6 tid=0x04700c00 nid=0xc54 in Object.wait() [0x05d1f000..0x05d1fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-4" daemon prio=6 tid=0x04700000 nid=0xe24 in Object.wait() [0x05c7f000..0x05c7fbe8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-3" daemon prio=6 tid=0x04700400 nid=0x134c waiting for monitor entry [0x05c2f000..0x05c2fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "Thread-10" daemon prio=6 tid=0x046ff800 nid=0x122c runnable [0x05bdf000..0x05bdfb68] java.lang.Thread.State: RUNNABLE at sun.net.dns.ResolverConfigurationImpl.notifyAddrChange0(Native Method) at sun.net.dns.ResolverConfigurationImpl$AddressChangeListener.run(ResolverConfigurationImpl.java:125) "http-8084-2" daemon prio=6 tid=0x046ff400 nid=0x17f4 waiting for monitor entry [0x05b8f000..0x05b8fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "TP-Monitor" daemon prio=6 tid=0x04a17400 nid=0x830 in Object.wait() [0x05b3f000..0x05b3fce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable.run(ThreadPool.java:565) - locked <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor4" daemon prio=6 tid=0x0497a000 nid=0x11dc runnable [0x05a8f000..0x05a8fd68] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e0a9b0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.jk.common.ChannelSocket.accept(ChannelSocket.java:306) at org.apache.jk.common.ChannelSocket.acceptConnections(ChannelSocket.java:660) at org.apache.jk.common.ChannelSocket$SocketAcceptor.runIt(ChannelSocket.java:870) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690) at java.lang.Thread.run(Thread.java:619) "TP-Processor3" daemon prio=6 tid=0x04979c00 nid=0xfe8 in Object.wait() [0x05a3f000..0x05a3f9e8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor2" daemon prio=6 tid=0x04982800 nid=0x10bc in Object.wait() [0x059ef000..0x059efa68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor1" daemon prio=6 tid=0x04982000 nid=0x131c in Object.wait() [0x0599f000..0x0599fae8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "http-8084-1" daemon prio=6 tid=0x04917000 nid=0x15f4 runnable [0x0594f000..0x0594fb68] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:260) at java.io.BufferedOutputStream.write(BufferedOutputStream.java:105) - locked <0x2395d280> (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:430) - locked <0x23951d08> (a java.io.PrintStream) at org.apache.tomcat.util.log.SystemLogHandler.write(SystemLogHandler.java:166) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272) at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276) at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122) - locked <0x23b1c1f0> (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212) at ch.qos.logback.core.WriterAppender.writerWrite(WriterAppender.java:245) 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 <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:92) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "http-8084-Acceptor-0" daemon prio=6 tid=0x049c2400 nid=0x129c runnable [0x058bf000..0x058bfbe8] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23a40168> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.tomcat.util.net.DefaultServerSocketFactory.acceptSocket(DefaultServerSocketFactory.java:61) at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:310) at java.lang.Thread.run(Thread.java:619) "ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=6 tid=0x051c9800 nid=0x152c waiting on condition [0x0452f000..0x0452fc68] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1579) at java.lang.Thread.run(Thread.java:619) "Thread-1" daemon prio=2 tid=0x04638c00 nid=0x1360 in Object.wait() [0x044df000..0x044dfce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon.nextTask(ClockDaemon.java:328) - locked <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:362) at java.lang.Thread.run(Thread.java:619) "ElementEventQueue.QProcessor-1" daemon prio=6 tid=0x050f2800 nid=0x17d0 in Object.wait() [0x0442f000..0x0442fd68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b81398> (a java.lang.Object) at java.lang.Object.wait(Object.java:485) at org.apache.jcs.engine.control.event.ElementEventQueue.take(ElementEventQueue.java:181) - locked <0x23b81398> (a java.lang.Object) at org.apache.jcs.engine.control.event.ElementEventQueue.access$300(ElementEventQueue.java:35) at org.apache.jcs.engine.control.event.ElementEventQueue$QProcessor.run(ElementEventQueue.java:245) "Low Memory Detector" daemon prio=6 tid=0x0215c800 nid=0x1370 runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "CompilerThread0" daemon prio=10 tid=0x02156400 nid=0x758 waiting on condition [0x00000000..0x0433f890] java.lang.Thread.State: RUNNABLE "Attach Listener" daemon prio=10 tid=0x02155400 nid=0x14f4 waiting on condition [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" daemon prio=10 tid=0x0214ac00 nid=0x151c runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Finalizer" daemon prio=8 tid=0x02143000 nid=0x430 in Object.wait() [0x0424f000..0x0424fce8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116) - locked <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x02141000 nid=0x510 in Object.wait() [0x0091f000..0x0091fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e7e8> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:485) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) - locked <0x2394e7e8> (a java.lang.ref.Reference$Lock) "main" prio=6 tid=0x0020a800 nid=0xef4 runnable [0x0025f000..0x0025fe28] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e18dc0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.catalina.core.StandardServer.await(StandardServer.java:389) at org.apache.catalina.startup.Catalina.await(Catalina.java:642) at org.apache.catalina.startup.Catalina.start(Catalina.java:602) 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.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288) at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413) "VM Thread" prio=10 tid=0x0213fc00 nid=0xdc0 runnable "VM Periodic Task Thread" prio=10 tid=0x0215dc00 nid=0x1128 waiting on condition JNI global references: 781 i also attach my logback configuration: <?xml version="1.0" encoding="UTF-8"?> <configuration debug="true"> <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> Operator %X{client}: %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> <!-- <appender name="file" class="ch.qos.logback.core.FileAppender" > <File>imsm-debug.log</File> <Append>false</Append> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> --> <logger name="net.sf.jguard.core" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.authorization" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.filters" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.ext" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.jee" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.ehcache" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.util" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.jguard" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBUserImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBGroupImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBOperatorImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBInstitutionImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="org.apache.jcs" additivity="false"> <level value="WARN" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <root> <!-- The following level element is not necessary since the --> <!-- level of the root level is set to DEBUG by default. --> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </root> </configuration>
-- 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
[ http://jira.qos.ch/browse/LBCORE-96?page=com.atlassian.jira.plugin.system.is... ] Joern Huxhorn commented on LBCORE-96: ------------------------------------- I just wanted to point out that this is a very serious issue for us. We are completely out of logs in our webapp atm because we can't risk a congestion...
Deadlock when running on multiple core processors -------------------------------------------------
Key: LBCORE-96 URL: http://jira.qos.ch/browse/LBCORE-96 Project: logback-core Issue Type: Bug Components: Appender Affects Versions: 0.9.15 Environment: Windows Vista quad core Apache Tomcat 6.0.18 JDK 1.6 Reporter: Lars Feistner Assignee: Logback dev list Attachments: AppenderBaseLock.patch
As Robert Dale mentioned on 23/Mar/09 04:05 PM I'm getting that deadlock in logback core (0.9.14 and 0.9.15). No console plugin or socket appenders, just plain RollingFileAppender. I am getting the deadlock using ConsoleAppender. see attached thread dump: 2009-04-06 11:49:45 Full thread dump Java HotSpot(TM) Client VM (11.0-b12 mixed mode, sharing): "http-8084-5" daemon prio=6 tid=0x04700c00 nid=0xc54 in Object.wait() [0x05d1f000..0x05d1fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-4" daemon prio=6 tid=0x04700000 nid=0xe24 in Object.wait() [0x05c7f000..0x05c7fbe8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-3" daemon prio=6 tid=0x04700400 nid=0x134c waiting for monitor entry [0x05c2f000..0x05c2fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "Thread-10" daemon prio=6 tid=0x046ff800 nid=0x122c runnable [0x05bdf000..0x05bdfb68] java.lang.Thread.State: RUNNABLE at sun.net.dns.ResolverConfigurationImpl.notifyAddrChange0(Native Method) at sun.net.dns.ResolverConfigurationImpl$AddressChangeListener.run(ResolverConfigurationImpl.java:125) "http-8084-2" daemon prio=6 tid=0x046ff400 nid=0x17f4 waiting for monitor entry [0x05b8f000..0x05b8fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "TP-Monitor" daemon prio=6 tid=0x04a17400 nid=0x830 in Object.wait() [0x05b3f000..0x05b3fce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable.run(ThreadPool.java:565) - locked <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor4" daemon prio=6 tid=0x0497a000 nid=0x11dc runnable [0x05a8f000..0x05a8fd68] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e0a9b0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.jk.common.ChannelSocket.accept(ChannelSocket.java:306) at org.apache.jk.common.ChannelSocket.acceptConnections(ChannelSocket.java:660) at org.apache.jk.common.ChannelSocket$SocketAcceptor.runIt(ChannelSocket.java:870) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690) at java.lang.Thread.run(Thread.java:619) "TP-Processor3" daemon prio=6 tid=0x04979c00 nid=0xfe8 in Object.wait() [0x05a3f000..0x05a3f9e8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor2" daemon prio=6 tid=0x04982800 nid=0x10bc in Object.wait() [0x059ef000..0x059efa68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor1" daemon prio=6 tid=0x04982000 nid=0x131c in Object.wait() [0x0599f000..0x0599fae8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "http-8084-1" daemon prio=6 tid=0x04917000 nid=0x15f4 runnable [0x0594f000..0x0594fb68] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:260) at java.io.BufferedOutputStream.write(BufferedOutputStream.java:105) - locked <0x2395d280> (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:430) - locked <0x23951d08> (a java.io.PrintStream) at org.apache.tomcat.util.log.SystemLogHandler.write(SystemLogHandler.java:166) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272) at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276) at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122) - locked <0x23b1c1f0> (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212) at ch.qos.logback.core.WriterAppender.writerWrite(WriterAppender.java:245) 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 <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:92) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "http-8084-Acceptor-0" daemon prio=6 tid=0x049c2400 nid=0x129c runnable [0x058bf000..0x058bfbe8] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23a40168> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.tomcat.util.net.DefaultServerSocketFactory.acceptSocket(DefaultServerSocketFactory.java:61) at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:310) at java.lang.Thread.run(Thread.java:619) "ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=6 tid=0x051c9800 nid=0x152c waiting on condition [0x0452f000..0x0452fc68] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1579) at java.lang.Thread.run(Thread.java:619) "Thread-1" daemon prio=2 tid=0x04638c00 nid=0x1360 in Object.wait() [0x044df000..0x044dfce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon.nextTask(ClockDaemon.java:328) - locked <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:362) at java.lang.Thread.run(Thread.java:619) "ElementEventQueue.QProcessor-1" daemon prio=6 tid=0x050f2800 nid=0x17d0 in Object.wait() [0x0442f000..0x0442fd68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b81398> (a java.lang.Object) at java.lang.Object.wait(Object.java:485) at org.apache.jcs.engine.control.event.ElementEventQueue.take(ElementEventQueue.java:181) - locked <0x23b81398> (a java.lang.Object) at org.apache.jcs.engine.control.event.ElementEventQueue.access$300(ElementEventQueue.java:35) at org.apache.jcs.engine.control.event.ElementEventQueue$QProcessor.run(ElementEventQueue.java:245) "Low Memory Detector" daemon prio=6 tid=0x0215c800 nid=0x1370 runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "CompilerThread0" daemon prio=10 tid=0x02156400 nid=0x758 waiting on condition [0x00000000..0x0433f890] java.lang.Thread.State: RUNNABLE "Attach Listener" daemon prio=10 tid=0x02155400 nid=0x14f4 waiting on condition [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" daemon prio=10 tid=0x0214ac00 nid=0x151c runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Finalizer" daemon prio=8 tid=0x02143000 nid=0x430 in Object.wait() [0x0424f000..0x0424fce8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116) - locked <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x02141000 nid=0x510 in Object.wait() [0x0091f000..0x0091fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e7e8> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:485) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) - locked <0x2394e7e8> (a java.lang.ref.Reference$Lock) "main" prio=6 tid=0x0020a800 nid=0xef4 runnable [0x0025f000..0x0025fe28] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e18dc0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.catalina.core.StandardServer.await(StandardServer.java:389) at org.apache.catalina.startup.Catalina.await(Catalina.java:642) at org.apache.catalina.startup.Catalina.start(Catalina.java:602) 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.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288) at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413) "VM Thread" prio=10 tid=0x0213fc00 nid=0xdc0 runnable "VM Periodic Task Thread" prio=10 tid=0x0215dc00 nid=0x1128 waiting on condition JNI global references: 781 i also attach my logback configuration: <?xml version="1.0" encoding="UTF-8"?> <configuration debug="true"> <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> Operator %X{client}: %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> <!-- <appender name="file" class="ch.qos.logback.core.FileAppender" > <File>imsm-debug.log</File> <Append>false</Append> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> --> <logger name="net.sf.jguard.core" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.authorization" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.filters" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.ext" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.jee" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.ehcache" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.util" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.jguard" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBUserImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBGroupImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBOperatorImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBInstitutionImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="org.apache.jcs" additivity="false"> <level value="WARN" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <root> <!-- The following level element is not necessary since the --> <!-- level of the root level is set to DEBUG by default. --> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </root> </configuration>
-- 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
[ http://jira.qos.ch/browse/LBCORE-96?page=com.atlassian.jira.plugin.system.is... ] Ceki Gulcu commented on LBCORE-96: ---------------------------------- Logback is using the standard synchronization mechanism found in the JDK. You are saying that that mechanism is unsuitable which, truth be told, sounds quite suspicious.
Deadlock when running on multiple core processors -------------------------------------------------
Key: LBCORE-96 URL: http://jira.qos.ch/browse/LBCORE-96 Project: logback-core Issue Type: Bug Components: Appender Affects Versions: 0.9.15 Environment: Windows Vista quad core Apache Tomcat 6.0.18 JDK 1.6 Reporter: Lars Feistner Assignee: Logback dev list Attachments: AppenderBaseLock.patch
As Robert Dale mentioned on 23/Mar/09 04:05 PM I'm getting that deadlock in logback core (0.9.14 and 0.9.15). No console plugin or socket appenders, just plain RollingFileAppender. I am getting the deadlock using ConsoleAppender. see attached thread dump: 2009-04-06 11:49:45 Full thread dump Java HotSpot(TM) Client VM (11.0-b12 mixed mode, sharing): "http-8084-5" daemon prio=6 tid=0x04700c00 nid=0xc54 in Object.wait() [0x05d1f000..0x05d1fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-4" daemon prio=6 tid=0x04700000 nid=0xe24 in Object.wait() [0x05c7f000..0x05c7fbe8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-3" daemon prio=6 tid=0x04700400 nid=0x134c waiting for monitor entry [0x05c2f000..0x05c2fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "Thread-10" daemon prio=6 tid=0x046ff800 nid=0x122c runnable [0x05bdf000..0x05bdfb68] java.lang.Thread.State: RUNNABLE at sun.net.dns.ResolverConfigurationImpl.notifyAddrChange0(Native Method) at sun.net.dns.ResolverConfigurationImpl$AddressChangeListener.run(ResolverConfigurationImpl.java:125) "http-8084-2" daemon prio=6 tid=0x046ff400 nid=0x17f4 waiting for monitor entry [0x05b8f000..0x05b8fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "TP-Monitor" daemon prio=6 tid=0x04a17400 nid=0x830 in Object.wait() [0x05b3f000..0x05b3fce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable.run(ThreadPool.java:565) - locked <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor4" daemon prio=6 tid=0x0497a000 nid=0x11dc runnable [0x05a8f000..0x05a8fd68] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e0a9b0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.jk.common.ChannelSocket.accept(ChannelSocket.java:306) at org.apache.jk.common.ChannelSocket.acceptConnections(ChannelSocket.java:660) at org.apache.jk.common.ChannelSocket$SocketAcceptor.runIt(ChannelSocket.java:870) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690) at java.lang.Thread.run(Thread.java:619) "TP-Processor3" daemon prio=6 tid=0x04979c00 nid=0xfe8 in Object.wait() [0x05a3f000..0x05a3f9e8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor2" daemon prio=6 tid=0x04982800 nid=0x10bc in Object.wait() [0x059ef000..0x059efa68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor1" daemon prio=6 tid=0x04982000 nid=0x131c in Object.wait() [0x0599f000..0x0599fae8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "http-8084-1" daemon prio=6 tid=0x04917000 nid=0x15f4 runnable [0x0594f000..0x0594fb68] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:260) at java.io.BufferedOutputStream.write(BufferedOutputStream.java:105) - locked <0x2395d280> (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:430) - locked <0x23951d08> (a java.io.PrintStream) at org.apache.tomcat.util.log.SystemLogHandler.write(SystemLogHandler.java:166) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272) at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276) at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122) - locked <0x23b1c1f0> (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212) at ch.qos.logback.core.WriterAppender.writerWrite(WriterAppender.java:245) 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 <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:92) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "http-8084-Acceptor-0" daemon prio=6 tid=0x049c2400 nid=0x129c runnable [0x058bf000..0x058bfbe8] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23a40168> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.tomcat.util.net.DefaultServerSocketFactory.acceptSocket(DefaultServerSocketFactory.java:61) at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:310) at java.lang.Thread.run(Thread.java:619) "ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=6 tid=0x051c9800 nid=0x152c waiting on condition [0x0452f000..0x0452fc68] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1579) at java.lang.Thread.run(Thread.java:619) "Thread-1" daemon prio=2 tid=0x04638c00 nid=0x1360 in Object.wait() [0x044df000..0x044dfce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon.nextTask(ClockDaemon.java:328) - locked <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:362) at java.lang.Thread.run(Thread.java:619) "ElementEventQueue.QProcessor-1" daemon prio=6 tid=0x050f2800 nid=0x17d0 in Object.wait() [0x0442f000..0x0442fd68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b81398> (a java.lang.Object) at java.lang.Object.wait(Object.java:485) at org.apache.jcs.engine.control.event.ElementEventQueue.take(ElementEventQueue.java:181) - locked <0x23b81398> (a java.lang.Object) at org.apache.jcs.engine.control.event.ElementEventQueue.access$300(ElementEventQueue.java:35) at org.apache.jcs.engine.control.event.ElementEventQueue$QProcessor.run(ElementEventQueue.java:245) "Low Memory Detector" daemon prio=6 tid=0x0215c800 nid=0x1370 runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "CompilerThread0" daemon prio=10 tid=0x02156400 nid=0x758 waiting on condition [0x00000000..0x0433f890] java.lang.Thread.State: RUNNABLE "Attach Listener" daemon prio=10 tid=0x02155400 nid=0x14f4 waiting on condition [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" daemon prio=10 tid=0x0214ac00 nid=0x151c runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Finalizer" daemon prio=8 tid=0x02143000 nid=0x430 in Object.wait() [0x0424f000..0x0424fce8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116) - locked <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x02141000 nid=0x510 in Object.wait() [0x0091f000..0x0091fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e7e8> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:485) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) - locked <0x2394e7e8> (a java.lang.ref.Reference$Lock) "main" prio=6 tid=0x0020a800 nid=0xef4 runnable [0x0025f000..0x0025fe28] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e18dc0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.catalina.core.StandardServer.await(StandardServer.java:389) at org.apache.catalina.startup.Catalina.await(Catalina.java:642) at org.apache.catalina.startup.Catalina.start(Catalina.java:602) 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.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288) at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413) "VM Thread" prio=10 tid=0x0213fc00 nid=0xdc0 runnable "VM Periodic Task Thread" prio=10 tid=0x0215dc00 nid=0x1128 waiting on condition JNI global references: 781 i also attach my logback configuration: <?xml version="1.0" encoding="UTF-8"?> <configuration debug="true"> <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> Operator %X{client}: %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> <!-- <appender name="file" class="ch.qos.logback.core.FileAppender" > <File>imsm-debug.log</File> <Append>false</Append> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> --> <logger name="net.sf.jguard.core" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.authorization" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.filters" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.ext" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.jee" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.ehcache" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.util" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.jguard" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBUserImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBGroupImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBOperatorImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBInstitutionImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="org.apache.jcs" additivity="false"> <level value="WARN" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <root> <!-- The following level element is not necessary since the --> <!-- level of the root level is set to DEBUG by default. --> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </root> </configuration>
-- 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
[ http://jira.qos.ch/browse/LBCORE-96?page=com.atlassian.jira.plugin.system.is... ] Ceki Gulcu resolved LBCORE-96. ------------------------------ Resolution: Won't Fix Without a test case, I can't reproduce the problem.
Deadlock when running on multiple core processors -------------------------------------------------
Key: LBCORE-96 URL: http://jira.qos.ch/browse/LBCORE-96 Project: logback-core Issue Type: Bug Components: Appender Affects Versions: 0.9.15 Environment: Windows Vista quad core Apache Tomcat 6.0.18 JDK 1.6 Reporter: Lars Feistner Assignee: Logback dev list Attachments: AppenderBaseLock.patch
As Robert Dale mentioned on 23/Mar/09 04:05 PM I'm getting that deadlock in logback core (0.9.14 and 0.9.15). No console plugin or socket appenders, just plain RollingFileAppender. I am getting the deadlock using ConsoleAppender. see attached thread dump: 2009-04-06 11:49:45 Full thread dump Java HotSpot(TM) Client VM (11.0-b12 mixed mode, sharing): "http-8084-5" daemon prio=6 tid=0x04700c00 nid=0xc54 in Object.wait() [0x05d1f000..0x05d1fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-4" daemon prio=6 tid=0x04700000 nid=0xe24 in Object.wait() [0x05c7f000..0x05c7fbe8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-3" daemon prio=6 tid=0x04700400 nid=0x134c waiting for monitor entry [0x05c2f000..0x05c2fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "Thread-10" daemon prio=6 tid=0x046ff800 nid=0x122c runnable [0x05bdf000..0x05bdfb68] java.lang.Thread.State: RUNNABLE at sun.net.dns.ResolverConfigurationImpl.notifyAddrChange0(Native Method) at sun.net.dns.ResolverConfigurationImpl$AddressChangeListener.run(ResolverConfigurationImpl.java:125) "http-8084-2" daemon prio=6 tid=0x046ff400 nid=0x17f4 waiting for monitor entry [0x05b8f000..0x05b8fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "TP-Monitor" daemon prio=6 tid=0x04a17400 nid=0x830 in Object.wait() [0x05b3f000..0x05b3fce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable.run(ThreadPool.java:565) - locked <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor4" daemon prio=6 tid=0x0497a000 nid=0x11dc runnable [0x05a8f000..0x05a8fd68] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e0a9b0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.jk.common.ChannelSocket.accept(ChannelSocket.java:306) at org.apache.jk.common.ChannelSocket.acceptConnections(ChannelSocket.java:660) at org.apache.jk.common.ChannelSocket$SocketAcceptor.runIt(ChannelSocket.java:870) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690) at java.lang.Thread.run(Thread.java:619) "TP-Processor3" daemon prio=6 tid=0x04979c00 nid=0xfe8 in Object.wait() [0x05a3f000..0x05a3f9e8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor2" daemon prio=6 tid=0x04982800 nid=0x10bc in Object.wait() [0x059ef000..0x059efa68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor1" daemon prio=6 tid=0x04982000 nid=0x131c in Object.wait() [0x0599f000..0x0599fae8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "http-8084-1" daemon prio=6 tid=0x04917000 nid=0x15f4 runnable [0x0594f000..0x0594fb68] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:260) at java.io.BufferedOutputStream.write(BufferedOutputStream.java:105) - locked <0x2395d280> (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:430) - locked <0x23951d08> (a java.io.PrintStream) at org.apache.tomcat.util.log.SystemLogHandler.write(SystemLogHandler.java:166) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272) at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276) at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122) - locked <0x23b1c1f0> (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212) at ch.qos.logback.core.WriterAppender.writerWrite(WriterAppender.java:245) 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 <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:92) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "http-8084-Acceptor-0" daemon prio=6 tid=0x049c2400 nid=0x129c runnable [0x058bf000..0x058bfbe8] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23a40168> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.tomcat.util.net.DefaultServerSocketFactory.acceptSocket(DefaultServerSocketFactory.java:61) at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:310) at java.lang.Thread.run(Thread.java:619) "ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=6 tid=0x051c9800 nid=0x152c waiting on condition [0x0452f000..0x0452fc68] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1579) at java.lang.Thread.run(Thread.java:619) "Thread-1" daemon prio=2 tid=0x04638c00 nid=0x1360 in Object.wait() [0x044df000..0x044dfce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon.nextTask(ClockDaemon.java:328) - locked <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:362) at java.lang.Thread.run(Thread.java:619) "ElementEventQueue.QProcessor-1" daemon prio=6 tid=0x050f2800 nid=0x17d0 in Object.wait() [0x0442f000..0x0442fd68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b81398> (a java.lang.Object) at java.lang.Object.wait(Object.java:485) at org.apache.jcs.engine.control.event.ElementEventQueue.take(ElementEventQueue.java:181) - locked <0x23b81398> (a java.lang.Object) at org.apache.jcs.engine.control.event.ElementEventQueue.access$300(ElementEventQueue.java:35) at org.apache.jcs.engine.control.event.ElementEventQueue$QProcessor.run(ElementEventQueue.java:245) "Low Memory Detector" daemon prio=6 tid=0x0215c800 nid=0x1370 runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "CompilerThread0" daemon prio=10 tid=0x02156400 nid=0x758 waiting on condition [0x00000000..0x0433f890] java.lang.Thread.State: RUNNABLE "Attach Listener" daemon prio=10 tid=0x02155400 nid=0x14f4 waiting on condition [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" daemon prio=10 tid=0x0214ac00 nid=0x151c runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Finalizer" daemon prio=8 tid=0x02143000 nid=0x430 in Object.wait() [0x0424f000..0x0424fce8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116) - locked <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x02141000 nid=0x510 in Object.wait() [0x0091f000..0x0091fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e7e8> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:485) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) - locked <0x2394e7e8> (a java.lang.ref.Reference$Lock) "main" prio=6 tid=0x0020a800 nid=0xef4 runnable [0x0025f000..0x0025fe28] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e18dc0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.catalina.core.StandardServer.await(StandardServer.java:389) at org.apache.catalina.startup.Catalina.await(Catalina.java:642) at org.apache.catalina.startup.Catalina.start(Catalina.java:602) 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.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288) at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413) "VM Thread" prio=10 tid=0x0213fc00 nid=0xdc0 runnable "VM Periodic Task Thread" prio=10 tid=0x0215dc00 nid=0x1128 waiting on condition JNI global references: 781 i also attach my logback configuration: <?xml version="1.0" encoding="UTF-8"?> <configuration debug="true"> <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> Operator %X{client}: %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> <!-- <appender name="file" class="ch.qos.logback.core.FileAppender" > <File>imsm-debug.log</File> <Append>false</Append> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> --> <logger name="net.sf.jguard.core" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.authorization" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.filters" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.ext" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.jee" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.ehcache" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.util" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.jguard" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBUserImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBGroupImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBOperatorImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBInstitutionImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="org.apache.jcs" additivity="false"> <level value="WARN" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <root> <!-- The following level element is not necessary since the --> <!-- level of the root level is set to DEBUG by default. --> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </root> </configuration>
-- 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
[ http://jira.qos.ch/browse/LBCORE-96?page=com.atlassian.jira.plugin.system.is... ] Ceki Gulcu closed LBCORE-96. ----------------------------
Deadlock when running on multiple core processors -------------------------------------------------
Key: LBCORE-96 URL: http://jira.qos.ch/browse/LBCORE-96 Project: logback-core Issue Type: Bug Components: Appender Affects Versions: 0.9.15 Environment: Windows Vista quad core Apache Tomcat 6.0.18 JDK 1.6 Reporter: Lars Feistner Assignee: Logback dev list Attachments: AppenderBaseLock.patch
As Robert Dale mentioned on 23/Mar/09 04:05 PM I'm getting that deadlock in logback core (0.9.14 and 0.9.15). No console plugin or socket appenders, just plain RollingFileAppender. I am getting the deadlock using ConsoleAppender. see attached thread dump: 2009-04-06 11:49:45 Full thread dump Java HotSpot(TM) Client VM (11.0-b12 mixed mode, sharing): "http-8084-5" daemon prio=6 tid=0x04700c00 nid=0xc54 in Object.wait() [0x05d1f000..0x05d1fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-4" daemon prio=6 tid=0x04700000 nid=0xe24 in Object.wait() [0x05c7f000..0x05c7fbe8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-3" daemon prio=6 tid=0x04700400 nid=0x134c waiting for monitor entry [0x05c2f000..0x05c2fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "Thread-10" daemon prio=6 tid=0x046ff800 nid=0x122c runnable [0x05bdf000..0x05bdfb68] java.lang.Thread.State: RUNNABLE at sun.net.dns.ResolverConfigurationImpl.notifyAddrChange0(Native Method) at sun.net.dns.ResolverConfigurationImpl$AddressChangeListener.run(ResolverConfigurationImpl.java:125) "http-8084-2" daemon prio=6 tid=0x046ff400 nid=0x17f4 waiting for monitor entry [0x05b8f000..0x05b8fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "TP-Monitor" daemon prio=6 tid=0x04a17400 nid=0x830 in Object.wait() [0x05b3f000..0x05b3fce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable.run(ThreadPool.java:565) - locked <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor4" daemon prio=6 tid=0x0497a000 nid=0x11dc runnable [0x05a8f000..0x05a8fd68] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e0a9b0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.jk.common.ChannelSocket.accept(ChannelSocket.java:306) at org.apache.jk.common.ChannelSocket.acceptConnections(ChannelSocket.java:660) at org.apache.jk.common.ChannelSocket$SocketAcceptor.runIt(ChannelSocket.java:870) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690) at java.lang.Thread.run(Thread.java:619) "TP-Processor3" daemon prio=6 tid=0x04979c00 nid=0xfe8 in Object.wait() [0x05a3f000..0x05a3f9e8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor2" daemon prio=6 tid=0x04982800 nid=0x10bc in Object.wait() [0x059ef000..0x059efa68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor1" daemon prio=6 tid=0x04982000 nid=0x131c in Object.wait() [0x0599f000..0x0599fae8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "http-8084-1" daemon prio=6 tid=0x04917000 nid=0x15f4 runnable [0x0594f000..0x0594fb68] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:260) at java.io.BufferedOutputStream.write(BufferedOutputStream.java:105) - locked <0x2395d280> (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:430) - locked <0x23951d08> (a java.io.PrintStream) at org.apache.tomcat.util.log.SystemLogHandler.write(SystemLogHandler.java:166) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272) at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276) at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122) - locked <0x23b1c1f0> (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212) at ch.qos.logback.core.WriterAppender.writerWrite(WriterAppender.java:245) 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 <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:92) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "http-8084-Acceptor-0" daemon prio=6 tid=0x049c2400 nid=0x129c runnable [0x058bf000..0x058bfbe8] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23a40168> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.tomcat.util.net.DefaultServerSocketFactory.acceptSocket(DefaultServerSocketFactory.java:61) at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:310) at java.lang.Thread.run(Thread.java:619) "ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=6 tid=0x051c9800 nid=0x152c waiting on condition [0x0452f000..0x0452fc68] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1579) at java.lang.Thread.run(Thread.java:619) "Thread-1" daemon prio=2 tid=0x04638c00 nid=0x1360 in Object.wait() [0x044df000..0x044dfce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon.nextTask(ClockDaemon.java:328) - locked <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:362) at java.lang.Thread.run(Thread.java:619) "ElementEventQueue.QProcessor-1" daemon prio=6 tid=0x050f2800 nid=0x17d0 in Object.wait() [0x0442f000..0x0442fd68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b81398> (a java.lang.Object) at java.lang.Object.wait(Object.java:485) at org.apache.jcs.engine.control.event.ElementEventQueue.take(ElementEventQueue.java:181) - locked <0x23b81398> (a java.lang.Object) at org.apache.jcs.engine.control.event.ElementEventQueue.access$300(ElementEventQueue.java:35) at org.apache.jcs.engine.control.event.ElementEventQueue$QProcessor.run(ElementEventQueue.java:245) "Low Memory Detector" daemon prio=6 tid=0x0215c800 nid=0x1370 runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "CompilerThread0" daemon prio=10 tid=0x02156400 nid=0x758 waiting on condition [0x00000000..0x0433f890] java.lang.Thread.State: RUNNABLE "Attach Listener" daemon prio=10 tid=0x02155400 nid=0x14f4 waiting on condition [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" daemon prio=10 tid=0x0214ac00 nid=0x151c runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Finalizer" daemon prio=8 tid=0x02143000 nid=0x430 in Object.wait() [0x0424f000..0x0424fce8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116) - locked <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x02141000 nid=0x510 in Object.wait() [0x0091f000..0x0091fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e7e8> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:485) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) - locked <0x2394e7e8> (a java.lang.ref.Reference$Lock) "main" prio=6 tid=0x0020a800 nid=0xef4 runnable [0x0025f000..0x0025fe28] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e18dc0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.catalina.core.StandardServer.await(StandardServer.java:389) at org.apache.catalina.startup.Catalina.await(Catalina.java:642) at org.apache.catalina.startup.Catalina.start(Catalina.java:602) 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.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288) at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413) "VM Thread" prio=10 tid=0x0213fc00 nid=0xdc0 runnable "VM Periodic Task Thread" prio=10 tid=0x0215dc00 nid=0x1128 waiting on condition JNI global references: 781 i also attach my logback configuration: <?xml version="1.0" encoding="UTF-8"?> <configuration debug="true"> <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> Operator %X{client}: %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> <!-- <appender name="file" class="ch.qos.logback.core.FileAppender" > <File>imsm-debug.log</File> <Append>false</Append> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> --> <logger name="net.sf.jguard.core" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.authorization" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.filters" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.ext" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.jee" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.ehcache" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.util" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.jguard" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBUserImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBGroupImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBOperatorImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBInstitutionImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="org.apache.jcs" additivity="false"> <level value="WARN" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <root> <!-- The following level element is not necessary since the --> <!-- level of the root level is set to DEBUG by default. --> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </root> </configuration>
-- 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
[ http://jira.qos.ch/browse/LBCORE-96?page=com.atlassian.jira.plugin.system.is... ] Ceki Gulcu reopened LBCORE-96: ------------------------------ If you wish to have a deadlock related issue fixed, please open a new issue. Do not forget to supply a test case (if possible).
Deadlock when running on multiple core processors -------------------------------------------------
Key: LBCORE-96 URL: http://jira.qos.ch/browse/LBCORE-96 Project: logback-core Issue Type: Bug Components: Appender Affects Versions: 0.9.15 Environment: Windows Vista quad core Apache Tomcat 6.0.18 JDK 1.6 Reporter: Lars Feistner Assignee: Logback dev list Attachments: AppenderBaseLock.patch
As Robert Dale mentioned on 23/Mar/09 04:05 PM I'm getting that deadlock in logback core (0.9.14 and 0.9.15). No console plugin or socket appenders, just plain RollingFileAppender. I am getting the deadlock using ConsoleAppender. see attached thread dump: 2009-04-06 11:49:45 Full thread dump Java HotSpot(TM) Client VM (11.0-b12 mixed mode, sharing): "http-8084-5" daemon prio=6 tid=0x04700c00 nid=0xc54 in Object.wait() [0x05d1f000..0x05d1fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-4" daemon prio=6 tid=0x04700000 nid=0xe24 in Object.wait() [0x05c7f000..0x05c7fbe8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-3" daemon prio=6 tid=0x04700400 nid=0x134c waiting for monitor entry [0x05c2f000..0x05c2fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "Thread-10" daemon prio=6 tid=0x046ff800 nid=0x122c runnable [0x05bdf000..0x05bdfb68] java.lang.Thread.State: RUNNABLE at sun.net.dns.ResolverConfigurationImpl.notifyAddrChange0(Native Method) at sun.net.dns.ResolverConfigurationImpl$AddressChangeListener.run(ResolverConfigurationImpl.java:125) "http-8084-2" daemon prio=6 tid=0x046ff400 nid=0x17f4 waiting for monitor entry [0x05b8f000..0x05b8fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "TP-Monitor" daemon prio=6 tid=0x04a17400 nid=0x830 in Object.wait() [0x05b3f000..0x05b3fce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable.run(ThreadPool.java:565) - locked <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor4" daemon prio=6 tid=0x0497a000 nid=0x11dc runnable [0x05a8f000..0x05a8fd68] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e0a9b0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.jk.common.ChannelSocket.accept(ChannelSocket.java:306) at org.apache.jk.common.ChannelSocket.acceptConnections(ChannelSocket.java:660) at org.apache.jk.common.ChannelSocket$SocketAcceptor.runIt(ChannelSocket.java:870) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690) at java.lang.Thread.run(Thread.java:619) "TP-Processor3" daemon prio=6 tid=0x04979c00 nid=0xfe8 in Object.wait() [0x05a3f000..0x05a3f9e8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor2" daemon prio=6 tid=0x04982800 nid=0x10bc in Object.wait() [0x059ef000..0x059efa68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor1" daemon prio=6 tid=0x04982000 nid=0x131c in Object.wait() [0x0599f000..0x0599fae8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "http-8084-1" daemon prio=6 tid=0x04917000 nid=0x15f4 runnable [0x0594f000..0x0594fb68] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:260) at java.io.BufferedOutputStream.write(BufferedOutputStream.java:105) - locked <0x2395d280> (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:430) - locked <0x23951d08> (a java.io.PrintStream) at org.apache.tomcat.util.log.SystemLogHandler.write(SystemLogHandler.java:166) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272) at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276) at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122) - locked <0x23b1c1f0> (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212) at ch.qos.logback.core.WriterAppender.writerWrite(WriterAppender.java:245) 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 <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:92) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "http-8084-Acceptor-0" daemon prio=6 tid=0x049c2400 nid=0x129c runnable [0x058bf000..0x058bfbe8] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23a40168> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.tomcat.util.net.DefaultServerSocketFactory.acceptSocket(DefaultServerSocketFactory.java:61) at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:310) at java.lang.Thread.run(Thread.java:619) "ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=6 tid=0x051c9800 nid=0x152c waiting on condition [0x0452f000..0x0452fc68] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1579) at java.lang.Thread.run(Thread.java:619) "Thread-1" daemon prio=2 tid=0x04638c00 nid=0x1360 in Object.wait() [0x044df000..0x044dfce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon.nextTask(ClockDaemon.java:328) - locked <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:362) at java.lang.Thread.run(Thread.java:619) "ElementEventQueue.QProcessor-1" daemon prio=6 tid=0x050f2800 nid=0x17d0 in Object.wait() [0x0442f000..0x0442fd68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b81398> (a java.lang.Object) at java.lang.Object.wait(Object.java:485) at org.apache.jcs.engine.control.event.ElementEventQueue.take(ElementEventQueue.java:181) - locked <0x23b81398> (a java.lang.Object) at org.apache.jcs.engine.control.event.ElementEventQueue.access$300(ElementEventQueue.java:35) at org.apache.jcs.engine.control.event.ElementEventQueue$QProcessor.run(ElementEventQueue.java:245) "Low Memory Detector" daemon prio=6 tid=0x0215c800 nid=0x1370 runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "CompilerThread0" daemon prio=10 tid=0x02156400 nid=0x758 waiting on condition [0x00000000..0x0433f890] java.lang.Thread.State: RUNNABLE "Attach Listener" daemon prio=10 tid=0x02155400 nid=0x14f4 waiting on condition [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" daemon prio=10 tid=0x0214ac00 nid=0x151c runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Finalizer" daemon prio=8 tid=0x02143000 nid=0x430 in Object.wait() [0x0424f000..0x0424fce8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116) - locked <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x02141000 nid=0x510 in Object.wait() [0x0091f000..0x0091fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e7e8> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:485) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) - locked <0x2394e7e8> (a java.lang.ref.Reference$Lock) "main" prio=6 tid=0x0020a800 nid=0xef4 runnable [0x0025f000..0x0025fe28] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e18dc0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.catalina.core.StandardServer.await(StandardServer.java:389) at org.apache.catalina.startup.Catalina.await(Catalina.java:642) at org.apache.catalina.startup.Catalina.start(Catalina.java:602) 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.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288) at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413) "VM Thread" prio=10 tid=0x0213fc00 nid=0xdc0 runnable "VM Periodic Task Thread" prio=10 tid=0x0215dc00 nid=0x1128 waiting on condition JNI global references: 781 i also attach my logback configuration: <?xml version="1.0" encoding="UTF-8"?> <configuration debug="true"> <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> Operator %X{client}: %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> <!-- <appender name="file" class="ch.qos.logback.core.FileAppender" > <File>imsm-debug.log</File> <Append>false</Append> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> --> <logger name="net.sf.jguard.core" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.authorization" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.filters" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.ext" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.jee" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.ehcache" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.util" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.jguard" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBUserImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBGroupImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBOperatorImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBInstitutionImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="org.apache.jcs" additivity="false"> <level value="WARN" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <root> <!-- The following level element is not necessary since the --> <!-- level of the root level is set to DEBUG by default. --> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </root> </configuration>
-- 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
[ http://jira.qos.ch/browse/LBCORE-96?page=com.atlassian.jira.plugin.system.is... ] Ceki Gulcu closed LBCORE-96. ---------------------------- Resolution: Fixed
Deadlock when running on multiple core processors -------------------------------------------------
Key: LBCORE-96 URL: http://jira.qos.ch/browse/LBCORE-96 Project: logback-core Issue Type: Bug Components: Appender Affects Versions: 0.9.15 Environment: Windows Vista quad core Apache Tomcat 6.0.18 JDK 1.6 Reporter: Lars Feistner Assignee: Logback dev list Attachments: AppenderBaseLock.patch
As Robert Dale mentioned on 23/Mar/09 04:05 PM I'm getting that deadlock in logback core (0.9.14 and 0.9.15). No console plugin or socket appenders, just plain RollingFileAppender. I am getting the deadlock using ConsoleAppender. see attached thread dump: 2009-04-06 11:49:45 Full thread dump Java HotSpot(TM) Client VM (11.0-b12 mixed mode, sharing): "http-8084-5" daemon prio=6 tid=0x04700c00 nid=0xc54 in Object.wait() [0x05d1f000..0x05d1fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24338c70> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-4" daemon prio=6 tid=0x04700000 nid=0xe24 in Object.wait() [0x05c7f000..0x05c7fbe8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.net.JIoEndpoint$Worker.await(JIoEndpoint.java:416) - locked <0x24254da8> (a org.apache.tomcat.util.net.JIoEndpoint$Worker) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:442) at java.lang.Thread.run(Thread.java:619) "http-8084-3" daemon prio=6 tid=0x04700400 nid=0x134c waiting for monitor entry [0x05c2f000..0x05c2fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "Thread-10" daemon prio=6 tid=0x046ff800 nid=0x122c runnable [0x05bdf000..0x05bdfb68] java.lang.Thread.State: RUNNABLE at sun.net.dns.ResolverConfigurationImpl.notifyAddrChange0(Native Method) at sun.net.dns.ResolverConfigurationImpl$AddressChangeListener.run(ResolverConfigurationImpl.java:125) "http-8084-2" daemon prio=6 tid=0x046ff400 nid=0x17f4 waiting for monitor entry [0x05b8f000..0x05b8fa68] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:66) - waiting to lock <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:88) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "TP-Monitor" daemon prio=6 tid=0x04a17400 nid=0x830 in Object.wait() [0x05b3f000..0x05b3fce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable.run(ThreadPool.java:565) - locked <0x23e0a900> (a org.apache.tomcat.util.threads.ThreadPool$MonitorRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor4" daemon prio=6 tid=0x0497a000 nid=0x11dc runnable [0x05a8f000..0x05a8fd68] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e0a9b0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.jk.common.ChannelSocket.accept(ChannelSocket.java:306) at org.apache.jk.common.ChannelSocket.acceptConnections(ChannelSocket.java:660) at org.apache.jk.common.ChannelSocket$SocketAcceptor.runIt(ChannelSocket.java:870) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690) at java.lang.Thread.run(Thread.java:619) "TP-Processor3" daemon prio=6 tid=0x04979c00 nid=0xfe8 in Object.wait() [0x05a3f000..0x05a3f9e8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0abc8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor2" daemon prio=6 tid=0x04982800 nid=0x10bc in Object.wait() [0x059ef000..0x059efa68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ac68> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "TP-Processor1" daemon prio=6 tid=0x04982000 nid=0x131c in Object.wait() [0x0599f000..0x0599fae8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Object.wait(Object.java:485) at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:662) - locked <0x23e0ad08> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) at java.lang.Thread.run(Thread.java:619) "http-8084-1" daemon prio=6 tid=0x04917000 nid=0x15f4 runnable [0x0594f000..0x0594fb68] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:260) at java.io.BufferedOutputStream.write(BufferedOutputStream.java:105) - locked <0x2395d280> (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:430) - locked <0x23951d08> (a java.io.PrintStream) at org.apache.tomcat.util.log.SystemLogHandler.write(SystemLogHandler.java:166) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272) at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:276) at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122) - locked <0x23b1c1f0> (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212) at ch.qos.logback.core.WriterAppender.writerWrite(WriterAppender.java:245) 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 <0x23b16ac8> (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_1(Logger.java:411) at ch.qos.logback.classic.Logger.debug(Logger.java:504) at de.ims.server.jguard.ImsRemoteServiceServlet.processCall(ImsRemoteServiceServlet.java:92) at com.google.gwt.user.server.rpc.RemoteServiceServlet.doPost(RemoteServiceServlet.java:86) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.netbeans.modules.web.monitor.server.MonitorFilter.doFilter(MonitorFilter.java:390) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:128) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:286) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:845) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:583) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:447) at java.lang.Thread.run(Thread.java:619) "http-8084-Acceptor-0" daemon prio=6 tid=0x049c2400 nid=0x129c runnable [0x058bf000..0x058bfbe8] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23a40168> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.tomcat.util.net.DefaultServerSocketFactory.acceptSocket(DefaultServerSocketFactory.java:61) at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:310) at java.lang.Thread.run(Thread.java:619) "ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=6 tid=0x051c9800 nid=0x152c waiting on condition [0x0452f000..0x0452fc68] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1579) at java.lang.Thread.run(Thread.java:619) "Thread-1" daemon prio=2 tid=0x04638c00 nid=0x1360 in Object.wait() [0x044df000..0x044dfce8] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon.nextTask(ClockDaemon.java:328) - locked <0x23b87d30> (a EDU.oswego.cs.dl.util.concurrent.ClockDaemon) at EDU.oswego.cs.dl.util.concurrent.ClockDaemon$RunLoop.run(ClockDaemon.java:362) at java.lang.Thread.run(Thread.java:619) "ElementEventQueue.QProcessor-1" daemon prio=6 tid=0x050f2800 nid=0x17d0 in Object.wait() [0x0442f000..0x0442fd68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x23b81398> (a java.lang.Object) at java.lang.Object.wait(Object.java:485) at org.apache.jcs.engine.control.event.ElementEventQueue.take(ElementEventQueue.java:181) - locked <0x23b81398> (a java.lang.Object) at org.apache.jcs.engine.control.event.ElementEventQueue.access$300(ElementEventQueue.java:35) at org.apache.jcs.engine.control.event.ElementEventQueue$QProcessor.run(ElementEventQueue.java:245) "Low Memory Detector" daemon prio=6 tid=0x0215c800 nid=0x1370 runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "CompilerThread0" daemon prio=10 tid=0x02156400 nid=0x758 waiting on condition [0x00000000..0x0433f890] java.lang.Thread.State: RUNNABLE "Attach Listener" daemon prio=10 tid=0x02155400 nid=0x14f4 waiting on condition [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" daemon prio=10 tid=0x0214ac00 nid=0x151c runnable [0x00000000..0x00000000] java.lang.Thread.State: RUNNABLE "Finalizer" daemon prio=8 tid=0x02143000 nid=0x430 in Object.wait() [0x0424f000..0x0424fce8] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116) - locked <0x2394e760> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x02141000 nid=0x510 in Object.wait() [0x0091f000..0x0091fc68] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x2394e7e8> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:485) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) - locked <0x2394e7e8> (a java.lang.ref.Reference$Lock) "main" prio=6 tid=0x0020a800 nid=0xef4 runnable [0x0025f000..0x0025fe28] java.lang.Thread.State: RUNNABLE at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384) - locked <0x23e18dc0> (a java.net.SocksSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:453) at java.net.ServerSocket.accept(ServerSocket.java:421) at org.apache.catalina.core.StandardServer.await(StandardServer.java:389) at org.apache.catalina.startup.Catalina.await(Catalina.java:642) at org.apache.catalina.startup.Catalina.start(Catalina.java:602) 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.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288) at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413) "VM Thread" prio=10 tid=0x0213fc00 nid=0xdc0 runnable "VM Periodic Task Thread" prio=10 tid=0x0215dc00 nid=0x1128 waiting on condition JNI global references: 781 i also attach my logback configuration: <?xml version="1.0" encoding="UTF-8"?> <configuration debug="true"> <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> Operator %X{client}: %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> <!-- <appender name="file" class="ch.qos.logback.core.FileAppender" > <File>imsm-debug.log</File> <Append>false</Append> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern> %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %L - %msg%n </Pattern> </layout> </appender> --> <logger name="net.sf.jguard.core" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.authorization" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.core.filters" additivity="false"> <level value="debug"/> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.ext" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.jguard.jee" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="net.sf.ehcache" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.util" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.jguard" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBUserImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBGroupImpl" additivity="false"> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBOperatorImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="de.ims.core.db.DBInstitutionImpl" additivity="false"> <level value="INFO" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <logger name="org.apache.jcs" additivity="false"> <level value="WARN" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </logger> <root> <!-- The following level element is not necessary since the --> <!-- level of the root level is set to DEBUG by default. --> <level value="DEBUG" /> <appender-ref ref="stdout" /> <!--<appender-ref ref="file" />--> </root> </configuration>
-- 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
participants (4)
-
Ceki Gulcu (JIRA) -
Joern Huxhorn (JIRA)
-
Lars Feistner (JIRA)
-
Ralph Goers (JIRA)