[BUG] Two concurrent transactions get the same snapshot

[maxmanuylov]

Describe the bug
Two concurrent write transactions can get the same snapshot, which leads to one of them being ignored in the consequence read requests.

To Reproduce
Below is the minimal example. Steps to reproduce:

1. docker-compose up
2. test.sh

The test script creates three relations, then removes two of them simultaneously. In some runs everything is ok, but in some — both relations get marked as expired in DB, but only one of them is reflected in the "check" requests.

docker-compose.yaml

services:
  postgres:
    image: postgres:17-alpine
    environment:
      POSTGRES_USER: pg
      POSTGRES_PASSWORD: pg
      POSTGRES_DB: permify
    ports: [ "5434:5432" ]

  permify:
    image: ghcr.io/permify/permify:v1.4.6
    environment:
      PERMIFY_DATABASE_ENGINE: postgres
      PERMIFY_DATABASE_URI: postgres://pg:pg@postgres:5432/permify?sslmode=disable
    ports: [ "3477:3476" ]
    depends_on: [ postgres ]

schema.perm

entity user {}

entity doc {
  relation can_read    @user
  relation can_comment @user
  relation can_edit    @user

  action read    = can_read
  action comment = can_comment
  action edit    = can_edit
}

test.sh

#!/bin/bash
set -e

# Write schema
curl -sS -w '\n' 'http://localhost:3477/v1/tenants/t1/schemas/write' \
     -H "Content-Type: application/json" \
     -d "$(cat "schema.perm" | jq -Rs '{schema: . }')"

# Grant permissions
curl -sS -w '\n' 'http://localhost:3477/v1/tenants/t1/data/write' \
     -H "Content-Type: application/json" \
     -d '{
         "metadata": {},
         "tuples": [
             {"entity": {"type": "doc", "id": "d1"}, "relation": "can_read", "subject": {"type": "user", "id": "u1"}},
             {"entity": {"type": "doc", "id": "d1"}, "relation": "can_comment", "subject": {"type": "user", "id": "u1"}},
             {"entity": {"type": "doc", "id": "d1"}, "relation": "can_edit", "subject": {"type": "user", "id": "u1"}}
         ]
     }'

# Define functions
function check_access() {
    ACTION=$1

    curl -sS -w '\n' 'http://localhost:3477/v1/tenants/t1/permissions/check' \
         -H "Content-Type: application/json" \
         -d "$(jq -Rn --arg action "$ACTION" '{
             metadata: {depth: 20},
             entity: {type: "doc", id: "d1"},
             permission: $action,
             subject: {type: "user", id: "u1"}
         }')"
}

function drop_access() {
    RELATION=$1

    curl -sS -w '\n' 'http://localhost:3477/v1/tenants/t1/data/delete' \
         -H "Content-Type: application/json" \
         -d "$(jq -Rn --arg relation "$RELATION" '{
             tuple_filter: {
                 entity: {type: "doc", id: "d1"},
                 relation: $relation,
                 subject: {type: "user", ids: ["u1"]}
             },
             attribute_filter: {}
         }')"
}

echo "READ    = $(check_access 'read')"
echo "COMMENT = $(check_access 'comment')"
echo "EDIT    = $(check_access 'edit')"

drop_access 'can_comment' &
PID1=$!
drop_access 'can_edit' &
PID2=$!
wait $PID1
wait $PID2

echo "READ    = $(check_access 'read')"
echo "COMMENT = $(check_access 'comment')"
echo "EDIT    = $(check_access 'edit')"

sleep 10

echo "READ    = $(check_access 'read')"
echo "COMMENT = $(check_access 'comment')"
echo "EDIT    = $(check_access 'edit')"

Here is an example output of a good run:

{"schema_version":"d3svbsniceas738hr2e0"}
{"snap_token":"MAMAAAAAAAA="}
READ    = {"can":"CHECK_RESULT_ALLOWED","metadata":{"check_count":2}}
COMMENT = {"can":"CHECK_RESULT_ALLOWED","metadata":{"check_count":2}}
EDIT    = {"can":"CHECK_RESULT_ALLOWED","metadata":{"check_count":2}}
{"snap_token":"MgMAAAAAAAA="}
{"snap_token":"MwMAAAAAAAA="}
READ    = {"can":"CHECK_RESULT_ALLOWED","metadata":{"check_count":2}}
COMMENT = {"can":"CHECK_RESULT_DENIED","metadata":{"check_count":2}}
EDIT    = {"can":"CHECK_RESULT_DENIED","metadata":{"check_count":2}}
READ    = {"can":"CHECK_RESULT_ALLOWED","metadata":{"check_count":1}}
COMMENT = {"can":"CHECK_RESULT_DENIED","metadata":{"check_count":1}}
EDIT    = {"can":"CHECK_RESULT_DENIED","metadata":{"check_count":1}}

And here is an example output of a bad run:

{"schema_version":"d3svat7iceas738hr2b0"}
{"snap_token":"DQMAAAAAAAA="}
READ    = {"can":"CHECK_RESULT_ALLOWED","metadata":{"check_count":2}}
COMMENT = {"can":"CHECK_RESULT_ALLOWED","metadata":{"check_count":2}}
EDIT    = {"can":"CHECK_RESULT_ALLOWED","metadata":{"check_count":2}}
{"snap_token":"DgMAAAAAAAA="}
{"snap_token":"DwMAAAAAAAA="}
READ    = {"can":"CHECK_RESULT_ALLOWED","metadata":{"check_count":2}}
COMMENT = {"can":"CHECK_RESULT_ALLOWED","metadata":{"check_count":2}}
EDIT    = {"can":"CHECK_RESULT_DENIED","metadata":{"check_count":2}}
READ    = {"can":"CHECK_RESULT_ALLOWED","metadata":{"check_count":1}}
COMMENT = {"can":"CHECK_RESULT_ALLOWED","metadata":{"check_count":1}}
EDIT    = {"can":"CHECK_RESULT_DENIED","metadata":{"check_count":1}}

Here is the DB dump showing that several transactions get same snapshot on bad runs. Good runs get different snapshot.

Expected behavior
All runs are good

Workaround
For those looking for a workaround until this is fixed: looks like the only guaranteed way to have the actual data in your "check" requests is to make additional fake write after every actual write — this touches the snapshot and makes your actual write visible.

Environment (please complete the following information, because it helps us investigate better):

• OS: macOS 14.3.1
• Permify: 1.4.6

[tolgaozen]

Hey @maxmanuylov, we’ve fixed this issue and deployed a nightly release. Could you try it using this image: ghcr.io/permify/permify:v1.4.8?

We’ve also added this case to the integration-test/race_condition section:
https://github.com/Permify/permify/tree/master/integration-test/race_condition

You can check there to see the test case we used.

[maxmanuylov]

@tolgaozen thanks for the fix! Just checked the version 1.4.8 - the probability of a race is much less now, though, unfortunately, it still occurs.

[tolgaozen]

Hey @maxmanuylov, are you experiencing the same issue? I ran 10 separate parallel tests and didn’t encounter any issue. What kind of test case should I run?

[maxmanuylov]

@tolgaozen My original test is in Go and is much bigger than this example, here I just wanted to simplify things. And the original one still fails (but much less often).

Also, I was investigating another issue (for which I do not have a minimal example) with Permify returning ERROR_CODE_SCHEMA_NOT_FOUND for an existing schema and found a bug that may be related to this issue as well. I created PR with the fix: #2580

[tolgaozen]

@maxmanuylov Thanks for the PR — I reviewed it and saw the issue, I’ll go ahead and merge it. Could you share the large test via email for the other topic? That way, I can find it more quickly. My email is tolga@permify.co

[maxmanuylov]

Sorry, the code belongs to my employer, I cannot share it. I will check if my PR fixed the issue and will try to make another minimal example, if not.

[tolgaozen]

No problem. Just let me know the outcome here, whether it’s positive or negative. Thanks

[maxmanuylov]

Sure. Can you release a new version with the fix, please, so I could check it?

[tolgaozen]

@maxmanuylov, I’ve released it as a nightly build. You can test it using this image: ghcr.io/permify/permify-beta:v1.4.9-c219fe8e.

[maxmanuylov]

It works now, thanks a lot!