cache: add a few more fields to ref trace logs.

The trace logs now also include the pointer value of the ref, which
serves as its "ID" amongst all the refs for the underlying record.

They also now include equal{Mutable,Immutable} IDs, which are otherwise
hard to determine with the Usage API.

Finally, LazyStackTrace now has a MarshalText method which returns the
same value as the existing String method. This allows it to work with
custom logrus hooks that rely on marshaling the fields.

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

Author: sipsma

cache/refs.go

@@ -35,6 +35,7 @@ import (
 	digest "github.com/opencontainers/go-digest"
 	ocispecs "github.com/opencontainers/image-spec/specs-go/v1"
 	"github.com/pkg/errors"
+	"github.com/sirupsen/logrus"
 	"golang.org/x/sync/errgroup"
 )
 
@@ -107,12 +108,7 @@ 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")
+	bklog.G(context.TODO()).WithFields(ref.traceLogFields()).Trace("acquired cache ref")
 	return ref
 }
 
@@ -124,12 +120,7 @@ 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")
+	bklog.G(context.TODO()).WithFields(ref.traceLogFields()).Trace("acquired cache ref")
 	return ref
 }
 
@@ -493,6 +484,24 @@ type immutableRef struct {
 	progress progress.Controller
 }
 
+// hold ref lock before calling
+func (sr *immutableRef) traceLogFields() logrus.Fields {
+	m := map[string]any{
+		"id":          sr.ID(),
+		"refID":       fmt.Sprintf("%p", sr),
+		"newRefCount": len(sr.refs),
+		"mutable":     false,
+		"stack":       bklog.LazyStackTrace{},
+	}
+	if sr.equalMutable != nil {
+		m["equalMutableID"] = sr.equalMutable.ID()
+	}
+	if sr.equalImmutable != nil {
+		m["equalImmutableID"] = sr.equalImmutable.ID()
+	}
+	return m
+}
+
 // Order is from parent->child, sr will be at end of slice. Refs should not
 // be released as they are used internally in the underlying cacheRecords.
 func (sr *immutableRef) layerChain() []*immutableRef {
@@ -615,6 +624,24 @@ type mutableRef struct {
 	descHandlers    DescHandlers
 }
 
+// hold ref lock before calling
+func (sr *mutableRef) traceLogFields() logrus.Fields {
+	m := map[string]any{
+		"id":          sr.ID(),
+		"refID":       fmt.Sprintf("%p", sr),
+		"newRefCount": len(sr.refs),
+		"mutable":     true,
+		"stack":       bklog.LazyStackTrace{},
+	}
+	if sr.equalMutable != nil {
+		m["equalMutableID"] = sr.equalMutable.ID()
+	}
+	if sr.equalImmutable != nil {
+		m["equalImmutableID"] = sr.equalImmutable.ID()
+	}
+	return m
+}
+
 func (sr *mutableRef) DescHandler(dgst digest.Digest) *DescHandler {
 	return sr.descHandlers[dgst]
 }
@@ -1320,12 +1347,7 @@ func (sr *immutableRef) updateLastUsedNow() bool {
 
 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{},
-		})
+		l := bklog.G(ctx).WithFields(sr.traceLogFields())
 		if rerr != nil {
 			l = l.WithError(rerr)
 		}
@@ -1514,12 +1536,7 @@ 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{},
-		})
+		l := bklog.G(ctx).WithFields(sr.traceLogFields())
 		if rerr != nil {
 			l = l.WithError(rerr)
 		}

util/bklog/log.go

@@ -70,3 +70,7 @@ type LazyStackTrace struct{}
 func (LazyStackTrace) String() string {
 	return string(debug.Stack())
 }
+
+func (LazyStackTrace) MarshalText() ([]byte, error) {
+	return debug.Stack(), nil
+}