Fix inconsistent bundle out-of-date detection

When we consider if a previously built bundle is out-of-date and should be rebuilt, we look at the porter.yaml file and also the set of mixins used by the bundle. We were storing those mixins and their installed version in a _map_, which doesn't sort consistently. So when a bundle used more than one mixin, there was always a chance that it would sort differently from the last build and trigger a rebuild.

I have updated how we compare the mixins used by the old/new bundle so that we always sort them in alphabetical order.

I have also added a bunch of debug logging and trace data so that it's easier to troubleshoot a bundle being incorrectly flagged as out-of-date next time. 😅

Signed-off-by: Carolyn Van Slyck <me@carolynvanslyck.com>

pkg/cnab/config-adapter/stamp.go

@@ -8,6 +8,7 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
+	"sort"
 
 	"get.porter.sh/porter/pkg"
 	"get.porter.sh/porter/pkg/cnab"
@@ -69,10 +70,31 @@ func (s Stamp) WriteManifest(cxt *portercontext.Context, path string) error {
 // MixinRecord contains information about a mixin used in a bundle
 // For now it is a placeholder for data that we would like to include in the future.
 type MixinRecord struct {
+	// Name of the mixin used in the bundle. This is used for sorting only, and
+	// should not be written to the Porter's stamp in bundle.json because we are
+	// storing these mixin records in a map, keyed by the mixin name.
+	Name string `json:"-"`
+
 	// Version of the mixin used in the bundle.
 	Version string `json:"version"`
 }
 
+type MixinRecords []MixinRecord
+
+func (m MixinRecords) Len() int {
+	return len(m)
+}
+
+func (m MixinRecords) Less(i, j int) bool {
+	return m[i].Name < m[j].Name
+}
+
+func (m MixinRecords) Swap(i, j int) {
+	tmp := m[i]
+	m[i] = m[j]
+	m[j] = tmp
+}
+
 func (c *ManifestConverter) GenerateStamp(ctx context.Context) (Stamp, error) {
 	log := tracing.LoggerFromContext(ctx)
 
@@ -86,11 +108,9 @@ func (c *ManifestConverter) GenerateStamp(ctx context.Context) (Stamp, error) {
 	stamp.EncodedManifest = base64.StdEncoding.EncodeToString(rawManifest)
 
 	stamp.Mixins = make(map[string]MixinRecord, len(c.Manifest.Mixins))
-	usedMixinsVersion := c.getUsedMixinsVersion()
-	for usedMixinName, usedMixinVersion := range usedMixinsVersion {
-		stamp.Mixins[usedMixinName] = MixinRecord{
-			Version: usedMixinVersion,
-		}
+	usedMixins := c.getUsedMixinRecords()
+	for _, record := range usedMixins {
+		stamp.Mixins[record.Name] = record
 	}
 
 	digest, err := c.DigestManifest()
@@ -122,9 +142,10 @@ func (c *ManifestConverter) DigestManifest() (string, error) {
 	v := pkg.Version
 	data = append(data, v...)
 
-	usedMixinsVersion := c.getUsedMixinsVersion()
-	for usedMixinName, usedMixinVersion := range usedMixinsVersion {
-		data = append(append(data, usedMixinName...), usedMixinVersion...)
+	usedMixins := c.getUsedMixinRecords()
+	sort.Sort(usedMixins) // Ensure that this is sorted so the digest is consistent
+	for _, mixinRecord := range usedMixins {
+		data = append(append(data, mixinRecord.Name...), mixinRecord.Version...)
 	}
 
 	digest := sha256.Sum256(data)
@@ -152,17 +173,21 @@ func LoadStamp(bun cnab.ExtendedBundle) (Stamp, error) {
 	return stamp, nil
 }
 
-// getUsedMixinsVersion compare the mixins defined in the manifest and the ones installed and then retrieve the mixin's version info
-func (c *ManifestConverter) getUsedMixinsVersion() map[string]string {
-	usedMixinsVersion := make(map[string]string)
+// getUsedMixinRecords compare the mixins defined in the manifest and the ones installed and then retrieve the mixin's version info
+func (c *ManifestConverter) getUsedMixinRecords() MixinRecords {
+	usedMixins := make(MixinRecords, 0)
 
 	for _, usedMixin := range c.Manifest.Mixins {
 		for _, installedMixin := range c.InstalledMixins {
 			if usedMixin.Name == installedMixin.Name {
-				usedMixinsVersion[usedMixin.Name] = installedMixin.GetVersionInfo().Version
+				usedMixins = append(usedMixins, MixinRecord{
+					Name:    installedMixin.Name,
+					Version: installedMixin.GetVersionInfo().Version,
+				})
 			}
 		}
 	}
 
-	return usedMixinsVersion
+	sort.Sort(usedMixins)
+	return usedMixins
 }

pkg/cnab/config-adapter/stamp_test.go

@@ -2,6 +2,7 @@ package configadapter
 
 import (
 	"context"
+	"sort"
 	"testing"
 
 	"get.porter.sh/porter/pkg"
@@ -36,7 +37,7 @@ func TestConfig_GenerateStamp(t *testing.T) {
 	stamp, err := a.GenerateStamp(ctx)
 	require.NoError(t, err, "DigestManifest failed")
 	assert.Equal(t, simpleManifestDigest, stamp.ManifestDigest)
-	assert.Equal(t, map[string]MixinRecord{"exec": {Version: "v1.2.3"}}, stamp.Mixins, "Stamp.Mixins was not populated properly")
+	assert.Equal(t, map[string]MixinRecord{"exec": {Name: "exec", Version: "v1.2.3"}}, stamp.Mixins, "Stamp.Mixins was not populated properly")
 	assert.Equal(t, pkg.Version, stamp.Version)
 	assert.Equal(t, pkg.Commit, stamp.Commit)
 
@@ -181,3 +182,17 @@ func TestConfig_GenerateStamp_IncludeVersion(t *testing.T) {
 	assert.Equal(t, "v1.2.3", stamp.Version)
 	assert.Equal(t, "abc123", stamp.Commit)
 }
+
+func TestMixinRecord_Sort(t *testing.T) {
+	records := MixinRecords{
+		{Name: "helm", Version: "0.1.2"},
+		{Name: "testmixin", Version: "1.2.3"},
+		{Name: "exec", Version: "2.1.0"},
+	}
+
+	sort.Sort(records)
+
+	assert.Equal(t, "exec", records[0].Name)
+	assert.Equal(t, "helm", records[1].Name)
+	assert.Equal(t, "testmixin", records[2].Name)
+}

pkg/porter/stamp.go

@@ -2,6 +2,7 @@ package porter
 
 import (
 	"context"
+	"encoding/json"
 	"errors"
 	"fmt"
 	"os"
@@ -70,62 +71,99 @@ func (p *Porter) IsBundleUpToDate(ctx context.Context, opts BundleDefinitionOpti
 	ctx, span := tracing.StartSpan(ctx)
 	defer span.EndSpan()
 
+	span.Debugf("Checking if the bundle is up-to-date...")
+
+	// This is a prefix for any message that explains why the bundle is out-of-date
+	const rebuildMessagePrefix = "Bundle is out-of-date and must be rebuilt"
+
 	if opts.File == "" {
-		return false, span.Error(errors.New("File is required"))
+		span.Debugf("%s because the current bundle was not specified. Please report this as a bug!", rebuildMessagePrefix)
+		return false, span.Errorf("File is required")
 	}
 	m, err := manifest.LoadManifestFrom(ctx, p.Config, opts.File)
 	if err != nil {
-		return false, err
+		err = fmt.Errorf("the current bundle could not be read: %w", err)
+		span.Debugf("%s: %w", rebuildMessagePrefix, err)
+		return false, span.Error(err)
 	}
 
 	if exists, _ := p.FileSystem.Exists(opts.CNABFile); exists {
 		bun, err := cnab.LoadBundle(p.Context, opts.CNABFile)
 		if err != nil {
-			return false, span.Error(fmt.Errorf("could not marshal data from %s: %w", opts.CNABFile, err))
+			err = fmt.Errorf("the previously built bundle at %s could not be read: %w", opts.CNABFile, err)
+			span.Debugf("%s: %w", rebuildMessagePrefix, err)
+			return false, span.Error(err)
 		}
 
 		// Check whether invocation images exist in host registry.
 		for _, invocationImage := range bun.InvocationImages {
 			// if the invocationImage is built before using a random string tag,
 			// we should rebuild it with the new format
 			if strings.HasSuffix(invocationImage.Image, "-installer") {
+				span.Debugf("%s because it uses the old -installer suffixed image name (%s)", invocationImage.Image)
 				return false, nil
 			}
 
 			imgRef, err := cnab.ParseOCIReference(invocationImage.Image)
 			if err != nil {
-				return false, span.Errorf("error parsing %s as an OCI image reference: %w", invocationImage.Image, err)
+				err = fmt.Errorf("error parsing %s as an OCI image reference: %w", invocationImage.Image, err)
+				span.Debugf("%s: %w", rebuildMessagePrefix, err)
+				return false, span.Error(err)
 			}
 
 			_, err = p.Registry.GetCachedImage(ctx, imgRef)
 			if err != nil {
 				if errors.Is(err, cnabtooci.ErrNotFound{}) {
-					span.Debugf("Invocation image %s doesn't exist in the local image cache, will need to build first", invocationImage.Image)
+					span.Debugf("%s because the invocation image %s doesn't exist in the local image cache", rebuildMessagePrefix, invocationImage.Image)
 					return false, nil
 				}
-				return false, err
-
+				err = fmt.Errorf("an error occurred checking the Docker cache for the invocation image: %w", err)
+				span.Debugf("%s: %w", rebuildMessagePrefix, err)
+				return false, span.Error(err)
 			}
 		}
 
 		oldStamp, err := configadapter.LoadStamp(bun)
 		if err != nil {
-			return false, span.Error(fmt.Errorf("could not load stamp from %s: %w", opts.CNABFile, err))
+			err = fmt.Errorf("could not load stamp from %s: %w", opts.CNABFile, err)
+			span.Debugf("%s: %w", rebuildMessagePrefix)
+			return false, span.Error(err)
 		}
 
 		mixins, err := p.getUsedMixins(ctx, m)
 		if err != nil {
-			return false, fmt.Errorf("error while listing used mixins: %w", err)
+			err = fmt.Errorf("an error occurred while listing used mixins: %w", err)
+			span.Debugf("%s: %w", rebuildMessagePrefix, err)
+			return false, span.Error(err)
 		}
 
 		converter := configadapter.NewManifestConverter(p.Config, m, nil, mixins)
 		newDigest, err := converter.DigestManifest()
 		if err != nil {
-			span.Debugf("could not determine if the bundle is up-to-date so will rebuild just in case: %w", err)
+			err = fmt.Errorf("the current manifest digest cannot be calculated: %w", err)
+			span.Debugf("%s: %w", rebuildMessagePrefix, err)
+			return false, span.Error(err)
+		}
+
+		manifestChanged := oldStamp.ManifestDigest != newDigest
+		if manifestChanged {
+			span.Debugf("%s because the cached bundle is stale", rebuildMessagePrefix)
+			if span.IsTracingEnabled() {
+				previousStampB, _ := json.Marshal(oldStamp)
+				currentStamp, _ := converter.GenerateStamp(ctx)
+				currentStampB, _ := json.Marshal(currentStamp)
+				span.SetAttributes(
+					attribute.String("previous-stamp", string(previousStampB)),
+					attribute.String("current-stamp", string(currentStampB)),
+				)
+			}
 			return false, nil
 		}
-		return oldStamp.ManifestDigest == newDigest, nil
+
+		span.Debugf("Bundle is up-to-date!")
+		return true, nil
 	}
 
+	span.Debugf("%s because a previously built bundle was not found", rebuildMessagePrefix)
 	return false, nil
 }

tests/integration/build_test.go

@@ -48,6 +48,17 @@ func TestRebuild(t *testing.T) {
 	test.Chdir(test.TestDir)
 	test.RequirePorter("create")
 
+	// Edit the bundle to use more than one mixin
+	// This helps us test that when we calculate the manifestDigest that it consistently sorts used mixins
+	test.EditYaml("porter.yaml", func(yq *yaml.Editor) error {
+		n, err := yq.GetNode("mixins")
+		require.NoError(t, err, "could not get mixins node for porter.yaml")
+		testMixin := *n.Content[0]
+		testMixin.Value = "testmixin"
+		n.Content = append(n.Content, &testMixin)
+		return nil
+	})
+
 	// Use a unique name with it so that if other tests install a newly created hello
 	// world bundle, they don't conflict
 	installationName := t.Name()
@@ -74,6 +85,14 @@ func TestRebuild(t *testing.T) {
 	_, output = test.RequirePorter("explain")
 	tests.RequireOutputContains(t, output, "Building bundle ===>", "expected a build before explain")
 
+	// Explain the bundle a bunch more times, it should not rebuild again.
+	// This is a regression test for a bug where the manifest would be considered out-of-date when nothing had changed
+	// caused by us using a go map when comparing the mixins used in the bundle, which has inconsistent sort order...
+	for i := 0; i < 10; i++ {
+		_, output = test.RequirePorter("explain")
+		tests.RequireOutputContains(t, output, "Bundle is up-to-date!", "expected the previous build to be reused")
+	}
+
 	bumpBundle()
 
 	// Explain the bundle, with --autobuild-disabled. It should work since the bundle has been built

tests/smoke/airgap_test.go

@@ -93,7 +93,12 @@ func TestAirgappedEnvironment(t *testing.T) {
 			}
 
 			// Publish a test bundle that references the image from the temp registry, and push to another insecure registry
-			test.RequirePorter("publish", "--registry", reg2.String(), insecureFlag)
+			_, output = test.RequirePorter("publish", "--registry", reg2.String(), insecureFlag, "--verbosity=debug")
+
+			// Validate that we aren't getting a rebuild since we are building immediately before publish
+			// I am using --verbosity=debug above so that we can see the reason why a rebuild was triggered
+			// which helps with troubleshooting if/when a regression occurs.
+			require.NotContains(t, output, "Building bundle", "expected a rebuild to not happen because we built before publishing")
 
 			// Stop the original registry, this ensures that we are relying 100% on the copy of the bundle in the second registry
 			reg1.Close()