More debug output

Makefile

@@ -20,6 +20,9 @@ endif
 
 TEST_CRDS:=controllers/testdata/crds
 
+# Log level for `make run`
+LOG_LEVEL?=info
+
 all: manager
 
 # Running the tests requires the source.toolkit.fluxcd.io CRDs
@@ -49,7 +52,7 @@ manager: generate fmt vet
 
 # Run against the configured Kubernetes cluster in ~/.kube/config
 run: generate fmt vet manifests
-	go run ./main.go
+	go run ./main.go --log-level=${LOG_LEVEL} --log-encoding=console
 
 # Install CRDs into a cluster
 install: manifests

controllers/git_test.go

@@ -11,6 +11,7 @@ import (
 	"github.com/go-git/go-git/v5"
 	"github.com/go-git/go-git/v5/plumbing/object"
 	"github.com/go-git/go-git/v5/storage/memory"
+	"github.com/go-logr/logr"
 )
 
 func populateRepoFromFixture(repo *git.Repository, fixture string) error {
@@ -100,7 +101,7 @@ func TestIgnoreBrokenSymlink(t *testing.T) {
 		t.Fatal(err)
 	}
 
-	_, err = commitChangedManifests(repo, tmp, nil, nil, "unused")
+	_, err = commitChangedManifests(logr.Discard(), repo, tmp, nil, nil, "unused")
 	if err != errNoChanges {
 		t.Fatalf("expected no changes but got: %v", err)
 	}

controllers/imageupdateautomation_controller.go

@@ -65,8 +65,16 @@ import (
 	"github.com/fluxcd/image-automation-controller/pkg/update"
 )
 
-// log level for debug info
+// log level for debug output
 const debug = 1
+
+// log level for trace output; the logging system
+// (fluxcd/pkg/runtime/logging) doesn't presently account for levels
+// more verbose than debug, so lump tracing into
+// --log-level=debug. However, it's useful as self-documentation to
+// keep tracing distinct.
+const trace = 1
+
 const originRemote = "origin"
 
 const defaultMessageTemplate = `Update from image update automation`
@@ -97,6 +105,8 @@ type ImageUpdateAutomationReconciler struct {
 
 func (r *ImageUpdateAutomationReconciler) Reconcile(ctx context.Context, req ctrl.Request) (ctrl.Result, error) {
 	log := logr.FromContext(ctx)
+	debuglog := log.V(debug)
+	tracelog := log.V(trace)
 	now := time.Now()
 	var templateValues TemplateData
 
@@ -164,6 +174,8 @@ func (r *ImageUpdateAutomationReconciler) Reconcile(ctx context.Context, req ctr
 		Name:      auto.Spec.SourceRef.Name,
 		Namespace: auto.GetNamespace(),
 	}
+	debuglog.Info("fetching git repository", "gitrepository", originName)
+
 	if err := r.Get(ctx, originName, &origin); err != nil {
 		if client.IgnoreNotFound(err) == nil {
 			imagev1.SetImageUpdateAutomationReadiness(&auto, metav1.ConditionFalse, imagev1.GitNotAvailableReason, "referenced git repository is missing")
@@ -176,19 +188,20 @@ func (r *ImageUpdateAutomationReconciler) Reconcile(ctx context.Context, req ctr
 		return ctrl.Result{}, err
 	}
 
-	log.V(debug).Info("found git repository", "gitrepository", originName)
-
 	// validate the git spec and default any values needed later, before proceeding
 	var ref *sourcev1.GitRepositoryRef
 	if gitSpec.Checkout != nil {
 		ref = &gitSpec.Checkout.Reference
+		tracelog.Info("using git repository ref from .spec.git.checkout", "ref", ref)
 	} else if r := origin.Spec.Reference; r != nil {
 		ref = r
+		tracelog.Info("using git repository ref from GitRepository spec", "ref", ref)
 	} // else remain as `nil`, which is an acceptable value for cloneInto, later.
 
 	var pushBranch string
 	if gitSpec.Push != nil {
 		pushBranch = gitSpec.Push.Branch
+		tracelog.Info("using push branch from .spec.push.branch", "branch", pushBranch)
 	} else {
 		// Here's where it gets constrained. If there's no push branch
 		// given, then the checkout ref must include a branch, and
@@ -197,6 +210,7 @@ func (r *ImageUpdateAutomationReconciler) Reconcile(ctx context.Context, req ctr
 			failWithError(fmt.Errorf("Push branch not given explicitly, and cannot be inferred from .spec.git.checkout.ref or GitRepository .spec.ref"))
 		}
 		pushBranch = ref.Branch
+		tracelog.Info("using push branch from $ref.branch", "branch", pushBranch)
 	}
 
 	tmp, err := ioutil.TempDir("", fmt.Sprintf("%s-%s", originName.Namespace, originName.Name))
@@ -207,6 +221,8 @@ func (r *ImageUpdateAutomationReconciler) Reconcile(ctx context.Context, req ctr
 
 	// FIXME use context with deadline for at least the following ops
 
+	debuglog.Info("attempting to clone git repository", "gitrepository", originName, "ref", ref, "working", tmp)
+
 	access, err := r.getRepoAccess(ctx, &origin)
 	if err != nil {
 		return failWithError(err)
@@ -229,10 +245,9 @@ func (r *ImageUpdateAutomationReconciler) Reconcile(ctx context.Context, req ctr
 		}
 	}
 
-	log.V(debug).Info("cloned git repository", "gitrepository", originName, "ref", ref, "working", tmp)
-
 	manifestsPath := tmp
 	if auto.Spec.Update.Path != "" {
+		tracelog.Info("adjusting update path according to .spec.update.path", "base", tmp, "spec-path", auto.Spec.Update.Path)
 		if p, err := securejoin.SecureJoin(tmp, auto.Spec.Update.Path); err != nil {
 			return failWithError(err)
 		} else {
@@ -250,7 +265,14 @@ func (r *ImageUpdateAutomationReconciler) Reconcile(ctx context.Context, req ctr
 			return failWithError(err)
 		}
 
-		if result, err := updateAccordingToSetters(ctx, manifestsPath, policies.Items); err != nil {
+		debuglog.Info("updating with setters according to image policies", "count", len(policies.Items), "manifests-path", manifestsPath)
+		if tracelog.Enabled() {
+			for _, item := range policies.Items {
+				tracelog.Info("found policy", "namespace", item.Namespace, "name", item.Name, "latest-image", item.Status.LatestImage)
+			}
+		}
+
+		if result, err := updateAccordingToSetters(ctx, tracelog, manifestsPath, policies.Items); err != nil {
 			return failWithError(err)
 		} else {
 			templateValues.Updated = result
@@ -263,7 +285,7 @@ func (r *ImageUpdateAutomationReconciler) Reconcile(ctx context.Context, req ctr
 		return ctrl.Result{}, r.patchStatus(ctx, req, auto.Status)
 	}
 
-	log.V(debug).Info("ran updates to working dir", "working", tmp)
+	debuglog.Info("ran updates to working dir", "working", tmp)
 
 	var statusMessage string
 
@@ -294,10 +316,11 @@ func (r *ImageUpdateAutomationReconciler) Reconcile(ctx context.Context, req ctr
 		Email: gitSpec.Commit.Author.Email,
 		When:  time.Now(),
 	}
-	if rev, err := commitChangedManifests(repo, tmp, signingEntity, author, messageBuf.String()); err != nil {
+
+	if rev, err := commitChangedManifests(tracelog, repo, tmp, signingEntity, author, messageBuf.String()); err != nil {
 		if err == errNoChanges {
 			r.event(ctx, auto, events.EventSeverityInfo, "no updates made")
-			log.V(debug).Info("no changes made in working directory; no commit")
+			debuglog.Info("no changes made in working directory; no commit")
 			statusMessage = "no updates made"
 			if lastCommit, lastTime := auto.Status.LastPushCommit, auto.Status.LastPushTime; lastCommit != "" {
 				statusMessage = fmt.Sprintf("%s; last commit %s at %s", statusMessage, lastCommit[:7], lastTime.Format(time.RFC3339))
@@ -520,11 +543,10 @@ func switchBranch(repo *gogit.Repository, pushBranch string) error {
 
 var errNoChanges error = errors.New("no changes made to working directory")
 
-func commitChangedManifests(repo *gogit.Repository, absRepoPath string, ent *openpgp.Entity, author *object.Signature, message string) (string, error) {
+func commitChangedManifests(tracelog logr.Logger, repo *gogit.Repository, absRepoPath string, ent *openpgp.Entity, author *object.Signature, message string) (string, error) {
 	working, err := repo.Worktree()
 	if err != nil {
 		return "", err
-
 	}
 	status, err := working.Status()
 	if err != nil {
@@ -547,9 +569,11 @@ func commitChangedManifests(repo *gogit.Repository, absRepoPath string, ent *ope
 			// of the bug mentioned above, but not of interest in any
 			// case.
 			if _, err := os.Stat(abspath); os.IsNotExist(err) {
+				tracelog.Info("apparently broken symlink found; ignoring", "path", abspath)
 				continue
 			}
 		}
+		tracelog.Info("adding file", "file", file)
 		working.Add(file)
 		changed = true
 	}
@@ -724,8 +748,8 @@ func (r *ImageUpdateAutomationReconciler) recordReadinessMetric(ctx context.Cont
 
 // updateAccordingToSetters updates files under the root by treating
 // the given image policies as kyaml setters.
-func updateAccordingToSetters(ctx context.Context, path string, policies []imagev1_reflect.ImagePolicy) (update.Result, error) {
-	return update.UpdateWithSetters(path, path, policies)
+func updateAccordingToSetters(ctx context.Context, tracelog logr.Logger, path string, policies []imagev1_reflect.ImagePolicy) (update.Result, error) {
+	return update.UpdateWithSetters(tracelog, path, path, policies)
 }
 
 func (r *ImageUpdateAutomationReconciler) recordSuspension(ctx context.Context, auto imagev1.ImageUpdateAutomation) {

pkg/update/filereader.go

@@ -23,6 +23,7 @@ import (
 	"os"
 	"path/filepath"
 
+	"github.com/go-logr/logr"
 	"sigs.k8s.io/kustomize/kyaml/kio"
 	"sigs.k8s.io/kustomize/kyaml/kio/kioutil"
 	"sigs.k8s.io/kustomize/kyaml/yaml"
@@ -38,6 +39,8 @@ type ScreeningLocalReader struct {
 	Token string
 	Path  string
 
+	Trace logr.Logger
+
 	// This records the relative path of each file that passed
 	// screening (i.e., contained the token), but couldn't be parsed.
 	ProblemFiles []string
@@ -51,6 +54,13 @@ type ScreeningLocalReader struct {
 // [LocalPackageReader.Read](https://godoc.org/sigs.k8s.io/kustomize/kyaml/kio#LocalPackageReader.Read),
 // adapting lightly (mainly to leave features out).
 func (r *ScreeningLocalReader) Read() ([]*yaml.RNode, error) {
+	tracelog := r.Trace
+	if tracelog == nil {
+		tracelog = logr.Discard()
+	}
+
+	tracelog.Info("scanning files", "path", r.Path, "token", r.Token)
+
 	if r.Path == "" {
 		return nil, fmt.Errorf("must supply path to scan for files")
 	}
@@ -108,6 +118,7 @@ func (r *ScreeningLocalReader) Read() ([]*yaml.RNode, error) {
 			kioutil.PathAnnotation: path,
 		}
 
+		tracelog.Info("reading file", "path", path)
 		rdr := &kio.ByteReader{
 			Reader:         bytes.NewBuffer(filebytes),
 			SetAnnotations: annotations,
@@ -119,6 +130,7 @@ func (r *ScreeningLocalReader) Read() ([]*yaml.RNode, error) {
 		// doesn't need to be the end of the matter; we can record
 		// this file as problematic, and continue.
 		if err != nil {
+			tracelog.Info("problem file", "path", path)
 			r.ProblemFiles = append(r.ProblemFiles, path)
 			return nil
 		}

pkg/update/filter.go

@@ -17,6 +17,7 @@ limitations under the License.
 package update
 
 import (
+	"github.com/go-logr/logr"
 	"k8s.io/kube-openapi/pkg/validation/spec"
 	"sigs.k8s.io/kustomize/kyaml/fieldmeta"
 	"sigs.k8s.io/kustomize/kyaml/openapi"
@@ -48,6 +49,14 @@ import (
 type SetAllCallback struct {
 	SettersSchema *spec.Schema
 	Callback      func(setter, oldValue, newValue string)
+	Trace         logr.Logger
+}
+
+func (s *SetAllCallback) TraceOrDiscard() logr.Logger {
+	if s.Trace == nil {
+		return logr.Discard()
+	}
+	return s.Trace
 }
 
 func (s *SetAllCallback) Filter(object *yaml.RNode) (*yaml.RNode, error) {
@@ -113,6 +122,7 @@ func (s *SetAllCallback) set(field *yaml.RNode, ext *setters2.CliExtension, sch
 	// this has a full setter, set its value
 	old := field.YNode().Value
 	field.YNode().Value = ext.Setter.Value
+	s.TraceOrDiscard().Info("applying setter", "setter", ext.Setter.Name, "old", old, "new", ext.Setter.Value)
 	s.Callback(ext.Setter.Name, old, ext.Setter.Value)
 
 	// format the node so it is quoted if it is a string. If there is
@@ -137,6 +147,7 @@ func (s *SetAllCallback) visitScalar(object *yaml.RNode, p string, fieldSchema *
 		return nil
 	}
 
+	s.TraceOrDiscard().Info("found schema extension", "path", p)
 	// perform a direct set of the field if it matches
 	_, err = s.set(object, ext, fieldSchema.Schema)
 	return err

pkg/update/setters.go

@@ -19,6 +19,7 @@ package update
 import (
 	"fmt"
 
+	"github.com/go-logr/logr"
 	"github.com/google/go-containerregistry/pkg/name"
 	"k8s.io/apimachinery/pkg/types"
 	"k8s.io/kube-openapi/pkg/validation/spec"
@@ -51,7 +52,7 @@ func init() {
 // UpdateWithSetters takes all YAML files from `inpath`, updates any
 // that contain an "in scope" image policy marker, and writes files it
 // updated (and only those files) back to `outpath`.
-func UpdateWithSetters(inpath, outpath string, policies []imagev1alpha1_reflect.ImagePolicy) (Result, error) {
+func UpdateWithSetters(tracelog logr.Logger, inpath, outpath string, policies []imagev1alpha1_reflect.ImagePolicy) (Result, error) {
 	// the OpenAPI schema is a package variable in kyaml/openapi. In
 	// lieu of being able to isolate invocations (per
 	// https://github.com/kubernetes-sigs/kustomize/issues/3058), I
@@ -161,28 +162,29 @@ func UpdateWithSetters(inpath, outpath string, policies []imagev1alpha1_reflect.
 		name := image[:len(image)-len(tag)-1]
 
 		imageSetter := fmt.Sprintf("%s:%s", policy.GetNamespace(), policy.GetName())
+		tracelog.Info("adding setter", "name", imageSetter)
 		defs[fieldmeta.SetterDefinitionPrefix+imageSetter] = setterSchema(imageSetter, policy.Status.LatestImage)
 		imageRefs[imageSetter] = ref
 
 		tagSetter := imageSetter + ":tag"
+		tracelog.Info("adding setter", "name", tagSetter)
 		defs[fieldmeta.SetterDefinitionPrefix+tagSetter] = setterSchema(tagSetter, tag)
 		imageRefs[tagSetter] = ref
 
 		// Context().Name() gives the image repository _as supplied_
 		nameSetter := imageSetter + ":name"
+		tracelog.Info("adding setter", "name", nameSetter)
 		defs[fieldmeta.SetterDefinitionPrefix+nameSetter] = setterSchema(nameSetter, name)
 		imageRefs[nameSetter] = ref
 	}
 
 	settersSchema.Definitions = defs
-	set := &SetAllCallback{
-		SettersSchema: &settersSchema,
-	}
 
 	// get ready with the reader and writer
 	reader := &ScreeningLocalReader{
 		Path:  inpath,
 		Token: fmt.Sprintf("%q", SetterShortHand),
+		Trace: tracelog,
 	}
 	writer := &kio.LocalPackageWriter{
 		PackagePath: outpath,
@@ -192,7 +194,7 @@ func UpdateWithSetters(inpath, outpath string, policies []imagev1alpha1_reflect.
 		Inputs:  []kio.Reader{reader},
 		Outputs: []kio.Writer{writer},
 		Filters: []kio.Filter{
-			setAll(set, setAllCallback),
+			setAll(&settersSchema, tracelog, setAllCallback),
 		},
 	}
 
@@ -210,7 +212,11 @@ func UpdateWithSetters(inpath, outpath string, policies []imagev1alpha1_reflect.
 // files with changed nodes. This is based on
 // [`SetAll`](https://github.com/kubernetes-sigs/kustomize/blob/kyaml/v0.10.16/kyaml/setters2/set.go#L503
 // from kyaml/kio.
-func setAll(filter *SetAllCallback, callback func(file, setterName string, node *yaml.RNode)) kio.Filter {
+func setAll(schema *spec.Schema, tracelog logr.Logger, callback func(file, setterName string, node *yaml.RNode)) kio.Filter {
+	filter := &SetAllCallback{
+		SettersSchema: schema,
+		Trace:         tracelog,
+	}
 	return kio.FilterFunc(
 		func(nodes []*yaml.RNode) ([]*yaml.RNode, error) {
 			filesToUpdate := sets.String{}

pkg/update/update_test.go

@@ -21,6 +21,7 @@ import (
 	"os"
 	"testing"
 
+	"github.com/go-logr/logr"
 	"github.com/google/go-containerregistry/pkg/name"
 	. "github.com/onsi/ginkgo"
 	. "github.com/onsi/gomega"
@@ -88,7 +89,7 @@ var _ = Describe("Update image via kyaml setters2", func() {
 			},
 		}
 
-		_, err = UpdateWithSetters("testdata/setters/original", tmp, policies)
+		_, err = UpdateWithSetters(logr.Discard(), "testdata/setters/original", tmp, policies)
 		Expect(err).ToNot(HaveOccurred())
 		test.ExpectMatchingDirectories(tmp, "testdata/setters/expected")
 	})
@@ -98,7 +99,7 @@ var _ = Describe("Update image via kyaml setters2", func() {
 		Expect(err).ToNot(HaveOccurred())
 		defer os.RemoveAll(tmp)
 
-		result, err := UpdateWithSetters("testdata/setters/original", tmp, policies)
+		result, err := UpdateWithSetters(logr.Discard(), "testdata/setters/original", tmp, policies)
 		Expect(err).ToNot(HaveOccurred())
 
 		kustomizeResourceID := ObjectIdentifier{yaml.ResourceIdentifier{