diff --git a/internal/api/handler_purchases.go b/internal/api/handler_purchases.go index c00644a6f..7bfa71dd3 100644 --- a/internal/api/handler_purchases.go +++ b/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 } diff --git a/internal/execution/fanout.go b/internal/execution/fanout.go index 9982cb976..22efcdd28 100644 --- a/internal/execution/fanout.go +++ b/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) } diff --git a/internal/purchase/approvals.go b/internal/purchase/approvals.go index 916be1c10..b9253f78e 100644 --- a/internal/purchase/approvals.go +++ b/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 "" so the distinction between +// "no actor provided" and "actor was empty string" is visible. +func maskActor(actor string) string { + if actor == "" { + return "" + } + 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 diff --git a/internal/purchase/coverage_extra_test.go b/internal/purchase/coverage_extra_test.go index c86bdd0d9..c422e7dcf 100644 --- a/internal/purchase/coverage_extra_test.go +++ b/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) { diff --git a/internal/purchase/execution.go b/internal/purchase/execution.go index fe0dd2ea1..fd1c7e84b 100644 --- a/internal/purchase/execution.go +++ b/internal/purchase/execution.go @@ -2,6 +2,7 @@ package purchase import ( "context" + "errors" "fmt" "strconv" "strings" @@ -289,34 +290,57 @@ func (e *partialPurchaseError) Error() string { } // resolveAccountProvider returns a *ProviderConfig with a pre-authenticated provider -// for the given account. Returns an error if credential resolution fails — callers +// for the given account. Returns an error if credential resolution fails -- callers // must NOT fall back to ambient credentials on error. func (m *Manager) resolveAccountProvider(ctx context.Context, account config.CloudAccount) (*provider.ProviderConfig, error) { + t0 := time.Now() + logging.Infof("purchase[resolveAccountProvider]: resolving credentials for provider=%s account=%s", + account.Provider, account.ID) + var cfg *provider.ProviderConfig + var err error switch account.Provider { case "aws": - return m.resolveAWSProvider(ctx, account) + cfg, err = m.resolveAWSProvider(ctx, account) case "azure": - return m.resolveAzureProvider(ctx, account) + cfg, err = m.resolveAzureProvider(ctx, account) case "gcp": - return m.resolveGCPProvider(ctx, account) + cfg, err = m.resolveGCPProvider(ctx, account) default: return nil, fmt.Errorf("credentials: unknown cloud provider %q for account %s", account.Provider, account.ID) } + if err != nil { + logging.Errorf("purchase[resolveAccountProvider]: credential resolution failed for provider=%s account=%s after %s: %v", + account.Provider, account.ID, time.Since(t0), err) + return nil, err + } + logging.Infof("purchase[resolveAccountProvider]: credentials resolved for provider=%s account=%s in %s", + account.Provider, account.ID, time.Since(t0)) + return cfg, nil } func (m *Manager) resolveAWSProvider(ctx context.Context, account config.CloudAccount) (*provider.ProviderConfig, error) { + t0 := time.Now() + logging.Infof("purchase[resolveAWSProvider]: resolving AWS credentials for account=%s authMode=%s", + account.ID, account.AWSAuthMode) if account.AWSAuthMode != "access_keys" && m.assumeRoleSTS == nil { return nil, fmt.Errorf("credentials: STS client not configured for non-access_keys mode (account %s)", account.ID) } awsCreds, err := credentials.ResolveAWSCredentialProviderWithOpts(ctx, &account, m.credStore, m.assumeRoleSTS, credentials.AWSResolveOptions{AmbientProvider: m.ambientAWSCreds}) if err != nil { + logging.Errorf("purchase[resolveAWSProvider]: failed for account=%s after %s: %v", + account.ID, time.Since(t0), err) return nil, fmt.Errorf("credentials: resolve AWS for account %s (%s): %w", account.ID, account.Name, err) } + logging.Infof("purchase[resolveAWSProvider]: AWS credentials resolved for account=%s in %s", + account.ID, time.Since(t0)) return &provider.ProviderConfig{Name: "aws", AWSCredentialsProvider: awsCreds}, nil } func (m *Manager) resolveAzureProvider(ctx context.Context, account config.CloudAccount) (*provider.ProviderConfig, error) { + t0 := time.Now() + logging.Infof("purchase[resolveAzureProvider]: resolving Azure credentials for account=%s authMode=%s", + account.ID, account.AzureAuthMode) if account.AzureAuthMode != "managed_identity" && m.credStore == nil { return nil, fmt.Errorf("credentials: credential store required for non-managed_identity Azure account %s", account.ID) } @@ -325,17 +349,26 @@ func (m *Manager) resolveAzureProvider(ctx context.Context, account config.Cloud IssuerURL: m.oidcIssuerURL, }) if err != nil { + logging.Errorf("purchase[resolveAzureProvider]: token credential resolution failed for account=%s after %s: %v", + account.ID, time.Since(t0), err) return nil, fmt.Errorf("credentials: resolve Azure for account %s (%s): %w", account.ID, account.Name, err) } azProv, err := azureprovider.NewAzureProvider(&provider.ProviderConfig{Profile: account.AzureSubscriptionID}) if err != nil { + logging.Errorf("purchase[resolveAzureProvider]: Azure provider construction failed for account=%s after %s: %v", + account.ID, time.Since(t0), err) return nil, fmt.Errorf("credentials: create Azure provider for account %s (%s): %w", account.ID, account.Name, err) } azProv.SetCredential(azCred) + logging.Infof("purchase[resolveAzureProvider]: Azure credentials resolved for account=%s in %s", + account.ID, time.Since(t0)) return &provider.ProviderConfig{ProviderOverride: azProv}, nil } func (m *Manager) resolveGCPProvider(ctx context.Context, account config.CloudAccount) (*provider.ProviderConfig, error) { + t0 := time.Now() + logging.Infof("purchase[resolveGCPProvider]: resolving GCP credentials for account=%s authMode=%s", + account.ID, account.GCPAuthMode) if account.GCPAuthMode != "application_default" && m.credStore == nil { return nil, fmt.Errorf("credentials: credential store required for non-ADC GCP account %s", account.ID) } @@ -344,13 +377,19 @@ func (m *Manager) resolveGCPProvider(ctx context.Context, account config.CloudAc IssuerURL: m.oidcIssuerURL, }) if err != nil { + logging.Errorf("purchase[resolveGCPProvider]: token source resolution failed for account=%s after %s: %v", + account.ID, time.Since(t0), err) return nil, fmt.Errorf("credentials: resolve GCP for account %s (%s): %w", account.ID, account.Name, err) } if gcpTS == nil { - // ADC mode: no explicit token source — use ambient credentials + // ADC mode: no explicit token source -- use ambient credentials. + logging.Infof("purchase[resolveGCPProvider]: GCP ADC mode for account=%s (ambient credentials) in %s", + account.ID, time.Since(t0)) return nil, nil } gcpProv := gcpprovider.NewProviderWithCredentials(ctx, account.GCPProjectID, gcpTS) + logging.Infof("purchase[resolveGCPProvider]: GCP credentials resolved for account=%s in %s", + account.ID, time.Since(t0)) return &provider.ProviderConfig{ProviderOverride: gcpProv}, nil } @@ -646,6 +685,24 @@ func (m *Manager) buildPurchaseConfirmationData(exec *config.PurchaseExecution, return data } +// logRecCtxErr emits a diagnostic log line when a per-recommendation context has +// been cancelled or timed out. It distinguishes DeadlineExceeded (the 30s per-rec +// budget fired) from Canceled (a parent context stopped the execution) so that +// CloudWatch filters can tell the two apart without parsing error strings. +// It is a no-op when recCtxErr is nil. +func logRecCtxErr(executionID, recTuple string, elapsed time.Duration, recCtxErr error) { + if recCtxErr == nil { + return + } + if errors.Is(recCtxErr, context.DeadlineExceeded) { + logging.Errorf("purchase[%s]: per-rec deadline exceeded for %s (elapsed=%s)", + executionID, recTuple, elapsed) + } else if errors.Is(recCtxErr, context.Canceled) { + logging.Errorf("purchase[%s]: recommendation context canceled for %s (elapsed=%s)", + executionID, recTuple, elapsed) + } +} + // executeSinglePurchase executes a single purchase using the appropriate provider. // provCfg carries optional per-account credentials; pass nil to use ambient credentials. // opts carries execution-level metadata (the source surface) that providers stamp @@ -653,7 +710,7 @@ func (m *Manager) buildPurchaseConfirmationData(exec *config.PurchaseExecution, func (m *Manager) executeSinglePurchase(ctx context.Context, rec config.RecommendationRecord, provCfg *provider.ProviderConfig, opts common.PurchaseOptions) (common.PurchaseResult, error) { // Per-purchase Info logs tagged with the owning execution ID so a // CloudWatch filter on the execution UUID surfaces every step of the - // purchase attempt — provider construction, service-client lookup, + // purchase attempt -- provider construction, service-client lookup, // details decode, the cloud SDK call, and the result. Issue #667 // surfaced that the prior flow had ZERO observable signal between the // approve handler and the final aggregated error toast; a timed-out @@ -661,9 +718,19 @@ func (m *Manager) executeSinglePurchase(ctx context.Context, rec config.Recommen logging.Infof("purchase[%s]: starting rec %s/%s/%s/%s (count=%d term=%dyr payment=%s)", opts.ExecutionID, rec.Provider, rec.Service, rec.Region, rec.ResourceType, rec.Count, rec.Term, rec.Payment) + // Cap this individual rec at 30s so one hung rec (SDK retry storm, STS + // hang, pagination hang) cannot exhaust the Lambda budget and starve the + // other recs running in parallel in the same execution. 30s matches the + // purchasecfg hard limits (2 retries * 15s HTTP timeout) from issue #683. + // The parent ctx governs the overall Lambda budget; this per-rec deadline + // is always the shorter of the two. + recTuple := fmt.Sprintf("%s/%s/%s/%s", rec.Provider, rec.Service, rec.Region, rec.ResourceType) + recCtx, recCancel := context.WithTimeout(ctx, 30*time.Second) + defer recCancel() + // Create the provider t0 := time.Now() - cloudProvider, err := m.providerFactory.CreateAndValidateProvider(ctx, rec.Provider, provCfg) + cloudProvider, err := m.providerFactory.CreateAndValidateProvider(recCtx, rec.Provider, provCfg) if err != nil { logging.Errorf("purchase[%s]: provider construction failed for %s after %s: %v", opts.ExecutionID, rec.Provider, time.Since(t0), err) @@ -676,7 +743,7 @@ func (m *Manager) executeSinglePurchase(ctx context.Context, rec config.Recommen // Get the service client for this region t0 = time.Now() - serviceClient, err := cloudProvider.GetServiceClient(ctx, serviceType, rec.Region) + serviceClient, err := cloudProvider.GetServiceClient(recCtx, serviceType, rec.Region) if err != nil { logging.Errorf("purchase[%s]: service client lookup failed for %s/%s in %s after %s: %v", opts.ExecutionID, rec.Provider, serviceType, rec.Region, time.Since(t0), err) @@ -737,9 +804,10 @@ func (m *Manager) executeSinglePurchase(ctx context.Context, rec config.Recommen // (which the AWS SDK retries up to 3× × 30s by default) versus // something earlier in the flow — issue #667. tCall := time.Now() - result, err := serviceClient.PurchaseCommitment(ctx, recommendation, opts) + result, err := serviceClient.PurchaseCommitment(recCtx, recommendation, opts) elapsed := time.Since(tCall) if err != nil { + logRecCtxErr(opts.ExecutionID, recTuple, elapsed, recCtx.Err()) logging.Errorf("purchase[%s]: %s/%s/%s/%s PurchaseCommitment failed after %s: %v", opts.ExecutionID, rec.Provider, rec.Service, rec.Region, rec.ResourceType, elapsed, err) return result, fmt.Errorf("purchase failed: %w", err) diff --git a/internal/purchase/execution_test.go b/internal/purchase/execution_test.go index 20a0adbf3..46d777bb5 100644 --- a/internal/purchase/execution_test.go +++ b/internal/purchase/execution_test.go @@ -17,6 +17,22 @@ import ( "github.com/stretchr/testify/require" ) +// hasPerRecDeadline returns a matcher that asserts the ctx carries a deadline +// whose remaining time is positive and within max. Used by tests that need to +// lock down the per-rec context.WithTimeout(ctx, max) contract introduced for +// issue #683: a bare _, ok := c.Deadline(); return ok matcher would pass even +// if executeSinglePurchase silently fell back to the parent's longer deadline. +func hasPerRecDeadline(max time.Duration) func(context.Context) bool { + return func(c context.Context) bool { + deadline, ok := c.Deadline() + if !ok { + return false + } + remaining := time.Until(deadline) + return remaining > 0 && remaining <= max + } +} + func TestManager_ExecutePurchase(t *testing.T) { ctx := context.Background() mockStore := new(MockConfigStore) @@ -67,9 +83,9 @@ func TestManager_ExecutePurchase(t *testing.T) { }, nil) // Mock provider factory to return a mock provider - mockFactory.On("CreateAndValidateProvider", ctx, "aws", mock.Anything).Return(mockProviderInst, nil) - mockProviderInst.On("GetServiceClient", ctx, common.ServiceEC2, "us-east-1").Return(mockServiceClient, nil) - mockServiceClient.On("PurchaseCommitment", ctx, mock.AnythingOfType("common.Recommendation"), mock.AnythingOfType("common.PurchaseOptions")).Return(common.PurchaseResult{ + mockFactory.On("CreateAndValidateProvider", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), "aws", mock.Anything).Return(mockProviderInst, nil) + mockProviderInst.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-12345", }, nil) @@ -127,11 +143,11 @@ func TestManager_ExecutePurchase_WebSourcePropagates(t *testing.T) { mockSTS.On("GetCallerIdentity", ctx, mock.AnythingOfType("*sts.GetCallerIdentityInput")).Return(&sts.GetCallerIdentityOutput{ Account: aws.String("123456789012"), }, nil) - mockFactory.On("CreateAndValidateProvider", ctx, "aws", mock.Anything).Return(mockProviderInst, nil) - mockProviderInst.On("GetServiceClient", ctx, common.ServiceEC2, "us-east-1").Return(mockServiceClient, nil) + mockFactory.On("CreateAndValidateProvider", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), "aws", mock.Anything).Return(mockProviderInst, nil) + mockProviderInst.On("GetServiceClient", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), common.ServiceEC2, "us-east-1").Return(mockServiceClient, nil) // The deterministic idempotency token (issue #636) is derived per-rec from // the execution ID and the rec's index, so the web path now also carries it. - mockServiceClient.On("PurchaseCommitment", ctx, + mockServiceClient.On("PurchaseCommitment", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), mock.AnythingOfType("common.Recommendation"), common.PurchaseOptions{ Source: common.PurchaseSourceWeb, @@ -183,11 +199,11 @@ func TestManager_ExecutePurchase_InvalidSourceFallsBackUntagged(t *testing.T) { mockSTS.On("GetCallerIdentity", ctx, mock.AnythingOfType("*sts.GetCallerIdentityInput")).Return(&sts.GetCallerIdentityOutput{ Account: aws.String("123456789012"), }, nil) - mockFactory.On("CreateAndValidateProvider", ctx, "aws", mock.Anything).Return(mockProviderInst, nil) - mockProviderInst.On("GetServiceClient", ctx, common.ServiceEC2, "us-east-1").Return(mockServiceClient, nil) + mockFactory.On("CreateAndValidateProvider", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), "aws", mock.Anything).Return(mockProviderInst, nil) + mockProviderInst.On("GetServiceClient", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), common.ServiceEC2, "us-east-1").Return(mockServiceClient, nil) // Expect EMPTY source, not "cudly-evil" — NormalizeSource must have wiped it. // The idempotency token (issue #636) is still derived regardless of source. - mockServiceClient.On("PurchaseCommitment", ctx, + mockServiceClient.On("PurchaseCommitment", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), mock.AnythingOfType("common.Recommendation"), common.PurchaseOptions{ Source: "", @@ -528,9 +544,9 @@ func TestManager_ExecutePurchase_MultiAccount(t *testing.T) { mockStore.On("SavePurchaseHistory", ctx, mock.AnythingOfType("*config.PurchaseHistoryRecord")).Return(nil).Times(2) mockEmail.On("SendPurchaseConfirmation", ctx, mock.AnythingOfType("email.NotificationData")).Return(nil).Times(2) - 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(common.PurchaseResult{ + mockFactory.On("CreateAndValidateProvider", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), "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-99999", }, nil) @@ -756,9 +772,9 @@ func TestExecuteMultiAccount_PartialFailure_IsolatesAccounts(t *testing.T) { // Only account-V reaches the provider; account-I fails at credential resolution. // Use .Once() so testify fails if the factory is called for account-I as well. - mockFactory.On("CreateAndValidateProvider", ctx, "aws", mock.Anything).Return(mockProviderInst, nil).Once() - mockProviderInst.On("GetServiceClient", ctx, common.ServiceEC2, "us-east-1").Return(mockServiceClient, nil).Once() - mockServiceClient.On("PurchaseCommitment", ctx, + mockFactory.On("CreateAndValidateProvider", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), "aws", mock.Anything).Return(mockProviderInst, nil).Once() + mockProviderInst.On("GetServiceClient", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), common.ServiceEC2, "us-east-1").Return(mockServiceClient, nil).Once() + mockServiceClient.On("PurchaseCommitment", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), mock.AnythingOfType("common.Recommendation"), mock.AnythingOfType("common.PurchaseOptions"), ).Return(common.PurchaseResult{Success: true, CommitmentID: commitmentV}, nil).Once() @@ -921,13 +937,13 @@ func TestExecuteMultiAccount_RunsAccountsInParallel(t *testing.T) { return nil } - mockFactory.On("CreateAndValidateProvider", ctx, "aws", mock.Anything).Return(mockProviderInst, nil).Twice() - mockProviderInst.On("GetServiceClient", ctx, common.ServiceEC2, "us-east-1").Return(mockServiceClient, nil).Twice() + mockFactory.On("CreateAndValidateProvider", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), "aws", mock.Anything).Return(mockProviderInst, nil).Twice() + mockProviderInst.On("GetServiceClient", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), common.ServiceEC2, "us-east-1").Return(mockServiceClient, nil).Twice() // Each PurchaseCommitment call blocks for perCallDelay. Under serial // execution the total elapsed time would exceed serialBoundary; under // errgroup-style parallelism it stays close to perCallDelay. - mockServiceClient.On("PurchaseCommitment", ctx, + mockServiceClient.On("PurchaseCommitment", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), mock.AnythingOfType("common.Recommendation"), mock.AnythingOfType("common.PurchaseOptions"), ).Return(common.PurchaseResult{Success: true, CommitmentID: "ri-parallel"}, nil). @@ -1039,7 +1055,7 @@ func TestExecutePurchase_SingleAccount_AzureUsesResolvedCreds(t *testing.T) { // The core assertion: factory must receive a non-nil provCfg. // Before the fix, nil was passed and Azure SDK fell back to DefaultAzureCredential. // After the fix, resolveAzureProvider populates ProviderOverride on the config. - mockFactory.On("CreateAndValidateProvider", ctx, "azure", + mockFactory.On("CreateAndValidateProvider", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), "azure", mock.MatchedBy(func(cfg *provider.ProviderConfig) bool { return cfg != nil && cfg.ProviderOverride != nil }), @@ -1049,8 +1065,8 @@ func TestExecutePurchase_SingleAccount_AzureUsesResolvedCreds(t *testing.T) { // mapServiceType returned. The mock previously expected ServiceEC2 and // silently encoded the production bug because mocks return success // regardless of the ServiceType passed in. - mockProviderInst.On("GetServiceClient", ctx, common.ServiceCompute, "eastus").Return(mockServiceClient, nil) - mockServiceClient.On("PurchaseCommitment", ctx, + mockProviderInst.On("GetServiceClient", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), common.ServiceCompute, "eastus").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: "azure-res-1"}, nil) @@ -1168,15 +1184,15 @@ func TestExecutePurchase_AzureCanonicalServiceTypes(t *testing.T) { Account: aws.String("123456789012"), }, nil) - mockFactory.On("CreateAndValidateProvider", ctx, "azure", + mockFactory.On("CreateAndValidateProvider", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), "azure", mock.MatchedBy(func(cfg *provider.ProviderConfig) bool { return cfg != nil && cfg.ProviderOverride != nil }), ).Return(mockProviderInst, nil) // The core assertion: GetServiceClient must be invoked with // the canonical ServiceType — not an AWS-legacy constant. - mockProviderInst.On("GetServiceClient", ctx, tc.expectedType, "eastus").Return(mockServiceClient, nil) - mockServiceClient.On("PurchaseCommitment", ctx, + mockProviderInst.On("GetServiceClient", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), tc.expectedType, "eastus").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: "azure-res-" + tc.name}, nil) @@ -1391,9 +1407,9 @@ func TestManager_ExecuteAndFinalize_HistorySaveFailure_StaysVisible(t *testing.T mockSTS.On("GetCallerIdentity", ctx, mock.AnythingOfType("*sts.GetCallerIdentityInput")).Return(&sts.GetCallerIdentityOutput{ Account: aws.String("123456789012"), }, nil) - mockFactory.On("CreateAndValidateProvider", ctx, "aws", mock.Anything).Return(mockProviderInst, nil) - mockProviderInst.On("GetServiceClient", ctx, common.ServiceEC2, "us-east-1").Return(mockServiceClient, nil) - mockServiceClient.On("PurchaseCommitment", ctx, mock.AnythingOfType("common.Recommendation"), mock.AnythingOfType("common.PurchaseOptions")).Return(common.PurchaseResult{ + mockFactory.On("CreateAndValidateProvider", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), "aws", mock.Anything).Return(mockProviderInst, nil) + mockProviderInst.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-auditgap", }, nil) @@ -1465,14 +1481,14 @@ func TestManager_ExecuteAndFinalize_SingleAccount_PartialSuccess(t *testing.T) { Account: aws.String("123456789012"), }, nil).Maybe() - mockFactory.On("CreateAndValidateProvider", ctx, "aws", mock.Anything).Return(mockProviderInst, nil) - mockProviderInst.On("GetServiceClient", ctx, common.ServiceEC2, "us-east-1").Return(mockServiceClient, nil) + mockFactory.On("CreateAndValidateProvider", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), "aws", mock.Anything).Return(mockProviderInst, nil) + mockProviderInst.On("GetServiceClient", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), common.ServiceEC2, "us-east-1").Return(mockServiceClient, nil) // m5.large succeeds; c5.xlarge fails. - mockServiceClient.On("PurchaseCommitment", ctx, + mockServiceClient.On("PurchaseCommitment", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), mock.MatchedBy(func(r common.Recommendation) bool { return r.ResourceType == "m5.large" }), mock.AnythingOfType("common.PurchaseOptions"), ).Return(common.PurchaseResult{Success: true, CommitmentID: "ri-ok"}, nil).Once() - mockServiceClient.On("PurchaseCommitment", ctx, + mockServiceClient.On("PurchaseCommitment", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), mock.MatchedBy(func(r common.Recommendation) bool { return r.ResourceType == "c5.xlarge" }), mock.AnythingOfType("common.PurchaseOptions"), ).Return(common.PurchaseResult{}, errors.New("offering not available")).Once() @@ -1547,13 +1563,13 @@ func TestExecuteForAccount_PartialSuccess(t *testing.T) { }, } - mockFactory.On("CreateAndValidateProvider", ctx, "aws", mock.Anything).Return(mockProviderInst, nil) - mockProviderInst.On("GetServiceClient", ctx, common.ServiceEC2, "us-east-1").Return(mockServiceClient, nil) - mockServiceClient.On("PurchaseCommitment", ctx, + mockFactory.On("CreateAndValidateProvider", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), "aws", mock.Anything).Return(mockProviderInst, nil) + mockProviderInst.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.MatchedBy(func(r common.Recommendation) bool { return r.ResourceType == "m5.large" }), mock.AnythingOfType("common.PurchaseOptions"), ).Return(common.PurchaseResult{Success: true, CommitmentID: "ri-ok"}, nil).Once() - mockServiceClient.On("PurchaseCommitment", ctx, + mockServiceClient.On("PurchaseCommitment", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), mock.MatchedBy(func(r common.Recommendation) bool { return r.ResourceType == "c5.xlarge" }), mock.AnythingOfType("common.PurchaseOptions"), ).Return(common.PurchaseResult{}, errors.New("offering not available")).Once() @@ -1685,9 +1701,9 @@ func TestManager_ExecutePurchase_SingleAccount_StampsTargetAccount(t *testing.T) mockSTS.On("GetCallerIdentity", ctx, mock.AnythingOfType("*sts.GetCallerIdentityInput")). Return(&sts.GetCallerIdentityOutput{Account: aws.String(hostAccount)}, nil).Maybe() - mockFactory.On("CreateAndValidateProvider", ctx, tc.provider, mock.Anything).Return(mockProviderInst, nil) - mockProviderInst.On("GetServiceClient", ctx, tc.expectedType, tc.region).Return(mockServiceClient, nil) - mockServiceClient.On("PurchaseCommitment", ctx, + mockFactory.On("CreateAndValidateProvider", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), tc.provider, mock.Anything).Return(mockProviderInst, nil) + mockProviderInst.On("GetServiceClient", mock.MatchedBy(hasPerRecDeadline(30*time.Second)), tc.expectedType, tc.region).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: "commit-1"}, nil) diff --git a/internal/purchase/manager_test.go b/internal/purchase/manager_test.go index 35977fb48..c70fd37d8 100644 --- a/internal/purchase/manager_test.go +++ b/internal/purchase/manager_test.go @@ -220,9 +220,9 @@ func TestManager_ProcessScheduledPurchases_DuePurchase(t *testing.T) { mockProvider := new(MockProvider) mockServiceClient := new(MockServiceClient) - mockFactory.On("CreateAndValidateProvider", ctx, "", 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(common.PurchaseResult{ + mockFactory.On("CreateAndValidateProvider", mock.Anything, "", 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-12345", }, nil) diff --git a/providers/aws/internal/purchasecfg/config.go b/providers/aws/internal/purchasecfg/config.go new file mode 100644 index 000000000..3b623c726 --- /dev/null +++ b/providers/aws/internal/purchasecfg/config.go @@ -0,0 +1,57 @@ +// Package purchasecfg provides a tightened AWS SDK config for purchase-path +// clients. +// +// Background: the AWS SDK v2 default retry policy (3 attempts, up to 30s per +// request) can consume up to ~90s wall-clock time when an API is slow. That +// budget exceeds the Lambda function timeout (previously 60s, now bumped to +// 300s). Purchase-path calls do not benefit from many retries because the +// errors that triggered this fix (context deadline exceeded) are caused by the +// Lambda budget itself running out -- retrying inside the same Lambda makes +// the situation worse, not better. +// +// Recommendation-collection clients deliberately keep the SDK default config; +// they call Cost Explorer and can tolerate more retries legitimately. +package purchasecfg + +import ( + "net/http" + "time" + + "github.com/aws/aws-sdk-go-v2/aws" +) + +const ( + // MaxAttempts is the maximum number of SDK-level retries for purchase-path + // API calls. 2 total attempts (1 initial + 1 retry) means a worst-case + // wall-clock of 2 * HTTPTimeout = 30s, well within the 300s Lambda budget. + MaxAttempts = 2 + + // HTTPTimeout is the per-request HTTP timeout for purchase-path API calls. + // A single transient slow AWS API response will time out at 15s, allowing + // the one retry to complete within 30s total. + HTTPTimeout = 15 * time.Second +) + +// NewConfig returns a copy of base with purchase-path-appropriate retry and +// HTTP timeout settings applied. The original base config is not modified. +// +// Applies: +// - RetryMaxAttempts = 2 (overrides the SDK default of 3) +// - HTTPClient with Timeout = 15s (overrides the SDK default of no timeout) +// +// If base.HTTPClient is an *http.Client, it is cloned and its Timeout is set +// to HTTPTimeout, preserving any custom Transport, Jar, or CheckRedirect the +// caller installed. If base.HTTPClient is nil or a non-*http.Client +// implementation, a fresh *http.Client{Timeout: HTTPTimeout} is used instead. +func NewConfig(base aws.Config) aws.Config { + cfg := base.Copy() + cfg.RetryMaxAttempts = MaxAttempts + if hc, ok := base.HTTPClient.(*http.Client); ok && hc != nil { + clone := *hc // shallow copy preserves Transport, Jar, CheckRedirect + clone.Timeout = HTTPTimeout + cfg.HTTPClient = &clone + } else { + cfg.HTTPClient = &http.Client{Timeout: HTTPTimeout} + } + return cfg +} diff --git a/providers/aws/internal/purchasecfg/config_test.go b/providers/aws/internal/purchasecfg/config_test.go new file mode 100644 index 000000000..f948b0ee6 --- /dev/null +++ b/providers/aws/internal/purchasecfg/config_test.go @@ -0,0 +1,98 @@ +package purchasecfg + +import ( + "net/http" + "testing" + "time" + + "github.com/aws/aws-sdk-go-v2/aws" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestNewConfig_SetsRetryMaxAttempts(t *testing.T) { + t.Helper() + base := aws.Config{ + Region: "us-east-1", + RetryMaxAttempts: 0, // SDK default (will be resolved to 3 at runtime) + } + + cfg := NewConfig(base) + + assert.Equal(t, MaxAttempts, cfg.RetryMaxAttempts, + "purchase-path config must cap retries at %d to prevent Lambda budget exhaustion", MaxAttempts) +} + +func TestNewConfig_SetsHTTPTimeout(t *testing.T) { + t.Helper() + base := aws.Config{Region: "us-east-1"} + + cfg := NewConfig(base) + + require.NotNil(t, cfg.HTTPClient, "HTTPClient must not be nil after NewConfig") + httpClient, ok := cfg.HTTPClient.(*http.Client) + require.True(t, ok, "HTTPClient must be *http.Client") + assert.Equal(t, HTTPTimeout, httpClient.Timeout, + "per-request HTTP timeout must be %s to bound individual AWS API calls", HTTPTimeout) +} + +func TestNewConfig_DoesNotMutateBase(t *testing.T) { + t.Helper() + base := aws.Config{ + Region: "eu-west-1", + RetryMaxAttempts: 5, + HTTPClient: &http.Client{Timeout: 60 * time.Second}, + } + + _ = NewConfig(base) + + assert.Equal(t, 5, base.RetryMaxAttempts, "NewConfig must not modify the original config's RetryMaxAttempts") + httpClient, ok := base.HTTPClient.(*http.Client) + require.True(t, ok) + assert.Equal(t, 60*time.Second, httpClient.Timeout, "NewConfig must not modify the original config's HTTPClient") +} + +// TestNewConfig_PreservesCustomTransport verifies that a non-nil *http.Client +// supplied in the base config has its Transport kept intact in the result. +// NewConfig must not silently drop custom transports, TLS settings, or +// instrumentation hooks by replacing the whole client unconditionally. +func TestNewConfig_PreservesCustomTransport(t *testing.T) { + t.Helper() + customTransport := &http.Transport{MaxIdleConns: 42} + base := aws.Config{ + Region: "us-east-1", + HTTPClient: &http.Client{Transport: customTransport, Timeout: 60 * time.Second}, + } + + cfg := NewConfig(base) + + require.NotNil(t, cfg.HTTPClient, "HTTPClient must not be nil after NewConfig") + httpClient, ok := cfg.HTTPClient.(*http.Client) + require.True(t, ok, "HTTPClient must be *http.Client") + assert.Equal(t, HTTPTimeout, httpClient.Timeout, + "NewConfig must override the Timeout to HTTPTimeout even when cloning a caller-provided client") + assert.Same(t, customTransport, httpClient.Transport, + "NewConfig must preserve the caller-provided Transport on the cloned client") +} + +func TestNewConfig_PreservesRegion(t *testing.T) { + t.Helper() + base := aws.Config{Region: "ap-southeast-1"} + + cfg := NewConfig(base) + + assert.Equal(t, "ap-southeast-1", cfg.Region, "NewConfig must preserve the original region") +} + +// TestNewConfig_WallClockBound documents the design invariant: with MaxAttempts=2 +// and HTTPTimeout=15s, the worst-case total for purchase-path API calls is +// 2*15s=30s, well under the 300s Lambda function timeout. +func TestNewConfig_WallClockBound(t *testing.T) { + t.Helper() + worstCaseWallClock := time.Duration(MaxAttempts) * HTTPTimeout + lambdaTimeout := 300 * time.Second + + assert.Less(t, worstCaseWallClock, lambdaTimeout, + "worst-case purchase SDK wall clock (%s) must be less than Lambda timeout (%s)", + worstCaseWallClock, lambdaTimeout) +} diff --git a/providers/aws/provider.go b/providers/aws/provider.go index d5af8bc66..c2b2d5a13 100644 --- a/providers/aws/provider.go +++ b/providers/aws/provider.go @@ -6,6 +6,7 @@ import ( "errors" "fmt" "sync" + "time" "github.com/aws/aws-sdk-go-v2/aws" "github.com/aws/aws-sdk-go-v2/config" @@ -233,11 +234,19 @@ func (p *AWSProvider) ValidateCredentials(ctx context.Context) error { stsClient = sts.NewFromConfig(p.cfg) } - _, err := stsClient.GetCallerIdentity(ctx, &sts.GetCallerIdentityInput{}) + t0 := time.Now() + logging.Infof("purchase[STS]: GetCallerIdentity starting (profile=%s region=%s)", + p.profile, p.region) + result, err := stsClient.GetCallerIdentity(ctx, &sts.GetCallerIdentityInput{}) if err != nil { + logging.Errorf("purchase[STS]: GetCallerIdentity failed after %s: %v", time.Since(t0), err) return fmt.Errorf("AWS credentials validation failed: %w", err) } - + account := "" + if result.Account != nil { + account = *result.Account + } + logging.Infof("purchase[STS]: GetCallerIdentity returned in %s (account=%s)", time.Since(t0), account) return nil } diff --git a/providers/aws/services/ec2/client.go b/providers/aws/services/ec2/client.go index 61768544a..74048b796 100644 --- a/providers/aws/services/ec2/client.go +++ b/providers/aws/services/ec2/client.go @@ -16,6 +16,7 @@ import ( "github.com/LeanerCloud/CUDly/pkg/common" "github.com/LeanerCloud/CUDly/pkg/exchange" "github.com/LeanerCloud/CUDly/pkg/retry" + "github.com/LeanerCloud/CUDly/providers/aws/internal/purchasecfg" ) // EC2API defines the interface for EC2 operations (enables mocking) @@ -35,10 +36,13 @@ type Client struct { region string } -// NewClient creates a new EC2 client +// NewClient creates a new EC2 client with purchase-path retry/timeout settings. +// The tightened config (2 retries, 15s HTTP timeout) bounds worst-case wall +// clock to 30s, preventing Lambda budget exhaustion on transient API slowness. func NewClient(cfg aws.Config) *Client { + pcfg := purchasecfg.NewConfig(cfg) return &Client{ - client: ec2.NewFromConfig(cfg), + client: ec2.NewFromConfig(pcfg), region: cfg.Region, } } @@ -138,7 +142,7 @@ func (c *Client) PurchaseCommitment(ctx context.Context, rec common.Recommendati } // Find the offering ID - offeringID, err := c.findOfferingID(ctx, rec) + offeringID, err := c.findOfferingID(ctx, rec, opts.ExecutionID) if err != nil { result.Error = fmt.Errorf("failed to find offering: %w", err) return result, result.Error @@ -389,6 +393,24 @@ func describeInputFromQuery(q ec2OfferingQuery, nextToken *string) *ec2.Describe } } +// buildEC2QueryFromRec extracts ComputeDetails from rec, converts the payment +// option, and assembles the ec2OfferingQuery used by findOfferingID. +// +// Pulled out of findOfferingID to keep that function under the cyclomatic limit. +func (c *Client) buildEC2QueryFromRec(rec common.Recommendation) (ec2OfferingQuery, error) { + details, ok := rec.Details.(*common.ComputeDetails) + if !ok || details == nil { + return ec2OfferingQuery{}, fmt.Errorf("invalid service details for EC2") + } + wantOfferingType, err := convertEC2PaymentOption(rec.PaymentOption) + if err != nil { + return ec2OfferingQuery{}, err + } + q := buildEC2OfferingQuery(rec, details, c.getDurationValue(rec.Term)) + q.wantOfferingType = wantOfferingType + return q, nil +} + // findOfferingID finds the appropriate EC2 Reserved Instance offering ID. // // The input is built from typed first-class fields on @@ -399,17 +421,22 @@ func describeInputFromQuery(q ec2OfferingQuery, nextToken *string) *ec2.Describe // Filter[]-heavy shape caused AWS to return empty pages with NextToken on // sparse offering sets, walking until the Lambda budget expired (issue #688). // Only scope has no typed equivalent on the input struct, so it stays in Filters[]. -func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation) (string, error) { - details, ok := rec.Details.(*common.ComputeDetails) - if !ok || details == nil { - return "", fmt.Errorf("invalid service details for EC2") - } - wantOfferingType, err := convertEC2PaymentOption(rec.PaymentOption) +// +// execID is the purchase execution UUID for log correlation; pass "" when +// calling outside of a purchase flow (ValidateOffering, GetOfferingDetails). +func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation, execID string) (string, error) { + q, err := c.buildEC2QueryFromRec(rec) if err != nil { return "", err } - q := buildEC2OfferingQuery(rec, details, c.getDurationValue(rec.Term)) - q.wantOfferingType = wantOfferingType + + tag := execID + if tag == "" { + tag = "no-exec" + } + t0 := time.Now() + log.Printf("purchase[%s]: EC2 findOfferingID starting (instance=%s platform=%s tenancy=%s term=%s payment=%s)", + tag, rec.ResourceType, q.productDesc, q.tenancy, rec.Term, rec.PaymentOption) var nextToken *string page := 0 @@ -420,16 +447,20 @@ func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation) page++ if page > maxOfferingPages { return "", fmt.Errorf("pagination cap reached after %d pages for EC2 %s %s %s (issue #688)", - maxOfferingPages, rec.ResourceType, details.Platform, rec.PaymentOption) + maxOfferingPages, rec.ResourceType, q.productDesc, rec.PaymentOption) } pageStart := time.Now() result, err := c.client.DescribeReservedInstancesOfferings(ctx, describeInputFromQuery(q, nextToken)) if err != nil { + log.Printf("purchase[%s]: EC2 findOfferingID page %d failed after %s (total %s): %v", + tag, page, time.Since(pageStart), time.Since(t0), err) return "", fmt.Errorf("failed to describe offerings: %w", err) } - log.Printf("EC2 findOfferingID page %d: %d offerings in %s", - page, len(result.ReservedInstancesOfferings), time.Since(pageStart)) - if id := scanEC2OfferingPage(result.ReservedInstancesOfferings, wantOfferingType); id != "" { + log.Printf("purchase[%s]: EC2 findOfferingID page %d: %d offerings in %s", + tag, page, len(result.ReservedInstancesOfferings), time.Since(pageStart)) + if id := scanEC2OfferingPage(result.ReservedInstancesOfferings, q.wantOfferingType); id != "" { + log.Printf("purchase[%s]: EC2 findOfferingID found match on page %d after %s total", + tag, page, time.Since(t0)) return id, nil } if isLastEC2Page(result.NextToken) { @@ -437,8 +468,10 @@ func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation) } nextToken = result.NextToken } + log.Printf("purchase[%s]: EC2 findOfferingID exhausted %d page(s) in %s -- no match", + tag, page, time.Since(t0)) return "", fmt.Errorf("no offerings found for EC2 %s %s %s after %d page(s) (issue #688)", - rec.ResourceType, details.Platform, rec.PaymentOption, page) + rec.ResourceType, q.productDesc, rec.PaymentOption, page) } // isLastEC2Page reports whether a NextToken indicates the terminal page. @@ -469,13 +502,13 @@ func scanEC2OfferingPage(offerings []types.ReservedInstancesOffering, wantType t // ValidateOffering checks if an offering exists without purchasing func (c *Client) ValidateOffering(ctx context.Context, rec common.Recommendation) error { - _, err := c.findOfferingID(ctx, rec) + _, err := c.findOfferingID(ctx, rec, "") return err } // GetOfferingDetails retrieves offering details func (c *Client) GetOfferingDetails(ctx context.Context, rec common.Recommendation) (*common.OfferingDetails, error) { - offeringID, err := c.findOfferingID(ctx, rec) + offeringID, err := c.findOfferingID(ctx, rec, "") if err != nil { return nil, err } diff --git a/providers/aws/services/ec2/client_test.go b/providers/aws/services/ec2/client_test.go index 408815f0f..e5085a76a 100644 --- a/providers/aws/services/ec2/client_test.go +++ b/providers/aws/services/ec2/client_test.go @@ -583,7 +583,7 @@ func TestFindOfferingID_PaginationCapFires(t *testing.T) { }, nil).Once() } - _, err := client.findOfferingID(context.Background(), rec) + _, err := client.findOfferingID(context.Background(), rec, "") if assert.Error(t, err) { assert.Contains(t, err.Error(), "pagination cap reached") @@ -626,7 +626,7 @@ func TestFindOfferingID_WrongVariantRejected(t *testing.T) { }, }, nil).Once() - _, err := client.findOfferingID(context.Background(), rec) + _, err := client.findOfferingID(context.Background(), rec, "") if assert.Error(t, err) { assert.Contains(t, err.Error(), "no offerings found") @@ -664,7 +664,7 @@ func TestFindOfferingID_HappyPath(t *testing.T) { }, }, nil).Once() - id, err := client.findOfferingID(context.Background(), rec) + id, err := client.findOfferingID(context.Background(), rec, "") assert.NoError(t, err) assert.Equal(t, "offering-ok", id) diff --git a/providers/aws/services/elasticache/client.go b/providers/aws/services/elasticache/client.go index 6736f6899..987e32e96 100644 --- a/providers/aws/services/elasticache/client.go +++ b/providers/aws/services/elasticache/client.go @@ -14,6 +14,7 @@ import ( "github.com/aws/aws-sdk-go-v2/service/elasticache/types" "github.com/LeanerCloud/CUDly/pkg/common" + "github.com/LeanerCloud/CUDly/providers/aws/internal/purchasecfg" "github.com/LeanerCloud/CUDly/providers/aws/internal/tagging" ) @@ -30,10 +31,12 @@ type Client struct { region string } -// NewClient creates a new ElastiCache client +// NewClient creates a new ElastiCache client with purchase-path retry/timeout +// settings. See purchasecfg for rationale. func NewClient(cfg aws.Config) *Client { + pcfg := purchasecfg.NewConfig(cfg) return &Client{ - client: elasticache.NewFromConfig(cfg), + client: elasticache.NewFromConfig(pcfg), region: cfg.Region, } } @@ -120,7 +123,7 @@ func (c *Client) PurchaseCommitment(ctx context.Context, rec common.Recommendati Timestamp: time.Now(), } - offeringID, err := c.findOfferingID(ctx, rec) + offeringID, err := c.findOfferingID(ctx, rec, opts.ExecutionID) if err != nil { result.Error = fmt.Errorf("failed to find offering: %w", err) return result, result.Error @@ -264,8 +267,10 @@ func (c *Client) recoverAlreadyExists(ctx context.Context, token, reservationID // of timing out the Lambda budget (issue #688). const maxOfferingPages = 5 -// findOfferingID finds the appropriate Reserved Cache Node offering ID -func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation) (string, error) { +// findOfferingID finds the appropriate Reserved Cache Node offering ID. +// execID is the purchase execution UUID for log correlation; pass "" when +// calling outside of a purchase flow (ValidateOffering, GetOfferingDetails). +func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation, execID string) (string, error) { details, ok := rec.Details.(*common.CacheDetails) if !ok || details == nil { return "", fmt.Errorf("invalid service details for ElastiCache") @@ -274,14 +279,21 @@ func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation) if err != nil { return "", err } - return c.paginateElastiCacheOfferings(ctx, rec, details, offeringType) + return c.paginateElastiCacheOfferings(ctx, rec, details, offeringType, execID) } // paginateElastiCacheOfferings walks DescribeReservedCacheNodesOfferings pages and returns // the first matching offering ID. It caps at maxOfferingPages to prevent Lambda // timeout exhaustion (issue #688). -func (c *Client) paginateElastiCacheOfferings(ctx context.Context, rec common.Recommendation, details *common.CacheDetails, offeringType string) (string, error) { +func (c *Client) paginateElastiCacheOfferings(ctx context.Context, rec common.Recommendation, details *common.CacheDetails, offeringType, execID string) (string, error) { duration := c.getDurationString(rec.Term) + tag := execID + if tag == "" { + tag = "no-exec" + } + t0 := time.Now() + log.Printf("purchase[%s]: ElastiCache findOfferingID starting (nodeType=%s engine=%s duration=%s payment=%s)", + tag, rec.ResourceType, details.Engine, duration, offeringType) var marker *string page := 0 @@ -305,13 +317,17 @@ func (c *Client) paginateElastiCacheOfferings(ctx context.Context, rec common.Re pageStart := time.Now() result, err := c.client.DescribeReservedCacheNodesOfferings(ctx, input) if err != nil { + log.Printf("purchase[%s]: ElastiCache findOfferingID page %d failed after %s (total %s): %v", + tag, page, time.Since(pageStart), time.Since(t0), err) return "", fmt.Errorf("failed to describe offerings: %w", err) } - log.Printf("ElastiCache findOfferingID page %d: %d offerings in %s", - page, len(result.ReservedCacheNodesOfferings), time.Since(pageStart)) + log.Printf("purchase[%s]: ElastiCache findOfferingID page %d: %d offerings in %s", + tag, page, len(result.ReservedCacheNodesOfferings), time.Since(pageStart)) if id, scanErr := scanElastiCacheOfferingPage(result.ReservedCacheNodesOfferings, rec, offeringType); scanErr != nil { return "", scanErr } else if id != "" { + log.Printf("purchase[%s]: ElastiCache findOfferingID found match on page %d after %s total", + tag, page, time.Since(t0)) return id, nil } if result.Marker == nil || aws.ToString(result.Marker) == "" { @@ -319,6 +335,8 @@ func (c *Client) paginateElastiCacheOfferings(ctx context.Context, rec common.Re } marker = result.Marker } + log.Printf("purchase[%s]: ElastiCache findOfferingID exhausted %d page(s) in %s -- no match", + tag, page, time.Since(t0)) return "", fmt.Errorf("no offerings found for ElastiCache %s %s %s after %d page(s) (issue #688)", rec.ResourceType, details.Engine, rec.PaymentOption, page) } @@ -340,13 +358,13 @@ func scanElastiCacheOfferingPage(offerings []types.ReservedCacheNodesOffering, r // ValidateOffering checks if an offering exists without purchasing func (c *Client) ValidateOffering(ctx context.Context, rec common.Recommendation) error { - _, err := c.findOfferingID(ctx, rec) + _, err := c.findOfferingID(ctx, rec, "") return err } // GetOfferingDetails retrieves offering details func (c *Client) GetOfferingDetails(ctx context.Context, rec common.Recommendation) (*common.OfferingDetails, error) { - offeringID, err := c.findOfferingID(ctx, rec) + offeringID, err := c.findOfferingID(ctx, rec, "") if err != nil { return nil, err } diff --git a/providers/aws/services/elasticache/client_test.go b/providers/aws/services/elasticache/client_test.go index b6e3263c1..69db4d4d9 100644 --- a/providers/aws/services/elasticache/client_test.go +++ b/providers/aws/services/elasticache/client_test.go @@ -608,7 +608,7 @@ func TestFindOfferingID_PaginationCapFires(t *testing.T) { }, nil).Once() } - _, err := client.findOfferingID(context.Background(), rec) + _, err := client.findOfferingID(context.Background(), rec, "") if assert.Error(t, err) { assert.Contains(t, err.Error(), "pagination cap reached") @@ -642,7 +642,7 @@ func TestFindOfferingID_WrongVariantRejected(t *testing.T) { }, }, nil).Once() - _, err := client.findOfferingID(context.Background(), rec) + _, err := client.findOfferingID(context.Background(), rec, "") if assert.Error(t, err) { assert.Contains(t, err.Error(), "payment option") @@ -675,7 +675,7 @@ func TestFindOfferingID_HappyPath(t *testing.T) { }, }, nil).Once() - id, err := client.findOfferingID(context.Background(), rec) + id, err := client.findOfferingID(context.Background(), rec, "") assert.NoError(t, err) assert.Equal(t, "offering-ok", id) diff --git a/providers/aws/services/memorydb/client.go b/providers/aws/services/memorydb/client.go index 3bb451ac9..2e4542fe1 100644 --- a/providers/aws/services/memorydb/client.go +++ b/providers/aws/services/memorydb/client.go @@ -14,6 +14,7 @@ import ( "github.com/aws/aws-sdk-go-v2/service/memorydb/types" "github.com/LeanerCloud/CUDly/pkg/common" + "github.com/LeanerCloud/CUDly/providers/aws/internal/purchasecfg" "github.com/LeanerCloud/CUDly/providers/aws/internal/tagging" ) @@ -30,10 +31,12 @@ type Client struct { region string } -// NewClient creates a new MemoryDB client +// NewClient creates a new MemoryDB client with purchase-path retry/timeout +// settings. See purchasecfg for rationale. func NewClient(cfg aws.Config) *Client { + pcfg := purchasecfg.NewConfig(cfg) return &Client{ - client: memorydb.NewFromConfig(cfg), + client: memorydb.NewFromConfig(pcfg), region: cfg.Region, } } @@ -116,7 +119,7 @@ func (c *Client) PurchaseCommitment(ctx context.Context, rec common.Recommendati Timestamp: time.Now(), } - offeringID, err := c.findOfferingID(ctx, rec) + offeringID, err := c.findOfferingID(ctx, rec, opts.ExecutionID) if err != nil { result.Error = fmt.Errorf("failed to find offering: %w", err) return result, result.Error @@ -276,13 +279,23 @@ func convertMemoryDBPaymentOption(option string) (string, error) { // findOfferingID finds the appropriate Reserved Node offering ID. // All supported narrow filters (NodeType, OfferingType, Duration) are set // directly on the request to minimize the result set (issue #688). -func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation) (string, error) { +// +// execID is the purchase execution UUID for log correlation; pass "" when +// calling outside of a purchase flow (ValidateOffering, GetOfferingDetails). +func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation, execID string) (string, error) { wantOfferingType, err := convertMemoryDBPaymentOption(rec.PaymentOption) if err != nil { return "", err } duration := c.getDurationStringForAPI(rec.Term) + tag := execID + if tag == "" { + tag = "no-exec" + } + t0 := time.Now() + log.Printf("purchase[%s]: MemoryDB findOfferingID starting (nodeType=%s term=%s payment=%s)", + tag, rec.ResourceType, rec.Term, rec.PaymentOption) var nextToken *string page := 0 @@ -308,31 +321,62 @@ func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation) pageStart := time.Now() result, err := c.client.DescribeReservedNodesOfferings(ctx, input) if err != nil { + log.Printf("purchase[%s]: MemoryDB findOfferingID page %d failed after %s (total %s): %v", + tag, page, time.Since(pageStart), time.Since(t0), err) return "", fmt.Errorf("failed to describe offerings: %w", err) } - log.Printf("MemoryDB findOfferingID page %d: %d offerings in %s", - page, len(result.ReservedNodesOfferings), time.Since(pageStart)) - - for _, o := range result.ReservedNodesOfferings { - got := aws.ToString(o.OfferingType) - if got != wantOfferingType { - return "", fmt.Errorf("MemoryDB offering %s has payment option %q, want %q (rec: %s %s) -- API filter mismatch", - aws.ToString(o.ReservedNodesOfferingId), got, wantOfferingType, - rec.ResourceType, rec.PaymentOption) - } - return aws.ToString(o.ReservedNodesOfferingId), nil + log.Printf("purchase[%s]: MemoryDB findOfferingID page %d: %d offerings in %s", + tag, page, len(result.ReservedNodesOfferings), time.Since(pageStart)) + + if id, err := scanMemoryDBOfferingPage(result.ReservedNodesOfferings, wantOfferingType, rec, tag, page, t0); err != nil { + return "", err + } else if id != "" { + return id, nil } - if result.NextToken == nil || aws.ToString(result.NextToken) == "" { + if isLastMemoryDBPage(result.NextToken) { break } nextToken = result.NextToken } + log.Printf("purchase[%s]: MemoryDB findOfferingID exhausted %d page(s) in %s -- no match", + tag, page, time.Since(t0)) return "", fmt.Errorf("no offerings found for MemoryDB %s %s after %d page(s) (issue #688)", rec.ResourceType, rec.PaymentOption, page) } +// scanMemoryDBOfferingPage inspects a single page of DescribeReservedNodesOfferings +// results and returns the first matching offering ID. +// It returns ("", nil) when the page is empty or no offering matched; it returns +// ("", err) on an API filter mismatch; it returns (id, nil) on a successful match. +// +// Pulled out of findOfferingID to keep that function under the cyclomatic limit. +func scanMemoryDBOfferingPage(offerings []types.ReservedNodesOffering, wantOfferingType string, rec common.Recommendation, tag string, page int, t0 time.Time) (string, error) { + for _, o := range offerings { + got := aws.ToString(o.OfferingType) + if got != wantOfferingType { + return "", fmt.Errorf("MemoryDB offering %s has payment option %q, want %q (rec: %s %s) -- API filter mismatch", + aws.ToString(o.ReservedNodesOfferingId), got, wantOfferingType, + rec.ResourceType, rec.PaymentOption) + } + log.Printf("purchase[%s]: MemoryDB findOfferingID found match on page %d after %s total", + tag, page, time.Since(t0)) + return aws.ToString(o.ReservedNodesOfferingId), nil + } + return "", nil +} + +// isLastMemoryDBPage reports whether a NextToken indicates the terminal page. +// The AWS SDK may return either nil or a pointer to an empty string for the +// last page; both must end pagination so the loop does not issue a redundant +// request (and risk a false page-cap error on borderline page counts). +// +// Pulled out of findOfferingID to keep that function under the cyclomatic limit. +func isLastMemoryDBPage(nextToken *string) bool { + return nextToken == nil || aws.ToString(nextToken) == "" +} + // getDurationStringForAPI converts the term string to a duration value accepted // by DescribeReservedNodesOfferings (seconds as a string or "1yr"/"3yr"). // The MemoryDB API accepts both numeric-seconds strings and year strings. @@ -345,13 +389,13 @@ func (c *Client) getDurationStringForAPI(term string) string { // ValidateOffering checks if an offering exists without purchasing func (c *Client) ValidateOffering(ctx context.Context, rec common.Recommendation) error { - _, err := c.findOfferingID(ctx, rec) + _, err := c.findOfferingID(ctx, rec, "") return err } // GetOfferingDetails retrieves offering details func (c *Client) GetOfferingDetails(ctx context.Context, rec common.Recommendation) (*common.OfferingDetails, error) { - offeringID, err := c.findOfferingID(ctx, rec) + offeringID, err := c.findOfferingID(ctx, rec, "") if err != nil { return nil, err } diff --git a/providers/aws/services/memorydb/client_test.go b/providers/aws/services/memorydb/client_test.go index f4f22b0d8..769954e81 100644 --- a/providers/aws/services/memorydb/client_test.go +++ b/providers/aws/services/memorydb/client_test.go @@ -308,7 +308,7 @@ func TestFindOfferingID_PaginationCapFires(t *testing.T) { }, nil).Once() } - _, err := client.findOfferingID(context.Background(), rec) + _, err := client.findOfferingID(context.Background(), rec, "") if assert.Error(t, err) { assert.Contains(t, err.Error(), "pagination cap reached") @@ -345,7 +345,7 @@ func TestFindOfferingID_WrongVariantRejected(t *testing.T) { }, }, nil).Once() - _, err := client.findOfferingID(context.Background(), rec) + _, err := client.findOfferingID(context.Background(), rec, "") if assert.Error(t, err) { assert.Contains(t, err.Error(), "payment option") @@ -378,7 +378,7 @@ func TestFindOfferingID_HappyPath(t *testing.T) { }, }, nil).Once() - id, err := client.findOfferingID(context.Background(), rec) + id, err := client.findOfferingID(context.Background(), rec, "") assert.NoError(t, err) assert.Equal(t, "offering-ok", id) diff --git a/providers/aws/services/opensearch/client.go b/providers/aws/services/opensearch/client.go index f2bf413d0..e4071aedf 100644 --- a/providers/aws/services/opensearch/client.go +++ b/providers/aws/services/opensearch/client.go @@ -16,6 +16,7 @@ import ( "github.com/LeanerCloud/CUDly/pkg/common" "github.com/LeanerCloud/CUDly/pkg/retry" + "github.com/LeanerCloud/CUDly/providers/aws/internal/purchasecfg" ) // OpenSearchAPI defines the interface for OpenSearch operations (enables mocking) @@ -43,11 +44,13 @@ type Client struct { accountErr error } -// NewClient creates a new OpenSearch client +// NewClient creates a new OpenSearch client with purchase-path retry/timeout +// settings. See purchasecfg for rationale. func NewClient(cfg aws.Config) *Client { + pcfg := purchasecfg.NewConfig(cfg) return &Client{ - client: opensearch.NewFromConfig(cfg), - stsClient: sts.NewFromConfig(cfg), + client: opensearch.NewFromConfig(pcfg), + stsClient: sts.NewFromConfig(pcfg), region: cfg.Region, } } @@ -144,7 +147,7 @@ func (c *Client) PurchaseCommitment(ctx context.Context, rec common.Recommendati Timestamp: time.Now(), } - offeringID, err := c.findOfferingID(ctx, rec) + offeringID, err := c.findOfferingID(ctx, rec, opts.ExecutionID) if err != nil { result.Error = fmt.Errorf("failed to find offering: %w", err) return result, result.Error @@ -361,7 +364,17 @@ const maxOfferingPages = 5 // findOfferingID finds the appropriate Reserved Instance offering ID. // The OpenSearch API does not support server-side filters on the offerings list, // so all matching is done client-side (issue #688). -func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation) (string, error) { +// execID is the purchase execution UUID for log correlation; pass "" when +// calling outside of a purchase flow (ValidateOffering, GetOfferingDetails). +func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation, execID string) (string, error) { + tag := execID + if tag == "" { + tag = "no-exec" + } + t0 := time.Now() + log.Printf("purchase[%s]: OpenSearch findOfferingID starting (instanceType=%s term=%s payment=%s)", + tag, rec.ResourceType, rec.Term, rec.PaymentOption) + var nextToken *string page := 0 for { @@ -383,14 +396,18 @@ func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation) pageStart := time.Now() result, err := c.client.DescribeReservedInstanceOfferings(ctx, input) if err != nil { + log.Printf("purchase[%s]: OpenSearch findOfferingID page %d failed after %s (total %s): %v", + tag, page, time.Since(pageStart), time.Since(t0), err) return "", fmt.Errorf("failed to describe offerings: %w", err) } - log.Printf("OpenSearch findOfferingID page %d: %d offerings in %s", - page, len(result.ReservedInstanceOfferings), time.Since(pageStart)) + log.Printf("purchase[%s]: OpenSearch findOfferingID page %d: %d offerings in %s", + tag, page, len(result.ReservedInstanceOfferings), time.Since(pageStart)) if id, scanErr := c.scanOpenSearchOfferingPage(result.ReservedInstanceOfferings, rec); scanErr != nil { return "", scanErr } else if id != "" { + log.Printf("purchase[%s]: OpenSearch findOfferingID found match on page %d after %s total", + tag, page, time.Since(t0)) return id, nil } @@ -400,6 +417,8 @@ func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation) nextToken = result.NextToken } + log.Printf("purchase[%s]: OpenSearch findOfferingID exhausted %d page(s) in %s -- no match", + tag, page, time.Since(t0)) return "", fmt.Errorf("no offerings found for OpenSearch %s %s after %d page(s) (issue #688)", rec.ResourceType, rec.PaymentOption, page) } @@ -469,13 +488,13 @@ func (c *Client) matchesDuration(offeringDuration int32, term string) bool { // ValidateOffering checks if an offering exists without purchasing func (c *Client) ValidateOffering(ctx context.Context, rec common.Recommendation) error { - _, err := c.findOfferingID(ctx, rec) + _, err := c.findOfferingID(ctx, rec, "") return err } // GetOfferingDetails retrieves offering details func (c *Client) GetOfferingDetails(ctx context.Context, rec common.Recommendation) (*common.OfferingDetails, error) { - offeringID, err := c.findOfferingID(ctx, rec) + offeringID, err := c.findOfferingID(ctx, rec, "") if err != nil { return nil, err } diff --git a/providers/aws/services/opensearch/client_test.go b/providers/aws/services/opensearch/client_test.go index 00a3ebf6b..8edcb4a05 100644 --- a/providers/aws/services/opensearch/client_test.go +++ b/providers/aws/services/opensearch/client_test.go @@ -837,7 +837,7 @@ func TestFindOfferingID_PaginationCapFires(t *testing.T) { }, nil).Once() } - _, err := client.findOfferingID(context.Background(), rec) + _, err := client.findOfferingID(context.Background(), rec, "") if assert.Error(t, err) { assert.Contains(t, err.Error(), "pagination cap reached") @@ -876,7 +876,7 @@ func TestFindOfferingID_WrongVariantRejected(t *testing.T) { }, }, nil).Once() - id, err := client.findOfferingID(context.Background(), rec) + id, err := client.findOfferingID(context.Background(), rec, "") assert.Error(t, err) assert.Contains(t, err.Error(), "payment option") @@ -908,7 +908,7 @@ func TestFindOfferingID_HappyPath(t *testing.T) { }, }, nil).Once() - id, err := client.findOfferingID(context.Background(), rec) + id, err := client.findOfferingID(context.Background(), rec, "") assert.NoError(t, err) assert.Equal(t, "offering-ok", id) diff --git a/providers/aws/services/rds/client.go b/providers/aws/services/rds/client.go index 199e4004d..fe65f85e9 100644 --- a/providers/aws/services/rds/client.go +++ b/providers/aws/services/rds/client.go @@ -16,6 +16,7 @@ import ( "github.com/aws/aws-sdk-go-v2/service/rds/types" "github.com/LeanerCloud/CUDly/pkg/common" + "github.com/LeanerCloud/CUDly/providers/aws/internal/purchasecfg" "github.com/LeanerCloud/CUDly/providers/aws/internal/tagging" ) @@ -32,10 +33,12 @@ type Client struct { region string } -// NewClient creates a new RDS client +// NewClient creates a new RDS client with purchase-path retry/timeout settings. +// See purchasecfg for rationale. func NewClient(cfg aws.Config) *Client { + pcfg := purchasecfg.NewConfig(cfg) return &Client{ - client: rds.NewFromConfig(cfg), + client: rds.NewFromConfig(pcfg), region: cfg.Region, } } @@ -134,7 +137,7 @@ func (c *Client) PurchaseCommitment(ctx context.Context, rec common.Recommendati } // Find the offering ID - offeringID, err := c.findOfferingID(ctx, rec) + offeringID, err := c.findOfferingID(ctx, rec, opts.ExecutionID) if err != nil { result.Error = fmt.Errorf("failed to find offering: %w", err) return result, result.Error @@ -292,8 +295,10 @@ func (c *Client) findReservationByID(ctx context.Context, reservationID string) // of timing out the Lambda budget (issue #688). const maxOfferingPages = 5 -// findOfferingID finds the appropriate RDS Reserved Instance offering ID -func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation) (string, error) { +// findOfferingID finds the appropriate RDS Reserved Instance offering ID. +// execID is the purchase execution UUID for log correlation; pass "" when +// calling outside of a purchase flow (ValidateOffering, GetOfferingDetails). +func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation, execID string) (string, error) { details, ok := rec.Details.(*common.DatabaseDetails) if !ok || details == nil { return "", fmt.Errorf("invalid service details for RDS") @@ -302,17 +307,25 @@ func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation) if err != nil { return "", fmt.Errorf("invalid payment option: %w", err) } - return c.paginateRDSOfferings(ctx, rec, details, offeringType) + return c.paginateRDSOfferings(ctx, rec, details, offeringType, execID) } // paginateRDSOfferings walks DescribeReservedDBInstancesOfferings pages and returns // the first matching offering ID. It caps at maxOfferingPages to prevent Lambda // timeout exhaustion (issue #688). -func (c *Client) paginateRDSOfferings(ctx context.Context, rec common.Recommendation, details *common.DatabaseDetails, offeringType string) (string, error) { +func (c *Client) paginateRDSOfferings(ctx context.Context, rec common.Recommendation, details *common.DatabaseDetails, offeringType string, execID string) (string, error) { multiAZ := details.AZConfig == "multi-az" normalizedEngine := c.normalizeEngineName(details.Engine) duration := c.getDurationString(rec.Term) + tag := execID + if tag == "" { + tag = "no-exec" + } + t0 := time.Now() + log.Printf("purchase[%s]: RDS findOfferingID starting (class=%s engine=%s multi-az=%v duration=%s payment=%s)", + tag, rec.ResourceType, normalizedEngine, multiAZ, duration, offeringType) + var marker *string page := 0 for { @@ -336,13 +349,17 @@ func (c *Client) paginateRDSOfferings(ctx context.Context, rec common.Recommenda pageStart := time.Now() result, err := c.client.DescribeReservedDBInstancesOfferings(ctx, input) if err != nil { + log.Printf("purchase[%s]: RDS findOfferingID page %d failed after %s (total %s): %v", + tag, page, time.Since(pageStart), time.Since(t0), err) return "", fmt.Errorf("failed to describe offerings: %w", err) } - log.Printf("RDS findOfferingID page %d: %d offerings in %s", - page, len(result.ReservedDBInstancesOfferings), time.Since(pageStart)) + log.Printf("purchase[%s]: RDS findOfferingID page %d: %d offerings in %s", + tag, page, len(result.ReservedDBInstancesOfferings), time.Since(pageStart)) if id, scanErr := scanRDSOfferingPage(result.ReservedDBInstancesOfferings, rec, offeringType); scanErr != nil { return "", scanErr } else if id != "" { + log.Printf("purchase[%s]: RDS findOfferingID found match on page %d after %s total", + tag, page, time.Since(t0)) return id, nil } if result.Marker == nil || aws.ToString(result.Marker) == "" { @@ -350,6 +367,8 @@ func (c *Client) paginateRDSOfferings(ctx context.Context, rec common.Recommenda } marker = result.Marker } + log.Printf("purchase[%s]: RDS findOfferingID exhausted %d page(s) in %s -- no match", + tag, page, time.Since(t0)) return "", fmt.Errorf("no offerings found for RDS %s %s multi-az=%v %s after %d page(s) (issue #688)", rec.ResourceType, details.Engine, multiAZ, rec.PaymentOption, page) } @@ -371,13 +390,13 @@ func scanRDSOfferingPage(offerings []types.ReservedDBInstancesOffering, rec comm // ValidateOffering checks if an offering exists without purchasing func (c *Client) ValidateOffering(ctx context.Context, rec common.Recommendation) error { - _, err := c.findOfferingID(ctx, rec) + _, err := c.findOfferingID(ctx, rec, "") return err } // GetOfferingDetails retrieves offering details func (c *Client) GetOfferingDetails(ctx context.Context, rec common.Recommendation) (*common.OfferingDetails, error) { - offeringID, err := c.findOfferingID(ctx, rec) + offeringID, err := c.findOfferingID(ctx, rec, "") if err != nil { return nil, err } diff --git a/providers/aws/services/redshift/client.go b/providers/aws/services/redshift/client.go index ac194e0f0..b65eab42e 100644 --- a/providers/aws/services/redshift/client.go +++ b/providers/aws/services/redshift/client.go @@ -16,6 +16,7 @@ import ( "github.com/LeanerCloud/CUDly/pkg/common" "github.com/LeanerCloud/CUDly/pkg/retry" + "github.com/LeanerCloud/CUDly/providers/aws/internal/purchasecfg" ) // RedshiftAPI defines the interface for Redshift operations (enables mocking) @@ -47,11 +48,13 @@ type Client struct { accountErr error } -// NewClient creates a new Redshift client +// NewClient creates a new Redshift client with purchase-path retry/timeout +// settings. See purchasecfg for rationale. func NewClient(cfg aws.Config) *Client { + pcfg := purchasecfg.NewConfig(cfg) return &Client{ - client: redshift.NewFromConfig(cfg), - stsClient: sts.NewFromConfig(cfg), + client: redshift.NewFromConfig(pcfg), + stsClient: sts.NewFromConfig(pcfg), region: cfg.Region, } } @@ -146,7 +149,7 @@ func (c *Client) PurchaseCommitment(ctx context.Context, rec common.Recommendati Timestamp: time.Now(), } - offeringID, err := c.findOfferingID(ctx, rec) + offeringID, err := c.findOfferingID(ctx, rec, opts.ExecutionID) if err != nil { result.Error = fmt.Errorf("failed to find offering: %w", err) return result, result.Error @@ -396,10 +399,19 @@ const maxOfferingPages = 5 // Redshift's DescribeReservedNodeOfferings has no server-side node-type or // payment-option filter, so matching is done client-side with a pagination cap // to prevent indefinite runtime (issue #688). -func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation) (string, error) { +// execID is the purchase execution UUID for log correlation; pass "" when +// calling outside of a purchase flow (ValidateOffering, GetOfferingDetails). +func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation, execID string) (string, error) { + tag := execID + if tag == "" { + tag = "no-exec" + } + t0 := time.Now() + log.Printf("purchase[%s]: Redshift findOfferingID starting (nodeType=%s term=%s payment=%s)", + tag, rec.ResourceType, rec.Term, rec.PaymentOption) + var marker *string page := 0 - for { if err := ctx.Err(); err != nil { return "", err @@ -419,14 +431,18 @@ func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation) pageStart := time.Now() result, err := c.client.DescribeReservedNodeOfferings(ctx, input) if err != nil { + log.Printf("purchase[%s]: Redshift findOfferingID page %d failed after %s (total %s): %v", + tag, page, time.Since(pageStart), time.Since(t0), err) return "", fmt.Errorf("failed to describe offerings: %w", err) } - log.Printf("Redshift findOfferingID page %d: %d offerings in %s", - page, len(result.ReservedNodeOfferings), time.Since(pageStart)) + log.Printf("purchase[%s]: Redshift findOfferingID page %d: %d offerings in %s", + tag, page, len(result.ReservedNodeOfferings), time.Since(pageStart)) if id, scanErr := c.scanRedshiftOfferingPage(result.ReservedNodeOfferings, rec); scanErr != nil { return "", scanErr } else if id != "" { + log.Printf("purchase[%s]: Redshift findOfferingID found match on page %d after %s total", + tag, page, time.Since(t0)) return id, nil } @@ -436,6 +452,8 @@ func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation) marker = result.Marker } + log.Printf("purchase[%s]: Redshift findOfferingID exhausted %d page(s) in %s -- no match", + tag, page, time.Since(t0)) return "", fmt.Errorf("no offerings found for Redshift %s after %d page(s) (issue #688)", rec.ResourceType, page) } @@ -486,13 +504,13 @@ func (c *Client) matchesOfferingType(offeringType string, _ string) bool { // ValidateOffering checks if an offering exists without purchasing func (c *Client) ValidateOffering(ctx context.Context, rec common.Recommendation) error { - _, err := c.findOfferingID(ctx, rec) + _, err := c.findOfferingID(ctx, rec, "") return err } // GetOfferingDetails retrieves offering details func (c *Client) GetOfferingDetails(ctx context.Context, rec common.Recommendation) (*common.OfferingDetails, error) { - offeringID, err := c.findOfferingID(ctx, rec) + offeringID, err := c.findOfferingID(ctx, rec, "") if err != nil { return nil, err } diff --git a/providers/aws/services/savingsplans/client.go b/providers/aws/services/savingsplans/client.go index 907d5396d..355b0503a 100644 --- a/providers/aws/services/savingsplans/client.go +++ b/providers/aws/services/savingsplans/client.go @@ -12,6 +12,7 @@ import ( "github.com/aws/aws-sdk-go-v2/service/savingsplans/types" "github.com/LeanerCloud/CUDly/pkg/common" + "github.com/LeanerCloud/CUDly/providers/aws/internal/purchasecfg" ) // SavingsPlansAPI defines the interface for Savings Plans operations (enables mocking) @@ -33,13 +34,14 @@ type Client struct { planType types.SavingsPlanType } -// NewClient creates a new Savings Plans client scoped to one plan type. -// The plan type determines which slug GetServiceType returns and which -// commitments GetExistingCommitments includes — both critical for the -// per-plan-type ServiceConfig dispatch added in the AWS provider. +// NewClient creates a new Savings Plans client scoped to one plan type with +// purchase-path retry/timeout settings. The plan type determines which slug +// GetServiceType returns and which commitments GetExistingCommitments includes. +// See purchasecfg for retry rationale. func NewClient(cfg aws.Config, planType types.SavingsPlanType) *Client { + pcfg := purchasecfg.NewConfig(cfg) return &Client{ - client: savingsplans.NewFromConfig(cfg), + client: savingsplans.NewFromConfig(pcfg), region: cfg.Region, planType: planType, } @@ -180,7 +182,7 @@ func (c *Client) PurchaseCommitment(ctx context.Context, rec common.Recommendati return result, result.Error } - offeringID, err := c.findOfferingID(ctx, rec) + offeringID, err := c.findOfferingID(ctx, rec, opts.ExecutionID) if err != nil { result.Error = fmt.Errorf("failed to find Savings Plans offering: %w", err) return result, result.Error @@ -221,8 +223,10 @@ func (c *Client) PurchaseCommitment(ctx context.Context, rec common.Recommendati return result, nil } -// findOfferingID finds the appropriate Savings Plans offering ID -func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation) (string, error) { +// findOfferingID finds the appropriate Savings Plans offering ID. +// execID is the purchase execution UUID for log correlation; pass "" when +// calling outside of a purchase flow (ValidateOffering, GetOfferingDetails). +func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation, execID string) (string, error) { spDetails, ok := rec.Details.(*common.SavingsPlanDetails) if !ok { return "", fmt.Errorf("invalid service details for Savings Plans") @@ -252,13 +256,28 @@ func (c *Client) findOfferingID(ctx context.Context, rec common.Recommendation) termSeconds := convertTermToSeconds(rec.Term) paymentOption := convertPaymentOption(rec.PaymentOption) + tag := execID + if tag == "" { + tag = "no-exec" + } + + t0 := time.Now() + log.Printf("purchase[%s]: SavingsPlans findOfferingID starting (planType=%s term=%s payment=%s)", + tag, planType, rec.Term, rec.PaymentOption) + input := &savingsplans.DescribeSavingsPlansOfferingsInput{ PlanTypes: []types.SavingsPlanType{planType}, Durations: []int64{termSeconds}, PaymentOptions: []types.SavingsPlanPaymentOption{paymentOption}, } - return c.lookupOfferingID(ctx, input) + offeringID, err := c.lookupOfferingID(ctx, input) + if err != nil { + log.Printf("purchase[%s]: SavingsPlans findOfferingID failed after %s: %v", tag, time.Since(t0), err) + } else { + log.Printf("purchase[%s]: SavingsPlans findOfferingID found offering in %s", tag, time.Since(t0)) + } + return offeringID, err } // convertPlanType converts a plan type string to AWS SDK type @@ -313,6 +332,7 @@ const maxOfferingPages = 5 // filters that narrow the result set, so only a handful of results are expected // on the first page. Pagination with a cap is added as a safety net. func (c *Client) lookupOfferingID(ctx context.Context, input *savingsplans.DescribeSavingsPlansOfferingsInput) (string, error) { + t0 := time.Now() page := 0 for { if err := ctx.Err(); err != nil { @@ -327,8 +347,12 @@ func (c *Client) lookupOfferingID(ctx context.Context, input *savingsplans.Descr result, err := c.client.DescribeSavingsPlansOfferings(ctx, input) if err != nil { + log.Printf("purchase[SavingsPlans]: DescribeSavingsPlansOfferings page %d failed after %s: %v", + page, time.Since(t0), err) return "", fmt.Errorf("failed to describe Savings Plans offerings: %w", err) } + log.Printf("purchase[SavingsPlans]: DescribeSavingsPlansOfferings page %d returned %d results in %s", + page, len(result.SearchResults), time.Since(t0)) for _, offering := range result.SearchResults { if offering.OfferingId == nil { @@ -348,13 +372,13 @@ func (c *Client) lookupOfferingID(ctx context.Context, input *savingsplans.Descr // ValidateOffering checks if a Savings Plans offering exists func (c *Client) ValidateOffering(ctx context.Context, rec common.Recommendation) error { - _, err := c.findOfferingID(ctx, rec) + _, err := c.findOfferingID(ctx, rec, "") return err } // GetOfferingDetails retrieves offering details func (c *Client) GetOfferingDetails(ctx context.Context, rec common.Recommendation) (*common.OfferingDetails, error) { - offeringID, err := c.findOfferingID(ctx, rec) + offeringID, err := c.findOfferingID(ctx, rec, "") if err != nil { return nil, err } diff --git a/providers/aws/services/savingsplans/client_test.go b/providers/aws/services/savingsplans/client_test.go index 6501307ee..813d753e8 100644 --- a/providers/aws/services/savingsplans/client_test.go +++ b/providers/aws/services/savingsplans/client_test.go @@ -284,7 +284,7 @@ func TestClient_findOfferingID_RejectsMismatchedPlanType(t *testing.T) { }, } - _, err := client.findOfferingID(context.Background(), rec) + _, err := client.findOfferingID(context.Background(), rec, "") require.Error(t, err) assert.Contains(t, err.Error(), "does not match client scope") // AWS API must not be called — the mismatch should be caught diff --git a/providers/azure/provider.go b/providers/azure/provider.go index 4d2c75e6a..568573158 100644 --- a/providers/azure/provider.go +++ b/providers/azure/provider.go @@ -6,6 +6,7 @@ import ( "fmt" "os" "sync" + "time" "github.com/Azure/azure-sdk-for-go/sdk/azcore" "github.com/Azure/azure-sdk-for-go/sdk/azcore/runtime" @@ -220,12 +221,15 @@ func (p *AzureProvider) ValidateCredentials(ctx context.Context) error { subClient = &realSubscriptionsClient{client: client} } + t0 := time.Now() + logging.Infof("purchase[Azure]: subscriptions.NewListPager/NextPage starting (subscription=%s)", p.subscriptionID) pager := subClient.NewListPager(nil) _, err := pager.NextPage(ctx) if err != nil { + logging.Errorf("purchase[Azure]: subscriptions.NextPage failed after %s: %v", time.Since(t0), err) return fmt.Errorf("Azure credentials validation failed: %w", err) } - + logging.Infof("purchase[Azure]: subscriptions.NextPage returned in %s", time.Since(t0)) return nil } diff --git a/terraform/environments/aws/github-dev.tfvars b/terraform/environments/aws/github-dev.tfvars index 0f50e5955..7a2018260 100644 --- a/terraform/environments/aws/github-dev.tfvars +++ b/terraform/environments/aws/github-dev.tfvars @@ -19,7 +19,7 @@ enable_docker_build = true # Build and push image via terraform apply on the run # Lambda Configuration lambda_memory_size = 2048 -lambda_timeout = 60 +lambda_timeout = 300 lambda_reserved_concurrency = -1 lambda_log_retention_days = 7 lambda_enable_function_url = true diff --git a/terraform/environments/aws/github-prod.tfvars b/terraform/environments/aws/github-prod.tfvars index 732a83cf9..3af0e89c5 100644 --- a/terraform/environments/aws/github-prod.tfvars +++ b/terraform/environments/aws/github-prod.tfvars @@ -19,7 +19,7 @@ enable_docker_build = true # Build image via Terraform build module (no separate # Lambda Configuration lambda_memory_size = 1024 -lambda_timeout = 60 +lambda_timeout = 300 lambda_reserved_concurrency = -1 lambda_log_retention_days = 30 lambda_enable_function_url = true diff --git a/terraform/environments/aws/github-staging.tfvars b/terraform/environments/aws/github-staging.tfvars index ec96da038..bb3cabad8 100644 --- a/terraform/environments/aws/github-staging.tfvars +++ b/terraform/environments/aws/github-staging.tfvars @@ -19,7 +19,7 @@ enable_docker_build = true # Build image via Terraform build module (no separate # Lambda Configuration lambda_memory_size = 1024 -lambda_timeout = 60 +lambda_timeout = 300 lambda_reserved_concurrency = -1 lambda_log_retention_days = 14 lambda_enable_function_url = true