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'