search

eclipse-vertx / vertx-junit5

Testing Vert.x applications with JUnit 5
Apache License 2.0
44 stars 32 forks source link

IntegrationTest: BindException: Address already in use #51

Closed julianladisch closed 6 years ago

julianladisch commented 6 years ago

On my slow laptop mvn surefire:test always runs successfully but mvn surefire:test -Dtest=* always fails.

The failure is in IntegrationTest only. It fails with one out of these four failure message types:

[INFO] Running io.vertx.junit5.IntegrationTest
Sep 24, 2018 1:57:52 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 2893 ms, time limit is 2000 ms
Sep 24, 2018 1:57:53 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 3893 ms, time limit is 2000 ms
[ERROR] Tests run: 3, Failures: 2, Errors: 0, Skipped: 0, Time elapsed: 5.502 s <<< FAILURE! - in io.vertx.junit5.IntegrationTest
[ERROR] vertx_check_http_server_response  Time elapsed: 5.196 s  <<< FAILURE!
org.junit.ComparisonFailure: expected:<[tru]e> but was:<[fals]e>
        at io.vertx.junit5.IntegrationTest$Naked.vertx_check_http_server_response(IntegrationTest.java:86)

[ERROR] start_and_request_http_server_with_checkpoints{Vertx, VertxTestContext}  Time elapsed: 0.182 s  <<< FAILURE!
java.lang.AssertionError: org.junit.ComparisonFailure: expected:<"[Ok]"> but was:<"[Plop]">
        at io.vertx.junit5.IntegrationTest$WithExtension.lambda$3(IntegrationTest.java:124)
        at io.vertx.junit5.IntegrationTest$WithExtension.lambda$2(IntegrationTest.java:124)
[INFO] Running io.vertx.junit5.IntegrationTest
Sep 24, 2018 1:40:54 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 2971 ms, time limit is 2000 ms
Sep 24, 2018 1:40:55 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 3979 ms, time limit is 2000 ms
[ERROR] Tests run: 3, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 5.206 s <<< FAILURE! - in io.vertx.junit5.IntegrationTest
[ERROR] start_and_request_http_server_with_checkpoints{Vertx, VertxTestContext}  Time elapsed: 0.284 s  <<< ERROR!
java.net.BindException: Address already in use: bind
[INFO] Running io.vertx.junit5.IntegrationTest
Sep 24, 2018 1:52:52 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 2824 ms, time limit is 2000 ms
Sep 24, 2018 1:52:53 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 3825 ms, time limit is 2000 ms
[ERROR] Tests run: 3, Failures: 1, Errors: 1, Skipped: 0, Time elapsed: 5.812 s <<< FAILURE! - in io.vertx.junit5.IntegrationTest
[ERROR] vertx_check_http_server_response  Time elapsed: 5.278 s  <<< FAILURE!
org.junit.ComparisonFailure: expected:<[tru]e> but was:<[fals]e>
        at io.vertx.junit5.IntegrationTest$Naked.vertx_check_http_server_response(IntegrationTest.java:86)

[ERROR] start_and_request_http_server_with_checkpoints{Vertx, VertxTestContext}  Time elapsed: 0.343 s  <<< ERROR!
java.net.BindException: Address already in use: bind
[INFO] Running io.vertx.junit5.IntegrationTest
Sep 24, 2018 1:56:26 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 2899 ms, time limit is 2000 ms
Sep 24, 2018 1:56:27 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 3899 ms, time limit is 2000 ms
Sep 24, 2018 1:56:28 PM io.netty.util.concurrent.DefaultPromise notifyListener0
WARNING: An exception was thrown by io.vertx.core.net.impl.ChannelProvider$$Lambda$332/148811425.operationComplete()
java.util.concurrent.RejectedExecutionException: event executor terminated
        at io.netty.util.concurrent.SingleThreadEventExecutor.reject(SingleThreadEventExecutor.java:842)
        at io.netty.util.concurrent.SingleThreadEventExecutor.offerTask(SingleThreadEventExecutor.java:328)
        at io.netty.util.concurrent.SingleThreadEventExecutor.addTask(SingleThreadEventExecutor.java:321)
        at io.netty.util.concurrent.SingleThreadEventExecutor.execute(SingleThreadEventExecutor.java:765)
        at io.vertx.core.http.impl.pool.Pool.acquireConnection(Pool.java:200)
        at io.vertx.core.http.impl.pool.Pool.checkPending(Pool.java:233)
        at io.vertx.core.http.impl.pool.Pool.lambda$createConnection$4(Pool.java:322)
        at io.vertx.core.impl.FutureImpl.tryFail(FutureImpl.java:170)
        at io.vertx.core.http.impl.HttpChannelConnector.connectFailed(HttpChannelConnector.java:297)
        at io.vertx.core.http.impl.HttpChannelConnector.lambda$doConnect$2(HttpChannelConnector.java:203)
        at io.vertx.core.net.impl.ChannelProvider.lambda$connect$0(ChannelProvider.java:54)
        at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:511)
        at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:485)
        at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:424)
        at io.netty.util.concurrent.DefaultPromise.addListener(DefaultPromise.java:162)
        at io.netty.channel.DefaultChannelPromise.addListener(DefaultChannelPromise.java:95)
        at io.netty.channel.DefaultChannelPromise.addListener(DefaultChannelPromise.java:30)
        at io.vertx.core.net.impl.ChannelProvider.connect(ChannelProvider.java:50)
        at io.vertx.core.http.impl.HttpChannelConnector.doConnect(HttpChannelConnector.java:207)
        at io.vertx.core.http.impl.HttpChannelConnector.connect(HttpChannelConnector.java:103)
        at io.vertx.core.http.impl.pool.Pool.createConnection(Pool.java:291)
        at io.vertx.core.http.impl.pool.Pool.lambda$acquireConnection$3(Pool.java:201)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasksFrom(SingleThreadEventExecutor.java:380)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:355)
        at io.netty.util.concurrent.SingleThreadEventExecutor.confirmShutdown(SingleThreadEventExecutor.java:701)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:474)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.lang.Thread.run(Thread.java:748)

Sep 24, 2018 1:56:28 PM io.vertx.core.net.impl.ConnectionBase
SEVERE: event executor terminated
Sep 24, 2018 1:56:28 PM io.vertx.core.net.impl.ConnectionBase
SEVERE: event executor terminated
Sep 24, 2018 1:56:28 PM io.vertx.core.net.impl.ConnectionBase
SEVERE: event executor terminated
Sep 24, 2018 1:56:28 PM io.vertx.core.net.impl.ConnectionBase
SEVERE: event executor terminated
[ERROR] Tests run: 3, Failures: 1, Errors: 1, Skipped: 0, Time elapsed: 5.748 s <<< FAILURE! - in io.vertx.junit5.IntegrationTest
[ERROR] vertx_check_http_server_response  Time elapsed: 5.08 s  <<< FAILURE!
org.junit.ComparisonFailure: expected:<[tru]e> but was:<[fals]e>
        at io.vertx.junit5.IntegrationTest$Naked.vertx_check_http_server_response(IntegrationTest.java:86)

[ERROR] start_and_request_http_server_with_checkpoints{Vertx, VertxTestContext}  Time elapsed: 0.47 s  <<< ERROR!
java.net.BindException: Address already in use: bind
jponge commented 6 years ago

What if we started with random ports? (e.g., listen())

vietj commented 6 years ago

@jponge this is a solution to heal the consequence of a leak in tests, if you leave a port open it means you are also leaking descriptors, so you should rather try to find the root cause of the bind error

jponge commented 6 years ago

Sometimes the port has been closed, but you still can have a bind error because you try to bind again too fast.

On 29 Oct 2018, at 15:16, Julien Viet notifications@github.com wrote:

@jponge this is a solution to heal the consequence of a leak in tests, if you leave a port open it means you are also leaking descriptors, so you should rather try to find the root cause of the bind error

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.

vietj commented 6 years ago

if you close vertx in shutdown of the test and wait until the async result of the close operation is completed, it should work

jponge commented 6 years ago

I’ll check that

On 29 Oct 2018, at 18:23, Julien Viet notifications@github.com wrote:

if you close vertx in shutdown of the test and wait until the async result of the close operation is completed, it should work

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.

vietj commented 6 years ago

that's what we do in vertx-core with 2200 tests :-)

jponge commented 6 years ago

Need to dig more, the extension is already waiting for the Vertx context to close.

On 29 Oct 2018, at 18:47, Julien Viet notifications@github.com wrote:

that's what we do in vertx-core with 2200 tests :-)

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or mute the thread.

jponge commented 6 years ago

I found the culprit in test ;-)

jponge commented 6 years ago

Fixed in master. Thanks @julianladisch for reporting!

vietj commented 6 years ago

good job Sherlock