cmd/opem/serve: improve logging related to caches

Signed-off-by: Joe Lanford <[email protected]>

alpha/action/render.go

@@ -6,7 +6,6 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
-	"io"
 	"os"
 	"path/filepath"
 	"sort"
@@ -17,7 +16,6 @@ import (
 	"github.com/h2non/filetype"
 	"github.com/h2non/filetype/matchers"
 	"github.com/operator-framework/api/pkg/operators/v1alpha1"
-	"github.com/sirupsen/logrus"
 	"k8s.io/apimachinery/pkg/util/sets"
 
 	"github.com/operator-framework/operator-registry/alpha/declcfg"
@@ -26,6 +24,7 @@ import (
 	"github.com/operator-framework/operator-registry/pkg/image"
 	"github.com/operator-framework/operator-registry/pkg/image/containerdregistry"
 	"github.com/operator-framework/operator-registry/pkg/lib/bundle"
+	"github.com/operator-framework/operator-registry/pkg/lib/log"
 	"github.com/operator-framework/operator-registry/pkg/registry"
 	"github.com/operator-framework/operator-registry/pkg/sqlite"
 )
@@ -61,12 +60,6 @@ type Render struct {
 	skipSqliteDeprecationLog bool
 }
 
-func nullLogger() *logrus.Entry {
-	logger := logrus.New()
-	logger.SetOutput(io.Discard)
-	return logrus.NewEntry(logger)
-}
-
 func (r Render) Run(ctx context.Context) (*declcfg.DeclarativeConfig, error) {
 	if r.skipSqliteDeprecationLog {
 		// exhaust once with a no-op function.
@@ -119,7 +112,7 @@ func (r Render) createRegistry() (*containerdregistry.Registry, error) {
 		// The containerd registry impl is somewhat verbose, even on the happy path,
 		// so discard all logger logs. Any important failures will be returned from
 		// registry methods and eventually logged as fatal errors.
-		containerdregistry.WithLog(nullLogger()),
+		containerdregistry.WithLog(log.Null()),
 	)
 	if err != nil {
 		return nil, err

cmd/opm/internal/util/util.go

@@ -2,12 +2,12 @@ package util
 
 import (
 	"errors"
-	"io"
 	"os"
 
-	"github.com/operator-framework/operator-registry/pkg/image/containerdregistry"
-	"github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
+
+	"github.com/operator-framework/operator-registry/pkg/image/containerdregistry"
+	"github.com/operator-framework/operator-registry/pkg/lib/log"
 )
 
 // GetTLSOptions validates and returns TLS options set by opm flags
@@ -59,16 +59,10 @@ func CreateCLIRegistry(cmd *cobra.Command) (*containerdregistry.Registry, error)
 		containerdregistry.WithCacheDir(cacheDir),
 		containerdregistry.SkipTLSVerify(skipTlsVerify),
 		containerdregistry.WithPlainHTTP(useHTTP),
-		containerdregistry.WithLog(nullLogger()),
+		containerdregistry.WithLog(log.Null()),
 	)
 	if err != nil {
 		return nil, err
 	}
 	return reg, nil
 }
-
-func nullLogger() *logrus.Entry {
-	logger := logrus.New()
-	logger.SetOutput(io.Discard)
-	return logrus.NewEntry(logger)
-}

cmd/opm/render/cmd.go

@@ -94,9 +94,3 @@ those images actually existing. Available template variables are:
 	cmd.Long += "\n" + sqlite.DeprecationMessage
 	return cmd
 }
-
-func nullLogger() *logrus.Entry {
-	logger := logrus.New()
-	logger.SetOutput(io.Discard)
-	return logrus.NewEntry(logger)
-}

cmd/opm/serve/serve.go

@@ -110,8 +110,6 @@ func (s *serve) run(ctx context.Context) error {
 		s.logger.WithError(err).Warn("unable to write default nsswitch config")
 	}
 
-	s.logger = s.logger.WithFields(logrus.Fields{"configs": s.configDir, "port": s.port})
-
 	if s.cacheDir == "" && s.cacheEnforceIntegrity {
 		return fmt.Errorf("--cache-dir must be specified with --cache-enforce-integrity")
 	}
@@ -123,8 +121,12 @@ func (s *serve) run(ctx context.Context) error {
 		}
 		defer os.RemoveAll(s.cacheDir)
 	}
+	s.logger = s.logger.WithFields(logrus.Fields{
+		"configs": s.configDir,
+		"cache":   s.cacheDir,
+	})
 
-	store, err := cache.New(s.cacheDir)
+	store, err := cache.New(s.cacheDir, cache.WithLog(s.logger))
 	if err != nil {
 		return err
 	}
@@ -146,6 +148,8 @@ func (s *serve) run(ctx context.Context) error {
 		return nil
 	}
 
+	s.logger = s.logger.WithFields(logrus.Fields{"port": s.port})
+
 	lis, err := net.Listen("tcp", ":"+s.port)
 	if err != nil {
 		return fmt.Errorf("failed to listen: %s", err)

pkg/cache/cache.go

@@ -10,8 +10,11 @@ import (
 	"path/filepath"
 	"strings"
 
+	"github.com/sirupsen/logrus"
+
 	"github.com/operator-framework/operator-registry/alpha/declcfg"
 	"github.com/operator-framework/operator-registry/pkg/api"
+	"github.com/operator-framework/operator-registry/pkg/lib/log"
 	"github.com/operator-framework/operator-registry/pkg/registry"
 )
 
@@ -25,6 +28,7 @@ type Cache interface {
 }
 
 type backend interface {
+	Name() string
 	IsCachePresent() bool
 
 	Init() error
@@ -43,22 +47,41 @@ type backend interface {
 	PutDigest(context.Context, string) error
 }
 
+type CacheOptions struct {
+	Log *logrus.Entry
+}
+
+func WithLog(log *logrus.Entry) CacheOption {
+	return func(o *CacheOptions) {
+		o.Log = log
+	}
+}
+
+type CacheOption func(*CacheOptions)
+
 // New creates a new Cache. It chooses a cache implementation based
 // on the files it finds in the cache directory, with a preference for the
 // latest iteration of the cache implementation. If the cache directory
 // is non-empty and a supported cache format is not found, an error is returned.
-func New(cacheDir string) (Cache, error) {
-	cacheBackend, err := getDefaultBackend(cacheDir)
+func New(cacheDir string, cacheOpts ...CacheOption) (Cache, error) {
+	opts := &CacheOptions{
+		Log: log.Null(),
+	}
+	for _, opt := range cacheOpts {
+		opt(opts)
+	}
+	cacheBackend, err := getDefaultBackend(cacheDir, opts.Log)
 	if err != nil {
 		return nil, err
 	}
+
 	if err := cacheBackend.Open(); err != nil {
 		return nil, fmt.Errorf("open cache: %v", err)
 	}
-	return &cache{backend: cacheBackend}, nil
+	return &cache{backend: cacheBackend, log: opts.Log}, nil
 }
 
-func getDefaultBackend(cacheDir string) (backend, error) {
+func getDefaultBackend(cacheDir string, log *logrus.Entry) (backend, error) {
 	entries, err := os.ReadDir(cacheDir)
 	if err != nil && !errors.Is(err, os.ErrNotExist) {
 		return nil, fmt.Errorf("detect cache format: read cache directory: %v", err)
@@ -70,17 +93,26 @@ func getDefaultBackend(cacheDir string) (backend, error) {
 	}
 
 	if len(entries) == 0 {
+		log.WithField("backend", backends[0].Name()).Info("cache directory is empty, using preferred backend")
 		return backends[0], nil
 	}
 
 	for _, backend := range backends {
 		if backend.IsCachePresent() {
+			log.WithField("backend", backend.Name()).Info("found existing cache contents")
 			return backend, nil
 		}
 	}
 
 	// Anything else is unexpected.
-	return nil, fmt.Errorf("cache directory has unexpected contents")
+	entryNames := make([]string, 0, len(entries))
+	for _, entry := range entries {
+		if entry.Name() == "." {
+			continue
+		}
+		entryNames = append(entryNames, entry.Name())
+	}
+	return nil, fmt.Errorf("cache directory has unexpected contents: %v", strings.Join(entryNames, ","))
 }
 
 func LoadOrRebuild(ctx context.Context, c Cache, fbc fs.FS) error {
@@ -96,6 +128,7 @@ var _ Cache = &cache{}
 
 type cache struct {
 	backend backend
+	log     *logrus.Entry
 	packageIndex
 }
 
@@ -195,6 +228,7 @@ func (c *cache) CheckIntegrity(ctx context.Context, fbc fs.FS) error {
 		return fmt.Errorf("compute digest: %v", err)
 	}
 	if existingDigest != computedDigest {
+		c.log.WithField("existingDigest", existingDigest).WithField("computedDigest", computedDigest).Warn("cache requires rebuild")
 		return fmt.Errorf("cache requires rebuild: cache reports digest as %q, but computed digest is %q", existingDigest, computedDigest)
 	}
 	return nil
@@ -205,6 +239,8 @@ func (c *cache) Build(ctx context.Context, fbcFsys fs.FS) error {
 	oldUmask := umask(000)
 	defer umask(oldUmask)
 
+	c.log.Info("building cache")
+
 	if err := c.backend.Init(); err != nil {
 		return fmt.Errorf("init cache: %v", err)
 	}

pkg/cache/json.go

@@ -40,6 +40,10 @@ type jsonBackend struct {
 	bundles bundleKeys
 }
 
+func (q *jsonBackend) Name() string {
+	return "json"
+}
+
 func (q *jsonBackend) IsCachePresent() bool {
 	entries, err := os.ReadDir(q.baseDir)
 	if err != nil && !errors.Is(err, os.ErrNotExist) {

pkg/cache/json_test.go

@@ -8,11 +8,13 @@ import (
 	"testing"
 
 	"github.com/stretchr/testify/require"
+
+	"github.com/operator-framework/operator-registry/pkg/lib/log"
 )
 
 func TestJSON_StableDigest(t *testing.T) {
 	cacheDir := t.TempDir()
-	c := &cache{backend: newJSONBackend(cacheDir)}
+	c := &cache{backend: newJSONBackend(cacheDir), log: log.Null()}
 	require.NoError(t, c.Build(context.Background(), validFS))
 
 	actualDigest, err := c.backend.GetDigest(context.Background())
@@ -94,7 +96,7 @@ func TestJSON_CheckIntegrity(t *testing.T) {
 	for _, tc := range testCases {
 		t.Run(tc.name, func(t *testing.T) {
 			cacheDir := t.TempDir()
-			c := &cache{backend: newJSONBackend(cacheDir)}
+			c := &cache{backend: newJSONBackend(cacheDir), log: log.Null()}
 
 			if tc.build {
 				require.NoError(t, c.Build(context.Background(), tc.fbcFS))

pkg/cache/pogrebv1.go

@@ -45,6 +45,10 @@ type pogrebV1Backend struct {
 	bundles bundleKeys
 }
 
+func (q *pogrebV1Backend) Name() string {
+	return pograbV1CacheDir
+}
+
 func (q *pogrebV1Backend) IsCachePresent() bool {
 	entries, err := os.ReadDir(q.baseDir)
 	if err != nil && !errors.Is(err, os.ErrNotExist) {

pkg/cache/pogrebv1_test.go

@@ -9,11 +9,12 @@ import (
 	"github.com/stretchr/testify/require"
 
 	"github.com/operator-framework/operator-registry/pkg/api"
+	"github.com/operator-framework/operator-registry/pkg/lib/log"
 )
 
 func TestPogrebV1_StableDigest(t *testing.T) {
 	cacheDir := t.TempDir()
-	c := &cache{backend: newPogrebV1Backend(cacheDir)}
+	c := &cache{backend: newPogrebV1Backend(cacheDir), log: log.Null()}
 	require.NoError(t, c.Build(context.Background(), validFS))
 
 	actualDigest, err := c.backend.GetDigest(context.Background())
@@ -94,7 +95,7 @@ func TestPogrebV1_CheckIntegrity(t *testing.T) {
 	for _, tc := range testCases {
 		t.Run(tc.name, func(t *testing.T) {
 			cacheDir := t.TempDir()
-			c := &cache{backend: newPogrebV1Backend(cacheDir)}
+			c := &cache{backend: newPogrebV1Backend(cacheDir), log: log.Null()}
 
 			if tc.build {
 				require.NoError(t, c.Build(context.Background(), tc.fbcFS))

pkg/lib/log/null.go

@@ -0,0 +1,12 @@
+package log
+
+import (
+	"github.com/sirupsen/logrus"
+	"io/ioutil"
+)
+
+func Null() *logrus.Entry {
+	l := logrus.New()
+	l.SetOutput(ioutil.Discard)
+	return logrus.NewEntry(l)
+}