Refactor debug logging methods.

test/e2e/ingress.go

@@ -65,6 +65,10 @@ var (
 	// Name of the loadbalancer controller within the cluster addon
 	lbContainerName = "l7-lb-controller"
 
+	// If set, the test tries to perform an HTTP GET on each url endpoint of
+	// the Ingress. Only set to false to short-circuit test runs in debugging.
+	verifyHTTPGET = true
+
 	// On average it takes ~6 minutes for a single backend to come online.
 	// We *don't* expect this poll to consistently take 15 minutes for every
 	// Ingress as GCE is creating/checking backends in parallel, but at the
@@ -173,7 +177,9 @@ func createApp(c *client.Client, ns string, i int) {
 // gcloudUnmarshal unmarshals json output of gcloud into given out interface.
 func gcloudUnmarshal(resource, regex string, out interface{}) {
 	output, err := exec.Command("gcloud", "compute", resource, "list",
-		fmt.Sprintf("--regex=%v", regex), "-q", "--format=json").CombinedOutput()
+		fmt.Sprintf("--regex=%v", regex),
+		fmt.Sprintf("--project=%v", testContext.CloudConfig.ProjectID),
+		"-q", "--format=json").CombinedOutput()
 	if err != nil {
 		Failf("Error unmarshalling gcloud output: %v", err)
 	}
@@ -204,7 +210,7 @@ func checkLeakedResources() error {
 	return nil
 }
 
-// run kubectl log on the L7 controller pod.
+// kubectlLogLBController logs kubectl debug output for the L7 controller pod.
 func kubectlLogLBController(c *client.Client) {
 	selector := labels.SelectorFromSet(labels.Set(map[string]string{"name": "glbc"}))
 	podList, err := c.Pods(api.NamespaceAll).List(selector, fields.Everything())
@@ -218,21 +224,11 @@ func kubectlLogLBController(c *client.Client) {
 	}
 	for _, p := range podList.Items {
 		Logf("\nLast 100 log lines of %v\n", p.Name)
-		Logf(runKubectl("logs", p.Name, "--namespace=kube-system", "-c", lbContainerName, "--tail=100"))
+		l, _ := runKubectl("logs", p.Name, fmt.Sprintf("--namespace=%v", api.NamespaceSystem), "-c", lbContainerName, "--tail=100")
+		Logf(l)
 	}
 }
 
-// dumpDebugAndFail dumps verbose debug output before failing.
-func dumpDebugAndFail(err string, ns string, c *client.Client) {
-	kubectlLogLBController(c)
-	Logf("\nOutput of kubectl describe ing:\n")
-
-	// TODO: runKubectl will hard fail if kubectl fails, swap it out for
-	// something more befitting for a debug dumper.
-	Logf(runKubectl("describe", "ing", fmt.Sprintf("--namespace=%v", ns)))
-	Failf(err)
-}
-
 var _ = Describe("GCE L7 LoadBalancer Controller", func() {
 	// These variables are initialized after framework's beforeEach.
 	var ns string
@@ -254,6 +250,12 @@ var _ = Describe("GCE L7 LoadBalancer Controller", func() {
 	})
 
 	AfterEach(func() {
+		if CurrentGinkgoTestDescription().Failed {
+			kubectlLogLBController(client)
+			Logf("\nOutput of kubectl describe ing:\n")
+			desc, _ := runKubectl("describe", "ing", fmt.Sprintf("--namespace=%v", ns))
+			Logf(desc)
+		}
 		framework.afterEach()
 		err := wait.Poll(lbPollInterval, lbPollTimeout, func() (bool, error) {
 			if err := checkLeakedResources(); err != nil {
@@ -301,13 +303,17 @@ var _ = Describe("GCE L7 LoadBalancer Controller", func() {
 			start := time.Now()
 			address, err := waitForIngressAddress(client, ing.Namespace, ing.Name, lbPollTimeout)
 			if err != nil {
-				dumpDebugAndFail(fmt.Sprintf("Ingress failed to acquire an IP address within %v", lbPollTimeout), ns, client)
+				Failf("Ingress failed to acquire an IP address within %v", lbPollTimeout)
 			}
 			Expect(err).NotTo(HaveOccurred())
 			By(fmt.Sprintf("Found address %v for ingress %v, took %v to come online",
 				address, ing.Name, time.Since(start)))
 			creationTimes = append(creationTimes, time.Since(start))
 
+			if !verifyHTTPGET {
+				continue
+			}
+
 			// Check that all rules respond to a simple GET.
 			for _, rules := range ing.Spec.Rules {
 				// As of Kubernetes 1.1 we only support HTTP Ingress.
@@ -330,8 +336,8 @@ var _ = Describe("GCE L7 LoadBalancer Controller", func() {
 						return true, nil
 					})
 					if pollErr != nil {
-						dumpDebugAndFail(fmt.Sprintf("Failed to execute a successful GET within %v, Last response body for %v, host %v:\n%v\n\n%v",
-							lbPollTimeout, route, rules.Host, lastBody, pollErr), ns, client)
+						Failf("Failed to execute a successful GET within %v, Last response body for %v, host %v:\n%v\n\n%v",
+							lbPollTimeout, route, rules.Host, lastBody, pollErr)
 					}
 					rt := time.Since(GETStart)
 					By(fmt.Sprintf("Route %v host %v took %v to respond", route, rules.Host, rt))
@@ -345,12 +351,15 @@ var _ = Describe("GCE L7 LoadBalancer Controller", func() {
 		sort.Sort(timeSlice(creationTimes))
 		perc50 := creationTimes[len(creationTimes)/2]
 		if perc50 > expectedLBCreationTime {
-			dumpDebugAndFail(fmt.Sprintf("Average creation time is too high: %+v", creationTimes), ns, client)
+			Failf("Average creation time is too high: %+v", creationTimes)
+		}
+		if !verifyHTTPGET {
+			return
 		}
 		sort.Sort(timeSlice(responseTimes))
 		perc50 = responseTimes[len(responseTimes)/2]
 		if perc50 > expectedLBHealthCheckTime {
-			dumpDebugAndFail(fmt.Sprintf("Average startup time is too high: %+v", responseTimes), ns, client)
+			Failf("Average startup time is too high: %+v", responseTimes)
 		}
 	})
 })

test/e2e/portforward.go

@@ -116,7 +116,7 @@ func runKubectlWithTimeout(timeout time.Duration, args ...string) string {
 	logOutput := make(chan string)
 	go func() {
 		defer GinkgoRecover()
-		logOutput <- runKubectl(args...)
+		logOutput <- runKubectlOrDie(args...)
 	}()
 	select {
 	case <-time.After(timeout):

test/e2e/util.go

@@ -926,14 +926,14 @@ func cleanup(filePath string, ns string, selectors ...string) {
 	if ns != "" {
 		nsArg = fmt.Sprintf("--namespace=%s", ns)
 	}
-	runKubectl("stop", "--grace-period=0", "-f", filePath, nsArg)
+	runKubectlOrDie("stop", "--grace-period=0", "-f", filePath, nsArg)
 
 	for _, selector := range selectors {
-		resources := runKubectl("get", "rc,svc", "-l", selector, "--no-headers", nsArg)
+		resources := runKubectlOrDie("get", "rc,svc", "-l", selector, "--no-headers", nsArg)
 		if resources != "" {
 			Failf("Resources left running after stop:\n%s", resources)
 		}
-		pods := runKubectl("get", "pods", "-l", selector, nsArg, "-o", "go-template={{ range .items }}{{ if not .metadata.deletionTimestamp }}{{ .metadata.name }}{{ \"\\n\" }}{{ end }}{{ end }}")
+		pods := runKubectlOrDie("get", "pods", "-l", selector, nsArg, "-o", "go-template={{ range .items }}{{ if not .metadata.deletionTimestamp }}{{ .metadata.name }}{{ \"\\n\" }}{{ end }}{{ end }}")
 		if pods != "" {
 			Failf("Pods left unterminated after stop:\n%s", pods)
 		}
@@ -967,7 +967,7 @@ func validateController(c *client.Client, containerImage string, replicas int, c
 	By(fmt.Sprintf("waiting for all containers in %s pods to come up.", testname)) //testname should be selector
 waitLoop:
 	for start := time.Now(); time.Since(start) < podStartTimeout; time.Sleep(5 * time.Second) {
-		getPodsOutput := runKubectl("get", "pods", "-o", "template", getPodsTemplate, "--api-version=v1", "-l", testname, fmt.Sprintf("--namespace=%v", ns))
+		getPodsOutput := runKubectlOrDie("get", "pods", "-o", "template", getPodsTemplate, "--api-version=v1", "-l", testname, fmt.Sprintf("--namespace=%v", ns))
 		pods := strings.Fields(getPodsOutput)
 		if numPods := len(pods); numPods != replicas {
 			By(fmt.Sprintf("Replicas for %s: expected=%d actual=%d", testname, replicas, numPods))
@@ -975,13 +975,13 @@ waitLoop:
 		}
 		var runningPods []string
 		for _, podID := range pods {
-			running := runKubectl("get", "pods", podID, "-o", "template", getContainerStateTemplate, "--api-version=v1", fmt.Sprintf("--namespace=%v", ns))
+			running := runKubectlOrDie("get", "pods", podID, "-o", "template", getContainerStateTemplate, "--api-version=v1", fmt.Sprintf("--namespace=%v", ns))
 			if running != "true" {
 				Logf("%s is created but not running", podID)
 				continue waitLoop
 			}
 
-			currentImage := runKubectl("get", "pods", podID, "-o", "template", getImageTemplate, "--api-version=v1", fmt.Sprintf("--namespace=%v", ns))
+			currentImage := runKubectlOrDie("get", "pods", podID, "-o", "template", getImageTemplate, "--api-version=v1", fmt.Sprintf("--namespace=%v", ns))
 			if currentImage != containerImage {
 				Logf("%s is created but running wrong image; expected: %s, actual: %s", podID, containerImage, currentImage)
 				continue waitLoop
@@ -1062,29 +1062,39 @@ func (b kubectlBuilder) withStdinReader(reader io.Reader) *kubectlBuilder {
 	return &b
 }
 
-func (b kubectlBuilder) exec() string {
+func (b kubectlBuilder) execOrDie() string {
+	str, err := b.exec()
+	Expect(err).NotTo(HaveOccurred())
+	return str
+}
+
+func (b kubectlBuilder) exec() (string, error) {
 	var stdout, stderr bytes.Buffer
 	cmd := b.cmd
 	cmd.Stdout, cmd.Stderr = &stdout, &stderr
 
 	Logf("Running '%s %s'", cmd.Path, strings.Join(cmd.Args[1:], " ")) // skip arg[0] as it is printed separately
 	if err := cmd.Run(); err != nil {
-		Failf("Error running %v:\nCommand stdout:\n%v\nstderr:\n%v\n", cmd, cmd.Stdout, cmd.Stderr)
-		return ""
+		return "", fmt.Errorf("Error running %v:\nCommand stdout:\n%v\nstderr:\n%v\n", cmd, cmd.Stdout, cmd.Stderr)
 	}
 	Logf(stdout.String())
 	// TODO: trimspace should be unnecessary after switching to use kubectl binary directly
-	return strings.TrimSpace(stdout.String())
+	return strings.TrimSpace(stdout.String()), nil
+}
+
+// runKubectlOrDie is a convenience wrapper over kubectlBuilder
+func runKubectlOrDie(args ...string) string {
+	return newKubectlCommand(args...).execOrDie()
 }
 
 // runKubectl is a convenience wrapper over kubectlBuilder
-func runKubectl(args ...string) string {
+func runKubectl(args ...string) (string, error) {
 	return newKubectlCommand(args...).exec()
 }
 
-// runKubectlInput is a convenience wrapper over kubectlBuilder that takes input to stdin
-func runKubectlInput(data string, args ...string) string {
-	return newKubectlCommand(args...).withStdinData(data).exec()
+// runKubectlOrDieInput is a convenience wrapper over kubectlBuilder that takes input to stdin
+func runKubectlOrDieInput(data string, args ...string) string {
+	return newKubectlCommand(args...).withStdinData(data).execOrDie()
 }
 
 func startCmdAndStreamOutput(cmd *exec.Cmd) (stdout, stderr io.ReadCloser, err error) {
@@ -1973,7 +1983,7 @@ func NewHostExecPodSpec(ns, name string) *api.Pod {
 // RunHostCmd runs the given cmd in the context of the given pod using `kubectl exec`
 // inside of a shell.
 func RunHostCmd(ns, name, cmd string) string {
-	return runKubectl("exec", fmt.Sprintf("--namespace=%v", ns), name, "--", "/bin/sh", "-c", cmd)
+	return runKubectlOrDie("exec", fmt.Sprintf("--namespace=%v", ns), name, "--", "/bin/sh", "-c", cmd)
 }
 
 // LaunchHostExecPod launches a hostexec pod in the given namespace and waits