Daml-on-sql: Exception during pool initialization. Connection attempt timed out

App Development
1

I try to run daml-on-sql-1.18.0.jar against a freshly installed postgresql. The first run succeeds to initialize the database.

If I restart the container that runs daml-on-sql, it seems to work at first – Schema "public" is up to date. No migration necessary. , but then throws the Exception seen below, Exception during pool initialization., Connection attempt timed out.

This is before deploying any dar to it. Also, the error message seems unlikely to be right, as there already is a connection to the database, witness the warning about the postgresql version.

Does this ring a bell with anyone? Seen this before?

Cheers,
mesch.

$ docker run --rm \
  -e JDBCURL='jdbc:postgresql://10.83.129.14:5432/postgres?user=ledger&password=-' \
  -p 6865:6865 '[redacted]/ledger:ledger-mesch-test-image' \
  java -jar daml-on-sql-1.18.0.jar \
  --ledgerid=ledger-mesch-test-ledger \
  --sql-backend-jdbcurl-env=JDBCURL

06:32:51.161 [daml-on-sql-akka.actor.default-dispatcher-5] INFO  o.f.c.i.license.VersionPrinter - Flyway Community Edition 7.13.0 by Redgate  
06:32:51.163 [daml-on-sql-akka.actor.default-dispatcher-5] INFO  o.f.c.i.d.base.BaseDatabaseType - Database: jdbc:postgresql://10.83.129.14:5432/postgres (PostgreSQL 14.0)  
06:32:51.486 [daml-on-sql-akka.actor.default-dispatcher-5] WARN  o.f.c.i.database.base.Database - Flyway upgrade recommended: PostgreSQL 14.0 is newer than this version of Flyway and support has not been tested. The latest supported version of PostgreSQL is 13.  
06:32:51.806 [daml-on-sql-akka.actor.default-dispatcher-5] INFO  o.f.core.internal.command.DbValidate - Successfully validated 72 migrations (execution time 00:00.271s)  
06:32:52.058 [daml-on-sql-akka.actor.default-dispatcher-5] INFO  o.f.core.internal.command.DbMigrate - Current version of schema "public": 117  
06:32:52.093 [daml-on-sql-akka.actor.default-dispatcher-5] INFO  o.f.core.internal.command.DbMigrate - Schema "public" is up to date. No migration necessary.  
06:32:54.227 [daml-on-sql-akka.actor.default-dispatcher-7] ERROR com.zaxxer.hikari.pool.HikariPool - daml.index.db.connection.sandbox - Exception during pool initialization.  
org.postgresql.util.PSQLException: Connection attempt timed out.
	at org.postgresql.Driver$ConnectThread.getResult(Driver.java:429)
	at org.postgresql.Driver.connect(Driver.java:271)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:677)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:228)
	at org.postgresql.ds.common.BaseDataSource.getConnection(BaseDataSource.java:103)
	at org.postgresql.ds.common.BaseDataSource.getConnection(BaseDataSource.java:87)
	at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:369)
	at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:198)
	at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:467)
	at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:541)
	at com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:115)
	at com.zaxxer.hikari.HikariDataSource.<init>(HikariDataSource.java:81)
	at com.daml.platform.store.appendonlydao.HikariDataSourceOwner$.$anonfun$apply$1(HikariJdbcConnectionProvider.scala:41)
	at scala.concurrent.Future$.$anonfun$apply$1(Future.scala:672)
	at scala.concurrent.impl.Promise$Transformation.run(Promise.scala:431)
	at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:53)
	at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(ForkJoinExecutorConfigurator.scala:48)
	at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
	at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020)
	at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656)
	at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594)
	at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183)
06:32:54.294 [scala-execution-context-global-38] ERROR com.daml.resources.ProgramResource - Shutting down because of an initialization error.  
com.zaxxer.hikari.pool.HikariPool$PoolInitializationException: Failed to initialize pool: Connection attempt timed out.
	at com.zaxxer.hikari.pool.HikariPool.throwPoolInitializationException(HikariPool.java:576)
	at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:562)
	at com.zaxxer.hikari.pool.HikariPool.<init>(HikariPool.java:115)
	at com.zaxxer.hikari.HikariDataSource.<init>(HikariDataSource.java:81)
	at com.daml.platform.store.appendonlydao.HikariDataSourceOwner$.$anonfun$apply$1(HikariJdbcConnectionProvider.scala:41)
	at scala.concurrent.Future$.$anonfun$apply$1(Future.scala:672)
	at scala.concurrent.impl.Promise$Transformation.run(Promise.scala:431)
	at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:53)
	at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(ForkJoinExecutorConfigurator.scala:48)
	at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
	at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020)
	at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656)
	at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594)
	at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183)
Caused by: org.postgresql.util.PSQLException: Connection attempt timed out.
	at org.postgresql.Driver$ConnectThread.getResult(Driver.java:429)
	at org.postgresql.Driver.connect(Driver.java:271)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:677)
	at java.sql/java.sql.DriverManager.getConnection(DriverManager.java:228)
	at org.postgresql.ds.common.BaseDataSource.getConnection(BaseDataSource.java:103)
	at org.postgresql.ds.common.BaseDataSource.getConnection(BaseDataSource.java:87)
	at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:369)
	at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:198)
	at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:467)
	at com.zaxxer.hikari.pool.HikariPool.checkFailFast(HikariPool.java:541)
	... 12 common frames omitted
2

An update, the exception appears only when daml-on-sql runs in a container. Running it directly on my workstation brings it up alright.

3

One more update. It seems that a real error message gets shadowed by spurious error messages.

**mesch@ledger-mesch-test-vm** : **/var/lib/ledger** $ java -jar ./daml-on-sql-1.18.0.jar --ledgerid=$(cat LEDGER_ID) --sql-backend-jdbcurl=$(cat JDBC_URL) --database-connection-pool-size=2

yields this unintelligible error:

06:18:40.131 [daml-on-sql-akka.actor.default-dispatcher-7] INFO  o.f.core.internal.command.DbMigrate - Schema "public" is up to date. No migration necessary.  
06:18:43.048 [daml-on-sql-akka.actor.default-dispatcher-9] ERROR com.zaxxer.hikari.pool.HikariPool - daml.index.db.connection.sandbox - Exception during pool initialization.  
org.postgresql.util.PSQLException: Connection attempt timed out.
	at org.postgresql.Driver$ConnectThread.getResult(Driver.java:429)

However, reducing the connection pool size to 1 --database-connection-pool-size=1 yields a more insightful error:

06:16:51.052 [daml-on-sql-akka.actor.default-dispatcher-6] INFO  o.f.core.internal.command.DbMigrate - Schema "public" is up to date. No migration necessary.  
06:16:56.058 [daml-on-sql-akka.actor.default-dispatcher-10] INFO  c.d.p.s.s.ledger.sql.SqlLedger$Owner - Resuming node with ledger id 'ledger-mesch-test-ledger-id and participant id 'daml-on-sql' , context: {participantId: "daml-on-sql"} 
06:16:56.384 [daml.index.db.threadpool.connection.sandbox-0] ERROR c.d.p.s.b.c.ParameterStorageBackendTemplate - Found existing database with mismatching ledgerId: existing 'ledger-mesch-test-ledger', provided 'ledger-mesch-test-ledger-id' , context: {participantId: "daml-on-sql"} 
06:17:01.052 [scala-execution-context-global-44] ERROR com.daml.resources.ProgramResource - Shutting down because of an initialization error.  
com.daml.platform.common.MismatchException$LedgerId: The provided ledger id does not match the existing one. Existing: "ledger-mesch-test-ledger", Provided: "ledger-mesch-test-ledger-id".
	at com.daml.platform.store.backend.common.ParameterStorageBackendTemplate$.initializeParameters(ParameterStorageBackendTemplate.scala:133)

Aha!

4

So the problem was not running in a container, but that the container invocation command line was pointing to the wrong database that was initialized with another ledger ID, while as the direct invocation was ore explicit and used the right database.

There is an error message that says as much: Found existing database with mismatching ledgerId, but the message doesn’t show up in the log unless --database-connection-pool-size is set to 1.