12

テスト実行全体が数秒しか続かないときに、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の確実な構成は次のとおりです。

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

なぜこれが起こっているのかについて考えている人はいますか？

編集：以下に要求されているように、ここにいくつかの詳細情報があります。

これは、テストの 1 つの出力です。私は単純なトランスポートメカニズムを構築しているので、ストリームを閉じて NIO スレッドを中断して終了させる単体テストを構築しています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 */)ます。以下は、テスト ケースの 1 つの署名です。

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

編集：確実なログの内容全体は次のとおりです。

-------------------------------------------------------------------------------
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/ catchforでラップしましInterruptedExceptionた。InterruptedException、問題を修正しました。

4

4 に答える 4

9

これは 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

これは控えめに言っても混乱を招きます。これは、タイムアウト ルールを使用した場合でも発生します。したがって、あなたの例では、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 を試してみます。それが機能する場合は、(自分のプライベート コピーで) 引き続き使用するか、新しいTimeoutルールとFailOnTimeoutクラスをコードにコピーできます。

その後、4.12 が出たら元に戻せます。それがいつになるかわかりません。

于 2013-06-18T14:04:50.127 に答える
2

これらのテストに定義されたタイムアウトを変更しましたか?

@Test (timeout=10000)

また

 @Rule
  public Timeout globalTimeout= new Timeout(10);
于 2013-06-10T12:28:19.753 に答える
1

JUnit は、タイムアウトしたテストをキャッチTimeoutExceptionして検出します。shutdownNowこれは通常、テストを実行している を呼び出すテスト フレームワークによって発生しExecutorServiceます。

失敗したテストの 1 つがこの例外自体をスローし、JUnit がそれをテスト タイムアウトとして報告している可能性はありますか?

于 2013-06-10T10:49:24.770 に答える