tail build logs into build object

Author: bparees

api/protobuf-spec/github_com_openshift_origin_pkg_build_apis_build_v1.proto

@@ -24586,6 +24586,10 @@
        "$ref": "v1.StageInfo"
       },
       "description": "stages contains details about each stage that occurs during the build including start time, duration (in milliseconds), and the steps that occured within each stage."
+     },
+     "logSnippet": {
+      "type": "string",
+      "description": "logSnippet is the last few lines of the build log.  This value is only set for builds that failed."
      }
     }
    },

api/swagger-spec/oapi-v1.json

@@ -82826,6 +82826,10 @@
       "type": "integer",
       "format": "int64"
      },
+     "logSnippet": {
+      "description": "logSnippet is the last few lines of the build log.  This value is only set for builds that failed.",
+      "type": "string"
+     },
      "message": {
       "description": "message is a human-readable message indicating details about why the build has this status.",
       "type": "string"

api/swagger-spec/openshift-openapi-spec.json

@@ -304,6 +304,9 @@ type BuildStatus struct {
 	// including start time, duration (in milliseconds), and the steps that
 	// occured within each stage.
 	Stages []StageInfo
+
+	// LogSnippet is the last few lines of the build log.  This value is only set for builds that failed.
+	LogSnippet string
 }
 
 // StageInfo contains details about a build stage.

pkg/build/apis/build/types.go

@@ -204,6 +204,7 @@ var map_BuildStatus = map[string]string{
 	"config":                     "config is an ObjectReference to the BuildConfig this Build is based on.",
 	"output":                     "output describes the Docker image the build has produced.",
 	"stages":                     "stages contains details about each stage that occurs during the build including start time, duration (in milliseconds), and the steps that occured within each stage.",
+	"logSnippet":                 "logSnippet is the last few lines of the build log.  This value is only set for builds that failed.",
 }
 
 func (BuildStatus) SwaggerDoc() map[string]string {

pkg/build/apis/build/v1/generated.pb.go

@@ -213,6 +213,9 @@ type BuildStatus struct {
 	// including start time, duration (in milliseconds), and the steps that
 	// occured within each stage.
 	Stages []StageInfo `json:"stages,omitempty" protobuf:"bytes,11,opt,name=stages"`
+
+	// logSnippet is the last few lines of the build log.  This value is only set for builds that failed.
+	LogSnippet string `json:"logSnippet,omitempty" protobuf:"bytes,12,opt,name=logSnippet"`
 }
 
 // StageInfo contains details about a build stage.

pkg/build/apis/build/v1/generated.proto

@@ -811,6 +811,7 @@ func autoConvert_v1_BuildStatus_To_build_BuildStatus(in *BuildStatus, out *build
 		return err
 	}
 	out.Stages = *(*[]build.StageInfo)(unsafe.Pointer(&in.Stages))
+	out.LogSnippet = in.LogSnippet
 	return nil
 }
 
@@ -840,6 +841,7 @@ func autoConvert_build_BuildStatus_To_v1_BuildStatus(in *build.BuildStatus, out
 		return err
 	}
 	out.Stages = *(*[]StageInfo)(unsafe.Pointer(&in.Stages))
+	out.LogSnippet = in.LogSnippet
 	return nil
 }
 

pkg/build/apis/build/v1/swagger_doc.go

@@ -2,6 +2,7 @@ package build
 
 import (
 	"fmt"
+	"strings"
 	"time"
 
 	"github.com/golang/glog"
@@ -42,6 +43,9 @@ import (
 
 const (
 	maxRetries = 15
+
+	// maxExcerptLength is the maximum length of the LogSnippet on a build.
+	maxExcerptLength = 5
 )
 
 // BuildController watches builds and synchronizes them with their
@@ -258,15 +262,19 @@ func shouldIgnore(build *buildapi.Build) bool {
 	}
 
 	// If a build is in a terminal state, ignore it; unless it is in a succeeded or failed
-	// state and its completion time is not set, then we should at least attempt to set its
-	// completion time if possible.
+	// state and its completion time or logsnippet is not set, then we should at least attempt to set its
+	// completion time and logsnippet if possible because the build pod may have put the build in
+	// this state and it would have not set the completion timestamp or logsnippet data.
 	if buildutil.IsBuildComplete(build) {
 		switch build.Status.Phase {
-		case buildapi.BuildPhaseComplete,
-			buildapi.BuildPhaseFailed:
+		case buildapi.BuildPhaseComplete:
 			if build.Status.CompletionTimestamp == nil {
 				return false
 			}
+		case buildapi.BuildPhaseFailed:
+			if build.Status.CompletionTimestamp == nil || len(build.Status.LogSnippet) == 0 {
+				return false
+			}
 		}
 		glog.V(4).Infof("Ignoring build %s in completed state", buildDesc(build))
 		return true
@@ -546,17 +554,13 @@ func (bc *BuildController) handleActiveBuild(build *buildapi.Build, pod *v1.Pod)
 // handleCompletedBuild will only be called on builds that are already in a terminal phase however, their completion timestamp
 // has not been set.
 func (bc *BuildController) handleCompletedBuild(build *buildapi.Build, pod *v1.Pod) (*buildUpdate, error) {
-	// Make sure that the completion timestamp has not already been set
-	if build.Status.CompletionTimestamp != nil {
+	// 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{}
-	var podStartTime *metav1.Time
-	if pod != nil {
-		podStartTime = pod.Status.StartTime
-	}
-	setBuildCompletionTimestampAndDuration(build, podStartTime, update)
+	setBuildCompletionData(build, pod, update)
 
 	return update, nil
 }
@@ -595,11 +599,7 @@ func (bc *BuildController) updateBuild(build *buildapi.Build, update *buildUpdat
 
 		// Update build completion timestamp if transitioning to a terminal phase
 		if buildutil.IsTerminalPhase(*update.phase) {
-			var podStartTime *metav1.Time
-			if pod != nil {
-				podStartTime = pod.Status.StartTime
-			}
-			setBuildCompletionTimestampAndDuration(build, podStartTime, update)
+			setBuildCompletionData(build, pod, update)
 		}
 		glog.V(4).Infof("Updating build %s -> %s%s", buildDesc(build), *update.phase, reasonText)
 	}
@@ -637,13 +637,13 @@ func (bc *BuildController) updateBuild(build *buildapi.Build, update *buildUpdat
 // patchBuild generates a patch for the given build and buildUpdate
 // and applies that patch using the REST client
 func (bc *BuildController) patchBuild(build *buildapi.Build, update *buildUpdate) (*buildapi.Build, error) {
-
 	// Create a patch using the buildUpdate object
 	updatedBuild, err := buildutil.BuildDeepCopy(build)
 	if err != nil {
 		return nil, fmt.Errorf("cannot create a deep copy of build %s: %v", buildDesc(build), err)
 	}
 	update.apply(updatedBuild)
+
 	patch, err := validation.CreateBuildPatch(build, updatedBuild)
 	if err != nil {
 		return nil, fmt.Errorf("failed to create a build patch: %v", err)
@@ -818,12 +818,18 @@ func isValidTransition(from, to buildapi.BuildPhase) bool {
 	return true
 }
 
-// setBuildCompletionTimestampAndDuration sets the build completion time and duration as well as the start time
-// if not already set on the given buildUpdate object
-func setBuildCompletionTimestampAndDuration(build *buildapi.Build, podStartTime *metav1.Time, update *buildUpdate) {
+// setBuildCompletionData sets the build completion time and duration as well as the start time
+// if not already set on the given buildUpdate object.  It also sets the log tail data
+// 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 {
@@ -834,4 +840,25 @@ func setBuildCompletionTimestampAndDuration(build *buildapi.Build, podStartTime
 		update.setStartTime(*startTime)
 	}
 	update.setDuration(now.Rfc3339Copy().Time.Sub(startTime.Rfc3339Copy().Time))
+
+	if 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")
+
+			excerptLength := maxExcerptLength
+			if len(parts) < maxExcerptLength {
+				excerptLength = len(parts)
+			}
+			excerpt := parts[len(parts)-excerptLength:]
+			for i, line := range excerpt {
+				if len(line) > 120 {
+					excerpt[i] = line[:58] + "..." + line[len(line)-59:]
+				}
+			}
+			msg = strings.Join(excerpt, "\n")
+			update.setLogSnippet(msg)
+		}
+	}
+
 }

pkg/build/apis/build/v1/types.go

@@ -267,10 +267,15 @@ func TestHandleBuild(t *testing.T) {
 				update,
 		},
 		{
-			name:         "failed -> failed with completion timestamp",
-			build:        withCompletionTS(build(buildapi.BuildPhaseFailed)),
-			pod:          pod(v1.PodFailed),
-			expectUpdate: nil,
+			name:             "failed -> failed with completion timestamp+message",
+			build:            withCompletionTS(build(buildapi.BuildPhaseFailed)),
+			pod:              pod(v1.PodFailed),
+			expectOnComplete: true,
+			expectUpdate: newUpdate().
+				startTime(now).
+				completionTime(now).
+				logSnippet("").
+				update,
 		},
 	}
 
@@ -773,7 +778,9 @@ func TestSetBuildCompletionTimestampAndDuration(t *testing.T) {
 
 	for _, test := range tests {
 		update := &buildUpdate{}
-		setBuildCompletionTimestampAndDuration(test.build, test.podStartTime, update)
+		pod := &v1.Pod{}
+		pod.Status.StartTime = test.podStartTime
+		setBuildCompletionData(test.build, pod, update)
 		// Ensure that only the fields in the expected update are set
 		if test.expected.podNameAnnotation == nil && (test.expected.podNameAnnotation != update.podNameAnnotation) {
 			t.Errorf("%s: podNameAnnotation should not be set", test.name)
@@ -1186,6 +1193,11 @@ func (b *updateBuilder) podNameAnnotation(podName string) *updateBuilder {
 	return b
 }
 
+func (b *updateBuilder) logSnippet(message string) *updateBuilder {
+	b.update.setLogSnippet(message)
+	return b
+}
+
 type fakeRunPolicy struct {
 	notRunnable      bool
 	onCompleteCalled bool

pkg/build/apis/build/v1/zz_generated.conversion.go

@@ -26,6 +26,7 @@ type buildUpdate struct {
 	completionTime    *metav1.Time
 	duration          *time.Duration
 	outputRef         *string
+	logSnippet        *string
 }
 
 func (u *buildUpdate) setPhase(phase buildapi.BuildPhase) {
@@ -60,6 +61,10 @@ func (u *buildUpdate) setPodNameAnnotation(podName string) {
 	u.podNameAnnotation = &podName
 }
 
+func (u *buildUpdate) setLogSnippet(message string) {
+	u.logSnippet = &message
+}
+
 func (u *buildUpdate) reset() {
 	u.podNameAnnotation = nil
 	u.phase = nil
@@ -69,6 +74,7 @@ func (u *buildUpdate) reset() {
 	u.completionTime = nil
 	u.duration = nil
 	u.outputRef = nil
+	u.logSnippet = nil
 }
 
 func (u *buildUpdate) isEmpty() bool {
@@ -79,7 +85,8 @@ func (u *buildUpdate) isEmpty() bool {
 		u.startTime == nil &&
 		u.completionTime == nil &&
 		u.duration == nil &&
-		u.outputRef == nil
+		u.outputRef == nil &&
+		u.logSnippet == nil
 }
 
 func (u *buildUpdate) apply(build *buildapi.Build) {
@@ -107,6 +114,9 @@ func (u *buildUpdate) apply(build *buildapi.Build) {
 	if u.outputRef != nil {
 		build.Status.OutputDockerImageReference = *u.outputRef
 	}
+	if u.logSnippet != nil {
+		build.Status.LogSnippet = *u.logSnippet
+	}
 }
 
 // String returns a string representation of this update
@@ -137,5 +147,8 @@ func (u *buildUpdate) String() string {
 	if u.podNameAnnotation != nil {
 		updates = append(updates, fmt.Sprintf("podName: %q", *u.podNameAnnotation))
 	}
+	if u.logSnippet != nil {
+		updates = append(updates, fmt.Sprintf("logSnippet: %q", *u.logSnippet))
+	}
 	return fmt.Sprintf("buildUpdate(%s)", strings.Join(updates, ", "))
 }

pkg/build/controller/build/build_controller.go

@@ -89,6 +89,7 @@ func (bs *CustomBuildStrategy) CreateBuildPod(build *buildapi.Build) (*v1.Pod, e
 					SecurityContext: &v1.SecurityContext{
 						Privileged: &privileged,
 					},
+					TerminationMessagePolicy: v1.TerminationMessageFallbackToLogsOnError,
 				},
 			},
 			RestartPolicy: v1.RestartPolicyNever,

pkg/build/controller/build/build_controller_test.go

@@ -60,6 +60,7 @@ func (bs *DockerBuildStrategy) CreateBuildPod(build *buildapi.Build) (*v1.Pod, e
 					SecurityContext: &v1.SecurityContext{
 						Privileged: &privileged,
 					},
+					TerminationMessagePolicy: v1.TerminationMessageFallbackToLogsOnError,
 				},
 			},
 			RestartPolicy: v1.RestartPolicyNever,

pkg/build/controller/build/buildupdate.go

@@ -84,6 +84,7 @@ func (bs *SourceBuildStrategy) CreateBuildPod(build *buildapi.Build) (*v1.Pod, e
 						Privileged: &privileged,
 					},
 					Args: []string{},
+					TerminationMessagePolicy: v1.TerminationMessageFallbackToLogsOnError,
 				},
 			},
 			RestartPolicy: v1.RestartPolicyNever,

pkg/build/controller/strategy/custom.go

@@ -170,7 +170,9 @@ func (d *BuildDescriber) Describe(namespace, name string, settings kprinters.Des
 
 		describeCommonSpec(build.Spec.CommonSpec, out)
 		describeBuildTriggerCauses(build.Spec.TriggeredBy, out)
-
+		if len(build.Status.LogSnippet) != 0 {
+			formatString(out, "Log Tail", build.Status.LogSnippet)
+		}
 		if settings.ShowEvents {
 			kinternalprinters.DescribeEvents(events, kinternalprinters.NewPrefixWriter(out))
 		}

pkg/build/controller/strategy/docker.go

@@ -3084,6 +3084,13 @@ func GetOpenAPIDefinitions(ref openapi.ReferenceCallback) map[string]openapi.Ope
 								},
 							},
 						},
+						"logSnippet": {
+							SchemaProps: spec.SchemaProps{
+								Description: "logSnippet is the last few lines of the build log.  This value is only set for builds that failed.",
+								Type:        []string{"string"},
+								Format:      "",
+							},
+						},
 					},
 					Required: []string{"phase"},
 				},