fix(purchases): tighten AWS SDK retry budget + bump Lambda timeout to 300s (closes #683)

internal/api/handler_purchases.go

@@ -360,6 +360,9 @@ func (h *Handler) approvePurchase(ctx context.Context, req *events.LambdaFunctio
 // invocation drives its own executeAndFinalize, which already fans out
 // per-account in parallel via executeMultiAccount.
 func (h *Handler) approvePurchaseViaSession(ctx context.Context, req *events.LambdaFunctionURLRequest, execution *config.PurchaseExecution) (any, error) {
+	t0 := time.Now()
+	logging.Infof("purchase[%s]: approvePurchaseViaSession entry (auth=session)", execution.ExecutionID)
+
 	session, err := h.requireSession(ctx, req)
 	if err != nil {
 		return nil, err
@@ -376,12 +379,16 @@ func (h *Handler) approvePurchaseViaSession(ctx context.Context, req *events.Lam
 	if err := h.purchase.ApproveAndExecute(ctx, execution.ExecutionID, session.Email); err != nil {
 		// ApproveAndExecute returns either a transition error (the row
 		// drifted out of pending/notified between our check and the UPDATE
-		// — race with cancel/expire) or an execution error (AWS API failed,
+		// -- race with cancel/expire) or an execution error (AWS API failed,
 		// status is now "failed" on disk). Both surface as 409 to the
 		// caller; the History view shows the resulting row state.
+		logging.Errorf("purchase[%s]: approvePurchaseViaSession failed after %s: %v",
+			execution.ExecutionID, time.Since(t0), err)
 		return nil, NewClientError(409, fmt.Sprintf("execution %s could not be approved: %v", execution.ExecutionID, err))
 	}
 
+	logging.Infof("purchase[%s]: approvePurchaseViaSession completed in %s (auth=session)",
+		execution.ExecutionID, time.Since(t0))
 	return map[string]string{"status": "completed"}, nil
 }
 

internal/execution/fanout.go

@@ -8,6 +8,7 @@ import (
 	"runtime"
 	"strconv"
 	"sync"
+	"time"
 
 	"github.com/LeanerCloud/CUDly/pkg/logging"
 )
@@ -92,7 +93,17 @@ func FanOutWithConcurrency[T any](
 					}
 				}
 			}()
+			t0 := time.Now()
+			logging.Infof("purchase[fan-out]: goroutine starting for account=%s", accountID)
 			val, err := fn(ctx, accountID)
+			elapsed := time.Since(t0)
+			if err != nil {
+				logging.Errorf("purchase[fan-out]: goroutine for account=%s failed after %s: %v",
+					accountID, elapsed, err)
+			} else {
+				logging.Infof("purchase[fan-out]: goroutine for account=%s completed in %s",
+					accountID, elapsed)
+			}
 			results[idx] = Result[T]{AccountID: accountID, Value: val, Err: err}
 		}(i, id)
 	}

internal/purchase/approvals.go

@@ -22,7 +22,8 @@ import (
 // NULL — the column is nullable TEXT and we don't want to claim "approved
 // by nobody".
 func (m *Manager) ApproveExecution(ctx context.Context, executionID, token, actor string) error {
-	logging.Infof("Approving execution: %s", executionID)
+	t0 := time.Now()
+	logging.Infof("purchase[%s]: ApproveExecution entry (auth=token actor=%q)", executionID, maskActor(actor))
 
 	execution, err := m.config.GetExecutionByID(ctx, executionID)
 	if err != nil {
@@ -50,10 +51,42 @@ func (m *Manager) ApproveExecution(ctx context.Context, executionID, token, acto
 	// Preflight guard (issue #609): reject non-AWS orphan executions before
 	// the cloud SDK is reached. See OrphanExecutionError for the full rationale.
 	if err := OrphanExecutionError(execution); err != nil {
+		logging.Errorf("purchase[%s]: ApproveExecution preflight rejected after %s: %v",
+			executionID, time.Since(t0), err)
 		return err
 	}
 
-	return m.ApproveAndExecute(ctx, executionID, actor)
+	err = m.ApproveAndExecute(ctx, executionID, actor)
+	if err != nil {
+		logging.Errorf("purchase[%s]: ApproveExecution (token path) failed after %s: %v",
+			executionID, time.Since(t0), err)
+	} else {
+		logging.Infof("purchase[%s]: ApproveExecution (token path) completed in %s",
+			executionID, time.Since(t0))
+	}
+	return err
+}
+
+// maskActor masks an actor email/username for safe log emission.
+// Full email addresses are PII; log only the domain part.
+// Empty actor is logged as "<anon>" so the distinction between
+// "no actor provided" and "actor was empty string" is visible.
+func maskActor(actor string) string {
+	if actor == "" {
+		return "<anon>"
+	}
+	if at := len(actor) - 1; at >= 0 {
+		for i, c := range actor {
+			if c == '@' {
+				return "***" + actor[i:]
+			}
+		}
+	}
+	// Not an email address -- log only the last 4 chars (e.g. a username).
+	if len(actor) > 4 {
+		return "..." + actor[len(actor)-4:]
+	}
+	return "****"
 }
 
 // OrphanExecutionError returns a descriptive error when the execution has no
@@ -108,24 +141,36 @@ func OrphanExecutionError(execution *config.PurchaseExecution) error {
 // approval drives its own executeAndFinalize, which already fans out
 // per-account in parallel via executeMultiAccount.
 func (m *Manager) ApproveAndExecute(ctx context.Context, executionID, actor string) error {
+	t0 := time.Now()
+	logging.Infof("purchase[%s]: ApproveAndExecute starting (actor=%q)", executionID, maskActor(actor))
+
 	updated, err := m.config.TransitionExecutionStatus(ctx, executionID, []string{"pending", "notified"}, "approved")
 	if err != nil {
+		logging.Errorf("purchase[%s]: ApproveAndExecute status transition failed after %s: %v",
+			executionID, time.Since(t0), err)
 		return fmt.Errorf("approve: %w", err)
 	}
+	logging.Infof("purchase[%s]: status transitioned to approved in %s", executionID, time.Since(t0))
 
 	if actor != "" {
 		a := actor
 		updated.ApprovedBy = &a
 		if saveErr := m.config.SavePurchaseExecution(ctx, updated); saveErr != nil {
-			// Attribution is best-effort once the atomic flip has landed —
+			// Attribution is best-effort once the atomic flip has landed --
 			// dropping ApprovedBy must not stop the purchase from firing.
 			// Log loudly so the audit gap is visible.
 			logging.Errorf("AUDIT GAP: failed to stamp approved_by on %s: %v", executionID, saveErr)
 		}
 	}
 
-	logging.Infof("Execution %s approved, executing synchronously", executionID)
-	return m.executeAndFinalize(ctx, updated)
+	logging.Infof("purchase[%s]: executing purchase synchronously", executionID)
+	execErr := m.executeAndFinalize(ctx, updated)
+	if execErr != nil {
+		logging.Errorf("purchase[%s]: ApproveAndExecute failed after %s: %v", executionID, time.Since(t0), execErr)
+	} else {
+		logging.Infof("purchase[%s]: ApproveAndExecute completed in %s", executionID, time.Since(t0))
+	}
+	return execErr
 }
 
 // CancelExecution cancels a pending execution. actor carries the email of

internal/purchase/coverage_extra_test.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"errors"
 	"testing"
+	"time"
 
 	"github.com/LeanerCloud/CUDly/internal/config"
 	"github.com/LeanerCloud/CUDly/pkg/common"
@@ -285,7 +286,7 @@ func TestHandleExecutePurchase_SaveError(t *testing.T) {
 	mockSTS.On("GetCallerIdentity", ctx, mock.Anything).Return(nil, errors.New("sts error"))
 
 	// Provider factory returns error → purchase fails
-	mockFactory.On("CreateAndValidateProvider", ctx, "aws", mock.Anything).Return(nil, errors.New("provider error"))
+	mockFactory.On("CreateAndValidateProvider", mock.Anything, "aws", mock.Anything).Return(nil, errors.New("provider error"))
 
 	manager := &Manager{
 		config:          mockStore,
@@ -582,7 +583,7 @@ func TestManager_ExecuteSinglePurchase_ProviderError(t *testing.T) {
 	}
 
 	mockStore.On("GetPurchasePlan", ctx, "plan-prov-err").Return(plan, nil)
-	mockFactory.On("CreateAndValidateProvider", ctx, "aws", mock.Anything).Return(nil, errors.New("provider unavailable"))
+	mockFactory.On("CreateAndValidateProvider", mock.Anything, "aws", mock.Anything).Return(nil, errors.New("provider unavailable"))
 	mockSTS.On("GetCallerIdentity", ctx, mock.Anything).Return(nil, errors.New("sts error"))
 
 	manager := &Manager{
@@ -630,8 +631,8 @@ func TestManager_ExecuteSinglePurchase_ServiceClientError(t *testing.T) {
 	}
 
 	mockStore.On("GetPurchasePlan", ctx, "plan-svc-err").Return(plan, nil)
-	mockFactory.On("CreateAndValidateProvider", ctx, "aws", mock.Anything).Return(mockProvider, nil)
-	mockProvider.On("GetServiceClient", ctx, common.ServiceRDS, "eu-west-1").Return(nil, errors.New("service client error"))
+	mockFactory.On("CreateAndValidateProvider", mock.Anything, "aws", mock.Anything).Return(mockProvider, nil)
+	mockProvider.On("GetServiceClient", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), common.ServiceRDS, "eu-west-1").Return(nil, errors.New("service client error"))
 	mockSTS.On("GetCallerIdentity", ctx, mock.Anything).Return(nil, errors.New("sts error"))
 
 	manager := &Manager{
@@ -679,9 +680,9 @@ func TestManager_ExecuteSinglePurchase_PurchaseNotSuccessful(t *testing.T) {
 	}
 
 	mockStore.On("GetPurchasePlan", ctx, "plan-not-success").Return(plan, nil)
-	mockFactory.On("CreateAndValidateProvider", ctx, "aws", mock.Anything).Return(mockProvider, nil)
-	mockProvider.On("GetServiceClient", ctx, common.ServiceElastiCache, "ap-southeast-1").Return(mockServiceClient, nil)
-	mockServiceClient.On("PurchaseCommitment", ctx, mock.AnythingOfType("common.Recommendation"), mock.AnythingOfType("common.PurchaseOptions")).Return(
+	mockFactory.On("CreateAndValidateProvider", mock.Anything, "aws", mock.Anything).Return(mockProvider, nil)
+	mockProvider.On("GetServiceClient", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), common.ServiceElastiCache, "ap-southeast-1").Return(mockServiceClient, nil)
+	mockServiceClient.On("PurchaseCommitment", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), mock.AnythingOfType("common.Recommendation"), mock.AnythingOfType("common.PurchaseOptions")).Return(
 		common.PurchaseResult{Success: false}, nil,
 	)
 	mockSTS.On("GetCallerIdentity", ctx, mock.Anything).Return(nil, errors.New("sts error"))
@@ -732,9 +733,9 @@ func TestManager_ExecuteSinglePurchase_PurchaseNotSuccessful_WithError(t *testin
 
 	specificErr := errors.New("capacity limit exceeded")
 	mockStore.On("GetPurchasePlan", ctx, "plan-err-result").Return(plan, nil)
-	mockFactory.On("CreateAndValidateProvider", ctx, "aws", mock.Anything).Return(mockProvider, nil)
-	mockProvider.On("GetServiceClient", ctx, common.ServiceOpenSearch, "us-west-2").Return(mockServiceClient, nil)
-	mockServiceClient.On("PurchaseCommitment", ctx, mock.AnythingOfType("common.Recommendation"), mock.AnythingOfType("common.PurchaseOptions")).Return(
+	mockFactory.On("CreateAndValidateProvider", mock.Anything, "aws", mock.Anything).Return(mockProvider, nil)
+	mockProvider.On("GetServiceClient", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), common.ServiceOpenSearch, "us-west-2").Return(mockServiceClient, nil)
+	mockServiceClient.On("PurchaseCommitment", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), mock.AnythingOfType("common.Recommendation"), mock.AnythingOfType("common.PurchaseOptions")).Return(
 		common.PurchaseResult{Success: false, Error: specificErr}, nil,
 	)
 	mockSTS.On("GetCallerIdentity", ctx, mock.Anything).Return(nil, errors.New("sts error"))
@@ -788,9 +789,9 @@ func TestManager_ExecuteSinglePurchase_WithEngine(t *testing.T) {
 	mockStore.On("GetPurchasePlan", ctx, "plan-engine").Return(plan, nil)
 	mockStore.On("SavePurchaseHistory", ctx, mock.AnythingOfType("*config.PurchaseHistoryRecord")).Return(nil)
 	mockEmail.On("SendPurchaseConfirmation", ctx, mock.AnythingOfType("email.NotificationData")).Return(nil)
-	mockFactory.On("CreateAndValidateProvider", ctx, "aws", mock.Anything).Return(mockProvider, nil)
-	mockProvider.On("GetServiceClient", ctx, common.ServiceRDS, "us-east-1").Return(mockServiceClient, nil)
-	mockServiceClient.On("PurchaseCommitment", ctx, mock.AnythingOfType("common.Recommendation"), mock.AnythingOfType("common.PurchaseOptions")).Return(
+	mockFactory.On("CreateAndValidateProvider", mock.Anything, "aws", mock.Anything).Return(mockProvider, nil)
+	mockProvider.On("GetServiceClient", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), common.ServiceRDS, "us-east-1").Return(mockServiceClient, nil)
+	mockServiceClient.On("PurchaseCommitment", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), mock.AnythingOfType("common.Recommendation"), mock.AnythingOfType("common.PurchaseOptions")).Return(
 		common.PurchaseResult{Success: true, CommitmentID: "ri-engine-001"}, nil,
 	)
 	mockSTS.On("GetCallerIdentity", ctx, mock.Anything).Return(nil, errors.New("sts error"))
@@ -845,9 +846,9 @@ func TestManager_SavePurchaseHistory_Error(t *testing.T) {
 	// SavePurchaseHistory returns error — should be logged but not fail executePurchase
 	mockStore.On("SavePurchaseHistory", ctx, mock.AnythingOfType("*config.PurchaseHistoryRecord")).Return(errors.New("history write error"))
 	mockEmail.On("SendPurchaseConfirmation", ctx, mock.AnythingOfType("email.NotificationData")).Return(nil)
-	mockFactory.On("CreateAndValidateProvider", ctx, "aws", mock.Anything).Return(mockProvider, nil)
-	mockProvider.On("GetServiceClient", ctx, common.ServiceEC2, "us-east-1").Return(mockServiceClient, nil)
-	mockServiceClient.On("PurchaseCommitment", ctx, mock.AnythingOfType("common.Recommendation"), mock.AnythingOfType("common.PurchaseOptions")).Return(
+	mockFactory.On("CreateAndValidateProvider", mock.Anything, "aws", mock.Anything).Return(mockProvider, nil)
+	mockProvider.On("GetServiceClient", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), common.ServiceEC2, "us-east-1").Return(mockServiceClient, nil)
+	mockServiceClient.On("PurchaseCommitment", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), mock.AnythingOfType("common.Recommendation"), mock.AnythingOfType("common.PurchaseOptions")).Return(
 		common.PurchaseResult{Success: true, CommitmentID: "ri-hist-001"}, nil,
 	)
 	mockSTS.On("GetCallerIdentity", ctx, mock.Anything).Return(nil, errors.New("sts error"))
@@ -1083,11 +1084,11 @@ func TestManager_ExecuteSinglePurchase_DetailsByService(t *testing.T) {
 			mockStore.On("GetPurchasePlan", ctx, plan.ID).Return(plan, nil)
 			mockStore.On("SavePurchaseHistory", ctx, mock.AnythingOfType("*config.PurchaseHistoryRecord")).Return(nil)
 			mockEmail.On("SendPurchaseConfirmation", ctx, mock.AnythingOfType("email.NotificationData")).Return(nil)
-			mockFactory.On("CreateAndValidateProvider", ctx, "aws", mock.Anything).Return(mockProvider, nil)
-			mockProvider.On("GetServiceClient", ctx, tc.serviceType, tc.region).Return(mockServiceClient, nil)
+			mockFactory.On("CreateAndValidateProvider", mock.Anything, "aws", mock.Anything).Return(mockProvider, nil)
+			mockProvider.On("GetServiceClient", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), tc.serviceType, tc.region).Return(mockServiceClient, nil)
 			mockServiceClient.On(
 				"PurchaseCommitment",
-				ctx,
+				mock.MatchedBy(hasPerRecDeadline(30*time.Second)),
 				mock.AnythingOfType("common.Recommendation"),
 				mock.AnythingOfType("common.PurchaseOptions"),
 			).Run(func(args mock.Arguments) {
@@ -1221,11 +1222,11 @@ func TestManager_ExecuteSinglePurchase_LegacyEmptyDetails(t *testing.T) {
 			mockStore.On("GetPurchasePlan", ctx, plan.ID).Return(plan, nil)
 			mockStore.On("SavePurchaseHistory", ctx, mock.AnythingOfType("*config.PurchaseHistoryRecord")).Return(nil)
 			mockEmail.On("SendPurchaseConfirmation", ctx, mock.AnythingOfType("email.NotificationData")).Return(nil)
-			mockFactory.On("CreateAndValidateProvider", ctx, "aws", mock.Anything).Return(mockProvider, nil)
-			mockProvider.On("GetServiceClient", ctx, tc.serviceType, tc.region).Return(mockServiceClient, nil)
+			mockFactory.On("CreateAndValidateProvider", mock.Anything, "aws", mock.Anything).Return(mockProvider, nil)
+			mockProvider.On("GetServiceClient", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), tc.serviceType, tc.region).Return(mockServiceClient, nil)
 			mockServiceClient.On(
 				"PurchaseCommitment",
-				ctx,
+				mock.MatchedBy(hasPerRecDeadline(30*time.Second)),
 				mock.AnythingOfType("common.Recommendation"),
 				mock.AnythingOfType("common.PurchaseOptions"),
 			).Run(func(args mock.Arguments) {