Merge pull request projectcalico#2814 from fasaxc/fix-bpf-logs

Reduce FV verbosity
fasaxc · May 18, 2021 · 65d4c75 · 65d4c75
1 parent c47545c
commit 65d4c75
Show file tree

Hide file tree

Showing 5 changed files with 94 additions and 58 deletions.
diff --git a/fv/containers/containers.go b/fv/containers/containers.go
@@ -54,6 +54,7 @@ type Container struct {
 	dataRaces     []string
 
 	logFinished sync.WaitGroup
+	dropAllLogs bool
 }
 
 type watch struct {
@@ -63,6 +64,17 @@ type watch struct {
 
 var containerIdx = 0
 
+func (c *Container) StopLogs() {
+	if c == nil {
+		log.Info("StopLogs no-op because nil container")
+		return
+	}
+
+	c.mutex.Lock()
+	c.dropAllLogs = true
+	c.mutex.Unlock()
+}
+
 func (c *Container) Stop() {
 	if c == nil {
 		log.Info("Stop no-op because nil container")
@@ -78,7 +90,7 @@ func (c *Container) Stop() {
 	}
 	c.mutex.Unlock()
 
-	logCxt.Info("Stop")
+	logCxt.Info("Stopping...")
 
 	// Ask docker to stop the container.
 	withTimeoutPanic(logCxt, 30*time.Second, c.execDockerStop)
@@ -347,7 +359,14 @@ func (c *Container) copyOutputToLog(streamName string, stream io.Reader, done *s
 
 	for scanner.Scan() {
 		line := scanner.Text()
-		fmt.Fprintf(ginkgo.GinkgoWriter, "%v[%v] %v\n", c.Name, streamName, line)
+
+		// Check if we're dropping logs (e.g. because we're tearing down the container at the end of the test).
+		c.mutex.Lock()
+		droppingLogs := c.dropAllLogs
+		c.mutex.Unlock()
+		if !droppingLogs {
+			fmt.Fprintf(ginkgo.GinkgoWriter, "%v[%v] %v\n", c.Name, streamName, line)
+		}
 
 		// Capture data race warnings and log to file.
 		if strings.Contains(line, "WARNING: DATA RACE") {
@@ -392,7 +411,7 @@ func (c *Container) copyOutputToLog(streamName string, stream io.Reader, done *s
 	}
 	logCxt := log.WithFields(log.Fields{
 		"name":   c.Name,
-		"stream": stream,
+		"stream": streamName,
 	})
 	if scanner.Err() != nil {
 		logCxt.WithError(scanner.Err()).Error("Non-EOF error reading container stream")

diff --git a/fv/infrastructure/infra_etcd.go b/fv/infrastructure/infra_etcd.go
@@ -1,4 +1,4 @@
-// Copyright (c) 2018-2020 Tigera, Inc. All rights reserved.
+// Copyright (c) 2018-2021 Tigera, Inc. All rights reserved.
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
 // you may not use this file except in compliance with the License.
@@ -198,6 +198,8 @@ func (eds *EtcdDatastoreInfra) DumpErrorData() {
 }
 
 func (eds *EtcdDatastoreInfra) Stop() {
+	eds.bpfLog.StopLogs()
+	eds.etcdContainer.StopLogs()
 	eds.bpfLog.Stop()
 	eds.etcdContainer.Stop()
 }
diff --git a/fv/infrastructure/infra_k8s.go b/fv/infrastructure/infra_k8s.go
@@ -98,6 +98,17 @@ var (
 func TearDownK8sInfra(kds *K8sDatastoreInfra) {
 	log.Info("TearDownK8sInfra starting")
 	var wg sync.WaitGroup
+
+	if kds.etcdContainer != nil {
+		kds.etcdContainer.StopLogs()
+	}
+	if kds.k8sApiContainer != nil {
+		kds.k8sApiContainer.StopLogs()
+	}
+	if kds.k8sControllerManager != nil {
+		kds.k8sControllerManager.StopLogs()
+	}
+
 	if kds.etcdContainer != nil {
 		wg.Add(1)
 		go func() {
@@ -166,6 +177,7 @@ func runK8sApiserver(etcdIp string) *containers.Container {
 		"-v", os.Getenv("PRIVATE_KEY")+":/private.key",
 		utils.Config.K8sImage,
 		"kube-apiserver",
+		"--v=0",
 		"--service-cluster-ip-range=10.101.0.0/16",
 		"--authorization-mode=RBAC",
 		"--insecure-port=8080", // allow insecure connection from controller manager.
@@ -196,7 +208,7 @@ func runK8sControllerManager(apiserverIp string) *containers.Container {
 		// they are enabled.
 		"--allocate-node-cidrs=false",
 		"--leader-elect=false",
-		"--v=3",
+		"--v=0",
 		"--service-account-private-key-file=/private.key",
 		"--concurrent-gc-syncs=50",
 	)
@@ -735,52 +747,52 @@ func (kds *K8sDatastoreInfra) AddDefaultDeny() error {
 func (kds *K8sDatastoreInfra) DumpErrorData() {
 	nsList, err := kds.K8sClient.CoreV1().Namespaces().List(context.Background(), metav1.ListOptions{})
 	if err == nil {
-		utils.AddToTestOutput("Kubernetes Namespaces\n")
+		log.Info("DIAGS: Kubernetes Namespaces:")
 		for _, ns := range nsList.Items {
-			utils.AddToTestOutput(spew.Sdump(ns))
+			log.Info(spew.Sdump(ns))
 		}
 	}
 
 	profiles, err := kds.calicoClient.Profiles().List(context.Background(), options.ListOptions{})
 	if err == nil {
-		utils.AddToTestOutput("Calico Profiles\n")
+		log.Info("DIAGS: Calico Profiles:")
 		for _, profile := range profiles.Items {
-			utils.AddToTestOutput(spew.Sdump(profile))
+			log.Info(spew.Sdump(profile))
 		}
 	}
 	policies, err := kds.calicoClient.NetworkPolicies().List(context.Background(), options.ListOptions{})
 	if err == nil {
-		utils.AddToTestOutput("Calico NetworkPolicies\n")
+		log.Info("DIAGS: Calico NetworkPolicies:")
 		for _, policy := range policies.Items {
-			utils.AddToTestOutput(spew.Sdump(policy))
+			log.Info(spew.Sdump(policy))
 		}
 	}
 	gnps, err := kds.calicoClient.GlobalNetworkPolicies().List(context.Background(), options.ListOptions{})
 	if err == nil {
-		utils.AddToTestOutput("Calico GlobalNetworkPolicies\n")
+		log.Info("DIAGS: Calico GlobalNetworkPolicies:")
 		for _, gnp := range gnps.Items {
-			utils.AddToTestOutput(spew.Sdump(gnp))
+			log.Info(spew.Sdump(gnp))
 		}
 	}
 	workloads, err := kds.calicoClient.WorkloadEndpoints().List(context.Background(), options.ListOptions{})
 	if err == nil {
-		utils.AddToTestOutput("Calico WorkloadEndpoints\n")
+		log.Info("DIAGS: Calico WorkloadEndpoints:")
 		for _, w := range workloads.Items {
-			utils.AddToTestOutput(spew.Sdump(w))
+			log.Info(spew.Sdump(w))
 		}
 	}
 	nodes, err := kds.calicoClient.Nodes().List(context.Background(), options.ListOptions{})
 	if err == nil {
-		utils.AddToTestOutput("Calico Nodes\n")
+		log.Info("DIAGS: Calico Nodes:")
 		for _, n := range nodes.Items {
-			utils.AddToTestOutput(spew.Sdump(n))
+			log.Info(spew.Sdump(n))
 		}
 	}
 	heps, err := kds.calicoClient.HostEndpoints().List(context.Background(), options.ListOptions{})
 	if err == nil {
-		utils.AddToTestOutput("Calico Host Endpoints\n")
+		log.Info("DIAGS: Calico Host Endpoints:")
 		for _, hep := range heps.Items {
-			utils.AddToTestOutput(spew.Sdump(hep))
+			log.Info(spew.Sdump(hep))
 		}
 	}
 }

diff --git a/fv/named_ports_test.go b/fv/named_ports_test.go
@@ -1,4 +1,4 @@
-// Copyright (c) 2020 Tigera, Inc. All rights reserved.
+// Copyright (c) 2020-2021 Tigera, Inc. All rights reserved.
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
 // you may not use this file except in compliance with the License.
@@ -156,37 +156,37 @@ func describeNamedPortTests(testSourcePorts bool, protocol string) {
 
 			profiles, err := client.Profiles().List(context.Background(), options.ListOptions{})
 			if err == nil {
-				utils.AddToTestOutput("Calico Profiles\n")
+				log.Info("DIAGS: Calico Profiles:")
 				for _, profile := range profiles.Items {
-					utils.AddToTestOutput(fmt.Sprintf("%v\n", profile))
+					log.Info(profile)
 				}
 			}
 			policies, err := client.NetworkPolicies().List(context.Background(), options.ListOptions{})
 			if err == nil {
-				utils.AddToTestOutput("Calico NetworkPolicies\n")
+				log.Info("DIAGS: Calico NetworkPolicies:")
 				for _, policy := range policies.Items {
-					utils.AddToTestOutput(fmt.Sprintf("%v\n", policy))
+					log.Info(policy)
 				}
 			}
 			gnps, err := client.GlobalNetworkPolicies().List(context.Background(), options.ListOptions{})
 			if err == nil {
-				utils.AddToTestOutput("Calico GlobalNetworkPolicies\n")
+				log.Info("DIAGS: Calico GlobalNetworkPolicies:")
 				for _, gnp := range gnps.Items {
-					utils.AddToTestOutput(fmt.Sprintf("%v\n", gnp))
+					log.Info(gnp)
 				}
 			}
 			workloads, err := client.WorkloadEndpoints().List(context.Background(), options.ListOptions{})
 			if err == nil {
-				utils.AddToTestOutput("Calico WorkloadEndpoints\n")
+				log.Info("DIAGS: Calico WorkloadEndpoints:")
 				for _, w := range workloads.Items {
-					utils.AddToTestOutput(fmt.Sprintf("%v\n", w))
+					log.Info(w)
 				}
 			}
 			nodes, err := client.Nodes().List(context.Background(), options.ListOptions{})
 			if err == nil {
-				utils.AddToTestOutput("Calico Nodes\n")
+				log.Info("DIAGS: Calico Nodes:")
 				for _, n := range nodes.Items {
-					utils.AddToTestOutput(fmt.Sprintf("%v\n", n))
+					log.Info(n)
 				}
 			}
 

diff --git a/fv/utils/utils.go b/fv/utils/utils.go
@@ -19,14 +19,12 @@ import (
 	"bytes"
 	"context"
 	"fmt"
-	"os"
 	"os/exec"
 	"strings"
 	"syscall"
 	"time"
 
 	"github.com/kelseyhightower/envconfig"
-	. "github.com/onsi/ginkgo"
 	. "github.com/onsi/gomega"
 	log "github.com/sirupsen/logrus"
 
@@ -76,8 +74,6 @@ func RunMayFail(command string, args ...string) error {
 	return run(nil, false, command, args...)
 }
 
-var currentTestOutput = []string{}
-
 var LastRunOutput string
 
 func run(input []byte, checkNoError bool, command string, args ...string) error {
@@ -86,14 +82,21 @@ func run(input []byte, checkNoError bool, command string, args ...string) error
 		cmd.Stdin = bytes.NewReader(input)
 	}
 	outputBytes, err := cmd.CombinedOutput()
-	currentTestOutput = append(currentTestOutput, fmt.Sprintf("Command: %v %v\n", command, args))
-	currentTestOutput = append(currentTestOutput, string(outputBytes))
+	output := string(outputBytes)
 	LastRunOutput = string(outputBytes)
+	formattedCmd := formatCommand(command, args)
 	if err != nil {
-		log.WithFields(log.Fields{
-			"command": command,
-			"args":    args,
-			"output":  string(outputBytes)}).WithError(err).Warning("Command failed")
+		if len(output) == 0 {
+			log.WithError(err).Warningf("Command failed [%s]: <no output>", formattedCmd)
+		} else {
+			log.WithError(err).Warningf("Command failed [%s]:\n%s", formattedCmd, indent(output, "\t"))
+		}
+	} else {
+		if len(output) == 0 {
+			log.Infof("Command succeeded [%s]: <no output>", formattedCmd)
+		} else {
+			log.Infof("Command succeeded [%s]:\n%s", formattedCmd, indent(output, "\t"))
+		}
 	}
 	if checkNoError {
 		Expect(err).NotTo(HaveOccurred(), fmt.Sprintf("Command failed\nCommand: %v args: %v\nOutput:\n\n%v",
@@ -106,24 +109,27 @@ func run(input []byte, checkNoError bool, command string, args ...string) error
 	return nil
 }
 
-func AddToTestOutput(args ...string) {
-	currentTestOutput = append(currentTestOutput, args...)
+func indent(s string, prefix string) string {
+	lines := strings.Split(s, "\n")
+	for i := range lines {
+		lines[i] = prefix + lines[i]
+	}
+	return strings.Join(lines, "\n")
 }
 
-var _ = BeforeEach(func() {
-	currentTestOutput = []string{}
-})
-
-var _ = AfterEach(func() {
-	if CurrentGinkgoTestDescription().Failed {
-		os.Stdout.WriteString(fmt.Sprintf("\n===== begin output from failed test %s =====\n",
-			CurrentGinkgoTestDescription().FullTestText))
-		for _, output := range currentTestOutput {
-			os.Stdout.WriteString(output)
+func formatCommand(command string, args []string) string {
+	out := command
+	for _, arg := range args {
+		// Only quote if there are actually some interesting characters in there, just to make it easier to read.
+		quoted := fmt.Sprintf("%q", arg)
+		if quoted == `"` + arg + `"` {
+			out += " " + arg
+		} else {
+			out += " " + quoted
 		}
-		os.Stdout.WriteString("===== end output from failed test =====\n\n")
 	}
-})
+	return out
+}
 
 func GetCommandOutput(command string, args ...string) (string, error) {
 	cmd := Command(command, args...)
@@ -139,10 +145,7 @@ func RunCommand(command string, args ...string) error {
 }
 
 func Command(name string, args ...string) *exec.Cmd {
-	log.WithFields(log.Fields{
-		"command":     name,
-		"commandArgs": args,
-	}).Info("Creating Command.")
+	log.Debugf("Creating Command [%s].", formatCommand(name, args))
 
 	return exec.Command(name, args...)
 }