Exposed: IsAutoCommit = false & transactionIsolation = "Transaction_Serializable" result in a PSQLException

Following test will always fail with a PSQLException : Cannot change transaction isolation level in the middle of a transaction Changing the autoCommit = false to true will make this behavior disappear, but since what if have read so far, autoCommit should always be set to false for exposed. This behavior was not present for version 0.37.3

Testcase:

import com.zaxxer.hikari.HikariConfig
import com.zaxxer.hikari.HikariDataSource
import kotlinx.coroutines.*
import kotlinx.coroutines.test.resetMain
import kotlinx.coroutines.test.setMain
import org.jetbrains.exposed.sql.*
import org.jetbrains.exposed.sql.transactions.experimental.newSuspendedTransaction
import org.jetbrains.exposed.sql.transactions.transaction
import org.junit.jupiter.api.*
import java.sql.Connection
import java.util.concurrent.*
import javax.sql.DataSource

@ExperimentalCoroutinesApi
@DelicateCoroutinesApi
@TestInstance(TestInstance.Lifecycle.PER_CLASS)
class DatebaseTest {

    private val mainThreadSurrogate = newSingleThreadContext("Coroutine thread")

    @BeforeAll
    fun setUp() {
        Dispatchers.setMain(mainThreadSurrogate)
    }

    @AfterAll
    fun tearDown() {
        Dispatchers.resetMain() // reset the main dispatcher to the original Main dispatcher
        mainThreadSurrogate.close()
    }

    @Test
    fun `Create a new Connection after it was closed, PSQLException`() = testCoroutine {
        val db = DatabaseMock(EnvironmentService())

        db.getPSQLVersion()
        delay(TimeUnit.SECONDS.toMillis(31))
        db.getPSQLVersion()
    }

    private suspend fun DatabaseMock.getPSQLVersion() = this.dbQuery {
        exec("SELECT VERSION();") { it.next(); it.getString(1) }
    }
}

class DatabaseMock(envVars: IEnvironmentService) : IDatabase {

    private val ISOLATION_LEVEL = "TRANSACTION_SERIALIZABLE"
    private val DRIVER_NAME = "org.postgresql.Driver"

    init {
        setupDatasource(envVars)
    }

    private fun setupDatasource(envVars: IEnvironmentService): DataSource {
        val dataSource = hikari(envVars)
        val database = org.jetbrains.exposed.sql.Database.connect(dataSource)
        // database.transactionManager.defaultIsolationLevel = Connection.TRANSACTION_SERIALIZABLE

        transaction(Connection.TRANSACTION_SERIALIZABLE, 1) {
            val schema = Schema(envVars["DATABASE_SCHEMA"], envVars["DATABASE_USER"])
            SchemaUtils.createSchema(schema)
            SchemaUtils.setSchema(schema)
        }
        return dataSource
    }

    private fun hikari(envVars: IEnvironmentService): HikariDataSource {
        val hikariConfig = HikariConfig().apply {
            driverClassName = DRIVER_NAME
            jdbcUrl = envVars["DATABASE_URL"]
            schema = envVars["DATABASE_SCHEMA"]
            username = envVars["DATABASE_USER"]
            password = envVars["DATABASE_PASSWORD"]
            maximumPoolSize = 5
            maxLifetime = 30020
            isAutoCommit = false
            transactionIsolation = ISOLATION_LEVEL
        }
        hikariConfig.validate()

        return HikariDataSource(hikariConfig)
    }

    override suspend fun <T> dbQuery(block: suspend Transaction.() -> T): T =
        newSuspendedTransaction(
            Dispatchers.IO,
            transactionIsolation = Connection.TRANSACTION_SERIALIZABLE
        ) {
            block()
        }
}

gradle.build.kts:

val exposedVersion = "0.39.2"

dependencies {

    implementation("org.jetbrains.exposed:exposed-core:$exposedVersion")
    implementation("org.jetbrains.exposed:exposed-jodatime:$exposedVersion")
    implementation("org.jetbrains.exposed:exposed-jdbc:$exposedVersion")
    implementation("org.jetbrains.exposed:exposed-dao:$exposedVersion")

    implementation("com.zaxxer:HikariCP:5.0.1")
    implementation("org.postgresql:postgresql:42.3.6")

About this issue

  • Original URL
  • State: closed
  • Created 2 years ago
  • Reactions: 2
  • Comments: 16 (6 by maintainers)

Commits related to this issue

Most upvoted comments

Also i think the problem was introduced sometime between 1.1.2022 and release of 0.38.1 where i first started to see it to happen.

Hey, sorry to inform you that the problem is still not fixed.

If i use transaction(Connection.TRANSACTION_SERIALIZABLE, 1) in setupDatasource() it still breaks immediately with:

2022-11-15 14:27:38.226 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Pool stats (total=1, active=0, idle=1, waiting=0)
2022-11-15 14:27:38.245 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@578a0128
2022-11-15 14:27:38.273 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@594df5a9
2022-11-15 14:27:38.300 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@5d726a58
2022-11-15 14:27:38.324 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@1870ff92
2022-11-15 14:27:38.340 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After adding stats (total=5, active=0, idle=5, waiting=0)
2022-11-15 14:27:38.406 [Coroutine thread @coroutine#2] WARN  Exposed - Transaction attempt #0 failed: Cannot change transaction isolation level in the middle of a transaction.. Statement(s): null
org.postgresql.util.PSQLException: Cannot change transaction isolation level in the middle of a transaction.
	at org.postgresql.jdbc.PgConnection.setTransactionIsolation(PgConnection.java:970)
	at com.zaxxer.hikari.pool.ProxyConnection.setTransactionIsolation(ProxyConnection.java:420)
	at com.zaxxer.hikari.pool.HikariProxyConnection.setTransactionIsolation(HikariProxyConnection.java)
	at org.jetbrains.exposed.sql.statements.jdbc.JdbcConnectionImpl.setTransactionIsolation(JdbcConnectionImpl.kt:60)
	at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManager$ThreadLocalTransaction$connectionLazy$1.invoke(ThreadLocalTransactionManager.kt:82)
	at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManager$ThreadLocalTransaction$connectionLazy$1.invoke(ThreadLocalTransactionManager.kt:75)
	at kotlin.UnsafeLazyImpl.getValue(Lazy.kt:81)
	at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManager$ThreadLocalTransaction.getConnection(ThreadLocalTransactionManager.kt:89)
	at org.jetbrains.exposed.sql.Transaction.getConnection(Transaction.kt)
	at org.jetbrains.exposed.sql.Database.metadata$exposed_core(Database.kt:38)
	at org.jetbrains.exposed.sql.Database$vendor$2.invoke(Database.kt:44)
	at org.jetbrains.exposed.sql.Database$vendor$2.invoke(Database.kt:43)
	at kotlin.SynchronizedLazyImpl.getValue(LazyJVM.kt:74)
	at org.jetbrains.exposed.sql.Database.getVendor(Database.kt:43)
	at org.jetbrains.exposed.sql.Database$dialect$2.invoke(Database.kt:48)
	at org.jetbrains.exposed.sql.Database$dialect$2.invoke(Database.kt:47)
	at kotlin.SynchronizedLazyImpl.getValue(LazyJVM.kt:74)
	at org.jetbrains.exposed.sql.Database.getDialect(Database.kt:47)
	at org.jetbrains.exposed.sql.vendors.DefaultKt.getCurrentDialect(Default.kt:893)
	at org.jetbrains.exposed.sql.Schema.exists(Schema.kt:40)
	at org.jetbrains.exposed.sql.SchemaUtils.createSchema(SchemaUtils.kt:550)
	at org.jetbrains.exposed.sql.SchemaUtils.createSchema$default(SchemaUtils.kt:547)
	at com.example.DatabaseMock$setupDatasource$1.invoke(DatebaseTest.kt:64)

if i setupDatabase() only with transaction() and no arguments the test fails after 31 seconds when hikari is opening new connections with:

org.jetbrains.exposed.exceptions.ExposedSQLException: org.postgresql.util.PSQLException: Cannot change transaction isolation level in the middle of a transaction.

Even if i don’t define the TRANSACTION_SERIALIZABLE level no where in my code (not in transaction, not in dbQuery, not in hikariConfig) the test is still failing after 31s with `org.postgresql.util.PSQLException: Cannot change transaction isolation level in the middle of a transaction.

2022-11-15 14:38:30.599 [Coroutine thread @coroutine#2] DEBUG com.zaxxer.hikari.HikariConfig - poolName........................"HikariPool-1"
2022-11-15 14:38:30.599 [Coroutine thread @coroutine#2] DEBUG com.zaxxer.hikari.HikariConfig - readOnly........................false
2022-11-15 14:38:30.600 [Coroutine thread @coroutine#2] DEBUG com.zaxxer.hikari.HikariConfig - registerMbeans..................false
2022-11-15 14:38:30.600 [Coroutine thread @coroutine#2] DEBUG com.zaxxer.hikari.HikariConfig - scheduledExecutor...............none
2022-11-15 14:38:30.600 [Coroutine thread @coroutine#2] DEBUG com.zaxxer.hikari.HikariConfig - schema.........................."test_schema"
2022-11-15 14:38:30.600 [Coroutine thread @coroutine#2] DEBUG com.zaxxer.hikari.HikariConfig - threadFactory...................internal
2022-11-15 14:38:30.600 [Coroutine thread @coroutine#2] DEBUG com.zaxxer.hikari.HikariConfig - transactionIsolation............default
2022-11-15 14:38:30.600 [Coroutine thread @coroutine#2] DEBUG com.zaxxer.hikari.HikariConfig - username........................"username"
2022-11-15 14:38:30.601 [Coroutine thread @coroutine#2] DEBUG com.zaxxer.hikari.HikariConfig - validationTimeout...............5000
2022-11-15 14:38:30.602 [Coroutine thread @coroutine#2] INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Starting...
2022-11-15 14:38:30.838 [Coroutine thread @coroutine#2] INFO  com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@3483016
2022-11-15 14:38:30.842 [Coroutine thread @coroutine#2] INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Start completed.
2022-11-15 14:38:30.946 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Pool stats (total=1, active=1, idle=0, waiting=0)
2022-11-15 14:38:30.959 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@19db5fb2
2022-11-15 14:38:30.967 [Coroutine thread @coroutine#2] DEBUG c.zaxxer.hikari.pool.ProxyConnection - HikariPool-1 - Executed rollback on connection org.postgresql.jdbc.PgConnection@3483016 due to dirty commit state on close().
2022-11-15 14:38:30.973 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After adding stats (total=2, active=0, idle=2, waiting=0)
2022-11-15 14:38:31.279 [Coroutine thread @coroutine#2] DEBUG Exposed - SET search_path TO smbc_processor
2022-11-15 14:38:31.317 [DefaultDispatcher-worker-1 @coroutine#3] DEBUG Exposed - SELECT VERSION();
2022-11-15 14:39:00.411 [HikariPool-1 connection closer] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@3483016: (connection has passed maxLifetime)
2022-11-15 14:39:00.424 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@33b5a67a
2022-11-15 14:39:00.849 [HikariPool-1 connection closer] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@19db5fb2: (connection has passed maxLifetime)
2022-11-15 14:39:00.863 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@3d724e7c
2022-11-15 14:39:00.956 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Pool stats (total=2, active=0, idle=2, waiting=0)
2022-11-15 14:39:00.957 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled (queueDepth=0).
2022-11-15 14:39:02.342 [DefaultDispatcher-worker-1 @coroutine#4] DEBUG Exposed - SELECT VERSION();
2022-11-15 14:39:02.343 [DefaultDispatcher-worker-1 @coroutine#4] WARN  Exposed - Transaction attempt #1 failed: org.postgresql.util.PSQLException: Cannot change transaction isolation level in the middle of a transaction.. Statement(s): SELECT VERSION();
org.jetbrains.exposed.exceptions.ExposedSQLException: org.postgresql.util.PSQLException: Cannot change transaction isolation level in the middle of a transaction.
	at org.jetbrains.exposed.sql.statements.Statement.executeIn$exposed_core(Statement.kt:49)
	at org.jetbrains.exposed.sql.Transaction.exec(Transaction.kt:141)
	at org.jetbrains.exposed.sql.Transaction.exec(Transaction.kt:127)
	at org.jetbrains.exposed.sql.Transaction.exec(Transaction.kt:109)
	at org.jetbrains.exposed.sql.Transaction.exec$default(Transaction.kt:97)
	at com.example.DatebaseTest$getPSQLVersion$2.invokeSuspend(DatebaseTest.kt:44)

Still only changing to isAutoCommit = true solves the issue with following output:

2022-11-15 14:49:47.087 [Coroutine thread @coroutine#2] DEBUG com.zaxxer.hikari.HikariConfig - transactionIsolation............"TRANSACTION_SERIALIZABLE"
2022-11-15 14:49:47.087 [Coroutine thread @coroutine#2] DEBUG com.zaxxer.hikari.HikariConfig - username........................"username"
2022-11-15 14:49:47.087 [Coroutine thread @coroutine#2] DEBUG com.zaxxer.hikari.HikariConfig - validationTimeout...............5000
2022-11-15 14:49:47.088 [Coroutine thread @coroutine#2] INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Starting...
2022-11-15 14:49:47.334 [Coroutine thread @coroutine#2] INFO  com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@5c966d9
2022-11-15 14:49:47.338 [Coroutine thread @coroutine#2] INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Start completed.
2022-11-15 14:49:47.442 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Pool stats (total=1, active=0, idle=1, waiting=0)
2022-11-15 14:49:47.458 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@6089113
2022-11-15 14:49:47.469 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - After adding stats (total=2, active=0, idle=2, waiting=0)
2022-11-15 14:49:47.780 [Coroutine thread @coroutine#2] DEBUG Exposed - SET search_path TO smbc_processor
2022-11-15 14:49:47.790 [Coroutine thread @coroutine#2] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@5c966d9
2022-11-15 14:49:47.832 [DefaultDispatcher-worker-1 @coroutine#3] DEBUG Exposed - SELECT VERSION();
2022-11-15 14:49:47.834 [DefaultDispatcher-worker-1 @coroutine#3] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@5c966d9
2022-11-15 14:50:16.802 [HikariPool-1 connection closer] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@5c966d9: (connection has passed maxLifetime)
2022-11-15 14:50:16.817 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@455560d5
2022-11-15 14:50:17.059 [HikariPool-1 connection closer] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Closing connection org.postgresql.jdbc.PgConnection@6089113: (connection has passed maxLifetime)
2022-11-15 14:50:17.072 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@4b92960f
2022-11-15 14:50:17.451 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Pool stats (total=2, active=0, idle=2, waiting=0)
2022-11-15 14:50:17.452 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled (queueDepth=0).
2022-11-15 14:50:18.858 [DefaultDispatcher-worker-1 @coroutine#4] DEBUG Exposed - SELECT VERSION();
2022-11-15 14:50:18.859 [DefaultDispatcher-worker-1 @coroutine#4] DEBUG com.zaxxer.hikari.pool.PoolBase - HikariPool-1 - Reset (autoCommit) on connection org.postgresql.jdbc.PgConnection@455560d5

Found possible cause. I will ask you to check if the problem is gone after the next release (possibly today)

Hi @Tapac,

I did the following tests with exposedVersion=0.40.1

  1. Setting Dispatchers.setMain(Dispatchers.Default) does not affect the test outcome. Test fails immediately.
  2. Test is still failing, either on transaction(Connection.TRANSACTION_SERIALIZABLE, 1) in setupDatasource or after 31s if i remove the isolation level in that call.
  3. transactionIsolation = Connection.TRANSACTION_SERIALIZABLE is not possible since hikari expects a string. transactionIsolation = "8" will give that same result as 2.