From c798f559fee4b43c22e4298efffd1b5ede961630 Mon Sep 17 00:00:00 2001 From: Michael Bridgen Date: Tue, 22 Jun 2021 15:47:50 +0100 Subject: [PATCH 1/3] Let log level be supplied for make run It's useful to be able to run with debug logging, which you can do now with: make run LOG_LEVEL=debug As a companion change, logging from `make run` is now explicitly set to console format, since the expectation is it will be run from a console. Signed-off-by: Michael Bridgen --- Makefile | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/Makefile b/Makefile index 9f7e6404..10186db9 100644 --- a/Makefile +++ b/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 From f011f2334e9469987f4842832ea3b92a077c4940 Mon Sep 17 00:00:00 2001 From: Michael Bridgen Date: Tue, 22 Jun 2021 18:00:14 +0100 Subject: [PATCH 2/3] Thread debug/tracing through controller and pkg/ This commit finesses the use of the debug log a little, and introduces a trace log. The trace log gets threaded through calls to utility procedures -- it's a little awkward putting loggers into func parameters and structs, but it always is. Signed-off-by: Michael Bridgen --- controllers/git_test.go | 3 +- .../imageupdateautomation_controller.go | 40 ++++++++++++++----- pkg/update/filereader.go | 12 ++++++ pkg/update/filter.go | 11 +++++ pkg/update/setters.go | 18 ++++++--- pkg/update/update_test.go | 5 ++- 6 files changed, 69 insertions(+), 20 deletions(-) diff --git a/controllers/git_test.go b/controllers/git_test.go index 59081ca7..e0e0a606 100644 --- a/controllers/git_test.go +++ b/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) } diff --git a/controllers/imageupdateautomation_controller.go b/controllers/imageupdateautomation_controller.go index 152aad84..f634eb07 100644 --- a/controllers/imageupdateautomation_controller.go +++ b/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 @@ -176,7 +186,7 @@ func (r *ImageUpdateAutomationReconciler) Reconcile(ctx context.Context, req ctr return ctrl.Result{}, err } - log.V(debug).Info("found git repository", "gitrepository", originName) + debuglog.Info("found git repository", "gitrepository", originName) // validate the git spec and default any values needed later, before proceeding var ref *sourcev1.GitRepositoryRef @@ -229,7 +239,7 @@ func (r *ImageUpdateAutomationReconciler) Reconcile(ctx context.Context, req ctr } } - log.V(debug).Info("cloned git repository", "gitrepository", originName, "ref", ref, "working", tmp) + debuglog.Info("cloned git repository", "gitrepository", originName, "ref", ref, "working", tmp) manifestsPath := tmp if auto.Spec.Update.Path != "" { @@ -250,7 +260,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("applying 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 +280,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 +311,10 @@ 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 +537,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 +563,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 +742,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) { diff --git a/pkg/update/filereader.go b/pkg/update/filereader.go index c58e21fa..68867140 100644 --- a/pkg/update/filereader.go +++ b/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 } diff --git a/pkg/update/filter.go b/pkg/update/filter.go index e59a68de..591342e8 100644 --- a/pkg/update/filter.go +++ b/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 diff --git a/pkg/update/setters.go b/pkg/update/setters.go index a68ed260..68ea65ad 100644 --- a/pkg/update/setters.go +++ b/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{} diff --git a/pkg/update/update_test.go b/pkg/update/update_test.go index 7f81c1a2..dee3234b 100644 --- a/pkg/update/update_test.go +++ b/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{ From 0a9c9a7437629093349eb3d3c77f8d9e5d6fba7c Mon Sep 17 00:00:00 2001 From: Michael Bridgen Date: Wed, 23 Jun 2021 12:23:36 +0100 Subject: [PATCH 3/3] Fill in tracking gaps - trace different code paths, e.g., how the push branch is chosen - move debug output so it records things not already covered by e.g., errors, events Signed-off-by: Michael Bridgen --- controllers/imageupdateautomation_controller.go | 16 +++++++++++----- 1 file changed, 11 insertions(+), 5 deletions(-) diff --git a/controllers/imageupdateautomation_controller.go b/controllers/imageupdateautomation_controller.go index f634eb07..b1f70e37 100644 --- a/controllers/imageupdateautomation_controller.go +++ b/controllers/imageupdateautomation_controller.go @@ -174,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") @@ -186,19 +188,20 @@ func (r *ImageUpdateAutomationReconciler) Reconcile(ctx context.Context, req ctr return ctrl.Result{}, err } - debuglog.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 @@ -207,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)) @@ -217,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) @@ -239,10 +245,9 @@ func (r *ImageUpdateAutomationReconciler) Reconcile(ctx context.Context, req ctr } } - debuglog.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 { @@ -260,7 +265,7 @@ func (r *ImageUpdateAutomationReconciler) Reconcile(ctx context.Context, req ctr return failWithError(err) } - debuglog.Info("applying image policies", "count", len(policies.Items), "manifests-path", manifestsPath) + 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) @@ -311,6 +316,7 @@ func (r *ImageUpdateAutomationReconciler) Reconcile(ctx context.Context, req ctr Email: gitSpec.Commit.Author.Email, When: time.Now(), } + 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")