Add pod start time (#322)

* Rename startTime -> creationTime

* add build actual start time to status

* Add comments and fix tests

* Refactor start time function

* Fix error msgs

* Update test setup

- Set creation time to now()-buffer to trigger timeout when updating build status

* Remove unnecessary test setup for timeout

* Add example with bad node selector

* Address comments

- Re-arrange imports
- Remove builder from custom columns txt

pkg/apis/build/v1alpha1/build_types.go

@@ -189,7 +189,9 @@ type BuildStatus struct {
 	// Google provides additional information if the builder is Google.
 	Google *GoogleSpec `json:"google,omitempty"`
 
-	// StartTime is the time the build started.
+	// Creation is the time the build is created.
+	CreationTime metav1.Time `json:"creationTime,omitEmpty"`
+	// StartTime is the time the build is actually started.
 	StartTime metav1.Time `json:"startTime,omitEmpty"`
 	// CompletionTime is the time the build completed.
 	CompletionTime metav1.Time `json:"completionTime,omitEmpty"`
@@ -198,7 +200,7 @@ type BuildStatus struct {
 	StepStates []corev1.ContainerState `json:"stepStates,omitEmpty"`
 	// Conditions describes the set of conditions of this build.
 	Conditions []BuildCondition `json:"conditions,omitempty"`
-
+	// StepsCompleted lists the name of build steps completed.
 	StepsCompleted []string `json:"stepsCompleted"`
 }
 

pkg/builder/cluster/builder.go

@@ -21,16 +21,17 @@ import (
 	"fmt"
 	"sync"
 
+	"github.com/knative/build/pkg/builder/cluster/convert"
 	"go.uber.org/zap"
 	corev1 "k8s.io/api/core/v1"
+	"k8s.io/apimachinery/pkg/api/errors"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	kubeinformers "k8s.io/client-go/informers"
 	"k8s.io/client-go/kubernetes"
 	"k8s.io/client-go/tools/cache"
 
 	v1alpha1 "github.com/knative/build/pkg/apis/build/v1alpha1"
 	buildercommon "github.com/knative/build/pkg/builder"
-	"github.com/knative/build/pkg/builder/cluster/convert"
 )
 
 type operation struct {
@@ -52,7 +53,8 @@ func (op *operation) Checkpoint(status *v1alpha1.BuildStatus) error {
 	}
 	status.Cluster.Namespace = op.namespace
 	status.Cluster.PodName = op.Name()
-	status.StartTime = op.startTime
+	status.CreationTime = op.startTime
+	status.StartTime = op.builder.podCreationTime
 	status.StepStates = nil
 	status.StepsCompleted = nil
 	for _, s := range op.statuses {
@@ -70,7 +72,17 @@ func (op *operation) Checkpoint(status *v1alpha1.BuildStatus) error {
 }
 
 func (op *operation) Terminate() error {
-	return op.builder.kubeclient.CoreV1().Pods(op.namespace).Delete(op.name, &metav1.DeleteOptions{})
+	if err := op.builder.kubeclient.CoreV1().Pods(op.namespace).Delete(op.name, &metav1.DeleteOptions{}); err != nil && !errors.IsNotFound(err) {
+		return err
+	}
+	return nil
+}
+
+func getStartTime(m *metav1.Time) metav1.Time {
+	if m == nil {
+		return metav1.Time{}
+	}
+	return *m
 }
 
 func (op *operation) Wait() (*v1alpha1.BuildStatus, error) {
@@ -101,7 +113,8 @@ func (op *operation) Wait() (*v1alpha1.BuildStatus, error) {
 			Namespace: op.namespace,
 			PodName:   op.Name(),
 		},
-		StartTime:      op.startTime,
+		CreationTime:   op.startTime,
+		StartTime:      op.builder.podCreationTime,
 		CompletionTime: metav1.Now(),
 		StepStates:     states,
 		StepsCompleted: stepsCompleted,
@@ -177,8 +190,9 @@ type builder struct {
 	// send a completion notification when we see that Pod complete.
 	// On success, an empty string is sent.
 	// On failure, the Message of the failure PodCondition is sent.
-	callbacks map[string]chan *corev1.Pod
-	logger    *zap.SugaredLogger
+	callbacks       map[string]chan *corev1.Pod
+	logger          *zap.SugaredLogger
+	podCreationTime metav1.Time
 }
 
 func (b *builder) Builder() v1alpha1.BuildProvider {
@@ -212,12 +226,12 @@ func (b *builder) OperationFromStatus(status *v1alpha1.BuildStatus) (buildercomm
 	for _, state := range status.StepStates {
 		statuses = append(statuses, corev1.ContainerStatus{State: state})
 	}
-
+	b.podCreationTime = status.CreationTime
 	return &operation{
 		builder:   b,
 		namespace: status.Cluster.Namespace,
 		name:      status.Cluster.PodName,
-		startTime: status.StartTime,
+		startTime: status.CreationTime,
 		statuses:  statuses,
 	}, nil
 }
@@ -253,6 +267,7 @@ func (b *builder) addPodEvent(obj interface{}) {
 	b.mux.Lock()
 	defer b.mux.Unlock()
 	key := getKey(pod.Namespace, pod.Name)
+	b.podCreationTime = getStartTime(pod.Status.StartTime)
 
 	if ch, ok := b.callbacks[key]; ok {
 		// Send the person listening the message.

pkg/builder/cluster/builder_test.go

@@ -67,12 +67,15 @@ func TestBasicFlow(t *testing.T) {
 	if buildercommon.IsDone(&bs) {
 		t.Errorf("IsDone(%v); wanted not done, got done.", bs)
 	}
-	if bs.StartTime.IsZero() {
-		t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
+	if bs.CreationTime.IsZero() {
+		t.Errorf("bs.CreationTime; want zero, got %v", bs.CreationTime)
 	}
 	if !bs.CompletionTime.IsZero() {
 		t.Errorf("bs.CompletionTime; want zero, got %v", bs.CompletionTime)
 	}
+	if !bs.StartTime.IsZero() {
+		t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
+	}
 	op, err = builder.OperationFromStatus(&bs)
 	if err != nil {
 		t.Fatalf("Unexpected error executing OperationFromStatus: %v", err)
@@ -101,11 +104,14 @@ func TestBasicFlow(t *testing.T) {
 		if msg, failed := buildercommon.ErrorMessage(status); failed {
 			t.Errorf("ErrorMessage(%v); wanted not failed, got %q", status, msg)
 		}
+		if status.CompletionTime.IsZero() {
+			t.Errorf("status.CompletionTime; want non-zero, got %v", status.CompletionTime)
+		}
 		if status.StartTime.IsZero() {
 			t.Errorf("status.StartTime; want non-zero, got %v", status.StartTime)
 		}
-		if status.CompletionTime.IsZero() {
-			t.Errorf("status.CompletionTime; want non-zero, got %v", status.CompletionTime)
+		if status.CreationTime.IsZero() {
+			t.Errorf("status.CreationTime; want non-zero, got %v", status.CreationTime)
 		}
 	}()
 	// Wait until the test thread is ready for us to update things.
@@ -117,6 +123,8 @@ func TestBasicFlow(t *testing.T) {
 	if err != nil {
 		t.Fatalf("Unexpected error fetching Pod: %v", err)
 	}
+	pod.Status.StartTime = &metav1.Time{Time: time.Now()}
+
 	// Now modify it to look done.
 	pod.Status.Phase = corev1.PodSucceeded
 	pod, err = podsclient.Update(pod)
@@ -162,12 +170,15 @@ func TestNonFinalUpdateFlow(t *testing.T) {
 	if buildercommon.IsDone(&bs) {
 		t.Errorf("IsDone(%v); wanted not done, got done.", bs)
 	}
-	if bs.StartTime.IsZero() {
-		t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
+	if bs.CreationTime.IsZero() {
+		t.Errorf("bs.CreationTime; want zero, got %v", bs.CreationTime)
 	}
 	if !bs.CompletionTime.IsZero() {
 		t.Errorf("bs.CompletionTime; want zero, got %v", bs.CompletionTime)
 	}
+	if !bs.StartTime.IsZero() {
+		t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
+	}
 	op, err = builder.OperationFromStatus(&bs)
 	if err != nil {
 		t.Fatalf("Unexpected error executing OperationFromStatus: %v", err)
@@ -185,8 +196,8 @@ func TestNonFinalUpdateFlow(t *testing.T) {
 		if err != nil {
 			t.Fatalf("Unexpected error waiting for builder.Operation: %v", err)
 		}
-		if status.StartTime.IsZero() {
-			t.Errorf("status.StartTime; want non-zero, got %v", status.StartTime)
+		if status.CreationTime.IsZero() {
+			t.Errorf("status.CreationTime; want non-zero, got %v", status.CreationTime)
 		}
 		if status.CompletionTime.IsZero() {
 			t.Errorf("status.CompletionTime; want non-zero, got %v", status.CompletionTime)
@@ -203,6 +214,8 @@ func TestNonFinalUpdateFlow(t *testing.T) {
 	}
 	// Make a non-terminal modification
 	pod.Status.Phase = corev1.PodRunning
+	pod.Status.StartTime = &metav1.Time{Time: time.Now()}
+
 	pod, err = podsclient.Update(pod)
 	if err != nil {
 		t.Fatalf("Unexpected error updating Pod: %v", err)
@@ -254,12 +267,15 @@ func TestFailureFlow(t *testing.T) {
 	if buildercommon.IsDone(&bs) {
 		t.Errorf("IsDone(%v); wanted not done, got done.", bs)
 	}
-	if bs.StartTime.IsZero() {
-		t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
+	if bs.CreationTime.IsZero() {
+		t.Errorf("bs.CreationTime; want zero, got %v", bs.CreationTime)
 	}
 	if !bs.CompletionTime.IsZero() {
 		t.Errorf("bs.CompletionTime; want zero, got %v", bs.CompletionTime)
 	}
+	if !bs.StartTime.IsZero() {
+		t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
+	}
 	op, err = builder.OperationFromStatus(&bs)
 	if err != nil {
 		t.Fatalf("Unexpected error executing OperationFromStatus: %v", err)
@@ -288,12 +304,15 @@ func TestFailureFlow(t *testing.T) {
 		if msg, failed := buildercommon.ErrorMessage(status); !failed || msg != expectedErrorMessage {
 			t.Errorf("ErrorMessage(%v); wanted %q, got %q", status, expectedErrorMessage, msg)
 		}
-		if status.StartTime.IsZero() {
-			t.Errorf("status.StartTime; want non-zero, got %v", status.StartTime)
+		if status.CreationTime.IsZero() {
+			t.Errorf("status.CreationTime; want non-zero, got %v", status.CreationTime)
 		}
 		if status.CompletionTime.IsZero() {
 			t.Errorf("status.CompletionTime; want non-zero, got %v", status.CompletionTime)
 		}
+		if status.StartTime.IsZero() {
+			t.Errorf("status.StartTime; want non-zero, got %v", status.StartTime)
+		}
 		if len(status.StepStates) != 1 {
 			t.Errorf("StepStates contained %d states, want 1: %+v", len(status.StepStates), status.StepStates)
 		} else if status.StepStates[0].Terminated.Reason != expectedErrorReason {
@@ -319,6 +338,7 @@ func TestFailureFlow(t *testing.T) {
 			},
 		},
 	}}
+	pod.Status.StartTime = &metav1.Time{Time: time.Now()}
 	pod, err = podsclient.Update(pod)
 	if err != nil {
 		t.Fatalf("Unexpected error updating Pod: %v", err)
@@ -352,12 +372,15 @@ func TestPodPendingFlow(t *testing.T) {
 	if buildercommon.IsDone(&bs) {
 		t.Errorf("IsDone(%v); wanted not done, got done.", bs)
 	}
-	if bs.StartTime.IsZero() {
-		t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
+	if bs.CreationTime.IsZero() {
+		t.Errorf("bs.CreationTime; want zero, got %v", bs.CreationTime)
 	}
 	if !bs.CompletionTime.IsZero() {
 		t.Errorf("bs.CompletionTime; want zero, got %v", bs.CompletionTime)
 	}
+	if !bs.StartTime.IsZero() {
+		t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
+	}
 	op, err = builder.OperationFromStatus(&bs)
 	if err != nil {
 		t.Fatalf("Unexpected error executing OperationFromStatus: %v", err)
@@ -386,6 +409,9 @@ func TestPodPendingFlow(t *testing.T) {
 		if msg := statusMessage(status); msg != expectedPendingMsg {
 			t.Errorf("ErrorMessage(%v); wanted %q, got %q", status, expectedPendingMsg, msg)
 		}
+		if status.CreationTime.IsZero() {
+			t.Errorf("status.CreationTime; want non-zero, got %v", status.CreationTime)
+		}
 		if status.StartTime.IsZero() {
 			t.Errorf("status.StartTime; want non-zero, got %v", status.StartTime)
 		}
@@ -418,6 +444,7 @@ func TestPodPendingFlow(t *testing.T) {
 			},
 		},
 	}}
+	pod.Status.StartTime = &metav1.Time{Time: time.Now()}
 	pod, err = podsclient.Update(pod)
 	if err != nil {
 		t.Fatalf("Unexpected error updating Pod: %v", err)
@@ -459,7 +486,10 @@ func TestStepFailureFlow(t *testing.T) {
 	if buildercommon.IsDone(&bs) {
 		t.Errorf("IsDone(%v); wanted not done, got done.", bs)
 	}
-	if bs.StartTime.IsZero() {
+	if bs.CreationTime.IsZero() {
+		t.Errorf("bs.CreationTime; want zero, got %v", bs.CreationTime)
+	}
+	if !bs.StartTime.IsZero() {
 		t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
 	}
 	if !bs.CompletionTime.IsZero() {
@@ -495,6 +525,9 @@ func TestStepFailureFlow(t *testing.T) {
 			!strings.Contains(msg, `"step-name"`) || !strings.Contains(msg, "128") {
 			t.Errorf("ErrorMessage(%v); got %q, want %q", status, msg, expectedErrorMessage)
 		}
+		if status.CreationTime.IsZero() {
+			t.Errorf("status.CreationTime; got %v, want non-zero", status.CreationTime)
+		}
 		if status.StartTime.IsZero() {
 			t.Errorf("status.StartTime; got %v, want non-zero", status.StartTime)
 		}
@@ -523,6 +556,7 @@ func TestStepFailureFlow(t *testing.T) {
 		ImageID: "docker-pullable://ubuntu@sha256:deadbeef",
 	}}
 	pod.Status.Message = "don't expect this!"
+	pod.Status.StartTime = &metav1.Time{Time: time.Now()}
 
 	pod, err = podsclient.Update(pod)
 	if err != nil {

pkg/builder/interface.go

@@ -92,8 +92,7 @@ func IsTimeout(status *v1alpha1.BuildStatus, buildTimeout string) bool {
 			return false
 		}
 	}
-
-	return time.Since(status.StartTime.Time).Seconds() > timeout.Seconds()
+	return time.Since(status.CreationTime.Time).Seconds() > timeout.Seconds()
 }
 
 // ErrorMessage returns the error message from the status.

pkg/builder/nop/builder.go

@@ -47,6 +47,7 @@ func (nb *operation) Checkpoint(status *v1alpha1.BuildStatus) error {
 		status.Google = &v1alpha1.GoogleSpec{}
 	}
 	status.Google.Operation = nb.Name()
+	status.CreationTime = startTime
 	status.StartTime = startTime
 	status.SetCondition(&v1alpha1.BuildCondition{
 		Type:   v1alpha1.BuildSucceeded,
@@ -67,6 +68,7 @@ func (nb *operation) Wait() (*v1alpha1.BuildStatus, error) {
 		Google: &v1alpha1.GoogleSpec{
 			Operation: nb.Name(),
 		},
+		CreationTime:   startTime,
 		StartTime:      startTime,
 		CompletionTime: completionTime,
 	}

pkg/builder/nop/builder_test.go

@@ -45,6 +45,9 @@ func TestBasicFlow(t *testing.T) {
 	if err != nil {
 		t.Fatalf("Unexpected error executing OperationFromStatus: %v", err)
 	}
+	if bs.CreationTime.IsZero() {
+		t.Errorf("bs.CreationTime; want non-zero, got %v", bs.CreationTime)
+	}
 	if bs.StartTime.IsZero() {
 		t.Errorf("bs.StartTime; want non-zero, got %v", bs.StartTime)
 	}
@@ -67,6 +70,9 @@ func TestBasicFlow(t *testing.T) {
 	if msg, failed := buildercommon.ErrorMessage(status); failed {
 		t.Errorf("ErrorMessage(%v); wanted not failed, got %q", status, msg)
 	}
+	if status.CreationTime.IsZero() {
+		t.Errorf("status.CreationTime; want non-zero, got %v", status.CreationTime)
+	}
 	if status.StartTime.IsZero() {
 		t.Errorf("status.StartTime; want non-zero, got %v", status.StartTime)
 	}

pkg/controller/build/controller_test.go

@@ -145,7 +145,7 @@ func TestBasicFlows(t *testing.T) {
 			t.Errorf("error fetching build: %v", err)
 		}
 		// Update status to current time
-		first.Status.StartTime = metav1.Now()
+		first.Status.CreationTime = metav1.Now()
 
 		if builder.IsDone(&first.Status) {
 			t.Errorf("First IsDone(%d); wanted not done, got done.", idx)
@@ -232,12 +232,11 @@ func TestTimeoutFlows(t *testing.T) {
 	bldr := &nop.Builder{}
 
 	build := newBuild("test")
-	addBuffer, err := time.ParseDuration("10m")
+	buffer, err := time.ParseDuration("10m")
 	if err != nil {
 		t.Errorf("Error parsing duration")
 	}
 
-	build.Status.StartTime.Time = metav1.Now().Time.Add(-addBuffer)
 	build.Spec.Timeout = "1s"
 
 	f := &fixture{
@@ -268,10 +267,9 @@ func TestTimeoutFlows(t *testing.T) {
 	if err != nil {
 		t.Errorf("error fetching build: %v", err)
 	}
-	// Update status to current time
-	//	first.Status.StartTime = metav1.Now()
-	first.Status.StartTime.Time = metav1.Now().Time.Add(-addBuffer)
-	first.Spec.Timeout = "1s"
+
+	// Update status to past time by substracting buffer time
+	first.Status.CreationTime.Time = metav1.Now().Time.Add(-buffer)
 
 	if builder.IsDone(&first.Status) {
 		t.Error("First IsDone; wanted not done, got done.")