Service logging

internal/biz/relationships.go

@@ -38,7 +38,6 @@ func NewCheckUsecase(repo ZanzibarRepository, logger log.Logger) *CheckUsecase {
 }
 
 func (rc *CheckUsecase) Check(ctx context.Context, check *v0.CheckRequest) (*v0.CheckResponse, error) {
-	rc.log.WithContext(ctx).Infof("Check: %v", check)
 	return rc.repo.Check(ctx, check)
 }
 
@@ -52,7 +51,6 @@ func NewCreateRelationshipsUsecase(repo ZanzibarRepository, logger log.Logger) *
 }
 
 func (rc *CreateRelationshipsUsecase) CreateRelationships(ctx context.Context, r []*v0.Relationship, touch bool) error {
-	rc.log.WithContext(ctx).Infof("CreateTuples: %v %s", r, touch)
 	return rc.repo.CreateRelationships(ctx, r, TouchSemantics(touch))
 }
 
@@ -66,8 +64,6 @@ func NewReadRelationshipsUsecase(repo ZanzibarRepository, logger log.Logger) *Re
 }
 
 func (rc *ReadRelationshipsUsecase) ReadRelationships(ctx context.Context, req *v0.ReadTuplesRequest) (chan *RelationshipResult, chan error, error) {
-	rc.log.WithContext(ctx).Infof("ReadTuples: %v", req)
-
 	limit := uint32(MaxStreamingCount)
 	continuation := ContinuationToken("")
 
@@ -100,6 +96,5 @@ func NewDeleteRelationshipsUsecase(repo ZanzibarRepository, logger log.Logger) *
 }
 
 func (rc *DeleteRelationshipsUsecase) DeleteRelationships(ctx context.Context, r *v0.RelationTupleFilter) error {
-	rc.log.WithContext(ctx).Infof("DeleteTuples: %v", r)
 	return rc.repo.DeleteRelationships(ctx, r)
 }

internal/data/spicedb.go

@@ -44,9 +44,7 @@ func NewSpiceDbRepository(c *conf.Data, logger log.Logger) (*SpiceDbRepository,
 		}
 	}
 	if token == "" {
-		err := fmt.Errorf("token is empty: %s", token)
-		log.NewHelper(logger).Error(err)
-		return nil, nil, err
+		return nil, nil, fmt.Errorf("error creating spicedb client: token is empty")
 	}
 
 	if !c.SpiceDb.UseTLS {
@@ -64,10 +62,7 @@ func NewSpiceDbRepository(c *conf.Data, logger log.Logger) (*SpiceDbRepository,
 	)
 
 	if err != nil {
-		err = fmt.Errorf("error creating spicedb client: %w", err)
-		log.NewHelper(logger).Error(err)
-
-		return nil, nil, err
+		return nil, nil, fmt.Errorf("error creating spicedb client: %w", err)
 	}
 
 	cleanup := func() {
@@ -85,7 +80,7 @@ func (s *SpiceDbRepository) LookupSubjects(ctx context.Context, subject_type *ap
 		}
 	}
 
-	client, err := s.client.LookupSubjects(ctx, &v1.LookupSubjectsRequest{
+	req := &v1.LookupSubjectsRequest{
 		Resource: &v1.ObjectReference{
 			ObjectType: kesselTypeToSpiceDBType(object.Type),
 			ObjectId:   object.Id,
@@ -96,10 +91,12 @@ func (s *SpiceDbRepository) LookupSubjects(ctx context.Context, subject_type *ap
 		OptionalSubjectRelation: subject_relation,
 		OptionalConcreteLimit:   limit,
 		OptionalCursor:          cursor,
-	})
+	}
+
+	client, err := s.client.LookupSubjects(ctx, req)
 
 	if err != nil {
-		return nil, nil, err
+		return nil, nil, fmt.Errorf("error invoking LookupSubjects in SpiceDB: %w", err)
 	}
 
 	subjects := make(chan *biz.SubjectResult)
@@ -110,7 +107,7 @@ func (s *SpiceDbRepository) LookupSubjects(ctx context.Context, subject_type *ap
 			msg, err := client.Recv()
 			if err != nil {
 				if !errors.Is(err, io.EOF) {
-					errs <- err
+					errs <- fmt.Errorf("error receiving subject from SpiceDB: %w", err)
 				}
 				close(errs)
 				close(subjects)
@@ -159,7 +156,10 @@ func (s *SpiceDbRepository) CreateRelationships(ctx context.Context, rels []*api
 		Updates: relationshipUpdates,
 	})
 
-	return err
+	if err != nil {
+		return fmt.Errorf("error writing relationships to SpiceDB: %w", err)
+	}
+	return nil
 }
 
 func (s *SpiceDbRepository) ReadRelationships(ctx context.Context, filter *apiV0.RelationTupleFilter, limit uint32, continuation biz.ContinuationToken) (chan *biz.RelationshipResult, chan error, error) {
@@ -169,14 +169,17 @@ func (s *SpiceDbRepository) ReadRelationships(ctx context.Context, filter *apiV0
 			Token: string(continuation),
 		}
 	}
-	client, err := s.client.ReadRelationships(ctx, &v1.ReadRelationshipsRequest{
+
+	req := &v1.ReadRelationshipsRequest{
 		RelationshipFilter: createSpiceDbRelationshipFilter(filter),
 		OptionalLimit:      limit,
 		OptionalCursor:     cursor,
-	})
+	}
+
+	client, err := s.client.ReadRelationships(ctx, req)
 
 	if err != nil {
-		return nil, nil, err
+		return nil, nil, fmt.Errorf("error invoking WriteRelationships in SpiceDB: %w", err)
 	}
 
 	relationshipTuples := make(chan *biz.RelationshipResult)
@@ -230,7 +233,7 @@ func (s *SpiceDbRepository) DeleteRelationships(ctx context.Context, filter *api
 
 	// TODO: we have not specified an option in our API to allow partial deletions, so currently it's all or nothing
 	if err != nil {
-		return err
+		return fmt.Errorf("error invoking DeleteRelationships in SpiceDB %w", err)
 	}
 
 	return nil
@@ -249,14 +252,14 @@ func (s *SpiceDbRepository) Check(ctx context.Context, check *apiV0.CheckRequest
 		ObjectType: kesselTypeToSpiceDBType(check.GetResource().GetType()),
 		ObjectId:   check.GetResource().GetId(),
 	}
-	checkResponse, err := s.client.CheckPermission(ctx, &v1.CheckPermissionRequest{
+	req := &v1.CheckPermissionRequest{
 		Resource:   resource,
 		Permission: check.GetRelation(),
 		Subject:    subject,
-	})
+	}
+	checkResponse, err := s.client.CheckPermission(ctx, req)
 	if err != nil {
-		log.Errorf("Error check permission %v", err.Error())
-		return &apiV0.CheckResponse{Allowed: apiV0.CheckResponse_ALLOWED_UNSPECIFIED}, err
+		return &apiV0.CheckResponse{Allowed: apiV0.CheckResponse_ALLOWED_UNSPECIFIED}, fmt.Errorf("error invoking CheckPermission in SpiceDB: %w", err)
 	}
 
 	if checkResponse.Permissionship == v1.CheckPermissionResponse_PERMISSIONSHIP_HAS_PERMISSION {

internal/server/grpc.go

@@ -4,9 +4,11 @@ import (
 	h "github.com/project-kessel/relations-api/api/health/v1"
 	v0 "github.com/project-kessel/relations-api/api/relations/v0"
 	"github.com/project-kessel/relations-api/internal/conf"
+	"github.com/project-kessel/relations-api/internal/server/middleware"
 	"github.com/project-kessel/relations-api/internal/service"
 
 	"github.com/go-kratos/kratos/v2/log"
+	"github.com/go-kratos/kratos/v2/middleware/logging"
 	"github.com/go-kratos/kratos/v2/middleware/recovery"
 	"github.com/go-kratos/kratos/v2/middleware/validate"
 	"github.com/go-kratos/kratos/v2/transport/grpc"
@@ -18,7 +20,9 @@ func NewGRPCServer(c *conf.Server, relations *service.RelationshipsService, heal
 		grpc.Middleware(
 			recovery.Recovery(),
 			validate.Validator(),
+			logging.Server(logger),
 		),
+		grpc.StreamInterceptor(middleware.StreamLogInterceptor(logger)),
 	}
 	if c.Grpc.Network != "" {
 		opts = append(opts, grpc.Network(c.Grpc.Network))

internal/server/http.go

@@ -7,6 +7,7 @@ import (
 	"github.com/project-kessel/relations-api/internal/service"
 
 	"github.com/go-kratos/kratos/v2/log"
+	"github.com/go-kratos/kratos/v2/middleware/logging"
 	"github.com/go-kratos/kratos/v2/middleware/recovery"
 	"github.com/go-kratos/kratos/v2/middleware/validate"
 	"github.com/go-kratos/kratos/v2/transport/http"
@@ -18,6 +19,7 @@ func NewHTTPServer(c *conf.Server, relationships *service.RelationshipsService,
 		http.Middleware(
 			recovery.Recovery(),
 			validate.Validator(),
+			logging.Server(logger),
 		),
 	}
 	if c.Http.Network != "" {

internal/server/middleware/logging.go

@@ -0,0 +1,84 @@
+package middleware
+
+import (
+	"fmt"
+	"time"
+
+	"github.com/go-kratos/kratos/v2/errors"
+	"github.com/go-kratos/kratos/v2/log"
+	"github.com/go-kratos/kratos/v2/middleware/logging"
+	"google.golang.org/grpc"
+)
+
+func StreamLogInterceptor(logger log.Logger) grpc.StreamServerInterceptor {
+	return func(srv any, ss grpc.ServerStream, info *grpc.StreamServerInfo, handler grpc.StreamHandler) error {
+		var (
+			code      int32
+			reason    string
+			kind      string
+			operation string
+		)
+		ctx := ss.Context()
+		startTime := time.Now()
+		operation = info.FullMethod
+		kind = "server"
+		wrapper := &requestInterceptingWrapper{ServerStream: ss}
+		err := handler(srv, wrapper)
+
+		if se := errors.FromError(err); se != nil {
+			code = se.Code
+			reason = se.Reason
+		}
+		level, stack := extractError(err)
+
+		log.NewHelper(log.WithContext(ctx, logger)).Log(level,
+			"kind", kind,
+			"component", kind,
+			"operation", operation,
+			"args", extractArgs(wrapper.req),
+			"code", code,
+			"reason", reason,
+			"stack", stack,
+			"latency", time.Since(startTime).Seconds())
+
+		return err
+	}
+}
+
+type requestInterceptingWrapper struct {
+	req any
+	grpc.ServerStream
+}
+
+func (w *requestInterceptingWrapper) RecvMsg(m interface{}) error {
+	err := w.ServerStream.RecvMsg(m) //Includes deserializing m, all fields are empty before this point
+	if w.req == nil {
+		w.req = m
+	}
+
+	return err
+}
+
+func (w *requestInterceptingWrapper) SendMsg(m interface{}) error {
+	return w.ServerStream.SendMsg(m)
+}
+
+// Taken from Kratos logging middleware
+// extractArgs returns the string of the req
+func extractArgs(req interface{}) string {
+	if redacter, ok := req.(logging.Redacter); ok {
+		return redacter.Redact()
+	}
+	if stringer, ok := req.(fmt.Stringer); ok {
+		return stringer.String()
+	}
+	return fmt.Sprintf("%+v", req)
+}
+
+// extractError returns the string of the error
+func extractError(err error) (log.Level, string) {
+	if err != nil {
+		return log.LevelError, fmt.Sprintf("%+v", err)
+	}
+	return log.LevelInfo, ""
+}

internal/service/check.go

@@ -2,6 +2,8 @@ package service
 
 import (
 	"context"
+	"fmt"
+
 	"github.com/project-kessel/relations-api/internal/biz"
 
 	"github.com/go-kratos/kratos/v2/log"
@@ -23,11 +25,9 @@ func NewCheckService(logger log.Logger, checkUseCase *biz.CheckUsecase) *CheckSe
 }
 
 func (s *CheckService) Check(ctx context.Context, req *pb.CheckRequest) (*pb.CheckResponse, error) {
-	s.log.Infof("Check permission: %v", req)
 	resp, err := s.check.Check(ctx, req)
 	if err != nil {
-		s.log.Errorf("Failed to perform check %v", err)
-		return resp, err
+		return resp, fmt.Errorf("failed to perform check: %w", err)
 	}
 	return resp, nil
 }

internal/service/lookup.go

@@ -1,6 +1,8 @@
 package service
 
 import (
+	"fmt"
+
 	"github.com/go-kratos/kratos/v2/errors"
 	"github.com/go-kratos/kratos/v2/log"
 	pb "github.com/project-kessel/relations-api/api/relations/v0"
@@ -33,11 +35,12 @@ func (s *LookupService) LookupSubjects(req *pb.LookupSubjectsRequest, conn pb.Ke
 	}
 
 	ctx := conn.Context()
+	s.log.Debugf("Lookup subjects request: %v", req) //TODO: remove when logging middleware supports streaming
 
 	subs, errs, err := s.subjectsUsecase.Get(ctx, req)
 
 	if err != nil {
-		return err
+		return fmt.Errorf("error retrieving subjects: %w", err)
 	}
 
 	for sub := range subs {
@@ -46,13 +49,13 @@ func (s *LookupService) LookupSubjects(req *pb.LookupSubjectsRequest, conn pb.Ke
 			Pagination: &pb.ResponsePagination{ContinuationToken: string(sub.Continuation)},
 		})
 		if err != nil {
-			return err
+			return fmt.Errorf("error sending retrieved subject to the client: %w", err)
 		}
 	}
 
 	err, ok := <-errs
 	if ok {
-		return err
+		return fmt.Errorf("error received while streaming subjects from Zanzibar backend: %w", err)
 	}
 
 	return nil

internal/service/lookup_test.go

@@ -2,11 +2,12 @@ package service
 
 import (
 	"context"
+	"os"
+	"testing"
+
 	v0 "github.com/project-kessel/relations-api/api/relations/v0"
 	"github.com/project-kessel/relations-api/internal/biz"
 	"github.com/project-kessel/relations-api/internal/data"
-	"os"
-	"testing"
 
 	"github.com/go-kratos/kratos/v2/log"
 	"github.com/go-kratos/kratos/v2/middleware/tracing"