api/payments/orchestrator/internal/service/orchestrator/handlers_commands.go

@@ -12,6 +12,7 @@ import (
 	"github.com/tech/sendico/pkg/merrors"
 	"github.com/tech/sendico/pkg/mlogger"
 	"github.com/tech/sendico/pkg/mservice"
+	"github.com/tech/sendico/pkg/mutil/mzap"
 	orchestratorv1 "github.com/tech/sendico/pkg/proto/payments/orchestrator/v1"
 	"go.mongodb.org/mongo-driver/bson/primitive"
 	"go.uber.org/zap"
@@ -61,7 +62,13 @@ func (h *quotePaymentCommand) Execute(ctx context.Context, req *orchestratorv1.Q
 		if err := quotesStore.Create(ctx, record); err != nil {
 			return gsresponse.Auto[orchestratorv1.QuotePaymentResponse](h.logger, mservice.PaymentOrchestrator, err)
 		}
-		h.logger.Info("Stored payment quote", zap.String("quote_ref", quoteRef), zap.String("org_ref", orgID.Hex()))
+		h.logger.Info(
+			"Stored payment quote",
+			zap.String("quote_ref", quoteRef),
+			mzap.ObjRef("org_ref", orgID),
+			zap.String("idempotency_key", strings.TrimSpace(req.GetIdempotencyKey())),
+			zap.String("kind", intent.GetKind().String()),
+		)
 	}
 
 	return gsresponse.Success(&orchestratorv1.QuotePaymentResponse{Quote: quote})
@@ -79,7 +86,7 @@ func (h *quotePaymentsCommand) Execute(ctx context.Context, req *orchestratorv1.
 	if req == nil {
 		return gsresponse.InvalidArgument[orchestratorv1.QuotePaymentsResponse](h.logger, mservice.PaymentOrchestrator, merrors.InvalidArgument("nil request"))
 	}
-	orgRef, orgID, err := validateMetaAndOrgRef(req.GetMeta())
+	orgID, orgRef, err := validateMetaAndOrgRef(req.GetMeta())
 	if err != nil {
 		return gsresponse.InvalidArgument[orchestratorv1.QuotePaymentsResponse](h.logger, mservice.PaymentOrchestrator, err)
 	}
@@ -101,7 +108,7 @@ func (h *quotePaymentsCommand) Execute(ctx context.Context, req *orchestratorv1.
 			Intent:         intent,
 			PreviewOnly:    req.GetPreviewOnly(),
 		}
-		quote, expiresAt, err := h.engine.BuildPaymentQuote(ctx, orgRef, quoteReq)
+		quote, expiresAt, err := h.engine.BuildPaymentQuote(ctx, orgID, quoteReq)
 		if err != nil {
 			return gsresponse.Auto[orchestratorv1.QuotePaymentsResponse](h.logger, mservice.PaymentOrchestrator, err)
 		}
@@ -132,11 +139,17 @@ func (h *quotePaymentsCommand) Execute(ctx context.Context, req *orchestratorv1.
 			ExpiresAt: expiresAt,
 		}
 		record.SetID(primitive.NewObjectID())
-		record.SetOrganizationRef(orgID)
+		record.SetOrganizationRef(orgRef)
 		if err := quotesStore.Create(ctx, record); err != nil {
 			return gsresponse.Auto[orchestratorv1.QuotePaymentsResponse](h.logger, mservice.PaymentOrchestrator, err)
 		}
-		h.logger.Info("stored payment quotes", zap.String("quote_ref", quoteRef), zap.String("org_ref", orgID.Hex()))
+		h.logger.Info(
+			"stored payment quotes",
+			zap.String("quote_ref", quoteRef),
+			mzap.ObjRef("org_ref", orgRef),
+			zap.String("idempotency_key", baseKey),
+			zap.Int("quote_count", len(quotes)),
+		)
 	}
 
 	return gsresponse.Success(&orchestratorv1.QuotePaymentsResponse{
@@ -158,7 +171,7 @@ func (h *initiatePaymentsCommand) Execute(ctx context.Context, req *orchestrator
 	if req == nil {
 		return gsresponse.InvalidArgument[orchestratorv1.InitiatePaymentsResponse](h.logger, mservice.PaymentOrchestrator, merrors.InvalidArgument("nil request"))
 	}
-	_, orgID, err := validateMetaAndOrgRef(req.GetMeta())
+	_, orgRef, err := validateMetaAndOrgRef(req.GetMeta())
 	if err != nil {
 		return gsresponse.InvalidArgument[orchestratorv1.InitiatePaymentsResponse](h.logger, mservice.PaymentOrchestrator, err)
 	}
@@ -175,7 +188,7 @@ func (h *initiatePaymentsCommand) Execute(ctx context.Context, req *orchestrator
 	if err != nil {
 		return gsresponse.Unavailable[orchestratorv1.InitiatePaymentsResponse](h.logger, mservice.PaymentOrchestrator, err)
 	}
-	record, err := quotesStore.GetByRef(ctx, orgID, quoteRef)
+	record, err := quotesStore.GetByRef(ctx, orgRef, quoteRef)
 	if err != nil {
 		if errors.Is(err, storage.ErrQuoteNotFound) {
 			return gsresponse.FailedPrecondition[orchestratorv1.InitiatePaymentsResponse](h.logger, mservice.PaymentOrchestrator, "quote_not_found", merrors.InvalidArgument("quote_ref not found or expired"))
@@ -213,14 +226,14 @@ func (h *initiatePaymentsCommand) Execute(ctx context.Context, req *orchestrator
 		quoteProto.QuoteRef = quoteRef
 
 		perKey := perIntentIdempotencyKey(idempotencyKey, i, len(intents))
-		if existing, err := getPaymentByIdempotencyKey(ctx, store, orgID, perKey); err == nil && existing != nil {
+		if existing, err := getPaymentByIdempotencyKey(ctx, store, orgRef, perKey); err == nil && existing != nil {
 			payments = append(payments, toProtoPayment(existing))
 			continue
 		} else if err != nil && !errors.Is(err, storage.ErrPaymentNotFound) {
 			return gsresponse.Auto[orchestratorv1.InitiatePaymentsResponse](h.logger, mservice.PaymentOrchestrator, err)
 		}
 
-		entity := newPayment(orgID, intentProto, perKey, req.GetMetadata(), quoteProto)
+		entity := newPayment(orgRef, intentProto, perKey, req.GetMetadata(), quoteProto)
 		if err = store.Create(ctx, entity); err != nil {
 			if errors.Is(err, storage.ErrDuplicatePayment) {
 				return gsresponse.Auto[orchestratorv1.InitiatePaymentsResponse](h.logger, mservice.PaymentOrchestrator, merrors.DataConflict("payment already exists"))
@@ -235,6 +248,13 @@ func (h *initiatePaymentsCommand) Execute(ctx context.Context, req *orchestrator
 		payments = append(payments, toProtoPayment(entity))
 	}
 
+	h.logger.Info(
+		"Payments initiated",
+		mzap.ObjRef("org_ref", orgRef),
+		zap.String("quote_ref", quoteRef),
+		zap.String("idempotency_key", idempotencyKey),
+		zap.Int("payment_count", len(payments)),
+	)
 	return gsresponse.Success(&orchestratorv1.InitiatePaymentsResponse{Payments: payments})
 }
 
@@ -273,6 +293,13 @@ func (h *initiatePaymentCommand) Execute(ctx context.Context, req *orchestratorv
 	if err != nil {
 		return gsresponse.InvalidArgument[orchestratorv1.InitiatePaymentResponse](h.logger, mservice.PaymentOrchestrator, err)
 	}
+	h.logger.Debug(
+		"Initiate payment request accepted",
+		zap.String("org_ref", orgID.Hex()),
+		zap.String("idempotency_key", idempotencyKey),
+		zap.String("quote_ref", quoteRef),
+		zap.Bool("has_intent", hasIntent),
+	)
 
 	store, err := ensurePaymentsStore(h.engine.Repository())
 	if err != nil {
@@ -280,7 +307,13 @@ func (h *initiatePaymentCommand) Execute(ctx context.Context, req *orchestratorv
 	}
 
 	if existing, err := getPaymentByIdempotencyKey(ctx, store, orgID, idempotencyKey); err == nil && existing != nil {
-		h.logger.Debug("idempotent payment request reused", zap.String("payment_ref", existing.PaymentRef), zap.String("org_ref", orgID.Hex()))
+		h.logger.Debug(
+			"idempotent payment request reused",
+			zap.String("payment_ref", existing.PaymentRef),
+			zap.String("org_ref", orgID.Hex()),
+			zap.String("idempotency_key", idempotencyKey),
+			zap.String("quote_ref", quoteRef),
+		)
 		return gsresponse.Success(&orchestratorv1.InitiatePaymentResponse{Payment: toProtoPayment(existing)})
 	} else if err != nil && !errors.Is(err, storage.ErrPaymentNotFound) {
 		return gsresponse.Auto[orchestratorv1.InitiatePaymentResponse](h.logger, mservice.PaymentOrchestrator, err)
@@ -315,6 +348,12 @@ func (h *initiatePaymentCommand) Execute(ctx context.Context, req *orchestratorv
 	if err := requireNonNilIntent(resolvedIntent); err != nil {
 		return gsresponse.InvalidArgument[orchestratorv1.InitiatePaymentResponse](h.logger, mservice.PaymentOrchestrator, err)
 	}
+	h.logger.Debug(
+		"Payment quote resolved",
+		zap.String("org_ref", orgID.Hex()),
+		zap.String("quote_ref", quoteRef),
+		zap.Bool("quote_ref_used", quoteRef != ""),
+	)
 
 	entity := newPayment(orgID, resolvedIntent, idempotencyKey, req.GetMetadata(), quoteSnapshot)
 
@@ -329,7 +368,14 @@ func (h *initiatePaymentCommand) Execute(ctx context.Context, req *orchestratorv
 		return gsresponse.Auto[orchestratorv1.InitiatePaymentResponse](h.logger, mservice.PaymentOrchestrator, err)
 	}
 
-	h.logger.Info("Payment initiated", zap.String("payment_ref", entity.PaymentRef), zap.String("org_ref", orgID.Hex()), zap.String("kind", resolvedIntent.GetKind().String()))
+	h.logger.Info(
+		"Payment initiated",
+		zap.String("payment_ref", entity.PaymentRef),
+		zap.String("org_ref", orgID.Hex()),
+		zap.String("kind", resolvedIntent.GetKind().String()),
+		zap.String("quote_ref", quoteSnapshot.GetQuoteRef()),
+		zap.String("idempotency_key", idempotencyKey),
+	)
 	return gsresponse.Success(&orchestratorv1.InitiatePaymentResponse{
 		Payment: toProtoPayment(entity),
 	})