I've got a couple of test cases that JUnit is telling me time out in 10000ms when the whole test run only lasts a couple of seconds. Here's the output:
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] ------------------------------------------------------------------------
It seems unlikely that my tests have timed out by taking more than 10 (or 50) seconds to run when the whole test run only lasted 4.3s. :)
Here's the surefire configuration from the POM I'm using to run the tests:
<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>
Does anyone have any thoughts about why this could be happening?
EDIT: Here's some more information, as requested below.
Here is the output of one of the tests. I'm building a simple transport mechanism, so I'm building unit tests that close streams and interrupt NIO threads to make them quit, which is why there are all those (expected) 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)
The tests are run with @Test(timeout=/* number */)
. Here's the signature of one of the test cases:
@Test(timeout = 10000)
public void closeTest1() throws IOException, InterruptedException {
/* Test goes here */
}
EDIT: Here is the entire contents of the surefire log:
-------------------------------------------------------------------------------
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: For posterity, @MatthewFarwell's answer below is correct, as indicated. I found that JUnit 4.12-SNAPSHOT was not available in Maven Central, so rather than set up more repositories and have a dependency on a SNAPSHOT artifact, I simply wrapped my test case in a try
/catch
for InterruptedException
s, which kept the test case from propagating the InterruptedException
, which fixed the problem.
This is an issue with JUnit. In fact, the 'test timed out' message appears if there is an InterruptedException
:
public class FooTest {
@Test(timeout = 10000)
public void timeoutTest() throws Exception {
throw new InterruptedException("hello");
}
}
results in:
java.lang.Exception: test timed out after 10000 milliseconds
which is confusing to say the least. This happens even if you use the Timeout Rule. So, in your example, you are throwing an InterruptedException
Caused by: java.lang.InterruptedException
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:996)
...
and this is causing the false timeout exception.
This is a bug in 4.11 (and previous), but it does work correctly in 4.12-SNAPSHOT, it produces:
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)
...
So, I would try out 4.12-SNAPSHOT, and if that works, you can either continue to use it (with your own private copy), or copy the new Timeout rule & FailOnTimeout class into your code.
Then, when 4.12 comes out, you can revert. No idea when that will be btw.
Do you have by any change a timeout defined for theses tests?
@Test (timeout=10000)
or
@Rule
public Timeout globalTimeout= new Timeout(10);
JUnit detects a test that has timed out by catching a TimeoutException
. This will normally be caused by the test framework calling shutdownNow
on the ExecutorService
that's running the test.
Is it possible that one of your failing tests is throwing this exception itself, and JUnit is reporting it as a test timeout?
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With