From a5ad4f4c3c487ab347cdda0434f22996fcbb3875 Mon Sep 17 00:00:00 2001 From: Stephan D Date: Fri, 12 Dec 2025 00:44:04 +0100 Subject: [PATCH] fx/oracle logging --- .../oracle/internal/service/oracle/logging.go | 90 +++++++++++++++++++ .../oracle/internal/service/oracle/service.go | 84 ++++++++++++++--- 2 files changed, 160 insertions(+), 14 deletions(-) create mode 100644 api/fx/oracle/internal/service/oracle/logging.go diff --git a/api/fx/oracle/internal/service/oracle/logging.go b/api/fx/oracle/internal/service/oracle/logging.go new file mode 100644 index 0000000..578e319 --- /dev/null +++ b/api/fx/oracle/internal/service/oracle/logging.go @@ -0,0 +1,90 @@ +package oracle + +import ( + "strings" + + fxv1 "github.com/tech/sendico/pkg/proto/common/fx/v1" + moneyv1 "github.com/tech/sendico/pkg/proto/common/money/v1" + tracev1 "github.com/tech/sendico/pkg/proto/common/trace/v1" + oraclev1 "github.com/tech/sendico/pkg/proto/oracle/v1" + "go.uber.org/zap" +) + +func quoteRequestFields(req *oraclev1.GetQuoteRequest) []zap.Field { + if req == nil { + return nil + } + fields := requestMetaFields(req.GetMeta()) + if pair := req.GetPair(); pair != nil { + if base := strings.TrimSpace(pair.GetBase()); base != "" { + fields = append(fields, zap.String("pair_base", base)) + } + if quote := strings.TrimSpace(pair.GetQuote()); quote != "" { + fields = append(fields, zap.String("pair_quote", quote)) + } + } + if side := req.GetSide(); side != fxv1.Side_SIDE_UNSPECIFIED { + fields = append(fields, zap.String("side", side.String())) + } + if req.GetFirm() { + fields = append(fields, zap.Bool("firm", req.GetFirm())) + } + if ttl := req.GetTtlMs(); ttl > 0 { + fields = append(fields, zap.Int64("ttl_ms", ttl)) + } + if maxAge := req.GetMaxAgeMs(); maxAge > 0 { + fields = append(fields, zap.Int32("max_age_ms", maxAge)) + } + if provider := strings.TrimSpace(req.GetPreferredProvider()); provider != "" { + fields = append(fields, zap.String("preferred_provider", provider)) + } + fields = append(fields, moneyFields("base_amount", req.GetBaseAmount())...) + fields = append(fields, moneyFields("quote_amount", req.GetQuoteAmount())...) + return fields +} + +func requestMetaFields(meta *oraclev1.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)) + } + if tenant := strings.TrimSpace(meta.GetTenantRef()); tenant != "" { + fields = append(fields, zap.String("tenant_ref", tenant)) + } + fields = append(fields, traceFields(meta.GetTrace())...) + return fields +} + +func moneyFields(prefix string, money *moneyv1.Money) []zap.Field { + if money == nil { + return nil + } + fields := make([]zap.Field, 0, 2) + if amt := strings.TrimSpace(money.GetAmount()); amt != "" { + fields = append(fields, zap.String(prefix, amt)) + } + if ccy := strings.TrimSpace(money.GetCurrency()); ccy != "" { + fields = append(fields, zap.String(prefix+"_currency", ccy)) + } + return fields +} + +func traceFields(trace *tracev1.TraceContext) []zap.Field { + if trace == nil { + return nil + } + fields := make([]zap.Field, 0, 3) + if ref := strings.TrimSpace(trace.GetTraceRef()); ref != "" { + fields = append(fields, zap.String("trace_ref", ref)) + } + if idem := strings.TrimSpace(trace.GetIdempotencyKey()); idem != "" { + fields = append(fields, zap.String("idempotency_key", idem)) + } + if req := strings.TrimSpace(trace.GetRequestRef()); req != "" { + fields = append(fields, zap.String("request_ref", req)) + } + return fields +} diff --git a/api/fx/oracle/internal/service/oracle/service.go b/api/fx/oracle/internal/service/oracle/service.go index 2adba31..f3f983a 100644 --- a/api/fx/oracle/internal/service/oracle/service.go +++ b/api/fx/oracle/internal/service/oracle/service.go @@ -101,22 +101,27 @@ func (s *Service) getQuoteResponder(ctx context.Context, req *oraclev1.GetQuoteR if req == nil { req = &oraclev1.GetQuoteRequest{} } - s.logger.Debug("Handling GetQuote", zap.String("pair", req.GetPair().GetBase()+"/"+req.GetPair().GetQuote()), zap.Bool("firm", req.GetFirm())) + logger := s.logger.With(quoteRequestFields(req)...) + logger.Debug("Handling GetQuote") if req.GetSide() == fxv1.Side_SIDE_UNSPECIFIED { + logger.Warn("GetQuote invalid: side missing") return gsresponse.InvalidArgument[oraclev1.GetQuoteResponse](s.logger, mservice.FXOracle, errSideRequired) } if req.GetBaseAmount() != nil && req.GetQuoteAmount() != nil { + logger.Warn("GetQuote invalid: both base_amount and quote_amount provided") return gsresponse.InvalidArgument[oraclev1.GetQuoteResponse](s.logger, mservice.FXOracle, errAmountsMutuallyExclusive) } if req.GetBaseAmount() == nil && req.GetQuoteAmount() == nil { + logger.Warn("GetQuote invalid: amount missing") return gsresponse.InvalidArgument[oraclev1.GetQuoteResponse](s.logger, mservice.FXOracle, errAmountRequired) } if err := s.pingStorage(ctx); err != nil { - s.logger.Warn("Storage unavailable during GetQuote", zap.Error(err)) + logger.Warn("Storage unavailable during GetQuote", zap.Error(err)) return gsresponse.Unavailable[oraclev1.GetQuoteResponse](s.logger, mservice.FXOracle, err) } pairMsg := req.GetPair() if pairMsg == nil || strings.TrimSpace(pairMsg.GetBase()) == "" || strings.TrimSpace(pairMsg.GetQuote()) == "" { + logger.Warn("GetQuote invalid: pair missing") return gsresponse.InvalidArgument[oraclev1.GetQuoteResponse](s.logger, mservice.FXOracle, errEmptyRequest) } pairKey := model.CurrencyPair{Base: strings.ToUpper(pairMsg.GetBase()), Quote: strings.ToUpper(pairMsg.GetQuote())} @@ -125,8 +130,10 @@ func (s *Service) getQuoteResponder(ctx context.Context, req *oraclev1.GetQuoteR if err != nil { switch { case errors.Is(err, merrors.ErrNoData): + logger.Warn("pair not supported", zap.String("pair", pairKey.Base+"/"+pairKey.Quote)) return gsresponse.InvalidArgument[oraclev1.GetQuoteResponse](s.logger, mservice.FXOracle, merrors.InvalidArgument("pair_not_supported")) default: + logger.Warn("GetQuote failed to load pair", zap.Error(err)) return gsresponse.Internal[oraclev1.GetQuoteResponse](s.logger, mservice.FXOracle, err) } } @@ -143,8 +150,10 @@ func (s *Service) getQuoteResponder(ctx context.Context, req *oraclev1.GetQuoteR if err != nil { switch { case errors.Is(err, merrors.ErrNoData): + logger.Warn("rate not found", zap.String("pair", pairKey.Base+"/"+pairKey.Quote), zap.String("provider", provider)) return gsresponse.FailedPrecondition[oraclev1.GetQuoteResponse](s.logger, mservice.FXOracle, "rate_not_found", err) default: + logger.Warn("GetQuote failed to load rate", zap.Error(err), zap.String("pair", pairKey.Base+"/"+pairKey.Quote), zap.String("provider", provider)) return gsresponse.Internal[oraclev1.GetQuoteResponse](s.logger, mservice.FXOracle, err) } } @@ -153,27 +162,31 @@ func (s *Service) getQuoteResponder(ctx context.Context, req *oraclev1.GetQuoteR if maxAge := req.GetMaxAgeMs(); maxAge > 0 { age := now.UnixMilli() - rate.AsOfUnixMs if age > int64(maxAge) { - s.logger.Warn("Rate snapshot stale", zap.Int64("age_ms", age), zap.Int32("max_age_ms", req.GetMaxAgeMs()), zap.String("pair", pairKey.Base+"/"+pairKey.Quote), zap.String("provider", provider)) + logger.Warn("Rate snapshot stale", zap.Int64("age_ms", age), zap.Int32("max_age_ms", req.GetMaxAgeMs()), zap.String("pair", pairKey.Base+"/"+pairKey.Quote), zap.String("provider", provider)) return gsresponse.FailedPrecondition[oraclev1.GetQuoteResponse](s.logger, mservice.FXOracle, "stale_rate", merrors.InvalidArgument("rate older than allowed window")) } } comp, err := newQuoteComputation(pair, rate, req.GetSide(), provider) if err != nil { + logger.Warn("GetQuote invalid input", zap.Error(err)) return gsresponse.InvalidArgument[oraclev1.GetQuoteResponse](s.logger, mservice.FXOracle, err) } if req.GetBaseAmount() != nil { if err := comp.withBaseInput(req.GetBaseAmount()); err != nil { + logger.Warn("GetQuote invalid base input", zap.Error(err)) return gsresponse.InvalidArgument[oraclev1.GetQuoteResponse](s.logger, mservice.FXOracle, err) } } else if req.GetQuoteAmount() != nil { if err := comp.withQuoteInput(req.GetQuoteAmount()); err != nil { + logger.Warn("GetQuote invalid quote input", zap.Error(err)) return gsresponse.InvalidArgument[oraclev1.GetQuoteResponse](s.logger, mservice.FXOracle, err) } } if err := comp.compute(); err != nil { + logger.Warn("GetQuote computation failed", zap.Error(err)) return gsresponse.Internal[oraclev1.GetQuoteResponse](s.logger, mservice.FXOracle, err) } @@ -195,12 +208,14 @@ func (s *Service) getQuoteResponder(ctx context.Context, req *oraclev1.GetQuoteR if err := s.storage.Quotes().Issue(ctx, quoteModel); err != nil { switch { case errors.Is(err, merrors.ErrDataConflict): + logger.Warn("GetQuote conflict issuing firm quote", zap.Error(err), zap.String("quote_ref", quoteModel.QuoteRef)) return gsresponse.Conflict[oraclev1.GetQuoteResponse](s.logger, mservice.FXOracle, err) default: + logger.Warn("GetQuote failed to issue firm quote", zap.Error(err), zap.String("quote_ref", quoteModel.QuoteRef)) return gsresponse.Internal[oraclev1.GetQuoteResponse](s.logger, mservice.FXOracle, err) } } - s.logger.Info("Firm quote stored", zap.String("quote_ref", quoteModel.QuoteRef), zap.String("pair", pairKey.Base+"/"+pairKey.Quote), zap.String("provider", quoteModel.Provider), zap.Int64("expires_at_ms", quoteModel.ExpiresAtUnixMs)) + logger.Info("Firm quote stored", zap.String("quote_ref", quoteModel.QuoteRef), zap.String("pair", pairKey.Base+"/"+pairKey.Quote), zap.String("provider", quoteModel.Provider), zap.Int64("expires_at_ms", quoteModel.ExpiresAtUnixMs)) } resp := &oraclev1.GetQuoteResponse{ @@ -214,18 +229,24 @@ func (s *Service) validateQuoteResponder(ctx context.Context, req *oraclev1.Vali if req == nil { req = &oraclev1.ValidateQuoteRequest{} } - s.logger.Debug("Handling ValidateQuote", zap.String("quote_ref", req.GetQuoteRef())) + logger := s.logger.With(requestMetaFields(req.GetMeta())...) + if ref := strings.TrimSpace(req.GetQuoteRef()); ref != "" { + logger = logger.With(zap.String("quote_ref", ref)) + } + logger.Debug("Handling ValidateQuote") if req.GetQuoteRef() == "" { + logger.Warn("ValidateQuote invalid: quote_ref missing") return gsresponse.InvalidArgument[oraclev1.ValidateQuoteResponse](s.logger, mservice.FXOracle, errQuoteRefRequired) } if err := s.pingStorage(ctx); err != nil { - s.logger.Warn("Storage unavailable during ValidateQuote", zap.Error(err)) + logger.Warn("Storage unavailable during ValidateQuote", zap.Error(err)) return gsresponse.Unavailable[oraclev1.ValidateQuoteResponse](s.logger, mservice.FXOracle, err) } quote, err := s.storage.Quotes().GetByRef(ctx, req.GetQuoteRef()) if err != nil { switch { case errors.Is(err, merrors.ErrNoData): + logger.Warn("ValidateQuote: quote not found", zap.String("quote_ref", req.GetQuoteRef())) resp := &oraclev1.ValidateQuoteResponse{ Meta: buildResponseMeta(req.GetMeta()), Quote: nil, @@ -234,6 +255,7 @@ func (s *Service) validateQuoteResponder(ctx context.Context, req *oraclev1.Vali } return gsresponse.Success(resp) default: + logger.Warn("ValidateQuote failed", zap.Error(err)) return gsresponse.Internal[oraclev1.ValidateQuoteResponse](s.logger, mservice.FXOracle, err) } } @@ -255,6 +277,11 @@ func (s *Service) validateQuoteResponder(ctx context.Context, req *oraclev1.Vali Valid: valid, Reason: reason, } + if !valid { + logger.Info("ValidateQuote invalid", zap.String("reason", reason), zap.Bool("firm", quote.Firm)) + } else { + logger.Debug("ValidateQuote valid", zap.Bool("firm", quote.Firm)) + } return gsresponse.Success(resp) } @@ -262,29 +289,43 @@ func (s *Service) consumeQuoteResponder(ctx context.Context, req *oraclev1.Consu if req == nil { req = &oraclev1.ConsumeQuoteRequest{} } - s.logger.Debug("Handling ConsumeQuote", zap.String("quote_ref", req.GetQuoteRef()), zap.String("ledger_txn_ref", req.GetLedgerTxnRef())) + logger := s.logger.With(requestMetaFields(req.GetMeta())...) + if ref := strings.TrimSpace(req.GetQuoteRef()); ref != "" { + logger = logger.With(zap.String("quote_ref", ref)) + } + if ledger := strings.TrimSpace(req.GetLedgerTxnRef()); ledger != "" { + logger = logger.With(zap.String("ledger_txn_ref", ledger)) + } + logger.Debug("Handling ConsumeQuote") if req.GetQuoteRef() == "" { + logger.Warn("ConsumeQuote invalid: quote_ref missing") return gsresponse.InvalidArgument[oraclev1.ConsumeQuoteResponse](s.logger, mservice.FXOracle, errQuoteRefRequired) } if req.GetLedgerTxnRef() == "" { + logger.Warn("ConsumeQuote invalid: ledger_txn_ref missing") return gsresponse.InvalidArgument[oraclev1.ConsumeQuoteResponse](s.logger, mservice.FXOracle, errLedgerTxnRefRequired) } if err := s.pingStorage(ctx); err != nil { - s.logger.Warn("Storage unavailable during ConsumeQuote", zap.Error(err)) + logger.Warn("Storage unavailable during ConsumeQuote", zap.Error(err)) return gsresponse.Unavailable[oraclev1.ConsumeQuoteResponse](s.logger, mservice.FXOracle, err) } _, err := s.storage.Quotes().Consume(ctx, req.GetQuoteRef(), req.GetLedgerTxnRef(), time.Now()) if err != nil { switch { case errors.Is(err, storage.ErrQuoteExpired): + logger.Warn("ConsumeQuote failed: expired") return gsresponse.FailedPrecondition[oraclev1.ConsumeQuoteResponse](s.logger, mservice.FXOracle, "expired", err) case errors.Is(err, storage.ErrQuoteConsumed): + logger.Warn("ConsumeQuote failed: already consumed") return gsresponse.FailedPrecondition[oraclev1.ConsumeQuoteResponse](s.logger, mservice.FXOracle, "consumed", err) case errors.Is(err, storage.ErrQuoteNotFirm): + logger.Warn("ConsumeQuote failed: quote not firm") return gsresponse.FailedPrecondition[oraclev1.ConsumeQuoteResponse](s.logger, mservice.FXOracle, "not_firm", err) case errors.Is(err, merrors.ErrNoData): + logger.Warn("ConsumeQuote failed: quote not found") return gsresponse.NotFound[oraclev1.ConsumeQuoteResponse](s.logger, mservice.FXOracle, err) default: + logger.Warn("ConsumeQuote failed", zap.Error(err)) return gsresponse.Internal[oraclev1.ConsumeQuoteResponse](s.logger, mservice.FXOracle, err) } } @@ -294,7 +335,7 @@ func (s *Service) consumeQuoteResponder(ctx context.Context, req *oraclev1.Consu Consumed: true, Reason: "consumed", } - s.logger.Debug("Quote consumed", zap.String("quote_ref", req.GetQuoteRef()), zap.String("ledger_txn_ref", req.GetLedgerTxnRef())) + logger.Info("Quote consumed") return gsresponse.Success(resp) } @@ -302,13 +343,21 @@ func (s *Service) latestRateResponder(ctx context.Context, req *oraclev1.LatestR if req == nil { req = &oraclev1.LatestRateRequest{} } - s.logger.Debug("Handling LatestRate", zap.String("pair", req.GetPair().GetBase()+"/"+req.GetPair().GetQuote())) + logger := s.logger.With(requestMetaFields(req.GetMeta())...) + if pair := req.GetPair(); pair != nil { + logger = logger.With(zap.String("pair_base", strings.TrimSpace(pair.GetBase())), zap.String("pair_quote", strings.TrimSpace(pair.GetQuote()))) + } + if provider := strings.TrimSpace(req.GetProvider()); provider != "" { + logger = logger.With(zap.String("provider", provider)) + } + logger.Debug("Handling LatestRate") if err := s.pingStorage(ctx); err != nil { - s.logger.Warn("Storage unavailable during LatestRate", zap.Error(err)) + logger.Warn("Storage unavailable during LatestRate", zap.Error(err)) return gsresponse.Unavailable[oraclev1.LatestRateResponse](s.logger, mservice.FXOracle, err) } pairMsg := req.GetPair() if pairMsg == nil || strings.TrimSpace(pairMsg.GetBase()) == "" || strings.TrimSpace(pairMsg.GetQuote()) == "" { + logger.Warn("LatestRate invalid: pair missing") return gsresponse.InvalidArgument[oraclev1.LatestRateResponse](s.logger, mservice.FXOracle, errEmptyRequest) } pair := model.CurrencyPair{Base: strings.ToUpper(pairMsg.GetBase()), Quote: strings.ToUpper(pairMsg.GetQuote())} @@ -317,8 +366,10 @@ func (s *Service) latestRateResponder(ctx context.Context, req *oraclev1.LatestR if err != nil { switch { case errors.Is(err, merrors.ErrNoData): + logger.Warn("LatestRate pair not found") return gsresponse.NotFound[oraclev1.LatestRateResponse](s.logger, mservice.FXOracle, err) default: + logger.Warn("LatestRate failed to load pair", zap.Error(err)) return gsresponse.Internal[oraclev1.LatestRateResponse](s.logger, mservice.FXOracle, err) } } @@ -335,8 +386,10 @@ func (s *Service) latestRateResponder(ctx context.Context, req *oraclev1.LatestR if err != nil { switch { case errors.Is(err, merrors.ErrNoData): + logger.Warn("LatestRate not found", zap.String("provider", provider)) return gsresponse.NotFound[oraclev1.LatestRateResponse](s.logger, mservice.FXOracle, err) default: + logger.Warn("LatestRate failed", zap.Error(err)) return gsresponse.Internal[oraclev1.LatestRateResponse](s.logger, mservice.FXOracle, err) } } @@ -345,6 +398,7 @@ func (s *Service) latestRateResponder(ctx context.Context, req *oraclev1.LatestR Meta: buildResponseMeta(req.GetMeta()), Rate: rateModelToProto(rate), } + logger.Debug("LatestRate succeeded", zap.String("provider", provider), zap.Int64("asof_unix_ms", rate.AsOfUnixMs)) return gsresponse.Success(resp) } @@ -352,13 +406,15 @@ func (s *Service) listPairsResponder(ctx context.Context, req *oraclev1.ListPair if req == nil { req = &oraclev1.ListPairsRequest{} } - s.logger.Debug("Handling ListPairs") + logger := s.logger.With(requestMetaFields(req.GetMeta())...) + logger.Debug("Handling ListPairs") if err := s.pingStorage(ctx); err != nil { - s.logger.Warn("Storage unavailable during ListPairs", zap.Error(err)) + logger.Warn("Storage unavailable during ListPairs", zap.Error(err)) return gsresponse.Unavailable[oraclev1.ListPairsResponse](s.logger, mservice.FXOracle, err) } pairs, err := s.storage.Pairs().ListEnabled(ctx) if err != nil { + logger.Warn("ListPairs failed", zap.Error(err)) return gsresponse.Internal[oraclev1.ListPairsResponse](s.logger, mservice.FXOracle, err) } result := make([]*oraclev1.PairMeta, 0, len(pairs)) @@ -369,7 +425,7 @@ func (s *Service) listPairsResponder(ctx context.Context, req *oraclev1.ListPair Meta: buildResponseMeta(req.GetMeta()), Pairs: result, } - s.logger.Debug("ListPairs returning metadata", zap.Int("pairs", len(resp.GetPairs()))) + logger.Debug("ListPairs returning metadata", zap.Int("pairs", len(resp.GetPairs()))) return gsresponse.Success(resp) }