From 324f1509502374e345691a05ea26122cf0303692 Mon Sep 17 00:00:00 2001 From: Stephan D Date: Thu, 11 Dec 2025 22:25:04 +0100 Subject: [PATCH] improved logging --- .../fees/internal/service/fees/service.go | 145 ++++++++++++++++-- 1 file changed, 131 insertions(+), 14 deletions(-) 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") }