Another (relatively minor) race condition

[glasserc]

This program:

"""
Another race-trash script that tries to race delete-bucket with checking for some records
"""
import aiohttp
import asyncio
import async_timeout
import base64
import psycopg2

AUTH = 'Basic ' + base64.b64encode(b'test:test').decode('utf-8')
BUCKET = 'http://localhost:8888/v1/buckets/default'
COLLECTION = BUCKET + '/collections/storage-sync-crypto'
RECORDS_URL = COLLECTION + '/records?_since=0'
A_CERTAIN_RECORD = COLLECTION + '/records/keys'

async def get_new_records(session):
    await asyncio.sleep(.01)    # You might have to modify this number to taste -- I just chose numbers until I saw the delete happen before/after the get in the output
    with async_timeout.timeout(10):
        async with session.get(RECORDS_URL) as response:
            resp = await response.json()
            print(resp)
            assert response.status == 200


async def put_record(session):
    with async_timeout.timeout(10):
        async with session.put(A_CERTAIN_RECORD, data='{"data": {"a": 1}}', headers=[("Content-Type", "application/json")]) as response:
            resp = await response.json()
            print(resp)
            assert response.status < 300


async def delete_bucket(session):
    async with session.delete(BUCKET) as response:
        text = await response.text()
        print(text)
        assert response.status == 200


def check_both_deleted_and_records(conn):
    cur = conn.cursor()
    cur.execute("SELECT * FROM records r JOIN deleted d ON (r.id = d.id AND r.parent_id = d.parent_id AND r.collection_id = d.collection_id);")
    assert not cur.fetchone()
    cur.close()


async def main():
    conn = psycopg2.connect("dbname=postgres user=postgres password=postgres host=localhost")
    async with aiohttp.ClientSession(headers={"Authorization": AUTH}) as session1:
        await put_record(session1)
        things = [
            delete_bucket(session1),
            get_new_records(session2),
        ]
        await asyncio.gather(*things)
        check_both_deleted_and_records(conn)
    conn.close()

loop = asyncio.get_event_loop()
loop.run_until_complete(main())

Eventually fails:

{'permissions': {'write': ['basicauth:44ac0e1157457b4ff75a88b490cd735f73a27d5c8ac5b3fb4672d449969d88ea']}, 'data': {'a': 1, 'id': 'keys', 'last_modified': 1511369823965}}
{"data":{"last_modified":1511369824042,"id":"3f2e55d2-25ad-5fa9-3dcb-c0f29235627f","deleted":true}}
{'code': 403, 'errno': 121, 'error': 'Forbidden', 'message': 'This user cannot access this resource.'}
Traceback (most recent call last):
  File "../race-trash-2.py", line 61, in <module>
    loop.run_until_complete(main())
  File "/usr/lib64/python3.6/asyncio/base_events.py", line 467, in run_until_complete
    return future.result()
  File "../race-trash-2.py", line 56, in main
    await asyncio.gather(*things)
  File "../race-trash-2.py", line 22, in get_new_records
    assert response.status == 200
AssertionError

In the logs:

2017-11-22 11:57:04,127 WARNI [kinto.core.authorization][waitress] Permission 'read' on '/buckets/3f2e55d2-25ad-5fa9-3dcb-c0f29235627f/collections/storage-sync-crypto/records' not granted to 'basicauth:44ac0e1157457b4ff75a88b490cd735f73a27d5c8ac5b3fb4672d449969d88ea'.

[leplatrem]

More generally, this is due to the fact that the storage and the permission backends are split.

We could investigate about 2-phase commits

[glasserc]

I could be wrong, but I wonder if 2-phase commit would even be helpful here -- the problem isn't that some transactions succeed and some don't, the problem is that with READ COMMITTED we can get changes in the middle of our transactions.