[logback-dev] Unit test hangs.

Ralph Goers rgoers at apache.org
Mon Sep 7 09:20:08 CEST 2009 

While testing my changes to logback I ran into a bit of a problem with  
one of the unit tests.  
ch.qos.logback.classic.net.SMTPAppender_SubethaSMTPTest hangs every  
time i run it. I even downloaded from your repository and tried it  
with the same results.  This is on my MacBook Pro.

Output from jstack.

2009-09-06 23:16:23
Full thread dump Java HotSpot(TM) 64-Bit Server VM (14.1-b02-90 mixed  
mode):

"Attach Listener" daemon prio=9 tid=0x000000010217e800 nid=0x1148d2000  
waiting on condition [0x0000000000000000]
    java.lang.Thread.State: RUNNABLE

"SocketAcceptorIoProcessor-2.0" prio=5 tid=0x0000000102c3e800  
nid=0x114cda000 runnable [0x0000000114cd9000]
    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 <0x0000000106cbd098> (a sun.nio.ch.Util$1)
	- locked <0x0000000106cbd080> (a java.util.Collections$UnmodifiableSet)
	- locked <0x0000000106cbcd20> (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=0x0000000102ad9800 nid=0x1146d6000  
runnable [0x00000001146d5000]
    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 <0x000000010897a298> (a sun.nio.ch.Util$1)
	- locked <0x000000010897a2b0> (a java.util.Collections$UnmodifiableSet)
	- locked <0x00000001082b1cc0> (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 @3d015a9e" daemon prio=5 tid=0x0000000102be0000  
nid=0x114bd7000 in Object.wait() [0x0000000114bd6000]
    java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000001077ffd18> (a org.hsqldb.lib.HsqlTimer)
	at org.hsqldb.lib.HsqlTimer.nextTask(Unknown Source)
	- locked <0x00000001077ffd18> (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=0x0000000102025800  
nid=0x114290000 runnable [0x0000000000000000]
    java.lang.Thread.State: RUNNABLE

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

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

"Signal Dispatcher" daemon prio=9 tid=0x0000000102024000  
nid=0x113f87000 runnable [0x0000000000000000]
    java.lang.Thread.State: RUNNABLE

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

"Finalizer" daemon prio=8 tid=0x0000000102885800 nid=0x113b03000 in  
Object.wait() [0x0000000113b02000]
    java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000001076f0848> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
	- locked <0x00000001076f0848> (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=0x0000000102016800  
nid=0x113a00000 in Object.wait() [0x00000001139ff000]
    java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000001076f7f50> (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 <0x00000001076f7f50> (a java.lang.ref.Reference$Lock)

"main" prio=5 tid=0x0000000102800800 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 <0x0000000106c839c0> (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 <0x0000000106c800c0> (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:279)
	at ch.qos.logback.core.net.SMTPAppenderBase.append 
(SMTPAppenderBase.java:150)
	at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:87)
	- locked <0x0000000107a67dc0> (a  
ch.qos.logback.classic.net.SMTPAppender)
	at  
ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders 
(AppenderAttachableImpl.java:60)
	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:271)
	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:258)
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend 
(Logger.java:440)
	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java: 
394)
	at ch.qos.logback.classic.Logger.error(Logger.java:557)
	at ch.qos.logback.classic.net.SMTPAppender_SubethaSMTPTest.htmlLong 
(SMTPAppender_SubethaSMTPTest.java:182)
	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=0x0000000102884000 nid=0x1138fd000 runnable

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

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

"Concurrent Mark-Sweep GC Thread" prio=9 tid=0x0000000102842000  
nid=0x11359f000 runnable
"VM Periodic Task Thread" prio=10 tid=0x0000000102026800  
nid=0x114393000 waiting on condition

"Exception Catcher Thread" prio=10 tid=0x0000000102801800  
nid=0x101701000 runnable
JNI global references: 701

Console output:

Running ch.qos.logback.classic.net.SMTPAppender_SubethaSMTPTest
TEST 23:53:02.564 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: AUTH
TEST 23:53:02.564 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: DATA
TEST 23:53:02.564 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: EHLO
TEST 23:53:02.564 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: HELO
TEST 23:53:02.564 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: HELP
TEST 23:53:02.565 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: MAIL
TEST 23:53:02.565 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: NOOP
TEST 23:53:02.565 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: QUIT
TEST 23:53:02.565 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: RCPT
TEST 23:53:02.565 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: RSET
TEST 23:53:02.565 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: STARTTLS
TEST 23:53:02.565 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: VRFY
TEST 23:53:02.659 [SocketAcceptorIoProcessor-0.0] DEBUG  
o.s.smtp.server.ConnectionHandler - Active connections = 1
TEST 23:53:02.661 [SocketAcceptorIoProcessor-0.0] DEBUG  
o.s.smtp.server.ConnectionHandler - SMTP connection count: 1
TEST 23:53:02.663 [SocketAcceptorIoProcessor-0.0] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 220 192.168.10.130 ESMTP  
SubEthaSMTP
TEST 23:53:02.672 [SocketAcceptorIoProcessor-0.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61067
TEST 23:53:02.673 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61067
TEST 23:53:02.675 [SocketAcceptorIoProcessor-0.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61067
TEST 23:53:02.676 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61067
TEST 23:53:02.679 [SocketAcceptorIoProcessor-0.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61067
TEST 23:53:02.679 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - C: EHLO rgoerss-macbook-pro.local
TEST 23:53:02.680 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 250-192.168.10.130
250-8BITMIME
250-STARTTLS
250 Ok
TEST 23:53:02.680 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61067
TEST 23:53:02.680 [SocketAcceptorIoProcessor-0.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61067
TEST 23:53:02.680 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61067
TEST 23:53:02.681 [SocketAcceptorIoProcessor-0.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61067
TEST 23:53:02.681 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - C: MAIL FROM:<user at host.dom>
TEST 23:53:02.681 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 250 Ok
TEST 23:53:02.681 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61067
TEST 23:53:02.681 [SocketAcceptorIoProcessor-0.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61067
TEST 23:53:02.682 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61067
TEST 23:53:02.682 [SocketAcceptorIoProcessor-0.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61067
TEST 23:53:02.682 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - C: RCPT TO:<noreply at qos.ch>
TEST 23:53:02.683 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 250 Ok
TEST 23:53:02.683 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61067
TEST 23:53:02.683 [SocketAcceptorIoProcessor-0.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61067
TEST 23:53:02.684 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61067
TEST 23:53:02.684 [SocketAcceptorIoProcessor-0.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61067
TEST 23:53:02.684 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - C: DATA
TEST 23:53:02.684 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 354 End data with  
<CR><LF>.<CR><LF>
TEST 23:53:02.684 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61067
TEST 23:53:02.684 [SocketAcceptorIoProcessor-0.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61067
TEST 23:53:02.685 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61067
TEST 23:53:02.690 [SocketAcceptorIoProcessor-0.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61067
TEST 23:53:02.692 [SubEthaSMTP Thread 1] DEBUG  
org.subethamail.wiser.Wiser - Delivering new message ...
TEST 23:53:02.704 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 250 Ok
TEST 23:53:02.705 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61067
TEST 23:53:02.705 [SocketAcceptorIoProcessor-0.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61067
TEST 23:53:02.705 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61067
TEST 23:53:02.706 [SocketAcceptorIoProcessor-0.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61067
TEST 23:53:02.706 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - C: QUIT
TEST 23:53:02.706 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 221 Bye
TEST 23:53:02.707 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61067
TEST 23:53:02.710 [SocketAcceptorIoProcessor-0.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61067
TEST 23:53:02.714 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - Active connections = 0
TEST 23:53:02.715 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61067
[HEADER
190  [main] DEBUG test  
ch.qos.logback.classic.net.SMTPAppender_SubethaSMTPTest - hello
191  [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:122) [test-classes/:na]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [na: 
1.6.0_15]
	at sun.reflect.NativeMethodAccessorImpl.invoke 
(NativeMethodAccessorImpl.java:39) [na:1.6.0_15]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke 
(DelegatingMethodAccessorImpl.java:25) [na:1.6.0_15]
	at java.lang.reflect.Method.invoke(Method.java:597) [na:1.6.0_15]
	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.2.jar:2.4.2]
	at  
org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet 
(AbstractDirectoryTestSuite.java:140) [surefire-api-2.4.2.jar:2.1]
	at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute 
(AbstractDirectoryTestSuite.java:127) [surefire-api-2.4.2.jar:2.1]
	at org.apache.maven.surefire.Surefire.run(Surefire.java:177)  
[surefire-api-2.4.2.jar:2.1]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [na: 
1.6.0_15]
	at sun.reflect.NativeMethodAccessorImpl.invoke 
(NativeMethodAccessorImpl.java:39) [na:1.6.0_15]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke 
(DelegatingMethodAccessorImpl.java:25) [na:1.6.0_15]
	at java.lang.reflect.Method.invoke(Method.java:597) [na:1.6.0_15]
	at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess 
(SurefireBooter.java:338) [surefire-booter-2.4.2.jar:na]
	at org.apache.maven.surefire.booter.SurefireBooter.main 
(SurefireBooter.java:997) [surefire-booter-2.4.2.jar:na]
FOOTER
TEST 23:53:02.726 [main] INFO  o.subethamail.smtp.server.SMTPServer -  
SMTP Server socket shut down.
TEST 23:53:02.743 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: AUTH
TEST 23:53:02.745 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: DATA
TEST 23:53:02.745 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: EHLO
TEST 23:53:02.745 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: HELO
TEST 23:53:02.745 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: HELP
TEST 23:53:02.745 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: MAIL
TEST 23:53:02.745 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: NOOP
TEST 23:53:02.745 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: QUIT
TEST 23:53:02.745 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: RCPT
TEST 23:53:02.745 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: RSET
TEST 23:53:02.745 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: STARTTLS
TEST 23:53:02.745 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: VRFY
TEST 23:53:02.763 [SocketAcceptorIoProcessor-1.0] DEBUG  
o.s.smtp.server.ConnectionHandler - Active connections = 1
TEST 23:53:02.763 [SocketAcceptorIoProcessor-1.0] DEBUG  
o.s.smtp.server.ConnectionHandler - SMTP connection count: 1
TEST 23:53:02.763 [SocketAcceptorIoProcessor-1.0] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 220 192.168.10.130 ESMTP  
SubEthaSMTP
TEST 23:53:02.774 [SocketAcceptorIoProcessor-1.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61068
TEST 23:53:02.778 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - C: EHLO rgoerss-macbook-pro.local
TEST 23:53:02.778 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 250-192.168.10.130
250-8BITMIME
250-STARTTLS
250 Ok
TEST 23:53:02.778 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61068
TEST 23:53:02.779 [SocketAcceptorIoProcessor-1.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61068
TEST 23:53:02.779 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61068
TEST 23:53:02.779 [SocketAcceptorIoProcessor-1.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61068
TEST 23:53:02.780 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - C: MAIL FROM:<user at host.dom>
TEST 23:53:02.780 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 250 Ok
TEST 23:53:02.780 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61068
TEST 23:53:02.780 [SocketAcceptorIoProcessor-1.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61068
TEST 23:53:02.780 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61068
TEST 23:53:02.780 [SocketAcceptorIoProcessor-1.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61068
TEST 23:53:02.783 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - C: RCPT TO:<noreply at qos.ch>
TEST 23:53:02.784 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 250 Ok
TEST 23:53:02.784 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61068
TEST 23:53:02.784 [SocketAcceptorIoProcessor-1.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61068
TEST 23:53:02.784 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61068
TEST 23:53:02.784 [SocketAcceptorIoProcessor-1.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61068
TEST 23:53:02.784 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - C: DATA
TEST 23:53:02.784 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 354 End data with  
<CR><LF>.<CR><LF>
TEST 23:53:02.785 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61068
TEST 23:53:02.785 [SocketAcceptorIoProcessor-1.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61068
TEST 23:53:02.785 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61068
TEST 23:53:02.796 [SocketAcceptorIoProcessor-1.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61068
TEST 23:53:02.796 [SubEthaSMTP Thread 1] DEBUG  
org.subethamail.wiser.Wiser - Delivering new message ...
TEST 23:53:02.796 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 250 Ok
TEST 23:53:02.796 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61068
TEST 23:53:02.798 [SocketAcceptorIoProcessor-1.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61068
TEST 23:53:02.806 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61068
TEST 23:53:02.807 [SocketAcceptorIoProcessor-1.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61068
TEST 23:53:02.807 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - C: QUIT
TEST 23:53:02.807 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 221 Bye
TEST 23:53:02.808 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61068
TEST 23:53:02.808 [SocketAcceptorIoProcessor-1.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61068
TEST 23:53:02.809 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - Active connections = 0
TEST 23:53:02.810 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61068
TEST 23:53:02.918 [main] INFO  o.subethamail.smtp.server.SMTPServer -  
SMTP Server socket shut down.
TEST 23:53:02.923 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: AUTH
TEST 23:53:02.923 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: DATA
TEST 23:53:02.923 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: EHLO
TEST 23:53:02.923 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: HELO
TEST 23:53:02.923 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: HELP
TEST 23:53:02.923 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: MAIL
TEST 23:53:02.923 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: NOOP
TEST 23:53:02.923 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: QUIT
TEST 23:53:02.923 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: RCPT
TEST 23:53:02.923 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: RSET
TEST 23:53:02.924 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: STARTTLS
TEST 23:53:02.924 [main] DEBUG o.s.smtp.server.CommandHandler - Added  
command: VRFY
TEST 23:53:03.073 [SocketAcceptorIoProcessor-2.0] DEBUG  
o.s.smtp.server.ConnectionHandler - Active connections = 1
TEST 23:53:03.073 [SocketAcceptorIoProcessor-2.0] DEBUG  
o.s.smtp.server.ConnectionHandler - SMTP connection count: 1
TEST 23:53:03.074 [SocketAcceptorIoProcessor-2.0] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 220 192.168.10.130 ESMTP  
SubEthaSMTP
TEST 23:53:03.074 [SocketAcceptorIoProcessor-2.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61069
TEST 23:53:03.074 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61069
TEST 23:53:03.074 [SocketAcceptorIoProcessor-2.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61069
TEST 23:53:03.075 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61069
TEST 23:53:03.075 [SocketAcceptorIoProcessor-2.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61069
TEST 23:53:03.076 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - C: EHLO rgoerss-macbook-pro.local
TEST 23:53:03.076 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 250-192.168.10.130
250-8BITMIME
250-STARTTLS
250 Ok
TEST 23:53:03.076 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61069
TEST 23:53:03.077 [SocketAcceptorIoProcessor-2.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61069
TEST 23:53:03.077 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61069
TEST 23:53:03.077 [SocketAcceptorIoProcessor-2.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61069
TEST 23:53:03.077 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - C: MAIL FROM:<user at host.dom>
TEST 23:53:03.077 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 250 Ok
TEST 23:53:03.077 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61069
TEST 23:53:03.078 [SocketAcceptorIoProcessor-2.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61069
TEST 23:53:03.078 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61069
TEST 23:53:03.078 [SocketAcceptorIoProcessor-2.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61069
TEST 23:53:03.078 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - C: RCPT TO:<noreply at qos.ch>
TEST 23:53:03.078 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 250 Ok
TEST 23:53:03.078 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61069
TEST 23:53:03.079 [SocketAcceptorIoProcessor-2.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61069
TEST 23:53:03.079 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - C: DATA
TEST 23:53:03.079 [SubEthaSMTP Thread 1] DEBUG  
o.s.smtp.server.ConnectionHandler - S: 354 End data with  
<CR><LF>.<CR><LF>
TEST 23:53:03.080 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61069
TEST 23:53:03.080 [SocketAcceptorIoProcessor-2.0] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Launching thread for / 
127.0.0.1:61069
TEST 23:53:03.080 [SubEthaSMTP Thread 1] DEBUG  
o.a.m.filter.executor.ExecutorFilter - Exiting since queue is empty  
for /127.0.0.1:61069
^CDestroying 1 processes
Destroying process..
Destroyed 1 processes

More information about the logback-dev mailing list