View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0006854 | Taler | exchange | public | 2021-05-06 16:01 | 2021-08-24 16:23 |
| Reporter | sebasjm | Assigned To | Christian Grothoff | ||
| Priority | normal | Severity | major | Reproducibility | sometimes |
| Status | closed | Resolution | fixed | ||
| Product Version | git (master) | ||||
| Target Version | 0.8 | Fixed in Version | 0.8 | ||
| Summary | 0006854: exchange get into a loop checking from transaction | ||||
| Description | About the "add transfer bug": sometimes the exchange get into this loop logs at [1] when I do notification it doesnt happen always, my guess is that it has to be if I wait to much after the order has been wired. the loop can be stopped cancelling the request from the backoffice to the backend Log: exchange INFO Request completed database ERROR: duplicate key value violates unique constraint "merchant_transfers_wtid_exchange_url_key" database DETAIL: Key (wtid, exchange_url)=(\xa9e05464fdc99160331006c15b395e69bb226e0d2b434373d0e19176c3ff0956, http://exchange.taler:8081/) already exists. database STATEMENT: INSERT INTO merchant_transfers(exchange_url,wtid,credit_amount_val,credit_amount_frac,account_serial,confirmed)SELECT $1, $2, $3, $4, account_serial, $6 FROM merchant_accounts WHERE payto_uri=$5 AND merchant_serial= (SELECT merchant_serial FROM merchant_instances WHERE merchant_id=$7) exchange INFO Handling new request exchange (PB8K6ZFFA3313EC4FP7WKP5G6M) INFO Handling request (GET) for URL '/transfers/N7G58S7XS68P0CRG0V0NPEAYD6XJ4VGD5D1M6WYGW68QDGZZ15B0' exchange INFO Request completed database ERROR: duplicate key value violates unique constraint "merchant_transfers_wtid_exchange_url_key" database DETAIL: Key (wtid, exchange_url)=(\xa9e05464fdc99160331006c15b395e69bb226e0d2b434373d0e19176c3ff0956, http://exchange.taler:8081/) already exists. database STATEMENT: INSERT INTO merchant_transfers(exchange_url,wtid,credit_amount_val,credit_amount_frac,account_serial,confirmed)SELECT $1, $2, $3, $4, account_serial, $6 FROM merchant_accounts WHERE payto_uri=$5 AND merchant_serial= (SELECT merchant_serial FROM merchant_instances WHERE merchant_id=$7) exchange INFO Handling new request exchange (WWFG14EFYVZJEV9WV4RVHZABQ4) INFO Handling request (GET) for URL '/transfers/N7G58S7XS68P0CRG0V0NPEAYD6XJ4VGD5D1M6WYGW68QDGZZ15B0' exchange INFO Request completed database ERROR: duplicate key value violates unique constraint "merchant_transfers_wtid_exchange_url_key" database DETAIL: Key (wtid, exchange_url)=(\xa9e05464fdc99160331006c15b395e69bb226e0d2b434373d0e19176c3ff0956, http://exchange.taler:8081/) already exists. database STATEMENT: INSERT INTO merchant_transfers(exchange_url,wtid,credit_amount_val,credit_amount_frac,account_serial,confirmed)SELECT $1, $2, $3, $4, account_serial, $6 FROM merchant_accounts WHERE payto_uri=$5 AND merchant_serial= (SELECT merchant_serial FROM merchant_instances WHERE merchant_id=$7) | ||||
| Steps To Reproduce | create an order pay it wait for the exchange to wire the amount to the merchant wait.... try to inform the transfer | ||||
| Tags | No tags attached. | ||||
|
|
Are you sure it is the *Exchange* going into a loop here? Looks more like the merchant has a problem (from the logs). |
|
|
I made some major improvements to the transaction logic of taler-merchant-httpd_private-post-transfers.c. Alas, I did not see anything that I would say would cause a loop. Anyway, reporting if this helps would be great, as would be a testcase in case the issue remains. |
|
|
ACK, will check |
|
|
now it blow ups in taler-merchant-httpd_private-post-transfers.c:1030, maybe should be a break instead of a assert? |
|
|
i can confirm that following the steps before, and changing GNUNET_assert -> GNUNET_break at taler-merchant-httpd_private-post-transfers.c:1030, not does not loop after finding duplicate keys. what is confusing is getting 502 and then seeing the transfer returned in the query when listing transactions (unit test on the way) also, after insert transactions i see this ERROR BUG: Preflight check committed transaction `post-transfers'! |
|
|
regarding my last comment and after reading here: https://docs.taler.net/core/api-merchant.html#informing-the-backend-about-incoming-wire-transfers 502 Bad gateway: The exchange returned an error when we asked it about the GET /transfer status for this wire transfer. Details of the exchange error are returned. I see no conflict. no more comments, we can close this. |
|
|
Eh, wait. I'm not sure the break () is OK, I need to check that. Also, then we have the error of the exchange returning an error. Which one is it? Are you sure it is legitmate for the exchange to fail here? |
|
|
I've looked more at the code, and a GNUNET_break() is fine, but it should still just not happen: we just queried for the transfer, did not find it, and then the INSERT with the same arguments (!) fails because of a UNIQUE constraint violation. Totally strange. I'm modifying the code to include the instance in the SELECT statement, but this cannot really fix the situation. A concurrent operation where Postgres fails with some delay with a serialization error may explain this (very hypothetically speaking), but still something is quite wrong here. Sebastian: can you please try to produce a shell script that I can use to trigger the break()? |
|
|
Ok, building a test right now. But as i mentioned before I do see the transaction being inserted in the merchant_transfers table when the exchange responds 404 (code 1451). No concurrent operations here. For your comments I deduce that you dont expect the transaction to be inserted. |
|
|
Test pushed at 0bcf8ea8..332630ca break will be trigger doing the api call at line 305 |
|
|
I found some transaction issues in POST /transfer logic, fixed in 332630c..906e303. |
|
|
Update: taler-merchant-httpd-94561(WPT8TWEQP4Q7RANDH61VKGEF08) ERROR Assertion failed at taler-merchant-httpd_private-post-transfers.c:1031 -- continues to be logged by sebasjm's test case. |
|
|
The break() arises because the entry exists in the table, but the SELECT () on lookup_transaction() fails because the "insert_transfer_signature" never happened and thus a JOIN of that table with another table gives the empty set! |
|
|
63abbe2..dfdd322 removes the GNUNET_break(), as this can legitimately happen if the exchange's response was ever non-successful. |
|
|
Updated test to refer to this bug to make it clear what it tests. Also confirmed that the exchange legitimately did not provide a good reply as the test used a bogus WTID (which is good for a test!) :-). |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2021-05-06 16:01 | sebasjm | New Issue | |
| 2021-05-06 16:01 | sebasjm | Status | new => assigned |
| 2021-05-06 16:01 | sebasjm | Assigned To | => Christian Grothoff |
| 2021-05-09 10:35 | Christian Grothoff | Note Added: 0017798 | |
| 2021-05-09 12:46 | Christian Grothoff | Note Added: 0017799 | |
| 2021-05-09 12:46 | Christian Grothoff | Assigned To | Christian Grothoff => sebasjm |
| 2021-05-09 12:46 | Christian Grothoff | Status | assigned => feedback |
| 2021-05-09 12:46 | Christian Grothoff | Target Version | git (master) => 0.9 |
| 2021-05-10 14:51 | sebasjm | Note Added: 0017808 | |
| 2021-05-10 18:34 | sebasjm | Note Added: 0017809 | |
| 2021-05-11 05:30 | sebasjm | Note Added: 0017814 | |
| 2021-05-11 05:30 | sebasjm | Note Edited: 0017814 | |
| 2021-05-11 05:48 | sebasjm | Note Added: 0017815 | |
| 2021-05-11 12:32 | Christian Grothoff | Note Added: 0017820 | |
| 2021-05-11 12:55 | Christian Grothoff | Note Added: 0017823 | |
| 2021-05-11 16:00 | sebasjm | Note Added: 0017827 | |
| 2021-05-11 16:04 | sebasjm | Note Added: 0017828 | |
| 2021-05-11 19:23 | Christian Grothoff | Note Added: 0017832 | |
| 2021-05-11 19:24 | Christian Grothoff | Note Added: 0017833 | |
| 2021-05-11 19:24 | Christian Grothoff | Assigned To | sebasjm => Christian Grothoff |
| 2021-05-11 19:24 | Christian Grothoff | Status | feedback => assigned |
| 2021-05-11 20:28 | Christian Grothoff | Note Added: 0017834 | |
| 2021-05-11 22:50 | Christian Grothoff | Note Added: 0017835 | |
| 2021-05-11 22:54 | Christian Grothoff | Status | assigned => resolved |
| 2021-05-11 22:54 | Christian Grothoff | Resolution | open => fixed |
| 2021-05-11 22:54 | Christian Grothoff | Fixed in Version | => 0.9 |
| 2021-05-11 22:54 | Christian Grothoff | Note Added: 0017836 | |
| 2021-07-30 13:57 | Christian Grothoff | Fixed in Version | 0.9 => 0.8.1 |
| 2021-07-30 13:59 | Christian Grothoff | Target Version | 0.9 => 0.8.1 |
| 2021-07-30 14:01 | Christian Grothoff | Fixed in Version | 0.8.1 => 0.8 |
| 2021-07-30 14:02 | Christian Grothoff | Target Version | 0.8.1 => 0.8 |
| 2021-08-24 16:23 | Christian Grothoff | Status | resolved => closed |
