diff --git a/fv/containers/containers.go b/fv/containers/containers.go index 8694dd0c0e..79679e1ab5 100644 --- 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 index 35ec3409b8..298f56b1b9 100644 --- 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 index a1bb8e9ad0..ea662eb33f 100644 --- 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 index 1350e2067a..13beef9b1f 100644 --- 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 index 254750dbbb..bfbcd5e994 100644 --- 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]: ", 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]: ", 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...) }