improved logging in callbacks

This commit is contained in:
Stephan D
2026-03-03 01:07:35 +01:00
parent b10ec79fe0
commit bae4cd6e35
45 changed files with 226 additions and 146 deletions

View File

@@ -73,9 +73,10 @@ func validateQuoteIdempotency(previewOnly bool, idempotencyKey string) error {
}
type InitiatePayment struct {
PaymentBase `json:",inline"`
Intent *PaymentIntent `json:"intent,omitempty"`
QuoteRef string `json:"quoteRef,omitempty"`
PaymentBase `json:",inline"`
Intent *PaymentIntent `json:"intent,omitempty"`
QuoteRef string `json:"quoteRef,omitempty"`
ClientPaymentRef string `json:"clientPaymentRef,omitempty"`
}
func (r InitiatePayment) Validate() error {
@@ -106,8 +107,9 @@ func (r InitiatePayment) Validate() error {
}
type InitiatePayments struct {
PaymentBase `json:",inline"`
QuoteRef string `json:"quoteRef,omitempty"`
PaymentBase `json:",inline"`
QuoteRef string `json:"quoteRef,omitempty"`
ClientPaymentRef string `json:"clientPaymentRef,omitempty"`
}
func (r *InitiatePayments) Validate() error {

View File

@@ -120,11 +120,11 @@ func (a *AccountAPI) resetPassword(r *http.Request) http.HandlerFunc {
var user model.Account
err = a.db.Get(ctx, accountRef, &user)
if errors.Is(err, merrors.ErrNoData) {
a.logger.Info("User not found for password reset", zap.String("account_ref", accountRef.Hex()))
a.logger.Info("User not found for password reset", mzap.ObjRef("account_ref", accountRef))
return response.NotFound(a.logger, a.Name(), "User not found")
}
if err != nil {
a.logger.Warn("Failed to get user for password reset", zap.Error(err), zap.String("account_ref", accountRef.Hex()))
a.logger.Warn("Failed to get user for password reset", zap.Error(err), mzap.ObjRef("account_ref", accountRef))
return response.Auto(a.logger, a.Name(), err)
}
@@ -140,7 +140,7 @@ func (a *AccountAPI) resetPassword(r *http.Request) http.HandlerFunc {
}
if t.AccountRef != accountRef {
a.logger.Warn("Token account reference does not match request account reference", zap.String("token_account_ref", t.AccountRef.Hex()), zap.String("request_account_ref", accountRef.Hex()))
a.logger.Warn("Token account reference does not match request account reference", mzap.ObjRef("token_account_ref", t.AccountRef), mzap.ObjRef("request_account_ref", accountRef))
return response.DataConflict(a.logger, a.Name(), "Token does not match account")
}

View File

@@ -13,6 +13,7 @@ import (
"github.com/prometheus/client_golang/prometheus/promauto"
"github.com/tech/sendico/pkg/merrors"
"github.com/tech/sendico/pkg/mlogger"
"github.com/tech/sendico/pkg/mutil/mzap"
"github.com/tech/sendico/pkg/vault/kv"
"go.mongodb.org/mongo-driver/v2/bson"
"go.uber.org/zap"
@@ -152,7 +153,7 @@ func (m *vaultSigningSecretManager) Provision(
}
secretRef := "vault:" + secretPath + "#" + m.field
m.logger.Info("Callback signing secret stored", zap.String("secret_ref", secretRef), zap.String("callback_ref", callbackRef.Hex()))
m.logger.Info("Callback signing secret stored", zap.String("secret_ref", secretRef), mzap.ObjRef("callback_ref", callbackRef))
return secretRef, secret, nil
}

View File

@@ -11,6 +11,7 @@ import (
"github.com/tech/sendico/pkg/model"
"github.com/tech/sendico/pkg/model/account_role"
"github.com/tech/sendico/pkg/mservice"
"github.com/tech/sendico/pkg/mutil/mzap"
describablev1 "github.com/tech/sendico/pkg/proto/common/describable/v1"
ledgerv1 "github.com/tech/sendico/pkg/proto/ledger/v1"
"github.com/tech/sendico/server/interface/api/srequest"
@@ -88,7 +89,7 @@ func (a *LedgerAPI) createAccount(r *http.Request, account *model.Account, token
Describable: describable,
})
if err != nil {
a.logger.Warn("Failed to create ledger account", zap.Error(err), zap.String("organization_ref", orgRef.Hex()))
a.logger.Warn("Failed to create ledger account", zap.Error(err), mzap.ObjRef("organization_ref", orgRef))
return response.Auto(a.logger, mservice.Ledger, err)
}

View File

@@ -47,7 +47,7 @@ func (a *LedgerAPI) listAccounts(r *http.Request, account *model.Account, token
resp, err := a.client.ListAccounts(ctx, req)
if err != nil {
a.logger.Warn("Failed to list ledger accounts", zap.Error(err), zap.String("organization_ref", orgRef.Hex()))
a.logger.Warn("Failed to list ledger accounts", zap.Error(err), mzap.ObjRef("organization_ref", orgRef))
return response.Auto(a.logger, mservice.Ledger, err)
}

View File

@@ -89,7 +89,7 @@ func (a *PaymentAPI) initiatePayment(r *http.Request, account *model.Account, to
req := &orchestrationv2.ExecutePaymentRequest{
Meta: requestMeta(orgRef.Hex(), payload.IdempotencyKey),
QuotationRef: quotationRef,
ClientPaymentRef: metadataValue(payload.Metadata, "client_payment_ref"),
ClientPaymentRef: strings.TrimSpace(payload.ClientPaymentRef),
}
resp, err := a.execution.ExecutePayment(ctx, req)
@@ -110,6 +110,7 @@ func decodeInitiatePayload(r *http.Request) (*srequest.InitiatePayment, error) {
}
payload.IdempotencyKey = strings.TrimSpace(payload.IdempotencyKey)
payload.QuoteRef = strings.TrimSpace(payload.QuoteRef)
payload.ClientPaymentRef = strings.TrimSpace(payload.ClientPaymentRef)
if err := payload.Validate(); err != nil {
return nil, err

View File

@@ -14,12 +14,12 @@ import (
"go.mongodb.org/mongo-driver/v2/bson"
)
func TestInitiateByQuote_DoesNotUseIntentRef(t *testing.T) {
func TestInitiateByQuote_ForwardsClientPaymentRef(t *testing.T) {
orgRef := bson.NewObjectID()
exec := &fakeExecutionClientForBatch{}
api := newBatchAPI(exec)
body := `{"idempotencyKey":"idem-by-quote","quoteRef":"quote-1","metadata":{"client_payment_ref":"client-ref-1"}}`
body := `{"idempotencyKey":"idem-by-quote","quoteRef":"quote-1","clientPaymentRef":"client-ref-1"}`
rr := invokeInitiateByQuote(t, api, orgRef, body)
if got, want := rr.Code, http.StatusOK; got != want {
t.Fatalf("status mismatch: got=%d want=%d body=%s", got, want, rr.Body.String())
@@ -32,6 +32,24 @@ func TestInitiateByQuote_DoesNotUseIntentRef(t *testing.T) {
}
}
func TestInitiateByQuote_DoesNotForwardLegacyClientPaymentRefFromMetadata(t *testing.T) {
orgRef := bson.NewObjectID()
exec := &fakeExecutionClientForBatch{}
api := newBatchAPI(exec)
body := `{"idempotencyKey":"idem-by-quote","quoteRef":"quote-1","metadata":{"client_payment_ref":"legacy-client-ref"}}`
rr := invokeInitiateByQuote(t, api, orgRef, body)
if got, want := rr.Code, http.StatusOK; got != want {
t.Fatalf("status mismatch: got=%d want=%d body=%s", got, want, rr.Body.String())
}
if got, want := len(exec.executeReqs), 1; got != want {
t.Fatalf("execute calls mismatch: got=%d want=%d", got, want)
}
if got := exec.executeReqs[0].GetClientPaymentRef(); got != "" {
t.Fatalf("expected empty client_payment_ref, got=%q", got)
}
}
func TestInitiateByQuote_RejectsMetadataIntentRef(t *testing.T) {
orgRef := bson.NewObjectID()
exec := &fakeExecutionClientForBatch{}

View File

@@ -8,6 +8,7 @@ import (
"github.com/tech/sendico/pkg/api/http/response"
"github.com/tech/sendico/pkg/merrors"
"github.com/tech/sendico/pkg/model"
"github.com/tech/sendico/pkg/mutil/mzap"
orchestrationv2 "github.com/tech/sendico/pkg/proto/payments/orchestration/v2"
"github.com/tech/sendico/server/interface/api/srequest"
"github.com/tech/sendico/server/interface/api/sresponse"
@@ -39,7 +40,7 @@ func (a *PaymentAPI) initiatePaymentsByQuote(r *http.Request, account *model.Acc
return response.BadPayload(a.logger, a.Name(), err)
}
clientPaymentRef := metadataValue(payload.Metadata, "client_payment_ref")
clientPaymentRef := strings.TrimSpace(payload.ClientPaymentRef)
idempotencyKey := strings.TrimSpace(payload.IdempotencyKey)
quotationRef := strings.TrimSpace(payload.QuoteRef)
@@ -50,7 +51,7 @@ func (a *PaymentAPI) initiatePaymentsByQuote(r *http.Request, account *model.Acc
}
resp, err := a.execution.ExecuteBatchPayment(ctx, req)
if err != nil {
a.logger.Warn("Failed to initiate batch payments", zap.Error(err), zap.String("organization_ref", orgRef.Hex()))
a.logger.Warn("Failed to initiate batch payments", zap.Error(err), mzap.ObjRef("organization_ref", orgRef))
return grpcErrorResponse(a.logger, a.Name(), err)
}
@@ -72,6 +73,7 @@ func decodeInitiatePaymentsPayload(r *http.Request) (*srequest.InitiatePayments,
}
payload.IdempotencyKey = strings.TrimSpace(payload.IdempotencyKey)
payload.QuoteRef = strings.TrimSpace(payload.QuoteRef)
payload.ClientPaymentRef = strings.TrimSpace(payload.ClientPaymentRef)
if err := payload.Validate(); err != nil {
return nil, err

View File

@@ -50,7 +50,7 @@ func TestInitiatePaymentsByQuote_ForwardsClientPaymentRef(t *testing.T) {
exec := &fakeExecutionClientForBatch{}
api := newBatchAPI(exec)
body := `{"idempotencyKey":"idem-batch","quoteRef":"quote-1","metadata":{"client_payment_ref":"client-ref-1"}}`
body := `{"idempotencyKey":"idem-batch","quoteRef":"quote-1","clientPaymentRef":"client-ref-1"}`
rr := invokeInitiatePaymentsByQuote(t, api, orgRef, body)
if got, want := rr.Code, http.StatusOK; got != want {
t.Fatalf("status mismatch: got=%d want=%d body=%s", got, want, rr.Body.String())
@@ -67,6 +67,25 @@ func TestInitiatePaymentsByQuote_ForwardsClientPaymentRef(t *testing.T) {
}
}
func TestInitiatePaymentsByQuote_DoesNotForwardLegacyClientPaymentRefFromMetadata(t *testing.T) {
orgRef := bson.NewObjectID()
exec := &fakeExecutionClientForBatch{}
api := newBatchAPI(exec)
body := `{"idempotencyKey":"idem-batch","quoteRef":"quote-1","metadata":{"client_payment_ref":"legacy-client-ref"}}`
rr := invokeInitiatePaymentsByQuote(t, api, orgRef, body)
if got, want := rr.Code, http.StatusOK; got != want {
t.Fatalf("status mismatch: got=%d want=%d body=%s", got, want, rr.Body.String())
}
if got, want := len(exec.executeBatchReqs), 1; got != want {
t.Fatalf("execute batch calls mismatch: got=%d want=%d", got, want)
}
if got := exec.executeBatchReqs[0].GetClientPaymentRef(); got != "" {
t.Fatalf("expected empty client_payment_ref, got=%q", got)
}
}
func TestInitiatePaymentsByQuote_RejectsDeprecatedIntentRefField(t *testing.T) {
orgRef := bson.NewObjectID()
exec := &fakeExecutionClientForBatch{}

View File

@@ -8,6 +8,7 @@ import (
"github.com/tech/sendico/pkg/api/http/response"
"github.com/tech/sendico/pkg/merrors"
"github.com/tech/sendico/pkg/model"
"github.com/tech/sendico/pkg/mutil/mzap"
quotationv2 "github.com/tech/sendico/pkg/proto/payments/quotation/v2"
"github.com/tech/sendico/server/interface/api/srequest"
"github.com/tech/sendico/server/interface/api/sresponse"
@@ -61,7 +62,7 @@ func (a *PaymentAPI) quotePayment(r *http.Request, account *model.Account, token
resp, err := a.quotation.QuotePayment(ctx, req)
if err != nil {
a.logger.Warn("Failed to quote payment", zap.Error(err), zap.String("organization_ref", orgRef.Hex()))
a.logger.Warn("Failed to quote payment", zap.Error(err), mzap.ObjRef("organization_ref", orgRef))
return grpcErrorResponse(a.logger, a.Name(), err)
}
@@ -117,7 +118,7 @@ func (a *PaymentAPI) quotePayments(r *http.Request, account *model.Account, toke
resp, err := a.quotation.QuotePayments(ctx, req)
if err != nil {
a.logger.Warn("Failed to quote payments", zap.Error(err), zap.String("organization_ref", orgRef.Hex()))
a.logger.Warn("Failed to quote payments", zap.Error(err), mzap.ObjRef("organization_ref", orgRef))
return grpcErrorResponse(a.logger, a.Name(), err)
}

View File

@@ -12,6 +12,7 @@ import (
"github.com/tech/sendico/pkg/merrors"
"github.com/tech/sendico/pkg/model"
"github.com/tech/sendico/pkg/mservice"
"github.com/tech/sendico/pkg/mutil/mzap"
connectorv1 "github.com/tech/sendico/pkg/proto/connector/v1"
"github.com/tech/sendico/server/interface/api/sresponse"
mutil "github.com/tech/sendico/server/internal/mutil/param"
@@ -65,24 +66,24 @@ func (a *WalletAPI) getWalletBalance(r *http.Request, account *model.Account, to
return response.Auto(a.logger, a.Name(), merrors.NoData("no crypto gateways available"))
}
a.logger.Debug("Resolved CRYPTO gateways for wallet balance lookup",
zap.String("organization_ref", orgRef.Hex()),
mzap.ObjRef("organization_ref", orgRef),
zap.String("wallet_ref", walletRef),
zap.Int("gateway_count", len(cryptoGateways)))
route, routeErr := a.walletRoute(ctx, orgRef.Hex(), walletRef)
if routeErr != nil {
a.logger.Warn("Failed to resolve wallet route", zap.Error(routeErr), zap.String("wallet_ref", walletRef), zap.String("organization_ref", orgRef.Hex()))
a.logger.Warn("Failed to resolve wallet route", zap.Error(routeErr), zap.String("wallet_ref", walletRef), mzap.ObjRef("organization_ref", orgRef))
}
if route != nil {
a.logger.Debug("Resolved stored wallet route",
zap.String("organization_ref", orgRef.Hex()),
mzap.ObjRef("organization_ref", orgRef),
zap.String("wallet_ref", walletRef),
zap.String("route_network", route.Network),
zap.String("route_gateway_id", route.GatewayID))
preferred := findGatewayForRoute(cryptoGateways, route)
if preferred != nil {
a.logger.Debug("Using preferred gateway from stored wallet route",
zap.String("organization_ref", orgRef.Hex()),
mzap.ObjRef("organization_ref", orgRef),
zap.String("wallet_ref", walletRef),
zap.String("gateway_id", preferred.ID),
zap.String("network", preferred.Network),
@@ -91,7 +92,7 @@ func (a *WalletAPI) getWalletBalance(r *http.Request, account *model.Account, to
if preferredErr == nil && bal != nil {
a.rememberWalletRoute(ctx, orgRef.Hex(), walletRef, preferred.Network, preferred.ID)
a.logger.Debug("Wallet balance resolved via preferred gateway",
zap.String("organization_ref", orgRef.Hex()),
mzap.ObjRef("organization_ref", orgRef),
zap.String("wallet_ref", walletRef),
zap.String("gateway_id", preferred.ID),
zap.String("network", preferred.Network))
@@ -124,20 +125,20 @@ func (a *WalletAPI) getWalletBalance(r *http.Request, account *model.Account, to
}
} else {
a.logger.Warn("Stored wallet route did not match any healthy discovery gateway",
zap.String("organization_ref", orgRef.Hex()),
mzap.ObjRef("organization_ref", orgRef),
zap.String("wallet_ref", walletRef),
zap.String("route_network", route.Network),
zap.String("route_gateway_id", route.GatewayID))
}
} else {
a.logger.Debug("Stored wallet route not found; using gateway fallback",
zap.String("organization_ref", orgRef.Hex()),
mzap.ObjRef("organization_ref", orgRef),
zap.String("wallet_ref", walletRef))
}
// Fall back to querying remaining gateways in parallel.
a.logger.Debug("Starting fallback wallet balance fan-out",
zap.String("organization_ref", orgRef.Hex()),
mzap.ObjRef("organization_ref", orgRef),
zap.String("wallet_ref", walletRef),
zap.Int("gateway_count", len(cryptoGateways)))
bal, err := a.queryBalanceFromGateways(ctx, cryptoGateways, orgRef.Hex(), walletRef)

View File

@@ -81,7 +81,7 @@ func (a *WalletAPI) create(r *http.Request, account *model.Account, token *sresp
return response.Auto(a.logger, a.Name(), merrors.InvalidArgument("no gateway available for network: "+networkName))
}
a.logger.Debug("Selected gateway for wallet creation",
zap.String("organization_ref", orgRef.Hex()),
mzap.ObjRef("organization_ref", orgRef),
zap.String("network", networkName),
zap.String("gateway_id", gateway.ID),
zap.String("gateway_network", gateway.Network),
@@ -134,7 +134,7 @@ func (a *WalletAPI) create(r *http.Request, account *model.Account, token *sresp
a.rememberWalletRoute(ctx, orgRef.Hex(), walletRef, networkName, gateway.ID)
a.rememberWalletRoute(ctx, orgRef.Hex(), walletRef, gateway.Network, gateway.ID)
a.logger.Debug("Persisted wallet route after wallet creation",
zap.String("organization_ref", orgRef.Hex()),
mzap.ObjRef("organization_ref", orgRef),
zap.String("wallet_ref", walletRef),
zap.String("network", networkName),
zap.String("gateway_id", gateway.ID))

View File

@@ -59,7 +59,7 @@ func (a *WalletAPI) listWallets(r *http.Request, account *model.Account, token *
return sresponse.Wallets(a.logger, nil, token)
}
a.logger.Debug("Resolved CRYPTO gateways for wallet list",
zap.String("organization_ref", orgRef.Hex()),
mzap.ObjRef("organization_ref", orgRef),
zap.Int("gateway_count", len(cryptoGateways)))
// Build request
@@ -80,7 +80,7 @@ func (a *WalletAPI) listWallets(r *http.Request, account *model.Account, token *
allAccounts := a.queryAllGateways(ctx, cryptoGateways, req)
dedupedAccounts := dedupeAccountsByWalletRef(allAccounts)
a.logger.Debug("Wallet list fan-out completed",
zap.String("organization_ref", orgRef.Hex()),
mzap.ObjRef("organization_ref", orgRef),
zap.Int("accounts_raw", len(allAccounts)),
zap.Int("accounts_deduped", len(dedupedAccounts)),
zap.Int("gateway_count", len(cryptoGateways)))