diff --git a/pkg/shp/cmd/build/run.go b/pkg/shp/cmd/build/run.go index 9db7aa3b3..2e9f1c0c3 100644 --- a/pkg/shp/cmd/build/run.go +++ b/pkg/shp/cmd/build/run.go @@ -3,21 +3,15 @@ package build import ( "errors" "fmt" - "sync" - "time" buildv1alpha1 "github.com/shipwright-io/build/pkg/apis/build/v1alpha1" - buildclientset "github.com/shipwright-io/build/pkg/client/clientset/versioned" - + "github.com/shipwright-io/cli/pkg/shp/cmd/follower" "github.com/shipwright-io/cli/pkg/shp/cmd/runner" "github.com/shipwright-io/cli/pkg/shp/flags" "github.com/shipwright-io/cli/pkg/shp/params" - "github.com/shipwright-io/cli/pkg/shp/reactor" - "github.com/shipwright-io/cli/pkg/shp/tail" "github.com/spf13/cobra" - corev1 "k8s.io/api/core/v1" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/cli-runtime/pkg/genericclioptions" ) @@ -27,19 +21,12 @@ import ( type RunCommand struct { cmd *cobra.Command // cobra command instance - ioStreams *genericclioptions.IOStreams // io-streams instance - pw *reactor.PodWatcher // pod-watcher instance - logTail *tail.Tail // follow container logs - tailLogsStarted map[string]bool // controls tail instance per container - - logLock sync.Mutex - buildName string buildRunName string namespace string buildRunSpec *buildv1alpha1.BuildRunSpec // stores command-line flags - shpClientset buildclientset.Interface - follow bool // flag to tail pod logs + follow bool // flag to tail pod logs + follower *follower.Follower } const buildRunLongDesc = ` @@ -63,35 +50,13 @@ func (r *RunCommand) Complete(params *params.Params, io *genericclioptions.IOStr return errors.New("build name is not informed") } - clientset, err := params.ClientSet() - if err != nil { - return err - } - r.logTail = tail.NewTail(r.Cmd().Context(), clientset) - r.ioStreams = io r.namespace = params.Namespace() if r.follow { - if r.shpClientset, err = params.ShipwrightClientSet(); err != nil { - return err - } - - kclientset, err := params.ClientSet() - if err != nil { - return err - } - to, err := params.RequestTimeout() - if err != nil { - return err - } - r.pw, err = reactor.NewPodWatcher(r.Cmd().Context(), to, kclientset, params.Namespace()) + var err error + r.follower, err = follower.NewFollower(r.Cmd().Context(), r.buildRunName, io, params) if err != nil { return err } - - r.pw.WithOnPodModifiedFn(r.onEvent) - r.pw.WithTimeoutPodFn(r.onTimeout) - r.pw.WithNoPodEventsYetFn(r.onNoPodEventsYet) - } // overwriting build-ref name to use what's on arguments @@ -106,109 +71,6 @@ func (r *RunCommand) Validate() error { return nil } -// tailLogs start tailing logs for each container name in init-containers and containers, if not -// started already. -func (r *RunCommand) tailLogs(pod *corev1.Pod) { - containers := append(pod.Spec.InitContainers, pod.Spec.Containers...) - for _, container := range containers { - if _, exists := r.tailLogsStarted[container.Name]; exists { - continue - } - r.tailLogsStarted[container.Name] = true - r.logTail.Start(pod.GetNamespace(), pod.GetName(), container.Name) - } -} - -// onNoPodEventsYet reacts to the pod watcher telling us it has not received any pod events for our build run -func (r *RunCommand) onNoPodEventsYet() { - r.Log(fmt.Sprintf("BuildRun %q log following has not observed any pod events yet.", r.buildRunName)) - br, err := r.shpClientset.ShipwrightV1alpha1().BuildRuns(r.namespace).Get(r.cmd.Context(), r.buildRunName, metav1.GetOptions{}) - if err != nil { - r.Log(fmt.Sprintf("error accessing BuildRun %q: %s", r.buildRunName, err.Error())) - return - } - - c := br.Status.GetCondition(buildv1alpha1.Succeeded) - giveUp := false - msg := "" - switch { - case c != nil && c.Status == corev1.ConditionTrue: - giveUp = true - msg = fmt.Sprintf("BuildRun '%s' has been marked as successful.\n", br.Name) - case c != nil && c.Status == corev1.ConditionFalse: - giveUp = true - msg = fmt.Sprintf("BuildRun '%s' has been marked as failed.\n", br.Name) - case br.IsCanceled(): - giveUp = true - msg = fmt.Sprintf("BuildRun '%s' has been canceled.\n", br.Name) - case br.DeletionTimestamp != nil: - giveUp = true - msg = fmt.Sprintf("BuildRun '%s' has been deleted.\n", br.Name) - case !br.HasStarted(): - r.Log(fmt.Sprintf("BuildRun '%s' has been marked as failed.\n", br.Name)) - } - if giveUp { - r.Log(msg) - r.Log(fmt.Sprintf("exiting 'ship build run --follow' for BuildRun %q", br.Name)) - r.stop() - } - -} - -// onTimeout reacts to either the context or request timeout causing the pod watcher to exit -func (r *RunCommand) onTimeout(msg string) { - r.Log(fmt.Sprintf("BuildRun %q log following has stopped because: %q\n", r.buildRunName, msg)) -} - -// onEvent reacts on pod state changes, to start and stop tailing container logs. -func (r *RunCommand) onEvent(pod *corev1.Pod) error { - switch pod.Status.Phase { - case corev1.PodRunning: - // graceful time to wait for container start - time.Sleep(3 * time.Second) - // start tailing container logs - r.tailLogs(pod) - case corev1.PodFailed: - msg := "" - br, err := r.shpClientset.ShipwrightV1alpha1().BuildRuns(pod.Namespace).Get(r.cmd.Context(), r.buildRunName, metav1.GetOptions{}) - switch { - case err == nil && br.IsCanceled(): - msg = fmt.Sprintf("BuildRun '%s' has been canceled.\n", br.Name) - case err == nil && br.DeletionTimestamp != nil: - msg = fmt.Sprintf("BuildRun '%s' has been deleted.\n", br.Name) - case pod.DeletionTimestamp != nil: - msg = fmt.Sprintf("Pod '%s' has been deleted.\n", pod.GetName()) - default: - msg = fmt.Sprintf("Pod '%s' has failed!\n", pod.GetName()) - err = fmt.Errorf("build pod '%s' has failed", pod.GetName()) - } - // see if because of deletion or cancelation - r.Log(msg) - r.stop() - return err - case corev1.PodSucceeded: - r.Log(fmt.Sprintf("Pod '%s' has succeeded!\n", pod.GetName())) - r.stop() - default: - r.Log(fmt.Sprintf("Pod '%s' is in state %q...\n", pod.GetName(), string(pod.Status.Phase))) - // handle any issues with pulling images that may fail - for _, c := range pod.Status.Conditions { - if c.Type == corev1.PodInitialized || c.Type == corev1.ContainersReady { - if c.Status == corev1.ConditionUnknown { - return fmt.Errorf(c.Message) - } - } - } - } - return nil -} - -// stop invoke stop on streaming components. -func (r *RunCommand) stop() { - r.logTail.Stop() - r.pw.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 { // resource using GenerateName, which will provide a unique instance @@ -244,18 +106,10 @@ func (r *RunCommand) Run(params *params.Params, ioStreams *genericclioptions.IOS r.buildName, br.GetName(), )} - _, err = r.pw.Start(listOpts) + _, err = r.follower.Start(listOpts) return err } -// Log prints a message -func (r *RunCommand) Log(msg string) { - // concurrent fmt.Fprintf(r.ioStream.Out...) calls need locking to avoid data races, as we 'write' to the stream - r.logLock.Lock() - defer r.logLock.Unlock() - fmt.Fprint(r.ioStreams.Out, msg) -} - // runCmd instantiate the "build run" sub-command using common BuildRun flags. func runCmd() runner.SubCommand { cmd := &cobra.Command{ @@ -264,10 +118,8 @@ func runCmd() runner.SubCommand { Long: buildRunLongDesc, } runCommand := &RunCommand{ - cmd: cmd, - buildRunSpec: flags.BuildRunSpecFromFlags(cmd.Flags()), - tailLogsStarted: make(map[string]bool), - logLock: sync.Mutex{}, + cmd: cmd, + buildRunSpec: flags.BuildRunSpecFromFlags(cmd.Flags()), } cmd.Flags().BoolVarP(&runCommand.follow, "follow", "F", runCommand.follow, "Start a build and watch its log until it completes or fails.") return runCommand diff --git a/pkg/shp/cmd/build/run_test.go b/pkg/shp/cmd/build/run_test.go index d08365f3b..5694392bc 100644 --- a/pkg/shp/cmd/build/run_test.go +++ b/pkg/shp/cmd/build/run_test.go @@ -3,11 +3,11 @@ package build import ( "bytes" "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/cmd/follower" "github.com/shipwright-io/cli/pkg/shp/flags" "github.com/shipwright-io/cli/pkg/shp/params" "github.com/shipwright-io/cli/pkg/shp/reactor" @@ -35,40 +35,40 @@ func TestStartBuildRunFollowLog(t *testing.T) { { name: "succeeded", phase: corev1.PodSucceeded, - logText: "Pod 'testpod' has succeeded!", + logText: "Pod \"testpod\" has succeeded!", }, { name: "pending", phase: corev1.PodPending, - logText: "Pod 'testpod' is in state \"Pending\"", + logText: "Pod \"testpod\" is in state \"Pending\"", }, { name: "unknown", phase: corev1.PodUnknown, - logText: "Pod 'testpod' is in state \"Unknown\"", + logText: "Pod \"testpod\" is in state \"Unknown\"", }, { name: "failed-cancelled", phase: corev1.PodFailed, cancelled: true, - logText: "BuildRun 'testpod' has been canceled.", + logText: "BuildRun \"testpod\" has been canceled.", }, { name: "failed-br-deleted", phase: corev1.PodFailed, brDeleted: true, - logText: "BuildRun 'testpod' has been deleted.", + logText: "BuildRun \"testpod\" has been deleted.", }, { name: "failed-pod-deleted", phase: corev1.PodFailed, podDeleted: true, - logText: "Pod 'testpod' has been deleted.", + logText: "Pod \"testpod\" has been deleted.", }, { name: "failed-something-else", phase: corev1.PodFailed, - logText: "Pod 'testpod' has failed!", + logText: "Pod \"testpod\" has failed!", }, { name: "running", @@ -135,13 +135,10 @@ func TestStartBuildRunFollowLog(t *testing.T) { } ccmd := &cobra.Command{} cmd := &RunCommand{ - cmd: ccmd, - buildRunName: name, - buildRunSpec: flags.BuildRunSpecFromFlags(ccmd.Flags()), - follow: true, - shpClientset: shpclientset, - tailLogsStarted: make(map[string]bool), - logLock: sync.Mutex{}, + cmd: ccmd, + buildRunName: name, + buildRunSpec: flags.BuildRunSpecFromFlags(ccmd.Flags()), + follow: true, } // set up context @@ -153,14 +150,33 @@ func TestStartBuildRunFollowLog(t *testing.T) { param := params.NewParamsForTest(kclientset, shpclientset, pm, metav1.NamespaceDefault) ioStreams, _, out, _ := genericclioptions.NewTestIOStreams() + cmd.follower, _ = follower.NewFollower(cmd.Cmd().Context(), br.Name, &ioStreams, param) switch { case test.cancelled: br.Spec.State = buildv1alpha1.BuildRunStateCancel + br.Status.Conditions = []buildv1alpha1.Condition{ + { + Type: buildv1alpha1.Succeeded, + Status: corev1.ConditionFalse, + }, + } case test.brDeleted: br.DeletionTimestamp = &metav1.Time{} + br.Status.Conditions = []buildv1alpha1.Condition{ + { + Type: buildv1alpha1.Succeeded, + Status: corev1.ConditionFalse, + }, + } case test.podDeleted: pod.DeletionTimestamp = &metav1.Time{} + br.Status.Conditions = []buildv1alpha1.Condition{ + { + Type: buildv1alpha1.Succeeded, + Status: corev1.ConditionFalse, + }, + } } cmd.Complete(param, &ioStreams, []string{name}) @@ -181,9 +197,9 @@ func TestStartBuildRunFollowLog(t *testing.T) { if !test.noPodYet { // mimic watch events, bypassing k8s fake client watch hoopla whose plug points are not always useful; pod.Status.Phase = test.phase - cmd.onEvent(pod) + cmd.follower.OnEvent(pod) } else { - cmd.onNoPodEventsYet() + cmd.follower.OnNoPodEventsYet() } checkLog(test.name, test.logText, cmd, out, t) } @@ -191,8 +207,8 @@ func TestStartBuildRunFollowLog(t *testing.T) { func checkLog(name, text string, cmd *RunCommand, out *bytes.Buffer, t *testing.T) { // need to employ log lock since accessing same iostream out used by Run cmd - cmd.logLock.Lock() - defer cmd.logLock.Unlock() + cmd.follower.GetLogLock().Lock() + defer cmd.follower.GetLogLock().Unlock() if !strings.Contains(out.String(), text) { t.Errorf("test %s: unexpected output: %s", name, out.String()) } diff --git a/pkg/shp/cmd/buildrun/logs.go b/pkg/shp/cmd/buildrun/logs.go index 71c90b50e..97eb69f0a 100644 --- a/pkg/shp/cmd/buildrun/logs.go +++ b/pkg/shp/cmd/buildrun/logs.go @@ -3,14 +3,17 @@ package buildrun import ( "fmt" "strings" - - buildv1alpha1 "github.com/shipwright-io/build/pkg/apis/build/v1alpha1" - "github.com/spf13/cobra" + "time" corev1 "k8s.io/api/core/v1" v1 "k8s.io/apimachinery/pkg/apis/meta/v1" + "k8s.io/apimachinery/pkg/util/wait" "k8s.io/cli-runtime/pkg/genericclioptions" + buildv1alpha1 "github.com/shipwright-io/build/pkg/apis/build/v1alpha1" + "github.com/spf13/cobra" + + "github.com/shipwright-io/cli/pkg/shp/cmd/follower" "github.com/shipwright-io/cli/pkg/shp/cmd/runner" "github.com/shipwright-io/cli/pkg/shp/params" "github.com/shipwright-io/cli/pkg/shp/util" @@ -21,16 +24,22 @@ type LogsCommand struct { cmd *cobra.Command name string + + follow bool + follower *follower.Follower } func logsCmd() runner.SubCommand { - return &LogsCommand{ - cmd: &cobra.Command{ - Use: "logs ", - Short: "See BuildRun log output", - Args: cobra.ExactArgs(1), - }, + cmd := &cobra.Command{ + Use: "logs ", + Short: "See BuildRun log output", + Args: cobra.ExactArgs(1), + } + logCommand := &LogsCommand{ + cmd: cmd, } + cmd.Flags().BoolVarP(&logCommand.follow, "follow", "F", logCommand.follow, "Follow the log of a buildrun until it completes or fails.") + return logCommand } // Cmd returns cobra command object @@ -41,6 +50,13 @@ func (c *LogsCommand) Cmd() *cobra.Command { // Complete fills in data provided by user func (c *LogsCommand) Complete(params *params.Params, io *genericclioptions.IOStreams, args []string) error { c.name = args[0] + if c.follow { + var err error + c.follower, err = follower.NewFollower(c.Cmd().Context(), c.name, io, params) + if err != nil { + return err + } + } return nil } @@ -61,29 +77,51 @@ func (c *LogsCommand) Run(params *params.Params, ioStreams *genericclioptions.IO LabelSelector: fmt.Sprintf("%v=%v", buildv1alpha1.LabelBuildRun, c.name), } + // first see if pod is already done; if so, even if we have follow == true, just do the normal path; + // we don't employ a pod watch here since the buildrun may already be complete before 'shp buildrun logs -F' + // is invoked. + justGetLogs := false var pods *corev1.PodList - if pods, err = clientset.CoreV1().Pods(params.Namespace()).List(c.cmd.Context(), lo); err != nil { + err = wait.PollImmediate(1*time.Second, 10*time.Second, func() (done bool, err error) { + if pods, err = clientset.CoreV1().Pods(params.Namespace()).List(c.cmd.Context(), lo); err != nil { + fmt.Fprintf(ioStreams.ErrOut, "error listing Pods for BuildRun %q: %s\n", c.name, err.Error()) + return false, nil + } + if len(pods.Items) == 0 { + fmt.Fprintf(ioStreams.ErrOut, "no builder pod found for BuildRun %q\n", c.name) + return false, nil + } + return true, nil + }) + if err != nil { return err } - if len(pods.Items) == 0 { - return fmt.Errorf("no builder pod found for BuildRun %q", c.name) + pod := pods.Items[0] + phase := pod.Status.Phase + if phase == corev1.PodFailed || phase == corev1.PodSucceeded { + justGetLogs = true } - fmt.Fprintf(ioStreams.Out, "Obtaining logs for BuildRun %q\n\n", c.name) + if !c.follow || justGetLogs { + fmt.Fprintf(ioStreams.Out, "Obtaining logs for BuildRun %q\n\n", c.name) - var b strings.Builder - pod := pods.Items[0] - for _, container := range pod.Spec.Containers { - logs, err := util.GetPodLogs(c.cmd.Context(), clientset, pod, container.Name) - if err != nil { - return err + var b strings.Builder + containers := append(pod.Spec.InitContainers, pod.Spec.Containers...) + for _, container := range containers { + logs, err := util.GetPodLogs(c.cmd.Context(), clientset, pod, container.Name) + if err != nil { + return err + } + + fmt.Fprintf(&b, "*** Pod %q, container %q: ***\n\n", pod.Name, container.Name) + fmt.Fprintln(&b, logs) } - fmt.Fprintf(&b, "*** Pod %q, container %q: ***\n\n", pod.Name, container.Name) - fmt.Fprintln(&b, logs) - } + fmt.Fprintln(ioStreams.Out, b.String()) - fmt.Fprintln(ioStreams.Out, b.String()) + return nil - return nil + } + _, err = c.follower.Start(lo) + return err } diff --git a/pkg/shp/cmd/buildrun/logs_test.go b/pkg/shp/cmd/buildrun/logs_test.go index 6cd2938b2..51e050e04 100644 --- a/pkg/shp/cmd/buildrun/logs_test.go +++ b/pkg/shp/cmd/buildrun/logs_test.go @@ -1,9 +1,16 @@ package buildrun import ( + "bytes" "strings" "testing" + shpfake "github.com/shipwright-io/build/pkg/client/clientset/versioned/fake" + "github.com/shipwright-io/cli/pkg/shp/cmd/follower" + "github.com/shipwright-io/cli/pkg/shp/reactor" + kruntime "k8s.io/apimachinery/pkg/runtime" + fakekubetesting "k8s.io/client-go/testing" + "github.com/shipwright-io/build/pkg/apis/build/v1alpha1" "github.com/shipwright-io/cli/pkg/shp/params" @@ -48,3 +55,196 @@ func TestStreamBuildLogs(t *testing.T) { t.Logf("%s", out.String()) } + +func TestStreamBuildRunFollowLogs(t *testing.T) { + tests := []struct { + name string + phase corev1.PodPhase + logText string + to string + noPodYet bool + 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. + }, + { + name: "timeout", + to: "1s", + logText: reactor.RequestTimeoutMessage, + }, + { + name: "no pod yet", + noPodYet: true, + logText: "has not observed any pod events yet", + }, + } + + for _, test := range tests { + name := "testpod" + containerName := "container" + pod := &corev1.Pod{ + ObjectMeta: metav1.ObjectMeta{ + Namespace: metav1.NamespaceDefault, + Name: name, + Labels: map[string]string{ + v1alpha1.LabelBuild: name, + v1alpha1.LabelBuildRun: name, + }, + }, + Spec: corev1.PodSpec{ + Containers: []corev1.Container{{ + Name: containerName, + }}, + }, + } + br := &v1alpha1.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() + if !test.noPodYet { + kclientset = fake.NewSimpleClientset(pod) + } + ccmd := &cobra.Command{} + cmd := &LogsCommand{ + cmd: ccmd, + name: name, + follow: true, + } + + // set up context + cmd.Cmd().ExecuteC() + pm := genericclioptions.NewConfigFlags(true) + if len(test.to) > 0 { + pm.Timeout = &test.to + } + param := params.NewParamsForTest(kclientset, shpclientset, pm, metav1.NamespaceDefault) + + ioStreams, _, out, _ := genericclioptions.NewTestIOStreams() + cmd.follower, _ = follower.NewFollower(cmd.Cmd().Context(), br.Name, &ioStreams, param) + + switch { + case test.cancelled: + br.Spec.State = v1alpha1.BuildRunStateCancel + br.Status.Conditions = []v1alpha1.Condition{ + { + Type: v1alpha1.Succeeded, + Status: corev1.ConditionFalse, + }, + } + case test.brDeleted: + br.DeletionTimestamp = &metav1.Time{} + br.Status.Conditions = []v1alpha1.Condition{ + { + Type: v1alpha1.Succeeded, + Status: corev1.ConditionFalse, + }, + } + case test.podDeleted: + pod.DeletionTimestamp = &metav1.Time{} + br.Status.Conditions = []v1alpha1.Condition{ + { + Type: v1alpha1.Succeeded, + Status: corev1.ConditionFalse, + }, + } + } + + cmd.Complete(param, &ioStreams, []string{name}) + if len(test.to) > 0 { + cmd.Run(param, &ioStreams) + checkLog(test.name, test.logText, cmd, out, t) + continue + } + + go func() { + err := cmd.Run(param, &ioStreams) + if err != nil { + t.Errorf("%s", err.Error()) + } + + }() + + if !test.noPodYet { + // mimic watch events, bypassing k8s fake client watch hoopla whose plug points are not always useful; + pod.Status.Phase = test.phase + cmd.follower.OnEvent(pod) + } else { + cmd.follower.OnNoPodEventsYet() + } + checkLog(test.name, test.logText, cmd, out, t) + } + +} + +func checkLog(name, text string, cmd *LogsCommand, out *bytes.Buffer, t *testing.T) { + // need to employ log lock since accessing same iostream out used by Run cmd + cmd.follower.GetLogLock().Lock() + defer cmd.follower.GetLogLock().Unlock() + if !strings.Contains(out.String(), text) { + t.Errorf("test %s: unexpected output: %s", name, out.String()) + } +} diff --git a/pkg/shp/cmd/follower/follow.go b/pkg/shp/cmd/follower/follow.go new file mode 100644 index 000000000..680dd7ef5 --- /dev/null +++ b/pkg/shp/cmd/follower/follow.go @@ -0,0 +1,249 @@ +package follower + +import ( + "context" + "encoding/json" + "fmt" + "strings" + "sync" + "time" + + buildv1alpha1 "github.com/shipwright-io/build/pkg/apis/build/v1alpha1" + buildclientset "github.com/shipwright-io/build/pkg/client/clientset/versioned" + "github.com/shipwright-io/cli/pkg/shp/params" + "github.com/shipwright-io/cli/pkg/shp/reactor" + "github.com/shipwright-io/cli/pkg/shp/tail" + "github.com/shipwright-io/cli/pkg/shp/util" + + corev1 "k8s.io/api/core/v1" + kerrors "k8s.io/apimachinery/pkg/api/errors" + metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" + "k8s.io/apimachinery/pkg/util/wait" + "k8s.io/cli-runtime/pkg/genericclioptions" + "k8s.io/client-go/kubernetes" +) + +// Follower encapsulate the function of tailing the logs for Pods derived from BuildRuns +type Follower struct { + ctx context.Context + + ioStreams *genericclioptions.IOStreams // io-streams instance + pw *reactor.PodWatcher // pod-watcher instance + logTail *tail.Tail // follow container logs + tailLogsStarted map[string]bool // controls tail instance per container + + logLock sync.Mutex + shpClientset buildclientset.Interface + kclientset kubernetes.Interface + + buildRunName string + namespace string + + enteredRunningState bool +} + +// NewFollower returns a Follower instance +func NewFollower( + ctx context.Context, + buildRunName string, + ioStreams *genericclioptions.IOStreams, + params *params.Params, +) (*Follower, error) { + follower := &Follower{ctx: ctx, ioStreams: ioStreams, buildRunName: buildRunName, logLock: sync.Mutex{}, tailLogsStarted: make(map[string]bool)} + follower.complete(params) + return follower, nil +} + +// GetLogLock returns the mutex used for coordinating access to log buffers. +func (f *Follower) GetLogLock() *sync.Mutex { + return &f.logLock +} + +func (f *Follower) complete(params *params.Params) error { + clientset, err := params.ClientSet() + if err != nil { + return err + } + f.logTail = tail.NewTail(f.ctx, clientset) + f.namespace = params.Namespace() + if f.shpClientset, err = params.ShipwrightClientSet(); err != nil { + return err + } + f.kclientset, err = params.ClientSet() + if err != nil { + return err + } + to, err := params.RequestTimeout() + if err != nil { + return err + } + f.pw, err = reactor.NewPodWatcher(f.ctx, to, f.kclientset, params.Namespace()) + if err != nil { + return err + } + + f.pw.WithOnPodModifiedFn(f.OnEvent) + f.pw.WithTimeoutPodFn(f.OnTimeout) + f.pw.WithNoPodEventsYetFn(f.OnNoPodEventsYet) + return nil +} + +// Log prints a message +func (f *Follower) Log(msg string) { + // concurrent fmt.Fprintf(r.ioStream.Out...) calls need locking to avoid data races, as we 'write' to the stream + f.logLock.Lock() + defer f.logLock.Unlock() + fmt.Fprint(f.ioStreams.Out, msg) +} + +// tailLogs start tailing logs for each container name in init-containers and containers, if not +// started already. +func (f *Follower) tailLogs(pod *corev1.Pod) { + containers := append(pod.Spec.InitContainers, pod.Spec.Containers...) + for _, container := range containers { + if _, exists := f.tailLogsStarted[container.Name]; exists { + continue + } + f.tailLogsStarted[container.Name] = true + f.logTail.Start(pod.GetNamespace(), pod.GetName(), container.Name) + } +} + +// stop invoke stop on streaming components. +func (f *Follower) stop() { + f.logTail.Stop() + f.pw.Stop() +} + +// OnEvent reacts on pod state changes, to start and stop tailing container logs. +func (f *Follower) OnEvent(pod *corev1.Pod) error { + switch pod.Status.Phase { + case corev1.PodRunning: + if !f.enteredRunningState { + f.Log(fmt.Sprintf("Pod %q in %q state, starting up log tail", pod.GetName(), corev1.PodRunning)) + f.enteredRunningState = true + // graceful time to wait for container start + time.Sleep(3 * time.Second) + // start tailing container logs + f.tailLogs(pod) + } + case corev1.PodFailed: + msg := "" + var br *buildv1alpha1.BuildRun + err := wait.PollImmediate(1*time.Second, 15*time.Second, func() (done bool, err error) { + br, err = f.shpClientset.ShipwrightV1alpha1().BuildRuns(pod.Namespace).Get(f.ctx, f.buildRunName, metav1.GetOptions{}) + if err != nil { + if kerrors.IsNotFound(err) { + return true, nil + } + f.Log(fmt.Sprintf("error getting buildrun %q for pod %q: %s\n", f.buildRunName, pod.GetName(), err.Error())) + return false, nil + } + if br.IsDone() { + return true, nil + } + return false, nil + }) + if err != nil { + f.Log(fmt.Sprintf("gave up trying to get a buildrun %q in a terminal state for pod %q, proceeding with pod failure processing", f.buildRunName, pod.GetName())) + } + switch { + case br == nil: + msg = fmt.Sprintf("BuildRun %q has been deleted.\n", br.Name) + case err == nil && br.IsCanceled(): + msg = fmt.Sprintf("BuildRun %q has been canceled.\n", br.Name) + case (err == nil && br.DeletionTimestamp != nil) || (err != nil && kerrors.IsNotFound(err)): + msg = fmt.Sprintf("BuildRun %q has been deleted.\n", br.Name) + case pod.DeletionTimestamp != nil: + msg = fmt.Sprintf("Pod %q has been deleted.\n", pod.GetName()) + default: + msg = fmt.Sprintf("Pod %q has failed!\n", pod.GetName()) + podBytes, err2 := json.MarshalIndent(pod, "", " ") + if err2 == nil { + msg = fmt.Sprintf("Pod %q has failed!\nPod JSON:\n%s\n", pod.GetName(), string(podBytes)) + } + err = fmt.Errorf("build pod %q has failed", pod.GetName()) + } + // see if because of deletion or cancelation + f.Log(msg) + f.stop() + return err + case corev1.PodSucceeded: + // encountered scenarios where the build run quickly enough that the pod effectively skips the running state, + // or the events come in reverse order, and we never enter the tail + if !f.enteredRunningState { + f.Log(fmt.Sprintf("succeeded event for pod %q arrived before or in place of running event so dumping logs now", pod.GetName())) + var b strings.Builder + for _, c := range pod.Spec.Containers { + logs, err := util.GetPodLogs(f.ctx, f.kclientset, *pod, c.Name) + if err != nil { + f.Log(fmt.Sprintf("could not get logs for container %q: %s", c.Name, err.Error())) + continue + } + fmt.Fprintf(&b, "*** Pod %q, container %q: ***\n\n", pod.Name, c.Name) + fmt.Fprintln(&b, logs) + } + f.Log(b.String()) + } + f.Log(fmt.Sprintf("Pod %q has succeeded!\n", pod.GetName())) + f.stop() + default: + f.Log(fmt.Sprintf("Pod %q is in state %q...\n", pod.GetName(), string(pod.Status.Phase))) + // handle any issues with pulling images that may fail + for _, c := range pod.Status.Conditions { + if c.Type == corev1.PodInitialized || c.Type == corev1.ContainersReady { + if c.Status == corev1.ConditionUnknown { + return fmt.Errorf(c.Message) + } + } + } + } + return nil + +} + +// OnTimeout reacts to either the context or request timeout causing the pod watcher to exit +func (f *Follower) OnTimeout(msg string) { + f.Log(fmt.Sprintf("BuildRun %q log following has stopped because: %q\n", f.buildRunName, msg)) +} + +// OnNoPodEventsYet reacts to the pod watcher telling us it has not received any pod events for our build run +func (f *Follower) OnNoPodEventsYet() { + f.Log(fmt.Sprintf("BuildRun %q log following has not observed any pod events yet.\n", f.buildRunName)) + br, err := f.shpClientset.ShipwrightV1alpha1().BuildRuns(f.namespace).Get(f.ctx, f.buildRunName, metav1.GetOptions{}) + if err != nil { + f.Log(fmt.Sprintf("error accessing BuildRun %q: %s", f.buildRunName, err.Error())) + return + } + + c := br.Status.GetCondition(buildv1alpha1.Succeeded) + giveUp := false + msg := "" + switch { + case c != nil && c.Status == corev1.ConditionTrue: + giveUp = true + msg = fmt.Sprintf("BuildRun '%s' has been marked as successful.\n", br.Name) + case c != nil && c.Status == corev1.ConditionFalse: + giveUp = true + msg = fmt.Sprintf("BuildRun '%s' has been marked as failed.\n", br.Name) + case br.IsCanceled(): + giveUp = true + msg = fmt.Sprintf("BuildRun '%s' has been canceled.\n", br.Name) + case br.DeletionTimestamp != nil: + giveUp = true + msg = fmt.Sprintf("BuildRun '%s' has been deleted.\n", br.Name) + case !br.HasStarted(): + f.Log(fmt.Sprintf("BuildRun '%s' has been marked as failed.\n", br.Name)) + } + if giveUp { + f.Log(msg) + f.Log(fmt.Sprintf("exiting 'shp build run --follow' for BuildRun %q", br.Name)) + f.stop() + } + +} + +// Start initiates the log following for the referenced BuildRun's Pod +func (f *Follower) Start(lo metav1.ListOptions) (*corev1.Pod, error) { + return f.pw.Start(lo) +} diff --git a/pkg/shp/params/params.go b/pkg/shp/params/params.go index 353585ff0..ae5c2f054 100644 --- a/pkg/shp/params/params.go +++ b/pkg/shp/params/params.go @@ -88,6 +88,12 @@ func (p *Params) ShipwrightClientSet() (buildclientset.Interface, error) { // Namespace returns kubernetes namespace with alle the overrides // from command line and kubernetes config func (p *Params) Namespace() string { + if len(p.namespace) == 0 { + clientConfig := p.configFlags.ToRawKubeConfigLoader() + clientConfig.ClientConfig() + p.namespace, _, _ = clientConfig.Namespace() + + } return p.namespace } diff --git a/test/e2e/log-follow--follow.bats b/test/e2e/log-follow--follow.bats new file mode 100644 index 000000000..7413c5846 --- /dev/null +++ b/test/e2e/log-follow--follow.bats @@ -0,0 +1,37 @@ +#!/usr/bin/env bats + +source test/e2e/helpers.sh + +setup() { + load 'bats/support/load' + load 'bats/assert/load' + load 'bats/file/load' +} + +teardown() { + run kubectl delete builds.shipwright.io --all + run kubectl delete buildruns.shipwright.io --all +} + +@test "shp buildrun logs follow verification" { + # generate random names for our build and buildrun + build_name=$(random_name) + buildrun_name=$(random_name) + + # create a Build with two environment variables + run shp build create ${build_name} --source-url=https://github.com/shipwright-io/sample-go --source-context-dir=source-build --output-image=registry.registry.svc.cluster.local:32222/shipwright-io/build-e2e + assert_success + + # initiate a BuildRun + run shp buildrun create --buildref-name ${build_name} ${buildrun_name} + # tail logs with -F + run shp buildrun logs --follow ${buildrun_name} + assert_success + + + # confirm output that would only exist if following BuildRun logs + assert_output --partial "[source-default]" + assert_output --partial "[place-tools]" + assert_output --partial "[build-and-push]" + assert_output --partial "has succeeded!" +} \ No newline at end of file diff --git a/test/e2e/log-follow-F.bats b/test/e2e/log-follow-F.bats new file mode 100644 index 000000000..2dbd20d61 --- /dev/null +++ b/test/e2e/log-follow-F.bats @@ -0,0 +1,37 @@ +#!/usr/bin/env bats + +source test/e2e/helpers.sh + +setup() { + load 'bats/support/load' + load 'bats/assert/load' + load 'bats/file/load' +} + +teardown() { + run kubectl delete builds.shipwright.io --all + run kubectl delete buildruns.shipwright.io --all +} + +@test "shp buildrun logs follow verification" { + # generate random names for our build and buildrun + build_name=$(random_name) + buildrun_name=$(random_name) + + # create a Build with two environment variables + run shp build create ${build_name} --source-url=https://github.com/shipwright-io/sample-go --source-context-dir=source-build --output-image=registry.registry.svc.cluster.local:32222/shipwright-io/build-e2e + assert_success + + # initiate a BuildRun + run shp buildrun create --buildref-name ${build_name} ${buildrun_name} + # tail logs with -F + run shp buildrun logs -F ${buildrun_name} + assert_success + + + # confirm output that would only exist if following BuildRun logs + assert_output --partial "[source-default]" + assert_output --partial "[place-tools]" + assert_output --partial "[build-and-push]" + assert_output --partial "has succeeded!" +} \ No newline at end of file