fix(purchases): add execution-tagged logging to executeSinglePurchase (refs #667) - #668
Merged
cristim merged 1 commit intoMay 22, 2026
Conversation
… (refs #667) The purchase-execution flow had zero Info-level observability between the approve handler and the final aggregated error toast. When a sync approve hit a context-deadline timeout on the cloud SDK call (issue #667), the only signal was the wrapped error returned to the HTTP response. CloudWatch showed nothing about which rec ran, what details shape was used, how long the AWS API call took, or whether the SDK reached the purchase call at all. This change adds Info/Error log lines at every critical step inside executeSinglePurchase + processPurchaseRecommendations, every line tagged with the owning execution UUID so a CloudWatch filter by exec ID surfaces the full per-rec trace: purchase[<exec-id>]: dispatching N recommendation(s) for account=X plan=Y purchase[<exec-id>]: starting rec <provider>/<svc>/<region>/<sku> ... purchase[<exec-id>]: provider <provider> constructed in <ms> purchase[<exec-id>]: service client <provider>/<svc>/<region> ready in <ms> purchase[<exec-id>]: details ready for <provider>/<svc> (detailsAbsent=<bool> engine=<engine> idempotencyToken=<token>) purchase[<exec-id>]: <rec-tuple> PurchaseCommitment succeeded in <ms> (commitmentID=<id>, cost=<n>) Failure paths log at Error level with the same exec-ID tag + elapsed time so a slow SDK call is distinguishable from a fast IAM denial. To carry the execution ID into executeSinglePurchase without a new parameter (which would ripple through every caller including the CLI purchase path that has no owning execution), a new ExecutionID field is added to common.PurchaseOptions. The web/dashboard path now populates it from exec.ExecutionID at the processPurchaseRecommendations entry; the CLI path leaves it empty as documented in the field comment. The `detailsAbsent=true` signal in the "details ready" line is the key diagnostic — when set, the rec has no persisted ServiceDetails JSON and the cloud client falls back to defaults (Platform=Linux/UNIX, Tenancy=default, Scope=Region), which is the legacy-row code path from issue #453. Combined with the timing on the PurchaseCommitment line, operators can now distinguish "AWS SDK retry storm against a fully- specified rec" from "AWS returned zero offerings because a legacy rec fell back to defaults". Updated two existing tests that asserted exact PurchaseOptions equality to include the new ExecutionID field. Test results: 161/161 purchase tests pass, full project build clean. Refs #667
cristim
added
priority/p1
Member
Author
|
@coderabbitai review |
Contributor
✅ Actions performedReview triggered.
|
Contributor
|
No actionable comments were generated in the recent review. 🎉 ℹ️ Recent review info⚙️ Run configurationConfiguration used: defaults Review profile: CHILL Plan: Pro Run ID: 📒 Files selected for processing (3)
📝 WalkthroughWalkthroughThis PR adds ChangesExecution ID Tracking
Estimated code review effort🎯 2 (Simple) | ⏱️ ~12 minutes Possibly related PRs
Suggested labels
Poem
🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
✏️ Tip: You can configure your own custom pre-merge checks in the settings. ✨ Finishing Touches📝 Generate docstrings
🧪 Generate unit tests (beta)
Comment |
This was referenced May 22, 2026
Merged
cristim
added a commit
that referenced
this pull request
May 25, 2026
…K retries Introduce providers/aws/internal/purchasecfg.NewConfig which returns a copy of the caller's aws.Config with RetryMaxAttempts=2 and http.Client.Timeout=15s. Worst-case wall clock: 2 * 15s = 30s, well inside the 300s Lambda budget. Recommendation-collection clients (recommendations.NewClient) are explicitly NOT touched; they call Cost Explorer and need the higher default retry budget. Adds five unit tests covering: retry cap, HTTP timeout, immutability of the base config, region preservation, and the wall-clock bound invariant. Closes #683. Refs #667 #668 #632 #681.
cristim
added a commit
that referenced
this pull request
May 25, 2026
… 300s (closes #683) (#684) * feat(providers/aws): add purchasecfg helper to bound purchase-path SDK retries Introduce providers/aws/internal/purchasecfg.NewConfig which returns a copy of the caller's aws.Config with RetryMaxAttempts=2 and http.Client.Timeout=15s. Worst-case wall clock: 2 * 15s = 30s, well inside the 300s Lambda budget. Recommendation-collection clients (recommendations.NewClient) are explicitly NOT touched; they call Cost Explorer and need the higher default retry budget. Adds five unit tests covering: retry cap, HTTP timeout, immutability of the base config, region preservation, and the wall-clock bound invariant. Closes #683. Refs #667 #668 #632 #681. * fix(purchases): wire purchasecfg into all 7 purchase-path SDK constructors Switch EC2, RDS, ElastiCache, MemoryDB, OpenSearch, Redshift, and SavingsPlans NewClient calls to use purchasecfg.NewConfig(cfg) so every purchase-path SDK client gets RetryMaxAttempts=2 and http.Client.Timeout=15s. OpenSearch and Redshift also pass the tightened config to their STS client (used for ARN construction / tagging on the purchase path). Recommendation-collection clients (recommendations.NewClient) are not touched; they use their own constructor and deliberately keep the SDK default retry budget for Cost Explorer calls. All 694 tests pass. go build ./... clean. Closes #683. Refs #667. * fix(terraform): bump Lambda timeout 60 -> 300s in all three env tfvars Raise lambda_timeout from 60s to 300s in github-dev, github-staging, and github-prod tfvars. The SDK retry tightening (purchasecfg, max 30s wall clock) combined with the increased Lambda budget means transient AWS API slowness either completes within 30s or surfaces a clear error to the user -- no more silent context deadline exceeded from the Lambda itself expiring mid-retry. Lambda Function URL has no upstream timeout ceiling, so 300s is safe. Closes #683. Refs #667 #681. * feat(purchase): cap per-rec execution at 30s via context.WithTimeout Each recommendation in processPurchaseRecommendations now runs under a 30s per-rec deadline derived from context.WithTimeout. This matches the purchasecfg hard limits (2 retries * 15s HTTP timeout) so a single hung rec (SDK retry storm, STS hang, or pagination hang) cannot exhaust the Lambda budget and starve the remaining recs in the same execution. On timeout, a purchase[<id>]: per-rec deadline 30s exceeded log line fires so CloudWatch pinpoints which rec hung and what the elapsed time was, without requiring a second failure to reproduce. Closes part of issue #683. * feat(purchase/api): add approve handler entry/exit diagnostic logging Adds purchase[<exec-id>]: tagged timing logs at every stage of the approval path so CloudWatch can pinpoint exactly where a future hang occurs: - approvePurchaseViaSession: entry (auth=session) + elapsed on exit - ApproveExecution: entry (auth=token) + elapsed on exit for both the preflight-reject path and the full execute path - ApproveAndExecute: entry + status-transition elapsed + execute elapsed Actor emails are masked to ***@Domain before logging (PII rule). Part of issue #683 diagnostic logging extension. * feat(purchase): add timing logs to resolveAccountProvider and sub-resolvers Adds purchase[resolveAccountProvider/resolveAWSProvider/resolveAzureProvider/ resolveGCPProvider]: entry + elapsed-on-exit logs so CloudWatch can show whether a hang is in credential resolution (STS AssumeRole, OIDC token exchange) vs the cloud API call itself. Each log includes provider, account ID, auth mode, and elapsed time. Error paths also log before returning so a failed resolution is visible in the trace even if the caller swallows the error in an aggregator. Part of issue #683 diagnostic logging extension. * feat(providers): add STS GetCallerIdentity and Azure subscriptions timing logs Instruments the two network calls that ValidateCredentials makes during provider construction so CloudWatch distinguishes a credential-validation hang from the subsequent offering-search or purchase hang: - providers/aws/provider.go: purchase[STS]: GetCallerIdentity starting / returned in <elapsed> / failed after <elapsed> - providers/azure/provider.go: purchase[Azure]: subscriptions.NewListPager/ NextPage starting / returned in <elapsed> / failed after <elapsed> Both use the purchase[...]: prefix for grep-ability. Profile/subscription context is logged but no tokens, key material, or full identities. Part of issue #683 diagnostic logging extension. * feat(providers/aws/services): add per-page timing logs to findOfferingID in all 7 AWS service clients Adds purchase[<exec-id>]: tagged per-pagination-page timing logs to the findOfferingID loop in each of the 7 AWS purchase-path service clients (EC2, RDS, ElastiCache, MemoryDB, OpenSearch, Redshift, SavingsPlans). Each log line records: - Entry: service, instance/node type, term, payment option - Per page: page number, offering count returned, page elapsed - Hit: page number where match was found, total elapsed - Exhausted: total pages scanned, total elapsed (no-match path) The exec-id is threaded from PurchaseCommitment(opts.ExecutionID) into findOfferingID so all lines share the same purchase[<uuid>]: prefix and a single CloudWatch Logs Insights query can reconstruct the full pagination trace for any hanging execution. ValidateOffering and GetOfferingDetails callers pass "" (rendered as "no-exec") since they run outside the purchase flow. Part of issue #683 diagnostic logging extension. * feat(execution): add per-goroutine entry/exit timing in FanOutWithConcurrency Adds purchase[fan-out]: entry + elapsed-on-exit log lines to each goroutine launched by FanOutWithConcurrency. Both the account fan-out (multi-account execution) and the per-rec fan-out (processPurchaseRec- ommendations) go through FanOutWithConcurrency, so one addition covers both call sites. Logs: - purchase[fan-out]: goroutine starting for account=<id> - purchase[fan-out]: goroutine for account=<id> completed in <elapsed> - purchase[fan-out]: goroutine for account=<id> failed after <elapsed>: <err> Together with the per-rec ctx.WithTimeout and findOfferingID page logs, a CloudWatch Logs Insights query on purchase[ now reconstructs the full timing tree for a stuck execution: fan-out goroutine start -> credential resolution -> STS -> service client -> findOfferingID pagination -> PurchaseCommitment. Part of issue #683 diagnostic logging extension. * fix(purchase/tests): fix per-rec context.WithTimeout breaking mock matchers Move context.WithTimeout from the fan-out closure (processPurchaseRecommendations) into executeSinglePurchase where it belongs -- the budget governs the cloud API call chain, not the fan-out bookkeeping. Update all GetServiceClient and PurchaseCommitment mock.On() setups in execution_test.go, coverage_extra_test.go, and manager_test.go to match on deadline-carrying contexts via: mock.MatchedBy(func(c context.Context) bool { _, ok := c.Deadline(); return ok }) This positively asserts the 30s per-rec timeout is propagated to every cloud SDK call rather than silently accepting any context (mock.Anything). Also fix the savingsplans/client_test.go build error: findOfferingID gained an execID string parameter in commit 5 but the direct test call was not updated (only the PurchaseCommitment path was updated). All 180 purchase package tests and 308 AWS service tests now pass. Part of issue #683 diagnostic logging extension. * fix(purchase): address CodeRabbit review on PR #684 Three changes per CR pass-1 triage: 1. Actionable (execution.go): distinguish context.DeadlineExceeded from context.Canceled in the post-PurchaseCommitment error log. The previous branch logged "per-rec deadline 30s exceeded" for any non-nil recCtx.Err(), including parent cancellations -- mislabeling Canceled as a timeout makes diagnostic triage harder. Logic extracted into logRecCtxErr helper to keep executeSinglePurchase cyclomatic complexity within the gocyclo limit. 2. Nitpick (execution_test.go): replace mock.Anything with a deadline-aware mock.MatchedBy on the first arg of all 12 CreateAndValidateProvider expectations. The 30s per-rec budget is set before the factory call, so all three mocked stages (factory, GetServiceClient, PurchaseCommitment) now assert deadline propagation end-to-end. 3. Nitpick (purchasecfg/config.go + config_test.go): preserve the caller's *http.Client when one is provided in base config. NewConfig now shallow- copies the client and only overrides Timeout, keeping any custom Transport, Jar, or CheckRedirect. Falls back to a fresh client when base.HTTPClient is nil or a non-*http.Client implementation. Adds TestNewConfig_PreservesCustomTransport to pin the contract. * test(purchase): tighten ctx matcher to assert per-rec 30s budget (CR #684) CodeRabbit on PR #684 (review 4348606803) noted that the 53 mock matchers using `_, ok := c.Deadline(); return ok` only assert *some* deadline is set -- they would still pass if `executeSinglePurchase` silently reused the parent's longer deadline instead of its own `context.WithTimeout(ctx, 30*time.Second)` wrap. Tighten the contract: introduce `hasPerRecDeadline(max time.Duration)` in `execution_test.go` and replace all 53 sites across `execution_test.go`, `coverage_extra_test.go`, and `manager_test.go` with `mock.MatchedBy(hasPerRecDeadline(30*time.Second))`. The matcher now positively asserts the remaining deadline is in (0, 30s], so removing or loosening the wrap fails the test. * refactor(aws/services): extract findOfferingID helpers to fit gocyclo budget memorydb: extract scanMemoryDBOfferingPage (per-page offering scan with mismatch guard) and isLastMemoryDBPage (terminal-page check) from findOfferingID, mirroring the helpers already in the ec2 package. ec2: extract buildEC2QueryFromRec (details type-assertion + payment-option conversion + query assembly) from findOfferingID into a standalone method. Both findOfferingID functions now sit at cyclomatic complexity ≤10. No behaviour change -- pure extraction verified by 72 passing unit tests.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
The purchase-execution flow had zero Info-level observability between the approve handler and the final aggregated error toast. QA reported a
context deadline exceededon EC2DescribeReservedInstancesOfferings(issue #667) and CloudWatch had no log lines to confirm which rec ran, what details were used, or how long the SDK call took. The only existing log was a singlePurchasing:Info line from the fan-out closure.This PR adds execution-tagged logging at every critical step in
executeSinglePurchase+processPurchaseRecommendationsso a CloudWatch filter on the execution UUID surfaces the full per-rec trace.What changed
pkg/common/types.go— addedExecutionID stringtoPurchaseOptionswith doc comment explaining the propagation contract.internal/purchase/execution.go:processPurchaseRecommendationspopulatesopts.ExecutionID = exec.ExecutionIDand logsdispatching N recommendation(s)at entry.executeSinglePurchasenow logs:starting rec <prov>/<svc>/<region>/<sku> (count=N term=Tyr payment=P)provider <prov> constructed in <ms>(or Error on failure)service client <prov>/<svc>/<region> ready in <ms>(or Error)details ready for <prov>/<svc> (detailsAbsent=<bool> engine=<e> idempotencyToken=<tok>)— thedetailsAbsentflag is the diagnostic for legacy-row code path from issue fix(purchases): every AWS purchase fails with 'invalid service details' after #373 (P0) #453<rec-tuple> PurchaseCommitment succeeded in <ms> (commitmentID=<id>, cost=<n>)on success<rec-tuple> PurchaseCommitment failed after <ms>: <err>on error (so a slow SDK call shows the elapsed wall clock)internal/purchase/execution_test.go— updated two tests (TestManager_ExecutePurchase_WebSourcePropagates,TestManager_ExecutePurchase_InvalidSourceFallsBackUntagged) to includeExecutionIDin the expectedPurchaseOptionsliteral.Why it matters
Diagnosing #667 (and similar future failures) currently requires guessing at where in the flow the SDK retry storm consumed the Lambda budget. With this PR, a single CloudWatch query filters the entire purchase timeline by exec ID:
Operators see: provider/service-client construction time, whether
detailsAbsent=true(signal that legacy fallback fired), and the exact elapsed time the cloud SDK call took before erroring. A 60s+ elapsed onPurchaseCommitment failedconfirms #667's retry-storm diagnosis; sub-second timings rule it out.Test plan
go test ./internal/purchase/... -count=1 -short— 161/161 passgo build ./...— cleanCross-references
Summary by CodeRabbit