Skip to content

Commit

Permalink
Add a node ID to debug tracing and spans
Browse files Browse the repository at this point in the history
  • Loading branch information
josephschorr committed Jan 7, 2025
1 parent 43e632c commit ab97060
Show file tree
Hide file tree
Showing 9 changed files with 278 additions and 65 deletions.
38 changes: 38 additions & 0 deletions internal/dispatch/graph/graph.go
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@ import (
log "github.com/authzed/spicedb/internal/logging"
datastoremw "github.com/authzed/spicedb/internal/middleware/datastore"
"github.com/authzed/spicedb/pkg/datastore"
"github.com/authzed/spicedb/pkg/middleware/nodeid"
core "github.com/authzed/spicedb/pkg/proto/core/v1"
v1 "github.com/authzed/spicedb/pkg/proto/dispatch/v1"
"github.com/authzed/spicedb/pkg/tuple"
Expand Down Expand Up @@ -177,10 +178,17 @@ func (ld *localDispatcher) lookupRelation(_ context.Context, ns *core.NamespaceD
func (ld *localDispatcher) DispatchCheck(ctx context.Context, req *v1.DispatchCheckRequest) (*v1.DispatchCheckResponse, error) {
resourceType := tuple.StringCoreRR(req.ResourceRelation)
spanName := "DispatchCheck → " + resourceType + "@" + req.Subject.Namespace + "#" + req.Subject.Relation

nodeID, err := nodeid.FromContext(ctx)
if err != nil {
log.Err(err).Msg("failed to get node ID")
}

ctx, span := tracer.Start(ctx, spanName, trace.WithAttributes(
attribute.String("resource-type", resourceType),
attribute.StringSlice("resource-ids", req.ResourceIds),
attribute.String("subject", tuple.StringCoreONR(req.Subject)),
attribute.String("node-id", nodeID),
))
defer span.End()

Expand Down Expand Up @@ -261,8 +269,14 @@ func (ld *localDispatcher) DispatchCheck(ctx context.Context, req *v1.DispatchCh

// DispatchExpand implements dispatch.Expand interface
func (ld *localDispatcher) DispatchExpand(ctx context.Context, req *v1.DispatchExpandRequest) (*v1.DispatchExpandResponse, error) {
nodeID, err := nodeid.FromContext(ctx)
if err != nil {
log.Err(err).Msg("failed to get node ID")
}

ctx, span := tracer.Start(ctx, "DispatchExpand", trace.WithAttributes(
attribute.String("start", tuple.StringCoreONR(req.ResourceAndRelation)),
attribute.String("node-id", nodeID),
))
defer span.End()

Expand Down Expand Up @@ -296,13 +310,19 @@ func (ld *localDispatcher) DispatchReachableResources(
req *v1.DispatchReachableResourcesRequest,
stream dispatch.ReachableResourcesStream,
) error {
nodeID, err := nodeid.FromContext(stream.Context())
if err != nil {
log.Err(err).Msg("failed to get node ID")
}

resourceType := tuple.StringCoreRR(req.ResourceRelation)
subjectRelation := tuple.StringCoreRR(req.SubjectRelation)
spanName := "DispatchReachableResources → " + resourceType + "@" + subjectRelation
ctx, span := tracer.Start(stream.Context(), spanName, trace.WithAttributes(
attribute.String("resource-type", resourceType),
attribute.String("subject-type", subjectRelation),
attribute.StringSlice("subject-ids", req.SubjectIds),
attribute.String("node-id", nodeID),
))
defer span.End()

Expand All @@ -329,9 +349,15 @@ func (ld *localDispatcher) DispatchLookupResources(
req *v1.DispatchLookupResourcesRequest,
stream dispatch.LookupResourcesStream,
) error {
nodeID, err := nodeid.FromContext(stream.Context())
if err != nil {
log.Err(err).Msg("failed to get node ID")
}

ctx, span := tracer.Start(stream.Context(), "DispatchLookupResources", trace.WithAttributes(
attribute.String("resource-type", tuple.StringCoreRR(req.ObjectRelation)),
attribute.String("subject", tuple.StringCoreONR(req.Subject)),
attribute.String("node-id", nodeID),
))
defer span.End()

Expand All @@ -357,9 +383,15 @@ func (ld *localDispatcher) DispatchLookupResources2(
req *v1.DispatchLookupResources2Request,
stream dispatch.LookupResources2Stream,
) error {
nodeID, err := nodeid.FromContext(stream.Context())
if err != nil {
log.Err(err).Msg("failed to get node ID")
}

ctx, span := tracer.Start(stream.Context(), "DispatchLookupResources2", trace.WithAttributes(
attribute.String("resource-type", tuple.StringCoreRR(req.ResourceRelation)),
attribute.String("subject", tuple.StringCoreONR(req.TerminalSubject)),
attribute.String("node-id", nodeID),
))
defer span.End()

Expand All @@ -386,6 +418,11 @@ func (ld *localDispatcher) DispatchLookupSubjects(
req *v1.DispatchLookupSubjectsRequest,
stream dispatch.LookupSubjectsStream,
) error {
nodeID, err := nodeid.FromContext(stream.Context())
if err != nil {
log.Err(err).Msg("failed to get node ID")
}

resourceType := tuple.StringCoreRR(req.ResourceRelation)
subjectRelation := tuple.StringCoreRR(req.SubjectRelation)
spanName := "DispatchLookupSubjects → " + resourceType + "@" + subjectRelation
Expand All @@ -394,6 +431,7 @@ func (ld *localDispatcher) DispatchLookupSubjects(
attribute.String("resource-type", resourceType),
attribute.String("subject-type", subjectRelation),
attribute.StringSlice("resource-ids", req.ResourceIds),
attribute.String("node-id", nodeID),
))
defer span.End()

Expand Down
13 changes: 12 additions & 1 deletion internal/graph/check.go
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@ import (
"github.com/authzed/spicedb/internal/taskrunner"
"github.com/authzed/spicedb/pkg/datastore"
"github.com/authzed/spicedb/pkg/genutil/mapz"
"github.com/authzed/spicedb/pkg/middleware/nodeid"
nspkg "github.com/authzed/spicedb/pkg/namespace"
core "github.com/authzed/spicedb/pkg/proto/core/v1"
v1 "github.com/authzed/spicedb/pkg/proto/dispatch/v1"
Expand Down Expand Up @@ -113,14 +114,24 @@ func (cc *ConcurrentChecker) Check(ctx context.Context, req ValidatedCheckReques
return resolved.Resp, resolved.Err
}

nodeID, err := nodeid.FromContext(ctx)
if err != nil {
// NOTE: we ignore this error here as if the node ID is missing, the debug
// trace is still valid.
log.Err(err).Msg("failed to get node ID")
}

// Add debug information if requested.
debugInfo := resolved.Resp.Metadata.DebugInfo
if debugInfo == nil {
debugInfo = &v1.DebugInformation{
Check: &v1.CheckDebugTrace{
TraceId: uuid.NewString(),
TraceId: uuid.NewString(),
SourceId: nodeID,
},
}
} else if debugInfo.Check != nil && debugInfo.Check.SourceId == "" {
debugInfo.Check.SourceId = nodeID
}

// Remove the traversal bloom from the debug request to save some data over the
Expand Down
2 changes: 2 additions & 0 deletions internal/services/v1/debug.go
Original file line number Diff line number Diff line change
Expand Up @@ -204,6 +204,7 @@ func convertCheckTrace(ctx context.Context, caveatContext map[string]any, ct *di
},
},
Duration: ct.Duration,
Source: ct.SourceId,
}, nil
}

Expand All @@ -228,5 +229,6 @@ func convertCheckTrace(ctx context.Context, caveatContext map[string]any, ct *di
WasCachedResult: ct.IsCachedResult,
},
Duration: ct.Duration,
Source: ct.SourceId,
}, nil
}
14 changes: 14 additions & 0 deletions pkg/cmd/server/defaults.go
Original file line number Diff line number Diff line change
Expand Up @@ -39,6 +39,7 @@ import (
"github.com/authzed/spicedb/pkg/datastore"
consistencymw "github.com/authzed/spicedb/pkg/middleware/consistency"
logmw "github.com/authzed/spicedb/pkg/middleware/logging"
"github.com/authzed/spicedb/pkg/middleware/nodeid"
"github.com/authzed/spicedb/pkg/middleware/requestid"
"github.com/authzed/spicedb/pkg/middleware/serverversion"
"github.com/authzed/spicedb/pkg/releases"
Expand Down Expand Up @@ -164,6 +165,7 @@ var alwaysDebugOption = grpclog.WithLevels(func(code codes.Code) grpclog.Level {

const (
DefaultMiddlewareRequestID = "requestid"
DefaultMiddlewareNodeID = "nodeid"
DefaultMiddlewareLog = "log"
DefaultMiddlewareGRPCLog = "grpclog"
DefaultMiddlewareOTelGRPC = "otelgrpc"
Expand Down Expand Up @@ -296,6 +298,11 @@ func DefaultUnaryMiddleware(opts MiddlewareOption) (*MiddlewareChain[grpc.UnaryS
WithInterceptor(logmw.UnaryServerInterceptor(logmw.ExtractMetadataField(string(requestmeta.RequestIDKey), "requestID"))).
Done(),

NewUnaryMiddleware().
WithName(DefaultMiddlewareNodeID).
WithInterceptor(nodeid.UnaryServerInterceptor("")).
Done(),

NewUnaryMiddleware().
WithName(DefaultMiddlewareOTelGRPC).
WithInterceptor(otelgrpc.UnaryServerInterceptor()). // nolint: staticcheck
Expand Down Expand Up @@ -369,6 +376,11 @@ func DefaultStreamingMiddleware(opts MiddlewareOption) (*MiddlewareChain[grpc.St
WithInterceptor(logmw.StreamServerInterceptor(logmw.ExtractMetadataField(string(requestmeta.RequestIDKey), "requestID"))).
Done(),

NewStreamMiddleware().
WithName(DefaultMiddlewareNodeID).
WithInterceptor(nodeid.StreamServerInterceptor("")).
Done(),

NewStreamMiddleware().
WithName(DefaultMiddlewareOTelGRPC).
WithInterceptor(otelgrpc.StreamServerInterceptor()). // nolint: staticcheck
Expand Down Expand Up @@ -448,6 +460,7 @@ func DefaultDispatchMiddleware(logger zerolog.Logger, authFunc grpcauth.AuthFunc
grpcMetricsUnaryInterceptor, grpcMetricsStreamingInterceptor := GRPCMetrics(disableGRPCLatencyHistogram)
return []grpc.UnaryServerInterceptor{
requestid.UnaryServerInterceptor(requestid.GenerateIfMissing(true)),
nodeid.UnaryServerInterceptor(""),
logmw.UnaryServerInterceptor(logmw.ExtractMetadataField(string(requestmeta.RequestIDKey), "requestID")),
grpclog.UnaryServerInterceptor(InterceptorLogger(logger), dispatchDefaultCodeToLevel, durationFieldOption, traceIDFieldOption),
grpcMetricsUnaryInterceptor,
Expand All @@ -456,6 +469,7 @@ func DefaultDispatchMiddleware(logger zerolog.Logger, authFunc grpcauth.AuthFunc
servicespecific.UnaryServerInterceptor,
}, []grpc.StreamServerInterceptor{
requestid.StreamServerInterceptor(requestid.GenerateIfMissing(true)),
nodeid.StreamServerInterceptor(""),
logmw.StreamServerInterceptor(logmw.ExtractMetadataField(string(requestmeta.RequestIDKey), "requestID")),
grpclog.StreamServerInterceptor(InterceptorLogger(logger), dispatchDefaultCodeToLevel, durationFieldOption, traceIDFieldOption),
grpcMetricsStreamingInterceptor,
Expand Down
88 changes: 88 additions & 0 deletions pkg/middleware/nodeid/nodeid.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,88 @@
package nodeid

import (
"context"
"os"

middleware "github.com/grpc-ecosystem/go-grpc-middleware/v2"
"google.golang.org/grpc"
)

const spiceDBPrefix = "spicedb:"

type ctxKeyType struct{}

var nodeIDKey ctxKeyType = struct{}{}

type nodeIDHandle struct {
nodeID string
}

var defaultNodeID string

// ContextWithHandle adds a placeholder to a context that will later be
// filled by the Node ID.
func ContextWithHandle(ctx context.Context) context.Context {
return context.WithValue(ctx, nodeIDKey, &nodeIDHandle{})
}

// FromContext reads the node's ID out of a context.Context.
func FromContext(ctx context.Context) (string, error) {
if c := ctx.Value(nodeIDKey); c != nil {
handle := c.(*nodeIDHandle)
return handle.nodeID, nil
}

if defaultNodeID == "" {
hostname, err := os.Hostname()
if err != nil {
return "", err
}
defaultNodeID = spiceDBPrefix + hostname
}

if err := setInContext(ctx, defaultNodeID); err != nil {
return "", err
}

return defaultNodeID, nil
}

// setInContext adds a node ID to the given context
func setInContext(ctx context.Context, nodeID string) error {
handle := ctx.Value(nodeIDKey)
if handle == nil {
return nil
}
handle.(*nodeIDHandle).nodeID = nodeID
return nil
}

// UnaryServerInterceptor returns a new unary server interceptor that adds the
// node ID to the context. If empty, spicedb:$hostname is used.
func UnaryServerInterceptor(nodeID string) grpc.UnaryServerInterceptor {
return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (interface{}, error) {
newCtx := ContextWithHandle(ctx)
if nodeID != "" {
if err := setInContext(newCtx, nodeID); err != nil {
return nil, err
}
}
return handler(newCtx, req)
}
}

// StreamServerInterceptor returns a new stream server interceptor that adds the
// node ID to the context. If empty, spicedb:$hostname is used.
func StreamServerInterceptor(nodeID string) grpc.StreamServerInterceptor {
return func(srv interface{}, stream grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error {
wrapped := middleware.WrapServerStream(stream)
wrapped.WrappedContext = ContextWithHandle(wrapped.WrappedContext)
if nodeID != "" {
if err := setInContext(wrapped.WrappedContext, nodeID); err != nil {
return err
}
}
return handler(srv, wrapped)
}
}
Loading

0 comments on commit ab97060

Please sign in to comment.