Improve resilience of oc start-build log streaming

* Add retry when attempting to stream build logs.
* Increase server-side build wait timeout to 30s.

Fixes bug 1575990

Author: adambkaplan

pkg/build/registry/buildlog/rest.go

@@ -38,7 +38,7 @@ type REST struct {
 	getSimpleLogsFn func(podNamespace, podName string, logOpts *kapi.PodLogOptions) (runtime.Object, error)
 }
 
-const defaultTimeout time.Duration = 10 * time.Second
+const defaultTimeout time.Duration = 30 * time.Second
 
 // NewREST creates a new REST for BuildLog
 // Takes build registry and pod client to get necessary attributes to assemble

pkg/oc/cli/cmd/startbuild.go

@@ -42,8 +42,8 @@ import (
 	cmdutil "github.com/openshift/origin/pkg/cmd/util"
 	"github.com/openshift/origin/pkg/git"
 	"github.com/openshift/origin/pkg/oc/cli/util/clientcmd"
+	ocerrors "github.com/openshift/origin/pkg/oc/errors"
 	utilenv "github.com/openshift/origin/pkg/oc/util/env"
-	oerrors "github.com/openshift/origin/pkg/util/errors"
 )
 
 var (
@@ -161,9 +161,10 @@ type StartBuildOptions struct {
 	GitRepository  string
 	GitPostReceive string
 
-	Mapper       meta.RESTMapper
-	BuildClient  buildclient.BuildInterface
-	ClientConfig *restclient.Config
+	Mapper         meta.RESTMapper
+	BuildClient    buildclient.BuildInterface
+	BuildLogClient buildclientinternalmanual.BuildLogInterface
+	ClientConfig   *restclient.Config
 
 	AsBinary    bool
 	ShortOutput bool
@@ -287,6 +288,8 @@ func (o *StartBuildOptions) Complete(f *clientcmd.Factory, cmd *cobra.Command, c
 	o.Namespace = namespace
 	o.Name = name
 
+	o.BuildLogClient = buildclientinternalmanual.NewBuildLogClient(o.BuildClient.RESTClient(), o.Namespace)
+
 	// Handle environment variables
 	cmdutil.WarnAboutCommaSeparation(o.ErrOut, o.Env, "--env")
 	env, _, err := utilenv.ParseEnv(o.Env, o.In)
@@ -431,27 +434,9 @@ func (o *StartBuildOptions) Run() error {
 
 	// Stream the logs from the build
 	if o.Follow {
-		opts := buildapi.BuildLogOptions{
-			Follow: true,
-			NoWait: false,
-		}
-		logClient := buildclientinternalmanual.NewBuildLogClient(o.BuildClient.RESTClient(), o.Namespace)
-		for {
-			rd, err := logClient.Logs(newBuild.Name, opts).Stream()
-			if err != nil {
-				// retry the connection to build logs when we hit the timeout.
-				if oerrors.IsTimeoutErr(err) {
-					fmt.Fprintf(o.ErrOut, "timed out getting logs, retrying\n")
-					continue
-				}
-				fmt.Fprintf(o.ErrOut, "error getting logs (%v), waiting for build to complete\n", err)
-				break
-			}
-			defer rd.Close()
-			if _, err = io.Copy(o.Out, rd); err != nil {
-				fmt.Fprintf(o.ErrOut, "error streaming logs (%v), waiting for build to complete\n", err)
-			}
-			break
+		err = o.streamBuildLogs(newBuild)
+		if err != nil {
+			fmt.Fprintf(o.ErrOut, "Failed to stream the build logs - to view the logs, run oc logs build/%s\nError: %v\n", newBuild.Name, err)
 		}
 	}
 
@@ -462,6 +447,32 @@ func (o *StartBuildOptions) Run() error {
 	return nil
 }
 
+func (o *StartBuildOptions) streamBuildLogs(build *buildapi.Build) error {
+	opts := buildapi.BuildLogOptions{
+		Follow: true,
+		NoWait: false,
+	}
+	var err error
+	for {
+		rd, logErr := o.BuildLogClient.Logs(build.Name, opts).Stream()
+		if logErr != nil {
+			err = ocerrors.NewError("unable to stream the build logs").WithCause(logErr)
+			glog.V(4).Infof("Error: %v", err)
+			if o.WaitForComplete {
+				continue
+			}
+			break
+		}
+		defer rd.Close()
+		if _, streamErr := io.Copy(o.Out, rd); streamErr != nil {
+			err = ocerrors.NewError("unable to stream the build logs").WithCause(streamErr)
+			glog.V(4).Infof("Error: %v", err)
+		}
+		break
+	}
+	return err
+}
+
 // RunListBuildWebHooks prints the webhooks for the provided build config.
 func (o *StartBuildOptions) RunListBuildWebHooks() error {
 	generic, github := false, false

pkg/oc/cli/cmd/startbuild_test.go

@@ -13,12 +13,18 @@ import (
 	"strings"
 	"testing"
 
+	kerrors "k8s.io/apimachinery/pkg/api/errors"
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	"k8s.io/apimachinery/pkg/runtime/schema"
 	restclient "k8s.io/client-go/rest"
+	restfake "k8s.io/client-go/rest/fake"
 	kclientcmd "k8s.io/client-go/tools/clientcmd"
 	clientcmdapi "k8s.io/client-go/tools/clientcmd/api"
 	"k8s.io/kubernetes/pkg/api/legacyscheme"
 
 	buildapi "github.com/openshift/origin/pkg/build/apis/build"
+	buildclient "github.com/openshift/origin/pkg/build/client/internalversion"
+	"github.com/openshift/origin/pkg/oauth/generated/clientset/scheme"
 )
 
 type FakeClientConfig struct {
@@ -282,3 +288,97 @@ func TestHttpBinary(t *testing.T) {
 		}
 	}
 }
+
+type logTestCase struct {
+	RequestErr     error
+	IOErr          error
+	ExpectedLogMsg string
+	ExpectedErrMsg string
+}
+
+type failReader struct {
+	Err error
+}
+
+func (r *failReader) Read(p []byte) (n int, err error) {
+	return 0, r.Err
+}
+
+func TestStreamBuildLogs(t *testing.T) {
+	cases := []logTestCase{
+		{
+			ExpectedLogMsg: "hello",
+		},
+		{
+			RequestErr:     errors.New("simulated failure"),
+			ExpectedErrMsg: "unable to stream the build logs",
+		},
+		{
+			RequestErr: &kerrors.StatusError{
+				ErrStatus: metav1.Status{
+					Reason:  metav1.StatusReasonTimeout,
+					Message: "timeout",
+				},
+			},
+			ExpectedErrMsg: "unable to stream the build logs",
+		},
+		{
+			IOErr:          errors.New("failed to read"),
+			ExpectedErrMsg: "unable to stream the build logs",
+		},
+	}
+
+	for _, tc := range cases {
+		out := &bytes.Buffer{}
+		build := &buildapi.Build{
+			ObjectMeta: metav1.ObjectMeta{
+				Name:      "test-build",
+				Namespace: "test-namespace",
+			},
+		}
+		// Set up dummy RESTClient to handle requests
+		fakeREST := &restfake.RESTClient{
+			NegotiatedSerializer: scheme.Codecs,
+			GroupVersion:         schema.GroupVersion{Group: "build.openshift.io", Version: "v1"},
+			Client: restfake.CreateHTTPClient(func(*http.Request) (*http.Response, error) {
+				if tc.RequestErr != nil {
+					return nil, tc.RequestErr
+				}
+				var body io.Reader
+				if tc.IOErr != nil {
+					body = &failReader{
+						Err: tc.IOErr,
+					}
+				} else {
+					body = bytes.NewBufferString(tc.ExpectedLogMsg)
+				}
+				return &http.Response{
+					StatusCode: http.StatusOK,
+					Body:       ioutil.NopCloser(body),
+				}, nil
+			}),
+		}
+
+		o := &StartBuildOptions{
+			Out:            out,
+			ErrOut:         out,
+			BuildLogClient: buildclient.NewBuildLogClient(fakeREST, build.Namespace),
+		}
+
+		err := o.streamBuildLogs(build)
+		if tc.RequestErr == nil && tc.IOErr == nil {
+			if err != nil {
+				t.Errorf("received unexpected error streaming build logs: %v", err)
+			}
+			if out.String() != tc.ExpectedLogMsg {
+				t.Errorf("expected log \"%s\", got \"%s\"", tc.ExpectedLogMsg, out.String())
+			}
+		} else {
+			if err == nil {
+				t.Errorf("no error was received, expected error message: %s", tc.ExpectedErrMsg)
+			} else if !strings.Contains(err.Error(), tc.ExpectedErrMsg) {
+				t.Errorf("expected error message \"%s\", got \"%s\"", tc.ExpectedErrMsg, err)
+			}
+		}
+	}
+}