Introduce go-logr to allow injecting loggers

This change adds a dependency on `go-logr/logr` and replaces all uses of
the `log` package from Go's standard library with a `logr`-based
implementation.

To ease the transition, and to keep the diff small, this change
introduces a package `github.com/google/ko/pkg/log` that should be
imported in place of `log` from the standard library.

The new package provides some of the same functions as `log`, e.g.,
`Printf()` and `Fatalf()`. The replacement functions takes an extra
`context.Context` argument. The `Context` is used to look up the
`logr.Logger` to use for logging.

Existing log statements have been updated to use the transition
functions, with `Context` plumbed through where required.

New code can use the new logging syntax, e.g.:

```go
log.L(ctx).Info("something interesting happened", "key", "value")
```

or

```go
log.L(ctx).Error(err, "uh oh", "what", "snafu")
```

This change alters the log output to `logr`'s structured output, with
named fields for the log message and level. As an example, a log line
that previously looked like this:

```
2022/01/25 19:44:18 Building github.com/google/ko/test for linux/amd64
```

Will look like as follows with this change:

```
2022/01/25 19:46:02 ko: "level"=1 "msg"="Building github.com/google/ko/test for linux/amd64"
```

Fixes: ko-build#560
Related: ko-build#542

go.mod

@@ -7,6 +7,8 @@ require (
 	github.com/docker/docker v20.10.12+incompatible
 	github.com/dprotaso/go-yit v0.0.0-20191028211022-135eb7262960
 	github.com/fsnotify/fsnotify v1.5.1
+	github.com/go-logr/logr v1.2.2
+	github.com/go-logr/stdr v1.2.2
 	github.com/go-training/helloworld v0.0.0-20200225145412-ba5f4379d78b
 	github.com/google/go-cmp v0.5.7
 	github.com/google/go-containerregistry v0.8.0

go.sum

@@ -602,8 +602,11 @@ github.com/go-logr/logr v0.1.0/go.mod h1:ixOQHD9gLJUVQQ2ZOR7zLEifBX6tGkNJF4QyIY7
 github.com/go-logr/logr v0.2.0/go.mod h1:z6/tIYblkpsD+a4lm/fGIIU9mZ+XfAiaFtq7xTgseGU=
 github.com/go-logr/logr v0.4.0/go.mod h1:z6/tIYblkpsD+a4lm/fGIIU9mZ+XfAiaFtq7xTgseGU=
 github.com/go-logr/logr v1.0.0/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
-github.com/go-logr/logr v1.2.0 h1:QK40JKJyMdUDz+h+xvCsru/bJhvG0UxvePV0ufL/AcE=
 github.com/go-logr/logr v1.2.0/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
+github.com/go-logr/logr v1.2.2 h1:ahHml/yUpnlb96Rp8HCvtYVPY8ZYpxq3g7UYchIYwbs=
+github.com/go-logr/logr v1.2.2/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A=
+github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag=
+github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE=
 github.com/go-openapi/analysis v0.0.0-20180825180245-b006789cd277/go.mod h1:k70tL6pCuVxPJOHXQ+wIac1FUrvNkHolPie/cLEU6hI=
 github.com/go-openapi/analysis v0.17.0/go.mod h1:IowGgpVeD0vNm45So8nr+IcQ3pxVtpRoBWb8PVZO0ik=
 github.com/go-openapi/analysis v0.18.0/go.mod h1:IowGgpVeD0vNm45So8nr+IcQ3pxVtpRoBWb8PVZO0ik=

main.go

@@ -18,21 +18,58 @@ package main
 
 import (
 	"context"
-	"log"
+	stdlog "log"
 	"os"
 	"os/signal"
 
+	"github.com/go-logr/logr"
+	"github.com/go-logr/stdr"
 	"github.com/google/go-containerregistry/pkg/logs"
+
 	"github.com/google/ko/pkg/commands"
+	"github.com/google/ko/pkg/log"
 )
 
-func main() {
-	logs.Warn.SetOutput(os.Stderr)
-	logs.Progress.SetOutput(os.Stderr)
+const (
+	defaultVerbosity = 1
+)
 
-	ctx, stop := signal.NotifyContext(context.Background(), os.Interrupt)
+func main() {
+	ctx := context.Background()
+	ctx, stop := signal.NotifyContext(configureLogging(ctx), os.Interrupt)
 	defer stop()
 	if err := commands.Root.ExecuteContext(ctx); err != nil {
-		log.Fatal("error during command execution:", err)
+		log.Fatal(ctx, "error during command execution:", err)
 	}
 }
+
+// configureLogging log logr logs logger logging
+func configureLogging(ctx context.Context) context.Context {
+	logger := defaultLogger()
+	configureGGCRLogging(logger)
+	return logr.NewContext(ctx, logger)
+}
+
+// defaultLogger returns a logr.Logger instance that wraps log.Logger from Go's standard library.
+// This function is placed here so `pkg` does not depend on the `stdr` module.
+func defaultLogger() logr.Logger {
+	stdLogger := stdlog.Default()
+	logger := stdr.New(stdLogger).V(defaultVerbosity).WithName("ko")
+	stdr.SetVerbosity(defaultVerbosity)
+	return logger
+}
+
+// configureGGCRLogging maps ggcr log levels as follows:
+//
+// ggcr Warn     -> logr V(0)
+// ggcr Progress -> logr V(defaultVerbosity)
+// ggcr Debug    -> logr V(defaultVerbosity + 1)
+func configureGGCRLogging(logger logr.Logger) {
+	ggcrLogger := logger.WithName("go-containerregistry")
+	logs.Warn.SetFlags(0)
+	logs.Warn.SetOutput(log.NewWriter(ggcrLogger.V(-1)))
+	logs.Progress.SetFlags(0)
+	logs.Progress.SetOutput(log.NewWriter(ggcrLogger))
+	logs.Debug.SetFlags(0)
+	logs.Debug.SetOutput(log.NewWriter(ggcrLogger.V(1)))
+}

pkg/build/cache.go

@@ -19,7 +19,6 @@ import (
 	"context"
 	"encoding/json"
 	"fmt"
-	"log"
 	"os"
 	"os/exec"
 	"path/filepath"
@@ -28,6 +27,8 @@ import (
 
 	v1 "github.com/google/go-containerregistry/pkg/v1"
 	"github.com/google/go-containerregistry/pkg/v1/partial"
+
+	"github.com/google/ko/pkg/log"
 )
 
 type diffIDToDescriptor map[v1.Hash]v1.Descriptor
@@ -61,7 +62,7 @@ func (c *layerCache) get(ctx context.Context, file string, miss layerFactory) (v
 		return nil, err
 	}
 	if err := c.put(ctx, file, layer); err != nil {
-		log.Printf("failed to cache metadata %s: %v", file, err)
+		log.Printf(ctx, "failed to cache metadata %s: %v", file, err)
 	}
 	return layer, nil
 }
@@ -203,7 +204,7 @@ func getBuildID(ctx context.Context, file string) (string, error) {
 	cmd.Stdout = &output
 
 	if err := cmd.Run(); err != nil {
-		log.Printf("Unexpected error running \"go tool buildid %s\": %v\n%v", err, file, output.String())
+		log.Printf(ctx, "Unexpected error running \"go tool buildid %s\": %v\n%v", err, file, output.String())
 		return "", err
 	}
 	return strings.TrimSpace(output.String()), nil

pkg/build/gobuild.go

@@ -25,7 +25,6 @@ import (
 	gb "go/build"
 	"io"
 	"io/ioutil"
-	"log"
 	"os"
 	"os/exec"
 	"path"
@@ -42,7 +41,6 @@ import (
 	"github.com/google/go-containerregistry/pkg/v1/mutate"
 	"github.com/google/go-containerregistry/pkg/v1/tarball"
 	"github.com/google/go-containerregistry/pkg/v1/types"
-	"github.com/google/ko/internal/sbom"
 	specsv1 "github.com/opencontainers/image-spec/specs-go/v1"
 	"github.com/sigstore/cosign/pkg/oci"
 	ocimutate "github.com/sigstore/cosign/pkg/oci/mutate"
@@ -52,6 +50,9 @@ import (
 	"golang.org/x/sync/errgroup"
 	"golang.org/x/sync/semaphore"
 	"golang.org/x/tools/go/packages"
+
+	"github.com/google/ko/internal/sbom"
+	"github.com/google/ko/pkg/log"
 )
 
 const (
@@ -288,12 +289,12 @@ func build(ctx context.Context, ip string, dir string, platform v1.Platform, con
 	cmd.Stderr = &output
 	cmd.Stdout = &output
 
-	log.Printf("Building %s for %s", ip, platformToString(platform))
+	log.Printf(ctx, "Building %s for %s", ip, platformToString(platform))
 	if err := cmd.Run(); err != nil {
 		if os.Getenv("KOCACHE") == "" {
 			os.RemoveAll(tmpDir)
 		}
-		log.Printf("Unexpected error running \"go build\": %v\n%v", err, output.String())
+		log.Printf(ctx, "Unexpected error running \"go build\": %v\n%v", err, output.String())
 		return "", err
 	}
 	return file, nil
@@ -469,7 +470,7 @@ const kodataRoot = "/var/run/ko"
 // walkRecursive performs a filepath.Walk of the given root directory adding it
 // to the provided tar.Writer with root -> chroot.  All symlinks are dereferenced,
 // which is what leads to recursion when we encounter a directory symlink.
-func walkRecursive(tw *tar.Writer, root, chroot string, creationTime v1.Time, platform *v1.Platform) error {
+func walkRecursive(ctx context.Context, tw *tar.Writer, root, chroot string, creationTime v1.Time, platform *v1.Platform) error {
 	return filepath.Walk(root, func(hostPath string, info os.FileInfo, err error) error {
 		if hostPath == root {
 			return nil
@@ -486,7 +487,7 @@ func walkRecursive(tw *tar.Writer, root, chroot string, creationTime v1.Time, pl
 		// Don't chase symlinks on Windows, where cross-compiled symlink support is not possible.
 		if platform.OS == "windows" {
 			if info.Mode()&os.ModeSymlink != 0 {
-				log.Println("skipping symlink in kodata for windows:", info.Name())
+				log.Println(ctx, "skipping symlink in kodata for windows:", info.Name())
 				return nil
 			}
 		}
@@ -503,7 +504,7 @@ func walkRecursive(tw *tar.Writer, root, chroot string, creationTime v1.Time, pl
 		}
 		// Skip other directories.
 		if info.Mode().IsDir() {
-			return walkRecursive(tw, evalPath, newPath, creationTime, platform)
+			return walkRecursive(ctx, tw, evalPath, newPath, creationTime, platform)
 		}
 
 		// Open the file to copy it into the tarball.
@@ -587,7 +588,7 @@ func (g *gobuild) tarKoData(ref reference, platform *v1.Platform) (*bytes.Buffer
 		}
 	}
 
-	return buf, walkRecursive(tw, root, chroot, creationTime, platform)
+	return buf, walkRecursive(g.ctx, tw, root, chroot, creationTime, platform)
 }
 
 func createTemplateData() map[string]interface{} {
@@ -658,7 +659,7 @@ func (g *gobuild) configForImportPath(ip string) Config {
 	}
 
 	if config.ID != "" {
-		log.Printf("Using build config %s for %s", config.ID, ip)
+		log.Printf(g.ctx, "Using build config %s for %s", config.ID, ip)
 	}
 
 	return config

pkg/commands/apply.go

@@ -17,15 +17,16 @@ package commands
 import (
 	"errors"
 	"fmt"
-	"log"
 	"os"
 	"os/exec"
 	"strings"
 
-	"github.com/google/ko/internal"
-	"github.com/google/ko/pkg/commands/options"
 	"github.com/spf13/cobra"
 	"golang.org/x/sync/errgroup"
+
+	"github.com/google/ko/internal"
+	"github.com/google/ko/pkg/commands/options"
+	"github.com/google/ko/pkg/log"
 )
 
 const kubectlFlagsWarningTemplate = `NOTICE!
@@ -92,7 +93,7 @@ func addApply(topLevel *cobra.Command) {
 			if err != nil {
 				return fmt.Errorf("error creating builder: %w", err)
 			}
-			publisher, err := makePublisher(po)
+			publisher, err := makePublisher(ctx, po)
 			if err != nil {
 				return fmt.Errorf("error creating publisher: %w", err)
 			}
@@ -104,7 +105,7 @@ func addApply(topLevel *cobra.Command) {
 			argv := []string{"apply", "-f", "-"}
 			if kflags := kf.Values(); len(kflags) != 0 {
 				skflags := strings.Join(kflags, " ")
-				log.Printf(kubectlFlagsWarningTemplate,
+				log.Printf(ctx, kubectlFlagsWarningTemplate,
 					"apply", skflags,
 					"apply", skflags)
 				argv = append(argv, kflags...)

pkg/commands/build.go

@@ -65,7 +65,7 @@ func addBuild(topLevel *cobra.Command) {
 			if err != nil {
 				return fmt.Errorf("error creating builder: %w", err)
 			}
-			publisher, err := makePublisher(po)
+			publisher, err := makePublisher(ctx, po)
 			if err != nil {
 				return fmt.Errorf("error creating publisher: %w", err)
 			}

pkg/commands/config.go

@@ -19,7 +19,6 @@ package commands
 import (
 	"context"
 	"fmt"
-	"log"
 	"os"
 	"strconv"
 	"strings"
@@ -34,6 +33,7 @@ import (
 
 	"github.com/google/ko/pkg/build"
 	"github.com/google/ko/pkg/commands/options"
+	"github.com/google/ko/pkg/log"
 	"github.com/google/ko/pkg/publish"
 )
 
@@ -129,7 +129,7 @@ func getBaseImage(bo *options.BuildOptions) build.GetBase {
 			return ref, cached, nil
 		}
 
-		log.Printf("Using base %s for %s", ref, s)
+		log.Printf(ctx, "Using base %s for %s", ref, s)
 		result, err := fetch(ctx, ref)
 		if err != nil {
 			return ref, result, err

pkg/commands/create.go

@@ -17,15 +17,16 @@ package commands
 import (
 	"errors"
 	"fmt"
-	"log"
 	"os"
 	"os/exec"
 	"strings"
 
-	"github.com/google/ko/internal"
-	"github.com/google/ko/pkg/commands/options"
 	"github.com/spf13/cobra"
 	"golang.org/x/sync/errgroup"
+
+	"github.com/google/ko/internal"
+	"github.com/google/ko/pkg/commands/options"
+	"github.com/google/ko/pkg/log"
 )
 
 // addCreate augments our CLI surface with apply.
@@ -77,7 +78,7 @@ func addCreate(topLevel *cobra.Command) {
 			if err != nil {
 				return fmt.Errorf("error creating builder: %w", err)
 			}
-			publisher, err := makePublisher(po)
+			publisher, err := makePublisher(ctx, po)
 			if err != nil {
 				return fmt.Errorf("error creating publisher: %w", err)
 			}
@@ -89,7 +90,7 @@ func addCreate(topLevel *cobra.Command) {
 			argv := []string{"create", "-f", "-"}
 			if kflags := kf.Values(); len(kflags) != 0 {
 				skflags := strings.Join(stripPassword(kflags), " ")
-				log.Printf(kubectlFlagsWarningTemplate,
+				log.Printf(ctx, kubectlFlagsWarningTemplate,
 					"create", skflags,
 					"create", skflags)
 				argv = append(argv, kflags...)

pkg/commands/publisher_test.go

@@ -75,7 +75,7 @@ func TestPublishImages(t *testing.T) {
 			DockerRepo:          repo,
 			PreserveImportPaths: true,
 		}
-		publisher, err := NewPublisher(po)
+		publisher, err := NewPublisher(ctx, po)
 		if err != nil {
 			t.Fatalf("%s: MakePublisher(): %v", test.description, err)
 		}

pkg/commands/resolve.go

@@ -62,7 +62,7 @@ func addResolve(topLevel *cobra.Command) {
 			if err != nil {
 				return fmt.Errorf("error creating builder: %w", err)
 			}
-			publisher, err := makePublisher(po)
+			publisher, err := makePublisher(ctx, po)
 			if err != nil {
 				return fmt.Errorf("error creating publisher: %w", err)
 			}

pkg/commands/resolver.go

@@ -23,7 +23,6 @@ import (
 	"fmt"
 	"io"
 	"io/ioutil"
-	"log"
 	"os"
 	"path"
 	"strings"
@@ -38,6 +37,7 @@ import (
 
 	"github.com/google/ko/pkg/build"
 	"github.com/google/ko/pkg/commands/options"
+	"github.com/google/ko/pkg/log"
 	"github.com/google/ko/pkg/publish"
 	"github.com/google/ko/pkg/resolve"
 )
@@ -162,11 +162,11 @@ func makeBuilder(ctx context.Context, bo *options.BuildOptions) (*build.Caching,
 }
 
 // NewPublisher creates a ko publisher
-func NewPublisher(po *options.PublishOptions) (publish.Interface, error) {
-	return makePublisher(po)
+func NewPublisher(ctx context.Context, po *options.PublishOptions) (publish.Interface, error) {
+	return makePublisher(ctx, po)
 }
 
-func makePublisher(po *options.PublishOptions) (publish.Interface, error) {
+func makePublisher(ctx context.Context, po *options.PublishOptions) (publish.Interface, error) {
 	// Create the publish.Interface that we will use to publish image references
 	// to either a docker daemon or a container image registry.
 	innerPublisher, err := func() (publish.Interface, error) {
@@ -203,15 +203,17 @@ func makePublisher(po *options.PublishOptions) (publish.Interface, error) {
 			publishers = append(publishers, lp)
 		}
 		if po.TarballFile != "" {
-			tp := publish.NewTarball(po.TarballFile, repoName, namer, po.Tags)
+			tp := publish.NewTarball(ctx, po.TarballFile, repoName, namer, po.Tags)
 			publishers = append(publishers, tp)
 		}
 		userAgent := ua()
 		if po.UserAgent != "" {
 			userAgent = po.UserAgent
 		}
 		if po.Push {
-			dp, err := publish.NewDefault(repoName,
+			dp, err := publish.NewDefault(
+				ctx,
+				repoName,
 				publish.WithUserAgent(userAgent),
 				publish.WithAuthFromKeychain(authn.DefaultKeychain),
 				publish.WithNamer(namer),
@@ -377,7 +379,7 @@ func resolveFilesToWriter(
 					// isn't fatal. Just print it and keep the watch open.
 					err := fmt.Errorf("error processing import paths in %q: %w", f, err)
 					if fo.Watch {
-						log.Print(err)
+						log.Print(ctx, err)
 						return nil
 					}
 					return err