From 7a1bf39a413ca5127b1ff09cff4dd27b883381f0 Mon Sep 17 00:00:00 2001 From: Adam Kaplan Date: Thu, 10 May 2018 15:11:42 -0400 Subject: [PATCH 1/2] 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 --- pkg/build/registry/buildlog/rest.go | 2 +- pkg/oc/cli/cmd/startbuild.go | 61 ++++++++++------- pkg/oc/cli/cmd/startbuild_test.go | 100 ++++++++++++++++++++++++++++ 3 files changed, 137 insertions(+), 26 deletions(-) diff --git a/pkg/build/registry/buildlog/rest.go b/pkg/build/registry/buildlog/rest.go index fc390caed644..ed7914973dec 100644 --- a/pkg/build/registry/buildlog/rest.go +++ b/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 diff --git a/pkg/oc/cli/cmd/startbuild.go b/pkg/oc/cli/cmd/startbuild.go index 6b8d8ddb3cfa..0c82965d6799 100644 --- a/pkg/oc/cli/cmd/startbuild.go +++ b/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 diff --git a/pkg/oc/cli/cmd/startbuild_test.go b/pkg/oc/cli/cmd/startbuild_test.go index 39b84a893eff..7523f6897494 100644 --- a/pkg/oc/cli/cmd/startbuild_test.go +++ b/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) + } + } + } +} From c848ef03944ccf98084b1b3be2f0d1d61904ac71 Mon Sep 17 00:00:00 2001 From: Adam Kaplan Date: Thu, 17 May 2018 09:59:43 -0400 Subject: [PATCH 2/2] oc: start-build waits only if --wait flag is set --- pkg/oc/cli/cmd/startbuild.go | 2 +- test/extended/gssapi.sh | 2 +- test/extended/ldap_groups.sh | 2 +- 3 files changed, 3 insertions(+), 3 deletions(-) diff --git a/pkg/oc/cli/cmd/startbuild.go b/pkg/oc/cli/cmd/startbuild.go index 0c82965d6799..4413bf44a6ef 100644 --- a/pkg/oc/cli/cmd/startbuild.go +++ b/pkg/oc/cli/cmd/startbuild.go @@ -440,7 +440,7 @@ func (o *StartBuildOptions) Run() error { } } - if o.Follow || o.WaitForComplete { + if o.WaitForComplete { return WaitForBuildComplete(o.BuildClient.Builds(o.Namespace), newBuild.Name) } diff --git a/test/extended/gssapi.sh b/test/extended/gssapi.sh index 3114e8fdbd0f..944981dc360c 100755 --- a/test/extended/gssapi.sh +++ b/test/extended/gssapi.sh @@ -62,7 +62,7 @@ os::cmd::expect_success "oc create -f '${test_data_location}/proxy'" # kick off a build and wait for it to finish os::cmd::expect_success "oc set env dc/gssapiproxy-server HOST='${host}' REALM='${realm}' BACKEND='${backend}'" -os::cmd::expect_success "oc start-build --from-dir='${test_data_location}/proxy' --follow gssapiproxy" +os::cmd::expect_success "oc start-build --from-dir='${test_data_location}/proxy' --follow --wait gssapiproxy" os_images=(fedora ubuntu) diff --git a/test/extended/ldap_groups.sh b/test/extended/ldap_groups.sh index a355cf8923fa..17cb5a4d5af9 100755 --- a/test/extended/ldap_groups.sh +++ b/test/extended/ldap_groups.sh @@ -54,7 +54,7 @@ os::test::junit::declare_suite_start "extended/ldap-groups/setup" os::cmd::try_until_text "oc get imagestream openldap --template='${is_event_template}'" 'latest' "$((60*TIME_SEC))" # kick off a build and wait for it to finish -oc start-build openldap --follow +oc start-build openldap --follow --wait server_ready_template=( \ "{{with \$items := .items}}" \