Merge pull request 'fx/oracle logging' (#92) from logging-90 into main

Reviewed-on: #92

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
+}

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)
 }