From 01c442147fd084cc0e7e8b45074b940f5c6bbdba Mon Sep 17 00:00:00 2001
From: Austin Vazquez <macedonv@amazon.com>
Date: Wed, 15 Nov 2023 16:10:50 +0000
Subject: [PATCH] Enhance container image unpack client logs

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>
---
 pkg/unpack/unpacker.go | 11 +++++++++--
 1 file changed, 9 insertions(+), 2 deletions(-)

diff --git a/pkg/unpack/unpacker.go b/pkg/unpack/unpacker.go
index f13724252..417ab6e30 100644
--- a/pkg/unpack/unpacker.go
+++ b/pkg/unpack/unpacker.go
@@ -235,6 +235,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
@@ -411,6 +412,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),
@@ -422,6 +424,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()
@@ -436,8 +442,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