Error on sandbox with long running choice

Questions
,
1

I tried to submit some choices into sandbox using client.getCommandSubmissionClient().submit(). Interestingly some commands didn’t get executed and the following errors were found.

DEBUG: HikariPool-2 - Timeout failure stats (total=1, active=1, idle=0, waiting=1)
INFO: Submission of command rejected: HikariPool-2 - Connection is not available, request timed out after 30001ms. (context: {commandId=044b172f-41ed-4297-ba58-e24e9305d40a, parties=[EUR_Bank]})
ERROR: Unhandled internal error (context: {commandId=044b172f-41ed-4297-ba58-e24e9305d40a, parties=[EUR_Bank]})
java.sql.SQLTransientConnectionException: HikariPool-2 - Connection is not available, request timed out after 30001ms.
at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:676)
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:190)
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:155)
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
at com.daml.ledger.on.sql.Database.$anonfun$inTransaction$1(Database.scala:47)
at com.daml.metrics.Timed$.$anonfun$value$1(Timed.scala:18)
at com.codahale.metrics.Timer.time(Timer.java:118)
at com.daml.metrics.Timed$.value(Timed.scala:18)
at com.daml.ledger.on.sql.Database.inTransaction(Database.scala:47)
at com.daml.ledger.on.sql.Database.inWriteTransaction(Database.scala:39)
at com.daml.ledger.on.sql.SqlLedgerReaderWriter$SqlLedgerStateAccess$.inTransaction(SqlLedgerReaderWriter.scala:98)
at com.daml.ledger.validator.SubmissionValidator$TimedLedgerStateAccess.inTransaction(SubmissionValidator.scala:272)
at com.daml.ledger.validator.SubmissionValidator.runValidation(SubmissionValidator.scala:184)
at com.daml.ledger.validator.SubmissionValidator.validateAndCommitWithLoggingContext(SubmissionValidator.scala:93)
at com.daml.ledger.validator.ValidatingCommitter.$anonfun$commit$1(ValidatingCommitter.scala:55)
at com.daml.logging.LoggingContext$.withEnrichedLoggingContext(LoggingContext.scala:23)
at com.daml.logging.LoggingContext$.$anonfun$newLoggingContext$1(LoggingContext.scala:19)
at com.daml.logging.LoggingContext$.newLoggingContext(LoggingContext.scala:15)
at com.daml.logging.LoggingContext$.newLoggingContext(LoggingContext.scala:19)
at com.daml.ledger.validator.ValidatingCommitter.commit(ValidatingCommitter.scala:53)
at com.daml.ledger.on.sql.SqlLedgerReaderWriter.commit(SqlLedgerReaderWriter.scala:94)
at com.daml.ledger.participant.state.kvutils.api.TimedLedgerWriter.$anonfun$commit$1(TimedLedgerWriter.scala:19)
at com.daml.metrics.Timed$.future(Timed.scala:30)
at com.daml.ledger.participant.state.kvutils.api.TimedLedgerWriter.commit(TimedLedgerWriter.scala:19)
at com.daml.ledger.participant.state.kvutils.api.KeyValueParticipantStateWriter.commit(KeyValueParticipantStateWriter.scala:82)
at com.daml.ledger.participant.state.kvutils.api.KeyValueParticipantStateWriter.submitTransaction(KeyValueParticipantStateWriter.scala:34)
at com.daml.ledger.participant.state.kvutils.api.KeyValueParticipantState.submitTransaction(KeyValueParticipantState.scala:51)
at com.daml.ledger.participant.state.v1.metrics.TimedWriteService.$anonfun$submitTransaction$1(TimedWriteService.scala:23)
at com.daml.metrics.Timed$.completionStage(Timed.scala:22)
at com.daml.ledger.participant.state.v1.metrics.TimedWriteService.submitTransaction(TimedWriteService.scala:23)
at com.daml.platform.apiserver.services.ApiSubmissionService.submitTransaction(ApiSubmissionService.scala:268)
at com.daml.platform.apiserver.services.ApiSubmissionService.submitTransaction(ApiSubmissionService.scala:251)
at com.daml.platform.apiserver.services.ApiSubmissionService.$anonfun$recordOnLedger$5(ApiSubmissionService.scala:203)
at scala.concurrent.Future.$anonfun$flatMap$1(Future.scala:307)
at scala.concurrent.impl.Promise.$anonfun$transformWith$1(Promise.scala:41)
at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:64)
at akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:55)
at akka.dispatch.BatchingExecutor$BlockableBatch.$anonfun$run$1(BatchingExecutor.scala:92)
at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:23)
at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:85)
at akka.dispatch.BatchingExecutor$BlockableBatch.run(BatchingExecutor.scala:92)
at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:47)
at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(ForkJoinExecutorConfigurator.scala:47)
at java.util.concurrent.ForkJoinTask.doExec(Unknown Source)
at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(Unknown Source)
at java.util.concurrent.ForkJoinPool.runWorker(Unknown Source)
at java.util.concurrent.ForkJoinWorkerThread.run(Unknown Source)
DEBUG: [id: 0x6227545d, L:/127.0.0.1:6865 - R:/127.0.0.1:59859] OUTBOUND HEADERS: streamId=9 headers=GrpcHttp2OutboundHeaders[:status: 200, content-type: application/grpc, grpc-status: 13, grpc-message: HikariPool-2 - Connection is not available, request timed out after 30001ms.] padding=0 endStream=true
DEBUG: [DA.Internal.Prelude:540]: 2020-07-14T07:17:42.294Z

Anyone know what this error is related to? Thanks.

2

We looked into the issue and noticed that there is an issue in how sandbox manages acquiring the connection to the server. It’s detailed in this ticket I just opened. The short explanation is that instead of queuing up transactions for writing we let them go straight to acquire a connection to the database for writing, causing an unwanted buildup of requests waiting on a single database writer thread (why just one? Because that’s the point where transactions are sequenced).

Until this is sorted out, it’s safe to retry those commands as the failure occurs before any persistence has taken effect. Please verify whether you have to change the command identifier to prevent command deduplication to cause the new command to be ignored.

3 Likes