beforeSpec called twice for single instance of Spec class.

tonicsoft commented 6 days ago

5.7.0-5.9.1

First, apologies for the incomplete bug report, I'm as yet unable to produce a minimal reproduction of the issue. However, since I think I've identified a root cause I thought it was worth reporting in case someone who knows the kotest internals has any ideas.

Assuming that the implementation of java.util.UUID.randomUUID() reliably does not return the same value for multiple calls, then I have a problem while upgrading my kotest version from 5.6.2 to 5.7.0 or later.

Attempts to reproduce the problem in a minimal and sharable way have failed, so I'll have to describe it as best I can.

The root cause of the issue seems to be the the beforeSpec function is called twice on the same object, something that I am not expecting and if I read the docs correctly, should not happen.

I'll explain why I think this. Our tests use an extension that creates a new postgres database for each test. If the database already exists, then this will fail with a pretty clear error.

I can share the extension implementation verbatim since there is nothing sensitive there.

interface PostgresContainerInfo : Extension {
    fun createDataSource(databaseName: String): PGSimpleDataSource

    fun createDefaultDataSource(): PGSimpleDataSource
}

class PostgresDatabaseExtension(
    private val postgresContainerInfo: PostgresContainerInfo
) : MountableExtension<Nothing, PGSimpleDataSource>, BeforeSpecListener {

    private val freshDatabaseName = "_" + UUID.randomUUID().toString().replace("-", "_")

    override suspend fun beforeSpec(spec: Spec) {
        postgresContainerInfo.createDefaultDataSource().getConnection().use { connection ->
            val statement = connection.prepareStatement("CREATE DATABASE $freshDatabaseName")

            statement.execute()
        }
    }

    override fun mount(configure: Nothing.() -> Unit): PGSimpleDataSource {
        return postgresContainerInfo.createDataSource(freshDatabaseName)
    }
}

And here is a example of the kind of tests that we have in the project:

class XxxxTest : DescribeSpec({
    isolationMode = IsolationMode.InstancePerTest

    val database = install(PostgresDatabaseExtension(ProjectConfig.postgresExtension)) {}

    describe("foo") {
        val doTestThings = createHikariDataSource(database)

        describe("nested foo") {
            it("test 1") {

            }

            it("test 2") {

            }
        }

        describe("foo 2") {
            it("test 3") {

            }

            it("test 4") {

            }
        }
    }
})

The postgresExtension is a single postgres server shared by all tests, which is why you get an error when trying to create multiple databases with the same name.

Since the names are generated by a randomUUID each time, the only explanation I can think of is that beforeSpec is being called twice. Just in case randomUUID doesn't behave how I expect, I have also confirmed this using AtomicInteger to record all calls to beforeSpec and it confirms that it's being called more than once.

Typical error message: org.postgresql.util.PSQLException: ERROR: database "_bd9e714f_6e72_4fb8_af77_460bb8694ff2" already exists

Some other things to note:

as you can see we are using the Per Test isolation mode, in order to provide a new, empty database for every test
we are running these tests with a parallelism of 8. When run with parallelism of 1, all tests pass in all version of kotest.
we have a similar pattern for stubbing other dependencies, namely amazon s3 and dynamoDB. In both cases, the different stub technologies return similar error messages indicated beforeSpec on their respective extensions have been called twice. (buckets for s3, tables for dynamoDb, databases for postgres).

I have bisected using all the available versions in a maven repository we use, and I can say that the behavior was introduced between version 5.6.2 (working) and 5.7.0 (broken).

I realize this is not a high quality bug report and I will make efforts to improve it when I can. In the meantime I was hoping someone might be able to offer insights into what kind of scenarios could possibly allow beforeSpec to be called twice.

I would also appreciate if someone could look at the commit log between 5.6.2 and 5.7.0 and indicate how big the surface area of that change is and whether further bisection on my side would be useful.

tonicsoft commented 6 days ago

Here is the comparison link between the two relevant versions https://github.com/kotest/kotest/compare/v5.6.2...v5.7.0

Possibly interesting commits: https://github.com/kotest/kotest/commit/29ed6c9f7753256fcbdfd7e2fddc99b2ff2e4392 https://github.com/kotest/kotest/commit/6de2ac2cc272cda177ff48ae03c01440f23ded6b#diff-e79c172aa77fc39e6f8e39383c5cb6781ed6237a73dbee355fb9ce9ca84d2b46 https://github.com/kotest/kotest/commit/e98016a999924b43f1babbb9b90be7c5a18ad55d#diff-0e9f7f35c996ac45a1c307c1d4874d49f142d4f4ccf6e37a675a020e44b6a649

tonicsoft commented 6 days ago

with associated change:

https://github.com/kotest/kotest/pull/3601/files

tonicsoft commented 4 days ago

Just for fun I decided to try version 6.0.0.M1, and can confirm that the same issue is present.

kotest / kotest

beforeSpec called twice for single instance of Spec class. #4419