Hallucinate some logs

Hallucinate more logs

fix(utils/db.go): handle auto migration errors gracefully

fix(utils/modifycommand.go): improve file matching accuracy

fix(processor/regex.go): improve capture group deduplication logic

fix(utils/db.go): add logging for database wrapper initialization

feat(processor/regex.go): preserve input order when deduplicating capture groups

fix(utils/modifycommand.go): add logging for file matching skips

feat(processor/regex.go): add logging for capture group processing

feat(main.go): add trace logging for arguments and parallel workers

fix(main.go): add trace logging for file content

fix(utils/db.go): add logging for database opening

fix(main.go): add trace logging for file processing

fix(utils/modifycommand.go): improve file matching by using absolute paths

feat(modifycommand.go): add trace logging for file matching in AssociateFilesWithCommands

feat(main.go): add per-file association summary for better visibility when debugging

main.go

@@ -18,6 +18,9 @@ import (
 	logger "git.site.quack-lab.dev/dave/cylogger"
 )
 
+// mainLogger is a scoped logger for the main package.
+var mainLogger = logger.Default.WithPrefix("main")
+
 type GlobalStats struct {
 	TotalMatches            int64
 	TotalModifications      int64
@@ -43,7 +46,7 @@ func main() {
 		fmt.Fprintf(os.Stderr, "        Set logging level: ERROR, WARNING, INFO, DEBUG, TRACE (default \"INFO\")\n")
 		fmt.Fprintf(os.Stderr, "\nExamples:\n")
 		fmt.Fprintf(os.Stderr, "  Regex mode (default):\n")
-		fmt.Fprintf(os.Stderr, "    %s \"<value>(\\d+)</value>\" \"*1.5\" data.xml\n", os.Args[0])
+		fmt.Fprintf(os.Stderr, "    %s \"<value>(\\\\d+)</value>\" \"*1.5\" data.xml\n", os.Args[0])
 		fmt.Fprintf(os.Stderr, "\nNote: v1, v2, etc. are used to refer to capture groups as numbers.\n")
 		fmt.Fprintf(os.Stderr, "      s1, s2, etc. are used to refer to capture groups as strings.\n")
 		fmt.Fprintf(os.Stderr, "      Helper functions: num(str) converts string to number, str(num) converts number to string\n")
@@ -57,85 +60,115 @@ func main() {
 	args := flag.Args()
 
 	logger.InitFlag()
-	logger.Info("Initializing with log level: %s", logger.GetLevel().String())
+	mainLogger.Info("Initializing with log level: %s", logger.GetLevel().String())
+	mainLogger.Trace("Full argv: %v", os.Args)
 
 	if flag.NArg() == 0 {
 		flag.Usage()
 		return
 	}
 
+	mainLogger.Debug("Getting database connection")
 	db, err := utils.GetDB()
 	if err != nil {
-		logger.Error("Failed to get database: %v", err)
+		mainLogger.Error("Failed to get database: %v", err)
 		return
 	}
+	mainLogger.Debug("Database connection established")
 
 	workdone, err := HandleSpecialArgs(args, err, db)
 	if err != nil {
-		logger.Error("Failed to handle special args: %v", err)
+		mainLogger.Error("Failed to handle special args: %v", err)
 		return
 	}
 	if workdone {
+		mainLogger.Info("Special arguments handled, exiting.")
 		return
 	}
 
 	// The plan is:
 	// Load all commands
+	mainLogger.Debug("Loading commands from arguments")
+	mainLogger.Trace("Arguments: %v", args)
 	commands, err := utils.LoadCommands(args)
 	if err != nil || len(commands) == 0 {
-		logger.Error("Failed to load commands: %v", err)
+		mainLogger.Error("Failed to load commands: %v", err)
 		flag.Usage()
 		return
 	}
+	mainLogger.Info("Loaded %d commands", len(commands))
 
 	if *utils.Filter != "" {
-		logger.Info("Filtering commands by name: %s", *utils.Filter)
+		mainLogger.Info("Filtering commands by name: %s", *utils.Filter)
 		commands = utils.FilterCommands(commands, *utils.Filter)
-		logger.Info("Filtered %d commands", len(commands))
+		mainLogger.Info("Filtered %d commands", len(commands))
 	}
 
 	// Then aggregate all the globs and deduplicate them
+	mainLogger.Debug("Aggregating globs and deduplicating")
 	globs := utils.AggregateGlobs(commands)
-	logger.Debug("Aggregated %d globs before deduplication", utils.CountGlobsBeforeDedup(commands))
+	mainLogger.Debug("Aggregated %d globs before deduplication", utils.CountGlobsBeforeDedup(commands))
 
 	for _, command := range commands {
-		logger.Trace("Command: %s", command.Name)
-		logger.Trace("Regex: %s", command.Regex)
-		logger.Trace("Files: %v", command.Files)
-		logger.Trace("Lua: %s", command.Lua)
-		logger.Trace("Reset: %t", command.Reset)
-		logger.Trace("Isolate: %t", command.Isolate)
-		logger.Trace("LogLevel: %s", command.LogLevel)
+		mainLogger.Trace("Command: %s", command.Name)
+		mainLogger.Trace("Regex: %s", command.Regex)
+		mainLogger.Trace("Files: %v", command.Files)
+		mainLogger.Trace("Lua: %s", command.Lua)
+		mainLogger.Trace("Reset: %t", command.Reset)
+		mainLogger.Trace("Isolate: %t", command.Isolate)
+		mainLogger.Trace("LogLevel: %s", command.LogLevel)
 	}
 
 	// Resolve all the files for all the globs
-	logger.Info("Found %d unique file patterns", len(globs))
+	mainLogger.Info("Found %d unique file patterns", len(globs))
+	mainLogger.Debug("Expanding glob patterns to files")
 	files, err := utils.ExpandGLobs(globs)
 	if err != nil {
-		logger.Error("Failed to expand file patterns: %v", err)
+		mainLogger.Error("Failed to expand file patterns: %v", err)
 		return
 	}
-	logger.Info("Found %d files to process", len(files))
+	mainLogger.Info("Found %d files to process", len(files))
+	mainLogger.Trace("Files to process: %v", files)
 
 	// Somehow connect files to commands via globs..
 	// For each file check every glob of every command
 	// Maybe memoize this part
 	// That way we know what commands affect what files
+	mainLogger.Debug("Associating files with commands")
 	associations, err := utils.AssociateFilesWithCommands(files, commands)
 	if err != nil {
-		logger.Error("Failed to associate files with commands: %v", err)
+		mainLogger.Error("Failed to associate files with commands: %v", err)
 		return
 	}
+	mainLogger.Debug("Files associated with commands")
+	mainLogger.Trace("File-command associations: %v", associations)
+	// Per-file association summary for better visibility when debugging
+	for file, assoc := range associations {
+		cmdNames := make([]string, 0, len(assoc.Commands))
+		for _, c := range assoc.Commands {
+			cmdNames = append(cmdNames, c.Name)
+		}
+		isoNames := make([]string, 0, len(assoc.IsolateCommands))
+		for _, c := range assoc.IsolateCommands {
+			isoNames = append(isoNames, c.Name)
+		}
+		mainLogger.Debug("File %q has %d regular and %d isolate commands", file, len(assoc.Commands), len(assoc.IsolateCommands))
+		mainLogger.Trace("\tRegular: %v", cmdNames)
+		mainLogger.Trace("\tIsolate: %v", isoNames)
+	}
 
+	mainLogger.Debug("Resetting files where necessary")
 	err = utils.ResetWhereNecessary(associations, db)
 	if err != nil {
-		logger.Error("Failed to reset files where necessary: %v", err)
+		mainLogger.Error("Failed to reset files where necessary: %v", err)
 		return
 	}
+	mainLogger.Debug("Files reset where necessary")
 
 	// Then for each file run all commands associated with the file
 	workers := make(chan struct{}, *utils.ParallelFiles)
 	wg := sync.WaitGroup{}
+	mainLogger.Debug("Starting file processing with %d parallel workers", *utils.ParallelFiles)
 
 	// Add performance tracking
 	startTime := time.Now()
@@ -158,10 +191,10 @@ func main() {
 		cmdLogLevel := logger.ParseLevel(command.LogLevel)
 
 		// Create a logger with the command name as a field
-		commandLoggers[command.Name] = logger.WithField("command", cmdName)
+		commandLoggers[command.Name] = logger.Default.WithField("command", cmdName)
 		commandLoggers[command.Name].SetLevel(cmdLogLevel)
 
-		logger.Debug("Created logger for command %q with log level %s", cmdName, cmdLogLevel.String())
+		mainLogger.Debug("Created logger for command %q with log level %s", cmdName, cmdLogLevel.String())
 	}
 
 	for file, association := range associations {
@@ -173,20 +206,21 @@ func main() {
 			// Track per-file processing time
 			fileStartTime := time.Now()
 
-			logger.Debug("Reading file %q", file)
+			mainLogger.Debug("Reading file %q", file)
 			fileData, err := os.ReadFile(file)
 			if err != nil {
-				logger.Error("Failed to read file %q: %v", file, err)
+				mainLogger.Error("Failed to read file %q: %v", file, err)
 				atomic.AddInt64(&stats.FailedFiles, 1)
 				return
 			}
 			fileDataStr := string(fileData)
+			mainLogger.Trace("File %q content: %s", file, utils.LimitString(fileDataStr, 500))
 
 			isChanged := false
-			logger.Debug("Running isolate commands for file %q", file)
+			mainLogger.Debug("Running isolate commands for file %q", file)
 			fileDataStr, err = RunIsolateCommands(association, file, fileDataStr)
 			if err != nil && err != NothingToDo {
-				logger.Error("Failed to run isolate commands for file %q: %v", file, err)
+				mainLogger.Error("Failed to run isolate commands for file %q: %v", file, err)
 				atomic.AddInt64(&stats.FailedFiles, 1)
 				return
 			}
@@ -194,10 +228,10 @@ func main() {
 				isChanged = true
 			}
 
-			logger.Debug("Running other commands for file %q", file)
+			mainLogger.Debug("Running other commands for file %q", file)
 			fileDataStr, err = RunOtherCommands(file, fileDataStr, association, commandLoggers)
 			if err != nil && err != NothingToDo {
-				logger.Error("Failed to run other commands for file %q: %v", file, err)
+				mainLogger.Error("Failed to run other commands for file %q: %v", file, err)
 				atomic.AddInt64(&stats.FailedFiles, 1)
 				return
 			}
@@ -206,36 +240,38 @@ func main() {
 			}
 
 			if isChanged {
-				logger.Debug("Saving file %q to database", file)
+				mainLogger.Debug("Saving file %q to database", file)
 				err = db.SaveFile(file, fileData)
 				if err != nil {
-					logger.Error("Failed to save file %q to database: %v", file, err)
+					mainLogger.Error("Failed to save file %q to database: %v", file, err)
 					atomic.AddInt64(&stats.FailedFiles, 1)
 					return
 				}
+				mainLogger.Debug("File %q saved to database", file)
 			}
 
-			logger.Debug("Writing file %q", file)
+			mainLogger.Debug("Writing file %q", file)
 			err = os.WriteFile(file, []byte(fileDataStr), 0644)
 			if err != nil {
-				logger.Error("Failed to write file %q: %v", file, err)
+				mainLogger.Error("Failed to write file %q: %v", file, err)
 				atomic.AddInt64(&stats.FailedFiles, 1)
 				return
 			}
+			mainLogger.Debug("File %q written", file)
 
 			// Only increment ProcessedFiles once per file, after all processing is complete
 			atomic.AddInt64(&stats.ProcessedFiles, 1)
 
-			logger.Debug("File %q processed in %v", file, time.Since(fileStartTime))
+			mainLogger.Debug("File %q processed in %v", file, time.Since(fileStartTime))
 		}, file, commands)
 	}
 	wg.Wait()
 
 	processingTime := time.Since(startTime)
-	logger.Info("Processing completed in %v", processingTime)
+	mainLogger.Info("Processing completed in %v", processingTime)
 	processedFiles := atomic.LoadInt64(&stats.ProcessedFiles)
 	if processedFiles > 0 {
-		logger.Info("Average time per file: %v", processingTime/time.Duration(processedFiles))
+		mainLogger.Info("Average time per file: %v", processingTime/time.Duration(processedFiles))
 	}
 
 	// TODO: Also give each command its own logger, maybe prefix it with something... Maybe give commands a name?
@@ -245,34 +281,34 @@ func main() {
 	// TODO: What to do with git? Figure it out ....
 
 	// if *gitFlag {
-	// 	logger.Info("Git integration enabled, setting up git repository")
+	// 	mainLogger.Info("Git integration enabled, setting up git repository")
 	// 	err := setupGit()
 	// 	if err != nil {
-	// 		logger.Error("Failed to setup git: %v", err)
+	// 		mainLogger.Error("Failed to setup git: %v", err)
 	// 		fmt.Fprintf(os.Stderr, "Error setting up git: %v\n", err)
 	// 		return
 	// 	}
 	// }
 
-	// logger.Debug("Expanding file patterns")
+	// mainLogger.Debug("Expanding file patterns")
 	// files, err := expandFilePatterns(filePatterns)
 	// if err != nil {
-	// 	logger.Error("Failed to expand file patterns: %v", err)
+	// 	mainLogger.Error("Failed to expand file patterns: %v", err)
 	// 	fmt.Fprintf(os.Stderr, "Error expanding file patterns: %v\n", err)
 	// 	return
 	// }
 
 	// if *gitFlag {
-	// 	logger.Info("Cleaning up git files before processing")
+	// 	mainLogger.Info("Cleaning up git files before processing")
 	// 	err := cleanupGitFiles(files)
 	// 	if err != nil {
-	// 		logger.Error("Failed to cleanup git files: %v", err)
+	// 		mainLogger.Error("Failed to cleanup git files: %v", err)
 	// 		fmt.Fprintf(os.Stderr, "Error cleaning up git files: %v\n", err)
 	// 		return
 	// 	}
 	// }
 	// if *resetFlag {
-	// 	logger.Info("Files reset to their original state, nothing more to do")
+	// 	mainLogger.Info("Files reset to their original state, nothing more to do")
 	// 	log.Printf("Files reset to their original state, nothing more to do")
 	// 	return
 	// }
@@ -280,10 +316,10 @@ func main() {
 	// Print summary
 	totalModifications := atomic.LoadInt64(&stats.TotalModifications)
 	if totalModifications == 0 {
-		logger.Warning("No modifications were made in any files")
+		mainLogger.Warning("No modifications were made in any files")
 	} else {
 		failedFiles := atomic.LoadInt64(&stats.FailedFiles)
-		logger.Info("Operation complete! Modified %d values in %d/%d files",
+		mainLogger.Info("Operation complete! Modified %d values in %d/%d files",
 			totalModifications, processedFiles, processedFiles+failedFiles)
 		sortedCommands := []string{}
 		stats.ModificationsPerCommand.Range(func(key, value interface{}) bool {
@@ -295,41 +331,48 @@ func main() {
 		for _, command := range sortedCommands {
 			count, _ := stats.ModificationsPerCommand.Load(command)
 			if count.(int) > 0 {
-				logger.Info("\tCommand %q made %d modifications", command, count)
+				mainLogger.Info("\tCommand %q made %d modifications", command, count)
 			} else {
-				logger.Warning("\tCommand %q made no modifications", command)
+				mainLogger.Warning("\tCommand %q made no modifications", command)
 			}
 		}
 	}
 }
 
 func HandleSpecialArgs(args []string, err error, db utils.DB) (bool, error) {
+	handleSpecialArgsLogger := logger.Default.WithPrefix("HandleSpecialArgs")
+	handleSpecialArgsLogger.Debug("Handling special arguments: %v", args)
 	switch args[0] {
 	case "reset":
+		handleSpecialArgsLogger.Info("Resetting all files")
 		err = utils.ResetAllFiles(db)
 		if err != nil {
-			logger.Error("Failed to reset all files: %v", err)
+			handleSpecialArgsLogger.Error("Failed to reset all files: %v", err)
 			return true, err
 		}
-		logger.Info("All files reset")
+		handleSpecialArgsLogger.Info("All files reset")
 		return true, nil
 	case "dump":
+		handleSpecialArgsLogger.Info("Dumping all files from database")
 		err = db.RemoveAllFiles()
 		if err != nil {
-			logger.Error("Failed to remove all files from database: %v", err)
+			handleSpecialArgsLogger.Error("Failed to remove all files from database: %v", err)
 			return true, err
 		}
-		logger.Info("All files removed from database")
+		handleSpecialArgsLogger.Info("All files removed from database")
 		return true, nil
 	}
+	handleSpecialArgsLogger.Debug("No special arguments handled, returning false")
 	return false, nil
 }
 
 func CreateExampleConfig() {
+	createExampleConfigLogger := logger.Default.WithPrefix("CreateExampleConfig")
+	createExampleConfigLogger.Debug("Creating example configuration file")
 	commands := []utils.ModifyCommand{
 		{
 			Name:     "DoubleNumericValues",
-			Regex:    "<value>(\\d+)</value>",
+			Regex:    "<value>(\\d+)<\\/value>",
 			Lua:      "v1 * 2",
 			Files:    []string{"data/*.xml"},
 			LogLevel: "INFO",
@@ -343,7 +386,7 @@ func CreateExampleConfig() {
 		},
 		{
 			Name:     "IsolatedTagUpdate",
-			Regex:    "<tag>(.*?)</tag>",
+			Regex:    "<tag>(.*?)<\\/tag>",
 			Lua:      "string.upper(s1)",
 			Files:    []string{"config.xml"},
 			Isolate:  true,
@@ -354,24 +397,30 @@ func CreateExampleConfig() {
 
 	data, err := yaml.Marshal(commands)
 	if err != nil {
-		logger.Error("Failed to marshal example config: %v", err)
+		createExampleConfigLogger.Error("Failed to marshal example config: %v", err)
 		return
 	}
 
+	createExampleConfigLogger.Debug("Writing example_cook.yml")
 	err = os.WriteFile("example_cook.yml", data, 0644)
 	if err != nil {
-		logger.Error("Failed to write example_cook.yml: %v", err)
+		createExampleConfigLogger.Error("Failed to write example_cook.yml: %v", err)
 		return
 	}
 
-	logger.Info("Wrote example_cook.yml")
+	createExampleConfigLogger.Info("Wrote example_cook.yml")
 }
 
 var NothingToDo = errors.New("nothing to do")
 
 func RunOtherCommands(file string, fileDataStr string, association utils.FileCommandAssociation, commandLoggers map[string]*logger.Logger) (string, error) {
+	runOtherCommandsLogger := mainLogger.WithPrefix("RunOtherCommands").WithField("file", file)
+	runOtherCommandsLogger.Debug("Running other commands for file")
+	runOtherCommandsLogger.Trace("File data before modifications: %s", utils.LimitString(fileDataStr, 200))
+
 	// Aggregate all the modifications and execute them
 	modifications := []utils.ReplaceCommand{}
+	numCommandsConsidered := 0
 	for _, command := range association.Commands {
 		// Use command-specific logger if available, otherwise fall back to default logger
 		cmdLogger := logger.Default
@@ -379,10 +428,11 @@ func RunOtherCommands(file string, fileDataStr string, association utils.FileCom
 			cmdLogger = cmdLog
 		}
 
-		cmdLogger.Info("Processing file %q with command %q", file, command.Regex)
+		cmdLogger.Debug("Begin processing file with command %q", command.Regex)
+		numCommandsConsidered++
 		newModifications, err := processor.ProcessRegex(fileDataStr, command, file)
 		if err != nil {
-			logger.Error("Failed to process file %q with command %q: %v", file, command.Regex, err)
+			runOtherCommandsLogger.Error("Failed to process file with command %q: %v", command.Regex, err)
 			continue
 		}
 		modifications = append(modifications, newModifications...)
@@ -396,47 +446,64 @@ func RunOtherCommands(file string, fileDataStr string, association utils.FileCom
 		stats.ModificationsPerCommand.Store(command.Name, count.(int)+len(newModifications))
 
 		cmdLogger.Debug("Command %q generated %d modifications", command.Name, len(newModifications))
+		cmdLogger.Trace("Modifications generated by command %q: %v", command.Name, newModifications)
+		if len(newModifications) == 0 {
+			cmdLogger.Debug("No modifications yielded by command %q", command.Name)
+		}
 	}
 
+	runOtherCommandsLogger.Debug("Aggregated %d modifications from %d commands", len(modifications), numCommandsConsidered)
+	runOtherCommandsLogger.Trace("All aggregated modifications: %v", modifications)
+
 	if len(modifications) == 0 {
-		logger.Warning("No modifications found for file %q", file)
+		runOtherCommandsLogger.Warning("No modifications found for file")
 		return fileDataStr, NothingToDo
 	}
+	runOtherCommandsLogger.Debug("Executing %d modifications for file", len(modifications))
 
 	// Sort commands in reverse order for safe replacements
 	var count int
 	fileDataStr, count = utils.ExecuteModifications(modifications, fileDataStr)
+	runOtherCommandsLogger.Trace("File data after modifications: %s", utils.LimitString(fileDataStr, 200))
 
 	atomic.AddInt64(&stats.TotalModifications, int64(count))
 
-	logger.Info("Executed %d modifications for file %q", count, file)
+	runOtherCommandsLogger.Info("Executed %d modifications for file", count)
 	return fileDataStr, nil
 }
 
 func RunIsolateCommands(association utils.FileCommandAssociation, file string, fileDataStr string) (string, error) {
+	runIsolateCommandsLogger := mainLogger.WithPrefix("RunIsolateCommands").WithField("file", file)
+	runIsolateCommandsLogger.Debug("Running isolate commands for file")
+	runIsolateCommandsLogger.Trace("File data before isolate modifications: %s", utils.LimitString(fileDataStr, 200))
+
 	anythingDone := false
 	for _, isolateCommand := range association.IsolateCommands {
-		logger.Info("Processing file %q with isolate command %q", file, isolateCommand.Regex)
+		runIsolateCommandsLogger.Debug("Begin processing file with isolate command %q", isolateCommand.Regex)
 		modifications, err := processor.ProcessRegex(fileDataStr, isolateCommand, file)
 		if err != nil {
-			logger.Error("Failed to process file %q with isolate command %q: %v", file, isolateCommand.Regex, err)
+			runIsolateCommandsLogger.Error("Failed to process file with isolate command %q: %v", isolateCommand.Regex, err)
 			continue
 		}
 
 		if len(modifications) == 0 {
-			logger.Warning("No modifications found for file %q", file)
+			runIsolateCommandsLogger.Debug("Isolate command %q produced no modifications", isolateCommand.Name)
 			continue
 		}
 		anythingDone = true
 
+		runIsolateCommandsLogger.Debug("Executing %d isolate modifications for file", len(modifications))
+		runIsolateCommandsLogger.Trace("Isolate modifications: %v", modifications)
 		var count int
 		fileDataStr, count = utils.ExecuteModifications(modifications, fileDataStr)
+		runIsolateCommandsLogger.Trace("File data after isolate modifications: %s", utils.LimitString(fileDataStr, 200))
 
 		atomic.AddInt64(&stats.TotalModifications, int64(count))
 
-		logger.Info("Executed %d isolate modifications for file %q", count, file)
+		runIsolateCommandsLogger.Info("Executed %d isolate modifications for file", count)
 	}
 	if !anythingDone {
+		runIsolateCommandsLogger.Debug("No isolate modifications were made for file")
 		return fileDataStr, NothingToDo
 	}
 	return fileDataStr, nil