View Issue Details

IDProjectCategoryView StatusLast Update
0006854Talerexchangepublic2021-08-24 16:23
Reportersebasjm Assigned ToChristian Grothoff  
PrioritynormalSeveritymajorReproducibilitysometimes
Status closedResolutionfixed 
Product Versiongit (master) 
Target Version0.8Fixed in Version0.8 
Summary0006854: exchange get into a loop checking from transaction
DescriptionAbout 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 Reproducecreate an order
pay it
wait for the exchange to wire the amount to the merchant
wait....
try to inform the transfer
TagsNo tags attached.

Activities

Christian Grothoff

2021-05-09 10:35

manager   ~0017798

Are you sure it is the *Exchange* going into a loop here? Looks more like the merchant has a problem (from the logs).

Christian Grothoff

2021-05-09 12:46

manager   ~0017799

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.

sebasjm

2021-05-10 14:51

developer   ~0017808

ACK, will check

sebasjm

2021-05-10 18:34

developer   ~0017809

now it blow ups in taler-merchant-httpd_private-post-transfers.c:1030, maybe should be a break instead of a assert?

sebasjm

2021-05-11 05:30

developer   ~0017814

Last edited: 2021-05-11 05:30

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'!

sebasjm

2021-05-11 05:48

developer   ~0017815

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.

Christian Grothoff

2021-05-11 12:32

manager   ~0017820

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?

Christian Grothoff

2021-05-11 12:55

manager   ~0017823

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()?

sebasjm

2021-05-11 16:00

developer   ~0017827

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.

sebasjm

2021-05-11 16:04

developer   ~0017828

Test pushed at 0bcf8ea8..332630ca

break will be trigger doing the api call at line 305

Christian Grothoff

2021-05-11 19:23

manager   ~0017832

I found some transaction issues in POST /transfer logic, fixed in 332630c..906e303.

Christian Grothoff

2021-05-11 19:24

manager   ~0017833

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.

Christian Grothoff

2021-05-11 20:28

manager   ~0017834

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!

Christian Grothoff

2021-05-11 22:50

manager   ~0017835

63abbe2..dfdd322 removes the GNUNET_break(), as this can legitimately happen if the exchange's response was ever non-successful.

Christian Grothoff

2021-05-11 22:54

manager   ~0017836

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

Issue History

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