View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0007445 | Taler | exchange | public | 2022-11-07 13:56 | 2023-01-26 22:53 |
| Reporter | oec | Assigned To | oec | ||
| Priority | normal | Severity | minor | Reproducibility | always |
| Status | closed | Resolution | fixed | ||
| Product Version | git (master) | ||||
| Target Version | 0.9.1 | Fixed in Version | 0.9.1 | ||
| Summary | 0007445: test-auditor.sh fails | ||||
| Description | The 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 Information | cat /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 | ||||
| Tags | No tags attached. | ||||
|
|
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... |
|
|
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 |
|
|
The latest code doesn't yet build, the DB plugin is being refactored. Should conclude on Monday. Sorry for the inconvenience ;-). |
|
|
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) |
|
|
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. |
|
|
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 ... |
|
|
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. |
|
|
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. |
|
|
Final note: Tested with libeufin commit 0583cf84bed2a4c2f788ded5bdff15495305c7fe |
|
|
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. |
| 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 | |
| 2023-01-06 21:12 | Christian Grothoff | Fixed in Version | git (master) => 0.9.1 |
| 2023-01-06 21:12 | Christian Grothoff | Target Version | => 0.9.1 |
| 2023-01-26 22:53 | Christian Grothoff | Status | resolved => closed |
