Repository: keikoproj/upgrade-manager
Pull request #166 (2020-12-17 22:44:52)

Expose template list and other execution errors to logs
Upon deploying v0.17 to our environment, rollingupgrades were silently failing with no decernable error messages. From tracing the possible error points, we deduced it was due to new launchtemplate requests that the serviceaccount did not have permission for. 

This PR adds an explicit error message when launchtemplate fetching fails similar to what happens in the other populate methods, as well as changing the signature of the private finishExecution method to accept an error instead of a status, allowing the error itself to be logged along with the status.

Open question if the error should also be exposed to the kubernetes event as well, or just remain in the controller logs.

codecov[bot]: # [Codecov](https://codecov.io/gh/keikoproj/upgrade-manager/pull/166?src=pr&el=h1) Report
> Merging [#166](https://codecov.io/gh/keikoproj/upgrade-manager/pull/166?src=pr&el=desc) (c6c84ad) into [master](https://codecov.io/gh/keikoproj/upgrade-manager/commit/826594b68cd717deab5433934f0cab346cbaef23?el=desc) (826594b) will **increase** coverage by `0.06%`.
> The diff coverage is `50.00%`.

[![Impacted file tree graph](https://codecov.io/gh/keikoproj/upgrade-manager/pull/166/graphs/tree.svg?width=650&height=150&src=pr&token=PbUYkNX6wz)](https://codecov.io/gh/keikoproj/upgrade-manager/pull/166?src=pr&el=tree)

```diff
@@            Coverage Diff             @@
##           master     #166      +/-   ##
==========================================
+ Coverage   68.38%   68.44%   +0.06%     
==========================================
  Files          11       11              
  Lines         933      938       +5     
==========================================
+ Hits          638      642       +4     
- Misses        262      263       +1     
  Partials       33       33              
```

| Flag | Coverage Δ | |
|---|---|---|
| unittests | `68.44% <50.00%> (+0.06%)` | :arrow_up: |

Flags with carried forward coverage won't be shown. [Click here](https://docs.codecov.io/docs/carryforward-flags#carryforward-flags-in-the-pull-request-comment) to find out more.

| [Impacted Files](https://codecov.io/gh/keikoproj/upgrade-manager/pull/166?src=pr&el=tree) | Coverage Δ | |
|---|---|---|
| [controllers/rollingupgrade\_controller.go](https://codecov.io/gh/keikoproj/upgrade-manager/pull/166/diff?src=pr&el=tree#diff-Y29udHJvbGxlcnMvcm9sbGluZ3VwZ3JhZGVfY29udHJvbGxlci5nbw==) | `68.01% <50.00%> (+0.10%)` | :arrow_up: |

------

[Continue to review full report at Codecov](https://codecov.io/gh/keikoproj/upgrade-manager/pull/166?src=pr&el=continue).
> **Legend** - [Click here to learn more](https://docs.codecov.io/docs/codecov-delta)
> `Δ = absolute <relative> (impact)`, `ø = not affected`, `? = missing data`
> Powered by [Codecov](https://codecov.io/gh/keikoproj/upgrade-manager/pull/166?src=pr&el=footer). Last update [826594b...bbe1c3f](https://codecov.io/gh/keikoproj/upgrade-manager/pull/166?src=pr&el=lastupdated). Read the [comment docs](https://docs.codecov.io/docs/pull-request-comments).

adammw: @shrinandj any more blockers to merge?

Patch:
diff --git a/controllers/rollingupgrade_controller.go b/controllers/rollingupgrade_controller.go
index cc40bdb..2e58466 100644
--- a/controllers/rollingupgrade_controller.go
+++ b/controllers/rollingupgrade_controller.go
@@ -455,14 +455,15 @@ func (r *RollingUpgradeReconciler) populateAsg(ruObj *upgrademgrv1alpha1.Rolling
 	return nil
 }
 
-func (r *RollingUpgradeReconciler) populateLaunchTemplates() error {
+func (r *RollingUpgradeReconciler) populateLaunchTemplates(ruObj *upgrademgrv1alpha1.RollingUpgrade) error {
 	launchTemplates := []*ec2.LaunchTemplate{}
 	err := r.EC2Client.DescribeLaunchTemplatesPages(&ec2.DescribeLaunchTemplatesInput{}, func(page *ec2.DescribeLaunchTemplatesOutput, lastPage bool) bool {
 		launchTemplates = append(launchTemplates, page.LaunchTemplates...)
 		return page.NextToken != nil
 	})
 	if err != nil {
-		return err
+		r.error(ruObj, err, "Failed to populate launch template list")
+		return fmt.Errorf("failed to populate launch template list for %s: %w", ruObj.NamespacedName(), err)
 	}
 	r.LaunchTemplates = launchTemplates
 	return nil
@@ -560,8 +561,20 @@ func (r *RollingUpgradeReconciler) runRestack(ctx *context.Context, ruObj *upgra
 	return processedInstances, nil
 }
 
-func (r *RollingUpgradeReconciler) finishExecution(finalStatus string, nodesProcessed int, ctx *context.Context, ruObj *upgrademgrv1alpha1.RollingUpgrade) {
-	r.info(ruObj, "Marked object as", "finalStatus", finalStatus)
+func (r *RollingUpgradeReconciler) finishExecution(err error, nodesProcessed int, ctx *context.Context, ruObj *upgrademgrv1alpha1.RollingUpgrade) {
+	var level string
+	var finalStatus string
+
+	if err == nil {
+		finalStatus = upgrademgrv1alpha1.StatusComplete
+		level = EventLevelNormal
+		r.info(ruObj, "Marked object as", "finalStatus", finalStatus)
+	} else {
+		finalStatus = upgrademgrv1alpha1.StatusError
+		level = EventLevelWarning
+		r.error(ruObj, err, "Marked object as", "finalStatus", finalStatus)
+	}
+
 	endTime := time.Now()
 	ruObj.Status.EndTime = endTime.Format(time.RFC3339)
 	ruObj.Status.CurrentStatus = finalStatus
@@ -580,12 +593,7 @@ func (r *RollingUpgradeReconciler) finishExecution(finalStatus string, nodesProc
 		ruObj.Status.TotalProcessingTime = endTime.Sub(startTime).String()
 	}
 	// end event
-	var level string
-	if finalStatus == upgrademgrv1alpha1.StatusComplete {
-		level = EventLevelNormal
-	} else {
-		level = EventLevelWarning
-	}
+
 	r.createK8sV1Event(ruObj, EventReasonRUFinished, level, map[string]string{
 		"status":   finalStatus,
 		"asgName":  ruObj.Spec.AsgName,
@@ -637,26 +645,26 @@ func (r *RollingUpgradeReconciler) Process(ctx *context.Context,
 	r.CacheConfig.FlushCache("autoscaling")
 	err := r.populateAsg(ruObj)
 	if err != nil {
-		r.finishExecution(upgrademgrv1alpha1.StatusError, 0, ctx, ruObj)
+		r.finishExecution(err, 0, ctx, ruObj)
 		return
 	}
 
 	//TODO(shri): Ensure that no node is Unschedulable at this time.
 	err = r.populateNodeList(ruObj, r.generatedClient.CoreV1().Nodes())
 	if err != nil {
-		r.finishExecution(upgrademgrv1alpha1.StatusError, 0, ctx, ruObj)
+		r.finishExecution(err, 0, ctx, ruObj)
 		return
 	}
 
-	if err := r.populateLaunchTemplates(); err != nil {
-		r.finishExecution(upgrademgrv1alpha1.StatusError, 0, ctx, ruObj)
+	if err := r.populateLaunchTemplates(ruObj); err != nil {
+		r.finishExecution(err, 0, ctx, ruObj)
 		return
 	}
 
 	asg, err := r.GetAutoScalingGroup(ruObj.NamespacedName())
 	if err != nil {
 		r.error(ruObj, err, "Unable to load ASG for rolling upgrade")
-		r.finishExecution(upgrademgrv1alpha1.StatusError, 0, ctx, ruObj)
+		r.finishExecution(err, 0, ctx, ruObj)
 		return
 	}
 
@@ -674,7 +682,7 @@ func (r *RollingUpgradeReconciler) Process(ctx *context.Context,
 	nodesProcessed, err := r.runRestack(ctx, ruObj)
 	if err != nil {
 		r.error(ruObj, err, "Failed to runRestack")
-		r.finishExecution(upgrademgrv1alpha1.StatusError, nodesProcessed, ctx, ruObj)
+		r.finishExecution(err, nodesProcessed, ctx, ruObj)
 		return
 	}
 
@@ -682,11 +690,12 @@ func (r *RollingUpgradeReconciler) Process(ctx *context.Context,
 	r.info(ruObj, "Validating the launch definition of nodes and ASG")
 	if err := r.validateNodesLaunchDefinition(ruObj); err != nil {
 		r.error(ruObj, err, "Launch definition validation failed")
-		r.finishExecution(upgrademgrv1alpha1.StatusError, nodesProcessed, ctx, ruObj)
+		r.finishExecution(err, nodesProcessed, ctx, ruObj)
 		return
 	}
 
-	r.finishExecution(upgrademgrv1alpha1.StatusComplete, nodesProcessed, ctx, ruObj)
+	// no error -> report success
+	r.finishExecution(nil, nodesProcessed, ctx, ruObj)
 }
 
 //Check if ec2Instances and the ASG have same launch config.


Test patch:
diff --git a/controllers/rollingupgrade_controller_test.go b/controllers/rollingupgrade_controller_test.go
index 94bbb5a..8e6c9c1 100644
--- a/controllers/rollingupgrade_controller_test.go
+++ b/controllers/rollingupgrade_controller_test.go
@@ -65,8 +65,9 @@ func TestErrorStatusMarkJanitor(t *testing.T) {
 	}
 
 	ctx := context.TODO()
+	err = fmt.Errorf("execution error")
 	rcRollingUpgrade.inProcessASGs.Store(someAsg, "processing")
-	rcRollingUpgrade.finishExecution(upgrademgrv1alpha1.StatusError, 3, &ctx, instance)
+	rcRollingUpgrade.finishExecution(err, 3, &ctx, instance)
 	g.Expect(instance.ObjectMeta.Annotations[JanitorAnnotation]).To(gomega.Equal(ClearErrorFrequency))
 	_, exists := rcRollingUpgrade.inProcessASGs.Load(someAsg)
 	g.Expect(exists).To(gomega.BeFalse())
@@ -935,7 +936,7 @@ func TestFinishExecutionCompleted(t *testing.T) {
 	ctx := context.TODO()
 	mockNodesProcessed := 3
 
-	rcRollingUpgrade.finishExecution(upgrademgrv1alpha1.StatusComplete, mockNodesProcessed, &ctx, ruObj)
+	rcRollingUpgrade.finishExecution(nil, mockNodesProcessed, &ctx, ruObj)
 
 	g.Expect(ruObj.Status.CurrentStatus).To(gomega.Equal(upgrademgrv1alpha1.StatusComplete))
 	g.Expect(ruObj.Status.NodesProcessed).To(gomega.Equal(mockNodesProcessed))
@@ -970,7 +971,8 @@ func TestFinishExecutionError(t *testing.T) {
 	ctx := context.TODO()
 	mockNodesProcessed := 3
 
-	rcRollingUpgrade.finishExecution(upgrademgrv1alpha1.StatusError, mockNodesProcessed, &ctx, ruObj)
+	err = fmt.Errorf("execution error")
+	rcRollingUpgrade.finishExecution(err, mockNodesProcessed, &ctx, ruObj)
 
 	g.Expect(ruObj.Status.CurrentStatus).To(gomega.Equal(upgrademgrv1alpha1.StatusError))
 	g.Expect(ruObj.Status.NodesProcessed).To(gomega.Equal(mockNodesProcessed))