diff --git a/api/billing/fees/internal/service/fees/logging.go b/api/billing/fees/internal/service/fees/logging.go new file mode 100644 index 0000000..d621628 --- /dev/null +++ b/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 +} diff --git a/api/billing/fees/internal/service/fees/service.go b/api/billing/fees/internal/service/fees/service.go index f788601..bcf74df 100644 --- a/api/billing/fees/internal/service/fees/service.go +++ b/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") }