Merge pull request #1930 from josephschorr/recursion-error-debug-trace

Add the debug trace to the details of the recursion error

internal/dispatch/singleflight/singleflight.go

@@ -8,8 +8,6 @@ import (
 
  "github.com/prometheus/client_golang/prometheus"
  "github.com/prometheus/client_golang/prometheus/promauto"
- "go.opentelemetry.io/otel/attribute"
- "go.opentelemetry.io/otel/trace"
  "google.golang.org/grpc/codes"
  "google.golang.org/grpc/status"
  "resenje.org/singleflight"
@@ -82,21 +80,16 @@ func (d *Dispatcher) DispatchCheck(ctx context.Context, req *v1.DispatchCheckReq
  return d.delegate.DispatchCheck(ctx, req)
  }
 
- primary := false
- v, isShared, err := d.checkGroup.Do(ctx, keyString, func(innerCtx context.Context) (*v1.DispatchCheckResponse, error) {
- primary = true
+ sharedResp, isShared, err := d.checkGroup.Do(ctx, keyString, func(innerCtx context.Context) (*v1.DispatchCheckResponse, error) {
  return d.delegate.DispatchCheck(innerCtx, req)
  })
 
- singleFlightCount.WithLabelValues("DispatchCheck", strconv.FormatBool(isShared)).Inc()
- if err != nil {
- return &v1.DispatchCheckResponse{Metadata: &v1.ResponseMeta{DispatchCount: 1}}, err
+ if sharedResp == nil {
+ sharedResp = &v1.DispatchCheckResponse{Metadata: &v1.ResponseMeta{DispatchCount: 1}}
  }
 
- span := trace.SpanFromContext(ctx)
- singleflighted := isShared && !primary
- span.SetAttributes(attribute.Bool("singleflight", singleflighted))
- return v, err
+ singleFlightCount.WithLabelValues("DispatchCheck", strconv.FormatBool(isShared)).Inc()
+ return sharedResp, err
 }
 
 func (d *Dispatcher) DispatchExpand(ctx context.Context, req *v1.DispatchExpandRequest) (*v1.DispatchExpandResponse, error) {

internal/graph/check.go

@@ -413,6 +413,7 @@ func (cc *ConcurrentChecker) checkDirect(ctx context.Context, crc currentRequest
  },
  crc.parentReq.Revision,
  })
+
  if childResult.Err != nil {
  return childResult
  }

internal/services/shared/errors.go

@@ -71,7 +71,7 @@ func (err ErrSchemaWriteDataValidation) GRPCStatus() *status.Status {
 
 // MaxDepthExceededError is an error returned when the maximum depth for dispatching has been exceeded.
 type MaxDepthExceededError struct {
- error
+ *spiceerrors.ErrorWithAdditionalDetails
 
  // AllowedMaximumDepth is the configured allowed maximum depth.
  AllowedMaximumDepth uint32
@@ -84,9 +84,9 @@ func (err MaxDepthExceededError) GRPCStatus() *status.Status {
  codes.ResourceExhausted,
  spiceerrors.ForReason(
  v1.ErrorReason_ERROR_REASON_MAXIMUM_DEPTH_EXCEEDED,
- map[string]string{
+ err.AddToDetails(map[string]string{
  "maximum_depth_allowed": strconv.Itoa(int(err.AllowedMaximumDepth)),
- },
+ }),
  ),
  )
 }
@@ -95,13 +95,13 @@ func (err MaxDepthExceededError) GRPCStatus() *status.Status {
 func NewMaxDepthExceededError(allowedMaximumDepth uint32, isCheckRequest bool) error {
  if isCheckRequest {
  return MaxDepthExceededError{
- fmt.Errorf("the check request has exceeded the allowable maximum depth of %d: this usually indicates a recursive or too deep data dependency. Try running zed with --explain to see the dependency. See: https://spicedb.dev/d/debug-max-depth-check", allowedMaximumDepth),
+ spiceerrors.NewErrorWithAdditionalDetails(fmt.Errorf("the check request has exceeded the allowable maximum depth of %d: this usually indicates a recursive or too deep data dependency. Try running zed with --explain to see the dependency. See: https://spicedb.dev/d/debug-max-depth-check", allowedMaximumDepth)),
  allowedMaximumDepth,
  }
  }
 
  return MaxDepthExceededError{
- fmt.Errorf("the request has exceeded the allowable maximum depth of %d: this usually indicates a recursive or too deep data dependency. See: https://spicedb.dev/d/debug-max-depth", allowedMaximumDepth),
+ spiceerrors.NewErrorWithAdditionalDetails(fmt.Errorf("the request has exceeded the allowable maximum depth of %d: this usually indicates a recursive or too deep data dependency. See: https://spicedb.dev/d/debug-max-depth", allowedMaximumDepth)),
  allowedMaximumDepth,
  }
 }
@@ -116,13 +116,26 @@ func AsValidationError(err error) *ErrSchemaWriteDataValidation {
 
 type ConfigForErrors struct {
  MaximumAPIDepth uint32
+ DebugTrace *v1.DebugInformation
 }
 
+// DebugTraceErrorDetailsKey is the key used to store the debug trace in the error details.
+// The value is expected to be a string containing the proto text of a DebugInformation message.
+const DebugTraceErrorDetailsKey = "debug_trace_proto_text"
+
 func RewriteErrorWithoutConfig(ctx context.Context, err error) error {
- return RewriteError(ctx, err, nil)
+ return rewriteError(ctx, err, nil)
 }
 
 func RewriteError(ctx context.Context, err error, config *ConfigForErrors) error {
+ rerr := rewriteError(ctx, err, config)
+ if config != nil && config.DebugTrace != nil {
+ spiceerrors.WithAdditionalDetails(rerr, DebugTraceErrorDetailsKey, config.DebugTrace.String())
+ }
+ return rerr
+}
+
+func rewriteError(ctx context.Context, err error, config *ConfigForErrors) error {
  // Check if the error can be directly used.
  if _, ok := status.FromError(err); ok {
  return err

internal/services/v1/permissions.go

@@ -35,6 +35,13 @@ func (ps *permissionServer) rewriteError(ctx context.Context, err error) error {
  })
 }
 
+func (ps *permissionServer) rewriteErrorWithOptionalDebugTrace(ctx context.Context, err error, debugTrace *v1.DebugInformation) error {
+ return shared.RewriteError(ctx, err, &shared.ConfigForErrors{
+ MaximumAPIDepth: ps.config.MaximumAPIDepth,
+ DebugTrace: debugTrace,
+ })
+}
+
 func (ps *permissionServer) CheckPermission(ctx context.Context, req *v1.CheckPermissionRequest) (*v1.CheckPermissionResponse, error) {
  atRevision, checkedAt, err := consistency.RevisionFromContext(ctx)
  if err != nil {
@@ -108,7 +115,7 @@ func (ps *permissionServer) CheckPermission(ctx context.Context, req *v1.CheckPe
  }
 
  if err != nil {
- return nil, ps.rewriteError(ctx, err)
+ return nil, ps.rewriteErrorWithOptionalDebugTrace(ctx, err, debugTrace)
  }
 
  permissionship, partialCaveat := checkResultToAPITypes(cr)

internal/services/v1/permissions_test.go

@@ -18,10 +18,12 @@ import (
  "github.com/authzed/grpcutil"
  "github.com/stretchr/testify/require"
  "go.uber.org/goleak"
+ "google.golang.org/genproto/googleapis/rpc/errdetails"
  "google.golang.org/grpc"
  "google.golang.org/grpc/codes"
  "google.golang.org/grpc/metadata"
  "google.golang.org/grpc/status"
+ "google.golang.org/protobuf/encoding/prototext"
  "google.golang.org/protobuf/types/known/structpb"
 
  "github.com/authzed/spicedb/internal/datastore/memdb"
@@ -383,6 +385,73 @@ func TestCheckPermissionWithDebugInfo(t *testing.T) {
  require.Equal(4, len(compiled.OrderedDefinitions))
 }
 
+func TestCheckPermissionWithDebugInfoInError(t *testing.T) {
+ req := require.New(t)
+ conn, cleanup, _, revision := testserver.NewTestServer(req, testTimedeltas[0], memdb.DisableGC, true,
+ func(ds datastore.Datastore, assertions *require.Assertions) (datastore.Datastore, datastore.Revision) {
+ return tf.DatastoreFromSchemaAndTestRelationships(
+ ds,
+ `definition user {}
+ 
+ definition document {
+ relation viewer: user | document#view
+ permission view = viewer
+ }
+ `,
+ []*core.RelationTuple{
+ tuple.MustParse("document:doc1#viewer@user:tom"),
+ tuple.MustParse("document:doc1#viewer@document:doc2#view"),
+ tuple.MustParse("document:doc2#viewer@document:doc3#view"),
+ tuple.MustParse("document:doc3#viewer@document:doc1#view"),
+ },
+ assertions,
+ )
+ },
+ )
+ client := v1.NewPermissionsServiceClient(conn)
+ t.Cleanup(cleanup)
+
+ ctx := context.Background()
+ ctx = requestmeta.AddRequestHeaders(ctx, requestmeta.RequestDebugInformation)
+
+ _, err := client.CheckPermission(ctx, &v1.CheckPermissionRequest{
+ Consistency: &v1.Consistency{
+ Requirement: &v1.Consistency_AtLeastAsFresh{
+ AtLeastAsFresh: zedtoken.MustNewFromRevision(revision),
+ },
+ },
+ Resource: obj("document", "doc1"),
+ Permission: "view",
+ Subject: sub("user", "fred", ""),
+ })
+
+ req.Error(err)
+ grpcutil.RequireStatus(t, codes.ResourceExhausted, err)
+
+ s, ok := status.FromError(err)
+ req.True(ok)
+
+ foundDebugInfo := false
+ for _, d := range s.Details() {
+ if errInfo, ok := d.(*errdetails.ErrorInfo); ok {
+ req.NotNil(errInfo.Metadata)
+ req.NotNil(errInfo.Metadata[shared.DebugTraceErrorDetailsKey])
+ req.NotEmpty(errInfo.Metadata[shared.DebugTraceErrorDetailsKey])
+
+ debugInfo := &v1.DebugInformation{}
+ err = prototext.Unmarshal([]byte(errInfo.Metadata[shared.DebugTraceErrorDetailsKey]), debugInfo)
+ req.NoError(err)
+
+ req.Equal(1, len(debugInfo.Check.GetSubProblems().Traces))
+ req.Equal(1, len(debugInfo.Check.GetSubProblems().Traces[0].GetSubProblems().Traces))
+
+ foundDebugInfo = true
+ }
+ }
+
+ req.True(foundDebugInfo)
+}
+
 func TestLookupResources(t *testing.T) {
  testCases := []struct {
  objectType string

pkg/spiceerrors/common.go

@@ -1,6 +1,9 @@
 package spiceerrors
 
-import "errors"
+import (
+ "errors"
+ "maps"
+)
 
 // SourcePosition is a position in the input source.
 type SourcePosition struct {
@@ -51,3 +54,35 @@ func AsErrorWithSource(err error) (*ErrorWithSource, bool) {
  }
  return nil, false
 }
+
+// ErrorWithAdditionalDetails is an error that includes additional details.
+type ErrorWithAdditionalDetails struct {
+ error
+
+ // AdditionalDetails is a map of additional details for the error.
+ AdditionalDetails map[string]string
+}
+
+func NewErrorWithAdditionalDetails(err error) *ErrorWithAdditionalDetails {
+ return &ErrorWithAdditionalDetails{err, nil}
+}
+
+// Unwrap returns the inner, wrapped error.
+func (err *ErrorWithAdditionalDetails) Unwrap() error {
+ return err.error
+}
+
+func (err *ErrorWithAdditionalDetails) WithAdditionalDetails(key string, value string) {
+ if err.AdditionalDetails == nil {
+ err.AdditionalDetails = make(map[string]string)
+ }
+ err.AdditionalDetails[key] = value
+}
+
+func (err *ErrorWithAdditionalDetails) AddToDetails(details map[string]string) map[string]string {
+ if err.AdditionalDetails != nil {
+ maps.Copy(details, err.AdditionalDetails)
+ }
+
+ return details
+}

pkg/spiceerrors/withstatus.go

@@ -57,6 +57,21 @@ func WithCodeAndReason(err error, code codes.Code, reason v1.ErrorReason) error
  return errWithStatus{err, status}
 }
 
+type SupportsAdditionalMetadata interface {
+ WithAdditionalDetails(key string, value string)
+}
+
+// WithAdditionalDetails adds an additional details field to the error if it is possible.
+func WithAdditionalDetails(err error, key string, value string) bool {
+ var supportsAdditionalDetails SupportsAdditionalMetadata
+ if ok := errors.As(err, &supportsAdditionalDetails); ok {
+ supportsAdditionalDetails.WithAdditionalDetails(key, value)
+ return true
+ }
+
+ return false
+}
+
 type errWithStatus struct {
  error
  status *status.Status