package services import ( "context" "crypto/rand" "encoding/base64" "encoding/json" "fmt" "io" "net/http" "strconv" "strings" "time" "payment/internal/config" "payment/internal/models" "payment/internal/utils" "github.com/go-redis/redis/v8" "github.com/google/uuid" "github.com/sirupsen/logrus" "gorm.io/gorm" ) // PaymentService handles payment operations type PaymentService struct { db *gorm.DB redis *redis.Client config *config.Config } // NewPaymentService creates a new payment service func NewPaymentService(db *gorm.DB, redis *redis.Client, config *config.Config) *PaymentService { return &PaymentService{ db: db, redis: redis, config: config, } } // InitiatePaymentRequest represents the request to initiate a payment type InitiatePaymentRequest struct { ClientID uuid.UUID `json:"client_id" binding:"required"` PhoneNumber string `json:"phone_number" binding:"required"` PackageID uuid.UUID `json:"package_id" binding:"required"` Metadata map[string]interface{} `json:"metadata"` } // PublicPaymentRequest represents the public API request to initiate payment type PublicPaymentRequest struct { ClientID uuid.UUID `json:"client_id" binding:"required"` PackageID uuid.UUID `json:"package_id" binding:"required"` Description string `json:"description" binding:"required"` } // PaymentResponse represents the response from payment initiation type PaymentResponse struct { TransactionID uuid.UUID `json:"transaction_id"` CheckoutID string `json:"checkout_id"` Message string `json:"message"` Status string `json:"status"` } // PaymentStatusResponse represents payment status response type PaymentStatusResponse struct { TransactionID uuid.UUID `json:"transaction_id"` CheckoutID string `json:"checkout_id"` Status string `json:"status"` Amount float64 `json:"amount"` Reference string `json:"reference"` PhoneNumber string `json:"phone_number"` } // InitiatePaymentPublic initiates a payment using public API (simplified) func (s *PaymentService) InitiatePaymentPublic(ctx context.Context, clientID uuid.UUID, packageID uuid.UUID, phoneNumber string, description string) (*PaymentResponse, error) { logrus.WithFields(logrus.Fields{ "client_id": clientID, "package_id": packageID, "phone_number": phoneNumber, "description": description, }).Info("Initiating public payment") // Validate client exists and is active var client models.Client if err := s.db.Where("id = ? AND is_active = true", clientID).First(&client).Error; err != nil { logrus.WithFields(logrus.Fields{ "client_id": clientID, "error": err.Error(), }).Error("Client not found or inactive") return nil, fmt.Errorf("client not found or inactive: %w", err) } // Format and validate phone number formattedPhone := utils.FormatPhoneNumber(phoneNumber) if formattedPhone == "" { logrus.WithFields(logrus.Fields{ "client_id": clientID, "phone_number": phoneNumber, }).Error("Invalid phone number format") return nil, fmt.Errorf("invalid phone number format. Expected format: +254xxxxxxxxx") } logrus.WithFields(logrus.Fields{ "client_id": clientID, "original_phone": phoneNumber, "formatted_phone": formattedPhone, }).Debug("Phone number formatted successfully") // Get client credentials credentials, err := s.getClientCredentials(ctx, clientID) if err != nil { logrus.WithFields(logrus.Fields{ "client_id": clientID, "error": err.Error(), }).Error("Failed to get client credentials") return nil, fmt.Errorf("failed to get client credentials: %w", err) } // Get internet package details var packageInfo models.InternetPackage if err := s.db.Where("id = ? AND client_id = ? AND is_active = true", packageID, clientID).First(&packageInfo).Error; err != nil { logrus.WithFields(logrus.Fields{ "client_id": clientID, "package_id": packageID, "error": err.Error(), }).Error("Package not found or inactive") return nil, fmt.Errorf("package not found or inactive: %w", err) } logrus.WithFields(logrus.Fields{ "package_id": packageID, "package_name": packageInfo.Name, "amount": packageInfo.Amount, "currency": packageInfo.Currency, }).Debug("Package details retrieved") // Generate unique reference reference := s.generateReference(clientID, packageInfo.Name) // Create transaction record transaction := &models.Transaction{ ID: uuid.New(), ClientID: clientID, PackageID: &packageID, Amount: packageInfo.Amount, Currency: packageInfo.Currency, PaymentMethod: "mobile_money", PaymentStatus: "pending", PhoneNumber: formattedPhone, Reference: reference, Description: description, Provider: "mpesa", } // Use transaction ID as temporary checkout ID checkoutID := transaction.ID.String() transaction.CheckoutID = checkoutID // Store metadata as JSON packageMetadata := map[string]interface{}{ "package_id": packageInfo.ID, "package_name": packageInfo.Name, "speed": packageInfo.Speed, "duration": packageInfo.Duration, } metadataJSON, _ := json.Marshal(packageMetadata) metadataStr := string(metadataJSON) transaction.Metadata = &metadataStr if err := s.db.Create(transaction).Error; err != nil { logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "client_id": clientID, "error": err.Error(), }).Error("Failed to create transaction") return nil, fmt.Errorf("failed to create transaction: %w", err) } logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "reference": reference, "amount": transaction.Amount, }).Info("Transaction created, initiating STK push") // Initiate STK Push stkResponse, err := s.initiateSTKPush(ctx, credentials, formattedPhone, packageInfo.Amount, checkoutID, description) if err != nil { logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "error": err.Error(), }).Error("STK push initiation failed, updating transaction status to failed") // Update transaction status to failed s.db.Model(transaction).Update("payment_status", "failed") return nil, fmt.Errorf("failed to initiate STK push: %w", err) } // Update transaction with STK response providerResponseJSON, _ := json.Marshal(stkResponse) providerResponseStr := string(providerResponseJSON) safaricomCheckoutID, _ := stkResponse["CheckoutRequestID"].(string) updates := map[string]interface{}{ "provider_response": &providerResponseStr, } if safaricomCheckoutID != "" { updates["checkout_id"] = safaricomCheckoutID checkoutID = safaricomCheckoutID logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "temp_checkout_id": transaction.CheckoutID, "safaricom_checkout_id": safaricomCheckoutID, }).Info("Updated checkout ID with Safaricom CheckoutRequestID") } s.db.Model(transaction).Updates(updates) logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "status": "pending", }).Info("Payment initiated successfully") return &PaymentResponse{ TransactionID: transaction.ID, CheckoutID: checkoutID, Message: "Payment initiated successfully", Status: "pending", }, nil } // InitiatePayment initiates a payment using M-Pesa STK Push func (s *PaymentService) InitiatePayment(ctx context.Context, req *InitiatePaymentRequest) (*PaymentResponse, error) { // Get client credentials credentials, err := s.getClientCredentials(ctx, req.ClientID) if err != nil { return nil, fmt.Errorf("failed to get client credentials: %w", err) } // Get internet package details var packageInfo models.InternetPackage if err := s.db.Where("id = ? AND client_id = ? AND is_active = true", req.PackageID, req.ClientID).First(&packageInfo).Error; err != nil { return nil, fmt.Errorf("package not found or inactive: %w", err) } // Format phone number phoneNumber := utils.FormatPhoneNumber(req.PhoneNumber) if phoneNumber == "" { return nil, fmt.Errorf("invalid phone number format") } // Generate unique reference reference := s.generateReference(req.ClientID, packageInfo.Name) // Create transaction record transaction := &models.Transaction{ ID: uuid.New(), ClientID: req.ClientID, PackageID: &req.PackageID, Amount: packageInfo.Amount, Currency: packageInfo.Currency, PaymentMethod: "mobile_money", PaymentStatus: "pending", PhoneNumber: phoneNumber, Reference: reference, Description: fmt.Sprintf("%s - %s", packageInfo.Name, packageInfo.Description), Provider: "mpesa", } // Use transaction ID as temporary checkout ID checkoutID := transaction.ID.String() transaction.CheckoutID = checkoutID // Store metadata as JSON only if provided packageMetadata := map[string]interface{}{ "package_id": packageInfo.ID, "package_name": packageInfo.Name, "speed": packageInfo.Speed, "duration": packageInfo.Duration, } // Merge with user-provided metadata if req.Metadata != nil { for k, v := range req.Metadata { packageMetadata[k] = v } } metadataJSON, _ := json.Marshal(packageMetadata) metadataStr := string(metadataJSON) transaction.Metadata = &metadataStr if err := s.db.Create(transaction).Error; err != nil { return nil, fmt.Errorf("failed to create transaction: %w", err) } // Initiate STK Push stkResponse, err := s.initiateSTKPush(ctx, credentials, phoneNumber, packageInfo.Amount, checkoutID, transaction.Description) if err != nil { // Update transaction status to failed s.db.Model(transaction).Update("payment_status", "failed") return nil, fmt.Errorf("failed to initiate STK push: %w", err) } // Update transaction with STK response providerResponseJSON, _ := json.Marshal(stkResponse) providerResponseStr := string(providerResponseJSON) // Use Safaricom's CheckoutRequestID as the primary checkout ID safaricomCheckoutID, _ := stkResponse["CheckoutRequestID"].(string) updates := map[string]interface{}{ "provider_response": &providerResponseStr, } if safaricomCheckoutID != "" { updates["checkout_id"] = safaricomCheckoutID checkoutID = safaricomCheckoutID } s.db.Model(transaction).Updates(updates) return &PaymentResponse{ TransactionID: transaction.ID, CheckoutID: checkoutID, Message: "Payment initiated successfully", Status: "pending", }, nil } // CheckPaymentStatus checks the status of a payment by querying Safaricom func (s *PaymentService) CheckPaymentStatus(ctx context.Context, clientID uuid.UUID, checkoutID string) (*PaymentStatusResponse, error) { logrus.WithFields(logrus.Fields{ "client_id": clientID, "checkout_id": checkoutID, }).Info("Checking payment status") // First, try to get client credentials to query Safaricom credentials, err := s.getClientCredentials(ctx, clientID) if err != nil { logrus.WithFields(logrus.Fields{ "client_id": clientID, "checkout_id": checkoutID, "error": err.Error(), }).Error("Failed to get client credentials for payment status check") return nil, fmt.Errorf("failed to get client credentials: %w", err) } logrus.WithFields(logrus.Fields{ "client_id": clientID, "checkout_id": checkoutID, "short_code": credentials.ShortCode, }).Debug("Client credentials retrieved successfully") // Try to find local transaction record first var transaction models.Transaction dbErr := s.db.Where("client_id = ? AND checkout_id = ?", clientID, checkoutID).First(&transaction).Error if dbErr != nil { logrus.WithFields(logrus.Fields{ "client_id": clientID, "checkout_id": checkoutID, "error": dbErr.Error(), }).Error("Transaction not found in local database") return nil, fmt.Errorf("transaction not found: %w", dbErr) } logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "local_status": transaction.PaymentStatus, "amount": transaction.Amount, }).Debug("Local transaction found, querying Safaricom for latest status") // Always query Safaricom directly to get the actual payment status safaricomResponse, err := s.querySafaricomPaymentStatus(ctx, credentials, checkoutID) if err != nil { // If Safaricom query fails completely (network error, unparseable response, etc.), // return local status without updating it // This preserves the current state and doesn't prematurely mark as failed errorMessage := err.Error() logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "error": errorMessage, "local_status": transaction.PaymentStatus, }).Warn("Safaricom query failed, returning local status without update") // Return local status as-is - don't update the database // If status is pending, it remains pending until Safaricom confirms otherwise return &PaymentStatusResponse{ TransactionID: transaction.ID, CheckoutID: checkoutID, Status: transaction.PaymentStatus, Amount: transaction.Amount, Reference: transaction.Reference, PhoneNumber: transaction.PhoneNumber, }, nil } logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "result_code": safaricomResponse.ResultCode, "result_desc": safaricomResponse.ResultDesc, "response_code": safaricomResponse.ResponseCode, "response_desc": safaricomResponse.ResponseDesc, "merchant_req_id": safaricomResponse.MerchantReqID, }).Info("Safaricom payment status query successful") // Map Safaricom result code to our payment status // This will only return "completed", "cancelled", or "pending" - never "failed" paymentStatus := s.mapSafaricomResultCode(safaricomResponse.ResultCode) logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "safaricom_code": safaricomResponse.ResultCode, "mapped_status": paymentStatus, "previous_status": transaction.PaymentStatus, }).Debug("Mapped Safaricom result code to payment status") // Update local transaction record with the latest status from Safaricom // Only update if status changed and it's a definitive status (completed or cancelled) // Preserve pending status - don't overwrite with failed if paymentStatus != transaction.PaymentStatus { // Only update if moving to a definitive status (completed or cancelled) // or if current status is failed and we're getting a pending (to allow retry) if paymentStatus == "completed" || paymentStatus == "cancelled" || (transaction.PaymentStatus == "failed" && paymentStatus == "pending") { logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "old_status": transaction.PaymentStatus, "new_status": paymentStatus, "update_reason": "definitive_status_from_safaricom", }).Info("Updating transaction status from Safaricom response") s.db.Model(&transaction).Update("payment_status", paymentStatus) transaction.PaymentStatus = paymentStatus } else { logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "old_status": transaction.PaymentStatus, "new_status": paymentStatus, "reason": "preserving_pending_status", }).Debug("Skipping status update to preserve pending state") } } else { logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "status": paymentStatus, }).Debug("Transaction status unchanged, no update needed") } logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "final_status": paymentStatus, "amount": transaction.Amount, }).Info("Payment status check completed") return &PaymentStatusResponse{ TransactionID: transaction.ID, CheckoutID: checkoutID, Status: paymentStatus, Amount: transaction.Amount, Reference: transaction.Reference, PhoneNumber: transaction.PhoneNumber, }, nil } // ProcessMpesaCallback processes M-Pesa callback and updates transaction status func (s *PaymentService) ProcessMpesaCallback(ctx context.Context, clientID uuid.UUID, callbackData map[string]interface{}) error { logrus.WithFields(logrus.Fields{ "client_id": clientID, }).Info("Processing M-Pesa callback") // Parse callback data body, ok := callbackData["Body"].(map[string]interface{}) if !ok { logrus.WithFields(logrus.Fields{ "client_id": clientID, "callback_data": callbackData, }).Error("Invalid callback body structure") return fmt.Errorf("invalid callback body structure") } stkCallback, ok := body["stkCallback"].(map[string]interface{}) if !ok { logrus.WithFields(logrus.Fields{ "client_id": clientID, "body": body, }).Error("Invalid stkCallback structure") return fmt.Errorf("invalid stkCallback structure") } resultCode, ok := stkCallback["ResultCode"].(float64) if !ok { logrus.WithFields(logrus.Fields{ "client_id": clientID, "stk_callback": stkCallback, }).Error("Invalid result code in callback") return fmt.Errorf("invalid result code") } checkoutID, ok := stkCallback["CheckoutRequestID"].(string) if !ok { logrus.WithFields(logrus.Fields{ "client_id": clientID, "stk_callback": stkCallback, }).Error("Invalid checkout request ID in callback") return fmt.Errorf("invalid checkout request ID") } logrus.WithFields(logrus.Fields{ "client_id": clientID, "checkout_id": checkoutID, "result_code": resultCode, }).Info("Parsed callback data, looking up transaction") // Find transaction var transaction models.Transaction if err := s.db.Where("client_id = ? AND checkout_id = ?", clientID, checkoutID).First(&transaction).Error; err != nil { logrus.WithFields(logrus.Fields{ "client_id": clientID, "checkout_id": checkoutID, "error": err.Error(), }).Error("Transaction not found for callback") return fmt.Errorf("transaction not found: %w", err) } logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "current_status": transaction.PaymentStatus, "result_code": resultCode, }).Info("Transaction found, processing callback") // Store callback data in transaction's provider_response field callbackJSON, _ := json.Marshal(callbackData) callbackStr := string(callbackJSON) resultCodeInt := int(resultCode) oldStatus := transaction.PaymentStatus if resultCodeInt == 0 { // Payment successful logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "result_code": resultCodeInt, }).Info("Payment successful, processing callback metadata") callbackMetadata, ok := stkCallback["CallbackMetadata"].(map[string]interface{}) if ok { items, ok := callbackMetadata["Item"].([]interface{}) if ok { for _, item := range items { itemMap, ok := item.(map[string]interface{}) if !ok { continue } name, _ := itemMap["Name"].(string) value := itemMap["Value"] switch name { case "Amount": if amount, ok := value.(float64); ok { logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "old_amount": transaction.Amount, "new_amount": amount, }).Debug("Updating transaction amount from callback") transaction.Amount = amount } case "MpesaReceiptNumber": if receipt, ok := value.(string); ok { logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "mpesa_receipt": receipt, }).Debug("Setting M-Pesa receipt number from callback") transaction.MpesaReceipt = receipt } case "PhoneNumber": if phone, ok := value.(string); ok { logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "phone_number": phone, }).Debug("Updating phone number from callback") transaction.PhoneNumber = phone } } } } } transaction.PaymentStatus = "completed" logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "old_status": oldStatus, "new_status": "completed", "result_code": resultCodeInt, }).Info("Payment marked as completed from callback") } else if resultCodeInt == 1032 { // Request cancelled by user - mark as cancelled, not failed transaction.PaymentStatus = "cancelled" logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "old_status": oldStatus, "new_status": "cancelled", "result_code": resultCodeInt, }).Info("Payment marked as cancelled by user from callback") } else { // Other error codes - mark as failed only when explicitly indicated by callback transaction.PaymentStatus = "failed" logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "old_status": oldStatus, "new_status": "failed", "result_code": resultCodeInt, }).Warn("Payment marked as failed from callback with non-zero result code") } // Update transaction with callback data and status updates := map[string]interface{}{ "payment_status": transaction.PaymentStatus, "provider_response": &callbackStr, } if err := s.db.Model(&transaction).Updates(updates).Error; err != nil { logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "error": err.Error(), }).Error("Failed to update transaction from callback") return fmt.Errorf("failed to update transaction: %w", err) } logrus.WithFields(logrus.Fields{ "transaction_id": transaction.ID, "checkout_id": checkoutID, "old_status": oldStatus, "new_status": transaction.PaymentStatus, "result_code": resultCodeInt, }).Info("Transaction status updated successfully from callback") return nil } // GetTransactions retrieves transactions for a client func (s *PaymentService) GetTransactions(ctx context.Context, clientID uuid.UUID, limit, offset int) ([]*PaymentStatusResponse, error) { var transactions []models.Transaction query := s.db.Where("client_id = ?", clientID).Order("created_at DESC") if limit > 0 { query = query.Limit(limit) } if offset > 0 { query = query.Offset(offset) } if err := query.Find(&transactions).Error; err != nil { return nil, fmt.Errorf("failed to fetch transactions: %w", err) } var responses []*PaymentStatusResponse for _, tx := range transactions { responses = append(responses, &PaymentStatusResponse{ TransactionID: tx.ID, CheckoutID: tx.CheckoutID, Status: tx.PaymentStatus, Amount: tx.Amount, Reference: tx.Reference, PhoneNumber: tx.PhoneNumber, }) } return responses, nil } // Helper methods func (s *PaymentService) getClientCredentials(ctx context.Context, clientID uuid.UUID) (*models.PaymentCredentials, error) { cacheKey := fmt.Sprintf("credentials:%s", clientID.String()) // Try to get from cache first cached, err := s.redis.Get(ctx, cacheKey).Result() if err == nil { var credentials models.PaymentCredentials unmarshalErr := json.Unmarshal([]byte(cached), &credentials) if unmarshalErr == nil { logrus.WithFields(logrus.Fields{ "client_id": clientID, }).Debug("Client credentials retrieved from cache") return &credentials, nil } logrus.WithFields(logrus.Fields{ "client_id": clientID, "error": unmarshalErr.Error(), }).Warn("Failed to unmarshal cached credentials, fetching from database") } logrus.WithFields(logrus.Fields{ "client_id": clientID, }).Debug("Fetching client credentials from database") // Get from database var credentials models.PaymentCredentials if err := s.db.Where("client_id = ? AND is_active = true", clientID).First(&credentials).Error; err != nil { logrus.WithFields(logrus.Fields{ "client_id": clientID, "error": err.Error(), }).Error("Failed to fetch client credentials from database") return nil, err } // Cache the credentials credentialsJSON, _ := json.Marshal(credentials) s.redis.Set(ctx, cacheKey, credentialsJSON, time.Duration(s.config.Cache.TTLSeconds)*time.Second) logrus.WithFields(logrus.Fields{ "client_id": clientID, "short_code": credentials.ShortCode, "base_url": credentials.BaseURL, "cache_ttl_sec": s.config.Cache.TTLSeconds, }).Debug("Client credentials fetched from database and cached") return &credentials, nil } func (s *PaymentService) generateReference(clientID uuid.UUID, packageName string) string { // Generate a globally unique reference with format: PACKAGE-TIMESTAMP-RANDOM timestamp := time.Now().Format("20060102150405") // Clean package name for reference (remove spaces, special chars) cleanPackage := strings.ReplaceAll(strings.ToUpper(packageName), " ", "-") cleanPackage = strings.ReplaceAll(cleanPackage, "INTERNET", "INT") cleanPackage = strings.ReplaceAll(cleanPackage, "PLAN", "PL") // Limit package name length if len(cleanPackage) > 10 { cleanPackage = cleanPackage[:10] } // Generate unique reference with retry logic for i := 0; i < 10; i++ { // Max 10 retries // Generate random suffix for uniqueness randomBytes := make([]byte, 4) rand.Read(randomBytes) randomSuffix := base64.URLEncoding.EncodeToString(randomBytes)[:6] // 6 chars reference := fmt.Sprintf("%s-%s-%s", cleanPackage, timestamp, randomSuffix) // Check if reference already exists in database var count int64 s.db.Model(&models.Transaction{}).Where("reference = ?", reference).Count(&count) if count == 0 { return reference // Reference is unique } // If not unique, try again with different random suffix time.Sleep(time.Millisecond * 10) // Small delay to ensure different timestamp } // Fallback: use UUID if all retries fail fallbackUUID := uuid.New().String()[:8] return fmt.Sprintf("%s-%s-%s", cleanPackage, timestamp, fallbackUUID) } func (s *PaymentService) initiateSTKPush(ctx context.Context, credentials *models.PaymentCredentials, phoneNumber string, amount float64, checkoutID, description string) (map[string]interface{}, error) { logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "phone_number": phoneNumber, "amount": amount, "description": description, "short_code": credentials.ShortCode, }).Info("Initiating STK push") // Get access token token, err := s.getAccessToken(ctx, credentials) if err != nil { logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "error": err.Error(), }).Error("Failed to get access token for STK push") return nil, fmt.Errorf("failed to get access token: %w", err) } // Prepare STK Push request timestamp := time.Now().Format("20060102150405") password := base64.StdEncoding.EncodeToString([]byte(credentials.ShortCode + credentials.PassKey + timestamp)) requestBody := map[string]interface{}{ "BusinessShortCode": credentials.ShortCode, "Password": password, "Timestamp": timestamp, "TransactionType": "CustomerPayBillOnline", "Amount": int(amount), "PartyA": phoneNumber, "PartyB": credentials.ShortCode, "PhoneNumber": phoneNumber, "CallBackURL": credentials.CallbackURL, "AccountReference": checkoutID, "TransactionDesc": description, } logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "business_short_code": credentials.ShortCode, "amount": int(amount), "phone_number": phoneNumber, "callback_url": credentials.CallbackURL, "timestamp": timestamp, }).Debug("Prepared STK push request body") // Make HTTP request url := credentials.BaseURL + "/mpesa/stkpush/v1/processrequest" reqBodyJSON := utils.ToJSON(requestBody) req, err := http.NewRequestWithContext(ctx, "POST", url, strings.NewReader(reqBodyJSON)) if err != nil { logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "url": url, "error": err.Error(), }).Error("Failed to create STK push HTTP request") return nil, fmt.Errorf("failed to create request: %w", err) } req.Header.Set("Authorization", "Bearer "+token) req.Header.Set("Content-Type", "application/json") logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "url": url, "method": "POST", }).Debug("Sending STK push request to Safaricom") client := &http.Client{Timeout: 30 * time.Second} startTime := time.Now() resp, err := client.Do(req) requestDuration := time.Since(startTime) if err != nil { logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "url": url, "error": err.Error(), "request_duration_ms": requestDuration.Milliseconds(), }).Error("STK push HTTP request failed") return nil, fmt.Errorf("failed to make request: %w", err) } defer resp.Body.Close() logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "status_code": resp.StatusCode, "request_duration_ms": requestDuration.Milliseconds(), }).Debug("Received STK push response from Safaricom") var response map[string]interface{} if err := json.NewDecoder(resp.Body).Decode(&response); err != nil { logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "status_code": resp.StatusCode, "error": err.Error(), }).Error("Failed to decode STK push response") return nil, fmt.Errorf("failed to decode response: %w", err) } if resp.StatusCode != http.StatusOK { logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "status_code": resp.StatusCode, "response": response, }).Error("STK push failed with non-200 status") return nil, fmt.Errorf("STK push failed with status %d: %v", resp.StatusCode, response) } logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "response_code": response["ResponseCode"], "response_description": response["ResponseDescription"], "checkout_request_id": response["CheckoutRequestID"], "merchant_request_id": response["MerchantRequestID"], }).Info("STK push initiated successfully") return response, nil } func (s *PaymentService) getAccessToken(ctx context.Context, credentials *models.PaymentCredentials) (string, error) { cacheKey := fmt.Sprintf("token:%s", credentials.ClientID.String()) // Try to get from cache first cached, err := s.redis.Get(ctx, cacheKey).Result() if err == nil { logrus.WithFields(logrus.Fields{ "client_id": credentials.ClientID, }).Debug("Access token retrieved from cache") return cached, nil } logrus.WithFields(logrus.Fields{ "client_id": credentials.ClientID, "base_url": credentials.BaseURL, }).Debug("Access token not in cache, generating new token") // Generate new token auth := base64.StdEncoding.EncodeToString([]byte(credentials.ConsumerKey + ":" + credentials.ConsumerSecret)) url := credentials.BaseURL + "/oauth/v1/generate?grant_type=client_credentials" req, err := http.NewRequestWithContext(ctx, "GET", url, nil) if err != nil { logrus.WithFields(logrus.Fields{ "client_id": credentials.ClientID, "url": url, "error": err.Error(), }).Error("Failed to create access token request") return "", fmt.Errorf("failed to create request: %w", err) } req.Header.Set("Authorization", "Basic "+auth) logrus.WithFields(logrus.Fields{ "client_id": credentials.ClientID, "url": url, }).Debug("Sending access token request to Safaricom") client := &http.Client{Timeout: 10 * time.Second} startTime := time.Now() resp, err := client.Do(req) requestDuration := time.Since(startTime) if err != nil { logrus.WithFields(logrus.Fields{ "client_id": credentials.ClientID, "url": url, "error": err.Error(), "request_duration_ms": requestDuration.Milliseconds(), }).Error("Access token request failed") return "", fmt.Errorf("failed to make request: %w", err) } defer resp.Body.Close() logrus.WithFields(logrus.Fields{ "client_id": credentials.ClientID, "status_code": resp.StatusCode, "request_duration_ms": requestDuration.Milliseconds(), }).Debug("Received access token response") var tokenResponse struct { AccessToken string `json:"access_token"` ExpiresIn string `json:"expires_in"` } if err := json.NewDecoder(resp.Body).Decode(&tokenResponse); err != nil { logrus.WithFields(logrus.Fields{ "client_id": credentials.ClientID, "status_code": resp.StatusCode, "error": err.Error(), }).Error("Failed to decode access token response") return "", fmt.Errorf("failed to decode token response: %w", err) } if resp.StatusCode != http.StatusOK { logrus.WithFields(logrus.Fields{ "client_id": credentials.ClientID, "status_code": resp.StatusCode, }).Error("Access token request failed with non-200 status") return "", fmt.Errorf("token request failed with status %d", resp.StatusCode) } // Cache the token expiresIn, err := strconv.Atoi(tokenResponse.ExpiresIn) if err != nil { logrus.WithFields(logrus.Fields{ "client_id": credentials.ClientID, "expires_in": tokenResponse.ExpiresIn, "error": err.Error(), }).Error("Failed to parse expires_in") return "", fmt.Errorf("failed to parse expires_in: %w", err) } expiry := time.Duration(expiresIn-60) * time.Second // Cache for 1 minute less than expiry s.redis.Set(ctx, cacheKey, tokenResponse.AccessToken, expiry) logrus.WithFields(logrus.Fields{ "client_id": credentials.ClientID, "expires_in": expiresIn, "cache_expiry": expiry.Seconds(), "token_length": len(tokenResponse.AccessToken), }).Info("Access token generated and cached successfully") return tokenResponse.AccessToken, nil } // SafaricomStatusResponse represents the response from Safaricom status query type SafaricomStatusResponse struct { ResponseCode string `json:"ResponseCode"` ResponseDesc string `json:"ResponseDescription"` MerchantReqID string `json:"MerchantRequestID"` CheckoutReqID string `json:"CheckoutRequestID"` ResultCode string `json:"ResultCode"` ResultDesc string `json:"ResultDesc"` } // querySafaricomPaymentStatus queries Safaricom for the payment status func (s *PaymentService) querySafaricomPaymentStatus(ctx context.Context, credentials *models.PaymentCredentials, checkoutID string) (*SafaricomStatusResponse, error) { logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "base_url": credentials.BaseURL, }).Debug("Starting Safaricom payment status query") // Get access token token, err := s.getAccessToken(ctx, credentials) if err != nil { logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "error": err.Error(), }).Error("Failed to get access token for Safaricom query") return nil, fmt.Errorf("failed to get access token: %w", err) } logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "token_length": len(token), }).Debug("Access token retrieved successfully") // Prepare request body timestamp := time.Now().Format("20060102150405") password := base64.StdEncoding.EncodeToString([]byte(credentials.ShortCode + credentials.PassKey + timestamp)) requestBody := map[string]interface{}{ "BusinessShortCode": credentials.ShortCode, "Password": password, "Timestamp": timestamp, "CheckoutRequestID": checkoutID, } logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "business_short_code": credentials.ShortCode, "timestamp": timestamp, }).Debug("Prepared Safaricom query request body") // Make HTTP request to Safaricom url := credentials.BaseURL + "/mpesa/stkpushquery/v1/query" reqBodyJSON := utils.ToJSON(requestBody) req, err := http.NewRequestWithContext(ctx, "POST", url, strings.NewReader(reqBodyJSON)) if err != nil { logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "url": url, "error": err.Error(), }).Error("Failed to create HTTP request for Safaricom query") return nil, fmt.Errorf("failed to create request: %w", err) } req.Header.Set("Authorization", "Bearer "+token) req.Header.Set("Content-Type", "application/json") logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "url": url, "method": "POST", }).Debug("Sending HTTP request to Safaricom") client := &http.Client{Timeout: 30 * time.Second} startTime := time.Now() resp, err := client.Do(req) requestDuration := time.Since(startTime) if err != nil { logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "url": url, "error": err.Error(), "request_duration_ms": requestDuration.Milliseconds(), }).Error("HTTP request to Safaricom failed") return nil, fmt.Errorf("failed to make request to Safaricom: %w", err) } defer resp.Body.Close() logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "status_code": resp.StatusCode, "request_duration_ms": requestDuration.Milliseconds(), }).Debug("Received response from Safaricom") // Read and parse the response body first, even if status code is not 200 // Safaricom may return valid response data even with rate limit errors (429) var response SafaricomStatusResponse respBytes, err := io.ReadAll(resp.Body) if err != nil { logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "status_code": resp.StatusCode, "error": err.Error(), }).Error("Failed to read Safaricom response body") return nil, fmt.Errorf("failed to read Safaricom response: %w", err) } logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "status_code": resp.StatusCode, "response_size": len(respBytes), "response_preview": func() string { if len(respBytes) > 500 { return string(respBytes[:500]) + "..." } return string(respBytes) }(), }).Debug("Read Safaricom response body") // Try to parse the response body - Safaricom may return valid JSON even with non-200 status if err := json.Unmarshal(respBytes, &response); err != nil { // If we can't parse the response and status is not 200, return error if resp.StatusCode != http.StatusOK { logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "status_code": resp.StatusCode, "response_body": string(respBytes), "error": err.Error(), }).Error("Failed to parse Safaricom response with non-200 status") return nil, fmt.Errorf("Safaricom query failed with status %d and unparseable response: %w", resp.StatusCode, err) } logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "response_body": string(respBytes), "error": err.Error(), }).Error("Failed to decode Safaricom response") return nil, fmt.Errorf("failed to decode Safaricom response: %w", err) } logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "status_code": resp.StatusCode, "result_code": response.ResultCode, "result_desc": response.ResultDesc, "response_code": response.ResponseCode, "response_desc": response.ResponseDesc, "merchant_req_id": response.MerchantReqID, "checkout_req_id": response.CheckoutReqID, }).Debug("Parsed Safaricom response successfully") // If we have a valid Safaricom response with ResultCode, use it even if HTTP status is not 200 // This handles cases like rate limiting (429) where Safaricom still returns valid payment status if response.ResultCode != "" || response.ResponseCode != "" { if resp.StatusCode != http.StatusOK { logrus.WithFields(logrus.Fields{ "status": resp.StatusCode, "response": string(respBytes), "checkout_id": checkoutID, "result_code": response.ResultCode, "result_desc": response.ResultDesc, "response_code": response.ResponseCode, }).Warn("Safaricom query returned non-200 status but has valid response data - using response data") } else { logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "result_code": response.ResultCode, "result_desc": response.ResultDesc, }).Info("Safaricom query successful with 200 status") } return &response, nil } // If no valid response data and status is not 200, return error if resp.StatusCode != http.StatusOK { logrus.WithFields(logrus.Fields{ "status": resp.StatusCode, "response": string(respBytes), "checkout_id": checkoutID, "result_code": response.ResultCode, "response_code": response.ResponseCode, }).Error("Safaricom query returned non-200 status with no valid response data") return nil, fmt.Errorf("Safaricom query failed with status %d: %s", resp.StatusCode, response.ResultDesc) } logrus.WithFields(logrus.Fields{ "checkout_id": checkoutID, "result_code": response.ResultCode, "result_desc": response.ResultDesc, }).Info("Safaricom query completed successfully") return &response, nil } // mapSafaricomResultCode maps Safaricom result codes to our payment status // Only explicitly mark as completed (0) or cancelled (1032), otherwise keep as pending // This ensures pending transactions remain pending until explicitly cancelled or completed func (s *PaymentService) mapSafaricomResultCode(resultCode string) string { var mappedStatus string var reason string switch resultCode { case "0": mappedStatus = "completed" // Success - payment completed reason = "payment_completed" case "1032": mappedStatus = "cancelled" // Request cancelled by user - explicitly cancelled reason = "user_cancelled" case "": mappedStatus = "pending" // No code yet - still processing reason = "no_result_code" default: // For all other codes (including 1037 timeout, 1017 invalid credentials, etc.), // keep as pending. The transaction may still be processing or Safaricom may retry. // Only update to failed when we receive explicit failure confirmation via callback // or when the user explicitly cancels (1032). mappedStatus = "pending" reason = fmt.Sprintf("unknown_code_%s_keeping_pending", resultCode) } logrus.WithFields(logrus.Fields{ "safaricom_result_code": resultCode, "mapped_status": mappedStatus, "mapping_reason": reason, }).Debug("Mapped Safaricom result code to payment status") return mappedStatus }