JUnit kiểm tra "Times Out" mặc dù thực hiện nhanh chóng?

Question

Tôi đã có một vài trường hợp thử nghiệm mà JUnit đang nói với tôi thời gian trong 10000ms khi toàn bộ chạy thử nghiệm chỉ kéo dài một vài giây. Dưới đây là kết quả:

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

Có vẻ như không chắc rằng thử nghiệm của tôi đã timed out bằng cách tham gia nhiều hơn 10 (hoặc 50) giây để chạy khi chạy thử toàn bộ chỉ kéo dài 4.3s. :)

Dưới đây là cấu hình chắc chắn hơn từ POM Tôi đang sử dụng để chạy các bài kiểm tra:

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

Có ai có bất kỳ suy nghĩ về lý do tại sao điều này có thể xảy ra?

EDIT: Dưới đây là một số thông tin khác, như được yêu cầu bên dưới.

Đây là đầu ra của một trong các thử nghiệm. Tôi đang xây dựng một cơ chế vận chuyển đơn giản, vì vậy tôi đang xây dựng các bài kiểm tra đơn vị đóng luồng và ngắt các luồng NIO để làm cho chúng thoát, đó là lý do tại sao có tất cả những thứ (được mong đợi) kiểu IO 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) 

Các thử nghiệm được chạy với @Test(timeout=/* number */). Dưới đây là chữ ký của một trong những trường hợp thử nghiệm:

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

EDIT: Dưới đây là toàn bộ nội dung của nhật ký chắc chắn hơn:

------------------------------------------------------------------------------- 
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: Đối với hậu thế, @ câu trả lời MatthewFarwell của dưới đây là chính xác, như được chỉ ra. Tôi thấy rằng JUnit 4.12-SNAPSHOT không có sẵn trong Maven Central, vì vậy thay vì thiết lập thêm kho và có phụ thuộc vào một tạo phẩm SNAPSHOT, tôi chỉ cần bọc vỏ thử nghiệm của mình vào try/catch cho InterruptedException s. từ việc tuyên truyền InterruptedException, đã khắc phục được sự cố.

Answer 1

Đây là vấn đề với JUnit. Trong thực tế, 'test timed out' thông báo xuất hiện nếu có một InterruptedException:

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

kết quả trong:

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

mà là khó hiểu để nói rằng ít nhất. Điều này xảy ra ngay cả khi bạn sử dụng Timeout Rule. Vì vậy, trong ví dụ của bạn, bạn đang ném một số InterruptedException

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

và điều này gây ra ngoại lệ hết thời gian chờ sai.

Đây là một lỗi trong 4.11 (và trước đó), nhưng nó không hoạt động chính xác trong 4.12-THÔNG SỐ CHUNG, nó tạo ra:

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

Vì vậy, tôi sẽ cố gắng ra 4.12-THÔNG SỐ CHUNG, và nếu thành công, bạn có thể tiếp tục sử dụng nó (với bản sao riêng của bạn) hoặc sao chép quy tắc Timeout quy tắc & FailOnTimeout mới vào mã của bạn.

Sau đó, khi 4.12 xuất hiện, bạn có thể hoàn nguyên. Không có ý tưởng khi đó sẽ được btw.

Answer 2

JUnit phát hiện thử nghiệm đã hết thời gian theo catching a TimeoutException. Điều này thường sẽ do khung kiểm tra gọi shutdownNow trên ExecutorService đang chạy thử nghiệm.

Có thể một trong các bài kiểm tra không thành công của bạn đang tự ném ngoại lệ này và JUnit báo cáo nó là thời gian chờ kiểm tra?

Answer 3

Bạn có thay đổi thời gian chờ nào được xác định cho các bài kiểm tra đề tài không?

@Test (timeout=10000) 

hoặc

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

Answer 4

Dường như các kết nối bị treo

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

Và kiểm tra không thực sự kết thúc sau một vài giây.

Cố gắng tập trung vào HttpConnection lỗi (hoặc thêm mã của bạn nếu bạn cần thêm trợ giúp)

Xem ví dụ cho vấn đề này:

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