View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0007809 | Taler | libeufin-nexus | public | 2023-04-22 15:34 | 2023-09-23 15:09 |
| Reporter | Christian Grothoff | Assigned To | Florian Dold | ||
| Priority | urgent | Severity | block | Reproducibility | always |
| Status | closed | Resolution | fixed | ||
| Platform | i7 | OS | Debian GNU/Linux | OS Version | squeeze |
| Product Version | git (master) | ||||
| Target Version | 0.9.3 | Fixed in Version | 0.9.3 | ||
| Summary | 0007809: regression: test_bank_api_with_nexus started to fail | ||||
| Description | Basically, the test says that the expected debit transaction history is empty, even though it should have a transaction in it. There were no changes I would consider even 'related' to this issue in the exchange, so this is likely a regression in libeufin. | ||||
| Tags | No tags attached. | ||||
|
|
Could not reproduce. |
|
|
Attaching the log from the test. I really just run 'make check' with the latest gnunet/exchange/merchant/libeufin. test_bank_api_with_nexus.log (27,721 bytes)
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)
|
|
|
The logs suggest that the failing "history-2b" command started before the libeufin scheduler could start the "fetch" task. This change in libeufin.git makes tighter rounds to schedule background tasks: 2471f00eba039a460cc31f02fc47a2267367efd. |
|
|
With Florians help, after spending like 2h, we've added the fetch-transactions you suggested. But, it still fails the same way as before. Log attached. new-log.txt (33,288 bytes)
2023-04-25T23:06:45.595964+0200 test-bank-api-50863 INFO Relying on nexus http://localhost:5001/facades/my-facade/taler-wire-gateway/ on port 5001
2023-04-25T23:06:45.596067+0200 test-bank-api-50863 INFO exchange payto: payto://iban/BIC/ES9121000418450200051332?receiver-name=Exchange
2023-04-25T23:06:45.596079+0200 test-bank-api-50863 INFO user42_payto: payto://iban/SANDBOXX/FR7630006000011234567890189?receiver-name=User42
2023-04-25T23:06:45.596086+0200 test-bank-api-50863 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/)
.23:06:46.500 [main] INFO tech.libeufin.nexus - Starting Nexus on port 5001
.23:06:46.864 [main] DEBUG tech.libeufin.nexus - Application started: io.ktor.server.application.Application@715d6168
23:06:47.732 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 404 Not Found: GET - /facades/my-facade/taler-wire-gateway/
23:06:48.633 [main] WARN tech.libeufin.sandbox - CAPTCHA URL doesn't have the WOPID placeholder. Taler withdrawals decrease usability
Waiting for `sandbox' to be ready.
.23:06:49.533 [main] INFO tech.libeufin.sandbox - Starting Sandbox on port 5000
.23:06:49.720 [main] DEBUG tech.libeufin.sandbox - Application started: io.ktor.server.application.Application@2e51d054
23:06:50.804 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, GET /
Hello, this is the Sandbox
23:06:51.206 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /demobanks/default/access-api/testing/register
23:06:51.374 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /demobanks/default/access-api/testing/register
23:06:51.536 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /demobanks/default/access-api/testing/register
Create EBICS host at Sandbox...23:06:52.278 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /admin/ebics/hosts
OK
Create exchange EBICS subscriber at Sandbox...23:06:52.448 [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...23:06:54.209 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /bank-connections
OK
Setup EBICS keying...23:06:55.104 [eventLoopGroupProxy-4-1] INFO tech.libeufin.sandbox - Serving a INI request
23:06:55.158 [eventLoopGroupProxy-4-1] INFO tech.libeufin.sandbox - Signature key inserted in database _and_ subscriber state changed accordingly
23:06:55.171 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb
23:06:55.239 [eventLoopGroupProxy-4-1] INFO tech.libeufin.sandbox - Serving a HIA request
23:06:55.267 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb
23:06:55.537 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb
23:06:55.629 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /bank-connections/my-bank-connection/connect
OK
Download bank account name from Sandbox...23:06:55.764 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Created EBICS HTD document for download initialization, nonce: 05F516B1EC8DD76973DEB32E4B2F79C6
23:06:55.857 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download initialization for order type HTD, nonce: 05F516B1EC8DD76973DEB32E4B2F79C6, transaction ID: A79A618A56621B05A9078BBEE179DDCA
23:06:55.949 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb
23:06:55.997 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Bank acknowledges EBICS download initialization. Transaction ID: A79A618A56621B05A9078BBEE179DDCA.
23:06:56.062 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download receipt for EBICS transaction: A79A618A56621B05A9078BBEE179DDCA
23:06:56.087 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb
23:06:56.125 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Bank acknowledges EBICS download receipt. Transaction ID: A79A618A56621B05A9078BBEE179DDCA.
23:06:56.153 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /bank-connections/my-bank-connection/fetch-accounts
OK
Importing bank account info into Nexus...23:06:56.312 [eventLoopGroupProxy-4-1] INFO tech.libeufin.nexus - Account 1 gets imported
23:06:56.316 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /bank-connections/my-bank-connection/import-account
OK
Create the Taler facade at Nexus...23:06:56.498 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /facades
DONE
Setup payments submission task..23:06:56.653 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /bank-accounts/my-bank-account/schedule
OK
Setup history fetch task..23:06:56.725 [DefaultDispatcher-worker-1] INFO tech.libeufin.nexus - Scheduling task exchange-payments at Optional[2023-04-25T23:06:57.714885433+02:00[Europe/Zurich]] (now is 2023-04-25T23:06:56.714885433+02:00[Europe/Zurich]).
23:06:56.894 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /bank-accounts/my-bank-account/schedule
OK
2023-04-25T23:06:56.916897+0200 test-bank-api-50863 INFO Bank serves at `http://localhost:5001/facades/my-facade/taler-wire-gateway/'
2023-04-25T23:06:56.916961+0200 test-bank-api-50863 INFO Running command `history-0'
2023-04-25T23:06:56.916993+0200 test-bank-api-50863 INFO Requesting credit history at `http://localhost:5001/facades/my-facade/taler-wire-gateway/history/incoming?delta=1'
23:06:56.925 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 204 No Content: GET - /facades/my-facade/taler-wire-gateway/history/incoming
2023-04-25T23:06:56.926617+0200 test-bank-api-50863 INFO Running command `credit-1'
2023-04-25T23:06:56.926791+0200 test-bank-api-50863 INFO Requesting administrative transaction at `http://localhost:5001/facades/my-facade/taler-wire-gateway/admin/add-incoming' for reserve 6N30AZWT
23:06:56.946 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - TWG add-incoming passed authentication
23:06:56.960 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - TWG add-incoming about to wire transfer
23:06:56.965 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Maybe wire transfer: fortytwo -> exchange, PQBTRXMCW5MYZSRCCJEYR3F6NKTN92VMP22EAPBG8CJB7BTXBZP0, KUDOS:5.01
23:06:56.981 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - TWG add-incoming has wire transferred
23:06:56.987 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /demobanks/default/taler-wire-gateway/exchange/admin/add-incoming
23:06:57.002 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Created EBICS C52 document for download initialization, nonce: B8C1EBACD92F7EF0C90B91B3ED71D232
23:06:57.065 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download initialization for order type C52, nonce: B8C1EBACD92F7EF0C90B91B3ED71D232, transaction ID: 0CDD1213B0189D113C66C57C02267C0B
23:06:57.109 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - camt.052 document 'sandbox-1682456817-W42DCOV5HJ' generated. It includes the payments:
- PQBTRXMCW5MYZSRCCJEYR3F6NKTN92VMP22EAPBG8CJB7BTXBZP0
23:06:57.150 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb
23:06:57.176 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Bank acknowledges EBICS download initialization. Transaction ID: 0CDD1213B0189D113C66C57C02267C0B.
23:06:57.238 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download receipt for EBICS transaction: 0CDD1213B0189D113C66C57C02267C0B
23:06:57.261 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb
23:06:57.283 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Bank acknowledges EBICS download receipt. Transaction ID: 0CDD1213B0189D113C66C57C02267C0B.
23:06:57.312 [eventLoopGroupProxy-4-1] INFO tech.libeufin.nexus - Camt document 'sandbox-1682456817-W42DCOV5HJ' received via C52.
23:06:57.455 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Camt C52 'sandbox-1682456817-W42DCOV5HJ' has new payments:
- PQBTRXMCW5MYZSRCCJEYR3F6NKTN92VMP22EAPBG8CJB7BTXBZP0
23:06:57.460 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Ingesting transactions for TALER facade 1, and bank account: my-bank-account
23:06:57.493 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Searching refundable payments of account: my-bank-account, after last seen transaction id: 0
23:06:57.510 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /facades/my-facade/taler-wire-gateway/admin/add-incoming
2023-04-25T23:06:57.511611+0200 test-bank-api-50863 INFO Running command `credit-1-fail'
2023-04-25T23:06:57.511759+0200 test-bank-api-50863 INFO Requesting administrative transaction at `http://localhost:5001/facades/my-facade/taler-wire-gateway/admin/add-incoming' for reserve 6N30AZWT
23:06:57.523 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - TWG add-incoming passed authentication
23:06:57.527 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - TWG add-incoming about to wire transfer
23:06:57.527 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Maybe wire transfer: fortytwo -> exchange, PQBTRXMCW5MYZSRCCJEYR3F6NKTN92VMP22EAPBG8CJB7BTXBZP0, KUDOS:2.01
23:06:57.537 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - TWG add-incoming has wire transferred
23:06:57.541 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /demobanks/default/taler-wire-gateway/exchange/admin/add-incoming
23:06:57.548 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Created EBICS C52 document for download initialization, nonce: 26D14EF9E418D2DA8C6703010C501E5C
23:06:57.593 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download initialization for order type C52, nonce: 26D14EF9E418D2DA8C6703010C501E5C, transaction ID: AB653CD266489BD9437F4ED210D8668A
23:06:57.601 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - camt.052 document 'sandbox-1682456817-TJ58836NFE' generated. It includes the payments:
- PQBTRXMCW5MYZSRCCJEYR3F6NKTN92VMP22EAPBG8CJB7BTXBZP0
23:06:57.631 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb
23:06:57.654 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Bank acknowledges EBICS download initialization. Transaction ID: AB653CD266489BD9437F4ED210D8668A.
23:06:57.705 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download receipt for EBICS transaction: AB653CD266489BD9437F4ED210D8668A
23:06:57.725 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb
23:06:57.744 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Bank acknowledges EBICS download receipt. Transaction ID: AB653CD266489BD9437F4ED210D8668A.
23:06:57.746 [eventLoopGroupProxy-4-1] INFO tech.libeufin.nexus - Camt document 'sandbox-1682456817-TJ58836NFE' received via C52.
23:06:57.783 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Camt C52 'sandbox-1682456817-TJ58836NFE' has new payments:
- PQBTRXMCW5MYZSRCCJEYR3F6NKTN92VMP22EAPBG8CJB7BTXBZP0
23:06:57.787 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Ingesting transactions for TALER facade 1, and bank account: my-bank-account
23:06:57.807 [eventLoopGroupProxy-4-1] INFO tech.libeufin.nexus - Reserve pub 'PQBTRXMCW5MYZSRCCJEYR3F6NKTN92VMP22EAPBG8CJB7BTXBZP0' was used already
23:06:57.809 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Searching refundable payments of account: my-bank-account, after last seen transaction id: 1
23:06:57.824 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Refund of transaction (AcctSvcrRef): 99E0G8YC got prepared
23:06:57.828 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /facades/my-facade/taler-wire-gateway/admin/add-incoming
2023-04-25T23:06:57.830969+0200 test-bank-api-50863 INFO Running command `Waiting 4s for 'credit-1' to settle'
23:07:01.731 [DefaultDispatcher-worker-3] INFO tech.libeufin.nexus - Scheduling task exchange-history at Optional[2023-04-25T23:07:02.731046217+02:00[Europe/Zurich]] (now is 2023-04-25T23:07:01.731046217+02:00[Europe/Zurich]).
23:07:01.741 [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
})
23:07:01.807 [DefaultDispatcher-worker-3] DEBUG tech.libeufin.util - Created EBICS CCT document for upload initialization, nonce: 9ABC59B96681F384F3FF4513240EDDBF
2023-04-25T23:07:01.831119+0200 test-bank-api-50863 INFO Running command `history-1c'
2023-04-25T23:07:01.831224+0200 test-bank-api-50863 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-25T23:07:01.831242+0200 test-bank-api-50863 INFO Requesting credit history at `http://localhost:5001/facades/my-facade/taler-wire-gateway/history/incoming?delta=5'
23:07:01.847 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: GET - /facades/my-facade/taler-wire-gateway/history/incoming
2023-04-25T23:07:01.848541+0200 test-bank-api-50863 INFO Running command `history-1d'
2023-04-25T23:07:01.848598+0200 test-bank-api-50863 INFO Checking commands 0 to 5 for debit history
2023-04-25T23:07:01.848608+0200 test-bank-api-50863 INFO Checking if command history-0 is relevant for debit history
2023-04-25T23:07:01.848617+0200 test-bank-api-50863 INFO Checking if command credit-1 is relevant for debit history
2023-04-25T23:07:01.848632+0200 test-bank-api-50863 INFO Trait wtid/0 not found.
2023-04-25T23:07:01.848641+0200 test-bank-api-50863 INFO Checking if command credit-1-fail is relevant for debit history
2023-04-25T23:07:01.848649+0200 test-bank-api-50863 INFO Checking if command Waiting 4s for 'credit-1' to settle is relevant for debit history
2023-04-25T23:07:01.848657+0200 test-bank-api-50863 INFO Checking if command history-1c is relevant for debit history
2023-04-25T23:07:01.848671+0200 test-bank-api-50863 INFO Requesting debit history at `http://localhost:5001/facades/my-facade/taler-wire-gateway/history/outgoing?delta=5'
23:07:01.851 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling upload initialization for order CCT, transactionID C91DB68CA20EF73CBD6C2B1E4BDBF227, nonce: 9ABC59B96681F384F3FF4513240EDDBF
23:07:01.856 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 204 No Content: GET - /facades/my-facade/taler-wire-gateway/history/outgoing
2023-04-25T23:07:01.856544+0200 test-bank-api-50863 INFO Running command `credit-2'
2023-04-25T23:07:01.856672+0200 test-bank-api-50863 INFO Requesting administrative transaction at `http://localhost:5001/facades/my-facade/taler-wire-gateway/admin/add-incoming' for reserve AD1EQXG3
23:07:01.865 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - inserting order signature for orderID OR01, order type CCT, transaction 'C91DB68CA20EF73CBD6C2B1E4BDBF227'
23:07:01.888 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb
23:07:01.890 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - TWG add-incoming passed authentication
23:07:01.894 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - TWG add-incoming about to wire transfer
23:07:01.894 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Maybe wire transfer: fortytwo -> exchange, 7X0T0HHKXFH2BYARJMXR1DWMF33KGNE5K86315GFR7JDVKHF70MG, KUDOS:3.21
23:07:01.901 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - TWG add-incoming has wire transferred
23:07:01.906 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /demobanks/default/taler-wire-gateway/exchange/admin/add-incoming
23:07:01.913 [DefaultDispatcher-worker-5] DEBUG tech.libeufin.util - Bank acknowledges EBICS upload initialization. Transaction ID: C91DB68CA20EF73CBD6C2B1E4BDBF227.
23:07:01.915 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Created EBICS C52 document for download initialization, nonce: 127EF8C05294D1953E53BE61DFF599AE
23:07:01.955 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download initialization for order type C52, nonce: 127EF8C05294D1953E53BE61DFF599AE, transaction ID: FCF876D94C02C8E069157DD97BC17AC5
23:07:01.962 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - camt.052 document 'sandbox-1682456821-RDGG6NVXQX' generated. It includes the payments:
- 7X0T0HHKXFH2BYARJMXR1DWMF33KGNE5K86315GFR7JDVKHF70MG
23:07:01.988 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb
23:07:02.007 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Bank acknowledges EBICS download initialization. Transaction ID: FCF876D94C02C8E069157DD97BC17AC5.
23:07:02.014 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling Pain.001: leuf-p-187ba3db09d-1-1, for payment: Taler refund of: PQBTRXMCW5MYZSRCCJEYR3F6NKTN92VMP22EAPBG8CJB7BTXBZP0
23:07:02.035 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb
23:07:02.047 [DefaultDispatcher-worker-12] DEBUG tech.libeufin.util - Bank acknowledges EBICS upload transfer. Transaction ID: C91DB68CA20EF73CBD6C2B1E4BDBF227
23:07:02.050 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download receipt for EBICS transaction: FCF876D94C02C8E069157DD97BC17AC5
23:07:02.062 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb
23:07:02.074 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Bank acknowledges EBICS download receipt. Transaction ID: FCF876D94C02C8E069157DD97BC17AC5.
23:07:02.075 [eventLoopGroupProxy-4-1] INFO tech.libeufin.nexus - Camt document 'sandbox-1682456821-RDGG6NVXQX' received via C52.
23:07:02.093 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Camt C52 'sandbox-1682456821-RDGG6NVXQX' has new payments:
- 7X0T0HHKXFH2BYARJMXR1DWMF33KGNE5K86315GFR7JDVKHF70MG
23:07:02.095 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Ingesting transactions for TALER facade 1, and bank account: my-bank-account
23:07:02.107 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Searching refundable payments of account: my-bank-account, after last seen transaction id: 2
23:07:02.111 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /facades/my-facade/taler-wire-gateway/admin/add-incoming
2023-04-25T23:07:02.112085+0200 test-bank-api-50863 INFO Running command `debit-1'
2023-04-25T23:07:02.112131+0200 test-bank-api-50863 INFO Transfer of KUDOS:3.22 from http://localhost:5001/facades/my-facade/taler-wire-gateway/ to payto://iban/SANDBOXX/FR7630006000011234567890189?receiver-name=User42
23:07:02.124 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Taler requests payment: 58N2MAHA58N2MAHA58N2MAHA58N2MAHA58N2MAHA58N2MAHA58N0
23:07:02.131 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /facades/my-facade/taler-wire-gateway/transfer
2023-04-25T23:07:02.131662+0200 test-bank-api-50863 INFO Running command `Waiting 5s for 'debit-1' to settle'
23:07:07.055 [DefaultDispatcher-worker-12] INFO tech.libeufin.nexus - Scheduling task exchange-payments at Optional[2023-04-25T23:07:08.054370819+02:00[Europe/Zurich]] (now is 2023-04-25T23:07:07.054370819+02:00[Europe/Zurich]).
23:07:07.057 [DefaultDispatcher-worker-12] INFO tech.libeufin.nexus - running task TaskSchedule(taskId=2, name=exchange-history, type=fetch, resourceType=bank-account, resourceId=my-bank-account, params={
"rangeType" : "latest",
"level" : "report"
})
23:07:07.069 [DefaultDispatcher-worker-12] DEBUG tech.libeufin.util - Created EBICS C52 document for download initialization, nonce: 3168257422084D9B026F52AF16F304E1
23:07:07.104 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download initialization for order type C52, nonce: 3168257422084D9B026F52AF16F304E1, transaction ID: 0D157FF99B943175A1F4690732733EF3
23:07:07.109 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - camt.052 document 'sandbox-1682456827-0HWTTCORBL' generated. It includes the payments:
- Taler refund of: PQBTRXMCW5MYZSRCCJEYR3F6NKTN92VMP22EAPBG8CJB7BTXBZP0
23:07:07.128 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb
2023-04-25T23:07:07.131801+0200 test-bank-api-50863 INFO Running command `fetch-transactions-at-nexus'
--2023-04-25 23:07:07-- http://localhost:5001/bank-accounts/my-bank-account/fetch-transactions
Resolving localhost (localhost)... ::1, 127.0.0.1
Connecting to localhost (localhost)|::1|:5001... connected.
HTTP request sent, awaiting response... 23:07:07.145 [DefaultDispatcher-worker-11] DEBUG tech.libeufin.util - Bank acknowledges EBICS download initialization. Transaction ID: 0D157FF99B943175A1F4690732733EF3.
23:07:07.149 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Created EBICS C52 document for download initialization, nonce: 4BD12C08DF474879EBBFDA468A9D25FB
23:07:07.189 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download initialization for order type C52, nonce: 4BD12C08DF474879EBBFDA468A9D25FB, transaction ID: 535F6E4C94EC650B346041069DAD42C4
23:07:07.211 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb
23:07:07.229 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - EBICS had no new data
23:07:07.231 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.util - Created EBICS C53 document for download initialization, nonce: 9855326D421B1F1C06EF4A2A3DE42B81
23:07:07.240 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download receipt for EBICS transaction: 0D157FF99B943175A1F4690732733EF3
23:07:07.256 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb
23:07:07.268 [DefaultDispatcher-worker-11] DEBUG tech.libeufin.util - Bank acknowledges EBICS download receipt. Transaction ID: 0D157FF99B943175A1F4690732733EF3.
23:07:07.270 [DefaultDispatcher-worker-11] INFO tech.libeufin.nexus - Camt document 'sandbox-1682456827-0HWTTCORBL' received via C52.
23:07:07.274 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling download initialization for order type C53, nonce: 9855326D421B1F1C06EF4A2A3DE42B81, transaction ID: BDE424A6BC400F434D5FD26DA1808878
23:07:07.275 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Serving C53 without date range.
23:07:07.287 [DefaultDispatcher-worker-11] INFO tech.libeufin.nexus - Could confirm one initiated payment: leuf-p-187ba3db09d-1-1
23:07:07.287 [DefaultDispatcher-worker-11] DEBUG tech.libeufin.nexus - Camt C52 'sandbox-1682456827-0HWTTCORBL' has new payments:
- Taler refund of: PQBTRXMCW5MYZSRCCJEYR3F6NKTN92VMP22EAPBG8CJB7BTXBZP0
23:07:07.288 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb
23:07:07.289 [DefaultDispatcher-worker-11] DEBUG tech.libeufin.nexus - Ingesting transactions for TALER facade 1, and bank account: my-bank-account
23:07:07.302 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - EBICS had no new data
23:07:07.304 [DefaultDispatcher-worker-11] DEBUG tech.libeufin.nexus - Searching refundable payments of account: my-bank-account, after last seen transaction id: 3
23:07:07.305 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Ingesting transactions for TALER facade 1, and bank account: my-bank-account
23:07:07.314 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Searching refundable payments of account: my-bank-account, after last seen transaction id: 3
23:07:07.316 [eventLoopGroupProxy-4-1] WARN Exposed - Transaction attempt #0 failed: org.sqlite.SQLiteException: [SQLITE_BUSY] The database file is locked (database is locked). Statement(s): UPDATE FacadeState SET highestSeenMessageSerialId=? WHERE id = ?
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.dao.EntityBatchUpdate.execute(EntityBatchUpdate.kt:33)
at org.jetbrains.exposed.dao.EntityCache$updateEntities$1$2.invoke(EntityCache.kt:63)
at org.jetbrains.exposed.dao.EntityCache$updateEntities$1$2.invoke(EntityCache.kt:62)
at org.jetbrains.exposed.dao.EntityLifecycleInterceptorKt.executeAsPartOfEntityLifecycle(EntityLifecycleInterceptor.kt:17)
at org.jetbrains.exposed.dao.EntityCache.updateEntities(EntityCache.kt:62)
at org.jetbrains.exposed.dao.EntityCache.flush(EntityCache.kt:85)
at org.jetbrains.exposed.dao.EntityCache.flush(EntityCache.kt:48)
at org.jetbrains.exposed.dao.EntityCacheKt.flushCache(EntityCache.kt:166)
at tech.libeufin.nexus.FacadeUtilKt$ingestFacadeTransactions$1.invoke(FacadeUtil.kt:119)
at tech.libeufin.nexus.FacadeUtilKt$ingestFacadeTransactions$1.invoke(FacadeUtil.kt:114)
at org.jetbrains.exposed.sql.transactions.ThreadLocalTransactionManagerKt.inTopLevelTransaction$run(ThreadLocalTransactionManager.kt:173)
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.FacadeUtilKt.ingestFacadeTransactions(FacadeUtil.kt:114)
at tech.libeufin.nexus.FacadeUtilKt.ingestFacadeTransactions$default(FacadeUtil.kt:53)
at tech.libeufin.nexus.bankaccount.BankAccountKt.fetchBankAccountTransactions(BankAccount.kt:422)
at tech.libeufin.nexus.bankaccount.BankAccountKt$fetchBankAccountTransactions$1.invokeSuspend(BankAccount.kt)
at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
at kotlinx.coroutines.EventLoop.processUnconfinedEvent(EventLoop.common.kt:69)
at kotlinx.coroutines.internal.DispatchedContinuation.resumeWith(DispatchedContinuation.kt:355)
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.execute(DB.java:863)
at org.sqlite.core.DB.executeUpdate(DB.java:904)
at org.sqlite.jdbc3.JDBC3PreparedStatement.executeUpdate(JDBC3PreparedStatement.java:98)
at org.jetbrains.exposed.sql.statements.jdbc.JdbcPreparedStatementImpl.executeUpdate(JdbcPreparedStatementImpl.kt:26)
at org.jetbrains.exposed.sql.statements.BatchUpdateStatement.executeInternal(BatchUpdateStatement.kt:41)
at org.jetbrains.exposed.sql.statements.BatchUpdateStatement.executeInternal(BatchUpdateStatement.kt:12)
at org.jetbrains.exposed.sql.statements.Statement.executeIn$exposed_core(Statement.kt:60)
... 45 common frames omitted
23:07:07.328 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Ingesting transactions for TALER facade 1, and bank account: my-bank-account
23:07:07.329 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - Searching refundable payments of account: my-bank-account, after last seen transaction id: 4
23:07:07.337 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 200 OK: POST - /bank-accounts/my-bank-account/fetch-transactions
200 OK
Length: unspecified [application/json]
Saving to: ‘fetch-transactions.1’
0K 11.4M=0s
2023-04-25 23:07:07 (11.4 MB/s) - ‘fetch-transactions.1’ saved [78]
2023-04-25T23:07:07.338542+0200 test-bank-api-50863 INFO Got SIGCHLD for `fetch-transactions-at-nexus'.
2023-04-25T23:07:07.338597+0200 test-bank-api-50863 INFO Running command `history-2b'
2023-04-25T23:07:07.338608+0200 test-bank-api-50863 INFO Checking commands 0 to 10 for debit history
2023-04-25T23:07:07.338614+0200 test-bank-api-50863 INFO Checking if command history-0 is relevant for debit history
2023-04-25T23:07:07.338618+0200 test-bank-api-50863 INFO Checking if command credit-1 is relevant for debit history
2023-04-25T23:07:07.338626+0200 test-bank-api-50863 INFO Trait wtid/0 not found.
2023-04-25T23:07:07.338631+0200 test-bank-api-50863 INFO Checking if command credit-1-fail is relevant for debit history
2023-04-25T23:07:07.338636+0200 test-bank-api-50863 INFO Checking if command Waiting 4s for 'credit-1' to settle is relevant for debit history
2023-04-25T23:07:07.338640+0200 test-bank-api-50863 INFO Checking if command history-1c is relevant for debit history
2023-04-25T23:07:07.338644+0200 test-bank-api-50863 INFO Checking if command history-1d is relevant for debit history
2023-04-25T23:07:07.338648+0200 test-bank-api-50863 INFO Checking if command credit-2 is relevant for debit history
2023-04-25T23:07:07.338653+0200 test-bank-api-50863 INFO Trait wtid/0 not found.
2023-04-25T23:07:07.338657+0200 test-bank-api-50863 INFO Checking if command debit-1 is relevant for debit history
2023-04-25T23:07:07.338664+0200 test-bank-api-50863 INFO Command debit-1 is relevant for debit history!
2023-04-25T23:07:07.338670+0200 test-bank-api-50863 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-25T23:07:07.338675+0200 test-bank-api-50863 INFO Checking if command Waiting 5s for 'debit-1' to settle is relevant for debit history
2023-04-25T23:07:07.338679+0200 test-bank-api-50863 INFO Checking if command fetch-transactions-at-nexus is relevant for debit history
2023-04-25T23:07:07.338683+0200 test-bank-api-50863 INFO Trait bank_row/0 not found.
2023-04-25T23:07:07.338694+0200 test-bank-api-50863 INFO Requesting debit history at `http://localhost:5001/facades/my-facade/taler-wire-gateway/history/outgoing?delta=5'
23:07:07.342 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.nexus - 204 No Content: GET - /facades/my-facade/taler-wire-gateway/history/outgoing
2023-04-25T23:07:07.343120+0200 test-bank-api-50863 ERROR Assertion failed at testing_api_cmd_bank_history_debit.c:413.
2023-04-25T23:07:07.343172+0200 test-bank-api-50863 ERROR Expected history of length 1, got 0; HTTP status code: 204/0, failed: 0
2023-04-25T23:07:07.343178+0200 test-bank-api-50863 ERROR Transaction history (debit) mismatch at position 4294967295/1
2023-04-25T23:07:07.343197+0200 test-bank-api-50863 ERROR Expected history:
2023-04-25T23:07:07.343222+0200 test-bank-api-50863 ERROR H(0): KUDOS:3.22 (serial: 1, subject: Y852C4XX, counterpart: payto://iban/SANDBOXX/FR7630006000011234567890189?receiver-name=User42)
2023-04-25T23:07:07.343229+0200 test-bank-api-50863 ERROR Failed at command `history-2b'
2023-04-25T23:07:07.343250+0200 test-bank-api-50863 INFO Executing shutdown at `history-2b'
|
|
|
Florian figured it out. Additional feature bugs filed, but for now the test again passes (together with MS change from 5s to 1s for scheduler loop frequency). |
|
|
The high-level point was that fetch-transactions is not enough, as first the transaction from nexus to sandbox has to go through, not only from sandbox to nexus. With a scheduler loop running only every 5s, the 5s sleep was no longer enough, even with the force-fetch. With 1s frequency, a 5s wait is plenty. |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2023-04-22 15:34 | Christian Grothoff | New Issue | |
| 2023-04-22 15:34 | Christian Grothoff | Status | new => assigned |
| 2023-04-22 15:34 | Christian Grothoff | Assigned To | => MS |
| 2023-04-24 14:49 | MS | Status | assigned => feedback |
| 2023-04-24 14:49 | MS | Note Added: 0020141 | |
| 2023-04-24 14:49 | MS | Assigned To | MS => Christian Grothoff |
| 2023-04-24 20:25 | Christian Grothoff | Note Added: 0020146 | |
| 2023-04-24 20:25 | Christian Grothoff | File Added: test_bank_api_with_nexus.log | |
| 2023-04-24 21:23 | Christian Grothoff | Assigned To | Christian Grothoff => MS |
| 2023-04-25 12:59 | MS | Note Added: 0020153 | |
| 2023-04-25 13:02 | MS | Note Edited: 0020153 | |
| 2023-04-25 13:12 | MS | Assigned To | MS => Christian Grothoff |
| 2023-04-25 23:07 | Christian Grothoff | Note Added: 0020156 | |
| 2023-04-25 23:07 | Christian Grothoff | File Added: new-log.txt | |
| 2023-04-25 23:07 | Christian Grothoff | Assigned To | Christian Grothoff => MS |
| 2023-04-26 00:22 | Christian Grothoff | Assigned To | MS => Florian Dold |
| 2023-04-26 00:22 | Christian Grothoff | Status | feedback => resolved |
| 2023-04-26 00:22 | Christian Grothoff | Resolution | open => fixed |
| 2023-04-26 00:22 | Christian Grothoff | Fixed in Version | => 0.9.3 |
| 2023-04-26 00:22 | Christian Grothoff | Note Added: 0020159 | |
| 2023-04-26 00:23 | Christian Grothoff | Note Added: 0020160 | |
| 2023-09-23 15:09 | Christian Grothoff | Status | resolved => closed |
