View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0009780 | Taler | merchant backend | public | 2025-04-23 22:07 | 2025-04-28 02:27 |
| Reporter | Florian Dold | Assigned To | Christian Grothoff | ||
| Priority | normal | Severity | major | Reproducibility | have not tried |
| Status | resolved | Resolution | fixed | ||
| Product Version | git (master) | ||||
| Target Version | 1.0 | ||||
| Summary | 0009780: merchant fails to re-fetch GET /keys when exchange loses keys | ||||
| Description | On a /pay request, the merchant claims that the exchange is not responding: "hint": "Unexpected HTTP status (504) in response", "requestUrl": "http://localhost:8083/orders/2025.113-03PF97V0EQX4Y/pay", "requestMethod": "POST", "httpStatusCode": 504, "errorResponse": { "code": 2011, "hint": "The exchange failed to respond to the merchant on time." } However, the merchant *actually* just refuses to re-fetch keys in time: --- denom-unoffered/merchant-httpd-testmerchant-1-stderr.log 2025-04-23T21:05:08.797910+0200 taler-merchant-httpd-310062(2M7R2V83D8VECKBBY62NVH9DXW) INFO Have missing denomination for exchange, updating http://localhost:8081/ 2025-04-23T21:05:08.797914+0200 taler-merchant-httpd-310062(2M7R2V83D8VECKBBY62NVH9DXW) INFO Forcing /keys download (once) as wire fees are unknown --- denom-unoffered/merchant-exchangekeyupdate-testmerchant-1-stderr.log 2025-04-23T21:05:08.798036+0200 taler-merchant-exchangekeyupdate-310063 INFO Received notification xr6bnxxwqkrdeav03was555tqge98215a7ckh4a0jjdy7b8w6023g with extra data `http://localhost:8081/' 2025-04-23T21:05:08.798043+0200 taler-merchant-exchangekeyupdate-310063 INFO Received keys change notification: reload `http://localhost:8081/' 2025-04-23T21:05:08.798048+0200 taler-merchant-exchangekeyupdate-310063 INFO Will download http://localhost:8081/keys in 299 | ||||
| Steps To Reproduce | $ taler-harness run-integrationtests denom-unoffered | ||||
| Tags | No tags attached. | ||||
|
|
Sure, that's a little white lie. To avoid merchants DDoSing us by accident, we do enforce a minimum delay between /keys fetches, so IMO that's by design. You'll have to time-travel for 5 minutes. |
|
|
We can discuss if you want, but I don't consider this a bug, but "work as intended". |
|
|
I've added the time travel (6 minutes), and it still doesn't work: The merchant continues reporting 504. That is *despite* the merchant-exchangekeyupdate-testmerchant logs reporting a re-fetch of the exchange keys (*after* taler-exchange-httpd was restarted the keys purge, based on the log timestamps). |
|
|
Eh, which process did you timetravel? It looks like you send taler-merchant-httpd into the future, and not taler-merchant-exchangekeyupdate! |
|
|
I'm time-travelling them *both*! And indeed the taler-merchant-exchangekeyupdate is re-started with time-travel. See the harness logs: 2025-04-25T23:05:53.666Z harness.ts INFO spawning process (merchant-exchangekeyupdate-testmerchant-1): taler-merchant-exchangekeyupdate taler-merchant-exchangekeyupdate -LDEBUG -c '/tmp/taler-integrationtests-jpA5Vg/denom-unoffered/merchant-testmerchant-1.conf' '--timetravel=+360000000' Maybe the process doesn't properly support time travel?! |
|
|
Can't be, the timetravel logic is the same everywhere. But the timestamps I saw in the logs were completely different, with taler-merchant-exchangekeyupdate timestamps being 5 minutes *before* taler-merchant-httpd, and taler-merchant-httpd being 5 minutes after the file system time for the log file, so it definitively didn't look like exchangkeyupdate had time-travelled. |
|
|
I've worked a bit more on this bug. AFAIK the merchant should *really* be fine now, I fixed one issue where we would return 504 even though we simply had a very current /keys response. Additionally, I'm storing the "earliest" retry time for a /keys download now in the merchant database, which has some further implications on the test. Now, the test works completely differently from what I thought it was doing, which cost me a ton of time. So let me explain what I think is going on. (1) wallet withdraws coins, (2) denomination of that coin is removed (revoked?) from exchange, (3) wallet tries to pay with now unknown denomination. As a result, the test now fails because the merchant does NOT have the latest /keys at all, forwards the deposit request, which fails at the exchange, and then the merchant passes that error back to the wallet. All of that happens *before* the test even tries to timetravel, within 2 seconds (!). So if you want to see the merchant reject the request, you need to timetravel the merchant and force it to download the new /keys. Note that the mechant downloads /keys if we get a coin of a denomination that we do NOT know, not if all denominations do appear in the known /keys response! |
|
|
It indeed works as expected now. It's possible that I misinterpreted where the 504 response came from, but it was incorrect and tripping up the test case (and me ;- ). |
| Date Modified | Username | Field | Change |
|---|---|---|---|
| 2025-04-23 22:07 | Florian Dold | New Issue | |
| 2025-04-23 22:07 | Florian Dold | Status | new => assigned |
| 2025-04-23 22:07 | Florian Dold | Assigned To | => Christian Grothoff |
| 2025-04-24 00:19 | Christian Grothoff | Note Added: 0024656 | |
| 2025-04-24 00:19 | Christian Grothoff | Assigned To | Christian Grothoff => |
| 2025-04-24 00:19 | Christian Grothoff | Status | assigned => acknowledged |
| 2025-04-24 00:19 | Christian Grothoff | Assigned To | => Florian Dold |
| 2025-04-24 00:19 | Christian Grothoff | Status | acknowledged => feedback |
| 2025-04-24 00:19 | Christian Grothoff | Note Added: 0024657 | |
| 2025-04-24 00:19 | Christian Grothoff | Product Version | => git (master) |
| 2025-04-25 16:14 | Florian Dold | Note Added: 0024671 | |
| 2025-04-25 16:14 | Florian Dold | Assigned To | Florian Dold => Christian Grothoff |
| 2025-04-25 22:17 | Christian Grothoff | Note Added: 0024673 | |
| 2025-04-25 22:17 | Christian Grothoff | Assigned To | Christian Grothoff => Florian Dold |
| 2025-04-26 01:07 | Florian Dold | Note Added: 0024674 | |
| 2025-04-26 01:07 | Florian Dold | Assigned To | Florian Dold => Christian Grothoff |
| 2025-04-26 10:36 | Christian Grothoff | Note Added: 0024682 | |
| 2025-04-27 23:33 | Christian Grothoff | Note Added: 0024684 | |
| 2025-04-27 23:33 | Christian Grothoff | Assigned To | Christian Grothoff => Florian Dold |
| 2025-04-27 23:33 | Christian Grothoff | Status | feedback => assigned |
| 2025-04-28 02:27 | Florian Dold | Assigned To | Florian Dold => Christian Grothoff |
| 2025-04-28 02:27 | Florian Dold | Status | assigned => resolved |
| 2025-04-28 02:27 | Florian Dold | Resolution | open => fixed |
| 2025-04-28 02:27 | Florian Dold | Note Added: 0024693 |
