Change LastFinished to LastUpdatedTimestamp, timestamp every plan sta…

…tus change (#1365)

Timestamp any changes to the status of a particular plan in order to
help human operators with troubleshooting and debugging a KUDO Operator.
This is a breaking change as it renames (repurposes) `LastFinished`.

Update the CLI so that this is displayed for a given plan, if set.

Signed-off-by: Nick Jones <nick@dischord.org>

config/crds/kudo.dev_instances.yaml

@@ -120,7 +120,7 @@ spec:
                   \      v                       v | Fatal error |        |    Complete
                   \   |"
                 properties:
-                  lastFinishedRun:
+                  lastUpdatedTimestamp:
                     format: date-time
                     nullable: true
                     type: string

pkg/apis/kudo/v1beta1/instance_types.go

@@ -17,6 +17,7 @@ package v1beta1
 
 import (
 	"fmt"
+	"time"
 
 	corev1 "k8s.io/api/core/v1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -89,9 +90,9 @@ type PlanStatus struct {
 	Status  ExecutionStatus `json:"status,omitempty"`
 	Message string          `json:"message,omitempty"` // more verbose explanation of the status, e.g. a detailed error message
 	// +nullable
-	LastFinishedRun *metav1.Time          `json:"lastFinishedRun,omitempty"`
-	Phases          []PhaseStatus         `json:"phases,omitempty"`
-	UID             apimachinerytypes.UID `json:"uid,omitempty"`
+	LastUpdatedTimestamp *metav1.Time          `json:"lastUpdatedTimestamp,omitempty"`
+	Phases               []PhaseStatus         `json:"phases,omitempty"`
+	UID                  apimachinerytypes.UID `json:"uid,omitempty"`
 }
 
 // PhaseStatus is representing status of a phase
@@ -130,11 +131,13 @@ func (s *PhaseStatus) SetWithMessage(status ExecutionStatus, message string) {
 }
 
 func (s *PlanStatus) Set(status ExecutionStatus) {
+	s.LastUpdatedTimestamp = &metav1.Time{Time: time.Now()}
 	s.Status = status
 	s.Message = ""
 }
 
 func (s *PlanStatus) SetWithMessage(status ExecutionStatus, message string) {
+	s.LastUpdatedTimestamp = &metav1.Time{Time: time.Now()}
 	s.Status = status
 	s.Message = message
 }

pkg/apis/kudo/v1beta1/instance_types_helpers.go

@@ -2,7 +2,9 @@ package v1beta1
 
 import (
 	"fmt"
+	"time"
 
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/util/uuid"
 
 	"github.com/kudobuilder/kudo/pkg/util/kudo"
@@ -57,6 +59,7 @@ func (i *Instance) NoPlanEverExecuted() bool {
 func (i *Instance) UpdateInstanceStatus(planStatus *PlanStatus) {
 	for k, v := range i.Status.PlanStatus {
 		if v.Name == planStatus.Name {
+			planStatus.LastUpdatedTimestamp = &metav1.Time{Time: time.Now()}
 			i.Status.PlanStatus[k] = *planStatus
 			i.Status.AggregatedStatus.Status = planStatus.Status
 			if planStatus.Status.IsTerminal() {
@@ -118,10 +121,10 @@ func (i *Instance) PlanStatus(plan string) *PlanStatus {
 
 // wasRunAfter returns true if p1 was run after p2
 func wasRunAfter(p1 PlanStatus, p2 PlanStatus) bool {
-	if p1.Status == ExecutionNeverRun || p2.Status == ExecutionNeverRun || p1.LastFinishedRun == nil || p2.LastFinishedRun == nil {
+	if p1.Status == ExecutionNeverRun || p2.Status == ExecutionNeverRun || p1.LastUpdatedTimestamp == nil || p2.LastUpdatedTimestamp == nil {
 		return false
 	}
-	return p1.LastFinishedRun.Time.After(p2.LastFinishedRun.Time)
+	return p1.LastUpdatedTimestamp.Time.After(p2.LastUpdatedTimestamp.Time)
 }
 
 // GetParamDefinitions retrieves parameter metadata from OperatorVersion CRD

pkg/apis/kudo/v1beta1/instance_types_helpers_test.go

@@ -54,16 +54,16 @@ func TestGetLastExecutedPlanStatus(t *testing.T) {
 			}}, "test"},
 		{"last executed plan", map[string]PlanStatus{
 			"test": {
-				Status:          ExecutionComplete,
-				Name:            "test",
-				LastFinishedRun: &metav1.Time{Time: testTime},
-				Phases:          []PhaseStatus{{Name: "phase", Status: ExecutionComplete, Steps: []StepStatus{{Status: ExecutionComplete, Name: "step"}}}},
+				Status:               ExecutionComplete,
+				Name:                 "test",
+				LastUpdatedTimestamp: &metav1.Time{Time: testTime},
+				Phases:               []PhaseStatus{{Name: "phase", Status: ExecutionComplete, Steps: []StepStatus{{Status: ExecutionComplete, Name: "step"}}}},
 			},
 			"test2": {
-				Status:          ExecutionComplete,
-				Name:            "test2",
-				LastFinishedRun: &metav1.Time{Time: testTime.Add(time.Hour)},
-				Phases:          []PhaseStatus{{Name: "phase", Status: ExecutionComplete, Steps: []StepStatus{{Status: ExecutionComplete, Name: "step"}}}},
+				Status:               ExecutionComplete,
+				Name:                 "test2",
+				LastUpdatedTimestamp: &metav1.Time{Time: testTime.Add(time.Hour)},
+				Phases:               []PhaseStatus{{Name: "phase", Status: ExecutionComplete, Steps: []StepStatus{{Status: ExecutionComplete, Name: "step"}}}},
 			}}, "test2"},
 	}
 
@@ -103,11 +103,11 @@ func TestInstance_ResetPlanStatus(t *testing.T) {
 		Status: InstanceStatus{
 			PlanStatus: map[string]PlanStatus{
 				"deploy": {
-					Status:          ExecutionInProgress,
-					Name:            "deploy",
-					LastFinishedRun: &metav1.Time{Time: testTime},
-					UID:             testUUID,
-					Phases:          []PhaseStatus{{Name: "phase", Status: ExecutionInProgress, Steps: []StepStatus{{Status: ExecutionInProgress, Name: "step"}}}},
+					Status:               ExecutionInProgress,
+					Name:                 "deploy",
+					LastUpdatedTimestamp: &metav1.Time{Time: testTime},
+					UID:                  testUUID,
+					Phases:               []PhaseStatus{{Name: "phase", Status: ExecutionInProgress, Steps: []StepStatus{{Status: ExecutionInProgress, Name: "step"}}}},
 				},
 				"update": {
 					Status: ExecutionNeverRun,
@@ -133,6 +133,7 @@ func TestInstance_ResetPlanStatus(t *testing.T) {
 	oldPlanStatus := instance.Status.PlanStatus["deploy"]
 	statusCopy := oldPlanStatus.DeepCopy()
 	statusCopy.UID = testUUID
+	statusCopy.LastUpdatedTimestamp = &metav1.Time{Time: testTime}
 	instance.Status.PlanStatus["deploy"] = *statusCopy
 
 	// Expected:
@@ -142,11 +143,11 @@ func TestInstance_ResetPlanStatus(t *testing.T) {
 	assert.Equal(t, InstanceStatus{
 		PlanStatus: map[string]PlanStatus{
 			"deploy": {
-				Status:          ExecutionPending,
-				Name:            "deploy",
-				LastFinishedRun: &metav1.Time{Time: testTime},
-				UID:             testUUID,
-				Phases:          []PhaseStatus{{Name: "phase", Status: ExecutionPending, Steps: []StepStatus{{Status: ExecutionPending, Name: "step"}}}},
+				Status:               ExecutionPending,
+				Name:                 "deploy",
+				LastUpdatedTimestamp: &metav1.Time{Time: testTime},
+				UID:                  testUUID,
+				Phases:               []PhaseStatus{{Name: "phase", Status: ExecutionPending, Steps: []StepStatus{{Status: ExecutionPending, Name: "step"}}}},
 			},
 			"update": {
 				Status: ExecutionNeverRun,

pkg/controller/instance/instance_controller.go

@@ -22,7 +22,6 @@ import (
 	"fmt"
 	"log"
 	"reflect"
-	"time"
 
 	"k8s.io/apimachinery/pkg/util/uuid"
 	"k8s.io/client-go/discovery"
@@ -238,7 +237,7 @@ func (r *Reconciler) Reconcile(request ctrl.Request) (ctrl.Result, error) {
 		return reconcile.Result{}, err
 	}
 	log.Printf("InstanceController: Going to proceed in execution of active plan %s on instance %s/%s", activePlan.Name, instance.Namespace, instance.Name)
-	newStatus, err := workflow.Execute(activePlan, metadata, r.Client, r.Discovery, r.Config, &renderer.DefaultEnhancer{Scheme: r.Scheme, Discovery: r.Discovery}, time.Now())
+	newStatus, err := workflow.Execute(activePlan, metadata, r.Client, r.Discovery, r.Config, &renderer.DefaultEnhancer{Scheme: r.Scheme, Discovery: r.Discovery})
 
 	// ---------- 5. Update status of instance after the execution proceeded ----------
 	if newStatus != nil {

pkg/engine/workflow/engine.go

@@ -5,9 +5,7 @@ import (
 	"fmt"
 	"log"
 	"strings"
-	"time"
 
-	v1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/client-go/discovery"
 	"k8s.io/client-go/rest"
 	"sigs.k8s.io/controller-runtime/pkg/client"
@@ -65,7 +63,7 @@ func (ap *ActivePlan) taskByName(name string) (*v1beta1.Task, bool) {
 //
 // Furthermore, a transient ERROR during a step execution, means that the next step may be executed if the step strategy
 // is "parallel". In case of a fatal error, it is returned alongside with the new plan status and published on the event bus.
-func Execute(pl *ActivePlan, em *engine.Metadata, c client.Client, di discovery.DiscoveryInterface, config *rest.Config, enh renderer.Enhancer, currentTime time.Time) (*v1beta1.PlanStatus, error) {
+func Execute(pl *ActivePlan, em *engine.Metadata, c client.Client, di discovery.DiscoveryInterface, config *rest.Config, enh renderer.Enhancer) (*v1beta1.PlanStatus, error) {
 	if pl.Status.IsTerminal() {
 		log.Printf("PlanExecution: %s/%s plan %s is terminal, nothing to do", em.InstanceNamespace, em.InstanceName, pl.Name)
 		return pl.PlanStatus, nil
@@ -227,7 +225,6 @@ func Execute(pl *ActivePlan, em *engine.Metadata, c client.Client, di discovery.
 	if phasesLeft == 0 {
 		log.Printf("PlanExecution: %s/%s all phases of the plan %s are ready", em.InstanceNamespace, em.InstanceName, pl.Name)
 		planStatus.Set(v1beta1.ExecutionComplete)
-		planStatus.LastFinishedRun = &v1.Time{Time: currentTime}
 	}
 
 	return planStatus, nil