View Issue Details

IDProjectCategoryView StatusLast Update
0009240Talermechant backendpublic2024-12-13 19:15
ReporterChristian Grothoff Assigned ToChristian Grothoff  
PrioritynormalSeverityminorReproducibilityhave not tried
Status closedResolutionfixed 
Platformi7OSDebian GNU/LinuxOS Versionsqueeze
Product Versiongit (master) 
Target Version0.14Fixed in Version0.14 
Summary0009240: test_merchant_product_creation fails
Descriptiontaler-merchant-keycheck didn't get the /keys from the exchange before order creation was attempted and then order creation fails.

The main issue is whether the keycheck tool long-polls for /keys, as the test *does* wait until the exchange /keys is ready, but the merchant presumably doesn't notice on time.
Steps To ReproduceBogdahn's (slow-ish) server had the test case failure.
TagsNo tags attached.

Activities

Christian Grothoff

2024-10-02 20:22

manager   ~0023429

I tried to reproduce this, including artificially slowing down /keys generation on my system. Didn't work. I added a bit more logging that may help diagnose, but I think we need to try again on your VM to figure this one out...

Christian Grothoff

2024-10-06 13:59

manager   ~0023447

Last edited: 2024-10-06 14:05

Timeline:

2024-10-06T11:53:11.101550+0000 taler-exchange-httpd-240051(H4ZFR6YBZEYC3SJ2YJ1H36XTE8) INFO Handling request (GET) for URL '/keys'
2024-10-06T11:53:11.204806+0000 taler-exchange-httpd-240051(H4ZFR6YBZEYC3SJ2YJ1H36XTE8) INFO Suspend
ing /keys request until key material changes

2024-10-06T11:53:13.837262+0000 taler-merchant-httpd-240130(16FCGCFEPH8AA1S07CQQ19TZ14) INFO Trying to find chosen exchange `http://localhost:8081/'
2024-10-06T11:53:13.837281+0000 taler-merchant-httpd-240130(16FCGCFEPH8AA1S07CQQ19TZ14) INFO Still trying to (re)load http://localhost:8081/keys

2024-10-06T11:53:14.004834+0000 taler-exchange-httpd-240051(H4ZFR6YBZEYC3SJ2YJ1H36XTE8) INFO Request for `/keys' took 2903 ms

2024-10-06T11:53:14.087601+0000 taler-merchant-httpd-240130(16FCGCFEPH8AA1S07CQQ19TZ14) WARNING Cannot create order: lacking trusted exchanges

2024-10-06T11:53:14.016836+0000 taler-merchant-exchangekeyupdate-240128 INFO Received keys from URL
`http://localhost:8081/keys' with status 200 and expiration Mon Oct 14 00:00:00 2024.
2024-10-06T11:53:14.170630+0000 taler-merchant-exchangekeyupdate-240128 INFO Committing merchant DB transaction update exchange key data

Christian Grothoff

2024-10-06 14:04

manager   ~0023448

Explanation: it seems things are mostly working:
1) The exchange is suspending /keys until it has the full response
2) The merchant exchangekeyupdate service is long-polling and serializing the result to the DB ASAP
3) The test case waits for /keys to be ready before launching into order creation
4) The merchant httpd service waits 250ms on /keys
5) But the merchant httpd service fails hard on order creation just before steps 1-4 can finish.

Christian Grothoff

2024-10-06 14:07

manager   ~0023449

Bumping the timeout to 750ms allows the test to pass. Bumped it to 2500ms in 4998506a..f0162d05 to be reasonable conservative also for even slower systems than this one.

Christian Grothoff

2024-10-06 14:09

manager   ~0023450

Note: you'll need to rebase your branch to get the test to pass.

Issue History

Date Modified Username Field Change
2024-10-02 15:24 Christian Grothoff New Issue
2024-10-02 15:24 Christian Grothoff Status new => assigned
2024-10-02 15:24 Christian Grothoff Assigned To => Christian Grothoff
2024-10-02 20:22 Christian Grothoff Assigned To Christian Grothoff => Bohdan
2024-10-02 20:22 Christian Grothoff Status assigned => feedback
2024-10-02 20:22 Christian Grothoff Note Added: 0023429
2024-10-05 22:32 Christian Grothoff Assigned To Bohdan => Christian Grothoff
2024-10-05 22:33 Christian Grothoff Status feedback => assigned
2024-10-06 13:59 Christian Grothoff Note Added: 0023447
2024-10-06 14:04 Christian Grothoff Note Added: 0023448
2024-10-06 14:05 Christian Grothoff Note Edited: 0023447
2024-10-06 14:07 Christian Grothoff Note Added: 0023449
2024-10-06 14:07 Christian Grothoff Status assigned => resolved
2024-10-06 14:07 Christian Grothoff Resolution open => fixed
2024-10-06 14:07 Christian Grothoff Fixed in Version => 0.14
2024-10-06 14:09 Christian Grothoff Note Added: 0023450
2024-12-13 19:15 Christian Grothoff Status resolved => closed