Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Reduce FV verbosity #2814

Merged
merged 2 commits into from
May 18, 2021
Merged

Reduce FV verbosity #2814

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
2fff0dc
Reduce FV verbosity:
fasaxc May 17, 2021
6c88ebb
Markups: fine tune command output.
fasaxc May 18, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
25 changes: 22 additions & 3 deletions fv/containers/containers.go
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I did not know you could call Info with a single object arg....

}
}
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
Open in desktop
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