From a42038a5e22b16ab9534d24defd399e78644b535 Mon Sep 17 00:00:00 2001 From: Michael Bridgen Date: Tue, 22 Jun 2021 18:00:14 +0100 Subject: [PATCH] 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 | 10 +++++ pkg/update/filter.go | 11 +++++ pkg/update/setters.go | 23 ++++++++--- pkg/update/update_test.go | 5 ++- 6 files changed, 72 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..b1dfde67 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,11 @@ 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() + } + if r.Path == "" { return nil, fmt.Errorf("must supply path to scan for files") } @@ -108,6 +116,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 +128,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..44e6f117 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" @@ -38,6 +39,11 @@ const ( // setters; instead of // # { "$ref": "#/definitions/ SetterShortHand = "$imagepolicy" + + // debug level for logger + debug = 1 + // trace level for logger + trace = 2 ) func init() { @@ -51,7 +57,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 +167,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 +199,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 +217,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{