Additional logging + improvements

Follow-up to #766
- Shift linting name logging to debug logging. Instead of sending everything to stdout, we can now have a cleaner "report"
- Missed some `log.Printf`(alias for Debug) in helm code, shifted that to info logs
- Added some caching logs, whether or not it's a cache hit + time elasped to calculate hash
- Changed `time` for `duration_ms` in env loading log. This conflicts with the log time

cmd/tk/lint.go

@@ -27,7 +27,12 @@ func lintCmd() *cli.Command {
 
 	exclude := cmd.Flags().StringSliceP("exclude", "e", []string{"**/.*", ".*", "**/vendor/**", "vendor/**"}, "globs to exclude")
 	parallelism := cmd.Flags().IntP("parallelism", "n", 4, "amount of workers")
-	verbose := cmd.Flags().BoolP("verbose", "v", false, "print each checked file")
+
+	// shifted to debug logs
+	cmd.Flags().BoolP("verbose", "v", false, "print each checked file")
+	if err := cmd.Flags().MarkDeprecated("verbose", "logs are sent to debug now, this is unused"); err != nil {
+		panic(err)
+	}
 
 	cmd.Run = func(cmd *cli.Command, args []string) error {
 		globs := make([]glob.Glob, len(*exclude))
@@ -39,7 +44,7 @@ func lintCmd() *cli.Command {
 			globs[i] = g
 		}
 
-		return jsonnet.Lint(args, &jsonnet.LintOpts{Excludes: globs, PrintNames: *verbose, Parallelism: *parallelism})
+		return jsonnet.Lint(args, &jsonnet.LintOpts{Excludes: globs, Parallelism: *parallelism})
 	}
 
 	return cmd

pkg/helm/charts.go

@@ -138,7 +138,7 @@ func (c Charts) Vendor(prune bool) error {
 			}
 
 			if chartYAML.Version.String() == r.Version.String() {
-				log.Info().Msgf(" %s exists", r)
+				log.Info().Msgf("%s exists", r)
 				continue
 			} else {
 				log.Info().Msgf("Removing %s", r)
@@ -174,7 +174,7 @@ func (c Charts) Vendor(prune bool) error {
 			return err
 		}
 
-		log.Info().Msgf(" %s@%s downloaded", r.Chart, r.Version.String())
+		log.Info().Msgf("%s@%s downloaded", r.Chart, r.Version.String())
 	}
 
 	if prune {
@@ -202,7 +202,7 @@ func (c Charts) Vendor(prune bool) error {
 // Add adds every Chart in reqs to the Manifest after validation, and runs
 // Vendor afterwards
 func (c *Charts) Add(reqs []string) error {
-	log.Printf("Adding %v Charts ...", len(reqs))
+	log.Info().Msgf("Adding %v Charts ...", len(reqs))
 
 	// parse new charts, append in memory
 	requirements := c.Manifest.Requires
@@ -219,7 +219,7 @@ func (c *Charts) Add(reqs []string) error {
 		}
 
 		requirements = append(requirements, *r)
-		log.Info().Msgf(" OK: %s", s)
+		log.Info().Msgf("OK: %s", s)
 	}
 
 	if err := requirements.Validate(); err != nil {
@@ -239,7 +239,7 @@ func (c *Charts) Add(reqs []string) error {
 	}
 
 	// worked fine? vendor it
-	log.Printf("Added %v Charts to helmfile.yaml. Vendoring ...", added)
+	log.Info().Msgf("Added %v Charts to helmfile.yaml. Vendoring ...", added)
 	return c.Vendor(false)
 }
 
@@ -258,7 +258,7 @@ func (c *Charts) AddRepos(repos ...Repo) error {
 
 		c.Manifest.Repositories = append(c.Manifest.Repositories, r)
 		added++
-		log.Info().Msgf(" OK: %s", r.Name)
+		log.Info().Msgf("OK: %s", r.Name)
 	}
 
 	// write out
@@ -346,5 +346,5 @@ func parseReqName(s string) string {
 }
 
 func skip(s string, err error) {
-	log.Printf(" Skipping %s: %s.", s, err)
+	log.Info().Msgf("Skipping %s: %s.", s, err)
 }

pkg/jsonnet/eval.go

@@ -3,9 +3,11 @@ package jsonnet
 import (
 	"os"
 	"regexp"
+	"time"
 
 	jsonnet "github.com/google/go-jsonnet"
 	"github.com/pkg/errors"
+	"github.com/rs/zerolog/log"
 
 	"github.com/grafana/tanka/pkg/jsonnet/jpath"
 	"github.com/grafana/tanka/pkg/jsonnet/native"
@@ -141,14 +143,18 @@ func evaluateSnippet(evalFunc evalFunc, path, data string, opts Opts) (string, e
 
 	var hash string
 	if cache != nil {
+		startTime := time.Now()
 		if hash, err = getSnippetHash(vm, path, data); err != nil {
 			return "", err
 		}
+		cacheLog := log.Debug().Str("path", path).Str("hash", hash).Dur("duration_ms", time.Since(startTime))
 		if v, err := cache.Get(hash); err != nil {
 			return "", err
 		} else if v != "" {
+			cacheLog.Bool("cache_hit", true).Msg("computed snippet hash")
 			return v, nil
 		}
+		cacheLog.Bool("cache_hit", false).Msg("computed snippet hash")
 	}
 
 	content, err := evalFunc(vm)

pkg/jsonnet/lint.go

@@ -5,11 +5,13 @@ import (
 	"fmt"
 	"os"
 	"path/filepath"
+	"time"
 
 	"github.com/gobwas/glob"
 	"github.com/google/go-jsonnet/linter"
 	"github.com/grafana/tanka/pkg/jsonnet/jpath"
 	"github.com/pkg/errors"
+	"github.com/rs/zerolog/log"
 )
 
 // LintOpts modifies the behaviour of Lint
@@ -18,9 +20,6 @@ type LintOpts struct {
 	// files
 	Excludes []glob.Glob
 
-	// PrintNames causes all filenames to be printed
-	PrintNames bool
-
 	// Parallelism determines the number of workers that will process files
 	Parallelism int
 }
@@ -54,9 +53,8 @@ func Lint(fds []string, opts *LintOpts) error {
 				continue
 			}
 
-			if opts.PrintNames {
-				fmt.Printf("Linting %s...\n", file)
-			}
+			log.Debug().Str("file", file).Msg("linting file")
+			startTime := time.Now()
 
 			vm := MakeVM(Opts{})
 			jpaths, _, _, err := jpath.Resolve(file, true)
@@ -71,6 +69,7 @@ func Lint(fds []string, opts *LintOpts) error {
 			content, _ := os.ReadFile(file)
 			failed := linter.LintSnippet(vm, buf, []linter.Snippet{{FileName: file, Code: string(content)}})
 			resultCh <- result{failed: failed, output: buf.String()}
+			log.Debug().Str("file", file).Dur("duration_ms", time.Since(startTime)).Msg("linted file")
 		}
 	}
 

pkg/tanka/parallel.go

@@ -98,6 +98,6 @@ func parallelWorker(jobsCh <-chan parallelJob, outCh chan parallelOut) {
 		}
 		outCh <- parallelOut{env: env, err: err}
 
-		log.Debug().Str("name", job.opts.Name).Str("path", job.path).Dur("time", time.Since(startTime)).Msg("Finished loading environment")
+		log.Debug().Str("name", job.opts.Name).Str("path", job.path).Dur("duration_ms", time.Since(startTime)).Msg("Finished loading environment")
 	}
 }