JUnit Test "Times Out" pomimo szybkiego wykonywania?

Question

Mam kilka przypadków testowych, które JUnit informuje mnie o przekroczeniu limitu czasu o 10000ms, gdy cały test trwa tylko kilka sekund. Oto wynik:

Tests run: 3, Failures: 0, Errors: 2, Skipped: 0, Time elapsed: 2.528 sec <<< FAILURE! 
closeTest1(com.w2ogroup.analytics.sibyl.transport.impl.http.server.HttpServerTransportTests) Time elapsed: 1.654 sec <<< ERROR! 
java.lang.Exception: test timed out after 10000 milliseconds 

closeTest2(com.w2ogroup.analytics.sibyl.transport.impl.http.server.HttpServerTransportTests) Time elapsed: 0.672 sec <<< ERROR! 
java.lang.Exception: test timed out after 50000 milliseconds 


Results : 

Tests in error: 
    HttpServerTransportTests » test timed out after 10000 milliseconds 
    HttpServerTransportTests » test timed out after 50000 milliseconds 

Tests run: 3, Failures: 0, Errors: 2, Skipped: 0 

[INFO] ------------------------------------------------------------------------ 
[INFO] BUILD FAILURE 
[INFO] ------------------------------------------------------------------------ 
[INFO] Total time: 4.383s 
[INFO] Finished at: Sun Jun 09 19:00:09 PDT 2013 
[INFO] Final Memory: 9M/129M 
[INFO] ------------------------------------------------------------------------ 

Wydaje się mało prawdopodobne, że moje testy timed out biorąc więcej niż 10 (lub 50) sekund, aby uruchomić, gdy tylko cały test nie trwał 4.3s. :)

Oto murowany konfiguracja z POM Używam uruchomić badań:

<plugin> 
    <groupId>org.apache.maven.plugins</groupId> 
    <artifactId>maven-surefire-plugin</artifactId> 
    <version>${maven-surefire-plugin.version}</version> 
    <configuration> 
    <!-- 
     We always want to exclude provided deps. I'm not sure why this 
     isn't the default. 
    --> 
    <classpathDependencyScopeExclude>provided</classpathDependencyScopeExclude> 
    <includes> 
     <include>**/*Tests.*</include> 
    </includes> 
    </configuration> 
</plugin> 

Czy ktoś ma jakieś myśli o tym, dlaczego to może być prawda?

EDYCJA: Oto kilka dodatkowych informacji, zgodnie z prośbą poniżej.

Oto wyniki jednego z testów. Buduję prosty mechanizm transportu, więc buduję testy jednostkowe, które zamykają strumienie i przerywają wątki NIO, aby je zamknąć, dlatego są wszystkie te (oczekiwane) IO-type Exception s.

Running com.siggroup.analytics.sibyl.transport.impl.http.server.HttpServerTransportTests 
2013-06-10 08:32:53.195:INFO:oejs.Server:Thread-0: jetty-9.0.3.v20130506 
Jun 10, 2013 8:32:53 AM com.sun.jersey.server.impl.application.WebApplicationImpl _initiate 
INFO: Initiating Jersey application, version 'Jersey: 1.17.1 02/28/2013 12:47 PM' 
2013-06-10 08:32:53.925:INFO:oejsh.ContextHandler:Thread-0: Started o.e.j.s.ServletContextHandler@30db7df3{/,null,AVAILABLE} 
2013-06-10 08:32:54.136:INFO:oejs.ServerConnector:Thread-0: Started ServerConnector@4584e5a8{HTTP/1.1}{0.0.0.0:8080} 
org.eclipse.jetty.server.HttpConnection$Input$1: SelectChannelEndPoint@329ecdd9{/127.0.0.1:58667<r-l>/127.0.0.1:8080,o=true,is=false,os=false,fi=FillInterest@32f4dc3$ 
EOF 
     at org.eclipse.jetty.server.HttpConnection$Input.blockForContent(HttpConnection.java:588) 
     at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:130) 
     at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:283) 
     at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:325) 
     at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:177) 
     at sun.nio.cs.StreamDecoder.read0(StreamDecoder.java:126) 
     at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:112) 
     at java.io.InputStreamReader.read(InputStreamReader.java:168) 
     at com.siggroup.analytics.sibyl.transport.impl.http.server.WorkerTrackingDelegatingReader$2.work(WorkerTrackingDelegatingReader.java:64) 
     at com.siggroup.analytics.sibyl.transport.impl.http.server.WorkerTrackingDelegatingReader$2.work(WorkerTrackingDelegatingReader.java:1) 
     at com.siggroup.analytics.commons.concurrent.Scope.work(Scope.java:49) 
     at com.siggroup.analytics.sibyl.transport.impl.http.server.WorkerTrackingDelegatingReader.read(WorkerTrackingDelegatingReader.java:60) 
     at java.io.FilterReader.read(FilterReader.java:65) 
     at java.io.PushbackReader.read(PushbackReader.java:90) 
     at com.siggroup.sibyl.transport.impl.readerwriter.ReaderWriterTransportReaderThread.readPacket(ReaderWriterTransportReaderThread.java:32) 
     at com.siggroup.sibyl.transport.impl.queued.QueuedTransportReaderThread.run(QueuedTransportReaderThread.java:21) 
Caused by: java.lang.InterruptedException 
     at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:996) 
     at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1303) 
     at java.util.concurrent.Semaphore.acquire(Semaphore.java:317) 
     at org.eclipse.jetty.util.BlockingCallback.block(BlockingCallback.java:96) 
     at org.eclipse.jetty.server.HttpConnection$Input.blockForContent(HttpConnection.java:559) 
     ... 15 more 
2013-06-10 08:32:54.958:WARN:oejs.HttpConnection:qtp557611759-26: HttpConnection@6a341611{FILLING_BLOCKED},g=HttpGenerator{s=END},p=HttpParser{s=CHUNKED_CONTENT,1 of$ 
java.lang.IllegalStateException: Already Blocked 
     at org.eclipse.jetty.io.AbstractConnection.block(AbstractConnection.java:233) 
     at org.eclipse.jetty.server.HttpConnection.access$400(HttpConnection.java:50) 
     at org.eclipse.jetty.server.HttpConnection$Input.blockForContent(HttpConnection.java:557) 
     at org.eclipse.jetty.server.HttpInput.consumeAll(HttpInput.java:282) 
     at org.eclipse.jetty.server.HttpConnection.completed(HttpConnection.java:460) 
     at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:333) 
     at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:225) 
     at org.eclipse.jetty.io.AbstractConnection$ReadCallback.run(AbstractConnection.java:358) 
     at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:596) 
     at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:527) 
     at java.lang.Thread.run(Thread.java:722) 
java.io.EOFException 
     at com.siggroup.sibyl.transport.impl.readerwriter.ReaderWriterTransportReaderThread.readPacket(ReaderWriterTransportReaderThread.java:36) 
     at com.siggroup.sibyl.transport.impl.queued.QueuedTransportReaderThread.run(QueuedTransportReaderThread.java:21) 

Testy przeprowadzane są pod numerem @Test(timeout=/* number */). Oto podpis jednego z przypadków testowych:

@Test(timeout = 10000) 
public void closeTest1() throws IOException, InterruptedException { 
    /* Test goes here */ 
} 

EDIT: Oto cała zawartość murowany dzienniku:

------------------------------------------------------------------------------- 
Test set: com.w2ogroup.analytics.sibyl.transport.impl.http.server.HttpServerTransportTests 
------------------------------------------------------------------------------- 
Tests run: 3, Failures: 0, Errors: 2, Skipped: 0, Time elapsed: 3.136 sec <<< FAILURE! 
closeTest1(com.w2ogroup.analytics.sibyl.transport.impl.http.server.HttpServerTransportTests) Time elapsed: 2.218 sec <<< ERROR! 
java.lang.Exception: test timed out after 10000 milliseconds 

closeTest2(com.w2ogroup.analytics.sibyl.transport.impl.http.server.HttpServerTransportTests) Time elapsed: 0.661 sec <<< ERROR! 
java.lang.Exception: test timed out after 50000 milliseconds 

EDIT: Dla potomności, @ odpowiedź MatthewFarwell jest poniżej poprawne, jak wskazano. Zauważyłem, że JUnit 4.12-SNAPSHOT nie był dostępny w Maven Central, więc zamiast tworzyć więcej repozytoriów i mieć zależność od artefaktu SNAPSHOT, po prostu opakowałem mój testowy przypadek w try/catch dla InterruptedException s, który zachował test z propagowania InterruptedException, która rozwiązała problem.

Answer 1

Jest to problem z JUnit. pojawia się w rzeczywistości, 'test timed out' wiadomość, czy jest InterruptedException:

public class FooTest { 
    @Test(timeout = 10000) 
    public void timeoutTest() throws Exception { 
    throw new InterruptedException("hello"); 
    } 
} 

skutkuje:

java.lang.Exception: test timed out after 10000 milliseconds 

która jest mylące co najmniej. Dzieje się tak, nawet jeśli używasz Timeout Rule. Tak więc, w przykładzie, jesteś rzuca InterruptedException

Caused by: java.lang.InterruptedException 
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:996) 
    ... 

i to jest przyczyną fałszywych wyjątku limitu czasu.

Jest to błąd w 4,11 (i poprzednie), ale to nie działa poprawnie w 4.12-SNAPSHOT, produkuje:

java.lang.InterruptedException: hello 
    at xxx.xxx.xxx.FooTest.timeoutTest(FooTest.java:13) 
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) 
    ... 

Tak, chciałbym wypróbować 4.12-SNAPSHOT, a jeśli to działa, możesz dalej używać go (z własną prywatną kopią) lub skopiować nową klasę & FailOnTimeout do swojego kodu.

Następnie, gdy 4.12 pojawi się, możesz wrócić. Nie mam pojęcia, kiedy to nastąpi.

Answer 2

JUnit wykrywa test, którego limit czasu upłynął o catching a TimeoutException. Zwykle jest to spowodowane przez framework testowy wywołujący shutdownNow na ExecutorService, który uruchamia test.

Czy to możliwe, że jeden z twoich testów niepowodzenia sam rzuca ten wyjątek, a JUnit zgłasza to jako czas testu?

Answer 3

Czy przez każdą zmianę zdefiniowano czas oczekiwania na te testy?

@Test (timeout=10000) 

lub

@Rule 
    public Timeout globalTimeout= new Timeout(10); 

Answer 4

Wygląda jak połączenie wisi

org.eclipse.jetty.server.HttpConnection$Input.blockForContent(HttpConnection.java:588) 

a test nie ma tak naprawdę kończy się po kilku sekundach.

Spróbuj koncentrując się na httpconnection błędu (lub dodać swój kod, jeśli potrzebujesz dalszej pomocy)

Zobacz przykłady tego problemu:

• https://bugs.eclipse.org/bugs/show_bug.cgi?id=401962
• https://code.google.com/p/gitblit/issues/detail?id=164