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."
+     },
+     "logTail": {
+      "type": "string",
+      "description": "LogTail 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"
      },
+     "logTail": {
+      "description": "LogTail 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
+
+	// LogTail is the last few lines of the build log.  This value is only set for builds that failed.
+	LogTail *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.",
+	"logTail":                    "LogTail 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"`
+
+	// LogTail is the last few lines of the build log.  This value is only set for builds that failed.
+	LogTail *string `json:"logTail,omitempty" protobuf:"bytes,12,opt,name=logTail"`
 }
 
 // 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.LogTail = (*string)(unsafe.Pointer(in.LogTail))
 	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.LogTail = (*string)(unsafe.Pointer(in.LogTail))
 	return nil
 }
 

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

@@ -470,6 +470,11 @@ func DeepCopy_v1_BuildStatus(in interface{}, out interface{}, c *conversion.Clon
 				}
 			}
 		}
+		if in.LogTail != nil {
+			in, out := &in.LogTail, &out.LogTail
+			*out = new(string)
+			**out = **in
+		}
 		return nil
 	}
 }

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

@@ -471,6 +471,11 @@ func DeepCopy_build_BuildStatus(in interface{}, out interface{}, c *conversion.C
 				}
 			}
 		}
+		if in.LogTail != nil {
+			in, out := &in.LogTail, &out.LogTail
+			*out = new(string)
+			**out = **in
+		}
 		return nil
 	}
 }

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

@@ -2,6 +2,7 @@ package build
 
 import (
 	"fmt"
+	"strings"
 	"time"
 
 	"github.com/golang/glog"
@@ -258,15 +259,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 logtail is not set, then we should at least attempt to set its
+	// completion time and logtail if possible because the build pod may have put the build in
+	// this state and it would have not set the completion timestamp or logtail 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 || build.Status.LogTail == nil {
+				return false
+			}
 		}
 		glog.V(4).Infof("Ignoring build %s in completed state", buildDesc(build))
 		return true
@@ -546,17 +551,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 logtail data(for failed builds only) has already been set
+	if build.Status.CompletionTimestamp != nil && (build.Status.LogTail != nil || 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 +596,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)
 	}
@@ -818,12 +815,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 +837,26 @@ 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(msg, "\n")
+			// 6 will get us 5 lines because the last entry in parts is an empty string.
+			excerptLength := 6
+			if len(parts) < excerptLength {
+				excerptLength = len(parts)
+			}
+			excerpt := parts[len(parts)-excerptLength:]
+			for i, line := range excerpt {
+				if len(line) > 100 {
+					excerpt[i] = line[0:97] + "..."
+				}
+			}
+			msg = strings.Join(excerpt, "\n")
+
+			update.setLogTail(msg)
+		}
+	}
+
 }

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

@@ -26,6 +26,7 @@ type buildUpdate struct {
 	completionTime    *metav1.Time
 	duration          *time.Duration
 	outputRef         *string
+	logTail           *string
 }
 
 func (u *buildUpdate) setPhase(phase buildapi.BuildPhase) {
@@ -60,6 +61,10 @@ func (u *buildUpdate) setPodNameAnnotation(podName string) {
 	u.podNameAnnotation = &podName
 }
 
+func (u *buildUpdate) setLogTail(message string) {
+	u.logTail = &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.logTail = 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.logTail == 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.logTail != nil {
+		build.Status.LogTail = u.logTail
+	}
 }
 
 // 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.logTail != nil {
+		updates = append(updates, fmt.Sprintf("logTail: %q", *u.logTail))
+	}
 	return fmt.Sprintf("buildUpdate(%s)", strings.Join(updates, ", "))
 }

pkg/build/apis/build/zz_generated.deepcopy.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.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 build.Status.LogTail != nil {
+			formatString(out, "Log Tail", *build.Status.LogTail)
+		}
 		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
 								},
 							},
 						},
+						"logTail": {
+							SchemaProps: spec.SchemaProps{
+								Description: "LogTail 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"},
 				},

pkg/build/controller/strategy/sti.go

@@ -2,11 +2,13 @@ package builds
 
 import (
 	"fmt"
+	"time"
 
 	g "github.com/onsi/ginkgo"
 	o "github.com/onsi/gomega"
 
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	"k8s.io/apimachinery/pkg/util/wait"
 
 	s2istatus "github.com/openshift/source-to-image/pkg/util/status"
 
@@ -57,6 +59,23 @@ var _ = g.Describe("[builds][Slow] update failure status", func() {
 			o.Expect(build.Status.Message).To(o.Equal(buildapi.StatusMessagePostCommitHookFailed))
 
 			exutil.CheckForBuildEvent(oc.KubeClient().Core(), br.Build, buildapi.BuildFailedEventReason, buildapi.BuildFailedEventMessage)
+
+			// wait for the build to be updated w/ completiontimestamp which should also mean the logtail
+			// is set if one is going to be set.
+			err = wait.Poll(time.Second, 30*time.Second, func() (bool, error) {
+				// note this is the same build variable used in the test scope
+				build, err = oc.Client().Builds(oc.Namespace()).Get(br.Build.Name, metav1.GetOptions{})
+				if err != nil {
+					return true, err
+				}
+				if build.Status.CompletionTimestamp != nil {
+					return true, nil
+				}
+				return false, nil
+			})
+			o.Expect(err).NotTo(o.HaveOccurred())
+			o.Expect(build.Status.LogTail).NotTo(o.BeNil(), "LogTail should be set to something for failed builds")
+			o.Expect(len(*build.Status.LogTail)).NotTo(o.Equal(0), "LogTail should be set to something for failed builds")
 		})
 	})