[logback-dev] [JIRA] Commented: (LBCLASSIC-112) ch.qos.logback.classic.net.SMTPAppender_SubethaSMTPTest hangs on Mac OS X

3 Mar 2010

      [ http://jira.qos.ch/browse/LBCLASSIC-112?page=com.atlassian.jira.plugin.syste... ] 

Joern Huxhorn commented on LBCLASSIC-112:
-----------------------------------------

Strange.
I had the impression that this was fixed in the meantime.

Apache Maven 2.2.0 (r788681; 2009-06-26 15:04:01+0200)
Java version: 1.6.0_17
Java home: /System/Library/Frameworks/JavaVM.framework/Versions/1.6.0/Home
Default locale: en_US, platform encoding: MacRoman
OS name: "mac os x" version: "10.5.8" arch: "x86_64" Family: "mac"

commit b6bb584c8cb7ff7e6ebf9a0eefcfec48f5a8418c

I'll attach the relevant part of output for reference:

Running ch.qos.logback.classic.net.SMTPAppender_SubethaSMTPTest
TEST 15:13:42.573 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: AUTH
TEST 15:13:42.574 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: DATA
TEST 15:13:42.574 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: EHLO
TEST 15:13:42.574 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: HELO
TEST 15:13:42.574 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: HELP
TEST 15:13:42.574 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: MAIL
TEST 15:13:42.574 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: NOOP
TEST 15:13:42.574 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: QUIT
TEST 15:13:42.574 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: RCPT
TEST 15:13:42.574 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: RSET
TEST 15:13:42.574 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: STARTTLS
TEST 15:13:42.574 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: VRFY
TEST 15:13:42.672 [SocketAcceptorIoProcessor-0.0] DEBUG o.s.smtp.server.ConnectionHandler - Active connections = 1
TEST 15:13:42.674 [SocketAcceptorIoProcessor-0.0] DEBUG o.s.smtp.server.ConnectionHandler - SMTP connection count: 1
TEST 15:13:42.676 [SocketAcceptorIoProcessor-0.0] DEBUG o.s.smtp.server.ConnectionHandler - S: 220 10.200.55.201 ESMTP SubEthaSMTP
TEST 15:13:42.684 [SocketAcceptorIoProcessor-0.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60281
TEST 15:13:42.687 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60281
TEST 15:13:42.689 [SocketAcceptorIoProcessor-0.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60281
TEST 15:13:42.689 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60281
TEST 15:13:42.713 [SocketAcceptorIoProcessor-0.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60281
TEST 15:13:42.713 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - C: EHLO LBFRA-0301-JHuxhorn-244-MBP-2.local
TEST 15:13:42.714 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - S: 250-10.200.55.201
250-8BITMIME
250-STARTTLS
250 Ok
TEST 15:13:42.714 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60281
TEST 15:13:42.718 [SocketAcceptorIoProcessor-0.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60281
TEST 15:13:42.719 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60281
TEST 15:13:42.719 [SocketAcceptorIoProcessor-0.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60281
TEST 15:13:42.720 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - C: MAIL FROM:<user@host.dom>
TEST 15:13:42.720 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - S: 250 Ok
TEST 15:13:42.720 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60281
TEST 15:13:42.720 [SocketAcceptorIoProcessor-0.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60281
TEST 15:13:42.720 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60281
TEST 15:13:42.721 [SocketAcceptorIoProcessor-0.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60281
TEST 15:13:42.721 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - C: RCPT TO:<noreply@qos.ch>
TEST 15:13:42.722 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - S: 250 Ok
TEST 15:13:42.722 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60281
TEST 15:13:42.722 [SocketAcceptorIoProcessor-0.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60281
TEST 15:13:42.722 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60281
TEST 15:13:42.722 [SocketAcceptorIoProcessor-0.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60281
TEST 15:13:42.722 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - C: DATA
TEST 15:13:42.722 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - S: 354 End data with <CR><LF>.<CR><LF>
TEST 15:13:42.723 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60281
TEST 15:13:42.723 [SocketAcceptorIoProcessor-0.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60281
TEST 15:13:42.723 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60281
TEST 15:13:42.755 [SocketAcceptorIoProcessor-0.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60281
TEST 15:13:42.761 [SubEthaSMTP Thread 1] DEBUG org.subethamail.wiser.Wiser - Delivering new message ...
TEST 15:13:42.768 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - S: 250 Ok
TEST 15:13:42.768 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60281
TEST 15:13:42.769 [SocketAcceptorIoProcessor-0.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60281
TEST 15:13:42.769 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60281
TEST 15:13:42.769 [SocketAcceptorIoProcessor-0.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60281
TEST 15:13:42.769 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - C: QUIT
TEST 15:13:42.769 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - S: 221 Bye
TEST 15:13:42.769 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60281
TEST 15:13:42.770 [SocketAcceptorIoProcessor-0.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60281
TEST 15:13:42.770 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60281
TEST 15:13:42.771 [SocketAcceptorIoProcessor-0.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60281
TEST 15:13:42.774 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - Active connections = 0
TEST 15:13:42.776 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60281
[HEADER
155  [main] DEBUG test ch.qos.logback.classic.net.SMTPAppender_SubethaSMTPTest - hello
155  [main] ERROR test ch.qos.logback.classic.net.SMTPAppender_SubethaSMTPTest - en error
java.lang.Exception: an exception
	at ch.qos.logback.classic.net.SMTPAppender_SubethaSMTPTest.smoke(SMTPAppender_SubethaSMTPTest.java:135) [test-classes/:na]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [na:1.6.0_17]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) [na:1.6.0_17]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [na:1.6.0_17]
	at java.lang.reflect.Method.invoke(Method.java:597) [na:1.6.0_17]
	at org.junit.internal.runners.TestMethod.invoke(TestMethod.java:59) [junit-4.4.jar:na]
	at org.junit.internal.runners.MethodRoadie.runTestMethod(MethodRoadie.java:98) [junit-4.4.jar:na]
	at org.junit.internal.runners.MethodRoadie$2.run(MethodRoadie.java:79) [junit-4.4.jar:na]
	at org.junit.internal.runners.MethodRoadie.runBeforesThenTestThenAfters(MethodRoadie.java:87) [junit-4.4.jar:na]
	at org.junit.internal.runners.MethodRoadie.runTest(MethodRoadie.java:77) [junit-4.4.jar:na]
	at org.junit.internal.runners.MethodRoadie.run(MethodRoadie.java:42) [junit-4.4.jar:na]
	at org.junit.internal.runners.JUnit4ClassRunner.invokeTestMethod(JUnit4ClassRunner.java:88) [junit-4.4.jar:na]
	at org.junit.internal.runners.JUnit4ClassRunner.runMethods(JUnit4ClassRunner.java:51) [junit-4.4.jar:na]
	at org.junit.internal.runners.JUnit4ClassRunner$1.run(JUnit4ClassRunner.java:44) [junit-4.4.jar:na]
	at org.junit.internal.runners.ClassRoadie.runUnprotected(ClassRoadie.java:27) [junit-4.4.jar:na]
	at org.junit.internal.runners.ClassRoadie.runProtected(ClassRoadie.java:37) [junit-4.4.jar:na]
	at org.junit.internal.runners.JUnit4ClassRunner.run(JUnit4ClassRunner.java:42) [junit-4.4.jar:na]
	at org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:62) [surefire-junit4-2.4.3.jar:2.4.3]
	at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140) [surefire-api-2.4.3.jar:2.4.3]
	at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127) [surefire-api-2.4.3.jar:2.4.3]
	at org.apache.maven.surefire.Surefire.run(Surefire.java:177) [surefire-api-2.4.3.jar:2.4.3]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [na:1.6.0_17]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) [na:1.6.0_17]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) [na:1.6.0_17]
	at java.lang.reflect.Method.invoke(Method.java:597) [na:1.6.0_17]
	at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:345) [surefire-booter-2.4.3.jar:2.4.3]
	at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:1009) [surefire-booter-2.4.3.jar:2.4.3]
FOOTER
TEST 15:13:42.784 [main] INFO  o.subethamail.smtp.server.SMTPServer - SMTP Server socket shut down.
TEST 15:13:42.809 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: AUTH
TEST 15:13:42.809 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: DATA
TEST 15:13:42.809 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: EHLO
TEST 15:13:42.809 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: HELO
TEST 15:13:42.809 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: HELP
TEST 15:13:42.809 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: MAIL
TEST 15:13:42.809 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: NOOP
TEST 15:13:42.809 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: QUIT
TEST 15:13:42.809 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: RCPT
TEST 15:13:42.809 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: RSET
TEST 15:13:42.810 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: STARTTLS
TEST 15:13:42.810 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: VRFY
TEST 15:13:42.820 [SocketAcceptorIoProcessor-1.0] DEBUG o.s.smtp.server.ConnectionHandler - Active connections = 1
TEST 15:13:42.820 [SocketAcceptorIoProcessor-1.0] DEBUG o.s.smtp.server.ConnectionHandler - SMTP connection count: 1
TEST 15:13:42.820 [SocketAcceptorIoProcessor-1.0] DEBUG o.s.smtp.server.ConnectionHandler - S: 220 10.200.55.201 ESMTP SubEthaSMTP
TEST 15:13:42.821 [SocketAcceptorIoProcessor-1.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60282
TEST 15:13:42.824 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60282
TEST 15:13:42.825 [SocketAcceptorIoProcessor-1.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60282
TEST 15:13:42.825 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - C: EHLO LBFRA-0301-JHuxhorn-244-MBP-2.local
TEST 15:13:42.826 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - S: 250-10.200.55.201
250-8BITMIME
250-STARTTLS
250 Ok
TEST 15:13:42.826 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60282
TEST 15:13:42.826 [SocketAcceptorIoProcessor-1.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60282
TEST 15:13:42.826 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60282
TEST 15:13:42.827 [SocketAcceptorIoProcessor-1.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60282
TEST 15:13:42.827 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - C: MAIL FROM:<user@host.dom>
TEST 15:13:42.827 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - S: 250 Ok
TEST 15:13:42.827 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60282
TEST 15:13:42.827 [SocketAcceptorIoProcessor-1.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60282
TEST 15:13:42.831 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60282
TEST 15:13:42.848 [SocketAcceptorIoProcessor-1.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60282
TEST 15:13:42.848 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - C: RCPT TO:<noreply@qos.ch>
TEST 15:13:42.848 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - S: 250 Ok
TEST 15:13:42.848 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60282
TEST 15:13:42.848 [SocketAcceptorIoProcessor-1.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60282
TEST 15:13:42.849 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60282
TEST 15:13:42.849 [SocketAcceptorIoProcessor-1.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60282
TEST 15:13:42.849 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - C: DATA
TEST 15:13:42.849 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - S: 354 End data with <CR><LF>.<CR><LF>
TEST 15:13:42.849 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60282
TEST 15:13:42.849 [SocketAcceptorIoProcessor-1.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60282
TEST 15:13:42.849 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60282
TEST 15:13:42.854 [SocketAcceptorIoProcessor-1.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60282
TEST 15:13:42.855 [SubEthaSMTP Thread 1] DEBUG org.subethamail.wiser.Wiser - Delivering new message ...
TEST 15:13:42.855 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - S: 250 Ok
TEST 15:13:42.855 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60282
TEST 15:13:42.855 [SocketAcceptorIoProcessor-1.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60282
TEST 15:13:42.855 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60282
TEST 15:13:42.855 [SocketAcceptorIoProcessor-1.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60282
TEST 15:13:42.855 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - C: QUIT
TEST 15:13:42.855 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - S: 221 Bye
TEST 15:13:42.855 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60282
TEST 15:13:42.856 [SocketAcceptorIoProcessor-1.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60282
TEST 15:13:42.856 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60282
TEST 15:13:42.856 [SocketAcceptorIoProcessor-1.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60282
TEST 15:13:42.857 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - Active connections = 0
TEST 15:13:42.857 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60282
TEST 15:13:43.014 [main] INFO  o.subethamail.smtp.server.SMTPServer - SMTP Server socket shut down.
TEST 15:13:43.018 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: AUTH
TEST 15:13:43.019 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: DATA
TEST 15:13:43.020 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: EHLO
TEST 15:13:43.022 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: HELO
TEST 15:13:43.022 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: HELP
TEST 15:13:43.022 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: MAIL
TEST 15:13:43.022 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: NOOP
TEST 15:13:43.022 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: QUIT
TEST 15:13:43.022 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: RCPT
TEST 15:13:43.022 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: RSET
TEST 15:13:43.022 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: STARTTLS
TEST 15:13:43.022 [main] DEBUG o.s.smtp.server.CommandHandler - Added command: VRFY
TEST 15:13:43.183 [SocketAcceptorIoProcessor-2.0] DEBUG o.s.smtp.server.ConnectionHandler - Active connections = 1
TEST 15:13:43.183 [SocketAcceptorIoProcessor-2.0] DEBUG o.s.smtp.server.ConnectionHandler - SMTP connection count: 1
TEST 15:13:43.183 [SocketAcceptorIoProcessor-2.0] DEBUG o.s.smtp.server.ConnectionHandler - S: 220 10.200.55.201 ESMTP SubEthaSMTP
TEST 15:13:43.183 [SocketAcceptorIoProcessor-2.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60283
TEST 15:13:43.185 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60283
TEST 15:13:43.185 [SocketAcceptorIoProcessor-2.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60283
TEST 15:13:43.185 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - C: EHLO LBFRA-0301-JHuxhorn-244-MBP-2.local
TEST 15:13:43.185 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - S: 250-10.200.55.201
250-8BITMIME
250-STARTTLS
250 Ok
TEST 15:13:43.185 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60283
TEST 15:13:43.185 [SocketAcceptorIoProcessor-2.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60283
TEST 15:13:43.186 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60283
TEST 15:13:43.186 [SocketAcceptorIoProcessor-2.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60283
TEST 15:13:43.186 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - C: MAIL FROM:<user@host.dom>
TEST 15:13:43.186 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - S: 250 Ok
TEST 15:13:43.186 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60283
TEST 15:13:43.186 [SocketAcceptorIoProcessor-2.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60283
TEST 15:13:43.186 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60283
TEST 15:13:43.187 [SocketAcceptorIoProcessor-2.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60283
TEST 15:13:43.187 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - C: RCPT TO:<noreply@qos.ch>
TEST 15:13:43.187 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - S: 250 Ok
TEST 15:13:43.187 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60283
TEST 15:13:43.187 [SocketAcceptorIoProcessor-2.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60283
TEST 15:13:43.187 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60283
TEST 15:13:43.187 [SocketAcceptorIoProcessor-2.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60283
TEST 15:13:43.188 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - C: DATA
TEST 15:13:43.188 [SubEthaSMTP Thread 1] DEBUG o.s.smtp.server.ConnectionHandler - S: 354 End data with <CR><LF>.<CR><LF>
TEST 15:13:43.188 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60283
TEST 15:13:43.188 [SocketAcceptorIoProcessor-2.0] DEBUG o.a.m.filter.executor.ExecutorFilter - Launching thread for /127.0.0.1:60283
TEST 15:13:43.188 [SubEthaSMTP Thread 1] DEBUG o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty for /127.0.0.1:60283
2010-03-03 15:15:50
Full thread dump Java HotSpot(TM) 64-Bit Server VM (14.3-b01-101 mixed mode):

"SocketAcceptorIoProcessor-2.0" prio=5 tid=0x0000000101910000 nid=0x1141db000 runnable [0x00000001141da000]
   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 <0x000000010508a400> (a sun.nio.ch.Util$1)
	- locked <0x000000010508a3e8> (a java.util.Collections$UnmodifiableSet)
	- locked <0x000000010508a088> (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=0x0000000101962000 nid=0x114a39000 runnable [0x0000000114a38000]
   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 <0x0000000106240150> (a sun.nio.ch.Util$1)
	- locked <0x0000000106240168> (a java.util.Collections$UnmodifiableSet)
	- locked <0x00000001062400d8> (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 @6e3e5a91" daemon prio=5 tid=0x000000010196f800 nid=0x11462d000 in Object.wait() [0x000000011462c000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x0000000106501100> (a org.hsqldb.lib.HsqlTimer)
	at org.hsqldb.lib.HsqlTimer.nextTask(Unknown Source)
	- locked <0x0000000106501100> (a org.hsqldb.lib.HsqlTimer)
	at org.hsqldb.lib.HsqlTimer$TaskRunner.run(Unknown Source)
	at java.lang.Thread.run(Thread.java:637)

"Low Memory Detector" daemon prio=5 tid=0x0000000101845800 nid=0x113750000 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=9 tid=0x0000000101844800 nid=0x11364d000 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=9 tid=0x0000000101842800 nid=0x11354a000 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=9 tid=0x0000000101841800 nid=0x113447000 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Surrogate Locker Thread (CMS)" daemon prio=5 tid=0x0000000101840800 nid=0x113344000 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=8 tid=0x000000010182a800 nid=0x112864000 in Object.wait() [0x0000000112863000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x0000000106507428> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
	- locked <0x0000000106507428> (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=0x0000000101829000 nid=0x112761000 in Object.wait() [0x0000000112760000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x0000000106507440> (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 <0x0000000106507440> (a java.lang.ref.Reference$Lock)

"main" prio=5 tid=0x0000000101801000 nid=0x100401000 runnable [0x00000001003fe000]
   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 <0x000000010507b6e0> (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 <0x0000000105077de0> (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:292)
	at ch.qos.logback.core.net.SMTPAppenderBase.append(SMTPAppenderBase.java:159)
	at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:85)
	- locked <0x00000001062d10e8> (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:275)
	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:262)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:465)
	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:419)
	at ch.qos.logback.classic.Logger.error(Logger.java:582)
	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:345)
	at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:1009)

"VM Thread" prio=9 tid=0x0000000101821800 nid=0x11265e000 runnable 

"Gang worker#0 (Parallel GC Threads)" prio=9 tid=0x0000000101803800 nid=0x1006c7000 runnable 

"Gang worker#1 (Parallel GC Threads)" prio=9 tid=0x0000000101805000 nid=0x1007ca000 runnable 

"Concurrent Mark-Sweep GC Thread" prio=9 tid=0x0000000101807000 nid=0x11235f000 runnable 
"VM Periodic Task Thread" prio=10 tid=0x0000000101847000 nid=0x113853000 waiting on condition 

"Exception Catcher Thread" prio=10 tid=0x0000000101802000 nid=0x100504000 runnable 
JNI global references: 803

Heap
 par new generation   total 18624K, used 3029K [0x0000000105010000, 0x00000001064d0000, 0x00000001064d0000)
  eden space 16000K,  12% used [0x0000000105010000, 0x00000001051f6928, 0x0000000105fb0000)
  from space 2624K,  41% used [0x0000000106240000, 0x000000010634ec18, 0x00000001064d0000)
  to   space 2624K,   0% used [0x0000000105fb0000, 0x0000000105fb0000, 0x0000000106240000)
 concurrent mark-sweep generation total 62656K, used 17936K [0x00000001064d0000, 0x000000010a200000, 0x000000010a410000)
 concurrent-mark-sweep perm gen total 21248K, used 20575K [0x000000010a410000, 0x000000010b8d0000, 0x000000010f810000)
...
ch.qos.logback.classic.net.SMTPAppender_SubethaSMTPTest hangs on Mac OS X
-------------------------------------------------------------------------
Key: LBCLASSIC-112
                URL: http://jira.qos.ch/browse/LBCLASSIC-112
            Project: logback-classic
         Issue Type: Bug
   Affects Versions: 0.9.16
           Reporter: Joern Huxhorn
           Assignee: Logback dev list
        Attachments: logbackTestHang.txt
This test keeps hanging repeatedly at the very same spot.
I'll attach a file with further info.
-- 
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

[logback-dev] [JIRA] Commented: (LBCLASSIC-112) ch.qos.logback.classic.net.SMTPAppender_SubethaSMTPTest hangs on Mac OS X

Joern Huxhorn (JIRA)