search

PrivateStorageio / ZKAPAuthorizer

a Tahoe-LAFS storage-system plugin which authorizes storage operations based on privacy-respecting tokens
10 stars 7 forks source link

UNIQUE constraint failed: unblinded-tokens.token #437

Closed exarkun closed 2 years ago

exarkun commented 2 years ago

Apparently redemption can result in this exception:

[_zkapauthorizer.controller.PaymentController#critical] Redeeming random tokens for a voucher (b'...') encountered error.
   Traceback (most recent call last):
     File "twisted\internet\defer.py", line 1791, in gotResult

     File "twisted\internet\defer.py", line 1781, in _inlineCallbacks

     File "twisted\internet\defer.py", line 695, in callback

     File "twisted\internet\defer.py", line 797, in _startRunCallbacks

   --- <exception caught here> ---
     File "twisted\internet\defer.py", line 891, in _runCallbacks

     File "_zkapauthorizer\controller.py", line 933, in _redeem_success

     File "_zkapauthorizer\model.py", line 223, in with_cursor

     File "_zkapauthorizer\model.py", line 565, in insert_unblinded_tokens_for_voucher

     File "_zkapauthorizer\replicate.py", line 538, in executemany

   sqlite3.IntegrityError: UNIQUE constraint failed: unblinded-tokens.token

It may be transient. It's not entirely clear to me how this case can arise, though.

meejah commented 2 years ago

If this is from the same log I looked at, I think it is transient -- or at least, some more tokens were added successfully later in the log.

exarkun commented 2 years ago

A closer reading of the log reveals:

2022-09-19T10:19:17-0700 [twisted.python.log#info] web: 127.0.0.1 GET /storage-plugins/privatestorageio-zkapauthz-v2/voucher 200 16
2022-09-19T10:19:19-0700 [_zkapauthorizer.resource._VoucherCollection#info] Accepting a voucher (VVV) for redemption.
2022-09-19T10:19:19-0700 [_zkapauthorizer.controller.PaymentController#info] Starting redemption of b'VVV'[0..16] for 150000 tokens.
2022-09-19T10:19:19-0700 [_zkapauthorizer.controller.PaymentController#info] Generating random tokens for a voucher (b'VVV').
2022-09-19T10:19:19-0700 [_zkapauthorizer.model.VoucherStore#info] Persisting 9375 random tokens for a voucher (VVV[0]).
2022-09-19T10:19:19-0700 [_zkapauthorizer.controller.PaymentController#info] Redeeming random tokens for a voucher (Voucher(number=b'VVV', expected_tokens=150000, created=datetime.datetime(2022, 9, 19, 17, 19, 19, 728643, tzinfo=+0:00:00 UTC), state=Pending(counter=0))).
2022-09-19T10:19:21-0700 [twisted.python.log#info] web: 127.0.0.1 PUT /storage-plugins/privatestorageio-zkapauthz-v2/voucher 200 -
2022-09-19T10:19:21-0700 [twisted.python.log#info] web: 127.0.0.1 GET /storage-plugins/privatestorageio-zkapauthz-v2/voucher 200 255
2022-09-19T10:19:21-0700 [twisted.python.log#info] web: 127.0.0.1 GET /storage-plugins/privatestorageio-zkapauthz-v2/voucher/VVV 200 239
2022-09-19T10:19:21-0700 [twisted.python.log#info] web: 127.0.0.1 GET /storage-plugins/privatestorageio-zkapauthz-v2/voucher 200 255
2022-09-19T10:19:23-0700 [twisted.python.log#info] web: 127.0.0.1 GET /storage-plugins/privatestorageio-zkapauthz-v2/voucher 200 255
2022-09-19T10:19:24-0700 [twisted.web.client._HTTP11ClientFactory#info] Starting factory _HTTP11ClientFactory(<function HTTPConnectionPool._newConnection.<locals>.quiescentCallback at 0x00000243CD6EAA70>, <twisted.internet.endpoints._WrapperEndpoint object at 0x00000243CDD16C80>)
2022-09-19T10:19:25-0700 [twisted.python.log#info] web: 127.0.0.1 GET /storage-plugins/privatestorageio-zkapauthz-v2/voucher 200 255
2022-09-19T10:19:27-0700 [twisted.python.log#info] web: 127.0.0.1 GET /storage-plugins/privatestorageio-zkapauthz-v2/voucher 200 255
2022-09-19T10:19:29-0700 [twisted.python.log#info] web: 127.0.0.1 GET /storage-plugins/privatestorageio-zkapauthz-v2/voucher 200 255
2022-09-19T10:19:31-0700 [twisted.python.log#info] web: 127.0.0.1 GET /storage-plugins/privatestorageio-zkapauthz-v2/voucher 200 255
2022-09-19T10:19:33-0700 [twisted.python.log#info] web: 127.0.0.1 GET /storage-plugins/privatestorageio-zkapauthz-v2/voucher 200 255
2022-09-19T10:19:34-0700 [_zkapauthorizer.resource._VoucherCollection#info] Accepting a voucher (VVV) for redemption.
2022-09-19T10:19:34-0700 [_zkapauthorizer.controller.PaymentController#info] Starting redemption of b'VVV'[0..16] for 150000 tokens.
2022-09-19T10:19:34-0700 [_zkapauthorizer.model.VoucherStore#info] Loaded 9375 random tokens for a voucher (VVV[0]).
2022-09-19T10:19:34-0700 [_zkapauthorizer.controller.PaymentController#info] Redeeming random tokens for a voucher (Voucher(number=b'VVV', expected_tokens=150000, created=datetime.datetime(2022, 9, 19, 17, 19, 19, 728643, tzinfo=+0:00:00 UTC), state=Pending(counter=0))).
2022-09-19T10:19:35-0700 [twisted.python.log#info] web: 127.0.0.1 PUT /storage-plugins/privatestorageio-zkapauthz-v2/voucher 200 -

In particular, notice two instances of:

PUT /storage-plugins/privatestorageio-zkapauthz-v2/voucher 200 -

and two instances of:

Accepting a voucher (VVV) for redemption.

It seems the same voucher was loaded into the node twice. This should be idempotent, I guess, to allow client retries in the face of errors. And it is ... kind of. The two vouchers will share the same set of tokens. However, PaymentController will try concurrent redemptions of those same tokens, too, and whichever of those processes loses the race will try to insert duplicate signed tokens into the database and provoke this UNIQUE constraint failure. PaymentController.redeem probably needs to notice if a voucher is already redeeming.

There's even some logic for that already too. But PaymentController.redeem jumps over it and goes straight to the database instead, woops.