build: debug flaky integration test

Adding log statements to better understand what's happening in kokoro.
Unfortunately I haven't been able to reproduce the problem locally (on
Linux) so far.

Related: GoogleContainerTools#6424, GoogleContainerTools#6643, GoogleContainerTools#6662

integration/dev_test.go

@@ -131,7 +131,9 @@ func TestDevGracefulCancel(t *testing.T) {
 			}()
 
 			// once deployments are stable, send a SIGINT and make sure things cleanup correctly
+			logrus.Info("Signalling SIGINT")
 			p.Signal(syscall.SIGINT)
+			logrus.Info("Signalled SIGINT")
 		})
 	}
 }

pkg/skaffold/build/misc/graceful.go

@@ -43,6 +43,7 @@ func HandleGracefulTermination(ctx context.Context, cmd *exec.Cmd) error {
 
 		select {
 		case <-ctx.Done():
+			log.Entry(ctx).Debugf("HandleGracefulTermination(): context canceled")
 			// On windows we can't send specific signals to processes, so we kill the process immediately
 			if runtime.GOOS == "windows" {
 				cmd.Process.Kill()
@@ -70,8 +71,12 @@ func HandleGracefulTermination(ctx context.Context, cmd *exec.Cmd) error {
 		}
 	}()
 
+	log.Entry(ctx).Debugf("HandleGracefulTermination(): waiting for command to finish")
 	err := cmd.Wait()
+	log.Entry(ctx).Debugf("HandleGracefulTermination(): sending true on done channel")
 	done <- true
+	log.Entry(ctx).Debugf("HandleGracefulTermination(): waiting for all goroutines to finish")
 	wg.Wait()
+	log.Entry(ctx).Debugf("HandleGracefulTermination(): returning error: %+v", err)
 	return err
 }

pkg/skaffold/deploy/kubectl/cli.go

@@ -73,6 +73,7 @@ func NewCLI(cfg Config, flags latestV1.KubectlFlags, defaultNamespace string) CL
 
 // Delete runs `kubectl delete` on a list of manifests.
 func (c *CLI) Delete(ctx context.Context, out io.Writer, manifests manifest.ManifestList) error {
+	log.Entry(ctx).Debugf("Delete(): deleting manifests: %+v", manifests)
 	args := c.args(c.Flags.Delete, "--ignore-not-found=true", "--wait=false", "-f", "-")
 	if err := c.Run(ctx, manifests.Reader(), out, "delete", args...); err != nil {
 		return deployerr.CleanupErr(fmt.Errorf("kubectl delete: %w", err))
@@ -129,7 +130,9 @@ type getResult struct {
 
 // WaitForDeletions waits for resource marked for deletion to complete their deletion.
 func (c *CLI) WaitForDeletions(ctx context.Context, out io.Writer, manifests manifest.ManifestList) error {
+	log.Entry(ctx).Debugf("WaitForDeletions(): called")
 	if !c.waitForDeletions.Enabled {
+		log.Entry(ctx).Debugf("WaitForDeletions(): not enabled, returning")
 		return nil
 	}
 
@@ -142,6 +145,7 @@ func (c *CLI) WaitForDeletions(ctx context.Context, out io.Writer, manifests man
 	for {
 		select {
 		case <-ctx.Done():
+			log.Entry(ctx).Debugf("WaitForDeletions(): context canceled, returning waitForDeletionErr()")
 			return waitForDeletionErr(fmt.Errorf("%d resources failed to complete their deletion before a new deployment: %s", previousCount, previousList))
 		default:
 			// List resources in json format.
@@ -186,7 +190,9 @@ func (c *CLI) WaitForDeletions(ctx context.Context, out io.Writer, manifests man
 
 			select {
 			case <-ctx.Done():
+				log.Entry(ctx).Debugf("WaitForDeletions(): context cancelled, doing nothing")
 			case <-time.After(c.waitForDeletions.Delay):
+				log.Entry(ctx).Debugf("WaitForDeletions(): waited delay, doing nothing")
 			}
 		}
 	}

pkg/skaffold/kubernetes/portforward/kubectl_forwarder.go

@@ -209,6 +209,7 @@ func (*KubectlForwarder) monitorLogs(ctx context.Context, logs io.Reader, cmd *k
 	for {
 		select {
 		case <-ctx.Done():
+			log.Entry(ctx).Debugf("KubectlForwarder.monitorLogs(): context canceled, returning")
 			return
 		case <-ticker.C:
 			s, _ := r.ReadString('\n')

pkg/skaffold/kubernetes/wait.go

@@ -44,13 +44,17 @@ func watchUntilTimeout(ctx context.Context, timeout time.Duration, w watch.Inter
 	for {
 		select {
 		case <-ctx.Done():
+			log.Entry(ctx).Debugf("watchUntilTimeout(): context cancelled, returning")
 			return ctx.Err()
 		case event := <-w.ResultChan():
+			log.Entry(ctx).Debugf("watchUntilTimeout(): got an event: %+v", event)
 			done, err := condition(&event)
 			if err != nil {
+				log.Entry(ctx).Debugf("watchUntilTimeout(): condition function returned an error, returning: %+v", err)
 				return err
 			}
 			if done {
+				log.Entry(ctx).Debugf("watchUntilTimeout(): condition function returned true, returning nil")
 				return nil
 			}
 		}
@@ -72,6 +76,7 @@ func WaitForPodSucceeded(ctx context.Context, pods corev1.PodInterface, podName
 
 func isPodSucceeded(podName string) func(event *watch.Event) (bool, error) {
 	return func(event *watch.Event) (bool, error) {
+		log.Entry(context.Background()).Debugf("isPodSucceeded(): Got event: %+v", event)
 		if event.Object == nil {
 			return false, nil
 		}
@@ -136,6 +141,7 @@ func WaitForDeploymentToStabilize(ctx context.Context, c kubernetes.Interface, n
 
 	return watchUntilTimeout(ctx, timeout, w, func(event *watch.Event) (bool, error) {
 		if event.Type == watch.Deleted {
+			log.Entry(ctx).Debugf("watchUntilTimeout condition func(): event.Type == watch.Deleted, returning error")
 			return false, apierrs.NewNotFound(schema.GroupResource{Resource: "deployments"}, "")
 		}