View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0006738 | Taler | merchant backend | public | 2021-02-04 18:50 | 2024-01-12 13:04 |
| Reporter | Florian Dold | Assigned To | Christian Grothoff | 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 | have not tried |
| Status | closed | Resolution | fixed | ||
| Product Version | git (master) | ||||
| Target Version | 0.8 | Fixed in Version | 0.8 | ||
| Summary | 0006738: merchant's /abort fails when one coin has not been deposited yet | ||||
| Description | This issue can be reproduced by running: $ taler-wallet-cli testing run-integrationtests pay-abort The test case makes a payment with two coins, but for one of the coins we simulate that the exchange doesn't accept the "/deposit" for that coin. In this scenario, the merchant obviously should allow an /abort of the payment. From studying the logs (relevant part in "Additional Information"), it looks like the merchant tries to refund both coins, but (as expected!) only one refund succeeds (as the other coin wasn't even deposited yet). But the merchant doesn't return the partial response, but instead returns a 502 without any useful body. Furthermore, the DB constraint violation looks a bit sketchy, I'm not sure if triggering the violation is intentional or not in this case. | ||||
| Additional Information | Feb 04 19:27:38-180460 taler-merchant-httpd-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG URL for refund: `http://localhost:9081/coins/F7C17YG0P0P8JV4E7PBFVK0EZC99HKP0XGF5H39DKS1H7GGHHNW0/refund' Feb 04 19:27:38-180478 util-scheduler-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG canceling task 0x564dd9e561f0 Feb 04 19:27:38-180483 util-scheduler-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG destroying task 0x564dd9e561f0 Feb 04 19:27:38-180655 taler-merchant-httpd-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG URL for refund: `http://localhost:9081/coins/1JE254KS3ZDBB5347CTBQDGG4018K1ESDJWN5KEE8BC3D57R6SH0/refund' Feb 04 19:27:38-180665 util-scheduler-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG canceling task 0x564dd9e3ba00 Feb 04 19:27:38-180670 util-scheduler-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG destroying task 0x564dd9e3ba00 Feb 04 19:27:38-180675 util-scheduler-279581 DEBUG destroying task 0x564dd9e54840 Feb 04 19:27:38-180680 util-scheduler-279581 DEBUG Running task 0x564dd9e561f0 Feb 04 19:27:38-180851 util-scheduler-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Adding task 0x564dd9e3c330 Feb 04 19:27:38-180861 util-scheduler-279581 DEBUG destroying task 0x564dd9e561f0 Feb 04 19:27:38-180868 util-scheduler-279581 DEBUG select timeout = Thu Feb 04 19:27:38 2021 Feb 04 19:27:38-380080 util-scheduler-279581 DEBUG Running task 0x564dd9e3c330 Feb 04 19:27:38-380138 util-scheduler-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Adding task 0x564dd9e36f30 Feb 04 19:27:38-380148 util-scheduler-279581 DEBUG destroying task 0x564dd9e3c330 Feb 04 19:27:38-380157 util-scheduler-279581 DEBUG select timeout = Thu Feb 04 19:27:38 2021 Feb 04 19:27:38-381198 util-scheduler-279581 DEBUG Running task 0x564dd9e36f30 Feb 04 19:27:38-381220 util-scheduler-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Adding task 0x564dd9e51c90 Feb 04 19:27:38-381229 util-scheduler-279581 DEBUG destroying task 0x564dd9e36f30 Feb 04 19:27:38-381237 util-scheduler-279581 DEBUG select timeout = Thu Feb 04 19:28:08 2021 Feb 04 19:27:38-587404 util-scheduler-279581 DEBUG Running task 0x564dd9e51c90 Feb 04 19:27:38-587463 taler-merchant-httpd-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Downloaded body: { "exchange_sig": "47YN446X46K2Q2B05JEFFRWB1E85T1H9S6VW9JCS4E3QHP8GSS2E9V05FRV32A2NA4GAZTN31DW6WDXWFDK4X7JPGXXMJ3BV9QT4C18", "exchange_pub": "AHSHNAKNCRN2VZ3FTPG6RT725BVGMDW404G8WA5BMZBM6PPHXDSG" } Feb 04 19:27:38-587548 util-scheduler-279581 DEBUG destroying task 0x564dd9e51c90 Feb 04 19:27:38-587553 util-scheduler-279581 DEBUG Running task 0x564dd9e3f9d0 Feb 04 19:27:38-587560 util-scheduler-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Adding task 0x564dd9e39610 Feb 04 19:27:38-587563 util-scheduler-279581 DEBUG destroying task 0x564dd9e3f9d0 Feb 04 19:27:38-587568 util-scheduler-279581 DEBUG select timeout = Thu Feb 04 19:28:08 2021 Feb 04 19:27:38-995817 util-scheduler-279581 DEBUG Running task 0x564dd9e39610 Feb 04 19:27:38-995878 taler-merchant-httpd-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Downloaded body: { "code": 1502, "hint": "The exchange knows about the coin we were asked to refund, but not about the specific /deposit operation. Hence, we cannot issue a refund (as we do not know if this merchant public key is authorized to do a refund).", "detail": null } Feb 04 19:27:38-995899 taler-merchant-httpd-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Starting merchant DB transaction Feb 04 19:27:38-995903 taler-merchant-httpd-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Running statement `START TRANSACTION ISOLATION LEVEL SERIALIZABLE' on 0x564dd9e28450 Feb 04 19:27:38-995998 taler-merchant-httpd-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Running prepared statement `lookup_order_status' on 0x564dd9e28450 Feb 04 19:27:38-996005 pq-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Executing prepared SQL statement `lookup_order_status' Feb 04 19:27:38-996228 taler-merchant-httpd-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Finding deposits for h_contract_terms '9F0FM963' Feb 04 19:27:38-996235 taler-merchant-httpd-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Running prepared statement `lookup_deposits' on 0x564dd9e28450 Feb 04 19:27:38-996239 pq-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Executing prepared SQL statement `lookup_deposits' Feb 04 19:27:38-996362 taler-merchant-httpd-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Running prepared statement `refund_coin' on 0x564dd9e28450 Feb 04 19:27:38-996368 pq-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Executing prepared SQL statement `refund_coin' Feb 04 19:27:38-996662 pq-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Query `refund_coin' failed with unique violation: duplicate key value violates unique constraint "merchant_refunds_order_serial_coin_pub_rtransaction_id_key"/Key (order_serial, coin_pub, rtransaction_id)=(1, \x79d813fa00b02c896c8e3d96fdcc0efb1298cec0ec1e588d2d9e4313c2118d78, 0) already exists./ERROR: duplicate key value violates unique constraint "merchant_refunds_order_serial_coin_pub_rtransaction_id_key" DETAIL: Key (order_serial, coin_pub, rtransaction_id)=(1, \x79d813fa00b02c896c8e3d96fdcc0efb1298cec0ec1e588d2d9e4313c2118d78, 0) already exists. /PGRES_FATAL_ERROR/ERROR: duplicate key value violates unique constraint "merchant_refunds_order_serial_coin_pub_rtransaction_id_key" DETAIL: Key (order_serial, coin_pub, rtransaction_id)=(1, \x79d813fa00b02c896c8e3d96fdcc0efb1298cec0ec1e588d2d9e4313c2118d78, 0) already exists. Feb 04 19:27:38-996672 taler-merchant-httpd-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Committing merchant DB transaction Feb 04 19:27:38-996676 taler-merchant-httpd-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Running prepared statement `end_transaction' on 0x564dd9e28450 Feb 04 19:27:38-996679 pq-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Executing prepared SQL statement `end_transaction' Feb 04 19:27:38-996742 taler-merchant-httpd-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Aborting pending /deposit operations Feb 04 19:27:38-996748 taler-merchant-httpd-279581(0AR0PWHQ5QDPKKPGARW29JK3FR) DEBUG Resuming /abort handling as exchange interaction is done (502) | ||||
| Tags | No tags attached. | ||||
| 00c0256..6ce9acf fixes the merchant to not generate a BAD_GATEWAY in case the exchange returns 404 or 410 (both legitimate replies for a good working exchange). With that change, the test passes again. | |
| The DB invariant violation is triggered intentionally, basically we 'insert' while really trying to "insert if not exists" (or rather: insert-if-not-violating-constraints). | |
| Fix committed to master branch. | |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2021-02-04 18:50 | Florian Dold | New Issue | |
| 2021-02-04 18:50 | Florian Dold | Status | new => assigned |
| 2021-02-04 18:50 | Florian Dold | Assigned To | => Christian Grothoff |
| 2021-02-04 19:06 | Christian Grothoff | Note Added: 0017498 | |
| 2021-02-04 19:08 | Christian Grothoff | Note Added: 0017499 | |
| 2021-02-04 19:08 | Christian Grothoff | Status | assigned => informing |
| 2021-02-04 19:08 | Christian Grothoff | Resolution | open => fixed |
| 2021-02-04 19:08 | Christian Grothoff | Fixed in Version | => 0.8.1 |
| 2021-02-04 19:08 | Christian Grothoff | Target Version | 0.8 => 0.8.1 |
| 2021-07-30 12:02 | Christian Grothoff | Fixed in Version | 0.8.1 => 0.8 |
| 2021-07-30 12:02 | Christian Grothoff | Target Version | 0.8.1 => 0.8 |
| 2021-08-24 14:23 | Christian Grothoff | Status | informing => closed |
| 2021-09-02 16:22 | Christian Grothoff | ||
| 2021-09-02 16:23 | Christian Grothoff | Note Added: 0018361 | |
| 2024-01-12 13:04 | Christian Grothoff | Category | merchant backend API (C) => mechant backend |
| 2025-03-22 13:09 | Christian Grothoff | Category | mechant backend => merchant backend |