Merge pull request #295 from numtide/feat/improve-logging

feat/improve logging

Author: mergify[bot]

cache/cache.go

@@ -89,14 +89,23 @@ func Open(treeRoot string, clean bool, formatters map[string]*format.Formatter)
 				return fmt.Errorf("failed to retrieve cache entry for formatter %v: %w", name, err)
 			}
 
-			clean = clean || entry == nil || !(entry.Size == stat.Size() && entry.Modified == stat.ModTime())
-			logger.Debug(
-				"checking if formatter has changed",
-				"name", name,
-				"clean", clean,
-				"entry", entry,
-				"stat", stat,
-			)
+			isNew := entry == nil
+			hasChanged := entry != nil && !(entry.Size == stat.Size() && entry.Modified == stat.ModTime())
+
+			if isNew {
+				logger.Debugf("formatter '%s' is new", name)
+			} else if hasChanged {
+				logger.Debug("formatter '%s' has changed",
+					name,
+					"size", stat.Size(),
+					"modTime", stat.ModTime(),
+					"cachedSize", entry.Size,
+					"cachedModTime", entry.Modified,
+				)
+			}
+
+			// update overall clean flag
+			clean = clean || isNew || hasChanged
 
 			// record formatters info
 			entry = &Entry{
@@ -182,7 +191,7 @@ func ChangeSet(ctx context.Context, walker walk.Walker, filesCh chan<- *walk.Fil
 	start := time.Now()
 
 	defer func() {
-		logger.Infof("finished generating change set in %v", time.Since(start))
+		logger.Debugf("finished generating change set in %v", time.Since(start))
 	}()
 
 	var tx *bolt.Tx
@@ -263,7 +272,7 @@ func ChangeSet(ctx context.Context, walker walk.Walker, filesCh chan<- *walk.Fil
 func Update(files []*walk.File) error {
 	start := time.Now()
 	defer func() {
-		logger.Infof("finished processing %v paths in %v", len(files), time.Since(start))
+		logger.Debugf("finished processing %v paths in %v", len(files), time.Since(start))
 	}()
 
 	if len(files) == 0 {

cli/format.go

@@ -57,12 +57,12 @@ func (f *Format) Run() (err error) {
 	}
 
 	// create a prefixed logger
-	l := log.WithPrefix("format")
+	log.SetPrefix("format")
 
 	// ensure cache is closed on return
 	defer func() {
 		if err := cache.Close(); err != nil {
-			l.Errorf("failed to close cache: %v", err)
+			log.Errorf("failed to close cache: %v", err)
 		}
 	}()
 
@@ -87,7 +87,7 @@ func (f *Format) Run() (err error) {
 		formatterCfg := cfg.Formatters[name]
 		formatter, err := format.NewFormatter(name, Cli.TreeRoot, formatterCfg, globalExcludes)
 		if errors.Is(err, format.ErrCommandNotFound) && Cli.AllowMissingFormatter {
-			l.Debugf("formatter not found: %v", name)
+			log.Debugf("formatter not found: %v", name)
 			continue
 		} else if err != nil {
 			return fmt.Errorf("%w: failed to initialise formatter: %v", err, name)
@@ -383,6 +383,7 @@ func applyFormatters(ctx context.Context) func() error {
 			if matched {
 				stats.Add(stats.Matched, 1)
 			} else {
+				log.Debugf("no match found: %s", file.Path)
 				// no match, so we send it direct to the processed channel
 				processedCh <- file
 			}

format/formatter.go

@@ -80,9 +80,12 @@ func (f *Formatter) Apply(ctx context.Context, files []*walk.File, filter bool)
 	}
 
 	// execute the command
-	cmd := exec.CommandContext(ctx, f.config.Command, args...)
+	cmd := exec.CommandContext(ctx, f.executable, args...)
 	cmd.Dir = f.workingDir
 
+	// log out the command being executed
+	f.log.Debugf("executing: %s", cmd.String())
+
 	if out, err := cmd.CombinedOutput(); err != nil {
 		if len(out) > 0 {
 			_, _ = fmt.Fprintf(os.Stderr, "%s error:\n%s\n", f.name, out)