View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0010158 | Taler | exchange | public | 2025-07-08 17:07 | 2025-07-30 15:04 |
| Reporter | sebasjm | Assigned To | Florian Dold | ||
| Priority | high | Severity | crash | Reproducibility | always |
| Status | resolved | Resolution | fixed | ||
| Target Version | 1.0 stretch goals | ||||
| Summary | 0010158: exchange didn't recover well after fail [2h] | ||||
| Description | I had a merchant which was doing KYC, when to KYC form to download TOS and when the merchant submitted the data my script failed Jul 08 12:00:14 taler-exchange-httpd[1004553]: DEBUG select timeout = Tue Jul 08 12:00:24 2025 Jul 08 12:00:14 taler-exchange-httpd[1135418]: /bin/sh: 1: mktemp: not found Jul 08 12:00:14 taler-exchange-httpd[1135418] node:internal/errors:983 Jul 08 12:00:14 taler-exchange-httpd[1135418]: const err = new Error(message); Jul 08 12:00:14 taler-exchange-httpd[1135418] ^ Jul 08 12:00:14 taler-exchange-httpd[1135418]: Error: Command failed: mktemp /tmp/taler-log-error-XXXXX.in Jul 08 12:00:14 taler-exchange-httpd[1135418]: /bin/sh: 1: mktemp: not found this is because i limited the PATH which is fine, I fixed the problem and submitted again the merchant form expecting the exchange to continue the process like nothing happened. But it failed Jul 08 12:01:29 taler-exchange-httpd[1004553]: (Q65D6N2AY4C6KD8KZCBNX0DM2W) INFO Handling request (POST) for URL '/kyc-upload/J5B3FWEC3KN0441M4ATGCW9ZG4ZBFB1SB0H44CG81421KB5R5S90-0-1' Jul 08 12:01:29 taler-exchange-httpd[1004553]: (Q65D6N2AY4C6KD8KZCBNX0DM2W) INFO Handling request (POST) for URL '/kyc-upload/J5B3FWEC3KN0441M4ATGCW9ZG4ZBFB1SB0H44CG81421KB5R5S90-0-1' Jul 08 12:01:29 taler-exchange-httpd[1004553]: (Q65D6N2AY4C6KD8KZCBNX0DM2W) INFO Handling request (POST) for URL '/kyc-upload/J5B3FWEC3KN0441M4ATGCW9ZG4ZBFB1SB0H44CG81421KB5R5S90-0-1' Jul 08 12:01:29 taler-exchange-httpd[1004553]: (Q65D6N2AY4C6KD8KZCBNX0DM2W) INFO /kyc-upload received form submission Jul 08 12:01:29 taler-exchange-httpd[1004553] { Jul 08 12:01:29 taler-exchange-httpd[1004553]: "DOWNLOADED_TERMS_OF_SERVICE": true, Jul 08 12:01:29 taler-exchange-httpd[1004553]: "ACCEPTED_TERMS_OF_SERVICE": "exchange-tos-v1", Jul 08 12:01:29 taler-exchange-httpd[1004553]: "FORM_ID": "accept-tos", Jul 08 12:01:29 taler-exchange-httpd[1004553]: "FORM_VERSION": 1, Jul 08 12:01:29 taler-exchange-httpd[1004553]: "FORM_CONTEXT": { Jul 08 12:01:29 taler-exchange-httpd[1004553]: "tos_url": "http://exchange.taler.test/terms", Jul 08 12:01:29 taler-exchange-httpd[1004553]: "tosVersion": "exchange-tos-v1", Jul 08 12:01:29 taler-exchange-httpd[1004553]: "provider_name": "Taler Operations AR" Jul 08 12:01:29 taler-exchange-httpd[1004553] } Jul 08 12:01:29 taler-exchange-httpd[1004553]: }(Q65D6N2AY4C6KD8KZCBNX0DM2W) DEBUG Running prepared statement `lookup_completed_legitimization' on 0x625685662c10 Jul 08 12:01:29 taler-exchange-httpd[1004553]: (Q65D6N2AY4C6KD8KZCBNX0DM2W) DEBUG Executing prepared SQL statement `lookup_completed_legitimization' Jul 08 12:01:29 taler-exchange-httpd[1004553]: (Q65D6N2AY4C6KD8KZCBNX0DM2W) DEBUG Execution of prepared SQL statement `lookup_completed_legitimization' finished (PGRES_TUPLES_OK) Jul 08 12:01:29 taler-exchange-httpd[1004553]: (Q65D6N2AY4C6KD8KZCBNX0DM2W) ERROR Statement lookup_completed_legitimization returned more than one result, but there must be at most one when using GNUNET_PQ_eval_prepared_singleton_select Jul 08 12:01:29 taler-exchange-httpd[1004553]: (Q65D6N2AY4C6KD8KZCBNX0DM2W) ERROR Assertion failed at ../src/lib/pq/pq_eval.c:234. Jul 08 12:01:29 taler-exchange-httpd[1004553]: (Q65D6N2AY4C6KD8KZCBNX0DM2W) ERROR Assertion failed at taler-exchange-httpd_kyc-upload.c:293. Jul 08 12:01:29 taler-exchange-httpd[1004553]: (Q65D6N2AY4C6KD8KZCBNX0DM2W) INFO Request for `/kyc-upload/J5B3FWEC3KN0441M4ATGCW9ZG4ZBFB1SB0H44CG81421KB5R5S90-0-1' completed with HTTP status 500 (0) Merchant can't continue and is very sad | ||||
| Tags | No tags attached. | ||||
|
|
Investigation: lm.legitimization_measure_serial_id is UNIQUE. kt.access_token is NOT UNIQUE, but created via random_bytes() and SHOULD be UNIQUE. -> check? lp.legitimization_process_serial_id is UNIQUE. kyc_attributes table lacks a UNIQUE constraint on legitimization_serial. => That could, theoretically, be one cause for multiple results. Confirmed with the test below: we have 2x entries in the attributes table, for the same legitimization_serial. |
|
|
I added two integration tests on a2b0317a7..f61a65488 # taler-harness run-integrationtests kyc-fail-recover-simple Have a program that will fail with the same error (calling a child process that fail). In step 4 the wallet will submit a form that will make the program fail and in step 5 the wallet will submit a form that is expecting to pass. In Step 5) the test fail because the exchange returns 409 instead of 204. Is not the same error but quite # taler-harness run-integrationtests kyc-fail-recover-double Have the same program but also the fallback measure fails (also calling a child that doesn't exists). Step 4 will submit a form with values that will make the program fail, this step is made twice to reproduce the same error above (maybe here is de duplication in the DB?) Then step 5 submit a form that should work but exchange return 500 instead of 204. |
|
|
So what I see is: - first /kyc-upload/ fails *legitimately* in the test because the measure script is deliberately bugged. - ditto for a second /kyc-upload/ that is idempotent, but the exchange nevertheless places a second record into kyc-attributes. - afterwards, the expected invariant is broken, and we go kaboom in /kyc-info/. The attributes are checked for idempotency in 'kyc-upload', but *ONLY* if "is_finished" is set, which did not happen *because* of the failure in the measure script. Thus, we don't check for idempotency, ignore that the attributes already exist, and simply insert them again (and are not stopped by a DB constraint either). |
|
|
Well, the 409 is *expected*, as clients should only be allowed to submit a KYC form *once*. Sure, on idempotent submission we should generate an idempotent response (and not store the attributes again), so I'm fixing that now. But the $ taler-harness run-integrationtests kyc-fail-recover-simple test seems "wrong" in that 409 is the right response IMO. |
|
|
Note: I have a first partial solution in my code, but it does not yet: - add the required UNIQUE constraint - properly use DB transactions to ensure that the logic is atomic. |
|
|
Fix committed in 8c3e26a88..9a18a1242. Note that you do get a 409 if you change the POSTed attributes after the transaction stored them in the DB. I consider this correct, the attributes can only be POSTed once. |
|
|
@sebasjm: assigning to you to review and then fix the wallet-core test so that it passes ;-). |
|
|
Florian, I believe you fixed this already? |
|
|
Yes. Had to "fix" one test that didn't make sense by removing it. The other test passes now. commit 425be38ce793c9590820b3b922906db76f9c2141 (HEAD -> master, origin/master, origin/HEAD) Author: Florian Dold <florian@dold.me> Date: Wed Jul 30 15:01:00 2025 +0200 harness: remove AMP double failure test The fallback AMP may not ever fail, we don't expect this to be handled properly, so it doesn't make sense to test for it. |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2025-07-08 17:07 | sebasjm | New Issue | |
| 2025-07-08 21:51 | Christian Grothoff | Assigned To | => Christian Grothoff |
| 2025-07-08 21:51 | Christian Grothoff | Status | new => assigned |
| 2025-07-08 23:08 | Christian Grothoff | Priority | normal => high |
| 2025-07-08 23:22 | Christian Grothoff | Note Added: 0025449 | |
| 2025-07-09 16:26 | sebasjm | Note Added: 0025463 | |
| 2025-07-09 17:29 | Christian Grothoff | Note Edited: 0025449 | |
| 2025-07-09 17:34 | Christian Grothoff | Note Added: 0025466 | |
| 2025-07-09 17:38 | Christian Grothoff | Note Edited: 0025466 | |
| 2025-07-09 17:56 | Christian Grothoff | Note Added: 0025467 | |
| 2025-07-09 17:57 | Christian Grothoff | Note Added: 0025468 | |
| 2025-07-09 22:55 | Christian Grothoff | Note Added: 0025475 | |
| 2025-07-09 22:55 | Christian Grothoff | Assigned To | Christian Grothoff => sebasjm |
| 2025-07-09 22:55 | Christian Grothoff | Status | assigned => feedback |
| 2025-07-09 22:56 | Christian Grothoff | Note Added: 0025476 | |
| 2025-07-17 17:51 | Christian Grothoff | Assigned To | sebasjm => Florian Dold |
| 2025-07-17 17:51 | Christian Grothoff | Status | feedback => assigned |
| 2025-07-17 17:51 | Christian Grothoff | Note Added: 0025517 | |
| 2025-07-30 10:53 | Christian Grothoff | Summary | exchange didn't recover well after fail => exchange didn't recover well after fail [2h] |
| 2025-07-30 15:04 | Florian Dold | Note Added: 0025593 | |
| 2025-07-30 15:04 | Florian Dold | Status | assigned => resolved |
| 2025-07-30 15:04 | Florian Dold | Resolution | open => fixed |
