Add trace logs for cache leaks.

Signed-off-by: Erik Sipsma <erik@sipsma.dev>

cache/refs.go

@@ -107,6 +107,12 @@ func (cr *cacheRecord) ref(triggerLastUsed bool, descHandlers DescHandlers, pg p
 		progress:        pg,
 	}
 	cr.refs[ref] = struct{}{}
+	bklog.G(context.TODO()).WithFields(map[string]any{
+		"id":          cr.ID(),
+		"newRefCount": len(cr.refs),
+		"mutable":     false,
+		"stack":       bklog.LazyStackTrace{},
+	}).Trace("acquired cache ref")
 	return ref
 }
 
@@ -118,6 +124,12 @@ func (cr *cacheRecord) mref(triggerLastUsed bool, descHandlers DescHandlers) *mu
 		descHandlers:    descHandlers,
 	}
 	cr.refs[ref] = struct{}{}
+	bklog.G(context.TODO()).WithFields(map[string]any{
+		"id":          cr.ID(),
+		"newRefCount": len(cr.refs),
+		"mutable":     true,
+		"stack":       bklog.LazyStackTrace{},
+	}).Trace("acquired cache ref")
 	return ref
 }
 
@@ -438,7 +450,19 @@ func (cr *cacheRecord) mount(ctx context.Context, s session.Group) (_ snapshot.M
 }
 
 // call when holding the manager lock
-func (cr *cacheRecord) remove(ctx context.Context, removeSnapshot bool) error {
+func (cr *cacheRecord) remove(ctx context.Context, removeSnapshot bool) (rerr error) {
+	defer func() {
+		l := bklog.G(ctx).WithFields(map[string]any{
+			"id":             cr.ID(),
+			"refCount":       len(cr.refs),
+			"removeSnapshot": removeSnapshot,
+			"stack":          bklog.LazyStackTrace{},
+		})
+		if rerr != nil {
+			l = l.WithError(rerr)
+		}
+		l.Trace("removed cache record")
+	}()
 	delete(cr.cm.records, cr.ID())
 	if removeSnapshot {
 		if err := cr.cm.LeaseManager.Delete(ctx, leases.Lease{
@@ -1294,9 +1318,21 @@ func (sr *immutableRef) updateLastUsedNow() bool {
 	return true
 }
 
-func (sr *immutableRef) release(ctx context.Context) error {
-	delete(sr.refs, sr)
+func (sr *immutableRef) release(ctx context.Context) (rerr error) {
+	defer func() {
+		l := bklog.G(ctx).WithFields(map[string]any{
+			"id":          sr.ID(),
+			"newRefCount": len(sr.refs),
+			"mutable":     false,
+			"stack":       bklog.LazyStackTrace{},
+		})
+		if rerr != nil {
+			l = l.WithError(rerr)
+		}
+		l.Trace("released cache ref")
+	}()
 
+	delete(sr.refs, sr)
 	if sr.updateLastUsedNow() {
 		sr.updateLastUsed()
 		if sr.equalMutable != nil {
@@ -1476,8 +1512,21 @@ func (sr *mutableRef) Release(ctx context.Context) error {
 	return sr.release(ctx)
 }
 
-func (sr *mutableRef) release(ctx context.Context) error {
+func (sr *mutableRef) release(ctx context.Context) (rerr error) {
+	defer func() {
+		l := bklog.G(ctx).WithFields(map[string]any{
+			"id":          sr.ID(),
+			"newRefCount": len(sr.refs),
+			"mutable":     true,
+			"stack":       bklog.LazyStackTrace{},
+		})
+		if rerr != nil {
+			l = l.WithError(rerr)
+		}
+		l.Trace("released cache ref")
+	}()
 	delete(sr.refs, sr)
+
 	if !sr.HasCachePolicyRetain() {
 		if sr.equalImmutable != nil {
 			if sr.equalImmutable.HasCachePolicyRetain() {

cmd/buildkitd/config/config.go

@@ -7,6 +7,7 @@ import (
 // Config provides containerd configuration data for the server
 type Config struct {
 	Debug bool `toml:"debug"`
+	Trace bool `toml:"trace"`
 
 	// Root is the path to a directory where buildkit will store persistent data
 	Root string `toml:"root"`

cmd/buildkitd/config/load_test.go

@@ -12,6 +12,7 @@ func TestLoad(t *testing.T) {
 	const testConfig = `
 root = "/foo/bar"
 debug=true
+trace=true
 insecure-entitlements = ["security.insecure"]
 
 [gc]
@@ -72,6 +73,7 @@ searchDomains=["example.com"]
 
 	require.Equal(t, "/foo/bar", cfg.Root)
 	require.Equal(t, true, cfg.Debug)
+	require.Equal(t, true, cfg.Trace)
 	require.Equal(t, "security.insecure", cfg.Entitlements[0])
 
 	require.Equal(t, "buildkit.sock", cfg.GRPC.Address[0])

cmd/buildkitd/main.go

@@ -157,6 +157,10 @@ func main() {
 			Name:  "debug",
 			Usage: "enable debug output in logs",
 		},
+		cli.BoolFlag{
+			Name:  "trace",
+			Usage: "enable trace output in logs (highly verbose, could affect performance)",
+		},
 		cli.StringFlag{
 			Name:  "root",
 			Usage: "path to state directory",
@@ -223,6 +227,9 @@ func main() {
 		if cfg.Debug {
 			logrus.SetLevel(logrus.DebugLevel)
 		}
+		if cfg.Trace {
+			logrus.SetLevel(logrus.TraceLevel)
+		}
 
 		if cfg.GRPC.DebugAddress != "" {
 			if err := setupDebugHandlers(cfg.GRPC.DebugAddress); err != nil {
@@ -457,6 +464,9 @@ func applyMainFlags(c *cli.Context, cfg *config.Config) error {
 	if c.IsSet("debug") {
 		cfg.Debug = c.Bool("debug")
 	}
+	if c.IsSet("trace") {
+		cfg.Trace = c.Bool("trace")
+	}
 	if c.IsSet("root") {
 		cfg.Root = c.String("root")
 	}

session/grpc.go

@@ -129,7 +129,7 @@ func monitorHealth(ctx context.Context, cc *grpc.ClientConn, cancelConn func())
 				}
 			}
 
-			bklog.G(ctx).WithFields(logFields).Debug("healthcheck completed")
+			bklog.G(ctx).WithFields(logFields).Trace("healthcheck completed")
 		}
 	}
 }

solver/llbsolver/mounts/mount.go

@@ -45,12 +45,16 @@ type MountManager struct {
 }
 
 func (mm *MountManager) getRefCacheDir(ctx context.Context, ref cache.ImmutableRef, id string, m *pb.Mount, sharing pb.CacheSharingOpt, s session.Group) (mref cache.MutableRef, err error) {
+	name := fmt.Sprintf("cached mount %s from %s", m.Dest, mm.managerName)
+	if id != m.Dest {
+		name += fmt.Sprintf(" with id %q", id)
+	}
 	g := &cacheRefGetter{
 		locker:          &mm.cacheMountsMu,
 		cacheMounts:     mm.cacheMounts,
 		cm:              mm.cm,
 		globalCacheRefs: sharedCacheRefs,
-		name:            fmt.Sprintf("cached mount %s from %s", m.Dest, mm.managerName),
+		name:            name,
 		session:         s,
 	}
 	return g.getRefCacheDir(ctx, ref, id, sharing)
@@ -75,19 +79,19 @@ func (g *cacheRefGetter) getRefCacheDir(ctx context.Context, ref cache.Immutable
 	defer mu.Unlock()
 
 	if ref, ok := g.cacheMounts[key]; ok {
-		return ref.clone(), nil
+		return ref.clone(ctx), nil
 	}
 	defer func() {
 		if err == nil {
 			share := &cacheRefShare{MutableRef: mref, refs: map[*cacheRef]struct{}{}}
 			g.cacheMounts[key] = share
-			mref = share.clone()
+			mref = share.clone(ctx)
 		}
 	}()
 
 	switch sharing {
 	case pb.CacheSharingOpt_SHARED:
-		return g.globalCacheRefs.get(key, func() (cache.MutableRef, error) {
+		return g.globalCacheRefs.get(ctx, key, func() (cache.MutableRef, error) {
 			return g.getRefCacheDirNoCache(ctx, key, ref, id, false)
 		})
 	case pb.CacheSharingOpt_PRIVATE:
@@ -101,7 +105,12 @@ func (g *cacheRefGetter) getRefCacheDir(ctx context.Context, ref cache.Immutable
 
 func (g *cacheRefGetter) getRefCacheDirNoCache(ctx context.Context, key string, ref cache.ImmutableRef, id string, block bool) (cache.MutableRef, error) {
 	makeMutable := func(ref cache.ImmutableRef) (cache.MutableRef, error) {
-		return g.cm.New(ctx, ref, g.session, cache.WithRecordType(client.UsageRecordTypeCacheMount), cache.WithDescription(g.name), cache.CachePolicyRetain)
+		newRef, err := g.cm.New(ctx, ref, g.session, cache.WithRecordType(client.UsageRecordTypeCacheMount), cache.WithDescription(g.name), cache.CachePolicyRetain)
+		if err != nil {
+			return nil, err
+		}
+		bklog.G(ctx).Debugf("created new ref for cache dir %q: %s", id, newRef.ID())
+		return newRef, nil
 	}
 
 	cacheRefsLocker.Lock(key)
@@ -114,10 +123,12 @@ func (g *cacheRefGetter) getRefCacheDirNoCache(ctx context.Context, key string,
 		locked := false
 		for _, si := range sis {
 			if mRef, err := g.cm.GetMutable(ctx, si.ID()); err == nil {
-				bklog.G(ctx).Debugf("reusing ref for cache dir: %s", mRef.ID())
+				bklog.G(ctx).Debugf("reusing ref for cache dir %q: %s", id, mRef.ID())
 				return mRef, nil
 			} else if errors.Is(err, cache.ErrLocked) {
 				locked = true
+			} else {
+				bklog.G(ctx).WithError(err).Errorf("failed to get reuse ref for cache dir %q: %s", id, si.ID())
 			}
 		}
 		if block && locked {
@@ -438,7 +449,7 @@ func CacheMountsLocker() sync.Locker {
 	return &sharedCacheRefs.mu
 }
 
-func (r *cacheRefs) get(key string, fn func() (cache.MutableRef, error)) (cache.MutableRef, error) {
+func (r *cacheRefs) get(ctx context.Context, key string, fn func() (cache.MutableRef, error)) (cache.MutableRef, error) {
 	r.mu.Lock()
 	defer r.mu.Unlock()
 
@@ -448,7 +459,7 @@ func (r *cacheRefs) get(key string, fn func() (cache.MutableRef, error)) (cache.
 
 	share, ok := r.shares[key]
 	if ok {
-		return share.clone(), nil
+		return share.clone(ctx), nil
 	}
 
 	mref, err := fn()
@@ -458,7 +469,7 @@ func (r *cacheRefs) get(key string, fn func() (cache.MutableRef, error)) (cache.
 
 	share = &cacheRefShare{MutableRef: mref, main: r, key: key, refs: map[*cacheRef]struct{}{}}
 	r.shares[key] = share
-	return share.clone(), nil
+	return share.clone(ctx), nil
 }
 
 type cacheRefShare struct {
@@ -469,7 +480,11 @@ type cacheRefShare struct {
 	key  string
 }
 
-func (r *cacheRefShare) clone() cache.MutableRef {
+func (r *cacheRefShare) clone(ctx context.Context) cache.MutableRef {
+	bklog.G(ctx).WithFields(map[string]any{
+		"key":   r.key,
+		"stack": bklog.LazyStackTrace{},
+	}).Trace("cloning cache mount ref share")
 	cacheRef := &cacheRef{cacheRefShare: r}
 	if cacheRefCloneHijack != nil {
 		cacheRefCloneHijack()
@@ -481,6 +496,10 @@ func (r *cacheRefShare) clone() cache.MutableRef {
 }
 
 func (r *cacheRefShare) release(ctx context.Context) error {
+	bklog.G(ctx).WithFields(map[string]any{
+		"key":   r.key,
+		"stack": bklog.LazyStackTrace{},
+	}).Trace("releasing cache mount ref share main")
 	if r.main != nil {
 		delete(r.main.shares, r.key)
 	}
@@ -495,6 +514,10 @@ type cacheRef struct {
 }
 
 func (r *cacheRef) Release(ctx context.Context) error {
+	bklog.G(ctx).WithFields(map[string]any{
+		"key":   r.key,
+		"stack": bklog.LazyStackTrace{},
+	}).Trace("releasing cache mount ref share")
 	if r.main != nil {
 		r.main.mu.Lock()
 		defer r.main.mu.Unlock()

util/bklog/log.go

@@ -2,6 +2,7 @@ package bklog
 
 import (
 	"context"
+	"runtime/debug"
 
 	"github.com/containerd/containerd/log"
 	"github.com/sirupsen/logrus"
@@ -61,3 +62,11 @@ func GetLogger(ctx context.Context) (l *logrus.Entry) {
 
 	return l
 }
+
+// LazyStackTrace lets you include a stack trace as a field's value in a log but only
+// call it when the log level is actually enabled.
+type LazyStackTrace struct{}
+
+func (LazyStackTrace) String() string {
+	return string(debug.Stack())
+}