Skip to content

Instantly share code, notes, and snippets.

@aberkovsky

aberkovsky/gist:4ca8fd7227b83772ba6d3fc19cc18595

Created April 18, 2023 11:59
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save aberkovsky/4ca8fd7227b83772ba6d3fc19cc18595 to your computer and use it in GitHub Desktop.
Save aberkovsky/4ca8fd7227b83772ba6d3fc19cc18595 to your computer and use it in GitHub Desktop.
Download ZIP
Bug in SpiceDB
Raw
gistfile1.txt
SpiceDB version: 1.19.1
Datasource: Postgress 14.7
Trace log during insert:
2023-04-18T08:33:57.270778129Z {"level":"debug","module":"pgx","args":[],"commandTag":"BEGIN","pid":4950,"sql":"begin isolation level serializable","time":0.254186,"time":"2023-04-18T08:33:57Z","message":"Query"}
2023-04-18T08:33:57.270818252Z {"level":"debug","module":"pgx","args":[],"commandTag":"BEGIN","pid":4951,"sql":"begin isolation level serializable","time":0.39534,"time":"2023-04-18T08:33:57Z","message":"Query"}
2023-04-18T08:33:57.271289191Z {"level":"debug","module":"pgx","alreadyPrepared":false,"name":"stmtcache_8","pid":4950,"sql":"INSERT INTO relation_tuple_transaction DEFAULT VALUES RETURNING xid, snapshot","time":0.582405,"time":"2023-04-18T08:33:57Z","message":"Prepare"}
2023-04-18T08:33:57.271869951Z {"level":"debug","module":"pgx","alreadyPrepared":false,"name":"stmtcache_9","pid":4951,"sql":"INSERT INTO relation_tuple_transaction DEFAULT VALUES RETURNING xid, snapshot","time":1.029358,"time":"2023-04-18T08:33:57Z","message":"Prepare"}
2023-04-18T08:33:57.273720524Z {"level":"debug","module":"pgx","args":[],"commandTag":"INSERT 0 1","pid":4951,"sql":"INSERT INTO relation_tuple_transaction DEFAULT VALUES RETURNING xid, snapshot","time":2.889267,"time":"2023-04-18T08:33:57Z","message":"Query"}
2023-04-18T08:33:57.274606023Z {"level":"debug","module":"pgx","args":[],"commandTag":"INSERT 0 1","pid":4950,"sql":"INSERT INTO relation_tuple_transaction DEFAULT VALUES RETURNING xid, snapshot","time":3.920537,"time":"2023-04-18T08:33:57Z","message":"Query"}
2023-04-18T08:33:57.275292372Z {"level":"debug","module":"pgx","alreadyPrepared":false,"name":"stmtcache_11","pid":4950,"sql":"SELECT serialized_config, created_xid FROM namespace_config WHERE deleted_xid = $1 AND (namespace = $2 OR namespace = $3)","time":0.489872,"time":"2023-04-18T08:33:57Z","message":"Prepare"}
2023-04-18T08:33:57.275321051Z {"level":"debug","module":"pgx","alreadyPrepared":false,"name":"stmtcache_10","pid":4951,"sql":"SELECT serialized_config, created_xid FROM namespace_config WHERE deleted_xid = $1 AND (namespace = $2 OR namespace = $3)","time":1.490911,"time":"2023-04-18T08:33:57Z","message":"Prepare"}
2023-04-18T08:33:57.278403378Z {"level":"debug","module":"pgx","args":[9223372036854775807,"org","usr"],"commandTag":"SELECT 2","pid":4951,"sql":"SELECT serialized_config, created_xid FROM namespace_config WHERE deleted_xid = $1 AND (namespace = $2 OR namespace = $3)","time":4.5271,"time":"2023-04-18T08:33:57Z","message":"Query"}
2023-04-18T08:33:57.278855411Z {"level":"debug","module":"pgx","args":[9223372036854775807,"usr","org"],"commandTag":"SELECT 2","pid":4950,"sql":"SELECT serialized_config, created_xid FROM namespace_config WHERE deleted_xid = $1 AND (namespace = $2 OR namespace = $3)","time":4.149491,"time":"2023-04-18T08:33:57Z","message":"Query"}
2023-04-18T08:33:57.279139735Z {"level":"debug","module":"pgx","alreadyPrepared":false,"name":"stmtcache_12","pid":4951,"sql":"INSERT INTO relation_tuple (namespace,object_id,relation,userset_namespace,userset_object_id,userset_relation,caveat_name,caveat_context) VALUES ($1,$2,$3,$4,$5,$6,$7,$8),($9,$10,$11,$12,$13,$14,$15,$16),($17,$18,$19,$20,$21,$22,$23,$24),($25,$26,$27,$28,$29,$30,$31,$32),($33,$34,$35,$36,$37,$38,$39,$40)","time":0.637969,"time":"2023-04-18T08:33:57Z","message":"Prepare"}
2023-04-18T08:33:57.279657738Z {"level":"debug","module":"pgx","alreadyPrepared":false,"name":"stmtcache_13","pid":4950,"sql":"INSERT INTO relation_tuple (namespace,object_id,relation,userset_namespace,userset_object_id,userset_relation,caveat_name,caveat_context) VALUES ($1,$2,$3,$4,$5,$6,$7,$8),($9,$10,$11,$12,$13,$14,$15,$16),($17,$18,$19,$20,$21,$22,$23,$24),($25,$26,$27,$28,$29,$30,$31,$32),($33,$34,$35,$36,$37,$38,$39,$40)","time":0.698103,"time":"2023-04-18T08:33:57Z","message":"Prepare"}
2023-04-18T08:33:57.282098159Z {"level":"debug","module":"pgx","args":["usr","j000000005","org","org","pdffiller","...","",null,"usr","j000000006","org","org","test","...","",null,"usr","j000000007","org","org","test","...","",null,"usr","j000000008","org","org","pdffiller","...","",null,"usr","j000000009","org","org","pdffiller","...","",null],"commandTag":"INSERT 0 5","pid":4950,"sql":"INSERT INTO relation_tuple (namespace,object_id,relation,userset_namespace,userset_object_id,userset_relation,caveat_name,caveat_context) VALUES ($1,$2,$3,$4,$5,$6,$7,$8),($9,$10,$11,$12,$13,$14,$15,$16),($17,$18,$19,$20,$21,$22,$23,$24),($25,$26,$27,$28,$29,$30,$31,$32),($33,$34,$35,$36,$37,$38,$39,$40)","time":3.021762,"time":"2023-04-18T08:33:57Z","message":"Query"}
2023-04-18T08:33:57.282167769Z {"level":"debug","module":"pgx","args":["usr","j000000000","org","org","pdffiller","...","",null,"usr","j000000001","org","org","test","...","",null,"usr","j000000002","org","org","test","...","",null,"usr","j000000003","org","org","pdffiller","...","",null,"usr","j000000004","org","org","pdffiller","...","",null],"commandTag":"INSERT 0 5","pid":4951,"sql":"INSERT INTO relation_tuple (namespace,object_id,relation,userset_namespace,userset_object_id,userset_relation,caveat_name,caveat_context) VALUES ($1,$2,$3,$4,$5,$6,$7,$8),($9,$10,$11,$12,$13,$14,$15,$16),($17,$18,$19,$20,$21,$22,$23,$24),($25,$26,$27,$28,$29,$30,$31,$32),($33,$34,$35,$36,$37,$38,$39,$40)","time":3.435398,"time":"2023-04-18T08:33:57Z","message":"Query"}
2023-04-18T08:33:57.286162760Z {"level":"debug","module":"pgx","args":[],"commandTag":"COMMIT","pid":4951,"sql":"commit","time":4.047827,"time":"2023-04-18T08:33:57Z","message":"Query"}
2023-04-18T08:33:57.286401174Z {"level":"info","grpc.component":"server","grpc.method":"WriteRelationships","grpc.method_type":"unary","grpc.service":"authzed.api.v1.PermissionsService","peer.address":"172.20.0.1:42302","protocol":"grpc","requestID":"f24634fefff763e8f709af0a74111cd8","grpc.start_time":"2023-04-18T08:33:57Z","grpc.code":"OK","grpc.time_ms":"17.631","time":"2023-04-18T08:33:57Z","message":"finished call"}
2023-04-18T08:33:57.289824746Z {"level":"debug","module":"pgx","args":[],"commandTag":"COMMIT","pid":4950,"sql":"commit","time":7.794917,"time":"2023-04-18T08:33:57Z","message":"Query"}
2023-04-18T08:33:57.289893832Z {"level":"info","grpc.component":"server","grpc.method":"WriteRelationships","grpc.method_type":"unary","grpc.service":"authzed.api.v1.PermissionsService","peer.address":"172.20.0.1:42328","protocol":"grpc","requestID":"b29bcf63370a650486cdb1402a848047","grpc.start_time":"2023-04-18T08:33:57Z","grpc.code":"OK","grpc.time_ms":"20.072","time":"2023-04-18T08:33:57Z","message":"finished call"}
relation_tuple_transaction:
+--------------------------+-----+------------+
|timestamp |xid |snapshot |
+--------------------------+-----+------------+
|2023-04-18 08:33:57.270302|54474|54474:54474:|
|2023-04-18 08:33:57.270279|54475|54474:54474:|
+--------------------------+-----+------------+
relation_tuple:
+---------+----------+--------+-----------------+-----------------+----------------+-----------+--------------+-----------+-------------------+
|namespace|object_id |relation|userset_namespace|userset_object_id|userset_relation|caveat_name|caveat_context|created_xid|deleted_xid |
+---------+----------+--------+-----------------+-----------------+----------------+-----------+--------------+-----------+-------------------+
|usr |j000000001|org |org |test |... | |null |54475 |9223372036854775807|
|usr |j000000002|org |org |test |... | |null |54475 |9223372036854775807|
|usr |j000000000|org |org |test |... | |null |54475 |9223372036854775807|
|usr |j000000004|org |org |test |... | |null |54475 |9223372036854775807|
|usr |j000000003|org |org |test |... | |null |54475 |9223372036854775807|
|usr |j000000008|org |org |test |... | |null |54474 |9223372036854775807|
|usr |j000000006|org |org |test |... | |null |54474 |9223372036854775807|
|usr |j000000005|org |org |test |... | |null |54474 |9223372036854775807|
|usr |j000000007|org |org |test |... | |null |54474 |9223372036854775807|
|usr |j000000009|org |org |test |... | |null |54474 |9223372036854775807|
+---------+----------+--------+-----------------+-----------------+----------------+-----------+--------------+-----------+-------------------+
Trace log during watch:
2023-04-18T08:33:59.628780390Z {"level":"debug","module":"pgx","args":[54474,54474,54474,54474],"commandTag":"SELECT 5","pid":4949,"sql":"SELECT namespace, object_id, relation, userset_namespace, userset_object_id, userset_relation, caveat_name, caveat_context, created_xid, deleted_xid FROM relation_tuple WHERE ((created_xid <= $1 AND created_xid >= $2) OR (deleted_xid <= $3 AND deleted_xid >= $4))","time":32.197572,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.628982659Z {"level":"debug","module":"pgx","args":[],"commandTag":"BEGIN","pid":4949,"sql":"begin isolation level repeatable read","time":0.285558,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.629377026Z {"level":"debug","module":"pgx","args":[{}],"commandTag":"SELECT 1","pid":4949,"sql":"\n\tSELECT xid, snapshot FROM relation_tuple_transaction\n\tWHERE xid >= pg_snapshot_xmax($1) OR (\n\t\txid >= pg_snapshot_xmin($1) AND NOT pg_visible_in_snapshot(xid, $1)\n\t) ORDER BY pg_xact_commit_timestamp(xid::xid), xid;","time":0.338281,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.629661271Z {"level":"debug","module":"pgx","args":[],"commandTag":"COMMIT","pid":4949,"sql":"commit","time":0.296923,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.662417330Z {"level":"debug","module":"pgx","args":[54475,54475,54475,54475],"commandTag":"SELECT 5","pid":4949,"sql":"SELECT namespace, object_id, relation, userset_namespace, userset_object_id, userset_relation, caveat_name, caveat_context, created_xid, deleted_xid FROM relation_tuple WHERE ((created_xid <= $1 AND created_xid >= $2) OR (deleted_xid <= $3 AND deleted_xid >= $4))","time":32.35166,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.662738909Z {"level":"debug","module":"pgx","args":[],"commandTag":"BEGIN","pid":4949,"sql":"begin isolation level repeatable read","time":0.460614,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.663282241Z {"level":"debug","module":"pgx","args":[{}],"commandTag":"SELECT 1","pid":4949,"sql":"\n\tSELECT xid, snapshot FROM relation_tuple_transaction\n\tWHERE xid >= pg_snapshot_xmax($1) OR (\n\t\txid >= pg_snapshot_xmin($1) AND NOT pg_visible_in_snapshot(xid, $1)\n\t) ORDER BY pg_xact_commit_timestamp(xid::xid), xid;","time":0.446867,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.663681060Z {"level":"debug","module":"pgx","args":[],"commandTag":"COMMIT","pid":4949,"sql":"commit","time":0.310544,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.695725586Z {"level":"debug","module":"pgx","args":[54474,54474,54474,54474],"commandTag":"SELECT 5","pid":4949,"sql":"SELECT namespace, object_id, relation, userset_namespace, userset_object_id, userset_relation, caveat_name, caveat_context, created_xid, deleted_xid FROM relation_tuple WHERE ((created_xid <= $1 AND created_xid >= $2) OR (deleted_xid <= $3 AND deleted_xid >= $4))","time":31.813404,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.696262449Z {"level":"debug","module":"pgx","args":[],"commandTag":"BEGIN","pid":4949,"sql":"begin isolation level repeatable read","time":0.64555,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.696596152Z {"level":"debug","module":"pgx","args":[{}],"commandTag":"SELECT 1","pid":4949,"sql":"\n\tSELECT xid, snapshot FROM relation_tuple_transaction\n\tWHERE xid >= pg_snapshot_xmax($1) OR (\n\t\txid >= pg_snapshot_xmin($1) AND NOT pg_visible_in_snapshot(xid, $1)\n\t) ORDER BY pg_xact_commit_timestamp(xid::xid), xid;","time":0.324967,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.696873872Z {"level":"debug","module":"pgx","args":[],"commandTag":"COMMIT","pid":4949,"sql":"commit","time":0.226394,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.732627468Z {"level":"debug","module":"pgx","args":[54475,54475,54475,54475],"commandTag":"SELECT 5","pid":4949,"sql":"SELECT namespace, object_id, relation, userset_namespace, userset_object_id, userset_relation, caveat_name, caveat_context, created_xid, deleted_xid FROM relation_tuple WHERE ((created_xid <= $1 AND created_xid >= $2) OR (deleted_xid <= $3 AND deleted_xid >= $4))","time":35.424548,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.732889177Z {"level":"debug","module":"pgx","args":[],"commandTag":"BEGIN","pid":4949,"sql":"begin isolation level repeatable read","time":0.41334,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.733230471Z {"level":"debug","module":"pgx","args":[{}],"commandTag":"SELECT 1","pid":4949,"sql":"\n\tSELECT xid, snapshot FROM relation_tuple_transaction\n\tWHERE xid >= pg_snapshot_xmax($1) OR (\n\t\txid >= pg_snapshot_xmin($1) AND NOT pg_visible_in_snapshot(xid, $1)\n\t) ORDER BY pg_xact_commit_timestamp(xid::xid), xid;","time":0.302513,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.733349868Z {"level":"debug","module":"pgx","args":[],"commandTag":"COMMIT","pid":4949,"sql":"commit","time":0.149435,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.765613347Z {"level":"debug","module":"pgx","args":[54474,54474,54474,54474],"commandTag":"SELECT 5","pid":4949,"sql":"SELECT namespace, object_id, relation, userset_namespace, userset_object_id, userset_relation, caveat_name, caveat_context, created_xid, deleted_xid FROM relation_tuple WHERE ((created_xid <= $1 AND created_xid >= $2) OR (deleted_xid <= $3 AND deleted_xid >= $4))","time":32.012343,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.765770812Z {"level":"debug","module":"pgx","args":[],"commandTag":"BEGIN","pid":4949,"sql":"begin isolation level repeatable read","time":0.200054,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.766208418Z {"level":"debug","module":"pgx","args":[{}],"commandTag":"SELECT 1","pid":4949,"sql":"\n\tSELECT xid, snapshot FROM relation_tuple_transaction\n\tWHERE xid >= pg_snapshot_xmax($1) OR (\n\t\txid >= pg_snapshot_xmin($1) AND NOT pg_visible_in_snapshot(xid, $1)\n\t) ORDER BY pg_xact_commit_timestamp(xid::xid), xid;","time":0.381181,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.766388355Z {"level":"debug","module":"pgx","args":[],"commandTag":"COMMIT","pid":4949,"sql":"commit","time":0.173555,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.796298826Z {"level":"debug","module":"pgx","args":[54475,54475,54475,54475],"commandTag":"SELECT 5","pid":4949,"sql":"SELECT namespace, object_id, relation, userset_namespace, userset_object_id, userset_relation, caveat_name, caveat_context, created_xid, deleted_xid FROM relation_tuple WHERE ((created_xid <= $1 AND created_xid >= $2) OR (deleted_xid <= $3 AND deleted_xid >= $4))","time":29.664591,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.796537432Z {"level":"debug","module":"pgx","args":[],"commandTag":"BEGIN","pid":4949,"sql":"begin isolation level repeatable read","time":0.279432,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.796888283Z {"level":"debug","module":"pgx","args":[{}],"commandTag":"SELECT 1","pid":4949,"sql":"\n\tSELECT xid, snapshot FROM relation_tuple_transaction\n\tWHERE xid >= pg_snapshot_xmax($1) OR (\n\t\txid >= pg_snapshot_xmin($1) AND NOT pg_visible_in_snapshot(xid, $1)\n\t) ORDER BY pg_xact_commit_timestamp(xid::xid), xid;","time":0.365821,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.797075771Z {"level":"debug","module":"pgx","args":[],"commandTag":"COMMIT","pid":4949,"sql":"commit","time":0.159384,"time":"2023-04-18T08:33:59Z","message":"Query"}
2023-04-18T08:33:59.823496252Z {"level":"debug","module":"pgx","args":[54474,54474,54474,54474],"commandTag":"SELECT 5","pid":4949,"sql":"SELECT namespace, object_id, relation, userset_namespace, userset_object_id, userset_relation, caveat_name, caveat_context, created_xid, deleted_xid FROM relation_tuple WHERE ((created_xid <= $1 AND created_xid >= $2) OR (deleted_xid <= $3 AND deleted_xid >= $4))","time":26.075841,"time":"2023-04-18T08:33:59Z","message":"Query"}
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment