SMTPAppender_SubethaSMTPTest hang --------------------------------- Key: LBGENERAL-33 URL: http://jira.qos.ch/browse/LBGENERAL-33 Project: logback-general Issue Type: Sub-task Affects Versions: 0.9.17 Environment: Mac OSX Reporter: Ralph Goers Assignee: Logback dev list This test frequently waits forever waiting for a response. The jstack output follows: 2009-10-13 09:59:33 Full thread dump Java HotSpot(TM) 64-Bit Server VM (14.1-b02-90 mixed mode): "Attach Listener" daemon prio=9 tid=0x00000001022f4800 nid=0x1150c6000 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "SocketAcceptorIoProcessor-2.0" prio=5 tid=0x000000011316f000 nid=0x115487000 runnable [0x0000000115486000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method) at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:136) at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:69) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69) - locked <0x00000001064d86b8> (a sun.nio.ch.Util$1) - locked <0x00000001064d86a0> (a java.util.Collections$UnmodifiableSet) - locked <0x00000001064d8340> (a sun.nio.ch.KQueueSelectorImpl) at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80) at org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run(SocketIoProcessor.java:480) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:637) "SocketAcceptor-2" prio=5 tid=0x0000000102196800 nid=0x114e4e000 runnable [0x0000000114e4d000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method) at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:136) at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:69) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69) - locked <0x0000000107ad72c0> (a sun.nio.ch.Util$1) - locked <0x0000000107ad72d8> (a java.util.Collections$UnmodifiableSet) - locked <0x0000000107aee2b8> (a sun.nio.ch.KQueueSelectorImpl) at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80) at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:84) at org.apache.mina.transport.socket.nio.SocketAcceptor$Worker.run(SocketAcceptor.java:220) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:637) "HSQLDB Timer @e8ae59a" daemon prio=5 tid=0x0000000113421800 nid=0x114fc3000 in Object.wait() [0x0000000114fc2000] java.lang.Thread.State: TIMED_WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x00000001072e8c08> (a org.hsqldb.lib.HsqlTimer) at org.hsqldb.lib.HsqlTimer.nextTask(Unknown Source) - locked <0x00000001072e8c08> (a org.hsqldb.lib.HsqlTimer) at org.hsqldb.lib.HsqlTimer$TaskRunner.run(Unknown Source) at java.lang.Thread.run(Thread.java:637) "Thread-5" prio=5 tid=0x00000001023ac800 nid=0x114b1b000 runnable [0x0000000114b1a000] java.lang.Thread.State: RUNNABLE at java.net.PlainDatagramSocketImpl.receive0(Native Method) - locked <0x00000001071a3c58> (a java.net.PlainDatagramSocketImpl) at java.net.PlainDatagramSocketImpl.receive(PlainDatagramSocketImpl.java:136) - locked <0x00000001071a3c58> (a java.net.PlainDatagramSocketImpl) at java.net.DatagramSocket.receive(DatagramSocket.java:712) - locked <0x00000001071c6cd8> (a java.net.DatagramPacket) - locked <0x0000000107195e18> (a java.net.DatagramSocket) at ch.qos.logback.classic.net.mock.MockSyslogServer.run(MockSyslogServer.java:50) "Thread-4" prio=5 tid=0x000000011321f800 nid=0x114a18000 runnable [0x0000000114a17000] java.lang.Thread.State: RUNNABLE at java.net.PlainDatagramSocketImpl.receive0(Native Method) - locked <0x00000001071a3cb0> (a java.net.PlainDatagramSocketImpl) at java.net.PlainDatagramSocketImpl.receive(PlainDatagramSocketImpl.java:136) - locked <0x00000001071a3cb0> (a java.net.PlainDatagramSocketImpl) at java.net.DatagramSocket.receive(DatagramSocket.java:712) - locked <0x00000001071c6d08> (a java.net.DatagramPacket) - locked <0x0000000107195e50> (a java.net.DatagramSocket) at ch.qos.logback.classic.net.mock.MockSyslogServer.run(MockSyslogServer.java:50) "Thread-3" prio=5 tid=0x000000010241d800 nid=0x114915000 runnable [0x0000000114914000] java.lang.Thread.State: RUNNABLE at java.net.PlainDatagramSocketImpl.receive0(Native Method) - locked <0x0000000107104030> (a java.net.PlainDatagramSocketImpl) at java.net.PlainDatagramSocketImpl.receive(PlainDatagramSocketImpl.java:136) - locked <0x0000000107104030> (a java.net.PlainDatagramSocketImpl) at java.net.DatagramSocket.receive(DatagramSocket.java:712) - locked <0x0000000107125850> (a java.net.DatagramPacket) - locked <0x00000001071243f8> (a java.net.DatagramSocket) at ch.qos.logback.classic.net.mock.MockSyslogServer.run(MockSyslogServer.java:50) "Thread-1" prio=5 tid=0x000000011316c000 nid=0x114703000 runnable [0x0000000114702000] java.lang.Thread.State: RUNNABLE at java.net.PlainDatagramSocketImpl.receive0(Native Method) - locked <0x0000000107077898> (a java.net.PlainDatagramSocketImpl) at java.net.PlainDatagramSocketImpl.receive(PlainDatagramSocketImpl.java:136) - locked <0x0000000107077898> (a java.net.PlainDatagramSocketImpl) at java.net.DatagramSocket.receive(DatagramSocket.java:712) - locked <0x00000001070e9668> (a java.net.DatagramPacket) - locked <0x00000001070f1b20> (a java.net.DatagramSocket) at ch.qos.logback.classic.net.mock.MockSyslogServer.run(MockSyslogServer.java:50) "Thread-0" prio=5 tid=0x0000000113113000 nid=0x1145ed000 runnable [0x00000001145ec000] java.lang.Thread.State: RUNNABLE at java.net.PlainDatagramSocketImpl.receive0(Native Method) - locked <0x00000001070778f0> (a java.net.PlainDatagramSocketImpl) at java.net.PlainDatagramSocketImpl.receive(PlainDatagramSocketImpl.java:136) - locked <0x00000001070778f0> (a java.net.PlainDatagramSocketImpl) at java.net.DatagramSocket.receive(DatagramSocket.java:712) - locked <0x00000001070e9698> (a java.net.DatagramPacket) - locked <0x00000001070f1b58> (a java.net.DatagramSocket) at ch.qos.logback.classic.net.mock.MockSyslogServer.run(MockSyslogServer.java:50) "Low Memory Detector" daemon prio=5 tid=0x000000010208e000 nid=0x114290000 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE "CompilerThread1" daemon prio=9 tid=0x000000010208d800 nid=0x11418d000 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "CompilerThread0" daemon prio=9 tid=0x000000010208c800 nid=0x11408a000 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Signal Dispatcher" daemon prio=9 tid=0x000000010208c000 nid=0x113f87000 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Surrogate Locker Thread (CMS)" daemon prio=5 tid=0x000000010208b000 nid=0x113e84000 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE "Finalizer" daemon prio=8 tid=0x0000000102075800 nid=0x113b07000 in Object.wait() [0x0000000113b06000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x0000000106ef0848> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118) - locked <0x0000000106ef0848> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x0000000113026000 nid=0x113a04000 in Object.wait() [0x0000000113a03000] java.lang.Thread.State: WAITING (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x0000000106ef0860> (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 <0x0000000106ef0860> (a java.lang.ref.Reference$Lock) "main" prio=5 tid=0x0000000102000800 nid=0x101301000 runnable [0x00000001012fe000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at com.sun.mail.util.TraceInputStream.read(TraceInputStream.java:97) at java.io.BufferedInputStream.fill(BufferedInputStream.java:218) at java.io.BufferedInputStream.read(BufferedInputStream.java:237) - locked <0x0000000106458610> (a java.io.BufferedInputStream) at com.sun.mail.util.LineInputStream.readLine(LineInputStream.java:75) at com.sun.mail.smtp.SMTPTransport.readServerResponse(SMTPTransport.java:1440) at com.sun.mail.smtp.SMTPTransport.issueSendCommand(SMTPTransport.java:1376) at com.sun.mail.smtp.SMTPTransport.finishData(SMTPTransport.java:1215) at com.sun.mail.smtp.SMTPTransport.sendMessage(SMTPTransport.java:586) - locked <0x0000000106454d10> (a com.sun.mail.smtp.SMTPTransport) at javax.mail.Transport.send0(Transport.java:169) at javax.mail.Transport.send(Transport.java:98) at ch.qos.logback.core.net.SMTPAppenderBase.sendBuffer(SMTPAppenderBase.java:282) at ch.qos.logback.core.net.SMTPAppenderBase.append(SMTPAppenderBase.java:153) at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:91) - locked <0x000000010710e350> (a ch.qos.logback.classic.net.SMTPAppender) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:64) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:276) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:263) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:445) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:399) at ch.qos.logback.classic.Logger.error(Logger.java:562) at ch.qos.logback.classic.net.SMTPAppender_SubethaSMTPTest.htmlLong(SMTPAppender_SubethaSMTPTest.java:195) 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.junit.internal.runners.TestMethod.invoke(TestMethod.java:59) at org.junit.internal.runners.MethodRoadie.runTestMethod(MethodRoadie.java:98) at org.junit.internal.runners.MethodRoadie$2.run(MethodRoadie.java:79) at org.junit.internal.runners.MethodRoadie.runBeforesThenTestThenAfters(MethodRoadie.java:87) at org.junit.internal.runners.MethodRoadie.runTest(MethodRoadie.java:77) at org.junit.internal.runners.MethodRoadie.run(MethodRoadie.java:42) at org.junit.internal.runners.JUnit4ClassRunner.invokeTestMethod(JUnit4ClassRunner.java:88) at org.junit.internal.runners.JUnit4ClassRunner.runMethods(JUnit4ClassRunner.java:51) at org.junit.internal.runners.JUnit4ClassRunner$1.run(JUnit4ClassRunner.java:44) at org.junit.internal.runners.ClassRoadie.runUnprotected(ClassRoadie.java:27) at org.junit.internal.runners.ClassRoadie.runProtected(ClassRoadie.java:37) at org.junit.internal.runners.JUnit4ClassRunner.run(JUnit4ClassRunner.java:42) at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:62) at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140) at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127) at org.apache.maven.surefire.Surefire.run(Surefire.java:177) 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.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:338) at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:997) "VM Thread" prio=9 tid=0x0000000102070000 nid=0x113901000 runnable "Gang worker#0 (Parallel GC Threads)" prio=9 tid=0x0000000102002000 nid=0x105902000 runnable "Gang worker#1 (Parallel GC Threads)" prio=9 tid=0x0000000102002800 nid=0x105a05000 runnable "Concurrent Mark-Sweep GC Thread" prio=9 tid=0x0000000102042000 nid=0x112d9f000 runnable "VM Periodic Task Thread" prio=10 tid=0x000000010208f000 nid=0x114393000 waiting on condition "Exception Catcher Thread" prio=10 tid=0x0000000102001800 nid=0x101701000 runnable JNI global references: 939 -- 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