View Issue Details

IDProjectCategoryView StatusLast Update
0006738Talermerchant backend API (C)public2021-02-04 20:08
ReporterFlorian Dold Assigned ToChristian Grothoff  
PrioritynormalSeverityminorReproducibilityhave not tried
Status resolvedResolutionfixed 
Product Versiongit (master) 
Target Version0.8.1Fixed in Version0.8.1 
Summary0006738: merchant's /abort fails when one coin has not been deposited yet
DescriptionThis 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 InformationFeb 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)
TagsNo tags attached.

Activities

Christian Grothoff

2021-02-04 20:06

manager   ~0017498

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.

Christian Grothoff

2021-02-04 20:08

manager   ~0017499

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).

Issue History

Date Modified Username Field Change
2021-02-04 19:50 Florian Dold New Issue
2021-02-04 19:50 Florian Dold Status new => assigned
2021-02-04 19:50 Florian Dold Assigned To => Christian Grothoff
2021-02-04 20:06 Christian Grothoff Note Added: 0017498
2021-02-04 20:08 Christian Grothoff Note Added: 0017499
2021-02-04 20:08 Christian Grothoff Status assigned => resolved
2021-02-04 20:08 Christian Grothoff Resolution open => fixed
2021-02-04 20:08 Christian Grothoff Fixed in Version => 0.8.1
2021-02-04 20:08 Christian Grothoff Target Version 0.8 => 0.8.1