java - JUnit 测试 "Times Out"尽管执行速度很快？

Question

我有几个测试用例，JUnit 告诉我在 10000 毫秒后超时，而整个测试运行仅持续几秒钟。这是输出:

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] ------------------------------------------------------------------------

当整个测试运行仅持续 4.3 秒时，我的测试似乎不太可能因为运行时间超过 10(或 50)秒而超时。 :)

这是我用来运行测试的 POM 中的 surefire 配置:

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

有没有人对为什么会发生这种情况有任何想法？

编辑:根据以下要求，这里有一些更多信息。

这是其中一项测试的输出。我正在构建一个简单的传输机制，所以我正在构建关闭流并中断 NIO 线程以使它们退出的单元测试，这就是为什么会有所有这些(预期的)IO 类型的 Exception .

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)

测试使用 @Test(timeout=/* number */) 运行。这是其中一个测试用例的签名:

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

编辑:这是 surefire 日志的全部内容:

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

编辑:为了后代，@MatthewFarwell 下面的回答是正确的，如下所示。我发现 JUnit 4.12-SNAPSHOT 在 Maven Central 中不可用，因此我没有设置更多存储库并依赖于 SNAPSHOT 工件，而是将我的测试用例简单地包装在 try/ 中catch 用于 InterruptedException，它阻止了测试用例传播 InterruptedException，从而解决了问题。

Answer 1

这是 JUnit 的问题。事实上，如果存在 InterruptedException，则会出现“测试超时”消息:

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

结果:

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

至少可以说是令人困惑。即使您使用 Timeout Rule 也会发生这种情况.因此，在您的示例中，您抛出了一个 InterruptedException

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

这会导致错误的超时异常。

这是 4.11(及之前版本)中的错误，但它在 4.12-SNAPSHOT 中可以正常工作，它会产生:

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

所以，我会试用 4.12-SNAPSHOT，如果可行，您可以继续使用它(使用您自己的私有(private)副本)，或者复制新的 Timeout规则 & FailOnTimeout类到您的代码中。

然后，当 4.12 发布时，您可以恢复。不知道什么时候会顺便说一句。