From 67e9e22a3699ac90e2548e436375f6163344905e Mon Sep 17 00:00:00 2001 From: Avi Deitcher Date: Tue, 1 Oct 2024 12:01:36 +0300 Subject: [PATCH] restructure logging Signed-off-by: Avi Deitcher --- .github/workflows/ci.yml | 6 ++--- src/cmd/linuxkit/cache/write.go | 11 ++++---- src/cmd/linuxkit/cmd.go | 9 ++++--- src/cmd/linuxkit/moby/build/image.go | 18 ++++++------- src/cmd/linuxkit/moby/config.go | 2 +- src/cmd/linuxkit/util/flags.go | 25 +++++++++++++++---- .../000_build/060_input_tar/000_build/test.sh | 2 +- 7 files changed, 44 insertions(+), 29 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 739c4e67d..6843c3d61 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -122,13 +122,13 @@ jobs: - name: Build Packages # Skip s390x as emulation is unreliable run: | - make OPTIONS="-v --skip-platforms linux/s390x" -C pkg build + make OPTIONS="-v 2 --skip-platforms linux/s390x" -C pkg build - name: Build Test Packages # ensures that the test packages are in linuxkit cache when we need them for tests later # Skip s390x as emulation is unreliable run: | - make OPTIONS="-v --skip-platforms linux/s390x" -C test/pkg build + make OPTIONS="-v 2 --skip-platforms linux/s390x" -C test/pkg build - name: Check Kernel Dependencies up to date # checks that any kernel dependencies are up to date. @@ -145,7 +145,7 @@ jobs: # ensures that the kernel packages are in linuxkit cache when we need them for tests later # no need for excluding s390x, as each build.yml in the kernel explicitly lists archs run: | - make OPTIONS="-v" -C kernel build + make OPTIONS="-v 2" -C kernel build - name: list cache contents run: | diff --git a/src/cmd/linuxkit/cache/write.go b/src/cmd/linuxkit/cache/write.go index 18131a573..10aaa37b9 100644 --- a/src/cmd/linuxkit/cache/write.go +++ b/src/cmd/linuxkit/cache/write.go @@ -21,7 +21,6 @@ import ( "github.com/google/go-containerregistry/pkg/v1/types" lktspec "github.com/linuxkit/linuxkit/src/cmd/linuxkit/spec" "github.com/linuxkit/linuxkit/src/cmd/linuxkit/util" - lktutil "github.com/linuxkit/linuxkit/src/cmd/linuxkit/util" imagespec "github.com/opencontainers/image-spec/specs-go/v1" log "github.com/sirupsen/logrus" ) @@ -58,17 +57,17 @@ func (p *Provider) ImagePull(ref *reference.Spec, trustedRef, architecture strin // unless alwaysPull is set to true, check locally first if alwaysPull { - log.Printf("Instructed always to pull, so pulling image %s arch %s", image, architecture) + log.Debugf("Instructed always to pull, so pulling image %s arch %s", image, architecture) } else { imgSrc, err := p.ValidateImage(ref, architecture) switch { case err == nil && imgSrc != nil: - log.Printf("Image %s arch %s found in local cache, not pulling", image, architecture) + log.Debugf("Image %s arch %s found in local cache, not pulling", image, architecture) return imgSrc, nil case err != nil && errors.Is(err, &noReferenceError{}): - log.Printf("Image %s arch %s not found in local cache, pulling", image, architecture) + log.Debugf("Image %s arch %s not found in local cache, pulling", image, architecture) default: - log.Printf("Image %s arch %s incomplete or invalid in local cache, error %v, pulling", image, architecture, err) + log.Debugf("Image %s arch %s incomplete or invalid in local cache, error %v, pulling", image, architecture, err) } // there was an error, so try to pull } @@ -318,7 +317,7 @@ func (p *Provider) IndexWrite(ref *reference.Spec, descriptors ...v1.Descriptor) appliedManifests[m.Digest] = true continue } - value, ok := m.Annotations[lktutil.AnnotationDockerReferenceDigest] + value, ok := m.Annotations[util.AnnotationDockerReferenceDigest] if !ok { manifest.Manifests = append(manifest.Manifests, m) appliedManifests[m.Digest] = true diff --git a/src/cmd/linuxkit/cmd.go b/src/cmd/linuxkit/cmd.go index 8b7e9e9c8..6376536b1 100644 --- a/src/cmd/linuxkit/cmd.go +++ b/src/cmd/linuxkit/cmd.go @@ -43,8 +43,9 @@ func readConfig() { func newCmd() *cobra.Command { var ( - flagQuiet bool - flagVerbose bool + flagQuiet bool + flagVerbose int + flagVerboseName = "verbose" ) cmd := &cobra.Command{ Use: "linuxkit", @@ -54,7 +55,7 @@ func newCmd() *cobra.Command { readConfig() // Set up logging - return util.SetupLogging(flagQuiet, flagVerbose) + return util.SetupLogging(flagQuiet, flagVerbose, cmd.Flag(flagVerboseName).Changed) }, } @@ -69,7 +70,7 @@ func newCmd() *cobra.Command { cmd.PersistentFlags().StringVar(&cacheDir, "cache", defaultLinuxkitCache(), fmt.Sprintf("Directory for caching and finding cached image, overrides env var %s", envVarCacheDir)) cmd.PersistentFlags().BoolVarP(&flagQuiet, "quiet", "q", false, "Quiet execution") - cmd.PersistentFlags().BoolVarP(&flagVerbose, "verbose", "v", false, "Verbose execution") + cmd.PersistentFlags().IntVarP(&flagVerbose, flagVerboseName, "v", 1, "Verbosity of logging: 0 = quiet, 1 = info, 2 = debug, 3 = trace. Default is info. Setting it explicitly will create structured logging lines.") return cmd } diff --git a/src/cmd/linuxkit/moby/build/image.go b/src/cmd/linuxkit/moby/build/image.go index b7476231a..7598d934e 100644 --- a/src/cmd/linuxkit/moby/build/image.go +++ b/src/cmd/linuxkit/moby/build/image.go @@ -237,7 +237,7 @@ func ImageTar(location string, ref *reference.Spec, prefix string, tw tarWriter, hdr.PAXRecords[moby.PaxRecordLinuxkitSource] = ref.String() hdr.PAXRecords[moby.PaxRecordLinuxkitLocation] = location if exclude[hdr.Name] { - log.Debugf("image tar: %s %s exclude %s", ref, prefix, hdr.Name) + log.Tracef("image tar: %s %s exclude %s", ref, prefix, hdr.Name) _, err = io.Copy(io.Discard, tr) if err != nil { return err @@ -248,7 +248,7 @@ func ImageTar(location string, ref *reference.Spec, prefix string, tw tarWriter, hdr.Size = int64(len(contents)) hdr.Name = prefix + hdr.Name hdr.ModTime = defaultModTime - log.Debugf("image tar: %s %s add %s (replaced)", ref, prefix, hdr.Name) + log.Tracef("image tar: %s %s add %s (replaced)", ref, prefix, hdr.Name) if err := tw.WriteHeader(hdr); err != nil { return err } @@ -263,7 +263,7 @@ func ImageTar(location string, ref *reference.Spec, prefix string, tw tarWriter, hdr.Typeflag = tar.TypeSymlink hdr.Linkname = resolv hdr.ModTime = defaultModTime - log.Debugf("image tar: %s %s add resolv symlink /etc/resolv.conf -> %s", ref, prefix, resolv) + log.Tracef("image tar: %s %s add resolv symlink /etc/resolv.conf -> %s", ref, prefix, resolv) if err := tw.WriteHeader(hdr); err != nil { return err } @@ -274,12 +274,12 @@ func ImageTar(location string, ref *reference.Spec, prefix string, tw tarWriter, } } else { if found, ok := touch[hdr.Name]; ok { - log.Debugf("image tar: %s %s add %s (touch)", ref, prefix, hdr.Name) + log.Tracef("image tar: %s %s add %s (touch)", ref, prefix, hdr.Name) hdr.ModTime = found.ModTime // record that we saw this one touchFound[hdr.Name] = true } else { - log.Debugf("image tar: %s %s add %s (original)", ref, prefix, hdr.Name) + log.Tracef("image tar: %s %s add %s (original)", ref, prefix, hdr.Name) } hdr.Name = prefix + hdr.Name if hdr.Typeflag == tar.TypeLink { @@ -304,7 +304,7 @@ func ImageTar(location string, ref *reference.Spec, prefix string, tw tarWriter, sort.Strings(touchNames) for _, name := range touchNames { if touchFound[name] { - log.Debugf("image tar: %s already found in original image", name) + log.Tracef("image tar: %s already found in original image", name) continue } hdr := touch[name] @@ -326,9 +326,9 @@ func ImageTar(location string, ref *reference.Spec, prefix string, tw tarWriter, hdr.Size = 0 hdr.Typeflag = tar.TypeSymlink hdr.Linkname = resolv - log.Debugf("image tar: %s %s add resolv symlink /etc/resolv.conf -> %s", ref, prefix, resolv) + log.Tracef("image tar: %s %s add resolv symlink /etc/resolv.conf -> %s", ref, prefix, resolv) } - log.Debugf("image tar: creating %s", name) + log.Tracef("image tar: creating %s", name) if err := tw.WriteHeader(&hdr); err != nil { return err } @@ -489,7 +489,7 @@ func ImageBundle(prefix, location string, ref *reference.Spec, config []byte, ru return err } - log.Debugf("image bundle: %s %s cfg: %s runtime: %s", prefix, ref, string(config), string(runtimeConfig)) + log.Tracef("image bundle: %s %s cfg: %s runtime: %s", prefix, ref, string(config), string(runtimeConfig)) return nil } diff --git a/src/cmd/linuxkit/moby/config.go b/src/cmd/linuxkit/moby/config.go index 0c7194357..c17511e01 100644 --- a/src/cmd/linuxkit/moby/config.go +++ b/src/cmd/linuxkit/moby/config.go @@ -446,7 +446,7 @@ func AppendConfig(m0, m1 Moby) (Moby, error) { // NewImage validates an parses yaml or json for a Image func NewImage(config []byte) (Image, error) { - log.Debugf("Reading label config: %s", string(config)) + log.Tracef("Reading label config: %s", string(config)) mi := Image{} diff --git a/src/cmd/linuxkit/util/flags.go b/src/cmd/linuxkit/util/flags.go index 33f47bfeb..93c59b1bc 100644 --- a/src/cmd/linuxkit/util/flags.go +++ b/src/cmd/linuxkit/util/flags.go @@ -25,23 +25,38 @@ func (f *infoFormatter) Format(entry *log.Entry) ([]byte, error) { } // SetupLogging once the flags have been parsed, setup the logging -func SetupLogging(quiet, verbose bool) error { +func SetupLogging(quiet bool, verbose int, verboseSet bool) error { // Set up logging log.SetFormatter(new(infoFormatter)) log.SetLevel(log.InfoLevel) - if quiet && verbose { + if quiet && verboseSet && verbose > 0 { return errors.New("can't set quiet and verbose flag at the same time") } - if quiet { + switch { + case quiet, verbose == 0: log.SetLevel(log.ErrorLevel) - } - if verbose { + case verbose == 1: + if verboseSet { + // Switch back to the standard formatter + log.SetFormatter(defaultLogFormatter) + } + log.SetLevel(log.InfoLevel) + case verbose == 2: // Switch back to the standard formatter log.SetFormatter(defaultLogFormatter) log.SetLevel(log.DebugLevel) // set go-containerregistry logging as well ggcrlog.Warn = stdlog.New(log.StandardLogger().WriterLevel(log.WarnLevel), "", 0) ggcrlog.Debug = stdlog.New(log.StandardLogger().WriterLevel(log.DebugLevel), "", 0) + case verbose == 3: + // Switch back to the standard formatter + log.SetFormatter(defaultLogFormatter) + log.SetLevel(log.TraceLevel) + // set go-containerregistry logging as well + ggcrlog.Warn = stdlog.New(log.StandardLogger().WriterLevel(log.WarnLevel), "", 0) + ggcrlog.Debug = stdlog.New(log.StandardLogger().WriterLevel(log.DebugLevel), "", 0) + default: + return errors.New("verbose flag can only be set to 0, 1, 2 or 3") } ggcrlog.Progress = stdlog.New(log.StandardLogger().WriterLevel(log.InfoLevel), "", 0) return nil diff --git a/test/cases/000_build/060_input_tar/000_build/test.sh b/test/cases/000_build/060_input_tar/000_build/test.sh index c5c22ec35..6c48a103f 100644 --- a/test/cases/000_build/060_input_tar/000_build/test.sh +++ b/test/cases/000_build/060_input_tar/000_build/test.sh @@ -21,7 +21,7 @@ logfile=$(mktemp) # do not include the sbom, because the SBoM unique IDs per file/package are *not* deterministic, # (currently based upon syft), and thus will make the file non-reproducible linuxkit build --no-sbom --format tar --o "${NAME}-1.tar" ./test1.yml -linuxkit build -v --no-sbom --format tar --input-tar "${NAME}-1.tar" --o "${NAME}-2.tar" ./test2.yml 2>&1 | tee ${logfile} +linuxkit build -v 2 --no-sbom --format tar --input-tar "${NAME}-1.tar" --o "${NAME}-2.tar" ./test2.yml 2>&1 | tee ${logfile} # the logfile should indicate which parts were copied and which not # we only know this because we built the test2.yml manually