Promise already completed error when connection timeout timer kicks in

[hanvanderveen]

Version

5.0.5

Context

We are getting a lot of "Promise already completed" errors in our log (on the global vertx exception handler).
The cause is that a handler.fail("Timeout") call is on a promise which has completed already.

We are using kotlin coroutines and vertx closely together and we have an issue that we think is related.

See vert-x3/vertx-lang-kotlin#279

What we get is this error:

java.lang.IllegalStateException: Promise already completed
	at io.vertx.core.Promise.fail(Promise.java:110)
	at io.vertx.sqlclient.impl.pool.SqlConnectionPool$1PoolRequest.lambda$onEnqueue$1(SqlConnectionPool.java:259)
	at io.vertx.core.Completable.succeed(Completable.java:31)
	at io.vertx.core.internal.pool.SimpleConnectionPool$Cancel.run(SimpleConnectionPool.java:688)
	at io.vertx.core.internal.pool.Task.runNextTasks(Task.java:43)
	at io.vertx.core.internal.pool.CombinerExecutor.submit(CombinerExecutor.java:91)
	at io.vertx.core.internal.pool.SimpleConnectionPool.execute(SimpleConnectionPool.java:242)
	at io.vertx.core.internal.pool.SimpleConnectionPool.cancel(SimpleConnectionPool.java:650)
	at io.vertx.sqlclient.impl.pool.SqlConnectionPool$1PoolRequest.lambda$onEnqueue$2(SqlConnectionPool.java:255)
	at io.vertx.core.impl.VertxImpl$InternalTimerHandler.handle(VertxImpl.java:1023)
	at io.vertx.core.impl.VertxImpl$InternalTimerHandler.handle(VertxImpl.java:990)
	at io.vertx.core.impl.ContextBase.emit(ContextBase.java:82)
	at io.vertx.core.impl.ContextBase.lambda$emit$0(ContextBase.java:89)
	at io.vertx.core.impl.WorkerExecutor$1.execute(WorkerExecutor.java:68)
	at io.vertx.core.impl.WorkerTask.run(WorkerTask.java:57)
	at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:80)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1090)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:614)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:1474)

What seems to happen is that the connection is returned, but the timer is not cleared.
So the timer is still executed, hence the error because of handler.fail("Timeout"), because the connection is already returned.

However, there is no functional error we observe, so everything really works. It just messes up our log lines.

There could be two things:

• For some reason we are hitting a timing issue way more often than others.
• Or kotlin coroutines somehow messes up with some internal state and therefore the timer is in another context or something

Our suggestion is to maybe change it to tryFail instead of fail.
But that might only fix the issue and not the cause.

Steps to reproduce

We are using this snippet, see other issue for more context.

suspend fun Pool.getConnectionSuspending(): SqlConnection {
    val connFuture = this.connection
    val currentContext = currentCoroutineContext()
    connFuture.onComplete { conn, cause ->
        if (!currentContext.isActive && conn != null) {
            conn.close()
        }
    }
    return connFuture.coAwait()
}

and

fun execute(block: (SqlConnection) -> Unit) {
        val conn = pool.getConnectionSuspending()
        try {
            block(conn)
        } finally {
            conn.close().coAwait()
        }
}

So nothing really special here.
The funny thing is that we also use vertx and kotlin in another application, but without coroutines and we are not hitting this error. Also, this also happen when we are not cancelling any jobs, so normal behavior we see it.

Our connection timeout is 3 seconds.

Do you have a reproducer?

No response