View Issue Details

IDProjectCategoryView StatusLast Update
0005258Talermechant backendpublic2018-04-15 20:33
ReporterFlorian Dold Assigned ToChristian Grothoff  
PrioritynormalSeverityminorReproducibilityhave not tried
Status closedResolutionfixed 
Product Versiongit (master) 
Target Version0.5Fixed in Version0.5 
Summary0005258: db error when picking up tip twice
DescriptionThere is some problem in the tipping logic of the merchant backend. The
/tip-approve is successful, but /tip-pickup returns an error (this
should prettty much never happen!), but (seemingly?) only the second
time that /test-pickup is queried. The error response does not make any
sense.

I suspect that this is due the recent changes how tipping checks if
the tipping reserve is sufficient?

BTW, I feature I'd like to see is /tip-approve returning the
(approximate?) tipping amount left, so the frontend can react properly.
Steps To ReproduceHere's a request that Chrome made (converted to curl via the DevTools)
and that will trigger the error:

curl 'https://backend.test.taler.net/tip-pickup' -H 'Pragma: no-cache'
-H 'Origin: chrome-extension://kiefficopbhhojgbggjjcfbinofpnljf' -H
'Accept-Encoding: gzip, deflate, br' -H 'Accept-Language:
en-US,en;q=0.9,de-DE;q=0.8,de;q=0.7' -H 'User-Agent: Mozilla/5.0 (X11;
Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.94
Safari/537.36' -H 'Content-Type: application/json;charset=UTF-8' -H
'Accept: application/json, text/plain, */*' -H 'Cache-Control: no-cache'
-H 'Connection: keep-alive' --data-binary
'{"planchets":[{"coin_ev":"JEVPHNBZEC9F887GK59KC1YM0XWCWETABV84RHKZGZFK99ADYD"},{"coin_ev":"PC63KC8NS5JPXBVA67N8DSYTSS9B0TBMACEMRVW44VHRZZZQ"},{"coin_ev":"VSMYT1CCHV27HXEH333ZYBAYV4JJZ5PVW6JMNN0355GWC98M"},{"coin_ev":"42AAF1GPXZ88WSD7PFNSMV0HP2H62XH9YYCA25NF5ES5EPYC",
"denom_pub_hash":"98G73X7GMAH1C55ED1WENS"},
...
],"tip_id":"1476PP1KSPE8QEEAZE5SDX8"}'
--compressed

The response is:

{
  "code": 2801,
  "error": "Database error approving tip"
}
Additional InformationThese are the logs:

Jan 19 00:30:24-239001 taler-merchant-httpd-7921 INFO Handling request
(POST) for URL `/tip-pickup'
Jan 19 00:30:24-239309 taler-merchant-httpd-7921 WARNING External
protocol violation detected at plugin_merchantdb_postgres.c:3235.
TagsNo tags attached.

Activities

Christian Grothoff

2018-01-19 02:04

manager   ~0012808

Very strange, I've now expanded the testcase (uncomment the #if B5258 line), and I get a _different_ error (2800 instead 2801). Yours suggests that the set of planchets between the two withdrawals changed, and hence the backend rejects your 2nd request. So that one _may_ not even be a bug.

Florian Dold

2018-01-19 02:13

manager   ~0012809

I'm relatively sure that the wallet used the same planchets (since we're storing them in the DB before sending them with (tipId, merchantDomain) as a key. Might have been some race condition though ...

However the wallet is now very careful to never accidentally requesting /tip-pickup twice, so tipping works again.

Even if the wallet would have sent different planchets, the error message is still wrong (it refers to approving the tip, even though we're in /tip-pickup and the tip already has been approved).

Christian Grothoff

2018-01-19 02:21

manager   ~0012810

Eh, you got 2801, which reads:
  /**
   * The amount requested exceeds the remaining tipping balance for this tip ID.
   * Returned with an HTTP status code of "service unavailable".
   */
  TALER_EC_TIP_PICKUP_NO_FUNDS = 2801,

How is this wrong? If you did pick up a 2nd time, with different coins, this is the perfect error code.

Florian Dold

2018-01-19 02:26

manager   ~0012811

Well what's wrong/confusing is the accompanying hint "Database error approving tip".

Also, the HTTP status code 503 service unavailable is completely off, since it would imply that there is something wrong with the *merchant backend* server, not the client (=wallet).

So when I saw this, my conclusion without further investigation was "there is something wrong with the backend", as suggested by both the error hint and the HTTP status code.

Christian Grothoff

2018-01-19 02:27

manager   ~0012812

I've fixed the human-readable hint now.

Christian Grothoff

2018-01-19 02:29

manager   ~0012813

Fair enough, it should be a 409, not a 503. Fixed.

Christian Grothoff

2018-01-22 20:15

manager   ~0012819

00d2528..bd79913 fixes the 12808 issue.

Issue History

Date Modified Username Field Change
2018-01-19 01:16 Florian Dold New Issue
2018-01-19 01:16 Florian Dold Status new => assigned
2018-01-19 01:16 Florian Dold Assigned To => Christian Grothoff
2018-01-19 01:51 Christian Grothoff Steps to Reproduce Updated
2018-01-19 02:04 Christian Grothoff Note Added: 0012808
2018-01-19 02:13 Florian Dold Note Added: 0012809
2018-01-19 02:21 Christian Grothoff Note Added: 0012810
2018-01-19 02:26 Florian Dold Note Added: 0012811
2018-01-19 02:27 Christian Grothoff Note Added: 0012812
2018-01-19 02:29 Christian Grothoff Note Added: 0012813
2018-01-22 20:15 Christian Grothoff Note Added: 0012819
2018-01-22 20:17 Christian Grothoff Status assigned => resolved
2018-01-22 20:17 Christian Grothoff Resolution open => fixed
2018-01-22 20:17 Christian Grothoff Fixed in Version => 0.5
2018-04-15 20:33 Christian Grothoff Status resolved => closed