2023-04-24T20:21:44.539120+0200 test-bank-api-64382 INFO Relying on nexus http://localhost:5001/facades/my-facade/taler-wire-gateway/ on port 5001 2023-04-24T20:21:44.539530+0200 test-bank-api-64382 INFO exchange payto: payto://iban/BIC/ES9121000418450200051332?receiver-name=Exchange 2023-04-24T20:21:44.539540+0200 test-bank-api-64382 INFO user42_payto: payto://iban/SANDBOXX/FR7630006000011234567890189?receiver-name=User42 2023-04-24T20:21:44.539546+0200 test-bank-api-64382 INFO user42_payto: payto://iban/SANDBOXX/GB33BUKB20201555555555?receiver-name=User43 Waiting for `nexus' to be ready (via curl -s http://localhost:5001/facades/my-facade/taler-wire-gateway/) .20:21:45.435 [main] INFO tech.libeufin.nexus - Starting Nexus on port 5001 .20:21:45.816 [main] DEBUG tech.libeufin.nexus - Application started: io.ktor.server.application.Application@715d6168 20:21:46.673 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 404 Not Found: GET - /facades/my-facade/taler-wire-gateway/ 20:21:47.580 [main] WARN tech.libeufin.sandbox - CAPTCHA URL doesn't have the WOPID placeholder. Taler withdrawals decrease usability Waiting for `sandbox' to be ready. .20:21:48.478 [main] INFO tech.libeufin.sandbox - Starting Sandbox on port 5000 .20:21:48.661 [main] DEBUG tech.libeufin.sandbox - Application started: io.ktor.server.application.Application@615e3f51 20:21:49.751 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, GET / Hello, this is the Sandbox 20:21:50.153 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /demobanks/default/access-api/testing/register 20:21:50.323 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /demobanks/default/access-api/testing/register 20:21:50.475 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /demobanks/default/access-api/testing/register Create EBICS host at Sandbox...20:21:51.086 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /admin/ebics/hosts OK Create exchange EBICS subscriber at Sandbox...20:21:51.254 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /demobanks/default/ebics/subscribers OK Create the exchange (super)user at Nexus... DONE Creating a EBICS connection at Nexus...20:21:53.007 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /bank-connections OK Setup EBICS keying...20:21:53.964 [eventLoopGroupProxy-4-1] INFO tech.libeufin.sandbox - Serving a INI request 20:21:54.025 [eventLoopGroupProxy-4-1] INFO tech.libeufin.sandbox - Signature key inserted in database _and_ subscriber state changed accordingly 20:21:54.037 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb 20:21:54.108 [eventLoopGroupProxy-4-1] INFO tech.libeufin.sandbox - Serving a HIA request 20:21:54.130 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb 20:21:54.395 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb 20:21:54.486 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /bank-connections/my-bank-connection/connect OK Download bank account name from Sandbox...20:21:54.640 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Created EBICS HTD document for download initialization, nonce: 7AFF6AF06FD00545DA6001A26437F6A5 20:21:54.727 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download initialization for order type HTD, nonce: 7AFF6AF06FD00545DA6001A26437F6A5, transaction ID: 61ED56D86990F6ED64612BD445781B4C 20:21:54.816 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb 20:21:54.867 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Bank acknowledges EBICS download initialization. Transaction ID: 61ED56D86990F6ED64612BD445781B4C. 20:21:54.938 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download receipt for EBICS transaction: 61ED56D86990F6ED64612BD445781B4C 20:21:54.967 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb 20:21:54.994 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Bank acknowledges EBICS download receipt. Transaction ID: 61ED56D86990F6ED64612BD445781B4C. 20:21:55.021 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /bank-connections/my-bank-connection/fetch-accounts OK Importing bank account info into Nexus...20:21:55.160 [eventLoopGroupProxy-4-1] INFO tech.libeufin.nexus - Account 1 gets imported 20:21:55.164 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /bank-connections/my-bank-connection/import-account OK Create the Taler facade at Nexus...20:21:55.343 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /facades DONE Setup payments submission task..20:21:55.529 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /bank-accounts/my-bank-account/schedule OK Setup history fetch task..20:21:55.673 [DefaultDispatcher-worker-1] INFO tech.libeufin.nexus - Scheduling task exchange-payments at Optional[2023-04-24T20:21:56.663217627+02:00[Europe/Zurich]] (now is 2023-04-24T20:21:55.663217627+02:00[Europe/Zurich]). 20:21:55.761 [eventLoopGroupProxy-4-1] WARN Exposed - Transaction attempt #0 failed: org.sqlite.SQLiteException: [SQLITE_BUSY] The database file is locked (database is locked). Statement(s): INSERT INTO NexusScheduledTasks (resourceId, resourceType, taskCronspec, taskName, taskParams, taskType) VALUES (?, ?, ?, ?, ?, ?) org.jetbrains.exposed.exceptions.ExposedSQLException: org.sqlite.SQLiteException: [SQLITE_BUSY] The database file is locked (database is locked) at org.jetbrains.exposed.sql.statements.Statement.executeIn$exposed_core(Statement.kt:62) at org.jetbrains.exposed.sql.Transaction.exec(Transaction.kt:135) at org.jetbrains.exposed.sql.Transaction.exec(Transaction.kt:121) at org.jetbrains.exposed.sql.statements.Statement.execute(Statement.kt:28) at org.jetbrains.exposed.sql.QueriesKt.batchInsert(Queries.kt:134) at org.jetbrains.exposed.sql.QueriesKt.batchInsert$default(Queries.kt:86) at org.jetbrains.exposed.dao.EntityCache$flushInserts$1$ids$1.invoke(EntityCache.kt:122) at org.jetbrains.exposed.dao.EntityCache$flushInserts$1$ids$1.invoke(EntityCache.kt:121) at org.jetbrains.exposed.dao.EntityLifecycleInterceptorKt.executeAsPartOfEntityLifecycle(EntityLifecycleInterceptor.kt:17) at org.jetbrains.exposed.dao.EntityCache.flushInserts$exposed_dao(EntityCache.kt:121) at org.jetbrains.exposed.dao.EntityCache.flush(EntityCache.kt:81) at org.jetbrains.exposed.dao.EntityCache.flush(EntityCache.kt:48) at org.jetbrains.exposed.dao.EntityCacheKt.flushCache(EntityCache.kt:166) at org.jetbrains.exposed.dao.EntityLifecycleInterceptor.beforeCommit(EntityLifecycleInterceptor.kt:68) at org.jetbrains.exposed.sql.Transaction.commit(Transaction.kt:63) at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManagerKt.inTopLevelTransaction$run(ThreadLocalTransactionManager.kt:174) at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManagerKt.access$inTopLevelTransaction$run(ThreadLocalTransactionManager.kt:1) at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManagerKt$inTopLevelTransaction$1.invoke(ThreadLocalTransactionManager.kt:194) at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManagerKt.keepAndRestoreTransactionRefAfterRun(ThreadLocalTransactionManager.kt:202) at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManagerKt.inTopLevelTransaction(ThreadLocalTransactionManager.kt:193) at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManagerKt$transaction$1.invoke(ThreadLocalTransactionManager.kt:151) at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManagerKt.keepAndRestoreTransactionRefAfterRun(ThreadLocalTransactionManager.kt:202) at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManagerKt.transaction(ThreadLocalTransactionManager.kt:123) at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManagerKt.transaction(ThreadLocalTransactionManager.kt:121) at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManagerKt.transaction$default(ThreadLocalTransactionManager.kt:120) at tech.libeufin.nexus.server.NexusServerKt$nexusApp$1$5$13.invokeSuspend(NexusServer.kt:479) at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33) at kotlinx.coroutines.internal.DispatchedContinuation.resumeWith(DispatchedContinuation.kt:205) at io.ktor.util.pipeline.SuspendFunctionGun.resumeRootWith(SuspendFunctionGun.kt:135) at io.ktor.util.pipeline.SuspendFunctionGun.loop(SuspendFunctionGun.kt:109) at io.ktor.util.pipeline.SuspendFunctionGun.access$loop(SuspendFunctionGun.kt:11) at io.ktor.util.pipeline.SuspendFunctionGun$continuation$1.resumeWith(SuspendFunctionGun.kt:59) at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46) at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469) at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:384) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.ktor.server.netty.EventLoopGroupProxy$Companion.create$lambda$1$lambda$0(NettyApplicationEngine.kt:291) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:833) Caused by: org.sqlite.SQLiteException: [SQLITE_BUSY] The database file is locked (database is locked) at org.sqlite.core.DB.newSQLException(DB.java:1012) at org.sqlite.core.DB.newSQLException(DB.java:1024) at org.sqlite.core.DB.throwex(DB.java:989) at org.sqlite.core.DB.executeBatch(DB.java:814) at org.sqlite.core.CorePreparedStatement.executeBatch(CorePreparedStatement.java:64) at org.jetbrains.exposed.sql.statements.jdbc.JdbcPreparedStatementImpl.executeBatch(JdbcPreparedStatementImpl.kt:48) at org.jetbrains.exposed.sql.statements.InsertStatement.execInsertFunction(InsertStatement.kt:111) at org.jetbrains.exposed.sql.statements.InsertStatement.executeInternal(InsertStatement.kt:117) at org.jetbrains.exposed.sql.statements.InsertStatement.executeInternal(InsertStatement.kt:11) at org.jetbrains.exposed.sql.statements.Statement.executeIn$exposed_core(Statement.kt:60) ... 41 common frames omitted 20:21:55.788 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /bank-accounts/my-bank-account/schedule OK 2023-04-24T20:21:55.803865+0200 test-bank-api-64382 INFO Bank serves at `http://localhost:5001/facades/my-facade/taler-wire-gateway/' 2023-04-24T20:21:55.803920+0200 test-bank-api-64382 INFO Running command `history-0' 2023-04-24T20:21:55.803952+0200 test-bank-api-64382 INFO Requesting credit history at `http://localhost:5001/facades/my-facade/taler-wire-gateway/history/incoming?delta=1' 20:21:55.813 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 204 No Content: GET - /facades/my-facade/taler-wire-gateway/history/incoming 2023-04-24T20:21:55.813495+0200 test-bank-api-64382 INFO Running command `credit-1' 2023-04-24T20:21:55.813685+0200 test-bank-api-64382 INFO Requesting administrative transaction at `http://localhost:5001/facades/my-facade/taler-wire-gateway/admin/add-incoming' for reserve J2CHGD9D 20:21:55.834 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - TWG add-incoming passed authentication 20:21:55.847 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - TWG add-incoming about to wire transfer 20:21:55.852 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Maybe wire transfer: fortytwo -> exchange, M5RGD718YZD2Z18Y5QBX1RY37SRMJX6FDY0NBPK1DNQ8GDNBHRRG, KUDOS:5.01 20:21:55.867 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - TWG add-incoming has wire transferred 20:21:55.873 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /demobanks/default/taler-wire-gateway/exchange/admin/add-incoming 20:21:55.883 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Created EBICS C52 document for download initialization, nonce: 70C3E8BC9866EC5F2C107C33EBBBFD95 20:21:55.933 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download initialization for order type C52, nonce: 70C3E8BC9866EC5F2C107C33EBBBFD95, transaction ID: 8D7D67E4705862A9B2681B497DAE08B9 20:21:55.979 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - camt.052 document 'sandbox-1682360515-YZABTUMX4V' generated. It includes the payments: - M5RGD718YZD2Z18Y5QBX1RY37SRMJX6FDY0NBPK1DNQ8GDNBHRRG 20:21:56.022 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb 20:21:56.041 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Bank acknowledges EBICS download initialization. Transaction ID: 8D7D67E4705862A9B2681B497DAE08B9. 20:21:56.081 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download receipt for EBICS transaction: 8D7D67E4705862A9B2681B497DAE08B9 20:21:56.095 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb 20:21:56.116 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Bank acknowledges EBICS download receipt. Transaction ID: 8D7D67E4705862A9B2681B497DAE08B9. 20:21:56.145 [eventLoopGroupProxy-4-1] INFO tech.libeufin.nexus - Camt document 'sandbox-1682360515-YZABTUMX4V' received via C52. 20:21:56.291 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Camt C52 'sandbox-1682360515-YZABTUMX4V' has new payments: - M5RGD718YZD2Z18Y5QBX1RY37SRMJX6FDY0NBPK1DNQ8GDNBHRRG 20:21:56.297 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Ingesting transactions for TALER facade 1, and bank account: my-bank-account 20:21:56.331 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Searching refundable payments of account: my-bank-account, after last seen transaction id: 0 20:21:56.348 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /facades/my-facade/taler-wire-gateway/admin/add-incoming 2023-04-24T20:21:56.349219+0200 test-bank-api-64382 INFO Running command `credit-1-fail' 2023-04-24T20:21:56.349361+0200 test-bank-api-64382 INFO Requesting administrative transaction at `http://localhost:5001/facades/my-facade/taler-wire-gateway/admin/add-incoming' for reserve J2CHGD9D 20:21:56.361 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - TWG add-incoming passed authentication 20:21:56.365 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - TWG add-incoming about to wire transfer 20:21:56.366 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Maybe wire transfer: fortytwo -> exchange, M5RGD718YZD2Z18Y5QBX1RY37SRMJX6FDY0NBPK1DNQ8GDNBHRRG, KUDOS:2.01 20:21:56.380 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - TWG add-incoming has wire transferred 20:21:56.384 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /demobanks/default/taler-wire-gateway/exchange/admin/add-incoming 20:21:56.391 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Created EBICS C52 document for download initialization, nonce: F7C96FDF0FA90DF7A08EE30B8EB5CD25 20:21:56.435 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download initialization for order type C52, nonce: F7C96FDF0FA90DF7A08EE30B8EB5CD25, transaction ID: B00A9249878672B79865E4F23F245553 20:21:56.442 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - camt.052 document 'sandbox-1682360516-3EQ0CLK6GC' generated. It includes the payments: - M5RGD718YZD2Z18Y5QBX1RY37SRMJX6FDY0NBPK1DNQ8GDNBHRRG 20:21:56.467 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb 20:21:56.490 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Bank acknowledges EBICS download initialization. Transaction ID: B00A9249878672B79865E4F23F245553. 20:21:56.542 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download receipt for EBICS transaction: B00A9249878672B79865E4F23F245553 20:21:56.562 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb 20:21:56.581 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Bank acknowledges EBICS download receipt. Transaction ID: B00A9249878672B79865E4F23F245553. 20:21:56.583 [eventLoopGroupProxy-4-1] INFO tech.libeufin.nexus - Camt document 'sandbox-1682360516-3EQ0CLK6GC' received via C52. 20:21:56.616 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Camt C52 'sandbox-1682360516-3EQ0CLK6GC' has new payments: - M5RGD718YZD2Z18Y5QBX1RY37SRMJX6FDY0NBPK1DNQ8GDNBHRRG 20:21:56.619 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Ingesting transactions for TALER facade 1, and bank account: my-bank-account 20:21:56.638 [eventLoopGroupProxy-4-1] INFO tech.libeufin.nexus - Reserve pub 'M5RGD718YZD2Z18Y5QBX1RY37SRMJX6FDY0NBPK1DNQ8GDNBHRRG' was used already 20:21:56.640 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Searching refundable payments of account: my-bank-account, after last seen transaction id: 1 20:21:56.656 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Refund of transaction (AcctSvcrRef): 60NPH99L got prepared 20:21:56.660 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /facades/my-facade/taler-wire-gateway/admin/add-incoming 2023-04-24T20:21:56.661553+0200 test-bank-api-64382 INFO Running command `Waiting 4s for 'credit-1' to settle' 2023-04-24T20:22:00.661712+0200 test-bank-api-64382 INFO Running command `history-1c' 2023-04-24T20:22:00.661780+0200 test-bank-api-64382 INFO Found history: payto://iban/SANDBOXX/FR7630006000011234567890189?receiver-name=User42->payto://void/the-exchange for account http://localhost:5001/facades/my-facade/taler-wire-gateway/ 2023-04-24T20:22:00.661795+0200 test-bank-api-64382 INFO Requesting credit history at `http://localhost:5001/facades/my-facade/taler-wire-gateway/history/incoming?delta=5' 20:22:00.675 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: GET - /facades/my-facade/taler-wire-gateway/history/incoming 2023-04-24T20:22:00.676726+0200 test-bank-api-64382 INFO Running command `history-1d' 2023-04-24T20:22:00.676781+0200 test-bank-api-64382 INFO Checking commands 0 to 5 for debit history 2023-04-24T20:22:00.676790+0200 test-bank-api-64382 INFO Checking if command history-0 is relevant for debit history 2023-04-24T20:22:00.676797+0200 test-bank-api-64382 INFO Checking if command credit-1 is relevant for debit history 2023-04-24T20:22:00.676811+0200 test-bank-api-64382 INFO Trait wtid/0 not found. 2023-04-24T20:22:00.676818+0200 test-bank-api-64382 INFO Checking if command credit-1-fail is relevant for debit history 2023-04-24T20:22:00.676825+0200 test-bank-api-64382 INFO Checking if command Waiting 4s for 'credit-1' to settle is relevant for debit history 2023-04-24T20:22:00.676832+0200 test-bank-api-64382 INFO Checking if command history-1c is relevant for debit history 2023-04-24T20:22:00.676845+0200 test-bank-api-64382 INFO Requesting debit history at `http://localhost:5001/facades/my-facade/taler-wire-gateway/history/outgoing?delta=5' 20:22:00.683 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 204 No Content: GET - /facades/my-facade/taler-wire-gateway/history/outgoing 2023-04-24T20:22:00.683741+0200 test-bank-api-64382 INFO Running command `credit-2' 2023-04-24T20:22:00.683852+0200 test-bank-api-64382 INFO Requesting administrative transaction at `http://localhost:5001/facades/my-facade/taler-wire-gateway/admin/add-incoming' for reserve K7Z2D6JP 20:22:00.695 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - TWG add-incoming passed authentication 20:22:00.698 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - TWG add-incoming about to wire transfer 20:22:00.698 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Maybe wire transfer: fortytwo -> exchange, ACJ5JXSVKS77H7252GSRG3MFMMNTS71TDKW52946Q7PD4CRZBS3G, KUDOS:3.21 20:22:00.706 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - TWG add-incoming has wire transferred 20:22:00.710 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /demobanks/default/taler-wire-gateway/exchange/admin/add-incoming 20:22:00.715 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Created EBICS C52 document for download initialization, nonce: C6503122D427CA5154B5A0947C23796A 20:22:00.753 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download initialization for order type C52, nonce: C6503122D427CA5154B5A0947C23796A, transaction ID: 6916A12A4CCAE3CD00BEBDA9D01FF36D 20:22:00.760 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - camt.052 document 'sandbox-1682360520-GJQ2SMQA74' generated. It includes the payments: - ACJ5JXSVKS77H7252GSRG3MFMMNTS71TDKW52946Q7PD4CRZBS3G 20:22:00.783 [DefaultDispatcher-worker-3] INFO tech.libeufin.nexus - Scheduling task exchange-history at Optional[2023-04-24T20:22:01.782541968+02:00[Europe/Zurich]] (now is 2023-04-24T20:22:00.782541968+02:00[Europe/Zurich]). 20:22:00.784 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb 20:22:00.793 [DefaultDispatcher-worker-3] INFO tech.libeufin.nexus - running task TaskSchedule(taskId=1, name=exchange-payments, type=submit, resourceType=bank-account, resourceId=my-bank-account, params={ "rangeType" : null, "level" : null }) 20:22:00.803 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Bank acknowledges EBICS download initialization. Transaction ID: 6916A12A4CCAE3CD00BEBDA9D01FF36D. 20:22:00.849 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download receipt for EBICS transaction: 6916A12A4CCAE3CD00BEBDA9D01FF36D 20:22:00.865 [DefaultDispatcher-worker-3] DEBUG tech.libeufin.util - Created EBICS CCT document for upload initialization, nonce: C4C1C6796E74154CF06824404A6DBF56 20:22:00.867 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb 20:22:00.879 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Bank acknowledges EBICS download receipt. Transaction ID: 6916A12A4CCAE3CD00BEBDA9D01FF36D. 20:22:00.881 [eventLoopGroupProxy-4-1] INFO tech.libeufin.nexus - Camt document 'sandbox-1682360520-GJQ2SMQA74' received via C52. 20:22:00.898 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Camt C52 'sandbox-1682360520-GJQ2SMQA74' has new payments: - ACJ5JXSVKS77H7252GSRG3MFMMNTS71TDKW52946Q7PD4CRZBS3G 20:22:00.900 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Ingesting transactions for TALER facade 1, and bank account: my-bank-account 20:22:00.908 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling upload initialization for order CCT, transactionID 36050792ACD95204561997D70475C388, nonce: C4C1C6796E74154CF06824404A6DBF56 20:22:00.912 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Searching refundable payments of account: my-bank-account, after last seen transaction id: 2 20:22:00.916 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /facades/my-facade/taler-wire-gateway/admin/add-incoming 2023-04-24T20:22:00.917446+0200 test-bank-api-64382 INFO Running command `debit-1' 2023-04-24T20:22:00.917516+0200 test-bank-api-64382 INFO Transfer of KUDOS:3.22 from http://localhost:5001/facades/my-facade/taler-wire-gateway/ to payto://iban/SANDBOXX/FR7630006000011234567890189?receiver-name=User42 20:22:00.919 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - inserting order signature for orderID OR01, order type CCT, transaction '36050792ACD95204561997D70475C388' 20:22:00.930 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Taler requests payment: 58N2MAHA58N2MAHA58N2MAHA58N2MAHA58N2MAHA58N2MAHA58N0 20:22:00.939 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /facades/my-facade/taler-wire-gateway/transfer 20:22:00.940 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb 2023-04-24T20:22:00.940545+0200 test-bank-api-64382 INFO Running command `Waiting 5s for 'debit-1' to settle' 20:22:00.955 [DefaultDispatcher-worker-1] DEBUG tech.libeufin.util - Bank acknowledges EBICS upload initialization. Transaction ID: 36050792ACD95204561997D70475C388. 20:22:01.014 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling Pain.001: leuf-p-187b480402d-1-1, for payment: Taler refund of: M5RGD718YZD2Z18Y5QBX1RY37SRMJX6FDY0NBPK1DNQ8GDNBHRRG 20:22:01.040 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb 20:22:01.057 [DefaultDispatcher-worker-1] DEBUG tech.libeufin.util - Bank acknowledges EBICS upload transfer. Transaction ID: 36050792ACD95204561997D70475C388 2023-04-24T20:22:05.940667+0200 test-bank-api-64382 INFO Running command `history-2b' 2023-04-24T20:22:05.940727+0200 test-bank-api-64382 INFO Checking commands 0 to 9 for debit history 2023-04-24T20:22:05.940736+0200 test-bank-api-64382 INFO Checking if command history-0 is relevant for debit history 2023-04-24T20:22:05.940742+0200 test-bank-api-64382 INFO Checking if command credit-1 is relevant for debit history 2023-04-24T20:22:05.940778+0200 test-bank-api-64382 INFO Trait wtid/0 not found. 2023-04-24T20:22:05.940788+0200 test-bank-api-64382 INFO Checking if command credit-1-fail is relevant for debit history 2023-04-24T20:22:05.940794+0200 test-bank-api-64382 INFO Checking if command Waiting 4s for 'credit-1' to settle is relevant for debit history 2023-04-24T20:22:05.940801+0200 test-bank-api-64382 INFO Checking if command history-1c is relevant for debit history 2023-04-24T20:22:05.940807+0200 test-bank-api-64382 INFO Checking if command history-1d is relevant for debit history 2023-04-24T20:22:05.940813+0200 test-bank-api-64382 INFO Checking if command credit-2 is relevant for debit history 2023-04-24T20:22:05.940820+0200 test-bank-api-64382 INFO Trait wtid/0 not found. 2023-04-24T20:22:05.940826+0200 test-bank-api-64382 INFO Checking if command debit-1 is relevant for debit history 2023-04-24T20:22:05.940838+0200 test-bank-api-64382 INFO Command debit-1 is relevant for debit history! 2023-04-24T20:22:05.940846+0200 test-bank-api-64382 INFO Found history: payto://iban/BIC/ES9121000418450200051332?receiver-name=Exchange->payto://iban/SANDBOXX/FR7630006000011234567890189?receiver-name=User42 for account http://localhost:5001/facades/my-facade/taler-wire-gateway/ 2023-04-24T20:22:05.940854+0200 test-bank-api-64382 INFO Checking if command Waiting 5s for 'debit-1' to settle is relevant for debit history 2023-04-24T20:22:05.940868+0200 test-bank-api-64382 INFO Requesting debit history at `http://localhost:5001/facades/my-facade/taler-wire-gateway/history/outgoing?delta=5' 20:22:05.946 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 204 No Content: GET - /facades/my-facade/taler-wire-gateway/history/outgoing 2023-04-24T20:22:05.947166+0200 test-bank-api-64382 ERROR Assertion failed at testing_api_cmd_bank_history_debit.c:413. 2023-04-24T20:22:05.947200+0200 test-bank-api-64382 ERROR Expected history of length 1, got 0; HTTP status code: 204/0, failed: 0 2023-04-24T20:22:05.947209+0200 test-bank-api-64382 ERROR Transaction history (debit) mismatch at position 4294967295/1 2023-04-24T20:22:05.947216+0200 test-bank-api-64382 ERROR Expected history: 2023-04-24T20:22:05.947240+0200 test-bank-api-64382 ERROR H(0): KUDOS:3.22 (serial: 1, subject: Y852C4XX, counterpart: payto://iban/SANDBOXX/FR7630006000011234567890189?receiver-name=User42) 2023-04-24T20:22:05.947249+0200 test-bank-api-64382 ERROR Failed at command `history-2b' 2023-04-24T20:22:05.947272+0200 test-bank-api-64382 INFO Executing shutdown at `history-2b' FAIL test_bank_api_with_nexus (exit status: 1)