Skip to content

Commit

Permalink
Merge pull request #2814 from fasaxc/fix-bpf-logs
Browse files Browse the repository at this point in the history 
Reduce FV verbosity
  • Loading branch information
@marvin-tigera
marvin-tigera authored May 18, 2021
2 parents 93e7c7e + 6c88ebb commit e7a8ae4
Show file tree
Hide file tree
Showing 5 changed files with 94 additions and 58 deletions.
25 changes: 22 additions & 3 deletions fv/containers/containers.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -54,6 +54,7 @@ type Container struct {
dataRaces []string

logFinished sync.WaitGroup
dropAllLogs bool
}

type watch struct {
Expand All @@ -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")
Expand All @@ -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)
Expand Down Expand Up @@ -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") {
Expand Down Expand Up @@ -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")
Expand Down
4 changes: 3 additions & 1 deletion fv/infrastructure/infra_etcd.go
View file
Original file line number Diff line number Diff line change
@@ -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.
Expand Down Expand Up @@ -198,6 +198,8 @@ func (eds *EtcdDatastoreInfra) DumpErrorData() {
}

func (eds *EtcdDatastoreInfra) Stop() {
eds.bpfLog.StopLogs()
eds.etcdContainer.StopLogs()
eds.bpfLog.Stop()
eds.etcdContainer.Stop()
}
42 changes: 27 additions & 15 deletions fv/infrastructure/infra_k8s.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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() {
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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",
)
Expand Down Expand Up @@ -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))
}
}
}
Expand Down
22 changes: 11 additions & 11 deletions fv/named_ports_test.go
View file
Original file line number Diff line number Diff line change
@@ -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.
Expand Down Expand Up @@ -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)
}
}

Expand Down
59 changes: 31 additions & 28 deletions fv/utils/utils.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"

Expand Down Expand Up @@ -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 {
Expand All @@ -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",
Expand All @@ -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...)
Expand All @@ -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...)
}
Expand Down

0 comments on commit e7a8ae4

Please sign in to comment.