FailedPrecondition desc = could not lookup caveat is_not_expired

[avevlad]

Apple M1 MAC OS 13.2.1 (22D68)

client: zed v0.11.1
service: (unknown)
spicedb v1.23.1

Input:

(base) ➜  zed context list

CURRENT	NAME              	ENDPOINT       	TOKEN     	TLS CERT
       	first-dev-context 	localhost:50051	<redacted>	insecure
   ✓   	caveat-dev-context	localhost:50051	<redacted>	insecure

spicedb serve --grpc-preshared-key "somerandomkeyhere" \
    --datastore-engine postgres --datastore-conn-uri "postgres://spicedb_user:spicedb_user_pwd@localhost:5432/spicedb?sslmode=disable"

zed schema write <(cat << EOF
definition user {}

caveat is_not_expired(current_time timestamp, expiration timestamp) {
    current_time < expiration
}

definition document {
    relation viewer: user with is_not_expired
    permission view = viewer
}
EOF
) --insecure

Output:

10:03PM FTL failed to write schema error="rpc error: code = FailedPrecondition desc = could not lookup caveat `is_not_expired` for relation `viewer`: caveat `is_not_expired` not found"

[josephschorr]

@avevlad Did you make sure to run migrate on the Postgres datastore before writing schema?

[avevlad]

@josephschorr Thank you for your quick response.

I run migrate after first install:

brew install authzed/tap/spicedb authzed/tap/zed

psql

CREATE USER spicedb_user WITH PASSWORD 'spicedb_user_pwd' CREATEDB;
CREATE DATABASE spicedb OWNER spicedb_user;

spicedb serve --grpc-preshared-key "somerandomkeyhere"
# CTRL+C (stop server)
spicedb migrate head --datastore-engine postgres --datastore-conn-uri "postgres://spicedb_user:spicedb_user_pwd@localhost:5432/spicedb?sslmode=disable"
spicedb serve --grpc-preshared-key "somerandomkeyhere" \
    --datastore-engine postgres --datastore-conn-uri "postgres://spicedb_user:spicedb_user_pwd@localhost:5432/spicedb?sslmode=disable"

After your response I tried this:

spicedb migrate head --datastore-engine postgres --datastore-conn-uri "postgres://spicedb_user:spicedb_user_pwd@localhost:5432/spicedb?sslmode=disable"


11:31PM INF configured logging async=false format=auto log_level=info provider=zerolog
11:31PM INF configured opentelemetry tracing endpoint= insecure=false provider=none sampleRatio=0.01 service=spicedb v=0
11:31PM INF this is the latest released version of SpiceDB latest-released-version=v1.23.1
11:31PM INF migrating postgres datastore
11:31PM INF running migrations targetRevision=head
11:31PM INF server already at requested revision targetRevision=head

But I still have the same problem (now on screenshot)

[josephschorr]

I'm unable to reproduce locally; I've tried with a fresh install twice.

Can you run SpiceDB with --log-level=trace, and attach logs from the failed WriteSchema call?

[avevlad]

9:13AM DBG Connect module=pgx pgx={"database":"spicedb","host":"localhost","pid":11866,"port":5432,"time":64.752375}
9:13AM DBG Connect module=pgx pgx={"database":"spicedb","host":"localhost","pid":11867,"port":5432,"time":65.4925}
9:13AM DBG Connect module=pgx pgx={"database":"spicedb","host":"localhost","pid":11868,"port":5432,"time":66.229125}
9:14AM DBG Prepare module=pgx pgx={"alreadyPrepared":false,"name":"stmtcache_6","pid":11868,"sql":"SELECT pg_current_snapshot();","time":0.363834}
9:14AM DBG Query module=pgx pgx={"args":[],"commandTag":"SELECT 1","pid":11868,"sql":"SELECT pg_current_snapshot();","time":1.431333}
9:14AM TRC adding sample duration to statistics duration=8.456 requestID=0bafaa5ad3114cc840c50a1735be36d8
9:14AM DBG Prepare module=pgx pgx={"alreadyPrepared":false,"name":"stmtcache_7","pid":11868,"sql":"SELECT serialized_config, created_xid FROM namespace_config WHERE pg_visible_in_snapshot(created_xid, $1) = $2 AND pg_visible_in_snapshot(deleted_xid, $3) = $4","time":0.464166}
9:14AM DBG Query module=pgx pgx={"args":[{},true,{},false],"commandTag":"SELECT 2","pid":11868,"sql":"SELECT serialized_config, created_xid FROM namespace_config WHERE pg_visible_in_snapshot(created_xid, $1) = $2 AND pg_visible_in_snapshot(deleted_xid, $3) = $4","time":4.978334}
9:14AM DBG Prepare module=pgx pgx={"alreadyPrepared":false,"name":"stmtcache_8","pid":11868,"sql":"SELECT definition, created_xid FROM caveat WHERE pg_visible_in_snapshot(created_xid, $1) = $2 AND pg_visible_in_snapshot(deleted_xid, $3) = $4 ORDER BY name","time":2.495417}
9:14AM DBG Query module=pgx pgx={"args":[{},true,{},false],"commandTag":"SELECT 0","pid":11868,"sql":"SELECT definition, created_xid FROM caveat WHERE pg_visible_in_snapshot(created_xid, $1) = $2 AND pg_visible_in_snapshot(deleted_xid, $3) = $4 ORDER BY name","time":3.933375}
9:14AM INF finished call grpc.code=OK grpc.component=server grpc.method=ReadSchema grpc.method_type=unary grpc.service=authzed.api.v1.SchemaService grpc.start_time=2023-07-20T09:14:05+03:00 grpc.time_ms=19.714 peer.address=[::1]:54667 protocol=grpc requestID=0bafaa5ad3114cc840c50a1735be36d8
9:14AM TRC requested Schema to be written requestID=515a3e7368f800ffdf90fa288d173fee schema="definition blog/user {}\n\ncaveat blog/is_not_expired(current_time timestamp, expiration timestamp) {\n\tcurrent_time < expiration\n}\n\ndefinition blog/document {\n\trelation viewer: blog/user with is_not_expired\n\tpermission view = viewer\n}"
9:14AM TRC compiled namespace definitions caveatDefinitions=1 objectDefinitions=2 requestID=515a3e7368f800ffdf90fa288d173fee
9:14AM WRN finished call grpc.code=FailedPrecondition grpc.component=server grpc.error="could not lookup caveat `is_not_expired` for relation `viewer`: caveat `is_not_expired` not found" grpc.method=WriteSchema grpc.method_type=unary grpc.service=authzed.api.v1.SchemaService grpc.start_time=2023-07-20T09:14:05+03:00 grpc.time_ms=4.911 peer.address=[::1]:54667 protocol=grpc requestID=515a3e7368f800ffdf90fa288d173fee

[avevlad]

If I run serve without connect with postgres, everything ok:

Server

spicedb serve --grpc-preshared-key "somerandomkeyhere"
9:28AM INF configured logging async=false format=auto log_level=info provider=zerolog
9:28AM INF configured opentelemetry tracing endpoint= insecure=false provider=none sampleRatio=0.01 service=spicedb v=0
9:28AM INF this is the latest released version of SpiceDB latest-released-version=v1.23.1
9:28AM INF configuration ClusterDispatchCacheConfig.Enabled=true ClusterDispatchCacheConfig.MaxCost=70% ClusterDispatchCacheConfig.Metrics=true ClusterDispatchCacheConfig.Name=cluster_dispatch ClusterDispatchCacheConfig.NumCounters=100000 DashboardAPI.HTTPAddress=:8080 DashboardAPI.HTTPEnabled=true DashboardAPI.HTTPTLSCertPath=(empty) DashboardAPI.HTTPTLSKeyPath=(empty) Datastore=nil DatastoreConfig.BootstrapFileContents="(map of size 0)" DatastoreConfig.BootstrapFiles=[] DatastoreConfig.BootstrapOverwrite=false DatastoreConfig.BootstrapTimeout=10000 DatastoreConfig.ConnectRate=100 DatastoreConfig.DisableStats=false DatastoreConfig.EnableConnectionBalancing=true DatastoreConfig.EnableDatastoreMetrics=true DatastoreConfig.Engine=memory DatastoreConfig.FollowerReadDelay=4800 DatastoreConfig.GCInterval=180000 DatastoreConfig.GCMaxOperationTime=60000 DatastoreConfig.GCWindow=86400000 DatastoreConfig.LegacyFuzzing=-0.000001 DatastoreConfig.MaxRetries=10 DatastoreConfig.MaxRevisionStalenessPercent=0.1 DatastoreConfig.MigrationPhase=(empty) DatastoreConfig.OverlapKey=key DatastoreConfig.OverlapStrategy=static DatastoreConfig.ReadConnPool.HealthCheckInterval=30000 DatastoreConfig.ReadConnPool.MaxIdleTime=1800000 DatastoreConfig.ReadConnPool.MaxLifetime=1800000 DatastoreConfig.ReadConnPool.MaxLifetimeJitter=0 DatastoreConfig.ReadConnPool.MaxOpenConns=20 DatastoreConfig.ReadConnPool.MinOpenConns=20 DatastoreConfig.ReadOnly=false DatastoreConfig.RequestHedgingEnabled=true DatastoreConfig.RequestHedgingInitialSlowValue=10 DatastoreConfig.RequestHedgingMaxRequests=1000000 DatastoreConfig.RequestHedgingQuantile=0.95 DatastoreConfig.RevisionQuantization=5000 DatastoreConfig.SpannerCredentialsFile=(empty) DatastoreConfig.SpannerEmulatorHost=(empty) DatastoreConfig.SplitQueryCount=1024 DatastoreConfig.TablePrefix=(empty) DatastoreConfig.URI=(empty) DatastoreConfig.WatchBufferLength=1024 DatastoreConfig.WriteConnPool.HealthCheckInterval=30000 DatastoreConfig.WriteConnPool.MaxIdleTime=1800000 DatastoreConfig.WriteConnPool.MaxLifetime=1800000 DatastoreConfig.WriteConnPool.MaxLifetimeJitter=0 DatastoreConfig.WriteConnPool.MaxOpenConns=10 DatastoreConfig.WriteConnPool.MinOpenConns=10 DisableV1SchemaAPI=false DisableVersionResponse=false DispatchCacheConfig.Enabled=true DispatchCacheConfig.MaxCost=30% DispatchCacheConfig.Metrics=true DispatchCacheConfig.Name=dispatch DispatchCacheConfig.NumCounters=10000 DispatchClientMetricsEnabled=true DispatchClientMetricsPrefix=(empty) DispatchClusterMetricsEnabled=true DispatchClusterMetricsPrefix=(empty) DispatchConcurrencyLimits.Check=0 DispatchConcurrencyLimits.LookupResources=0 DispatchConcurrencyLimits.LookupSubjects=0 DispatchConcurrencyLimits.ReachableResources=0 DispatchHashringReplicationFactor=100 DispatchHashringSpread=1 DispatchMaxDepth=50 DispatchServer.Address=:50053 DispatchServer.BufferSize=0 DispatchServer.ClientCAPath=(empty) DispatchServer.Enabled=false DispatchServer.MaxConnAge=30000 DispatchServer.MaxWorkers=0 DispatchServer.Network=tcp DispatchServer.TLSCertPath=(empty) DispatchServer.TLSKeyPath=(empty) DispatchUpstreamAddr=(empty) DispatchUpstreamCAPath=(empty) DispatchUpstreamTimeout=60000 Dispatcher=nil GRPCAuthFunc=(value) GRPCServer.Address=:50051 GRPCServer.BufferSize=0 GRPCServer.ClientCAPath=(empty) GRPCServer.Enabled=true GRPCServer.MaxConnAge=30000 GRPCServer.MaxWorkers=0 GRPCServer.Network=tcp GRPCServer.TLSCertPath=(empty) GRPCServer.TLSKeyPath=(empty) GlobalDispatchConcurrencyLimit=50 HTTPGateway.HTTPAddress=:8443 HTTPGateway.HTTPEnabled=false HTTPGateway.HTTPTLSCertPath=(empty) HTTPGateway.HTTPTLSKeyPath=(empty) HTTPGatewayCorsAllowedOrigins=[*] HTTPGatewayCorsEnabled=false HTTPGatewayUpstreamAddr=(empty) HTTPGatewayUpstreamTLSCertPath=(empty) MaxCaveatContextSize=4096 MaxDatastoreReadPageSize=1000 MaxRelationshipContextSize=25000 MaximumPreconditionCount=1000 MaximumUpdatesPerWrite=1000 MetricsAPI.HTTPAddress=:9090 MetricsAPI.HTTPEnabled=true MetricsAPI.HTTPTLSCertPath=(empty) MetricsAPI.HTTPTLSKeyPath=(empty) NamespaceCacheConfig.Enabled=true NamespaceCacheConfig.MaxCost=16MiB NamespaceCacheConfig.Metrics=true NamespaceCacheConfig.Name=namespace NamespaceCacheConfig.NumCounters=1000 PresharedSecureKey=(sensitive) SchemaPrefixesRequired=false ShutdownGracePeriod=0 SilentlyDisableTelemetry=false StreamingAPITimeout=30000 TelemetryCAOverridePath=(empty) TelemetryEndpoint=https://telemetry.authzed.com TelemetryInterval=3600000 V1SchemaAdditiveOnly=false
9:28AM INF using memory datastore engine
9:28AM WRN in-memory datastore is not persistent and not feasible to run in a high availability fashion
9:28AM INF request hedging enabled hedgingQuantile=0.95 initialSlowRequest=10ms maxRequests=1000000
9:28AM INF configured namespace cache defaultTTL=0 maxCost="16 MiB" numCounters=1000
9:28AM INF configured dispatch cache defaultTTL=20600 maxCost="28 MiB" numCounters=10000
9:28AM INF configured dispatcher balancerconfig={"loadBalancingConfig":[{"consistent-hashring":{"replicationFactor":100,"spread":1}}]} concurrency-limit-check-permission=50 concurrency-limit-lookup-resources=50 concurrency-limit-lookup-subjects=50 concurrency-limit-reachable-resources=50
9:28AM INF grpc server started serving addr=:50051 insecure=true network=tcp service=grpc workers=0
9:28AM INF http server started serving addr=:9090 insecure=true service=metrics
9:28AM INF http server started serving addr=:8080 insecure=true service=dashboard
9:28AM INF telemetry reporter scheduled endpoint=https://telemetry.authzed.com interval=1h0m0s next=3m45s
9:30AM INF finished call grpc.code=NotFound grpc.component=server grpc.error="rpc error: code = NotFound desc = No schema has been defined; please call WriteSchema to start" grpc.method=ReadSchema grpc.method_type=unary grpc.service=authzed.api.v1.SchemaService grpc.start_time=2023-07-20T09:30:44+03:00 grpc.time_ms=0.663 peer.address=[::1]:54202 protocol=grpc requestID=be2eb52cc2328c1f9707ac8909585013
9:30AM INF finished call grpc.code=OK grpc.component=server grpc.method=WriteSchema grpc.method_type=unary grpc.service=authzed.api.v1.SchemaService grpc.start_time=2023-07-20T09:30:44+03:00 grpc.time_ms=3.779 peer.address=[::1]:54202 protocol=grpc requestID=32203f9ce60d801faf825e44679b4f2b

zed schema write

(base) ➜  proof_of_concept git:(main) ✗ zed context list
CURRENT	NAME              	ENDPOINT       	TOKEN     	TLS CERT
   ✓   	first-dev-context 	localhost:50051	<redacted>	insecure
       	caveat-dev-context	localhost:50051	<redacted>	insecure
(base) ➜  proof_of_concept git:(main) ✗ zed context use caveat-dev-context
(base) ➜  proof_of_concept git:(main) ✗ zed context list
CURRENT	NAME              	ENDPOINT       	TOKEN     	TLS CERT
       	first-dev-context 	localhost:50051	<redacted>	insecure
   ✓   	caveat-dev-context	localhost:50051	<redacted>	insecure

(base) ➜  proof_of_concept git:(main) ✗ cat ./caveat.zed
definition user {}

caveat is_not_expired(current_time timestamp, expiration timestamp) {
    current_time < expiration
}

definition document {
    relation viewer: user with is_not_expired
    permission view = viewer
}
(base) ➜  proof_of_concept git:(main) ✗ zed schema write caveat.zed --insecure

Apparently the problem has something to do with migrations in PosgreSQL
I will try to make a reproducible docker compose file one of these days

[josephschorr]

@avevlad any updates?

[josephschorr]

@avevlad Closing; please reopen if you are able to reproduce