-
Notifications
You must be signed in to change notification settings - Fork 46
fix(#975): add diagnostic context to provisioning error logs #976
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: main
Are you sure you want to change the base?
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -2,7 +2,6 @@ package taskrun | |
|
|
||
| import ( | ||
| "context" | ||
| "errors" | ||
| "fmt" | ||
| "strconv" | ||
| "time" | ||
|
|
@@ -48,7 +47,11 @@ func (r DynamicResolver) Deallocate(taskRun *ReconcileTaskRun, ctx context.Conte | |
| func (r DynamicResolver) Allocate(taskRun *ReconcileTaskRun, ctx context.Context, tr *v1.TaskRun, secretName string) (reconcile.Result, error) { | ||
| log := logr.FromContextOrDiscard(ctx) | ||
| if tr.Annotations[FailedHosts] != "" { | ||
| return reconcile.Result{}, errors.New("failed to provision host") | ||
| log.Error(nil, "all provisioning attempts exhausted", | ||
|
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 3. Nil error in error() DynamicResolver.Allocate calls log.Error(nil, ...) when provisioning attempts are exhausted, emitting an error-level log without an error value and diverging from the repo’s normal logging pattern. This reduces log consistency/utility and makes the returned error (created afterward) unavailable to the logger. Agent Prompt
|
||
| "failedHosts", tr.Annotations[FailedHosts], | ||
| "instanceTag", r.instanceTag, | ||
| ) | ||
| return reconcile.Result{}, fmt.Errorf("failed to provision host, all attempts exhausted for instance tag %s (previously failed hosts: %s)", r.instanceTag, tr.Annotations[FailedHosts]) | ||
| } | ||
|
|
||
| if tr.Annotations == nil { | ||
|
|
@@ -59,8 +62,12 @@ func (r DynamicResolver) Allocate(taskRun *ReconcileTaskRun, ctx context.Context | |
| startTime, err := strconv.ParseInt(allocStart, 10, 64) | ||
| if err == nil { | ||
| if startTime+r.timeout < time.Now().Unix() { | ||
| err = errors.New("timed out waiting for instance address") | ||
| log.Error(err, "timed out waiting for instance address") | ||
| err = fmt.Errorf("timed out waiting for instance address (instance: %s, instanceTag: %s, timeout: %ds)", tr.Annotations[CloudInstanceId], r.instanceTag, r.timeout) | ||
| log.Error(err, "timed out waiting for instance address", | ||
| "instanceId", tr.Annotations[CloudInstanceId], | ||
| "instanceTag", r.instanceTag, | ||
| "timeoutSeconds", r.timeout, | ||
| ) | ||
| //ugh, try and unassign | ||
| terr := r.TerminateInstance(taskRun.client, ctx, cloud.InstanceIdentifier(tr.Annotations[CloudInstanceId])) | ||
| if terr != nil { | ||
|
|
@@ -85,7 +92,10 @@ func (r DynamicResolver) Allocate(taskRun *ReconcileTaskRun, ctx context.Context | |
| //An instance already exists, so get its IP address | ||
| address, err := r.GetInstanceAddress(taskRun.client, ctx, cloud.InstanceIdentifier(tr.Annotations[CloudInstanceId])) | ||
| if err != nil { // A permanent error occurred when fetching the IP address for the VM | ||
| log.Error(err, "failed to get instance address for cloud host") | ||
| log.Error(err, "failed to get instance address for cloud host", | ||
| "instanceId", tr.Annotations[CloudInstanceId], | ||
| "instanceTag", r.instanceTag, | ||
| ) | ||
| //Try to delete the instance and unassign it from the TaskRun | ||
| terr := r.TerminateInstance(taskRun.client, ctx, cloud.InstanceIdentifier(tr.Annotations[CloudInstanceId])) | ||
| if terr != nil { | ||
|
|
@@ -124,9 +134,13 @@ func (r DynamicResolver) Allocate(taskRun *ReconcileTaskRun, ctx context.Context | |
| if unassignErr != nil { | ||
| log.Error(unassignErr, "failed to unassign instance from task after provisioning failure") | ||
| } else { | ||
| log.Error(err, "failed to provision cloud host") | ||
| log.Error(err, "failed to provision cloud host", | ||
|
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 1. Dynamic provision error untested The modified provisioning-task failure path in DynamicResolver.Allocate adds new executable error/logging lines, but there is no test scenario that can reach it given the current test harness always provides the SSH secret and the fake client create path does not fail. This violates the requirement that every new/modified executable line in the patch is exercised by automated tests (or has an explicit coverage justification). Agent Prompt
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 4. Instance id lost in error When launchProvisioningTask fails, DynamicResolver.Allocate deletes CloudInstanceId from tr.Annotations before constructing the new structured log fields and wrapped error that read tr.Annotations[CloudInstanceId]. If termination succeeds, the returned error/logs can show an empty instance ID, defeating the added diagnostic context and affecting user-visible error secrets. Agent Prompt
|
||
| "instanceId", tr.Annotations[CloudInstanceId], | ||
| "instanceTag", r.instanceTag, | ||
| "address", address, | ||
| ) | ||
| } | ||
| return reconcile.Result{}, err | ||
| return reconcile.Result{}, fmt.Errorf("failed to provision cloud host (instance: %s, address: %s): %w", tr.Annotations[CloudInstanceId], address, err) | ||
| } | ||
| return reconcile.Result{}, nil | ||
| } else { // A transient error (that wasn't returned) occurred when fetching the IP address for the VM | ||
|
|
@@ -194,7 +208,10 @@ func (r DynamicResolver) Allocate(taskRun *ReconcileTaskRun, ctx context.Context | |
| if err != nil { | ||
| launchErr := err | ||
| //launch failed | ||
| log.Error(err, "Failed to create cloud host") | ||
| log.Error(err, "Failed to create cloud host", | ||
| "instanceTag", r.instanceTag, | ||
| "platform", r.platform, | ||
| ) | ||
| failureCount := 0 | ||
| existingFailureString := tr.Annotations[CloudFailures] | ||
| if existingFailureString != "" { | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -135,15 +135,19 @@ func (hp HostPool) Allocate(r *ReconcileTaskRun, ctx context.Context, tr *v1.Tas | |
|
|
||
| if err != nil { | ||
| //ugh, try and unassign | ||
| log.Error(err, "failed to launch provisioning task, unassigning host") | ||
| log.Error(err, "failed to launch provisioning task, unassigning host", | ||
|
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 2. Hostpool provision error untested The modified HostPool.Allocate provisioning-task launch failure path adds/changes executable error/logging lines, but the test harness always provides the awskeys secret and does not introduce a failing create path to execute this branch. This violates the requirement that every new/modified executable line in the patch is exercised by automated tests (or has an explicit coverage justification). Agent Prompt
|
||
| "host", selected.Name, | ||
| "address", selected.Address, | ||
| "platform", hp.targetPlatform, | ||
| ) | ||
| delete(tr.Labels, constant.AssignedHost) | ||
| controllerutil.RemoveFinalizer(tr, PipelineFinalizer) | ||
| updateErr := UpdateTaskRunWithRetry(ctx, r.client, r.apiReader, tr) | ||
| if updateErr != nil { | ||
| log.Error(updateErr, "Could not unassign task after provisioning failure") | ||
| return reconcile.Result{}, err | ||
| } | ||
| return reconcile.Result{}, fmt.Errorf("failed to provision host: %v", err) | ||
| return reconcile.Result{}, fmt.Errorf("failed to provision host %s (%s): %w", selected.Name, selected.Address, err) | ||
| } | ||
| return reconcile.Result{}, nil | ||
| } | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -283,6 +283,46 @@ var _ = Describe("Test Dynamic Host Provisioning", func() { | |
| }) | ||
| }) | ||
|
|
||
| When("error messages contain diagnostic context", func() { | ||
|
|
||
| It("should include failed hosts and instance tag in error when all provisioning attempts are exhausted", func(ctx SpecContext) { | ||
| createUserTaskRun(ctx, client, "test-err-ctx", "linux/arm64") | ||
| tr := getUserTaskRun(ctx, client, "test-err-ctx") | ||
| // Simulate that a previous host already failed | ||
| tr.Annotations = map[string]string{FailedHosts: "host-abc"} | ||
| Expect(client.Update(ctx, tr)).ShouldNot(HaveOccurred()) | ||
|
|
||
| _, err := reconciler.Reconcile(ctx, reconcile.Request{NamespacedName: types.NamespacedName{Namespace: userNamespace, Name: "test-err-ctx"}}) | ||
| Expect(err).Should(HaveOccurred()) | ||
| Expect(err.Error()).Should(ContainSubstring("host-abc")) | ||
| Expect(err.Error()).Should(ContainSubstring("all attempts exhausted")) | ||
| }) | ||
|
|
||
| It("should include instance ID and timeout in error when instance address times out", func(ctx SpecContext) { | ||
| cloudImpl.TimeoutGetAddress = true | ||
| defer func() { cloudImpl.TimeoutGetAddress = false }() | ||
|
|
||
| createUserTaskRun(ctx, client, "test-timeout-ctx", "linux/arm64") | ||
| // 1st reconcile: launches instance | ||
| _, err := reconciler.Reconcile(ctx, reconcile.Request{NamespacedName: types.NamespacedName{Namespace: userNamespace, Name: "test-timeout-ctx"}}) | ||
| Expect(err).ShouldNot(HaveOccurred()) | ||
|
|
||
| // Verify instance was created and has an ID | ||
| tr := getUserTaskRun(ctx, client, "test-timeout-ctx") | ||
| Expect(tr.Annotations[CloudInstanceId]).ShouldNot(BeEmpty()) | ||
|
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. [low] testing time.Sleep(time.Second * 3) is timing-sensitive. The 3-second sleep must exceed the 2-second allocation-timeout, but slow CI environments could make this flaky. This follows the pre-existing pattern in the file. Suggested fix: Consider increasing the sleep margin or refactoring to use Eventually with a polling interval in a future cleanup. |
||
| instanceID := tr.Annotations[CloudInstanceId] | ||
|
|
||
| // Wait for timeout (allocation-timeout is 2 seconds in test config) | ||
|
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 5. Sleep-based timeout test The new dynamic provisioning test uses time.Sleep(3s) to trigger the allocation timeout, which slows the test suite and can be timing-flaky in loaded CI environments. The timeout logic is purely computed from AllocationStartTimeAnnotation and r.timeout, so the test can simulate timeout deterministically by backdating the annotation instead of sleeping. Agent Prompt
|
||
| time.Sleep(time.Second * 3) | ||
|
|
||
| // Reconcile after timeout | ||
| _, err = reconciler.Reconcile(ctx, reconcile.Request{NamespacedName: types.NamespacedName{Namespace: userNamespace, Name: "test-timeout-ctx"}}) | ||
| Expect(err).Should(HaveOccurred()) | ||
| Expect(err.Error()).Should(ContainSubstring("timed out")) | ||
| Expect(err.Error()).Should(ContainSubstring(instanceID)) | ||
| }) | ||
| }) | ||
|
|
||
| // Tests for buildDynamicResolver function - only the sad paths since happy paths are thoroughly tested elsewhere | ||
| When("testing buildDynamicResolver error paths", func() { | ||
| It("should use default instance tag when platform config doesn't specify one", func(ctx SpecContext) { | ||
|
|
||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
[low] style
log.Error(nil, ...) passes nil as the error argument. While valid in logr, this is unusual in this codebase where most callers pass a non-nil error. Consider creating the fmt.Errorf first and passing it to both the log and the return, as done in the timeout path a few lines below.
Suggested fix: Create the error with fmt.Errorf first, then pass it to log.Error and return it.