Add tracing throughout code and ensure level is passed to server

- Adds numerous trace logging lines in the codebase - Modifies the way `gen` invokes the aggregator so that the log level is persisted. Signed-off-by: John Schnake <[email protected]>
vmware-tanzu · Oct 7, 2021 · 623d739 · 623d739
1 parent 57b5ecc
commit 623d739
Show file tree

Hide file tree

Showing 45 changed files with 128 additions and 4 deletions.
diff --git a/cmd/sonobuoy/app/root.go b/cmd/sonobuoy/app/root.go
@@ -18,7 +18,7 @@ package app
 
 import (
 	"flag"
-
+	"fmt"
 	"github.com/sirupsen/logrus"
 	"github.com/vmware-tanzu/sonobuoy/pkg/errlog"
 
@@ -90,10 +90,14 @@ func rootCmd(cmd *cobra.Command, args []string) {
 func prerunChecks(cmd *cobra.Command, args []string) error {
 	// Getting a list of all flags provided by the user.
 	flagsSet := map[string]bool{}
+	flagsDebug := []string{}
 	cmd.Flags().Visit(func(f *pflag.Flag) {
 		flagsSet[f.Name] = true
+		flagsDebug = append(flagsDebug, fmt.Sprintf("%v=%v", f.Name, f.Value.String()))
 	})
 
+	logrus.Tracef("Invoked command %v with args %v and flags %v", cmd.Name(), args, flagsDebug)
+
 	// Difficult to do checks like this within the flag themselves (since they dont know
 	// about each other).
 	if flagsSet["mode"] && (flagsSet["e2e-focus"] || flagsSet["e2e-skip"]) {

diff --git a/pkg/client/gen.go b/pkg/client/gen.go
@@ -25,6 +25,9 @@ import (
 	"sort"
 	"strings"
 
+	"github.com/sirupsen/logrus"
+	"github.com/vmware-tanzu/sonobuoy/pkg/errlog"
+
 	"github.com/pkg/errors"
 
 	"github.com/vmware-tanzu/sonobuoy/pkg/config"
@@ -76,6 +79,10 @@ type templateValues struct {
 	CustomRegistries string
 
 	SecurityContext string
+
+	// Translate our log level into a glog value to for the aggregator/workers (e.g. the 9 in -v=9)
+	KlogLevel int
+	LogLevel  string
 }
 
 // GenerateManifest fills in a template with a Sonobuoy config
@@ -247,6 +254,9 @@ func (*SonobuoyClient) GenerateManifestAndPlugins(cfg *GenConfig) ([]byte, []*ma
 		ConfigMaps: configs,
 
 		SecurityContext: secContextFromMode(conf.SecurityContextMode),
+
+		KlogLevel: errlog.GetLevelForGlog(),
+		LogLevel:  logrus.GetLevel().String(),
 	}
 
 	var buf bytes.Buffer

diff --git a/pkg/client/gen.tmpl.yaml b/pkg/client/gen.tmpl.yaml
@@ -118,6 +118,8 @@ spec:
     image: {{.SonobuoyImage}}
     imagePullPolicy: {{.ImagePullPolicy}}
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level={{ .LogLevel }}", "-v={{ .KlogLevel }}", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/results/processing.go b/pkg/client/results/processing.go
@@ -156,13 +156,17 @@ func PostProcessPlugin(p plugin.Interface, dir string) (Item, []error) {
 
 	switch p.GetResultFormat() {
 	case ResultFormatE2E, ResultFormatJUnit:
+		logrus.WithField("plugin", p.GetName()).Trace("Using junit post-processor")
 		i, errs = processPluginWithProcessor(p, dir, junitProcessFile, fileOrExtension(p.GetResultFiles(), ".xml"))
 	case ResultFormatRaw:
+		logrus.WithField("plugin", p.GetName()).Trace("Using raw post-processor")
 		i, errs = processPluginWithProcessor(p, dir, rawProcessFile, fileOrAny(p.GetResultFiles()))
 	case ResultFormatManual:
+		logrus.WithField("plugin", p.GetName()).Trace("Using manual post-processor")
 		// Only process the specified plugin result files or a Sonobuoy results file.
 		i, errs = processPluginWithProcessor(p, dir, manualProcessFile, fileOrDefault(p.GetResultFiles(), PostProcessedResultsFile))
 	default:
+		logrus.WithField("plugin", p.GetName()).Trace("Defaulting to raw post-processor")
 		// Default to raw format so that consumers can still expect the aggregate file to exist and
 		// can navigate the output of the plugin more easily.
 		i, errs = processPluginWithProcessor(p, dir, rawProcessFile, fileOrAny(p.GetResultFiles()))

diff --git a/pkg/client/testdata/default-plugins-via-nil-selection.golden b/pkg/client/testdata/default-plugins-via-nil-selection.golden
@@ -139,6 +139,8 @@ spec:
     image: sonobuoy/sonobuoy:static-version-for-testing
     imagePullPolicy: IfNotPresent
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/default-plugins-via-selection.golden b/pkg/client/testdata/default-plugins-via-selection.golden
@@ -139,6 +139,8 @@ spec:
     image: sonobuoy/sonobuoy:static-version-for-testing
     imagePullPolicy: IfNotPresent
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/default-pod-spec.golden b/pkg/client/testdata/default-pod-spec.golden
@@ -150,6 +150,8 @@ spec:
     image: 
     imagePullPolicy: 
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/default.golden b/pkg/client/testdata/default.golden
@@ -139,6 +139,8 @@ spec:
     image: sonobuoy/sonobuoy:static-version-for-testing
     imagePullPolicy: IfNotPresent
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/e2e-default.golden b/pkg/client/testdata/e2e-default.golden
@@ -139,6 +139,8 @@ spec:
     image: sonobuoy/sonobuoy:static-version-for-testing
     imagePullPolicy: IfNotPresent
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/e2e-progress-custom-port.golden b/pkg/client/testdata/e2e-progress-custom-port.golden
@@ -99,6 +99,8 @@ spec:
     image: 
     imagePullPolicy: 
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/e2e-progress-vs-user-defined.golden b/pkg/client/testdata/e2e-progress-vs-user-defined.golden
@@ -99,6 +99,8 @@ spec:
     image: 
     imagePullPolicy: 
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/e2e-progress.golden b/pkg/client/testdata/e2e-progress.golden
@@ -99,6 +99,8 @@ spec:
     image: 
     imagePullPolicy: 
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/envoverrides.golden b/pkg/client/testdata/envoverrides.golden
@@ -102,6 +102,8 @@ spec:
     image: 
     imagePullPolicy: 
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/goRunnerRemoved.golden b/pkg/client/testdata/goRunnerRemoved.golden
@@ -97,6 +97,8 @@ spec:
     image: 
     imagePullPolicy: 
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/imagePullPolicy-all-plugins.golden b/pkg/client/testdata/imagePullPolicy-all-plugins.golden
@@ -89,6 +89,8 @@ spec:
     image: sonobuoy/sonobuoy:static-version-for-testing
     imagePullPolicy: IfNotPresent
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/imagePullSecrets.golden b/pkg/client/testdata/imagePullSecrets.golden
@@ -99,6 +99,8 @@ spec:
     image: 
     imagePullPolicy: 
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/manual-custom-plugin-plus-e2e.golden b/pkg/client/testdata/manual-custom-plugin-plus-e2e.golden
@@ -115,6 +115,8 @@ spec:
     image: 
     imagePullPolicy: 
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/manual-custom-plugin-plus-systemd.golden b/pkg/client/testdata/manual-custom-plugin-plus-systemd.golden
@@ -109,6 +109,8 @@ spec:
     image: 
     imagePullPolicy: 
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/manual-custom-plugin.golden b/pkg/client/testdata/manual-custom-plugin.golden
@@ -71,6 +71,8 @@ spec:
     image: 
     imagePullPolicy: 
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/manual-e2e.golden b/pkg/client/testdata/manual-e2e.golden
@@ -99,6 +99,8 @@ spec:
     image: 
     imagePullPolicy: 
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/multiple-node-selector.golden b/pkg/client/testdata/multiple-node-selector.golden
@@ -142,6 +142,8 @@ spec:
     image: sonobuoy/sonobuoy:static-version-for-testing
     imagePullPolicy: IfNotPresent
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/plugin-configmaps.golden b/pkg/client/testdata/plugin-configmaps.golden
@@ -109,6 +109,8 @@ spec:
     image: sonobuoy/sonobuoy:static-version-for-testing
     imagePullPolicy: IfNotPresent
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/plugins-and-pluginSelection.golden b/pkg/client/testdata/plugins-and-pluginSelection.golden
@@ -89,6 +89,8 @@ spec:
     image: sonobuoy/sonobuoy:static-version-for-testing
     imagePullPolicy: IfNotPresent
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/single-node-selector.golden b/pkg/client/testdata/single-node-selector.golden
@@ -141,6 +141,8 @@ spec:
     image: sonobuoy/sonobuoy:static-version-for-testing
     imagePullPolicy: IfNotPresent
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/systemd-logs-default.golden b/pkg/client/testdata/systemd-logs-default.golden
@@ -139,6 +139,8 @@ spec:
     image: sonobuoy/sonobuoy:static-version-for-testing
     imagePullPolicy: IfNotPresent
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/client/testdata/use-existing-pod-spec.golden b/pkg/client/testdata/use-existing-pod-spec.golden
@@ -73,6 +73,8 @@ spec:
     image: 
     imagePullPolicy: 
     name: kube-sonobuoy
+    command: ["/sonobuoy"]
+    args: ["aggregator", "--no-exit", "--level=info", "-v=4", "--alsologtostderr"]
     volumeMounts:
     - mountPath: /etc/sonobuoy
       name: sonobuoy-config-volume

diff --git a/pkg/discovery/discovery.go b/pkg/discovery/discovery.go
@@ -134,10 +134,13 @@ func Run(restConf *rest.Config, cfg *config.Config) (errCount int) {
 
 	// 3. Dump the config.json we used to run our test
 	if blob, err := json.Marshal(cfg); err == nil {
+		logrus.Trace("Recording the marshalled Sonobuoy config")
 		if err = ioutil.WriteFile(filepath.Join(metapath, "config.json"), blob, 0644); err != nil {
 			errlog.LogError(errors.Wrap(err, "could not write config.json file"))
 			return errCount + 1
 		}
+	} else {
+		errlog.LogError(errors.Wrap(err, "error marshalling Sonobuoy config"))
 	}
 
 	// runInfo is for dumping additional information to help enable processing of the resulting tarball.
@@ -216,6 +219,7 @@ func Run(restConf *rest.Config, cfg *config.Config) (errCount int) {
 
 	// Postprocessing before we create the tarball.
 	for _, p := range cfg.LoadedPlugins {
+		logrus.WithField("plugin", p.GetName()).Trace("Post-processing")
 		item, errs := results.PostProcessPlugin(p, outpath)
 		for _, e := range errs {
 			logrus.Errorf("Error processing plugin %v: %v", p.GetName(), e)
@@ -234,6 +238,9 @@ func Run(restConf *rest.Config, cfg *config.Config) (errCount int) {
 
 	// Saving plugin definitions in their respective folders for easy reference.
 	for _, p := range cfg.LoadedPlugins {
+		logrus.
+			WithField("plugin", p.GetName()).
+			Tracef("Saving plugin definition")
 		runInfo.LoadedPlugins = append(runInfo.LoadedPlugins, p.GetName())
 		trackErrorsFor("saving plugin info")(
 			dumpPlugin(p, outpath),
@@ -363,6 +370,7 @@ func updateStatus(client kubernetes.Interface, namespace string, status string,
 }
 
 func updatePluginStatus(client kubernetes.Interface, namespace string, pluginName string, item results.Item) error {
+	logrus.WithField("plugin", pluginName).Trace("Updating plugin status")
 	podStatus, _, err := pluginaggregation.GetStatus(client, namespace)
 	if err != nil {
 		return errors.Wrap(err, "failed to get the existing status")
@@ -386,13 +394,18 @@ func integrateResultsIntoStatus(podStatus *pluginaggregation.Status, pluginName
 		}
 
 		if itemForNode == nil {
+			logrus.WithField("plugin", pluginName).Trace("No results for node in this result")
 			return
 		}
 
 		statusInfo := map[string]int{}
 		statusCounts(itemForNode, statusInfo)
 		podStatus.Plugins[i].ResultStatus = itemForNode.Status
 		podStatus.Plugins[i].ResultStatusCounts = statusInfo
+		logrus.
+			WithField("plugin", pluginName).
+			WithField("node", podStatus.Plugins[i].Node).
+			Tracef("Updating with status %v", itemForNode.Status)
 	}
 }
 

diff --git a/pkg/discovery/pods.go b/pkg/discovery/pods.go
@@ -85,12 +85,15 @@ func gatherPodLogs(kubeClient kubernetes.Interface, ns string, opts metav1.ListO
 	//   pods/:podname/logs/:containername.txt
 	for _, pod := range podlist.Items {
 		if _, ok := visitedPods[string(pod.UID)]; ok {
-			continue // skip visited pods
+			logrus.
+				WithField("pod.UID", pod.UID).WithField("pod.Name", pod.Name).
+				Tracef("Skipping pod pod logs since we have already visited it before")
+			continue
 		}
 		visitedPods[string(pod.UID)] = struct{}{}
 
 		if pod.Status.Phase == v1.PodFailed && pod.Status.Reason == "Evicted" {
-			logrus.WithField("podName", pod.Name).Info("Skipping evicted pod.")
+			logrus.WithField("podName", pod.Name).Trace("Skipping evicted pod.")
 			continue
 		}
 		for _, container := range pod.Spec.Containers {

diff --git a/pkg/errlog/errlog.go b/pkg/errlog/errlog.go
@@ -70,6 +70,10 @@ func SetLevel(s string) error {
 
 }
 
+func GetLevelForGlog() int {
+	return int(logrus.GetLevel())
+}
+
 // LogError logs an error, optionally with a tracelog
 func LogError(err error) {
 	if DebugOutput {

diff --git a/pkg/image/imageversion.go b/pkg/image/imageversion.go
@@ -18,11 +18,12 @@ package image
 
 import (
 	"fmt"
+	"github.com/sirupsen/logrus"
 	"io/ioutil"
 	"net/http"
 	"strings"
 
-	version "github.com/hashicorp/go-version"
+	"github.com/hashicorp/go-version"
 	"github.com/pkg/errors"
 	"github.com/vmware-tanzu/sonobuoy/pkg/config"
 	"k8s.io/client-go/discovery"
@@ -97,12 +98,14 @@ func (c *ConformanceImageVersion) Get(client discovery.ServerVersionInterface, l
 		}
 
 		ver, err := conformanceTagFromSemver(version.GitVersion)
+		logrus.Tracef("Resolved 'auto' version to %v from GitVersion %v", ver, version.GitVersion)
 		return config.UpstreamKubeConformanceImageURL, ver, err
 	case ConformanceImageVersionLatest:
 		version, err := GetLatestDevVersion(latestURL)
 		if err != nil {
 			return "", "", errors.Wrap(err, "couldn't identify latest dev image")
 		}
+		logrus.Tracef("Resolved 'latest' version to %v via URL %v", version, latestURL)
 
 		return DevVersionImageURL, version, nil
 	}