Enhance container image unpack client logs

austinvazquez · austinvazquez · commit 5930a3750c5d · 2023-11-15T21:37:29.000-08:00
Adds debug message per layer unpacking and adds duration field to the existing image unpacking debug message. Signed-off-by: Austin Vazquez <macedonv@amazon.com> (cherry picked from commit 01c4421) Signed-off-by: Austin Vazquez <macedonv@amazon.com>
diff --git a/pkg/unpack/unpacker.go b/pkg/unpack/unpacker.go
@@ -236,6 +236,7 @@ func (u *Unpacker) unpack(
 	ctx := u.ctx
 	ctx, layerSpan := tracing.StartSpan(ctx, tracing.Name(unpackSpanPrefix, "unpack"))
 	defer layerSpan.End()
+	unpackStart := time.Now()
 	p, err := content.ReadBlob(ctx, u.content, config)
 	if err != nil {
 		return err
@@ -412,6 +413,7 @@ func (u *Unpacker) unpack(
 
 	for i, desc := range layers {
 		_, layerSpan := tracing.StartSpan(ctx, tracing.Name(unpackSpanPrefix, "unpackLayer"))
+		unpackLayerStart := time.Now()
 		layerSpan.SetAttributes(
 			tracing.Attribute("layer.media.type", desc.MediaType),
 			tracing.Attribute("layer.media.size", desc.Size),
@@ -423,6 +425,10 @@ func (u *Unpacker) unpack(
 			return err
 		}
 		layerSpan.End()
+		log.G(ctx).WithFields(log.Fields{
+			"layer":    desc.Digest,
+			"duration": time.Since(unpackLayerStart),
+		}).Debug("layer unpacked")
 	}
 
 	chainID := identity.ChainID(chain).String()
@@ -437,8 +443,9 @@ func (u *Unpacker) unpack(
 		return err
 	}
 	log.G(ctx).WithFields(log.Fields{
-		"config":  config.Digest,
-		"chainID": chainID,
+		"config":   config.Digest,
+		"chainID":  chainID,
+		"duration": time.Since(unpackStart),
 	}).Debug("image unpacked")
 
 	return nil
