Merge pull request #77 from anchore/improve-logging

feat: improve logging

.gitignore

@@ -37,3 +37,6 @@ coverage.txt
 # Kubeconfigs contain sensitive information and are specific to someone's environment
 # Ignore it in case anyone puts it in the dir
 kubeconfig
+
+# Location for checking out the chart for using skaffold
+anchore-charts

Dockerfile.skaffold

@@ -0,0 +1,21 @@
+FROM gcr.io/distroless/static:nonroot
+
+COPY snapshot/kai /usr/bin
+
+USER nonroot:nobody
+
+ARG BUILD_DATE
+ARG BUILD_VERSION
+ARG VCS_REF
+ARG VCS_URL
+
+LABEL org.opencontainers.image.created=$BUILD_DATE
+LABEL org.opencontainers.image.title="kai"
+LABEL org.opencontainers.image.description="KAI (Kubernetes Automated Inventory) can poll Kubernetes Cluster API(s) to tell Anchore which Images are currently in-use"
+LABEL org.opencontainers.image.source=$VCS_URL
+LABEL org.opencontainers.image.revision=$VCS_REF
+LABEL org.opencontainers.image.vendor="Anchore, Inc."
+LABEL org.opencontainers.image.version=$BUILD_VERSION
+LABEL org.opencontainers.image.licenses="Apache-2.0"
+
+ENTRYPOINT ["kai"]

Makefile

@@ -208,3 +208,8 @@ clean-snapshot:
 .PHONY: clean-dist
 clean-dist:
 	rm -rf $(DISTDIR) $(TEMPDIR)/goreleaser.yaml
+
+.PHONY: bootstrap-skaffold
+bootstrap-skaffold:
+	$(call title, Cloning chart for local skaffold dev)
+	git clone https://github.com/anchore/anchore-charts.git

README.md

@@ -18,7 +18,7 @@ By default, KAI will look for a Kubeconfig in the home directory to use to authe
 
 ### CLI
 ```shell script
-$ kai
+$ kai --verbose-inventory-reports
 {
   "timestamp": "2021-11-17T18:47:36Z",
   "results": [
@@ -88,7 +88,7 @@ $ kai
 
 In order to run kai as a container, it needs a kubeconfig
 ```sh
-~ docker run -it --rm -v ~/.kube/config:/.kube/config anchore/kai:v0.3.0
+~ docker run -it --rm -v ~/.kube/config:/.kube/config anchore/kai:v0.5.0 --verbose-inventory-reports
 {
   "timestamp": "2021-11-17T18:47:36Z",
   "results": [
@@ -231,6 +231,9 @@ kubeconfig:
     client-cert:
     private-key:
     token:
+
+# enable/disable printing inventory reports to stdout
+verbose-inventory-reports: false
 ```
 
 ### Namespace selection
@@ -379,6 +382,13 @@ anchore:
     timeout-seconds: 10
 ```
 
+## Behavior change (v0.5.0)
+
+In versions of KAI < v0.5.0 the default behavior was to output the inventory report
+to stdout every time it was generated. KAI v0.5.0 changes this so it will not print
+to stdout unless `verbose-inventory-reports: true` is set in the config file or
+KAI is called with the `--verbose-inventory-reports` flag.
+
 ## Configuration Changes (v0.2.2 -> v0.3.0)
 
 There are a few configurations that were changed from v0.2.2 to v0.3.0
@@ -462,6 +472,17 @@ KAI comes with shell completion for specifying namespaces, it can be enabled as
 kai completion <zsh|bash|fish>
 ```
 
+### Using Skaffold
+You can use skaffold for dev. The 'bootstrap-skaffold' make target will clone the chart into the current directory to wire
+it up for skaffold to use. To trigger redeployments you'll need to run `make linux-binary` and skaffold will rebuild the image
+and update the helm release.
+
+```sh
+make bootstrap-skaffold
+make linux-binary
+skaffold dev
+```
+
 ## Releasing
 To create a release of kai, a tag needs to be created that points to a commit in `main`
 that we want to release. This tag shall be a semver prefixed with a `v`, e.g. `v0.2.7`.

cmd/root.go

@@ -21,6 +21,7 @@ var rootCmd = &cobra.Command{
     Kubernetes Cluster API(s) to tell Anchore which Images are currently in-use`,
 	Args: cobra.MaximumNArgs(0),
 	Run: func(cmd *cobra.Command, args []string) {
+		log.Info("KAI is starting up...")
 		if appConfig.Dev.ProfileCPU {
 			f, err := os.Create("cpu.profile")
 			if err != nil {
@@ -96,4 +97,11 @@ func init() {
 		fmt.Printf("unable to bind flag '%s': %+v", opt, err)
 		os.Exit(1)
 	}
+
+	opt = "verbose-inventory-reports"
+	rootCmd.Flags().BoolP(opt, "i", false, "If true, will print the full inventory report to stdout")
+	if err := viper.BindPFlag(opt, rootCmd.Flags().Lookup(opt)); err != nil {
+		fmt.Printf("unable to bind flag '%s': %+v", opt, err)
+		os.Exit(1)
+	}
 }

internal/config/config.go

@@ -12,6 +12,8 @@ package config
 
 import (
 	"fmt"
+	"path"
+	"strings"
 
 	"gopkg.in/yaml.v2"
 
@@ -23,9 +25,6 @@ import (
 	"github.com/mitchellh/go-homedir"
 	"github.com/sirupsen/logrus"
 	"github.com/spf13/viper"
-
-	"path"
-	"strings"
 )
 
 const redacted = "******"
@@ -56,6 +55,7 @@ type Application struct {
 	IgnoreNotRunning                bool        `mapstructure:"ignore-not-running"`
 	PollingIntervalSeconds          int         `mapstructure:"polling-interval-seconds"`
 	AnchoreDetails                  AnchoreInfo `mapstructure:"anchore"`
+	VerboseInventoryReports         bool        `mapstructure:"verbose-inventory-reports"`
 }
 
 // MissingTagConf details the policy for handling missing tags when reporting images
@@ -201,7 +201,7 @@ func (cfg *Application) Build() error {
 			case v >= 2:
 				cfg.Log.LevelOpt = logrus.DebugLevel
 			default:
-				cfg.Log.LevelOpt = logrus.ErrorLevel
+				cfg.Log.LevelOpt = logrus.InfoLevel
 			}
 		}
 	}
@@ -320,7 +320,6 @@ func (cfg Application) String() string {
 
 	// yaml is pretty human friendly (at least when compared to json)
 	appCfgStr, err := yaml.Marshal(&cfg)
-
 	if err != nil {
 		return err.Error()
 	}

internal/config/test-fixtures/snapshot/TestDefaultConfigString.golden

@@ -47,3 +47,4 @@ anchoredetails:
   http:
     insecure: false
     timeoutseconds: 10
+verboseinventoryreports: false

internal/config/test-fixtures/snapshot/TestEmptyConfigString.golden

@@ -47,3 +47,4 @@ anchoredetails:
   http:
     insecure: false
     timeoutseconds: 0
+verboseinventoryreports: false

internal/config/test-fixtures/snapshot/TestSensitiveConfigString.golden

@@ -47,3 +47,4 @@ anchoredetails:
   http:
     insecure: false
     timeoutseconds: 10
+verboseinventoryreports: false

internal/tracker/time.go

@@ -0,0 +1,27 @@
+package tracker
+
+import (
+	"time"
+
+	"github.com/anchore/kai/internal/log"
+)
+
+// TrackFunctionTime is a function that tracks the time it takes to execute a function
+// and logs the time it took to execute the function
+//
+// It takes a time.Time object and a string as parameters
+// The time.Time object is the time the function started executing
+// The string is the name of the function that is being tracked (or any arbitrary message useful for logging)
+//
+// It is intended to be run at the beginning of a function and defer the function call
+// for example:
+//
+//	func someFunction() {
+//		start := time.Now()
+//		defer TrackFunctionTime(start, "someFunction")
+//		// do stuff
+//	}
+func TrackFunctionTime(start time.Time, msg string) {
+	elapsed := time.Since(start)
+	log.Log.Debugf("%s took %s", msg, elapsed)
+}

kai/lib.go

@@ -1,8 +1,7 @@
 /*
 Package kai retrieves Kubernetes In-Use Image data from the Kubernetes API. Runs adhoc and periodically, using the
 k8s go SDK
-*/
-package kai
+*/package kai
 
 import (
 	"context"
@@ -19,6 +18,7 @@ import (
 
 	"github.com/anchore/kai/internal/config"
 	"github.com/anchore/kai/internal/log"
+	"github.com/anchore/kai/internal/tracker"
 	"github.com/anchore/kai/kai/client"
 	"github.com/anchore/kai/kai/inventory"
 	"github.com/anchore/kai/kai/logger"
@@ -37,12 +37,15 @@ func HandleReport(report inventory.Report, cfg *config.Application) error {
 		if err := reporter.Post(report, cfg.AnchoreDetails); err != nil {
 			return fmt.Errorf("unable to report Inventory to Anchore: %w", err)
 		}
+		log.Info("Inventory report sent to Anchore")
 	} else {
-		log.Debug("Anchore details not specified, not reporting inventory")
+		log.Info("Anchore details not specified, not reporting inventory")
 	}
 
-	if err := presenter.GetPresenter(cfg.PresenterOpt, report).Present(os.Stdout); err != nil {
-		return fmt.Errorf("unable to show inventory: %w", err)
+	if cfg.VerboseInventoryReports {
+		if err := presenter.GetPresenter(cfg.PresenterOpt, report).Present(os.Stdout); err != nil {
+			return fmt.Errorf("unable to show inventory: %w", err)
+		}
 	}
 	return nil
 }
@@ -64,6 +67,8 @@ func PeriodicallyGetInventoryReport(cfg *config.Application) {
 			}
 		}
 
+		log.Infof("Waiting %d seconds for next poll...", cfg.PollingIntervalSeconds)
+
 		// Wait at least as long as the ticker
 		log.Debugf("Start new gather: %s", <-ticker.C)
 	}
@@ -93,8 +98,18 @@ func launchPodWorkerPool(cfg *config.Application, kubeconfig *rest.Config, ch ch
 	}
 }
 
+func getImageCountFromResults(results []inventory.ReportItem) int {
+	imageCount := 0
+	for _, result := range results {
+		imageCount += len(result.Images)
+	}
+	return imageCount
+}
+
 // GetInventoryReport is an atomic method for getting in-use image results, in parallel for multiple namespaces
 func GetInventoryReport(cfg *config.Application) (inventory.Report, error) {
+	log.Info("Starting image inventory collection")
+
 	kubeconfig, err := client.GetKubeConfig(cfg)
 	if err != nil {
 		return inventory.Report{}, err
@@ -151,6 +166,11 @@ func GetInventoryReport(cfg *config.Application) (inventory.Report, error) {
 		return inventory.Report{}, fmt.Errorf("failed to get Cluster Server Version: %w", err)
 	}
 
+	log.Infof(
+		"Got Inventory Report with %d images running across %d namespaces",
+		getImageCountFromResults(results),
+		len(results),
+	)
 	return inventory.Report{
 		Timestamp:             time.Now().UTC().Format(time.RFC3339),
 		Results:               results,
@@ -223,6 +243,7 @@ func excludeNamespace(checks []excludeCheck, namespace string) bool {
 // OR if there are no namespaces listed in the configuration then it will
 // return every namespace in the cluster.
 func fetchNamespaces(kubeconfig *rest.Config, cfg *config.Application) ([]string, error) {
+	defer tracker.TrackFunctionTime(time.Now(), "Fetching namespaces")
 	namespaces := make([]string, 0)
 
 	exclusionChecklist := buildExclusionChecklist(cfg.NamespaceSelectors.Exclude)
@@ -274,6 +295,7 @@ func fetchNamespaces(kubeconfig *rest.Config, cfg *config.Application) ([]string
 
 // Atomic Function that gets all the Namespace Images for a given searchNamespace and reports them to the unbuffered results channel
 func fetchPodsInNamespace(clientset *kubernetes.Clientset, cfg *config.Application, ns string, ch channels) {
+	defer tracker.TrackFunctionTime(time.Now(), "Fetching pods in namespace: "+ns)
 	pods := make([]v1.Pod, 0)
 	cont := ""
 	for {
@@ -299,7 +321,7 @@ func fetchPodsInNamespace(clientset *kubernetes.Clientset, cfg *config.Applicati
 		}
 	}
 
-	log.Debugf("There are %d pods in namespace \"%s\"", len(pods), ns)
+	log.Infof("There are %d pods in namespace \"%s\"", len(pods), ns)
 	ch.reportItem <- inventory.NewReportItem(pods, ns, cfg.IgnoreNotRunning, cfg.MissingTagPolicy.Policy, cfg.MissingTagPolicy.Tag)
 }
 

kai/reporter/reporter.go

@@ -12,6 +12,7 @@ import (
 
 	"github.com/anchore/kai/internal/config"
 	"github.com/anchore/kai/internal/log"
+	"github.com/anchore/kai/internal/tracker"
 	"github.com/anchore/kai/kai/inventory"
 )
 
@@ -21,6 +22,7 @@ const ReportAPIPath = "v1/enterprise/inventories"
 //
 //nolint:gosec
 func Post(report inventory.Report, anchoreDetails config.AnchoreInfo) error {
+	defer tracker.TrackFunctionTime(time.Now(), "Reporting results to Anchore for cluster: "+report.ClusterName+"")
 	log.Debug("Reporting results to Anchore")
 	tr := &http.Transport{
 		TLSClientConfig: &tls.Config{InsecureSkipVerify: anchoreDetails.HTTP.Insecure},

skaffold.yaml

@@ -0,0 +1,23 @@
+apiVersion: skaffold/v4beta2
+kind: Config
+metadata:
+  name: kai
+build:
+  artifacts:
+  - image: local/kai
+    docker:
+      dockerfile: Dockerfile.skaffold
+deploy:
+  helm:
+    releases:
+    - name: kai
+      chartPath: anchore-charts/stable/kai
+      setValueTemplates:
+        image.repository: "{{.IMAGE_REPO_local_kai}}"
+        image.tag: "{{.IMAGE_TAG_local_kai}}"
+      setValues:
+        kai.log.level: debug
+        kai.log.structured: false
+        kai.quiet: false
+        kai.verboseInventoryReports: false
+        kai.pollingIntervalSeconds: 60