JUnit Test "Times Out" Despite Executing Quickly?

java junit junit4 maven-surefire-plugin
sigpwned picture sigpwned · Jun 10, 2013 · Viewed 9.5k times · Source

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 Exceptions.

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 InterruptedExceptions, which kept the test case from propagating the InterruptedException, which fixed the problem.

Answer

Matthew Farwell picture Matthew Farwell · Jun 18, 2013

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.

Related questions

How do you assert that a certain exception is thrown in JUnit 4 tests?

How can I use JUnit4 idiomatically to test that some code throws an exception? While I can certainly do something like this: @Test public void testFooThrowsIndexOutOfBoundsException() { boolean thrown = false; try { foo.doStuff(); } catch (IndexOutOfBoundsException e) { thrown = true; } assertTrue(thrown); } I …

Read More
How to run test methods in specific order in JUnit4?

I want to execute test methods which are annotated by @Test in specific order. For example: public class MyTest { @Test public void test1(){} @Test public void test2(){} } I want to ensure to run test1() before test2() each time I run …

Read More
Java/ JUnit - AssertTrue vs AssertFalse

I'm pretty new to Java and am following the Eclipse Total Beginner's Tutorials. They are all very helpful, but in Lesson 12, he uses assertTrue for one test case and assertFalse for another. Here's the code: // Check the book out to …

Read More