0007899: libeufin longpolling does not work (never returns early)

ID	Project	Category	View Status	Date Submitted	Last Update
0007899	Taler	libeufin-nexus	public	2023-08-02 22:13	2023-11-29 00:30

Reporter	Windfisch	Assigned To	Antoine A	Resolution deadline
Implementer		Reviewer
Release signed by		Deployed by
Verifier		Communicator
Data protection authority notification required	No
CSIRT notification required	No
Estimated effort (hours)		Actual effort (hours)	0
Fast-track	No
Work package	none
Priority	normal	Severity	minor	Reproducibility	always
Status	closed	Resolution	duplicate
Product Version	0.9.2
Target Version	0.9.3	Fixed in Version	0.9.3

Summary	0007899: libeufin longpolling does not work (never returns early)
Description	Hi, i just stumbled about a problem that causes delays of up to a minute when withdrawing money into the wallet: The long-polling support in libeufin-nexus does not work: It does not return early on change, but always waits for the full waittime. The symptoms look like this: in taler-exchange-wirewatch logs, I see lines like these: 2023-08-02T21:42:25.732836+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1012&start=12&long_poll_ms=60000' 2023-08-02T21:43:25.793958+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1012&start=12&long_poll_ms=60000' 2023-08-02T21:44:25.907327+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1011&start=13&long_poll_ms=60000' 2023-08-02T21:44:25.950741+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1010&start=14&long_poll_ms=60000' 2023-08-02T21:45:26.020468+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1010&start=14&long_poll_ms=60000' You can see that the minute is steadily increasing, but the seconds part always stays the same, despite me doing transactions at random points in time. Setting the -f, --longpoll-timeout=DELAY option on taler-exchange-wirewatch to 1 second improves the delay, so i suspect this is a problem in nexus (or maybe the libeufin demobank behind) The long-polling in taler-exchange-http appears fine, see logs below.
Steps To Reproduce	Run the setup at https://github.com/Windfisch/taler-podman, but remove the --longpoll-timeout option in taler-exchange-insecure/entrypoint.sh. (This will be online as of 2023-08-03 17:00 CEST, haven't pushed it yet) Make a couple of withdrawals and note how takes up to a minute for the coins to arrive in the wallet. Note how it's always the same second they arrive.
Tags	No tags attached.

Windfisch

2023-08-02 22:14

reporter ~0020399

logs

libeufin-nexus.txt (4,700 bytes)

21:44:25.737 [DefaultDispatcher-worker-3] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=2, name=fetch-reports-each-second, type=fetch, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : "latest",
  "level" : "report"
})
21:44:25.946 [DefaultDispatcher-worker-10] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=1, name=submit-payments-each-second, type=submit, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : null,
  "level" : null
})
21:44:27.012 [DefaultDispatcher-worker-10] INFO  tech.libeufin.nexus - scheduling task fetch-reports-each-second at Optional[2023-08-02T21:44:28.012176139Z[Etc/UTC]] (now is 2023-08-02T21:44:27.012176139Z[Etc/UTC])
21:44:27.012 [DefaultDispatcher-worker-10] INFO  tech.libeufin.nexus - scheduling task submit-payments-each-second at Optional[2023-08-02T21:44:28.012428766Z[Etc/UTC]] (now is 2023-08-02T21:44:27.012428766Z[Etc/UTC])
21:44:28.093 [DefaultDispatcher-worker-10] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=2, name=fetch-reports-each-second, type=fetch, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : "latest",
  "level" : "report"
})
21:44:28.359 [DefaultDispatcher-worker-6] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=1, name=submit-payments-each-second, type=submit, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : null,
  "level" : null
})
21:44:29.424 [DefaultDispatcher-worker-6] INFO  tech.libeufin.nexus - scheduling task fetch-reports-each-second at Optional[2023-08-02T21:44:30.424165117Z[Etc/UTC]] (now is 2023-08-02T21:44:29.424165117Z[Etc/UTC])
21:44:29.425 [DefaultDispatcher-worker-6] INFO  tech.libeufin.nexus - scheduling task submit-payments-each-second at Optional[2023-08-02T21:44:30.424447257Z[Etc/UTC]] (now is 2023-08-02T21:44:29.424447257Z[Etc/UTC])
21:44:30.497 [DefaultDispatcher-worker-6] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=1, name=submit-payments-each-second, type=submit, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : null,
  "level" : null
})
21:44:30.537 [DefaultDispatcher-worker-6] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=2, name=fetch-reports-each-second, type=fetch, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : "latest",
  "level" : "report"
})
21:44:31.761 [DefaultDispatcher-worker-6] INFO  tech.libeufin.nexus - scheduling task submit-payments-each-second at Optional[2023-08-02T21:44:32.761700664Z[Etc/UTC]] (now is 2023-08-02T21:44:31.761700664Z[Etc/UTC])
21:44:31.762 [DefaultDispatcher-worker-6] INFO  tech.libeufin.nexus - scheduling task fetch-reports-each-second at Optional[2023-08-02T21:44:32.762048460Z[Etc/UTC]] (now is 2023-08-02T21:44:31.762048460Z[Etc/UTC])
21:44:32.841 [DefaultDispatcher-worker-6] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=1, name=submit-payments-each-second, type=submit, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : null,
  "level" : null
})
21:44:32.891 [DefaultDispatcher-worker-6] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=2, name=fetch-reports-each-second, type=fetch, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : "latest",
  "level" : "report"
})
21:44:34.168 [DefaultDispatcher-worker-2] INFO  tech.libeufin.nexus - scheduling task submit-payments-each-second at Optional[2023-08-02T21:44:35.168031221Z[Etc/UTC]] (now is 2023-08-02T21:44:34.168031221Z[Etc/UTC])
21:44:34.169 [DefaultDispatcher-worker-2] INFO  tech.libeufin.nexus - scheduling task fetch-reports-each-second at Optional[2023-08-02T21:44:35.168324376Z[Etc/UTC]] (now is 2023-08-02T21:44:34.168324376Z[Etc/UTC])
21:44:35.233 [DefaultDispatcher-worker-2] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=1, name=submit-payments-each-second, type=submit, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : null,
  "level" : null
})
21:44:35.265 [DefaultDispatcher-worker-2] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=2, name=fetch-reports-each-second, type=fetch, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : "latest",
  "level" : "report"
})
21:44:36.527 [DefaultDispatcher-worker-4] INFO  tech.libeufin.nexus - scheduling task submit-payments-each-second at Optional[2023-08-02T21:44:37.527204653Z[Etc/UTC]] (now is 2023-08-02T21:44:36.527204653Z[Etc/UTC])
21:44:36.527 [DefaultDispatcher-worker-4] INFO  tech.libeufin.nexus - scheduling task fetch-reports-each-second at Optional[2023-08-02T21:44:37.527434202Z[Etc/UTC]] (now is 2023-08-02T21:44:36.527434202Z[Etc/UTC])

libeufin-nexus.txt (4,700 bytes)

libeufin-sandbox.txt (4,700 bytes)

21:44:25.737 [DefaultDispatcher-worker-3] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=2, name=fetch-reports-each-second, type=fetch, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : "latest",
  "level" : "report"
})
21:44:25.946 [DefaultDispatcher-worker-10] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=1, name=submit-payments-each-second, type=submit, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : null,
  "level" : null
})
21:44:27.012 [DefaultDispatcher-worker-10] INFO  tech.libeufin.nexus - scheduling task fetch-reports-each-second at Optional[2023-08-02T21:44:28.012176139Z[Etc/UTC]] (now is 2023-08-02T21:44:27.012176139Z[Etc/UTC])
21:44:27.012 [DefaultDispatcher-worker-10] INFO  tech.libeufin.nexus - scheduling task submit-payments-each-second at Optional[2023-08-02T21:44:28.012428766Z[Etc/UTC]] (now is 2023-08-02T21:44:27.012428766Z[Etc/UTC])
21:44:28.093 [DefaultDispatcher-worker-10] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=2, name=fetch-reports-each-second, type=fetch, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : "latest",
  "level" : "report"
})
21:44:28.359 [DefaultDispatcher-worker-6] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=1, name=submit-payments-each-second, type=submit, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : null,
  "level" : null
})
21:44:29.424 [DefaultDispatcher-worker-6] INFO  tech.libeufin.nexus - scheduling task fetch-reports-each-second at Optional[2023-08-02T21:44:30.424165117Z[Etc/UTC]] (now is 2023-08-02T21:44:29.424165117Z[Etc/UTC])
21:44:29.425 [DefaultDispatcher-worker-6] INFO  tech.libeufin.nexus - scheduling task submit-payments-each-second at Optional[2023-08-02T21:44:30.424447257Z[Etc/UTC]] (now is 2023-08-02T21:44:29.424447257Z[Etc/UTC])
21:44:30.497 [DefaultDispatcher-worker-6] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=1, name=submit-payments-each-second, type=submit, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : null,
  "level" : null
})
21:44:30.537 [DefaultDispatcher-worker-6] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=2, name=fetch-reports-each-second, type=fetch, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : "latest",
  "level" : "report"
})
21:44:31.761 [DefaultDispatcher-worker-6] INFO  tech.libeufin.nexus - scheduling task submit-payments-each-second at Optional[2023-08-02T21:44:32.761700664Z[Etc/UTC]] (now is 2023-08-02T21:44:31.761700664Z[Etc/UTC])
21:44:31.762 [DefaultDispatcher-worker-6] INFO  tech.libeufin.nexus - scheduling task fetch-reports-each-second at Optional[2023-08-02T21:44:32.762048460Z[Etc/UTC]] (now is 2023-08-02T21:44:31.762048460Z[Etc/UTC])
21:44:32.841 [DefaultDispatcher-worker-6] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=1, name=submit-payments-each-second, type=submit, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : null,
  "level" : null
})
21:44:32.891 [DefaultDispatcher-worker-6] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=2, name=fetch-reports-each-second, type=fetch, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : "latest",
  "level" : "report"
})
21:44:34.168 [DefaultDispatcher-worker-2] INFO  tech.libeufin.nexus - scheduling task submit-payments-each-second at Optional[2023-08-02T21:44:35.168031221Z[Etc/UTC]] (now is 2023-08-02T21:44:34.168031221Z[Etc/UTC])
21:44:34.169 [DefaultDispatcher-worker-2] INFO  tech.libeufin.nexus - scheduling task fetch-reports-each-second at Optional[2023-08-02T21:44:35.168324376Z[Etc/UTC]] (now is 2023-08-02T21:44:34.168324376Z[Etc/UTC])
21:44:35.233 [DefaultDispatcher-worker-2] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=1, name=submit-payments-each-second, type=submit, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : null,
  "level" : null
})
21:44:35.265 [DefaultDispatcher-worker-2] INFO  tech.libeufin.nexus - running task TaskSchedule(taskId=2, name=fetch-reports-each-second, type=fetch, resourceType=bank-account, resourceId=nickname, params={
  "rangeType" : "latest",
  "level" : "report"
})
21:44:36.527 [DefaultDispatcher-worker-4] INFO  tech.libeufin.nexus - scheduling task submit-payments-each-second at Optional[2023-08-02T21:44:37.527204653Z[Etc/UTC]] (now is 2023-08-02T21:44:36.527204653Z[Etc/UTC])
21:44:36.527 [DefaultDispatcher-worker-4] INFO  tech.libeufin.nexus - scheduling task fetch-reports-each-second at Optional[2023-08-02T21:44:37.527434202Z[Etc/UTC]] (now is 2023-08-02T21:44:36.527434202Z[Etc/UTC])

libeufin-sandbox.txt (4,700 bytes)

taler-exchange-httpd.txt (4,850 bytes)

2023-08-02T21:46:43.439596+0000 taler-exchange-httpd-959(9MQ8D5D6VMC37BF6N388N2SM3R) INFO Handling new request
2023-08-02T21:46:43.440308+0000 taler-exchange-httpd-959(FAXQ5YAH16D16ATSDQCSJACGE4) INFO Handling request (GET) for URL '/reserves/6CX9R6PDHRHQWXN2JR1EJ94DSJKWFT82FVD26M3P5W4J0D1CHTK0'
2023-08-02T21:46:43.440480+0000 taler-exchange-httpd-959(FAXQ5YAH16D16ATSDQCSJACGE4) INFO Starting DB event listening
2023-08-02T21:46:43.440696+0000 taler-exchange-httpd-959(FAXQ5YAH16D16ATSDQCSJACGE4) INFO Executing PQ command `LISTEN XYEVZHEMF1XP8ZZSEY3ET4BK8HMT4MGY63XJZFJT0SWS4D4HMRJYG'
2023-08-02T21:46:43.441632+0000 taler-exchange-httpd-959(FAXQ5YAH16D16ATSDQCSJACGE4) INFO Starting transaction `get reserve balance'
2023-08-02T21:46:43.443480+0000 taler-exchange-httpd-959(FAXQ5YAH16D16ATSDQCSJACGE4) INFO Long-polling on reserve for 30 s
2023-08-02T21:47:13.471933+0000 taler-exchange-httpd-959(FAXQ5YAH16D16ATSDQCSJACGE4) INFO Resuming from long-polling on reserve
2023-08-02T21:47:13.472587+0000 taler-exchange-httpd-959(FAXQ5YAH16D16ATSDQCSJACGE4) INFO Handling request (GET) for URL '/reserves/6CX9R6PDHRHQWXN2JR1EJ94DSJKWFT82FVD26M3P5W4J0D1CHTK0'
2023-08-02T21:47:13.472929+0000 taler-exchange-httpd-959(FAXQ5YAH16D16ATSDQCSJACGE4) INFO Starting transaction `get reserve balance'
2023-08-02T21:47:13.477313+0000 taler-exchange-httpd-959(FAXQ5YAH16D16ATSDQCSJACGE4) INFO Cancelling DB event listening
2023-08-02T21:47:13.479171+0000 taler-exchange-httpd-959(FAXQ5YAH16D16ATSDQCSJACGE4) INFO Executing PQ command `UNLISTEN XYEVZHEMF1XP8ZZSEY3ET4BK8HMT4MGY63XJZFJT0SWS4D4HMRJYG'
2023-08-02T21:47:13.481342+0000 taler-exchange-httpd-959(FAXQ5YAH16D16ATSDQCSJACGE4) INFO Request for `/reserves/6CX9R6PDHRHQWXN2JR1EJ94DSJKWFT82FVD26M3P5W4J0D1CHTK0' completed with HTTP status 404 (0)
2023-08-02T21:47:13.481464+0000 taler-exchange-httpd-959(FAXQ5YAH16D16ATSDQCSJACGE4) INFO Request for `/reserves/6CX9R6PDHRHQWXN2JR1EJ94DSJKWFT82FVD26M3P5W4J0D1CHTK0' took 30 s
2023-08-02T21:47:17.194462+0000 taler-exchange-httpd-959(FAXQ5YAH16D16ATSDQCSJACGE4) INFO Handling new request
2023-08-02T21:47:17.194958+0000 taler-exchange-httpd-959(G01RVDKMTYH25V490H0QV0FXNR) INFO Handling request (GET) for URL '/reserves/6CX9R6PDHRHQWXN2JR1EJ94DSJKWFT82FVD26M3P5W4J0D1CHTK0'
2023-08-02T21:47:17.195398+0000 taler-exchange-httpd-959(G01RVDKMTYH25V490H0QV0FXNR) INFO Starting DB event listening
2023-08-02T21:47:17.195549+0000 taler-exchange-httpd-959(G01RVDKMTYH25V490H0QV0FXNR) INFO Executing PQ command `LISTEN XYEVZHEMF1XP8ZZSEY3ET4BK8HMT4MGY63XJZFJT0SWS4D4HMRJYG'
2023-08-02T21:47:17.196464+0000 taler-exchange-httpd-959(G01RVDKMTYH25V490H0QV0FXNR) INFO Starting transaction `get reserve balance'
2023-08-02T21:47:17.197858+0000 taler-exchange-httpd-959(G01RVDKMTYH25V490H0QV0FXNR) INFO Long-polling on reserve for 30 s
2023-08-02T21:47:26.236664+0000 taler-exchange-httpd-959 INFO PG poll job active
2023-08-02T21:47:26.236759+0000 taler-exchange-httpd-959 INFO Received notification xyevzhemf1xp8zzsey3et4bk8hmt4mgy63xjzfjt0sws4d4hmrjyg with extra data `'
2023-08-02T21:47:26.236813+0000 taler-exchange-httpd-959(G01RVDKMTYH25V490H0QV0FXNR) INFO Resuming from long-polling on reserve
2023-08-02T21:47:26.236923+0000 taler-exchange-httpd-959(G01RVDKMTYH25V490H0QV0FXNR) INFO Handling request (GET) for URL '/reserves/6CX9R6PDHRHQWXN2JR1EJ94DSJKWFT82FVD26M3P5W4J0D1CHTK0'
2023-08-02T21:47:26.236986+0000 taler-exchange-httpd-959(G01RVDKMTYH25V490H0QV0FXNR) INFO Starting transaction `get reserve balance'
2023-08-02T21:47:26.238027+0000 taler-exchange-httpd-959 INFO PG poll job finishes after 1 events
2023-08-02T21:47:26.238055+0000 taler-exchange-httpd-959 INFO Resubscribing
2023-08-02T21:47:26.238291+0000 taler-exchange-httpd-959(G01RVDKMTYH25V490H0QV0FXNR) INFO Cancelling DB event listening
2023-08-02T21:47:26.238324+0000 taler-exchange-httpd-959(G01RVDKMTYH25V490H0QV0FXNR) INFO Executing PQ command `UNLISTEN XYEVZHEMF1XP8ZZSEY3ET4BK8HMT4MGY63XJZFJT0SWS4D4HMRJYG'
2023-08-02T21:47:26.238905+0000 taler-exchange-httpd-959(G01RVDKMTYH25V490H0QV0FXNR) INFO Request for `/reserves/6CX9R6PDHRHQWXN2JR1EJ94DSJKWFT82FVD26M3P5W4J0D1CHTK0' completed with HTTP status 200 (0)
2023-08-02T21:47:26.238943+0000 taler-exchange-httpd-959(G01RVDKMTYH25V490H0QV0FXNR) INFO Request for `/reserves/6CX9R6PDHRHQWXN2JR1EJ94DSJKWFT82FVD26M3P5W4J0D1CHTK0' took 9 s
2023-08-02T21:47:27.382164+0000 taler-exchange-httpd-959(G01RVDKMTYH25V490H0QV0FXNR) INFO Handling new request
2023-08-02T21:47:27.382387+0000 taler-exchange-httpd-959(2Y1B0V66XK6KTJ1VT994W7QD8W) INFO Handling request (POST) for URL '/reserves/6CX9R6PDHRHQWXN2JR1EJ94DSJKWFT82FVD26M3P5W4J0D1CHTK0/withdraw'
2023-08-02T21:47:27.382438+0000 taler-exchange-httpd-959(2Y1B0V66XK6KTJ1VT994W7QD8W) INFO Handling request (POST) for URL '/reserves/6CX9R6PDHRHQWXN2JR1EJ94DSJKWFT82FVD26M3P5W4J0D1CHTK0/withdraw'

taler-exchange-httpd.txt (4,850 bytes)

taler-exchange-wirewatch.txt (16,388 bytes)

2023-08-02T21:41:25.411672+0000 taler-exchange-wirewatch-958 INFO Change in PQ event FD to -1
2023-08-02T21:41:25.411755+0000 taler-exchange-wirewatch-958 INFO New poll FD is -1
2023-08-02T21:41:25.484136+0000 taler-exchange-wirewatch-958 INFO Change in PQ event FD to 5
2023-08-02T21:41:25.484177+0000 taler-exchange-wirewatch-958 INFO New poll FD is 5
2023-08-02T21:41:25.484356+0000 taler-exchange-wirewatch-958 INFO Will try to lock next shard of wirewatch-exchange-account-1 in 0 ms
2023-08-02T21:41:25.484404+0000 taler-exchange-wirewatch-958 INFO Starting transaction `begin_shard'
2023-08-02T21:41:25.491340+0000 taler-exchange-wirewatch-958 INFO Claimed new shard
2023-08-02T21:41:25.491396+0000 taler-exchange-wirewatch-958 INFO Starting with shard wirewatch-exchange-account-1 at (0,1024] locked for 3145 ms
2023-08-02T21:41:25.491409+0000 taler-exchange-wirewatch-958 INFO Resetting shard start to original start point (0)
2023-08-02T21:41:25.491429+0000 taler-exchange-wirewatch-958 INFO Requesting credit history staring from 0
2023-08-02T21:41:25.491466+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1024&long_poll_ms=60000'
2023-08-02T21:41:25.647060+0000 taler-exchange-wirewatch-958 INFO History request returned with HTTP status 200
2023-08-02T21:41:25.647113+0000 taler-exchange-wirewatch-958 INFO Importing 12 transactions
2023-08-02T21:41:25.647152+0000 taler-exchange-wirewatch-958 INFO Starting READ COMMITTED transaction `READ_COMMITED`
2023-08-02T21:41:25.660262+0000 taler-exchange-wirewatch-958 INFO Starting transaction `reserve-insert-continued'
2023-08-02T21:41:25.665029+0000 taler-exchange-wirewatch-958 INFO Attempted to import transaction 1 (wirewatch-exchange-account-1) twice. This should happen rarely (if not, ask for support).
2023-08-02T21:41:25.665083+0000 taler-exchange-wirewatch-958 INFO Attempted to import transaction 2 (wirewatch-exchange-account-1) twice. This should happen rarely (if not, ask for support).
2023-08-02T21:41:25.665110+0000 taler-exchange-wirewatch-958 INFO Attempted to import transaction 3 (wirewatch-exchange-account-1) twice. This should happen rarely (if not, ask for support).
2023-08-02T21:41:25.665257+0000 taler-exchange-wirewatch-958 INFO Attempted to import transaction 4 (wirewatch-exchange-account-1) twice. This should happen rarely (if not, ask for support).
2023-08-02T21:41:25.665276+0000 taler-exchange-wirewatch-958 INFO Attempted to import transaction 5 (wirewatch-exchange-account-1) twice. This should happen rarely (if not, ask for support).
2023-08-02T21:41:25.665288+0000 taler-exchange-wirewatch-958 INFO Attempted to import transaction 6 (wirewatch-exchange-account-1) twice. This should happen rarely (if not, ask for support).
2023-08-02T21:41:25.665301+0000 taler-exchange-wirewatch-958 INFO Attempted to import transaction 7 (wirewatch-exchange-account-1) twice. This should happen rarely (if not, ask for support).
2023-08-02T21:41:25.665313+0000 taler-exchange-wirewatch-958 INFO Attempted to import transaction 8 (wirewatch-exchange-account-1) twice. This should happen rarely (if not, ask for support).
2023-08-02T21:41:25.665325+0000 taler-exchange-wirewatch-958 INFO Attempted to import transaction 9 (wirewatch-exchange-account-1) twice. This should happen rarely (if not, ask for support).
2023-08-02T21:41:25.665337+0000 taler-exchange-wirewatch-958 INFO Attempted to import transaction 10 (wirewatch-exchange-account-1) twice. This should happen rarely (if not, ask for support).
2023-08-02T21:41:25.665349+0000 taler-exchange-wirewatch-958 INFO Attempted to import transaction 11 (wirewatch-exchange-account-1) twice. This should happen rarely (if not, ask for support).
2023-08-02T21:41:25.665361+0000 taler-exchange-wirewatch-958 INFO Attempted to import transaction 12 (wirewatch-exchange-account-1) twice. This should happen rarely (if not, ask for support).
2023-08-02T21:41:25.665437+0000 taler-exchange-wirewatch-958 INFO Requesting credit history staring from 12
2023-08-02T21:41:25.665456+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1012&start=12&long_poll_ms=60000'
2023-08-02T21:41:25.714491+0000 taler-exchange-wirewatch-958 INFO History request returned with HTTP status 204
2023-08-02T21:41:25.714551+0000 taler-exchange-wirewatch-958 INFO Will retry my shard (0,1024] of wirewatch-exchange-account-1 in 59 s
2023-08-02T21:42:25.725546+0000 taler-exchange-wirewatch-958 INFO Shard not completed in time, will try to re-acquire
2023-08-02T21:42:25.725811+0000 taler-exchange-wirewatch-958 INFO Starting transaction `begin_shard'
2023-08-02T21:42:25.732558+0000 taler-exchange-wirewatch-958 INFO Claimed new shard
2023-08-02T21:42:25.732654+0000 taler-exchange-wirewatch-958 INFO Starting with shard wirewatch-exchange-account-1 at (0,1024] locked for 2319 ms
2023-08-02T21:42:25.732685+0000 taler-exchange-wirewatch-958 INFO Continuing from 12
2023-08-02T21:42:25.732739+0000 taler-exchange-wirewatch-958 INFO Requesting credit history staring from 12
2023-08-02T21:42:25.732836+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1012&start=12&long_poll_ms=60000'
2023-08-02T21:42:25.779271+0000 taler-exchange-wirewatch-958 INFO History request returned with HTTP status 204
2023-08-02T21:42:25.779364+0000 taler-exchange-wirewatch-958 INFO Will retry my shard (0,1024] of wirewatch-exchange-account-1 in 59 s
2023-08-02T21:43:25.789425+0000 taler-exchange-wirewatch-958 INFO Shard not completed in time, will try to re-acquire
2023-08-02T21:43:25.789776+0000 taler-exchange-wirewatch-958 INFO Starting transaction `begin_shard'
2023-08-02T21:43:25.793705+0000 taler-exchange-wirewatch-958 INFO Claimed new shard
2023-08-02T21:43:25.793790+0000 taler-exchange-wirewatch-958 INFO Starting with shard wirewatch-exchange-account-1 at (0,1024] locked for 2702 ms
2023-08-02T21:43:25.793822+0000 taler-exchange-wirewatch-958 INFO Continuing from 12
2023-08-02T21:43:25.793873+0000 taler-exchange-wirewatch-958 INFO Requesting credit history staring from 12
2023-08-02T21:43:25.793958+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1012&start=12&long_poll_ms=60000'
2023-08-02T21:43:25.839602+0000 taler-exchange-wirewatch-958 INFO History request returned with HTTP status 200
2023-08-02T21:43:25.839680+0000 taler-exchange-wirewatch-958 INFO Importing 1 transactions
2023-08-02T21:43:25.839717+0000 taler-exchange-wirewatch-958 INFO Starting READ COMMITTED transaction `READ_COMMITED`
2023-08-02T21:43:25.844128+0000 taler-exchange-wirewatch-958 INFO Imported transaction 13.2023-08-02T21:43:25.844220+0000 taler-exchange-wirewatch-958 INFO Requesting credit history staring from 13
2023-08-02T21:43:25.844237+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1011&start=13&long_poll_ms=60000'
2023-08-02T21:43:25.884314+0000 taler-exchange-wirewatch-958 INFO History request returned with HTTP status 204
2023-08-02T21:43:25.884391+0000 taler-exchange-wirewatch-958 INFO Will retry my shard (0,1024] of wirewatch-exchange-account-1 in 59 s
2023-08-02T21:44:25.904310+0000 taler-exchange-wirewatch-958 INFO Shard not completed in time, will try to re-acquire
2023-08-02T21:44:25.904464+0000 taler-exchange-wirewatch-958 INFO Starting transaction `begin_shard'
2023-08-02T21:44:25.907157+0000 taler-exchange-wirewatch-958 INFO Claimed new shard
2023-08-02T21:44:25.907215+0000 taler-exchange-wirewatch-958 INFO Starting with shard wirewatch-exchange-account-1 at (0,1024] locked for 1477 ms
2023-08-02T21:44:25.907232+0000 taler-exchange-wirewatch-958 INFO Continuing from 13
2023-08-02T21:44:25.907263+0000 taler-exchange-wirewatch-958 INFO Requesting credit history staring from 13
2023-08-02T21:44:25.907327+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1011&start=13&long_poll_ms=60000'
2023-08-02T21:44:25.947491+0000 taler-exchange-wirewatch-958 INFO History request returned with HTTP status 200
2023-08-02T21:44:25.947555+0000 taler-exchange-wirewatch-958 INFO Importing 1 transactions
2023-08-02T21:44:25.947599+0000 taler-exchange-wirewatch-958 INFO Starting READ COMMITTED transaction `READ_COMMITED`
2023-08-02T21:44:25.950634+0000 taler-exchange-wirewatch-958 INFO Imported transaction 14.2023-08-02T21:44:25.950724+0000 taler-exchange-wirewatch-958 INFO Requesting credit history staring from 14
2023-08-02T21:44:25.950741+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1010&start=14&long_poll_ms=60000'
2023-08-02T21:44:25.979831+0000 taler-exchange-wirewatch-958 INFO History request returned with HTTP status 204
2023-08-02T21:44:25.979883+0000 taler-exchange-wirewatch-958 INFO Will retry my shard (0,1024] of wirewatch-exchange-account-1 in 59 s
2023-08-02T21:45:26.012068+0000 taler-exchange-wirewatch-958 INFO Shard not completed in time, will try to re-acquire
2023-08-02T21:45:26.012278+0000 taler-exchange-wirewatch-958 INFO Starting transaction `begin_shard'
2023-08-02T21:45:26.020208+0000 taler-exchange-wirewatch-958 INFO Claimed new shard
2023-08-02T21:45:26.020343+0000 taler-exchange-wirewatch-958 INFO Starting with shard wirewatch-exchange-account-1 at (0,1024] locked for 3222 ms
2023-08-02T21:45:26.020366+0000 taler-exchange-wirewatch-958 INFO Continuing from 14
2023-08-02T21:45:26.020405+0000 taler-exchange-wirewatch-958 INFO Requesting credit history staring from 14
2023-08-02T21:45:26.020468+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1010&start=14&long_poll_ms=60000'
2023-08-02T21:45:26.071587+0000 taler-exchange-wirewatch-958 INFO History request returned with HTTP status 200
2023-08-02T21:45:26.071737+0000 taler-exchange-wirewatch-958 INFO Importing 1 transactions
2023-08-02T21:45:26.071797+0000 taler-exchange-wirewatch-958 INFO Starting READ COMMITTED transaction `READ_COMMITED`
2023-08-02T21:45:26.074540+0000 taler-exchange-wirewatch-958 INFO Imported transaction 15.2023-08-02T21:45:26.074648+0000 taler-exchange-wirewatch-958 INFO Requesting credit history staring from 15
2023-08-02T21:45:26.074666+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1009&start=15&long_poll_ms=60000'
2023-08-02T21:45:26.118744+0000 taler-exchange-wirewatch-958 INFO History request returned with HTTP status 204
2023-08-02T21:45:26.118808+0000 taler-exchange-wirewatch-958 INFO Will retry my shard (0,1024] of wirewatch-exchange-account-1 in 59 s
2023-08-02T21:46:26.133425+0000 taler-exchange-wirewatch-958 INFO Shard not completed in time, will try to re-acquire
2023-08-02T21:46:26.133724+0000 taler-exchange-wirewatch-958 INFO Starting transaction `begin_shard'
2023-08-02T21:46:26.137852+0000 taler-exchange-wirewatch-958 INFO Claimed new shard
2023-08-02T21:46:26.137942+0000 taler-exchange-wirewatch-958 INFO Starting with shard wirewatch-exchange-account-1 at (0,1024] locked for 2816 ms
2023-08-02T21:46:26.137965+0000 taler-exchange-wirewatch-958 INFO Continuing from 15
2023-08-02T21:46:26.138003+0000 taler-exchange-wirewatch-958 INFO Requesting credit history staring from 15
2023-08-02T21:46:26.138073+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1009&start=15&long_poll_ms=60000'
2023-08-02T21:46:26.197853+0000 taler-exchange-wirewatch-958 INFO History request returned with HTTP status 204
2023-08-02T21:46:26.197962+0000 taler-exchange-wirewatch-958 INFO Will retry my shard (0,1024] of wirewatch-exchange-account-1 in 59 s
2023-08-02T21:47:26.162182+0000 taler-exchange-wirewatch-958 INFO Shard not completed in time, will try to re-acquire
2023-08-02T21:47:26.162430+0000 taler-exchange-wirewatch-958 INFO Starting transaction `begin_shard'
2023-08-02T21:47:26.166140+0000 taler-exchange-wirewatch-958 INFO Claimed new shard
2023-08-02T21:47:26.166210+0000 taler-exchange-wirewatch-958 INFO Starting with shard wirewatch-exchange-account-1 at (0,1024] locked for 2114 ms
2023-08-02T21:47:26.166232+0000 taler-exchange-wirewatch-958 INFO Continuing from 15
2023-08-02T21:47:26.166267+0000 taler-exchange-wirewatch-958 INFO Requesting credit history staring from 15
2023-08-02T21:47:26.166339+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1009&start=15&long_poll_ms=60000'
2023-08-02T21:47:26.233221+0000 taler-exchange-wirewatch-958 INFO History request returned with HTTP status 200
2023-08-02T21:47:26.233292+0000 taler-exchange-wirewatch-958 INFO Importing 1 transactions
2023-08-02T21:47:26.233333+0000 taler-exchange-wirewatch-958 INFO Starting READ COMMITTED transaction `READ_COMMITED`
2023-08-02T21:47:26.236366+0000 taler-exchange-wirewatch-958 INFO Imported transaction 16.2023-08-02T21:47:26.236459+0000 taler-exchange-wirewatch-958 INFO Requesting credit history staring from 16
2023-08-02T21:47:26.236481+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1008&start=16&long_poll_ms=60000'
2023-08-02T21:47:26.289610+0000 taler-exchange-wirewatch-958 INFO History request returned with HTTP status 204
2023-08-02T21:47:26.289673+0000 taler-exchange-wirewatch-958 INFO Will retry my shard (0,1024] of wirewatch-exchange-account-1 in 59 s
2023-08-02T21:48:26.269427+0000 taler-exchange-wirewatch-958 INFO Shard not completed in time, will try to re-acquire
2023-08-02T21:48:26.269697+0000 taler-exchange-wirewatch-958 INFO Starting transaction `begin_shard'
2023-08-02T21:48:26.273444+0000 taler-exchange-wirewatch-958 INFO Claimed new shard
2023-08-02T21:48:26.273551+0000 taler-exchange-wirewatch-958 INFO Starting with shard wirewatch-exchange-account-1 at (0,1024] locked for 3189 ms
2023-08-02T21:48:26.273573+0000 taler-exchange-wirewatch-958 INFO Continuing from 16
2023-08-02T21:48:26.273608+0000 taler-exchange-wirewatch-958 INFO Requesting credit history staring from 16
2023-08-02T21:48:26.273680+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1008&start=16&long_poll_ms=60000'
2023-08-02T21:48:26.343898+0000 taler-exchange-wirewatch-958 INFO History request returned with HTTP status 204
2023-08-02T21:48:26.343989+0000 taler-exchange-wirewatch-958 INFO Will retry my shard (0,1024] of wirewatch-exchange-account-1 in 59 s
2023-08-02T21:49:26.333933+0000 taler-exchange-wirewatch-958 INFO Shard not completed in time, will try to re-acquire
2023-08-02T21:49:26.334280+0000 taler-exchange-wirewatch-958 INFO Starting transaction `begin_shard'
2023-08-02T21:49:26.338036+0000 taler-exchange-wirewatch-958 INFO Claimed new shard
2023-08-02T21:49:26.338139+0000 taler-exchange-wirewatch-958 INFO Starting with shard wirewatch-exchange-account-1 at (0,1024] locked for 3167 ms
2023-08-02T21:49:26.338193+0000 taler-exchange-wirewatch-958 INFO Continuing from 16
2023-08-02T21:49:26.338267+0000 taler-exchange-wirewatch-958 INFO Requesting credit history staring from 16
2023-08-02T21:49:26.338374+0000 taler-exchange-wirewatch-958 INFO Requesting credit history at `http://libeufin_nexus:5017/facades/taler-facade/taler-wire-gateway/history/incoming?delta=1008&start=16&long_poll_ms=60000'
2023-08-02T21:49:26.399473+0000 taler-exchange-wirewatch-958 INFO History request returned with HTTP status 204
2023-08-02T21:49:26.399593+0000 taler-exchange-wirewatch-958 INFO Will retry my shard (0,1024] of wirewatch-exchange-account-1 in 59 s

taler-exchange-wirewatch.txt (16,388 bytes)

Date Modified	Username	Field	Change
2023-08-02 22:13	Windfisch	New Issue
2023-08-02 22:13	Windfisch	Status	new => assigned
2023-08-02 22:13	Windfisch	Assigned To	=> MS
2023-08-02 22:14	Windfisch	Note Added: 0020399
2023-08-02 22:14	Windfisch	File Added: libeufin-nexus.txt
2023-08-02 22:14	Windfisch	File Added: libeufin-sandbox.txt
2023-08-02 22:14	Windfisch	File Added: taler-exchange-httpd.txt
2023-08-02 22:14	Windfisch	File Added: taler-exchange-wirewatch.txt
2023-09-03 16:11	Christian Grothoff	Assigned To	MS => Antoine A
2023-09-03 16:13	Christian Grothoff	Relationship added	duplicate of 0007693
2023-09-05 09:39	Florian Dold	Product Version	0.9.2 => 0.9.4
2023-09-05 09:39	Florian Dold	Product Version	0.9.4 => 0.9.2
2023-09-05 09:39	Florian Dold	Target Version	=> 0.9.4
2023-11-17 17:22	Antoine A	Status	assigned => informing
2023-11-17 17:22	Antoine A	Resolution	open => duplicate
2023-11-29 00:28	Christian Grothoff	Target Version	0.9.4 => 0.9.3
2023-11-29 00:29	Christian Grothoff	Fixed in Version	=> 0.9.3
2023-11-29 00:30	Christian Grothoff	Status	informing => closed

View Issue Details

Required notifications

Relationships

Activities

Issue History