Fix inconsistent rebuild

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/lifecycle.go

@@ -211,7 +211,11 @@ func (p *Porter) resolveBundleReference(ctx context.Context, opts *BundleReferen
 			return cnab.BundleReference{}, err
 		}
 	} else if opts.File != "" { // load the local bundle source
-		localBundle, err := p.ensureLocalBundleIsUpToDate(ctx, opts.BundleDefinitionOptions)
+		buildOpts := BuildOptions{
+			BundleDefinitionOptions: opts.BundleDefinitionOptions,
+			InsecureRegistry:        opts.InsecureRegistry,
+		}
+		localBundle, err := p.ensureLocalBundleIsUpToDate(ctx, buildOpts)
 		if err != nil {
 			return cnab.BundleReference{}, err
 		}

pkg/porter/publish.go

@@ -99,7 +99,11 @@ func (p *Porter) publishFromFile(ctx context.Context, opts PublishOptions) error
 	ctx, log := tracing.StartSpan(ctx)
 	defer log.EndSpan()
 
-	_, err := p.ensureLocalBundleIsUpToDate(ctx, opts.BundleDefinitionOptions)
+	buildOpts := BuildOptions{
+		BundleDefinitionOptions: opts.BundleDefinitionOptions,
+		InsecureRegistry:        opts.InsecureRegistry,
+	}
+	_, err := p.ensureLocalBundleIsUpToDate(ctx, buildOpts)
 	if err != nil {
 		return err
 	}

pkg/porter/stamp.go

@@ -2,6 +2,7 @@ package porter
 
 import (
 	"context"
+	"encoding/json"
 	"errors"
 	"fmt"
 	"os"
@@ -18,7 +19,7 @@ import (
 
 // ensureLocalBundleIsUpToDate ensures that the bundle is up-to-date with the porter manifest,
 // if it is out-of-date, performs a build of the bundle.
-func (p *Porter) ensureLocalBundleIsUpToDate(ctx context.Context, opts BundleDefinitionOptions) (cnab.BundleReference, error) {
+func (p *Porter) ensureLocalBundleIsUpToDate(ctx context.Context, opts BuildOptions) (cnab.BundleReference, error) {
 	ctx, log := tracing.StartSpan(ctx,
 		attribute.Bool("autobuild-disabled", opts.AutoBuildDisabled))
 	defer log.EndSpan()
@@ -27,7 +28,7 @@ func (p *Porter) ensureLocalBundleIsUpToDate(ctx context.Context, opts BundleDef
 		return cnab.BundleReference{}, nil
 	}
 
-	upToDate, err := p.IsBundleUpToDate(ctx, opts)
+	upToDate, err := p.IsBundleUpToDate(ctx, opts.BundleDefinitionOptions)
 	if err != nil {
 		log.Warnf("WARNING: %w", err)
 	}
@@ -36,12 +37,15 @@ func (p *Porter) ensureLocalBundleIsUpToDate(ctx context.Context, opts BundleDef
 		if opts.AutoBuildDisabled {
 			log.Warn("WARNING: The bundle is out-of-date. Skipping autobuild because --autobuild-disabled was specified")
 		} else {
+			log.Info("Changes have been detected and the previously built bundle is out-of-date, rebuilding the bundle before proceeding...")
 			log.Info("Building bundle ===>")
 			// opts.File is non-empty, which overrides opts.CNABFile if set
 			// (which may be if a cached bundle is fetched e.g. when running an action)
 			opts.CNABFile = ""
-			buildOpts := BuildOptions{BundleDefinitionOptions: opts}
-			buildOpts.Validate(p)
+			buildOpts := opts
+			if err = buildOpts.Validate(p); err != nil {
+				return cnab.BundleReference{}, log.Errorf("Validation of build options when autobuilding the bundle failed: %w", err)
+			}
 			err := p.Build(ctx, buildOpts)
 			if err != nil {
 				return cnab.BundleReference{}, err
@@ -67,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

@@ -38,6 +38,7 @@ func TestAirgappedEnvironment(t *testing.T) {
 		{name: "untrusted tls, no alias", useTLS: false, useAlias: true, insecure: true},
 	}
 	for _, tc := range testcases {
+		tc := tc
 		t.Run(tc.name, func(t *testing.T) {
 			insecureFlag := fmt.Sprintf("--insecure-registry=%t", tc.insecure)
 
@@ -92,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()