Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Connections hanging and leaking (ScalikeJDBC + HikariCP + Postgres) #1366

Open
f1llon opened this issue Nov 9, 2021 · 1 comment
Open

Connections hanging and leaking (ScalikeJDBC + HikariCP + Postgres) #1366

f1llon opened this issue Nov 9, 2021 · 1 comment
Labels
core good first issue
Milestone
version 5 or later

Comments

@f1llon
Copy link

f1llon commented Nov 9, 2021 •
edited

the postgres:

version - PostgreSQL 13.4 (Debian 13.4-4.pgdg110+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit

the DDL:

create table test (
  id bigint,
  name text
)

the build.sbt:

name := "scalikejdbc-hikari-postgres-connection-leaks"
scalaVersion := "2.12.15"

libraryDependencies ++= Seq(
  "org.postgresql" % "postgresql" % "42.2.6",
  "com.zaxxer" % "HikariCP" % "5.0.0" excludeAll ExclusionRule(organization = "org.slf4j"),
  "org.scalikejdbc" %% "scalikejdbc" % "4.0.0", //the issue was faced at version 3.2.+, and still reproducable at version 4.0.0
  "ch.qos.logback" % "logback-classic" % "1.2.6"
)

the code:

import com.zaxxer.hikari.HikariDataSource
import scalikejdbc._

import java.util.concurrent.Executors
import scala.concurrent.duration.DurationInt
import scala.concurrent.{Await, ExecutionContext, Future}

case class Test(
  id: Long,
  name: String,
)

object Test extends SQLSyntaxSupport[Test] {
  override def tableName: String = "test"

  val t = syntax("t")
}

object TestApp extends App {

  implicit val ec = ExecutionContext.fromExecutorService(Executors.newFixedThreadPool(4))

  GlobalSettings.loggingSQLAndTime = LoggingSQLAndTimeSettings(
    enabled = true,
    singleLineMode = true,
    printUnprocessedStackTrace = true,
    stackTraceDepth = 30,
    warningEnabled = true,
    warningThresholdMillis = 3000L
  )

  val dataSource: HikariDataSource = {
    val ds = new HikariDataSource()
    ds.setLeakDetectionThreshold(15000)
    ds.setMaximumPoolSize(10)
    ds.setDataSourceClassName("org.postgresql.ds.PGSimpleDataSource")
    ds.addDataSourceProperty("serverName", "127.0.0.1")
    ds.addDataSourceProperty("portNumber", 5432)
    ds.addDataSourceProperty("databaseName", "test_db")
    ds.addDataSourceProperty("user", "user")
    ds.addDataSourceProperty("password", "password")
    ds
  }

  ConnectionPool.singleton(new DataSourceConnectionPool(dataSource))


  //this batch of queries works fine
  val simpleQueriesResultF = Future.sequence(
    (1 to 50).map(_ ⇒
      DB.futureLocalTx { implicit session ⇒
        Future {
          sql"select * from test".map(_.long(1)).list.apply
        }
      }
    )
  )

  val simpleQueriesResult = Await.result(simpleQueriesResultF, 30.seconds)
  println(s"result for simpleQueriesResult - ${simpleQueriesResult.flatten.toSet}")


  //this batch hangs and nothing happens
  //worth noticing that it works if you remove the simpleQueriesResultF batch
  val dslQueriesResultF = Future.sequence(
    (1 to 50).map(_ ⇒
      DB.futureLocalTx { implicit session ⇒
        Future {
          withSQL(select.from(Test as Test.t)).map(_.long(1)).list.apply
        }
      }
    )
  )

  val dslQueriesResult = Await.result(dslQueriesResultF, 30.seconds)
  println(s"result for dslQueriesResult - ${dslQueriesResult.flatten.toSet}")

  ec.shutdownNow()
}

This code shows how to reproduce the issue.
The first batch of queries is executed successfully, I can see the queries and the result message in logs.
The second batch of queries just hangs nothing happens, in 15 seconds I can see the messages about leaked connection detection, in 30 seconds I see the message that connection is not available, request timed out after 30006ms.
The only difference between the first and the second batch - the QueryDSL is used in the second.

the logs

18:59:56.804 [main] DEBUG scalikejdbc.ConnectionPool$ - Registered singleton connection pool : ConnectionPool(url:<external-data-source>, user:<external-data-source>)
18:59:56.871 [main] DEBUG com.zaxxer.hikari.HikariConfig - HikariPool-1 - configuration:
18:59:56.890 [main] DEBUG com.zaxxer.hikari.HikariConfig - allowPoolSuspension.............false
18:59:56.890 [main] DEBUG com.zaxxer.hikari.HikariConfig - autoCommit......................true
18:59:56.890 [main] DEBUG com.zaxxer.hikari.HikariConfig - catalog.........................none
18:59:56.891 [main] DEBUG com.zaxxer.hikari.HikariConfig - connectionInitSql...............none
18:59:56.891 [main] DEBUG com.zaxxer.hikari.HikariConfig - connectionTestQuery.............none
18:59:56.891 [main] DEBUG com.zaxxer.hikari.HikariConfig - connectionTimeout...............30000
18:59:56.891 [main] DEBUG com.zaxxer.hikari.HikariConfig - dataSource......................none
18:59:56.897 [main] DEBUG com.zaxxer.hikari.HikariConfig - dataSourceClassName............."org.postgresql.ds.PGSimpleDataSource"
18:59:56.897 [main] DEBUG com.zaxxer.hikari.HikariConfig - dataSourceJNDI..................none
18:59:56.898 [main] DEBUG com.zaxxer.hikari.HikariConfig - dataSourceProperties............{password=<masked>, databaseName=test_db, serverName=127.0.0.1, user=user, portNumber=5432}
18:59:56.899 [main] DEBUG com.zaxxer.hikari.HikariConfig - driverClassName.................none
18:59:56.899 [main] DEBUG com.zaxxer.hikari.HikariConfig - exceptionOverrideClassName......none
18:59:56.899 [main] DEBUG com.zaxxer.hikari.HikariConfig - healthCheckProperties...........{}
18:59:56.899 [main] DEBUG com.zaxxer.hikari.HikariConfig - healthCheckRegistry.............none
18:59:56.899 [main] DEBUG com.zaxxer.hikari.HikariConfig - idleTimeout.....................600000
18:59:56.899 [main] DEBUG com.zaxxer.hikari.HikariConfig - initializationFailTimeout.......1
18:59:56.899 [main] DEBUG com.zaxxer.hikari.HikariConfig - isolateInternalQueries..........false
18:59:56.900 [main] DEBUG com.zaxxer.hikari.HikariConfig - jdbcUrl.........................none
18:59:56.900 [main] DEBUG com.zaxxer.hikari.HikariConfig - keepaliveTime...................0
18:59:56.900 [main] DEBUG com.zaxxer.hikari.HikariConfig - leakDetectionThreshold..........15000
18:59:56.900 [main] DEBUG com.zaxxer.hikari.HikariConfig - maxLifetime.....................1800000
18:59:56.900 [main] DEBUG com.zaxxer.hikari.HikariConfig - maximumPoolSize.................10
18:59:56.900 [main] DEBUG com.zaxxer.hikari.HikariConfig - metricRegistry..................none
18:59:56.900 [main] DEBUG com.zaxxer.hikari.HikariConfig - metricsTrackerFactory...........none
18:59:56.900 [main] DEBUG com.zaxxer.hikari.HikariConfig - minimumIdle.....................10
18:59:56.900 [main] DEBUG com.zaxxer.hikari.HikariConfig - password........................<masked>
18:59:56.901 [main] DEBUG com.zaxxer.hikari.HikariConfig - poolName........................"HikariPool-1"
18:59:56.901 [main] DEBUG com.zaxxer.hikari.HikariConfig - readOnly........................false
18:59:56.901 [main] DEBUG com.zaxxer.hikari.HikariConfig - registerMbeans..................false
18:59:56.901 [main] DEBUG com.zaxxer.hikari.HikariConfig - scheduledExecutor...............none
18:59:56.901 [main] DEBUG com.zaxxer.hikari.HikariConfig - schema..........................none
18:59:56.901 [main] DEBUG com.zaxxer.hikari.HikariConfig - threadFactory...................internal
18:59:56.902 [main] DEBUG com.zaxxer.hikari.HikariConfig - transactionIsolation............default
18:59:56.902 [main] DEBUG com.zaxxer.hikari.HikariConfig - username........................none
18:59:56.902 [main] DEBUG com.zaxxer.hikari.HikariConfig - validationTimeout...............5000
18:59:56.902 [main] INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Starting...
18:59:57.149 [main] INFO  com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@69e1dd28
18:59:57.157 [main] INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Start completed.
18:59:57.256 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Pool stats (total=1, active=1, idle=0, waiting=1)
18:59:57.300 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@58695725
18:59:57.301 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.335 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@562f87a2
18:59:57.336 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.379 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@58e86317
18:59:57.382 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.417 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@5cd7ecd2
18:59:57.420 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.445 [pool-1-thread-4] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (6 ms)
18:59:57.445 [pool-1-thread-1] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (14 ms)
18:59:57.445 [pool-1-thread-2] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (14 ms)
18:59:57.445 [pool-1-thread-3] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (14 ms)
18:59:57.457 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@19d5692c
18:59:57.457 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.468 [pool-1-thread-3] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (5 ms)
18:59:57.468 [pool-1-thread-4] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (5 ms)
18:59:57.470 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.473 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.475 [pool-1-thread-2] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.475 [pool-1-thread-4] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.475 [pool-1-thread-1] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.475 [pool-1-thread-3] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (1 ms)
18:59:57.478 [pool-1-thread-2] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.478 [pool-1-thread-4] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.478 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.481 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.482 [pool-1-thread-1] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (1 ms)
18:59:57.483 [pool-1-thread-4] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.483 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@336def23
18:59:57.483 [pool-1-thread-2] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (1 ms)
18:59:57.484 [pool-1-thread-3] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.484 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.485 [pool-1-thread-1] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.487 [pool-1-thread-3] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.488 [pool-1-thread-1] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.488 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.490 [pool-1-thread-1] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.490 [pool-1-thread-3] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.491 [pool-1-thread-2] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.492 [pool-1-thread-4] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (1 ms)
18:59:57.493 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.495 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.497 [pool-1-thread-1] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.497 [pool-1-thread-2] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.497 [pool-1-thread-3] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.497 [pool-1-thread-4] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.499 [pool-1-thread-2] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (1 ms)
18:59:57.499 [pool-1-thread-3] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.499 [pool-1-thread-1] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.500 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.502 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.503 [pool-1-thread-1] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (1 ms)
18:59:57.503 [pool-1-thread-4] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.504 [pool-1-thread-3] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (1 ms)
18:59:57.504 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@2886d282
18:59:57.504 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.505 [pool-1-thread-4] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.505 [pool-1-thread-2] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.505 [pool-1-thread-1] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.507 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.507 [pool-1-thread-1] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (1 ms)
18:59:57.508 [pool-1-thread-2] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.509 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.509 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.510 [pool-1-thread-3] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.511 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.511 [pool-1-thread-4] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (1 ms)
18:59:57.511 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.511 [pool-1-thread-2] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (1 ms)
18:59:57.512 [pool-1-thread-1] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.513 [pool-1-thread-3] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (1 ms)
18:59:57.513 [pool-1-thread-4] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.515 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.515 [pool-1-thread-2] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.515 [pool-1-thread-3] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (2 ms)
18:59:57.516 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.517 [pool-1-thread-3] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (1 ms)
18:59:57.518 [pool-1-thread-2] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (1 ms)
18:59:57.519 [pool-1-thread-1] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (1 ms)
18:59:57.520 [pool-1-thread-3] DEBUG s.StatementExecutor$$anon$1 - [SQL Execution] select * from test; (1 ms)
18:59:57.526 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@4bd40a3c
result for simpleQueriesResult - Set()
18:59:57.545 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
18:59:57.547 [HikariPool-1 connection adder] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Added connection org.postgresql.jdbc.PgConnection@79fa9663
18:59:57.547 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Add connection elided, waiting=1, adders pending/running=2
19:00:12.551 [HikariPool-1 housekeeper] WARN  com.zaxxer.hikari.pool.ProxyLeakTask - Connection leak detection triggered for org.postgresql.jdbc.PgConnection@69e1dd28 on thread main, stack trace follows
java.lang.Exception: Apparent connection leak detected
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
	at scalikejdbc.DataSourceConnectionPool.borrow(DataSourceConnectionPool.scala:21)
	at scalikejdbc.DB$.localTx(DB.scala:296)
	at scalikejdbc.DB$.futureLocalTx(DB.scala:316)
	at TestApp$.$anonfun$dslQueriesResultF$1(TestApp.scala:67)
	at TestApp$.$anonfun$dslQueriesResultF$1$adapted(TestApp.scala:66)
	at scala.collection.TraversableLike.$anonfun$map$1(TraversableLike.scala:286)
	at scala.collection.immutable.Range.foreach(Range.scala:158)
	at scala.collection.TraversableLike.map(TraversableLike.scala:286)
	at scala.collection.TraversableLike.map$(TraversableLike.scala:279)
	at scala.collection.AbstractTraversable.map(Traversable.scala:108)
	at TestApp$.delayedEndpoint$TestApp$1(TestApp.scala:66)
	at TestApp$delayedInit$body.apply(TestApp.scala:19)
	at scala.Function0.apply$mcV$sp(Function0.scala:39)
	at scala.Function0.apply$mcV$sp$(Function0.scala:39)
	at scala.runtime.AbstractFunction0.apply$mcV$sp(AbstractFunction0.scala:17)
	at scala.App.$anonfun$main$1$adapted(App.scala:80)
	at scala.collection.immutable.List.foreach(List.scala:431)
	at scala.App.main(App.scala:80)
	at scala.App.main$(App.scala:78)
	at TestApp$.main(TestApp.scala:19)
	at TestApp.main(TestApp.scala)
19:00:12.551 [HikariPool-1 housekeeper] WARN  com.zaxxer.hikari.pool.ProxyLeakTask - Connection leak detection triggered for org.postgresql.jdbc.PgConnection@58695725 on thread main, stack trace follows
java.lang.Exception: Apparent connection leak detected
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
	at scalikejdbc.DataSourceConnectionPool.borrow(DataSourceConnectionPool.scala:21)
	at scalikejdbc.DB$.localTx(DB.scala:296)
	at scalikejdbc.DB$.futureLocalTx(DB.scala:316)
	at TestApp$.$anonfun$dslQueriesResultF$1(TestApp.scala:67)
	at TestApp$.$anonfun$dslQueriesResultF$1$adapted(TestApp.scala:66)
	at scala.collection.TraversableLike.$anonfun$map$1(TraversableLike.scala:286)
	at scala.collection.immutable.Range.foreach(Range.scala:158)
	at scala.collection.TraversableLike.map(TraversableLike.scala:286)
	at scala.collection.TraversableLike.map$(TraversableLike.scala:279)
	at scala.collection.AbstractTraversable.map(Traversable.scala:108)
	at TestApp$.delayedEndpoint$TestApp$1(TestApp.scala:66)
	at TestApp$delayedInit$body.apply(TestApp.scala:19)
	at scala.Function0.apply$mcV$sp(Function0.scala:39)
	at scala.Function0.apply$mcV$sp$(Function0.scala:39)
	at scala.runtime.AbstractFunction0.apply$mcV$sp(AbstractFunction0.scala:17)
	at scala.App.$anonfun$main$1$adapted(App.scala:80)
	at scala.collection.immutable.List.foreach(List.scala:431)
	at scala.App.main(App.scala:80)
	at scala.App.main$(App.scala:78)
	at TestApp$.main(TestApp.scala:19)
	at TestApp.main(TestApp.scala)
19:00:12.552 [HikariPool-1 housekeeper] WARN  com.zaxxer.hikari.pool.ProxyLeakTask - Connection leak detection triggered for org.postgresql.jdbc.PgConnection@562f87a2 on thread main, stack trace follows
java.lang.Exception: Apparent connection leak detected
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
	at scalikejdbc.DataSourceConnectionPool.borrow(DataSourceConnectionPool.scala:21)
	at scalikejdbc.DB$.localTx(DB.scala:296)
	at scalikejdbc.DB$.futureLocalTx(DB.scala:316)
	at TestApp$.$anonfun$dslQueriesResultF$1(TestApp.scala:67)
	at TestApp$.$anonfun$dslQueriesResultF$1$adapted(TestApp.scala:66)
	at scala.collection.TraversableLike.$anonfun$map$1(TraversableLike.scala:286)
	at scala.collection.immutable.Range.foreach(Range.scala:158)
	at scala.collection.TraversableLike.map(TraversableLike.scala:286)
	at scala.collection.TraversableLike.map$(TraversableLike.scala:279)
	at scala.collection.AbstractTraversable.map(Traversable.scala:108)
	at TestApp$.delayedEndpoint$TestApp$1(TestApp.scala:66)
	at TestApp$delayedInit$body.apply(TestApp.scala:19)
	at scala.Function0.apply$mcV$sp(Function0.scala:39)
	at scala.Function0.apply$mcV$sp$(Function0.scala:39)
	at scala.runtime.AbstractFunction0.apply$mcV$sp(AbstractFunction0.scala:17)
	at scala.App.$anonfun$main$1$adapted(App.scala:80)
	at scala.collection.immutable.List.foreach(List.scala:431)
	at scala.App.main(App.scala:80)
	at scala.App.main$(App.scala:78)
	at TestApp$.main(TestApp.scala:19)
	at TestApp.main(TestApp.scala)
19:00:12.552 [HikariPool-1 housekeeper] WARN  com.zaxxer.hikari.pool.ProxyLeakTask - Connection leak detection triggered for org.postgresql.jdbc.PgConnection@58e86317 on thread main, stack trace follows
java.lang.Exception: Apparent connection leak detected
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
	at scalikejdbc.DataSourceConnectionPool.borrow(DataSourceConnectionPool.scala:21)
	at scalikejdbc.DB$.localTx(DB.scala:296)
	at scalikejdbc.DB$.futureLocalTx(DB.scala:316)
	at TestApp$.$anonfun$dslQueriesResultF$1(TestApp.scala:67)
	at TestApp$.$anonfun$dslQueriesResultF$1$adapted(TestApp.scala:66)
	at scala.collection.TraversableLike.$anonfun$map$1(TraversableLike.scala:286)
	at scala.collection.immutable.Range.foreach(Range.scala:158)
	at scala.collection.TraversableLike.map(TraversableLike.scala:286)
	at scala.collection.TraversableLike.map$(TraversableLike.scala:279)
	at scala.collection.AbstractTraversable.map(Traversable.scala:108)
	at TestApp$.delayedEndpoint$TestApp$1(TestApp.scala:66)
	at TestApp$delayedInit$body.apply(TestApp.scala:19)
	at scala.Function0.apply$mcV$sp(Function0.scala:39)
	at scala.Function0.apply$mcV$sp$(Function0.scala:39)
	at scala.runtime.AbstractFunction0.apply$mcV$sp(AbstractFunction0.scala:17)
	at scala.App.$anonfun$main$1$adapted(App.scala:80)
	at scala.collection.immutable.List.foreach(List.scala:431)
	at scala.App.main(App.scala:80)
	at scala.App.main$(App.scala:78)
	at TestApp$.main(TestApp.scala:19)
	at TestApp.main(TestApp.scala)
19:00:12.553 [HikariPool-1 housekeeper] WARN  com.zaxxer.hikari.pool.ProxyLeakTask - Connection leak detection triggered for org.postgresql.jdbc.PgConnection@5cd7ecd2 on thread main, stack trace follows
java.lang.Exception: Apparent connection leak detected
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
	at scalikejdbc.DataSourceConnectionPool.borrow(DataSourceConnectionPool.scala:21)
	at scalikejdbc.DB$.localTx(DB.scala:296)
	at scalikejdbc.DB$.futureLocalTx(DB.scala:316)
	at TestApp$.$anonfun$dslQueriesResultF$1(TestApp.scala:67)
	at TestApp$.$anonfun$dslQueriesResultF$1$adapted(TestApp.scala:66)
	at scala.collection.TraversableLike.$anonfun$map$1(TraversableLike.scala:286)
	at scala.collection.immutable.Range.foreach(Range.scala:158)
	at scala.collection.TraversableLike.map(TraversableLike.scala:286)
	at scala.collection.TraversableLike.map$(TraversableLike.scala:279)
	at scala.collection.AbstractTraversable.map(Traversable.scala:108)
	at TestApp$.delayedEndpoint$TestApp$1(TestApp.scala:66)
	at TestApp$delayedInit$body.apply(TestApp.scala:19)
	at scala.Function0.apply$mcV$sp(Function0.scala:39)
	at scala.Function0.apply$mcV$sp$(Function0.scala:39)
	at scala.runtime.AbstractFunction0.apply$mcV$sp(AbstractFunction0.scala:17)
	at scala.App.$anonfun$main$1$adapted(App.scala:80)
	at scala.collection.immutable.List.foreach(List.scala:431)
	at scala.App.main(App.scala:80)
	at scala.App.main$(App.scala:78)
	at TestApp$.main(TestApp.scala:19)
	at TestApp.main(TestApp.scala)
19:00:12.553 [HikariPool-1 housekeeper] WARN  com.zaxxer.hikari.pool.ProxyLeakTask - Connection leak detection triggered for org.postgresql.jdbc.PgConnection@19d5692c on thread main, stack trace follows
java.lang.Exception: Apparent connection leak detected
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
	at scalikejdbc.DataSourceConnectionPool.borrow(DataSourceConnectionPool.scala:21)
	at scalikejdbc.DB$.localTx(DB.scala:296)
	at scalikejdbc.DB$.futureLocalTx(DB.scala:316)
	at TestApp$.$anonfun$dslQueriesResultF$1(TestApp.scala:67)
	at TestApp$.$anonfun$dslQueriesResultF$1$adapted(TestApp.scala:66)
	at scala.collection.TraversableLike.$anonfun$map$1(TraversableLike.scala:286)
	at scala.collection.immutable.Range.foreach(Range.scala:158)
	at scala.collection.TraversableLike.map(TraversableLike.scala:286)
	at scala.collection.TraversableLike.map$(TraversableLike.scala:279)
	at scala.collection.AbstractTraversable.map(Traversable.scala:108)
	at TestApp$.delayedEndpoint$TestApp$1(TestApp.scala:66)
	at TestApp$delayedInit$body.apply(TestApp.scala:19)
	at scala.Function0.apply$mcV$sp(Function0.scala:39)
	at scala.Function0.apply$mcV$sp$(Function0.scala:39)
	at scala.runtime.AbstractFunction0.apply$mcV$sp(AbstractFunction0.scala:17)
	at scala.App.$anonfun$main$1$adapted(App.scala:80)
	at scala.collection.immutable.List.foreach(List.scala:431)
	at scala.App.main(App.scala:80)
	at scala.App.main$(App.scala:78)
	at TestApp$.main(TestApp.scala:19)
	at TestApp.main(TestApp.scala)
19:00:12.553 [HikariPool-1 housekeeper] WARN  com.zaxxer.hikari.pool.ProxyLeakTask - Connection leak detection triggered for org.postgresql.jdbc.PgConnection@336def23 on thread main, stack trace follows
java.lang.Exception: Apparent connection leak detected
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
	at scalikejdbc.DataSourceConnectionPool.borrow(DataSourceConnectionPool.scala:21)
	at scalikejdbc.DB$.localTx(DB.scala:296)
	at scalikejdbc.DB$.futureLocalTx(DB.scala:316)
	at TestApp$.$anonfun$dslQueriesResultF$1(TestApp.scala:67)
	at TestApp$.$anonfun$dslQueriesResultF$1$adapted(TestApp.scala:66)
	at scala.collection.TraversableLike.$anonfun$map$1(TraversableLike.scala:286)
	at scala.collection.immutable.Range.foreach(Range.scala:158)
	at scala.collection.TraversableLike.map(TraversableLike.scala:286)
	at scala.collection.TraversableLike.map$(TraversableLike.scala:279)
	at scala.collection.AbstractTraversable.map(Traversable.scala:108)
	at TestApp$.delayedEndpoint$TestApp$1(TestApp.scala:66)
	at TestApp$delayedInit$body.apply(TestApp.scala:19)
	at scala.Function0.apply$mcV$sp(Function0.scala:39)
	at scala.Function0.apply$mcV$sp$(Function0.scala:39)
	at scala.runtime.AbstractFunction0.apply$mcV$sp(AbstractFunction0.scala:17)
	at scala.App.$anonfun$main$1$adapted(App.scala:80)
	at scala.collection.immutable.List.foreach(List.scala:431)
	at scala.App.main(App.scala:80)
	at scala.App.main$(App.scala:78)
	at TestApp$.main(TestApp.scala:19)
	at TestApp.main(TestApp.scala)
19:00:12.554 [HikariPool-1 housekeeper] WARN  com.zaxxer.hikari.pool.ProxyLeakTask - Connection leak detection triggered for org.postgresql.jdbc.PgConnection@2886d282 on thread main, stack trace follows
java.lang.Exception: Apparent connection leak detected
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
	at scalikejdbc.DataSourceConnectionPool.borrow(DataSourceConnectionPool.scala:21)
	at scalikejdbc.DB$.localTx(DB.scala:296)
	at scalikejdbc.DB$.futureLocalTx(DB.scala:316)
	at TestApp$.$anonfun$dslQueriesResultF$1(TestApp.scala:67)
	at TestApp$.$anonfun$dslQueriesResultF$1$adapted(TestApp.scala:66)
	at scala.collection.TraversableLike.$anonfun$map$1(TraversableLike.scala:286)
	at scala.collection.immutable.Range.foreach(Range.scala:158)
	at scala.collection.TraversableLike.map(TraversableLike.scala:286)
	at scala.collection.TraversableLike.map$(TraversableLike.scala:279)
	at scala.collection.AbstractTraversable.map(Traversable.scala:108)
	at TestApp$.delayedEndpoint$TestApp$1(TestApp.scala:66)
	at TestApp$delayedInit$body.apply(TestApp.scala:19)
	at scala.Function0.apply$mcV$sp(Function0.scala:39)
	at scala.Function0.apply$mcV$sp$(Function0.scala:39)
	at scala.runtime.AbstractFunction0.apply$mcV$sp(AbstractFunction0.scala:17)
	at scala.App.$anonfun$main$1$adapted(App.scala:80)
	at scala.collection.immutable.List.foreach(List.scala:431)
	at scala.App.main(App.scala:80)
	at scala.App.main$(App.scala:78)
	at TestApp$.main(TestApp.scala:19)
	at TestApp.main(TestApp.scala)
19:00:12.554 [HikariPool-1 housekeeper] WARN  com.zaxxer.hikari.pool.ProxyLeakTask - Connection leak detection triggered for org.postgresql.jdbc.PgConnection@4bd40a3c on thread main, stack trace follows
java.lang.Exception: Apparent connection leak detected
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
	at scalikejdbc.DataSourceConnectionPool.borrow(DataSourceConnectionPool.scala:21)
	at scalikejdbc.DB$.localTx(DB.scala:296)
	at scalikejdbc.DB$.futureLocalTx(DB.scala:316)
	at TestApp$.$anonfun$dslQueriesResultF$1(TestApp.scala:67)
	at TestApp$.$anonfun$dslQueriesResultF$1$adapted(TestApp.scala:66)
	at scala.collection.TraversableLike.$anonfun$map$1(TraversableLike.scala:286)
	at scala.collection.immutable.Range.foreach(Range.scala:158)
	at scala.collection.TraversableLike.map(TraversableLike.scala:286)
	at scala.collection.TraversableLike.map$(TraversableLike.scala:279)
	at scala.collection.AbstractTraversable.map(Traversable.scala:108)
	at TestApp$.delayedEndpoint$TestApp$1(TestApp.scala:66)
	at TestApp$delayedInit$body.apply(TestApp.scala:19)
	at scala.Function0.apply$mcV$sp(Function0.scala:39)
	at scala.Function0.apply$mcV$sp$(Function0.scala:39)
	at scala.runtime.AbstractFunction0.apply$mcV$sp(AbstractFunction0.scala:17)
	at scala.App.$anonfun$main$1$adapted(App.scala:80)
	at scala.collection.immutable.List.foreach(List.scala:431)
	at scala.App.main(App.scala:80)
	at scala.App.main$(App.scala:78)
	at TestApp$.main(TestApp.scala:19)
	at TestApp.main(TestApp.scala)
19:00:12.554 [HikariPool-1 housekeeper] WARN  com.zaxxer.hikari.pool.ProxyLeakTask - Connection leak detection triggered for org.postgresql.jdbc.PgConnection@79fa9663 on thread main, stack trace follows
java.lang.Exception: Apparent connection leak detected
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
	at scalikejdbc.DataSourceConnectionPool.borrow(DataSourceConnectionPool.scala:21)
	at scalikejdbc.DB$.localTx(DB.scala:296)
	at scalikejdbc.DB$.futureLocalTx(DB.scala:316)
	at TestApp$.$anonfun$dslQueriesResultF$1(TestApp.scala:67)
	at TestApp$.$anonfun$dslQueriesResultF$1$adapted(TestApp.scala:66)
	at scala.collection.TraversableLike.$anonfun$map$1(TraversableLike.scala:286)
	at scala.collection.immutable.Range.foreach(Range.scala:158)
	at scala.collection.TraversableLike.map(TraversableLike.scala:286)
	at scala.collection.TraversableLike.map$(TraversableLike.scala:279)
	at scala.collection.AbstractTraversable.map(Traversable.scala:108)
	at TestApp$.delayedEndpoint$TestApp$1(TestApp.scala:66)
	at TestApp$delayedInit$body.apply(TestApp.scala:19)
	at scala.Function0.apply$mcV$sp(Function0.scala:39)
	at scala.Function0.apply$mcV$sp$(Function0.scala:39)
	at scala.runtime.AbstractFunction0.apply$mcV$sp(AbstractFunction0.scala:17)
	at scala.App.$anonfun$main$1$adapted(App.scala:80)
	at scala.collection.immutable.List.foreach(List.scala:431)
	at scala.App.main(App.scala:80)
	at scala.App.main$(App.scala:78)
	at TestApp$.main(TestApp.scala:19)
	at TestApp.main(TestApp.scala)
19:00:27.284 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Pool stats (total=10, active=10, idle=0, waiting=2)
19:00:27.284 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled (queueDepth=0.
19:00:27.552 [main] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Timeout failure stats (total=10, active=10, idle=0, waiting=1)
Exception in thread "main" java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30006ms.
	at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:696)
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:181)
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:146)
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
	at scalikejdbc.DataSourceConnectionPool.borrow(DataSourceConnectionPool.scala:21)
	at scalikejdbc.DB$.localTx(DB.scala:296)
	at scalikejdbc.DB$.futureLocalTx(DB.scala:316)
	at TestApp$.$anonfun$dslQueriesResultF$1(TestApp.scala:67)
	at TestApp$.$anonfun$dslQueriesResultF$1$adapted(TestApp.scala:66)
	at scala.collection.TraversableLike.$anonfun$map$1(TraversableLike.scala:286)
	at scala.collection.immutable.Range.foreach(Range.scala:158)
	at scala.collection.TraversableLike.map(TraversableLike.scala:286)
	at scala.collection.TraversableLike.map$(TraversableLike.scala:279)
	at scala.collection.AbstractTraversable.map(Traversable.scala:108)
	at TestApp$.delayedEndpoint$TestApp$1(TestApp.scala:66)
	at TestApp$delayedInit$body.apply(TestApp.scala:19)
	at scala.Function0.apply$mcV$sp(Function0.scala:39)
	at scala.Function0.apply$mcV$sp$(Function0.scala:39)
	at scala.runtime.AbstractFunction0.apply$mcV$sp(AbstractFunction0.scala:17)
	at scala.App.$anonfun$main$1$adapted(App.scala:80)
	at scala.collection.immutable.List.foreach(List.scala:431)
	at scala.App.main(App.scala:80)
	at scala.App.main$(App.scala:78)
	at TestApp$.main(TestApp.scala:19)
	at TestApp.main(TestApp.scala)
19:00:27.572 [pool-1-thread-3] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Timeout failure stats (total=10, active=10, idle=0, waiting=0)
19:00:57.286 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Pool stats (total=10, active=10, idle=0, waiting=1)
19:00:57.286 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled (queueDepth=0.
19:00:57.578 [pool-1-thread-1] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Timeout failure stats (total=10, active=10, idle=0, waiting=0)
@seratch
Copy link
Member

seratch commented Dec 7, 2021

Thanks for taking the time to report this!

On the ScalikeJDBC side, the only thing that we can do is to properly use DataSource (the general interface -- not HikariCP specific one)'s methods.

I do understand that you are facing the issue with ScalikeJDBC + HikariCP here but I am not sure about what this library can be improved for your use case yet. If someone finds room for improvements on this library side, sharing your insights would be greatly appreciated.

@seratch seratch added this to the version 5 or later milestone Dec 7, 2021
@pvgoran pvgoran mentioned this issue Jan 9, 2023
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
core good first issue
Milestone
version 5 or later
Development

No branches or pull requests
2 participants
@seratch @f1llon