Start buildrun follow logs test

pkg/shp/cmd/build/run.go

@@ -3,6 +3,7 @@ package build
 import (
 	"errors"
 	"fmt"
+	"sync"
 	"time"
 
 	buildv1alpha1 "github.com/shipwright-io/build/pkg/apis/build/v1alpha1"
@@ -36,6 +37,7 @@ type RunCommand struct {
 	buildRunSpec *buildv1alpha1.BuildRunSpec // stores command-line flags
 	shpClientset buildclientset.Interface
 	follow       bool // flag to tail pod logs
+	watchLock    sync.Mutex
 }
 
 const buildRunLongDesc = `
@@ -92,6 +94,9 @@ func (r *RunCommand) tailLogs(pod *corev1.Pod) {
 
 // onEvent reacts on pod state changes, to start and stop tailing container logs.
 func (r *RunCommand) onEvent(pod *corev1.Pod) error {
+	// found more data races during unit testing with concurrent events coming in
+	r.watchLock.Lock()
+	defer r.watchLock.Unlock()
 	switch pod.Status.Phase {
 	case corev1.PodRunning:
 		// graceful time to wait for container start
@@ -141,6 +146,9 @@ func (r *RunCommand) stop() {
 
 // Run creates a BuildRun resource based on Build's name informed on arguments.
 func (r *RunCommand) Run(params *params.Params, ioStreams *genericclioptions.IOStreams) error {
+	// ran into some data race conditions during unit test with this starting up, but pod events
+	// coming in before we completed initialization below
+	r.watchLock.Lock()
 	// resource using GenerateName, which will provice a unique instance
 	br := &buildv1alpha1.BuildRun{
 		ObjectMeta: metav1.ObjectMeta{
@@ -164,15 +172,15 @@ func (r *RunCommand) Run(params *params.Params, ioStreams *genericclioptions.IOS
 		return nil
 	}
 
-	r.buildRunName = br.Name
-	if r.shpClientset, err = params.ShipwrightClientSet(); err != nil {
-		return err
-	}
-
+	r.ioStreams = ioStreams
 	kclientset, err := params.ClientSet()
 	if err != nil {
 		return err
 	}
+	r.buildRunName = br.Name
+	if r.shpClientset, err = params.ShipwrightClientSet(); err != nil {
+		return err
+	}
 
 	// instantiating a pod watcher with a specific label-selector to find the indented pod where the
 	// actual build started by this subcommand is being executed, including the randomized buildrun
@@ -187,8 +195,10 @@ func (r *RunCommand) Run(params *params.Params, ioStreams *genericclioptions.IOS
 		return err
 	}
 
-	r.ioStreams = ioStreams
 	r.pw.WithOnPodModifiedFn(r.onEvent)
+	// cannot defer with unlock up top because r.pw.Start() blocks;  but the erroring out above kills the
+	// cli invocation, so it does not matter
+	r.watchLock.Unlock()
 	_, err = r.pw.Start()
 	return err
 }
@@ -204,6 +214,7 @@ func runCmd() runner.SubCommand {
 		cmd:             cmd,
 		buildRunSpec:    flags.BuildRunSpecFromFlags(cmd.Flags()),
 		tailLogsStarted: make(map[string]bool),
+		watchLock:       sync.Mutex{},
 	}
 	cmd.Flags().BoolVarP(&runCommand.follow, "follow", "F", runCommand.follow, "Start a build and watch its log until it completes or fails.")
 	return runCommand

pkg/shp/cmd/build/run_test.go

@@ -0,0 +1,165 @@
+package build
+
+import (
+	"runtime"
+	"strings"
+	"sync"
+	"testing"
+
+	buildv1alpha1 "github.com/shipwright-io/build/pkg/apis/build/v1alpha1"
+	shpfake "github.com/shipwright-io/build/pkg/client/clientset/versioned/fake"
+	"github.com/shipwright-io/cli/pkg/shp/flags"
+	"github.com/shipwright-io/cli/pkg/shp/params"
+	"github.com/spf13/cobra"
+	corev1 "k8s.io/api/core/v1"
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	kruntime "k8s.io/apimachinery/pkg/runtime"
+	"k8s.io/cli-runtime/pkg/genericclioptions"
+	"k8s.io/client-go/kubernetes/fake"
+	fakekubetesting "k8s.io/client-go/testing"
+)
+
+func TestStartBuildRunFollowLog(t *testing.T) {
+	tests := []struct {
+		name       string
+		phase      corev1.PodPhase
+		logText    string
+		cancelled  bool
+		brDeleted  bool
+		podDeleted bool
+	}{
+		{
+			name:    "succeeded",
+			phase:   corev1.PodSucceeded,
+			logText: "Pod 'testpod' has succeeded!",
+		},
+		{
+			name:    "pending",
+			phase:   corev1.PodPending,
+			logText: "Pod 'testpod' is in state \"Pending\"",
+		},
+		{
+			name:    "unknown",
+			phase:   corev1.PodUnknown,
+			logText: "Pod 'testpod' is in state \"Unknown\"",
+		},
+		{
+			name:      "failed-cancelled",
+			phase:     corev1.PodFailed,
+			cancelled: true,
+			logText:   "BuildRun 'testpod' has been canceled.",
+		},
+		{
+			name:      "failed-br-deleted",
+			phase:     corev1.PodFailed,
+			brDeleted: true,
+			logText:   "BuildRun 'testpod' has been deleted.",
+		},
+		{
+			name:       "failed-pod-deleted",
+			phase:      corev1.PodFailed,
+			podDeleted: true,
+			logText:    "Pod 'testpod' has been deleted.",
+		},
+		{
+			name:    "failed-something-else",
+			phase:   corev1.PodFailed,
+			logText: "Pod 'testpod' has failed!",
+		},
+		{
+			name:  "running",
+			phase: corev1.PodRunning,
+			// we do not verify log text here; the k8s fake client stuff around watches, getting pods logs, and
+			// what we do in this repo's tail logic is unreliable, and we've received guidance from some upstream
+			// k8s folks to "be careful" with it; fortunately, what we do for tail and pod_watcher so far is within
+			// the realm of reliable.
+		},
+	}
+
+	for _, test := range tests {
+		name := "testpod"
+		containerName := "container"
+		pod := &corev1.Pod{
+			ObjectMeta: metav1.ObjectMeta{
+				Namespace: metav1.NamespaceDefault,
+				Name:      name,
+				Labels: map[string]string{
+					buildv1alpha1.LabelBuild:    name,
+					buildv1alpha1.LabelBuildRun: name,
+				},
+			},
+			Spec: corev1.PodSpec{
+				Containers: []corev1.Container{{
+					Name: containerName,
+				}},
+			},
+		}
+		br := &buildv1alpha1.BuildRun{
+			ObjectMeta: metav1.ObjectMeta{
+				Namespace: metav1.NamespaceDefault,
+				Name:      name,
+			},
+		}
+		shpclientset := shpfake.NewSimpleClientset()
+		// need this reactor since the Run method uses the ObjectMeta.GenerateName k8s feature to generate the random
+		// name for the BuildRun.  However, for our purposes with unit testing, we want to control the name of the BuildRun
+		// to facilitate the list/selector via labels that is also employed by the Run method.
+		createReactorFunc := func(action fakekubetesting.Action) (handled bool, ret kruntime.Object, err error) {
+			return true, br, nil
+		}
+		shpclientset.PrependReactor("create", "buildruns", createReactorFunc)
+		// need this reactor to handle returning our test BuildRun with whatever updates we make based on the various
+		// test bools that result in spec.state or deletion timestamp updates
+		getReactorFunc := func(action fakekubetesting.Action) (handled bool, ret kruntime.Object, err error) {
+			return true, br, nil
+		}
+		shpclientset.PrependReactor("get", "buildruns", getReactorFunc)
+		kclientset := fake.NewSimpleClientset(pod)
+		ccmd := &cobra.Command{}
+		cmd := &RunCommand{
+			cmd:             ccmd,
+			buildRunName:    name,
+			buildRunSpec:    flags.BuildRunSpecFromFlags(ccmd.Flags()),
+			follow:          true,
+			shpClientset:    shpclientset,
+			tailLogsStarted: make(map[string]bool),
+			watchLock:       sync.Mutex{},
+		}
+
+		// set up context
+		cmd.Cmd().ExecuteC()
+		param := params.NewParamsForTest(kclientset, shpclientset, nil, metav1.NamespaceDefault)
+
+		ioStreams, _, out, _ := genericclioptions.NewTestIOStreams()
+
+		switch {
+		case test.cancelled:
+			br.Spec.State = buildv1alpha1.BuildRunStateCancel
+		case test.brDeleted:
+			br.DeletionTimestamp = &metav1.Time{}
+		case test.podDeleted:
+			pod.DeletionTimestamp = &metav1.Time{}
+		}
+
+		cmd.Complete(param, []string{name})
+		go func() {
+			err := cmd.Run(param, &ioStreams)
+			if err != nil {
+				t.Errorf("%s", err.Error())
+			}
+
+		}()
+
+		// yield the processor, so the initialization in Run can occur; afterward, the watchLock should allow
+		// coordination between Run and onEvent
+		runtime.Gosched()
+
+		// mimic watch events, bypassing k8s fake client watch hoopla whose plug points are not always useful;
+		pod.Status.Phase = test.phase
+		cmd.onEvent(pod)
+		if !strings.Contains(out.String(), test.logText) {
+			t.Errorf("test %s: unexpected output: %s", test.name, out.String())
+		}
+
+	}
+}