only set the build timestamps exactly once

pkg/build/controller/build/build_controller.go

@@ -551,13 +551,9 @@ func (bc *BuildController) handleActiveBuild(build *buildapi.Build, pod *v1.Pod)
 	return update, nil
 }
 
-// handleCompletedBuild will only be called on builds that are already in a terminal phase however, their completion timestamp
-// has not been set.
+// handleCompletedBuild will only be called on builds that are already in a terminal phase.  It is used to setup the
+// completion timestamp and failure logsnippet as needed.
 func (bc *BuildController) handleCompletedBuild(build *buildapi.Build, pod *v1.Pod) (*buildUpdate, error) {
-	// No-op if the completion timestamp and logsnippet data(for failed builds only) has already been set
-	if build.Status.CompletionTimestamp != nil && (len(build.Status.LogSnippet) > 0 || build.Status.Phase != buildapi.BuildPhaseFailed) {
-		return nil, nil
-	}
 
 	update := &buildUpdate{}
 	setBuildCompletionData(build, pod, update)
@@ -823,25 +819,25 @@ func isValidTransition(from, to buildapi.BuildPhase) bool {
 // if applicable.
 func setBuildCompletionData(build *buildapi.Build, pod *v1.Pod, update *buildUpdate) {
 	now := metav1.Now()
-	update.setCompletionTime(now)
-
-	var podStartTime *metav1.Time
-	if pod != nil {
-		podStartTime = pod.Status.StartTime
-	}
 
 	startTime := build.Status.StartTimestamp
 	if startTime == nil {
-		if podStartTime != nil {
-			startTime = podStartTime
-		} else {
+		if pod != nil {
+			startTime = pod.Status.StartTime
+		}
+
+		if startTime == nil {
 			startTime = &now
 		}
 		update.setStartTime(*startTime)
 	}
-	update.setDuration(now.Rfc3339Copy().Time.Sub(startTime.Rfc3339Copy().Time))
+	if build.Status.CompletionTimestamp == nil {
+		update.setCompletionTime(now)
+		update.setDuration(now.Rfc3339Copy().Time.Sub(startTime.Rfc3339Copy().Time))
+	}
 
-	if pod != nil && len(pod.Status.ContainerStatuses) != 0 && pod.Status.ContainerStatuses[0].State.Terminated != nil {
+	if build.Status.Phase == buildapi.BuildPhaseFailed && len(build.Status.LogSnippet) == 0 &&
+		pod != nil && len(pod.Status.ContainerStatuses) != 0 && pod.Status.ContainerStatuses[0].State.Terminated != nil {
 		msg := pod.Status.ContainerStatuses[0].State.Terminated.Message
 		if len(msg) != 0 {
 			parts := strings.Split(strings.TrimRight(msg, "\n"), "\n")

pkg/build/controller/build/build_controller_test.go

@@ -44,7 +44,9 @@ import (
 // TestHandleBuild is the main test for build updates through the controller
 func TestHandleBuild(t *testing.T) {
 
-	now := metav1.Now()
+	// patch appears to drop sub-second accuracy from times, which causes problems
+	// during equality testing later, so start with a rounded number of seconds for a time.
+	now := metav1.NewTime(time.Now().Round(time.Second))
 	before := metav1.NewTime(now.Time.Add(-1 * time.Hour))
 
 	build := func(phase buildapi.BuildPhase) *buildapi.Build {
@@ -59,8 +61,20 @@ func TestHandleBuild(t *testing.T) {
 		p := mockBuildPod(build(buildapi.BuildPhaseNew))
 		p.Status.Phase = phase
 		switch phase {
-		case v1.PodRunning, v1.PodFailed:
+		case v1.PodRunning:
+			p.Status.StartTime = &now
+		case v1.PodFailed:
 			p.Status.StartTime = &now
+			p.Status.ContainerStatuses = []v1.ContainerStatus{
+				{
+					Name: "container",
+					State: v1.ContainerState{
+						Terminated: &v1.ContainerStateTerminated{
+							ExitCode: 1,
+						},
+					},
+				},
+			}
 		case v1.PodSucceeded:
 			p.Status.StartTime = &now
 			p.Status.ContainerStatuses = []v1.ContainerStatus{
@@ -76,6 +90,15 @@ func TestHandleBuild(t *testing.T) {
 		}
 		return p
 	}
+	withTerminationMessage := func(pod *v1.Pod) *v1.Pod {
+		pod.Status.ContainerStatuses[0].State.Terminated.Message = "termination message"
+		return pod
+	}
+	withPodCreationTS := func(pod *v1.Pod, tm metav1.Time) *v1.Pod {
+		pod.CreationTimestamp = tm
+		return pod
+	}
+
 	cancelled := func(build *buildapi.Build) *buildapi.Build {
 		build.Status.Cancelled = true
 		return build
@@ -88,9 +111,9 @@ func TestHandleBuild(t *testing.T) {
 		build.CreationTimestamp = tm
 		return build
 	}
-	withPodCreationTS := func(pod *v1.Pod, tm metav1.Time) *v1.Pod {
-		pod.CreationTimestamp = tm
-		return pod
+	withLogSnippet := func(build *buildapi.Build) *buildapi.Build {
+		build.Status.LogSnippet = "termination message"
+		return build
 	}
 
 	tests := []struct {
@@ -267,16 +290,22 @@ func TestHandleBuild(t *testing.T) {
 				update,
 		},
 		{
-			name:             "failed -> failed with completion timestamp+message",
-			build:            withCompletionTS(build(buildapi.BuildPhaseFailed)),
-			pod:              pod(v1.PodFailed),
-			expectOnComplete: true,
+			name:  "failed -> failed with completion timestamp+message and no logsnippet",
+			build: withCompletionTS(build(buildapi.BuildPhaseFailed)),
+			pod:   withTerminationMessage(pod(v1.PodFailed)),
+			// no oncomplete call because the completion timestamp is already set.
+			expectOnComplete: false,
 			expectUpdate: newUpdate().
 				startTime(now).
-				completionTime(now).
-				logSnippet("").
+				logSnippet("termination message").
 				update,
 		},
+		{
+			name:             "failed -> failed with completion timestamp+message and logsnippet",
+			build:            withLogSnippet(withCompletionTS(build(buildapi.BuildPhaseFailed))),
+			pod:              withTerminationMessage(pod(v1.PodFailed)),
+			expectOnComplete: false,
+		},
 	}
 
 	for _, tc := range tests {