kubernetesapply: improve user-facing logging (#5211)

* Result of apply now consistently logged for both YAML + Cmd deploys
  * This slightly changes things for YAML, which used to show the
    objects it was _going_ to apply
* Image injection message only shown when relevant and moved to debug
  * More detailed, including the entity and the transformation that
    was applied
* Consistent/improved indentation across YAML + Cmd deploys

Fixes #5192.

internal/controllers/core/kubernetesapply/reconciler.go

@@ -343,18 +343,28 @@ func (r *Reconciler) forceApplyHelper(
 	}
 
 	var deployed []k8s.K8sEntity
+	deployCtx := r.indentLogger(ctx)
 	if spec.YAML != "" {
-		deployed, err = r.runYAMLDeploy(ctx, spec, imageMaps)
+		deployed, err = r.runYAMLDeploy(deployCtx, spec, imageMaps)
 		if err != nil {
 			return errorStatus(err), nil
 		}
 	} else {
-		deployed, err = r.runCmdDeploy(ctx, spec)
+		deployed, err = r.runCmdDeploy(deployCtx, spec)
 		if err != nil {
 			return errorStatus(err), nil
 		}
 	}
 
+	// Use a min component count of 2 for computing names,
+	// so that the resource type appears
+	l := logger.Get(r.indentLogger(ctx))
+	l.Infof("Objects applied to cluster:")
+	displayNames := k8s.UniqueNames(deployed, 2)
+	for _, displayName := range displayNames {
+		l.Infof("  → %s", displayName)
+	}
+
 	status.LastApplyTime = apis.NowMicro()
 	status.AppliedInputHash = inputHash
 	for _, d := range deployed {
@@ -377,17 +387,7 @@ func (r *Reconciler) runYAMLDeploy(ctx context.Context, spec v1alpha1.Kubernetes
 		return newK8sEntities, err
 	}
 
-	ctx = r.indentLogger(ctx)
-	l := logger.Get(ctx)
-
-	l.Infof("Applying via kubectl:")
-
-	// Use a min component count of 2 for computing names,
-	// so that the resource type appears
-	displayNames := k8s.UniqueNames(newK8sEntities, 2)
-	for _, displayName := range displayNames {
-		l.Infof("→ %s", displayName)
-	}
+	logger.Get(ctx).Infof("Applying YAML to cluster")
 
 	timeout := spec.Timeout.Duration
 	if timeout == 0 {
@@ -449,6 +449,11 @@ func (r *Reconciler) indentLogger(ctx context.Context) context.Context {
 	return logger.WithLogger(ctx, newL)
 }
 
+type injectResult struct {
+	meta     k8s.EntityMeta
+	imageMap *v1alpha1.ImageMap
+}
+
 func (r *Reconciler) createEntitiesToDeploy(ctx context.Context,
 	imageMaps map[types.NamespacedName]*v1alpha1.ImageMap,
 	spec v1alpha1.KubernetesApplySpec) ([]k8s.K8sEntity, error) {
@@ -501,6 +506,7 @@ func (r *Reconciler) createEntitiesToDeploy(ctx context.Context,
 			policy = v1.PullNever
 		}
 
+		var injectResults []injectResult
 		for _, imageMapName := range imageMapNames {
 			imageMap := imageMaps[types.NamespacedName{Name: imageMapName}]
 			imageMapSpec := imageMap.Spec
@@ -526,6 +532,10 @@ func (r *Reconciler) createEntitiesToDeploy(ctx context.Context,
 			}
 			if replaced {
 				injectedImageMaps[imageMapName] = true
+				injectResults = append(injectResults, injectResult{
+					meta:     e,
+					imageMap: imageMap,
+				})
 
 				if imageMapSpec.OverrideCommand != nil || imageMapSpec.OverrideArgs != nil {
 					e, err = k8s.InjectCommandAndArgs(e, ref, imageMapSpec.OverrideCommand, imageMapSpec.OverrideArgs)
@@ -536,6 +546,28 @@ func (r *Reconciler) createEntitiesToDeploy(ctx context.Context,
 			}
 		}
 
+		l := logger.Get(ctx)
+		if l.Level().ShouldDisplay(logger.DebugLvl) {
+			if len(injectResults) != 0 {
+				l.Debugf("Injecting images into Kubernetes YAML:")
+				meta := make([]k8s.EntityMeta, len(injectResults))
+				for i := range injectResults {
+					meta[i] = injectResults[i].meta
+				}
+				names := k8s.UniqueNamesMeta(meta, 2)
+				for i := range injectResults {
+					l.Debugf(
+						"  → %s: %s ⇒ %s",
+						names[i],
+						injectResults[i].imageMap.Spec.Selector,
+						injectResults[i].imageMap.Status.Image,
+					)
+				}
+			} else {
+				l.Debugf("No images injected into Kubernetes YAML")
+			}
+		}
+
 		// This needs to be after all the other injections, to ensure the hash includes the Tilt-generated
 		// image tag, etc
 		e, err := k8s.InjectPodTemplateSpecHashes(e)

internal/controllers/core/kubernetesapply/reconciler_test.go

@@ -5,6 +5,7 @@ import (
 	"fmt"
 	"reflect"
 	"strconv"
+	"strings"
 	"testing"
 	"time"
 
@@ -102,6 +103,10 @@ func TestBasicApplyYAML(t *testing.T) {
 	assert.Contains(f.T(), ka.Status.ResultYAML, "name: sancho")
 	assert.Contains(f.T(), ka.Status.ResultYAML, "uid:")
 
+	assert.Contains(t, f.storeLogs(),
+		"Objects applied to cluster:\n       → sancho:deployment\n",
+		"Log output did not include applied objects")
+
 	// Make sure that re-reconciling doesn't re-apply the YAML"
 	f.kClient.Yaml = ""
 	f.MustReconcile(types.NamespacedName{Name: "a"})
@@ -128,6 +133,10 @@ func TestBasicApplyCmd(t *testing.T) {
 	assert.NotZero(t, ka.Status.LastApplyTime)
 	assert.Equal(t, yamlOut, ka.Status.ResultYAML)
 
+	assert.Contains(t, f.storeLogs(),
+		"Objects applied to cluster:\n       → sancho:deployment\n",
+		"Log output did not include applied objects")
+
 	// verify that a re-reconcile does NOT re-invoke the command
 	f.execer.RegisterCommandError("custom-apply-cmd", errors.New("this should not get invoked"))
 	f.MustReconcile(types.NamespacedName{Name: "a"})
@@ -179,7 +188,7 @@ func TestBasicApplyCmd_NonZeroExitCode(t *testing.T) {
 
 	if assert.Equal(t, "apply command exited with status 77\nstdout:\nwhoops\n\n", ka.Status.Error) {
 		logAction := f.st.WaitForAction(t, reflect.TypeOf(store.LogAction{}))
-		assert.Equal(t, `manifest: foo, spanID: KubernetesApply-a, msg: "oh no\n"`, logAction.(store.LogAction).String())
+		assert.Equal(t, `manifest: foo, spanID: KubernetesApply-a, msg: "     oh no\n"`, logAction.(store.LogAction).String())
 	}
 }
 
@@ -572,3 +581,14 @@ func (f *fixture) createApplyCmd(name string, yaml string) (v1alpha1.KubernetesA
 		Args: []string{name},
 	}, yamlOut
 }
+
+func (f *fixture) storeLogs() string {
+	actions := f.st.Actions()
+	var sb strings.Builder
+	for i := range actions {
+		if logAction, ok := actions[i].(store.LogAction); ok {
+			sb.Write(logAction.Message())
+		}
+	}
+	return sb.String()
+}

internal/engine/buildcontrol/image_build_and_deployer.go

@@ -310,8 +310,6 @@ func (ibd *ImageBuildAndDeployer) deploy(
 	ps.StartPipelineStep(ctx, "Deploying")
 	defer ps.EndPipelineStep(ctx)
 
-	ps.StartBuildStep(ctx, "Injecting images into Kubernetes YAML")
-
 	kTargetNN := types.NamespacedName{Name: kTargetID.Name.String()}
 	// Note: `KubernetesApply` object may not exist yet when this `ForceApply` is called
 	// and may cause a race-condition-related "Not found" error here.