Merge pull request 'logging-84' (#83) from logging-84 into main

Reviewed-on: #83

api/billing/fees/internal/service/fees/logging.go

@@ -0,0 +1,88 @@
+package fees
+
+import (
+	"strings"
+	"time"
+
+	feesv1 "github.com/tech/sendico/pkg/proto/billing/fees/v1"
+	tracev1 "github.com/tech/sendico/pkg/proto/common/trace/v1"
+	"go.uber.org/zap"
+)
+
+func requestLogFields(meta *feesv1.RequestMeta, intent *feesv1.Intent) []zap.Field {
+	fields := logFieldsFromRequestMeta(meta)
+	fields = append(fields, logFieldsFromIntent(intent)...)
+	return fields
+}
+
+func logFieldsFromRequestMeta(meta *feesv1.RequestMeta) []zap.Field {
+	if meta == nil {
+		return nil
+	}
+	fields := make([]zap.Field, 0, 4)
+	if org := strings.TrimSpace(meta.GetOrganizationRef()); org != "" {
+		fields = append(fields, zap.String("organization_ref", org))
+	}
+	fields = append(fields, logFieldsFromTrace(meta.GetTrace())...)
+	return fields
+}
+
+func logFieldsFromIntent(intent *feesv1.Intent) []zap.Field {
+	if intent == nil {
+		return nil
+	}
+	fields := make([]zap.Field, 0, 5)
+	if trigger := intent.GetTrigger(); trigger != feesv1.Trigger_TRIGGER_UNSPECIFIED {
+		fields = append(fields, zap.String("trigger", trigger.String()))
+	}
+	if base := intent.GetBaseAmount(); base != nil {
+		if amount := strings.TrimSpace(base.GetAmount()); amount != "" {
+			fields = append(fields, zap.String("base_amount", amount))
+		}
+		if currency := strings.TrimSpace(base.GetCurrency()); currency != "" {
+			fields = append(fields, zap.String("base_currency", currency))
+		}
+	}
+	if booked := intent.GetBookedAt(); booked != nil && booked.IsValid() {
+		fields = append(fields, zap.Time("booked_at", booked.AsTime()))
+	}
+	if attrs := intent.GetAttributes(); len(attrs) > 0 {
+		fields = append(fields, zap.Int("attributes_count", len(attrs)))
+	}
+	return fields
+}
+
+func logFieldsFromTrace(trace *tracev1.TraceContext) []zap.Field {
+	if trace == nil {
+		return nil
+	}
+	fields := make([]zap.Field, 0, 3)
+	if reqRef := strings.TrimSpace(trace.GetRequestRef()); reqRef != "" {
+		fields = append(fields, zap.String("request_ref", reqRef))
+	}
+	if idem := strings.TrimSpace(trace.GetIdempotencyKey()); idem != "" {
+		fields = append(fields, zap.String("idempotency_key", idem))
+	}
+	if traceRef := strings.TrimSpace(trace.GetTraceRef()); traceRef != "" {
+		fields = append(fields, zap.String("trace_ref", traceRef))
+	}
+	return fields
+}
+
+func logFieldsFromTokenPayload(payload *feeQuoteTokenPayload) []zap.Field {
+	if payload == nil {
+		return nil
+	}
+	fields := make([]zap.Field, 0, 6)
+	if org := strings.TrimSpace(payload.OrganizationRef); org != "" {
+		fields = append(fields, zap.String("organization_ref", org))
+	}
+	if payload.ExpiresAtUnixMs > 0 {
+		fields = append(fields,
+			zap.Int64("expires_at_unix_ms", payload.ExpiresAtUnixMs),
+			zap.Time("expires_at", time.UnixMilli(payload.ExpiresAtUnixMs)))
+	}
+	fields = append(fields, logFieldsFromIntent(payload.Intent)...)
+	fields = append(fields, logFieldsFromTrace(payload.Trace)...)
+	return fields
+}

api/billing/fees/internal/service/fees/service.go

@@ -72,26 +72,57 @@ func (s *Service) Register(router routers.GRPC) error {
 }
 
 func (s *Service) QuoteFees(ctx context.Context, req *feesv1.QuoteFeesRequest) (resp *feesv1.QuoteFeesResponse, err error) {
+	var (
+		meta   *feesv1.RequestMeta
+		intent *feesv1.Intent
+	)
+	if req != nil {
+		meta = req.GetMeta()
+		intent = req.GetIntent()
+	}
+	logger := s.logger.With(requestLogFields(meta, intent)...)
+
 	start := s.clock.Now()
 	trigger := feesv1.Trigger_TRIGGER_UNSPECIFIED
-	if req != nil && req.GetIntent() != nil {
-		trigger = req.GetIntent().GetTrigger()
+	if intent != nil {
+		trigger = intent.GetTrigger()
 	}
 	var fxUsed bool
 	defer func() {
 		statusLabel := statusFromError(err)
+		linesCount := 0
+		appliedCount := 0
 		if err == nil && resp != nil {
 			fxUsed = resp.GetFxUsed() != nil
+			linesCount = len(resp.GetLines())
+			appliedCount = len(resp.GetApplied())
 		}
 		observeMetrics("quote", trigger, statusLabel, fxUsed, time.Since(start))
+
+		logFields := []zap.Field{
+			zap.String("status", statusLabel),
+			zap.Duration("duration", time.Since(start)),
+			zap.Bool("fx_used", fxUsed),
+			zap.String("trigger", trigger.String()),
+			zap.Int("lines", linesCount),
+			zap.Int("applied_rules", appliedCount),
+		}
+		if err != nil {
+			logger.Warn("QuoteFees finished", append(logFields, zap.Error(err))...)
+			return
+		}
+		logger.Info("QuoteFees finished", logFields...)
 	}()
 
+	logger.Debug("QuoteFees request received")
+
 	if err = s.validateQuoteRequest(req); err != nil {
 		return nil, err
 	}
 
 	orgRef, parseErr := primitive.ObjectIDFromHex(req.GetMeta().GetOrganizationRef())
 	if parseErr != nil {
+		logger.Warn("QuoteFees invalid organization_ref", zap.Error(parseErr))
 		err = status.Error(codes.InvalidArgument, "invalid organization_ref")
 		return nil, err
 	}
@@ -112,20 +143,59 @@ func (s *Service) QuoteFees(ctx context.Context, req *feesv1.QuoteFeesRequest) (
 }
 
 func (s *Service) PrecomputeFees(ctx context.Context, req *feesv1.PrecomputeFeesRequest) (resp *feesv1.PrecomputeFeesResponse, err error) {
+	var (
+		meta   *feesv1.RequestMeta
+		intent *feesv1.Intent
+	)
+	if req != nil {
+		meta = req.GetMeta()
+		intent = req.GetIntent()
+	}
+	logger := s.logger.With(requestLogFields(meta, intent)...)
+
 	start := s.clock.Now()
 	trigger := feesv1.Trigger_TRIGGER_UNSPECIFIED
-	if req != nil && req.GetIntent() != nil {
-		trigger = req.GetIntent().GetTrigger()
+	if intent != nil {
+		trigger = intent.GetTrigger()
 	}
-	var fxUsed bool
+	var (
+		fxUsed    bool
+		expiresAt time.Time
+	)
 	defer func() {
 		statusLabel := statusFromError(err)
+		linesCount := 0
+		appliedCount := 0
 		if err == nil && resp != nil {
 			fxUsed = resp.GetFxUsed() != nil
+			linesCount = len(resp.GetLines())
+			appliedCount = len(resp.GetApplied())
+			if ts := resp.GetExpiresAt(); ts != nil {
+				expiresAt = ts.AsTime()
+			}
 		}
 		observeMetrics("precompute", trigger, statusLabel, fxUsed, time.Since(start))
+
+		logFields := []zap.Field{
+			zap.String("status", statusLabel),
+			zap.Duration("duration", time.Since(start)),
+			zap.Bool("fx_used", fxUsed),
+			zap.String("trigger", trigger.String()),
+			zap.Int("lines", linesCount),
+			zap.Int("applied_rules", appliedCount),
+		}
+		if !expiresAt.IsZero() {
+			logFields = append(logFields, zap.Time("expires_at", expiresAt))
+		}
+		if err != nil {
+			logger.Warn("PrecomputeFees finished", append(logFields, zap.Error(err))...)
+			return
+		}
+		logger.Info("PrecomputeFees finished", logFields...)
 	}()
 
+	logger.Debug("PrecomputeFees request received")
+
 	if err = s.validatePrecomputeRequest(req); err != nil {
 		return nil, err
 	}
@@ -134,6 +204,7 @@ func (s *Service) PrecomputeFees(ctx context.Context, req *feesv1.PrecomputeFees
 
 	orgRef, parseErr := primitive.ObjectIDFromHex(req.GetMeta().GetOrganizationRef())
 	if parseErr != nil {
+		logger.Warn("PrecomputeFees invalid organization_ref", zap.Error(parseErr))
 		err = status.Error(codes.InvalidArgument, "invalid organization_ref")
 		return nil, err
 	}
@@ -148,7 +219,7 @@ func (s *Service) PrecomputeFees(ctx context.Context, req *feesv1.PrecomputeFees
 	if ttl <= 0 {
 		ttl = 60000
 	}
-	expiresAt := now.Add(time.Duration(ttl) * time.Millisecond)
+	expiresAt = now.Add(time.Duration(ttl) * time.Millisecond)
 
 	payload := feeQuoteTokenPayload{
 		OrganizationRef: req.GetMeta().GetOrganizationRef(),
@@ -159,7 +230,7 @@ func (s *Service) PrecomputeFees(ctx context.Context, req *feesv1.PrecomputeFees
 
 	var token string
 	if token, err = encodeTokenPayload(payload); err != nil {
-		s.logger.Warn("failed to encode fee quote token", zap.Error(err))
+		logger.Warn("failed to encode fee quote token", zap.Error(err))
 		err = status.Error(codes.Internal, "failed to encode fee quote token")
 		return nil, err
 	}
@@ -176,9 +247,18 @@ func (s *Service) PrecomputeFees(ctx context.Context, req *feesv1.PrecomputeFees
 }
 
 func (s *Service) ValidateFeeToken(ctx context.Context, req *feesv1.ValidateFeeTokenRequest) (resp *feesv1.ValidateFeeTokenResponse, err error) {
+	tokenLen := 0
+	if req != nil {
+		tokenLen = len(strings.TrimSpace(req.GetFeeQuoteToken()))
+	}
+	logger := s.logger.With(zap.Int("token_length", tokenLen))
+
 	start := s.clock.Now()
 	trigger := feesv1.Trigger_TRIGGER_UNSPECIFIED
-	var fxUsed bool
+	var (
+		fxUsed       bool
+		resultReason string
+	)
 	defer func() {
 		statusLabel := statusFromError(err)
 		if err == nil && resp != nil {
@@ -191,9 +271,28 @@ func (s *Service) ValidateFeeToken(ctx context.Context, req *feesv1.ValidateFeeT
 			}
 		}
 		observeMetrics("validate", trigger, statusLabel, fxUsed, time.Since(start))
+
+		logFields := []zap.Field{
+			zap.String("status", statusLabel),
+			zap.Duration("duration", time.Since(start)),
+			zap.Bool("fx_used", fxUsed),
+			zap.String("trigger", trigger.String()),
+			zap.Bool("valid", resp != nil && resp.GetValid()),
+		}
+		if resultReason != "" {
+			logFields = append(logFields, zap.String("reason", resultReason))
+		}
+		if err != nil {
+			logger.Warn("ValidateFeeToken finished", append(logFields, zap.Error(err))...)
+			return
+		}
+		logger.Info("ValidateFeeToken finished", logFields...)
 	}()
 
+	logger.Debug("ValidateFeeToken request received")
+
 	if req == nil || strings.TrimSpace(req.GetFeeQuoteToken()) == "" {
+		resultReason = "missing_token"
 		err = status.Error(codes.InvalidArgument, "fee_quote_token is required")
 		return nil, err
 	}
@@ -202,21 +301,29 @@ func (s *Service) ValidateFeeToken(ctx context.Context, req *feesv1.ValidateFeeT
 
 	payload, decodeErr := decodeTokenPayload(req.GetFeeQuoteToken())
 	if decodeErr != nil {
-		s.logger.Warn("failed to decode fee quote token", zap.Error(decodeErr))
+		resultReason = "invalid_token"
+		logger.Warn("failed to decode fee quote token", zap.Error(decodeErr))
 		resp = &feesv1.ValidateFeeTokenResponse{Meta: &feesv1.ResponseMeta{}, Valid: false, Reason: "invalid_token"}
 		return resp, nil
 	}
 
-	trigger = payload.Intent.GetTrigger()
+	logger = logger.With(logFieldsFromTokenPayload(&payload)...)
+
+	if payload.Intent != nil {
+		trigger = payload.Intent.GetTrigger()
+	}
 
 	if now.UnixMilli() > payload.ExpiresAtUnixMs {
+		resultReason = "expired"
+		logger.Info("fee quote token expired")
 		resp = &feesv1.ValidateFeeTokenResponse{Meta: &feesv1.ResponseMeta{}, Valid: false, Reason: "expired"}
 		return resp, nil
 	}
 
 	orgRef, parseErr := primitive.ObjectIDFromHex(payload.OrganizationRef)
 	if parseErr != nil {
-		s.logger.Warn("token contained invalid organization reference", zap.Error(parseErr))
+		resultReason = "invalid_token"
+		logger.Warn("token contained invalid organization reference", zap.Error(parseErr))
 		resp = &feesv1.ValidateFeeTokenResponse{Meta: &feesv1.ResponseMeta{}, Valid: false, Reason: "invalid_token"}
 		return resp, nil
 	}
@@ -280,6 +387,16 @@ func (s *Service) computeQuoteWithTime(ctx context.Context, orgRef primitive.Obj
 		bookedAt = intent.GetBookedAt().AsTime()
 	}
 
+	logFields := []zap.Field{
+		zap.Time("booked_at_used", bookedAt),
+	}
+	if !orgRef.IsZero() {
+		logFields = append(logFields, zap.String("organization_ref", orgRef.Hex()))
+	}
+	logFields = append(logFields, logFieldsFromIntent(intent)...)
+	logFields = append(logFields, logFieldsFromTrace(trace)...)
+	logger := s.logger.With(logFields...)
+
 	var orgPtr *primitive.ObjectID
 	if !orgRef.IsZero() {
 		orgPtr = &orgRef
@@ -288,7 +405,7 @@ func (s *Service) computeQuoteWithTime(ctx context.Context, orgRef primitive.Obj
 	plan, rule, err := s.resolver.ResolveFeeRule(ctx, orgPtr, convertTrigger(intent.GetTrigger()), bookedAt, intent.GetAttributes())
 	if err != nil {
 		switch {
-	case errors.Is(err, merrors.ErrNoData):
+		case errors.Is(err, merrors.ErrNoData):
 			return nil, nil, nil, status.Error(codes.NotFound, "fee rule not found")
 		case errors.Is(err, merrors.ErrDataConflict):
 			return nil, nil, nil, status.Error(codes.FailedPrecondition, "conflicting fee rules")
@@ -297,7 +414,7 @@ func (s *Service) computeQuoteWithTime(ctx context.Context, orgRef primitive.Obj
 		case errors.Is(err, storage.ErrFeePlanNotFound):
 			return nil, nil, nil, status.Error(codes.NotFound, "fee plan not found")
 		default:
-			s.logger.Warn("failed to resolve fee rule", zap.Error(err))
+			logger.Warn("failed to resolve fee rule", zap.Error(err))
 			return nil, nil, nil, status.Error(codes.Internal, "failed to resolve fee rule")
 		}
 	}
@@ -313,7 +430,7 @@ func (s *Service) computeQuoteWithTime(ctx context.Context, orgRef primitive.Obj
 		if errors.Is(calcErr, merrors.ErrInvalidArg) {
 			return nil, nil, nil, status.Error(codes.InvalidArgument, calcErr.Error())
 		}
-		s.logger.Warn("failed to compute fee quote", zap.Error(calcErr))
+		logger.Warn("failed to compute fee quote", zap.Error(calcErr))
 		return nil, nil, nil, status.Error(codes.Internal, "failed to compute fee quote")
 	}