View Issue Details

IDProjectCategoryView StatusLast Update
0007445Talerexchangepublic2022-11-20 16:57
Reporteroec Assigned Tooec  
PrioritynormalSeverityminorReproducibilityalways
Status resolvedResolutionfixed 
Product Versiongit (master) 
Fixed in Versiongit (master) 
Summary0007445: test-auditor.sh fails
DescriptionThe call to exchange/src/auditor/test-auditor.sh fails in "wire audit", quote from test-auditor.sh.log:

...
===========16: incorrect wire_out amount=================
Launching bankUsing Sandbox-DB-connection jdbc:sqlite:auditor-basedb-sandbox.sqlite3
Using Nexus-DB-connection jdbc:sqlite:auditor-basedb-nexus.sqlite3
................... DONE
Running exchange aggregator ... DONE
Running exchange closer ... DONE
Running exchange transfer ... DONE
Running Nexus payment submitter ... DONE
Download bank transactions ... DONE
Stopping libeufin...
Killing libeufin sandbox 912872
Killing libeufin nexus 912873
Stopping libeufin DONE
Using Sandbox-DB-connection jdbc:sqlite:auditor-basedb-sandbox.sqlite3
Using Nexus-DB-connection jdbc:sqlite:auditor-basedb-nexus.sqlite3
Running audit(s) ...........FAILING test: wire audit failed
Running exit-cleanup
Stopping Postgres at /usr/lib/postgresql/14/bin
Stopping libeufin...
Killing libeufin sandbox 913063
Killing libeufin nexus 913064
Stopping libeufin DONE
DONE

Steps To Reproduce- install latest libeufin
- `make install` in exchange
-`make check`in exchange
Additional Informationcat /tmp/taler-auditor-basedbCF3Y3J/test-wire-audit.log
2022-11-07T13:42:18.420027+0100 taler-helper-auditor-wire-913192 INFO Taler auditor running for exchange master public key F78Z6FT2
2022-11-07T13:42:18.421943+0100 taler-helper-auditor-wire-913192 INFO Change in PQ event FD to -1
2022-11-07T13:42:18.421992+0100 taler-helper-auditor-wire-913192 INFO New poll FD is -1
2022-11-07T13:42:18.429344+0100 taler-helper-auditor-wire-913192 INFO Change in PQ event FD to 6
2022-11-07T13:42:18.429413+0100 taler-helper-auditor-wire-913192 INFO New poll FD is 6
2022-11-07T13:42:18.429847+0100 taler-helper-auditor-wire-913192 INFO Change in PQ event FD to -1
2022-11-07T13:42:18.429885+0100 taler-helper-auditor-wire-913192 INFO New poll FD is -1
2022-11-07T13:42:18.434753+0100 taler-helper-auditor-wire-913192 INFO Change in PQ event FD to 7
2022-11-07T13:42:18.434806+0100 taler-helper-auditor-wire-913192 INFO New poll FD is 7
2022-11-07T13:42:18.435690+0100 taler-helper-auditor-wire-913192 INFO Found exchange account `exchange-account-1'
2022-11-07T13:42:18.456159+0100 taler-helper-auditor-wire-913192 INFO Starting transaction `wire auditor'
* First analysis of with wire auditor, starting audit from scratch
2022-11-07T13:42:18.459260+0100 taler-helper-auditor-wire-913192 INFO Analyzing exchange's wire IN table for account `exchange-account-1'
2022-11-07T13:42:18.460750+0100 taler-helper-auditor-wire-913192 INFO Analyzing exchange wire IN (1) at So Nov 06 13:39:27 2022 of TESTKUDOS:10 with reserve_pub 8XJS6XG7
2022-11-07T13:42:18.460807+0100 taler-helper-auditor-wire-913192 INFO Analyzing exchange wire IN (2) at So Nov 06 13:39:36 2022 of TESTKUDOS:18 with reserve_pub SPPM3XSK
2022-11-07T13:42:18.460838+0100 taler-helper-auditor-wire-913192 INFO Requesting credit history at `http://localhost:8082/facades/test-facade/taler-wire-gateway/history/incoming?delta=2147483647'
2022-11-07T13:42:18.461208+0100 taler-helper-auditor-wire-913192 FEHLER Error fetching credit history of account exchange-account-1: 0/The response we got from the server was not even in JSON format.!
2022-11-07T13:42:18.461248+0100 taler-helper-auditor-wire-913192 FEHLER Hard error, not recording progress
TagsNo tags attached.

Activities

Christian Grothoff

2022-11-07 20:27

manager   ~0019386

Well, it works for me ;-). Are you sure you have a recent libeufin? Did libeufin crash? Looks like the wire-auditor fails to talk to the bank, so probably an issue with the libeufin-nexus or sandbox. You didn't include their logs...

oec

2022-11-12 12:38

developer   ~0019404

With commit 945821cbc842644f9d10de4ef36e8ef03d2d2253, it gets worse (after `make clean; bootstrap; make install`):

exchange/src/auditor> ./test-auditor.sh
Testing for jq
Testing for faketime
Testing for libeufin
Testing for pdflatex
Testing for taler-wallet-cli
Testing for Postgres FOUND at /usr/lib/postgresql/14/bin
Using /tmp/taler-auditor-basedbRCqBA8 for logging and temporary data
Setting up Postgres DB at /tmp/taler-auditor-basedbRCqBA8/postgres/ ...DONE
Launching Postgres service DONE
Generating fresh database at /tmp/taler-auditor-basedbRCqBA8
Created configuration at /tmp/taler-auditor-basedbRCqBA8/auditor-basedb.conf
Testing for libeufin FOUND
Testing for taler-wallet-cli FOUND
Testing for curl FOUND
MASTER PUB is 4BR1FF29ZWHQTXXGNMTX6QVG184J3TJ7M9664P3SXJS62DTB5YR0 using file /tmp/taler-auditor-basedbRCqBA8/auditor-basedb.mpriv
AUDITOR PUB is 12S3QEBCG32KV6AR0XXZ7D56Q495X4QFKVTTBZQVNQ496HZAEVBG using file /tmp/taler-auditor-basedbRCqBA8/auditor-basedb.apriv
Setting up exchange
2022-11-11T12:36:30.242154+0100 util-plugin-144258 FEHLER `lt_dlopenext' failed for library `libtaler_plugin_exchangedb_postgres' with error: file not found
Failed to initialize database plugin.
Running generate-auditor-basedb exit cleanup logic...
killing libeufin DONE
Generation failed
Running exit-cleanup
Stopping Postgres at /usr/lib/postgresql/14/bin
Stopping libeufin...
Stopping libeufin DONE
DONE

> ls -lart /usr/local/lib/taler/libtaler_plugin_exchangedb_postgres.so
-rwxr-xr-x 1 oec oec 1334952 Nov 12 12:33 /usr/local/lib/taler/libtaler_plugin_exchangedb_postgres.so

Christian Grothoff

2022-11-13 11:26

manager   ~0019407

The latest code doesn't yet build, the DB plugin is being refactored. Should conclude on Monday. Sorry for the inconvenience ;-).

oec

2022-11-14 10:15

developer   ~0019415

With commit 41e3c1ecbf0c437f58be3084a9401aa71c515a62, test-auditor.sh still fails (see below) and test-revocation.sh loops.

(from test-auditor.sh.log:)
...
===========15: deposit wire salt wrong=================
Launching bank................... DONE
Running audit(s) ............. DONE
Stopping libeufin...
Killing libeufin sandbox 408991
Killing libeufin nexus 408992
Stopping libeufin DONE
TeXing ... DONE
Testing inconsistency detection... PASS
===========16: incorrect wire_out amount=================
Launching bank................... DONE
Running exchange aggregator ... DONE
Running exchange closer ... DONE
Running exchange transfer ... DONE
Running Nexus payment submitter ... DONE
Download bank transactions ... DONE
Stopping libeufin...
Killing libeufin sandbox 409238
Killing libeufin nexus 409239
Stopping libeufin DONE
Running audit(s) ...........FAILING test: wire audit failed
Running exit-cleanup
Stopping Postgres at /usr/lib/postgresql/14/bin
Stopping libeufin...
Killing libeufin sandbox 409431
Killing libeufin nexus 409432
Stopping libeufin DONE
DONE
FAIL test-auditor.sh (exit status: 1)

oec

2022-11-20 13:10

developer   ~0019461

In test-auditor.sh, function audit_only() fails in the call to:

 $VALGRIND taler-helper-auditor-wire -i -L DEBUG -c $CONF -m $MASTER_PUB > test-audit-wire.json 2> ${MY_TMP_DIR}/test-wire-audit.log || exit_fail "wire audit failed".

The corresponding test-wire-audit.log says:

2022-11-20T13:01:03.827407+0100 taler-helper-auditor-wire-73279 INFO Taler auditor running for exchange master public key HCKSYPM1
2022-11-20T13:01:03.829727+0100 taler-helper-auditor-wire-73279 INFO Change in PQ event FD to -1
2022-11-20T13:01:03.829786+0100 taler-helper-auditor-wire-73279 INFO New poll FD is -1
2022-11-20T13:01:03.838198+0100 taler-helper-auditor-wire-73279 INFO Change in PQ event FD to 6
2022-11-20T13:01:03.838260+0100 taler-helper-auditor-wire-73279 INFO New poll FD is 6
2022-11-20T13:01:03.838742+0100 taler-helper-auditor-wire-73279 INFO Change in PQ event FD to -1
2022-11-20T13:01:03.838781+0100 taler-helper-auditor-wire-73279 INFO New poll FD is -1
2022-11-20T13:01:03.844117+0100 taler-helper-auditor-wire-73279 INFO Change in PQ event FD to 7
2022-11-20T13:01:03.844171+0100 taler-helper-auditor-wire-73279 INFO New poll FD is 7
2022-11-20T13:01:03.845258+0100 taler-helper-auditor-wire-73279 INFO Found exchange account `exchange-account-1'
2022-11-20T13:01:03.848787+0100 taler-helper-auditor-wire-73279 INFO Starting transaction `wire auditor'
* First analysis of with wire auditor, starting audit from scratch
2022-11-20T13:01:03.853108+0100 taler-helper-auditor-wire-73279 INFO Analyzing exchange's wire IN table for account `exchange-account-1'
2022-11-20T13:01:03.854989+0100 taler-helper-auditor-wire-73279 INFO Analyzing exchange wire IN (1) at Sa Nov 19 13:00:30 2022 of TESTKUDOS:10 with reserve_pub 0AXP9S86
2022-11-20T13:01:03.855058+0100 taler-helper-auditor-wire-73279 INFO Analyzing exchange wire IN (2) at Sa Nov 19 13:00:39 2022 of TESTKUDOS:18 with reserve_pub B8NMPTVR
2022-11-20T13:01:03.855091+0100 taler-helper-auditor-wire-73279 INFO Requesting credit history at `http://localhost:8082/facades/test-facade/taler-wire-gateway/history/incoming?delta=2147483647'
2022-11-20T13:01:03.855488+0100 taler-helper-auditor-wire-73279 FEHLER Error fetching credit history of account exchange-account-1: 0/The response we got from the server was not even in JSON format.!
2022-11-20T13:01:03.855532+0100 taler-helper-auditor-wire-73279 FEHLER Hard error, not recording progress

Next step: figuring out, what http://localhost:8082/facades/test-facade/taler-wire-gateway/history/incoming?delta=2147483647 returns and what is expected.

oec

2022-11-20 14:14

developer   ~0019462

Adding a 'sleep 2' before the call to taler-helper-auditor-wire helps to things catch up. A `sleep 1` is not always sufficient, it either fails with the original error or with:

...
Running audit(s) ........... WAITING A SECOND FOR WHATEVER THINGS TO CATCH UP..... DONE
Testing inconsistency detection... FAILING test: Reported justified amount wrong: null
...

oec

2022-11-20 16:32

developer   ~0019463

After adding a retry logic in test-auditor.sh, function audit_only, for the taler-helper-auditor-wire call and watching /tmp/taler-auditor-baseXXXXX/libeufin-sandbox-stderr.log, it seems that libeufin-sandbox is crashing or exiting during the run of an audit. The adapted test script (calling `test-auditor.sh 16`) outputs:
...
===========16: incorrect wire_out amount=================
Launching bank.................... DONE
Running exchange aggregator ... DONE
Running exchange closer ... DONE
Running exchange transfer ... DONE
Running Nexus payment submitter ... DONE
Download bank transactions ... DONE
Stopping libeufin...
Killing libeufin sandbox 260804
Killing libeufin nexus 260805
Stopping libeufin DONE
Running audit(s) ........... FIRST CALL TO taler-helper-auditor-wire FAILED,
RETRY AFTER TWO SECONDS...
.. DONE
Testing inconsistency detection... PASS
Stopping libeufin...
Killing libeufin sandbox 260998
Killing libeufin nexus 260999
Stopping libeufin DONE
Second modification: wire nothing
Running audit(s) ............. DONE
Stopping libeufin...
Killing libeufin sandbox 261185
Killing libeufin nexus 261186
Stopping libeufin DONE
Testing inconsistency detection... PASS
Stopping libeufin...
Stopping libeufin DONE
TeXing ... DONE
Doing full reload of the database (/tmp/taler-auditor-basedbfYeDhz/auditor-basedb - auditor-basedb)...
DONE
Stopping libeufin...
Stopping libeufin DONE
Loading libeufin Nexus basedb: /tmp/taler-auditor-basedbfYeDhz/auditor-basedb-libeufin-nexus.sql DONE
Loading libeufin Sandbox basedb: /tmp/taler-auditor-basedbfYeDhz/auditor-basedb-libeufin-sandbox.sql DONE
Cleanup (disabled, leaving database auditor-basedb behind)
Cleaning up /tmp/taler-auditor-basedbfYeDhz...
Running exit-cleanup
Stopping Postgres at /usr/lib/postgresql/14/bin
Stopping libeufin...
Stopping libeufin DONE
DONE

During `Running audit(s) ...........`is printed for test-auditor.sh 16`, the output of `tail -F libeufin-sandbox-stderr.log` suddenly reports a file truncation and than an apparent restart of the sandbox:

...
16:20:53.244 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb - thread (id/name/group): 15/eventLoopGroupProxy-4-1/main
tail: taler-auditor-basedbfYeDhz/libeufin-sandbox-stderr.log: file truncated
16:20:55.717 [main] INFO tech.libeufin.sandbox - LibEuFin Sandbox running on port 18082
16:20:56.010 [main] DEBUG tech.libeufin.sandbox - Application started: io.ktor.application.Application@7cf283e1
16:20:58.373 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - handling initialization for order type C52
16:20:58.374 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - Handling C52 request
16:20:58.829 [eventLoopGroupProxy-4-1] DEBUG tech.libeufin.sandbox - 200 OK, POST /ebicsweb - thread (id/name/group): 15/eventLoopGroupProxy-4-1/main
...

This seems to be a problem in libeufin.

oec

2022-11-20 16:37

developer   ~0019464

Last edited: 2022-11-20 16:45

Commit 496a13f35eb3b352eb2bcf8cf84938ce0683e9c5 adds retry logic to test-auditor.sh and the tests now ran through, a few - 16, 17, 21 and 27 - only after a retry.

This works around the problem but the root cause - probably in libeufin - needs triage.

oec

2022-11-20 16:55

developer   ~0019465

Final note: Tested with libeufin commit 0583cf84bed2a4c2f788ded5bdff15495305c7fe

oec

2022-11-20 16:57

developer   ~0019466

The retry logic in test-auditor.sh has "resolved" the particular issue, that is, the script test-auditor.sh now runs through with all tests passing.

Nevertheless, I'm going to open another bug against libeufin.

Issue History

Date Modified Username Field Change
2022-11-07 13:56 oec New Issue
2022-11-07 13:56 oec Status new => assigned
2022-11-07 13:56 oec Assigned To => Christian Grothoff
2022-11-07 20:27 Christian Grothoff Note Added: 0019386
2022-11-07 20:27 Christian Grothoff Assigned To Christian Grothoff => oec
2022-11-07 20:27 Christian Grothoff Status assigned => feedback
2022-11-12 12:38 oec Note Added: 0019404
2022-11-12 12:38 oec Assigned To oec =>
2022-11-12 12:39 oec Assigned To => Christian Grothoff
2022-11-12 12:39 oec Status feedback => assigned
2022-11-13 11:26 Christian Grothoff Note Added: 0019407
2022-11-14 10:15 oec Note Added: 0019415
2022-11-15 15:30 Christian Grothoff Assigned To Christian Grothoff => oec
2022-11-20 13:10 oec Note Added: 0019461
2022-11-20 14:14 oec Note Added: 0019462
2022-11-20 16:32 oec Note Added: 0019463
2022-11-20 16:37 oec Note Added: 0019464
2022-11-20 16:45 oec Note Edited: 0019464
2022-11-20 16:55 oec Note Added: 0019465
2022-11-20 16:57 oec Status assigned => resolved
2022-11-20 16:57 oec Resolution open => fixed
2022-11-20 16:57 oec Fixed in Version => git (master)
2022-11-20 16:57 oec Note Added: 0019466