Repository: openfga/openfga

Issue:
Surface partial metrics on check resolutions
### Checklist

- [x] I agree to the terms within the [OpenFGA Code of Conduct](https://github.com/openfga/.github/blob/main/CODE_OF_CONDUCT.md).

### Describe the problem you'd like to have solved

If a Check query times out because of dispatch throttling, logs, metrics, and traces are missing helpful information like dispatch count, datastore query count, and if the request was throttled or not.

This happens because most of the logic that surfaces those metrics only happens if there wasn't an error.

https://github.com/openfga/openfga/blob/73dceae92683474c2d788c9b4467abe2d2e3b3db/pkg/server/check.go#L71-L89

### Describe the ideal solution

Change the order of operations to allow surfacing data collected until a point in time whenever possible.

### Alternatives and current workarounds

_No response_

### Additional context

_No response_

Discussion:

Solution patch:
diff --git a/CHANGELOG.md b/CHANGELOG.md
index 348c7365..c24312dd 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -12,6 +12,7 @@ Try to keep listed changes to a concise bulleted list of simple explanations of
 - Added "dispatch_count" histogram metric to batch-check requests.
 - Added "request.throttled" boolean to the context tags for check and batch-check
 - Added "throttled_requests_count" metric to batch-check requests.
+- Surface partial metrics on check resolutions [#2371](https://github.com/openfga/openfga/pull/2371)
 
 ## [1.8.9] - 2025-04-01
 [Full changelog](https://github.com/openfga/openfga/compare/v1.8.8...v1.8.9)
diff --git a/pkg/server/check.go b/pkg/server/check.go
index 0f0f93f6..291ac780 100644
--- a/pkg/server/check.go
+++ b/pkg/server/check.go
@@ -24,7 +24,9 @@ import (
 )
 
 func (s *Server) Check(ctx context.Context, req *openfgav1.CheckRequest) (*openfgav1.CheckResponse, error) {
-	start := time.Now()
+	const methodName = "check"
+
+	startTime := time.Now()
 
 	tk := req.GetTupleKey()
 	ctx, span := tracer.Start(ctx, authz.Check, trace.WithAttributes(
@@ -76,7 +78,58 @@ func (s *Server) Check(ctx context.Context, req *openfgav1.CheckRequest) (*openf
 		Consistency:      req.GetConsistency(),
 	})
 
-	const methodName = "check"
+	endTime := time.Since(startTime).Milliseconds()
+
+	var (
+		wasRequestThrottled bool
+		rawDispatchCount    uint32
+	)
+
+	if checkRequestMetadata != nil {
+		wasRequestThrottled = checkRequestMetadata.WasThrottled.Load()
+		rawDispatchCount = checkRequestMetadata.DispatchCounter.Load()
+		dispatchCount := float64(rawDispatchCount)
+
+		grpc_ctxtags.Extract(ctx).Set(dispatchCountHistogramName, dispatchCount)
+		span.SetAttributes(attribute.Float64(dispatchCountHistogramName, dispatchCount))
+		dispatchCountHistogram.WithLabelValues(
+			s.serviceName,
+			methodName,
+		).Observe(dispatchCount)
+	}
+
+	if resp != nil {
+		queryCount := float64(resp.GetResolutionMetadata().DatastoreQueryCount)
+
+		grpc_ctxtags.Extract(ctx).Set(datastoreQueryCountHistogramName, queryCount)
+		span.SetAttributes(attribute.Float64(datastoreQueryCountHistogramName, queryCount))
+		datastoreQueryCountHistogram.WithLabelValues(
+			s.serviceName,
+			methodName,
+		).Observe(queryCount)
+
+		requestDurationHistogram.WithLabelValues(
+			s.serviceName,
+			methodName,
+			utils.Bucketize(uint(queryCount), s.requestDurationByQueryHistogramBuckets),
+			utils.Bucketize(uint(rawDispatchCount), s.requestDurationByDispatchCountHistogramBuckets),
+			req.GetConsistency().String(),
+		).Observe(float64(endTime))
+
+		if s.authorizer.AccessControlStoreID() == req.GetStoreId() {
+			accessControlStoreCheckDurationHistogram.WithLabelValues(
+				utils.Bucketize(uint(queryCount), s.requestDurationByQueryHistogramBuckets),
+				utils.Bucketize(uint(rawDispatchCount), s.requestDurationByDispatchCountHistogramBuckets),
+				req.GetConsistency().String(),
+			).Observe(float64(endTime))
+		}
+
+		if wasRequestThrottled {
+			throttledRequestCounter.WithLabelValues(s.serviceName, methodName).Inc()
+		}
+		grpc_ctxtags.Extract(ctx).Set("request.throttled", wasRequestThrottled)
+	}
+
 	if err != nil {
 		telemetry.TraceError(span, err)
 		finalErr := commands.CheckCommandErrorToServerError(err)
@@ -88,56 +141,15 @@ func (s *Server) Check(ctx context.Context, req *openfgav1.CheckRequest) (*openf
 		return nil, finalErr
 	}
 
+	checkResultCounter.With(prometheus.Labels{allowedLabel: strconv.FormatBool(resp.GetAllowed())}).Inc()
+
 	span.SetAttributes(
 		attribute.Bool("cycle_detected", resp.GetCycleDetected()),
 		attribute.Bool("allowed", resp.GetAllowed()))
 
-	queryCount := float64(resp.GetResolutionMetadata().DatastoreQueryCount)
-
-	grpc_ctxtags.Extract(ctx).Set(datastoreQueryCountHistogramName, queryCount)
-	span.SetAttributes(attribute.Float64(datastoreQueryCountHistogramName, queryCount))
-	datastoreQueryCountHistogram.WithLabelValues(
-		s.serviceName,
-		methodName,
-	).Observe(queryCount)
-
-	rawDispatchCount := checkRequestMetadata.DispatchCounter.Load()
-	dispatchCount := float64(rawDispatchCount)
-
-	grpc_ctxtags.Extract(ctx).Set(dispatchCountHistogramName, dispatchCount)
-	span.SetAttributes(attribute.Float64(dispatchCountHistogramName, dispatchCount))
-	dispatchCountHistogram.WithLabelValues(
-		s.serviceName,
-		methodName,
-	).Observe(dispatchCount)
-
 	res := &openfgav1.CheckResponse{
 		Allowed: resp.Allowed,
 	}
 
-	checkResultCounter.With(prometheus.Labels{allowedLabel: strconv.FormatBool(resp.GetAllowed())}).Inc()
-
-	requestDurationHistogram.WithLabelValues(
-		s.serviceName,
-		methodName,
-		utils.Bucketize(uint(queryCount), s.requestDurationByQueryHistogramBuckets),
-		utils.Bucketize(uint(rawDispatchCount), s.requestDurationByDispatchCountHistogramBuckets),
-		req.GetConsistency().String(),
-	).Observe(float64(time.Since(start).Milliseconds()))
-
-	if s.authorizer.AccessControlStoreID() == req.GetStoreId() {
-		accessControlStoreCheckDurationHistogram.WithLabelValues(
-			utils.Bucketize(uint(queryCount), s.requestDurationByQueryHistogramBuckets),
-			utils.Bucketize(uint(rawDispatchCount), s.requestDurationByDispatchCountHistogramBuckets),
-			req.GetConsistency().String(),
-		).Observe(float64(time.Since(start).Milliseconds()))
-	}
-
-	wasRequestThrottled := checkRequestMetadata.WasThrottled.Load()
-	if wasRequestThrottled {
-		throttledRequestCounter.WithLabelValues(s.serviceName, methodName).Inc()
-	}
-	grpc_ctxtags.Extract(ctx).Set("request.throttled", wasRequestThrottled)
-
 	return res, nil
 }
diff --git a/pkg/server/commands/check_command.go b/pkg/server/commands/check_command.go
index 6b5a5186..9b7f49d4 100644
--- a/pkg/server/commands/check_command.go
+++ b/pkg/server/commands/check_command.go
@@ -121,19 +121,31 @@ func (c *CheckQuery) Execute(ctx context.Context, params *CheckCommandParams) (*
 	ctx = storage.ContextWithRelationshipTupleReader(ctx, datastoreWithTupleCache)
 
 	startTime := time.Now()
-
 	resp, err := c.checkResolver.ResolveCheck(ctx, resolveCheckRequest)
+	endTime := time.Since(startTime)
+
+	// ResolveCheck might fail half way throughout (e.g. due to a timeout) and return a nil response.
+	// Partial resolution metadata is still useful for obsevability.
+	// From here on, we can assume that request metadata and response are not nil even if
+	// there is an error present.
+	if resp == nil {
+		resp = &graph.ResolveCheckResponse{
+			Allowed:            false,
+			ResolutionMetadata: graph.ResolveCheckResponseMetadata{},
+		}
+	}
+
+	resp.ResolutionMetadata.Duration = endTime
+	resp.ResolutionMetadata.DatastoreQueryCount = datastoreWithTupleCache.GetMetrics().DatastoreQueryCount
+
 	if err != nil {
 		if errors.Is(err, context.DeadlineExceeded) && resolveCheckRequest.GetRequestMetadata().WasThrottled.Load() {
-			return nil, nil, &ThrottledError{Cause: err}
+			return resp, resolveCheckRequest.GetRequestMetadata(), &ThrottledError{Cause: err}
 		}
 
-		return nil, nil, err
+		return resp, resolveCheckRequest.GetRequestMetadata(), err
 	}
 
-	resp.ResolutionMetadata.Duration = time.Since(startTime)
-	resp.ResolutionMetadata.DatastoreQueryCount = datastoreWithTupleCache.GetMetrics().DatastoreQueryCount
-
 	return resp, resolveCheckRequest.GetRequestMetadata(), nil
 }
 



Test patch:
diff --git a/pkg/server/commands/check_command_test.go b/pkg/server/commands/check_command_test.go
index 8b1db3de..5c257300 100644
--- a/pkg/server/commands/check_command_test.go
+++ b/pkg/server/commands/check_command_test.go
@@ -215,6 +215,36 @@ type doc
 		})
 		require.Error(t, err)
 	})
+
+	t.Run("metadata_on_error", func(t *testing.T) {
+		ctx := context.Background()
+
+		mockDatastore.EXPECT().Read(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()).
+			Times(1)
+
+		mockCheckResolver.EXPECT().ResolveCheck(gomock.Any(), gomock.Any()).
+			Times(1).
+			DoAndReturn(func(ctx context.Context, req *graph.ResolveCheckRequest) (*graph.ResolveCheckResponse, error) {
+				req.GetRequestMetadata().Depth++
+				req.GetRequestMetadata().DispatchCounter.Add(1)
+				req.GetRequestMetadata().WasThrottled.Store(true)
+				ds, _ := storage.RelationshipTupleReaderFromContext(ctx)
+				_, _ = ds.Read(ctx, req.StoreID, nil, storage.ReadOptions{})
+				return nil, context.DeadlineExceeded
+			})
+
+		cmd := NewCheckCommand(mockDatastore, mockCheckResolver, ts)
+		checkResp, checkRequestMetadata, err := cmd.Execute(ctx, &CheckCommandParams{
+			StoreID:  ulid.Make().String(),
+			TupleKey: tuple.NewCheckRequestTupleKey("doc:1", "viewer", "user:1"),
+		})
+
+		require.Error(t, err)
+		require.Equal(t, uint32(1), checkResp.GetResolutionMetadata().DatastoreQueryCount)
+		require.Equal(t, uint32(1), checkRequestMetadata.Depth)
+		require.Equal(t, uint32(1), checkRequestMetadata.DispatchCounter.Load())
+		require.True(t, checkRequestMetadata.WasThrottled.Load())
+	})
 }
 
 func TestCheckCommandErrorToServerError(t *testing.T) {