diff --git a/main.go b/main.go index b6146d7..c49981e 100644 --- a/main.go +++ b/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 \"(\\d+)\" \"*1.5\" data.xml\n", os.Args[0]) + fmt.Fprintf(os.Stderr, " %s \"(\\\\d+)\" \"*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: "(\\d+)", + Regex: "(\\d+)<\\/value>", Lua: "v1 * 2", Files: []string{"data/*.xml"}, LogLevel: "INFO", @@ -343,7 +386,7 @@ func CreateExampleConfig() { }, { Name: "IsolatedTagUpdate", - Regex: "(.*?)", + Regex: "(.*?)<\\/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 diff --git a/processor/processor.go b/processor/processor.go index 0f770a1..1541a71 100644 --- a/processor/processor.go +++ b/processor/processor.go @@ -6,151 +6,106 @@ import ( "net/http" "strings" + "cook/utils" + logger "git.site.quack-lab.dev/dave/cylogger" lua "github.com/yuin/gopher-lua" ) +// processorLogger is a scoped logger for the processor package. +var processorLogger = logger.Default.WithPrefix("processor") + // Maybe we make this an interface again for the shits and giggles // We will see, it could easily be... func NewLuaState() (*lua.LState, error) { + newLStateLogger := processorLogger.WithPrefix("NewLuaState") + newLStateLogger.Debug("Creating new Lua state") L := lua.NewState() // defer L.Close() // Load math library - logger.Debug("Loading Lua math library") + newLStateLogger.Debug("Loading Lua math library") L.Push(L.GetGlobal("require")) L.Push(lua.LString("math")) if err := L.PCall(1, 1, nil); err != nil { - logger.Error("Failed to load Lua math library: %v", err) + newLStateLogger.Error("Failed to load Lua math library: %v", err) return nil, fmt.Errorf("error loading Lua math library: %v", err) } + newLStateLogger.Debug("Lua math library loaded") // Initialize helper functions - logger.Debug("Initializing Lua helper functions") + newLStateLogger.Debug("Initializing Lua helper functions") if err := InitLuaHelpers(L); err != nil { - logger.Error("Failed to initialize Lua helper functions: %v", err) + newLStateLogger.Error("Failed to initialize Lua helper functions: %v", err) return nil, err } + newLStateLogger.Debug("Lua helper functions initialized") + newLStateLogger.Debug("New Lua state created successfully") return L, nil } -// func Process(filename string, pattern string, luaExpr string) (int, int, error) { -// logger.Debug("Processing file %q with pattern %q", filename, pattern) -// -// // Read file content -// cwd, err := os.Getwd() -// if err != nil { -// logger.Error("Failed to get current working directory: %v", err) -// return 0, 0, fmt.Errorf("error getting current working directory: %v", err) -// } -// -// fullPath := filepath.Join(cwd, filename) -// logger.Trace("Reading file from: %s", fullPath) -// -// stat, err := os.Stat(fullPath) -// if err != nil { -// logger.Error("Failed to stat file %s: %v", fullPath, err) -// return 0, 0, fmt.Errorf("error getting file info: %v", err) -// } -// logger.Debug("File size: %d bytes, modified: %s", stat.Size(), stat.ModTime().Format(time.RFC3339)) -// -// content, err := os.ReadFile(fullPath) -// if err != nil { -// logger.Error("Failed to read file %s: %v", fullPath, err) -// return 0, 0, fmt.Errorf("error reading file: %v", err) -// } -// -// fileContent := string(content) -// logger.Trace("File read successfully: %d bytes, hash: %x", len(content), md5sum(content)) -// -// // Detect and log file type -// fileType := detectFileType(filename, fileContent) -// if fileType != "" { -// logger.Debug("Detected file type: %s", fileType) -// } -// -// // Process the content -// logger.Debug("Starting content processing") -// modifiedContent, modCount, matchCount, err := ProcessContent(fileContent, pattern, luaExpr) -// if err != nil { -// logger.Error("Processing error: %v", err) -// return 0, 0, err -// } -// -// logger.Debug("Processing results: %d matches, %d modifications", matchCount, modCount) -// -// // If we made modifications, save the file -// if modCount > 0 { -// // Calculate changes summary -// changePercent := float64(len(modifiedContent)) / float64(len(fileContent)) * 100 -// logger.Info("File size change: %d → %d bytes (%.1f%%)", -// len(fileContent), len(modifiedContent), changePercent) -// -// logger.Debug("Writing modified content to %s", fullPath) -// err = os.WriteFile(fullPath, []byte(modifiedContent), 0644) -// if err != nil { -// logger.Error("Failed to write to file %s: %v", fullPath, err) -// return 0, 0, fmt.Errorf("error writing file: %v", err) -// } -// logger.Debug("File written successfully, new hash: %x", md5sum([]byte(modifiedContent))) -// } else if matchCount > 0 { -// logger.Debug("No content modifications needed for %d matches", matchCount) -// } else { -// logger.Debug("No matches found in file") -// } -// -// return modCount, matchCount, nil -// } - // FromLua converts a Lua table to a struct or map recursively func FromLua(L *lua.LState, luaValue lua.LValue) (interface{}, error) { + fromLuaLogger := processorLogger.WithPrefix("FromLua").WithField("luaType", luaValue.Type().String()) + fromLuaLogger.Debug("Converting Lua value to Go interface") switch v := luaValue.(type) { - // Well shit... - // Tables in lua are both maps and arrays - // As arrays they are ordered and as maps, obviously, not - // So when we parse them to a go map we fuck up the order for arrays - // We have to find a better way.... case *lua.LTable: + fromLuaLogger.Debug("Processing Lua table") isArray, err := IsLuaTableArray(L, v) if err != nil { + fromLuaLogger.Error("Failed to determine if Lua table is array: %v", err) return nil, err } + fromLuaLogger.Debug("Lua table is array: %t", isArray) if isArray { + fromLuaLogger.Debug("Converting Lua table to Go array") result := make([]interface{}, 0) v.ForEach(func(key lua.LValue, value lua.LValue) { converted, _ := FromLua(L, value) result = append(result, converted) }) + fromLuaLogger.Trace("Converted Go array: %v", result) return result, nil } else { + fromLuaLogger.Debug("Converting Lua table to Go map") result := make(map[string]interface{}) v.ForEach(func(key lua.LValue, value lua.LValue) { converted, _ := FromLua(L, value) result[key.String()] = converted }) + fromLuaLogger.Trace("Converted Go map: %v", result) return result, nil } case lua.LString: + fromLuaLogger.Debug("Converting Lua string to Go string") + fromLuaLogger.Trace("Lua string: %q", string(v)) return string(v), nil case lua.LBool: + fromLuaLogger.Debug("Converting Lua boolean to Go boolean") + fromLuaLogger.Trace("Lua boolean: %t", bool(v)) return bool(v), nil case lua.LNumber: + fromLuaLogger.Debug("Converting Lua number to Go float64") + fromLuaLogger.Trace("Lua number: %f", float64(v)) return float64(v), nil default: + fromLuaLogger.Debug("Unsupported Lua type, returning nil") return nil, nil } } func IsLuaTableArray(L *lua.LState, v *lua.LTable) (bool, error) { - logger.Trace("Checking if Lua table is an array") + isLuaTableArrayLogger := processorLogger.WithPrefix("IsLuaTableArray") + isLuaTableArrayLogger.Debug("Checking if Lua table is an array") + isLuaTableArrayLogger.Trace("Lua table input: %v", v) L.SetGlobal("table_to_check", v) // Use our predefined helper function from InitLuaHelpers err := L.DoString(`is_array = isArray(table_to_check)`) if err != nil { - logger.Error("Error determining if table is an array: %v", err) + isLuaTableArrayLogger.Error("Error determining if table is an array: %v", err) return false, fmt.Errorf("error determining if table is array: %w", err) } @@ -158,13 +113,15 @@ func IsLuaTableArray(L *lua.LState, v *lua.LTable) (bool, error) { isArray := L.GetGlobal("is_array") // LVIsFalse returns true if a given LValue is a nil or false otherwise false. result := !lua.LVIsFalse(isArray) - logger.Trace("Lua table is array: %v", result) + isLuaTableArrayLogger.Debug("Lua table is array: %t", result) + isLuaTableArrayLogger.Trace("isArray result Lua value: %v", isArray) return result, nil } // InitLuaHelpers initializes common Lua helper functions func InitLuaHelpers(L *lua.LState) error { - logger.Debug("Loading Lua helper functions") + initLuaHelpersLogger := processorLogger.WithPrefix("InitLuaHelpers") + initLuaHelpersLogger.Debug("Loading Lua helper functions") helperScript := ` -- Custom Lua helpers for math operations @@ -245,26 +202,21 @@ end modified = false ` if err := L.DoString(helperScript); err != nil { - logger.Error("Failed to load Lua helper functions: %v", err) + initLuaHelpersLogger.Error("Failed to load Lua helper functions: %v", err) return fmt.Errorf("error loading helper functions: %v", err) } + initLuaHelpersLogger.Debug("Lua helper functions loaded") - logger.Debug("Setting up Lua print function to Go") + initLuaHelpersLogger.Debug("Setting up Lua print function to Go") L.SetGlobal("print", L.NewFunction(printToGo)) L.SetGlobal("fetch", L.NewFunction(fetch)) + initLuaHelpersLogger.Debug("Lua print and fetch functions bound to Go") return nil } -// LimitString truncates a string to maxLen and adds "..." if truncated -func LimitString(s string, maxLen int) string { - s = strings.ReplaceAll(s, "\n", "\\n") - if len(s) <= maxLen { - return s - } - return s[:maxLen-3] + "..." -} - func PrependLuaAssignment(luaExpr string) string { + prependLuaAssignmentLogger := processorLogger.WithPrefix("PrependLuaAssignment").WithField("originalLuaExpr", luaExpr) + prependLuaAssignmentLogger.Debug("Prepending Lua assignment if necessary") // Auto-prepend v1 for expressions starting with operators if strings.HasPrefix(luaExpr, "*") || strings.HasPrefix(luaExpr, "/") || @@ -273,30 +225,29 @@ func PrependLuaAssignment(luaExpr string) string { strings.HasPrefix(luaExpr, "^") || strings.HasPrefix(luaExpr, "%") { luaExpr = "v1 = v1" + luaExpr + prependLuaAssignmentLogger.Debug("Prepended 'v1 = v1' due to operator prefix") } else if strings.HasPrefix(luaExpr, "=") { // Handle direct assignment with = operator luaExpr = "v1 " + luaExpr + prependLuaAssignmentLogger.Debug("Prepended 'v1' due to direct assignment operator") } // Add assignment if needed if !strings.Contains(luaExpr, "=") { luaExpr = "v1 = " + luaExpr + prependLuaAssignmentLogger.Debug("Prepended 'v1 =' as no assignment was found") } + prependLuaAssignmentLogger.Trace("Final Lua expression after prepending: %q", luaExpr) return luaExpr } // BuildLuaScript prepares a Lua expression from shorthand notation func BuildLuaScript(luaExpr string) string { - logger.Debug("Building Lua script from expression: %s", luaExpr) + buildLuaScriptLogger := processorLogger.WithPrefix("BuildLuaScript").WithField("inputLuaExpr", luaExpr) + buildLuaScriptLogger.Debug("Building full Lua script from expression") luaExpr = PrependLuaAssignment(luaExpr) - // This allows the user to specify whether or not they modified a value - // If they do nothing we assume they did modify (no return at all) - // If they return before our return then they themselves specify what they did - // If nothing is returned lua assumes nil - // So we can say our value was modified if the return value is either nil or true - // If the return value is false then the user wants to keep the original fullScript := fmt.Sprintf(` function run() %s @@ -304,11 +255,14 @@ func BuildLuaScript(luaExpr string) string { local res = run() modified = res == nil or res `, luaExpr) + buildLuaScriptLogger.Trace("Generated full Lua script: %q", utils.LimitString(fullScript, 200)) return fullScript } func printToGo(L *lua.LState) int { + printToGoLogger := processorLogger.WithPrefix("printToGo") + printToGoLogger.Debug("Lua print function called, redirecting to Go logger") top := L.GetTop() args := make([]interface{}, top) @@ -322,20 +276,26 @@ func printToGo(L *lua.LState) int { parts = append(parts, fmt.Sprintf("%v", arg)) } message := strings.Join(parts, " ") + printToGoLogger.Trace("Lua print message: %q", message) // Use the LUA log level with a script tag logger.Lua("%s", message) + printToGoLogger.Debug("Message logged from Lua") return 0 } func fetch(L *lua.LState) int { + fetchLogger := processorLogger.WithPrefix("fetch") + fetchLogger.Debug("Lua fetch function called") // Get URL from first argument url := L.ToString(1) if url == "" { + fetchLogger.Error("Fetch failed: URL is required") L.Push(lua.LNil) L.Push(lua.LString("URL is required")) return 2 } + fetchLogger.Debug("Fetching URL: %q", url) // Get options from second argument if provided var method string = "GET" @@ -345,30 +305,38 @@ func fetch(L *lua.LState) int { if L.GetTop() > 1 { options := L.ToTable(2) if options != nil { + fetchLogger.Debug("Processing fetch options") // Get method if methodVal := options.RawGetString("method"); methodVal != lua.LNil { method = methodVal.String() + fetchLogger.Trace("Method from options: %q", method) } // Get headers if headersVal := options.RawGetString("headers"); headersVal != lua.LNil { if headersTable, ok := headersVal.(*lua.LTable); ok { + fetchLogger.Trace("Processing headers table") headersTable.ForEach(func(key lua.LValue, value lua.LValue) { headers[key.String()] = value.String() + fetchLogger.Trace("Header: %q = %q", key.String(), value.String()) }) } + fetchLogger.Trace("All headers: %v", headers) } // Get body if bodyVal := options.RawGetString("body"); bodyVal != lua.LNil { body = bodyVal.String() + fetchLogger.Trace("Body from options: %q", utils.LimitString(body, 100)) } } } + fetchLogger.Debug("Fetch request details: Method=%q, URL=%q, BodyLength=%d, Headers=%v", method, url, len(body), headers) // Create HTTP request req, err := http.NewRequest(method, url, strings.NewReader(body)) if err != nil { + fetchLogger.Error("Error creating HTTP request: %v", err) L.Push(lua.LNil) L.Push(lua.LString(fmt.Sprintf("Error creating request: %v", err))) return 2 @@ -378,24 +346,33 @@ func fetch(L *lua.LState) int { for key, value := range headers { req.Header.Set(key, value) } + fetchLogger.Debug("HTTP request created and headers set") + fetchLogger.Trace("HTTP Request: %+v", req) // Make request client := &http.Client{} resp, err := client.Do(req) if err != nil { + fetchLogger.Error("Error making HTTP request: %v", err) L.Push(lua.LNil) L.Push(lua.LString(fmt.Sprintf("Error making request: %v", err))) return 2 } - defer resp.Body.Close() + defer func() { + fetchLogger.Debug("Closing HTTP response body") + resp.Body.Close() + }() + fetchLogger.Debug("HTTP request executed. Status Code: %d", resp.StatusCode) // Read response body bodyBytes, err := io.ReadAll(resp.Body) if err != nil { + fetchLogger.Error("Error reading response body: %v", err) L.Push(lua.LNil) L.Push(lua.LString(fmt.Sprintf("Error reading response: %v", err))) return 2 } + fetchLogger.Trace("Response body length: %d", len(bodyBytes)) // Create response table responseTable := L.NewTable() @@ -403,14 +380,18 @@ func fetch(L *lua.LState) int { responseTable.RawSetString("statusText", lua.LString(resp.Status)) responseTable.RawSetString("ok", lua.LBool(resp.StatusCode >= 200 && resp.StatusCode < 300)) responseTable.RawSetString("body", lua.LString(string(bodyBytes))) + fetchLogger.Debug("Created Lua response table") // Set headers in response headersTable := L.NewTable() for key, values := range resp.Header { headersTable.RawSetString(key, lua.LString(values[0])) + fetchLogger.Trace("Response header: %q = %q", key, values[0]) } responseTable.RawSetString("headers", headersTable) + fetchLogger.Trace("Full response table: %v", responseTable) L.Push(responseTable) + fetchLogger.Debug("Pushed response table to Lua stack") return 1 } diff --git a/processor/regex.go b/processor/regex.go index 23c4552..d1078bb 100644 --- a/processor/regex.go +++ b/processor/regex.go @@ -12,6 +12,9 @@ import ( lua "github.com/yuin/gopher-lua" ) +// regexLogger is a scoped logger for the processor/regex package. +var regexLogger = logger.Default.WithPrefix("processor/regex") + type CaptureGroup struct { Name string Value string @@ -23,52 +26,59 @@ type CaptureGroup struct { // The filename here exists ONLY so we can pass it to the lua environment // It's not used for anything else func ProcessRegex(content string, command utils.ModifyCommand, filename string) ([]utils.ReplaceCommand, error) { - var commands []utils.ReplaceCommand - logger.Trace("Processing regex: %q", command.Regex) + processRegexLogger := regexLogger.WithPrefix("ProcessRegex").WithField("commandName", command.Name).WithField("file", filename) + processRegexLogger.Debug("Starting regex processing for file") + processRegexLogger.Trace("Initial file content length: %d", len(content)) + processRegexLogger.Trace("Command details: %+v", command) + var commands []utils.ReplaceCommand // Start timing the regex processing startTime := time.Now() // We don't HAVE to do this multiple times for a pattern // But it's quick enough for us to not care pattern := resolveRegexPlaceholders(command.Regex) + processRegexLogger.Debug("Resolved regex placeholders. Pattern: %s", pattern) + // I'm not too happy about having to trim regex, we could have meaningful whitespace or newlines // But it's a compromise that allows us to use | in yaml // Otherwise we would have to escape every god damn pair of quotation marks // And a bunch of other shit pattern = strings.TrimSpace(pattern) - logger.Debug("Compiling regex pattern: %s", pattern) + processRegexLogger.Debug("Trimmed regex pattern: %s", pattern) patternCompileStart := time.Now() compiledPattern, err := regexp.Compile(pattern) if err != nil { - logger.Error("Error compiling pattern: %v", err) + processRegexLogger.Error("Error compiling pattern %q: %v", pattern, err) return commands, fmt.Errorf("error compiling pattern: %v", err) } - logger.Debug("Compiled pattern successfully in %v: %s", time.Since(patternCompileStart), pattern) + processRegexLogger.Debug("Compiled pattern successfully in %v", time.Since(patternCompileStart)) // Same here, it's just string concatenation, it won't kill us // More important is that we don't fuck up the command // But we shouldn't be able to since it's passed by value - previous := command.Lua + previousLuaExpr := command.Lua luaExpr := BuildLuaScript(command.Lua) - logger.Debug("Transformed Lua expression: %q → %q", previous, luaExpr) + processRegexLogger.Debug("Transformed Lua expression: %q → %q", previousLuaExpr, luaExpr) + processRegexLogger.Trace("Full Lua script: %q", utils.LimitString(luaExpr, 200)) // Process all regex matches matchFindStart := time.Now() indices := compiledPattern.FindAllStringSubmatchIndex(content, -1) matchFindDuration := time.Since(matchFindStart) - logger.Debug("Found %d matches in content of length %d (search took %v)", + processRegexLogger.Debug("Found %d matches in content of length %d (search took %v)", len(indices), len(content), matchFindDuration) + processRegexLogger.Trace("Match indices: %v", indices) // Log pattern complexity metrics patternComplexity := estimatePatternComplexity(pattern) - logger.Debug("Pattern complexity estimate: %d", patternComplexity) + processRegexLogger.Debug("Pattern complexity estimate: %d", patternComplexity) if len(indices) == 0 { - logger.Warning("No matches found for regex: %q", pattern) - logger.Debug("Total regex processing time: %v", time.Since(startTime)) + processRegexLogger.Warning("No matches found for regex: %q", pattern) + processRegexLogger.Debug("Total regex processing time: %v", time.Since(startTime)) return commands, nil } @@ -77,12 +87,13 @@ func ProcessRegex(content string, command utils.ModifyCommand, filename string) // By going backwards we fuck up all the indices to the end of the file that we don't care about // Because there either aren't any (last match) or they're already modified (subsequent matches) for i, matchIndices := range indices { - logger.Debug("Processing match %d of %d", i+1, len(indices)) - logger.Trace("Match indices: %v (match position %d-%d)", matchIndices, matchIndices[0], matchIndices[1]) + matchLogger := processRegexLogger.WithField("matchNum", i+1) + matchLogger.Debug("Processing match %d of %d", i+1, len(indices)) + matchLogger.Trace("Match indices: %v (match position %d-%d)", matchIndices, matchIndices[0], matchIndices[1]) L, err := NewLuaState() if err != nil { - logger.Error("Error creating Lua state: %v", err) + matchLogger.Error("Error creating Lua state: %v", err) return commands, fmt.Errorf("error creating Lua state: %v", err) } L.SetGlobal("file", lua.LString(filename)) @@ -90,7 +101,7 @@ func ProcessRegex(content string, command utils.ModifyCommand, filename string) // Maybe we want to close them every iteration // We'll leave it as is for now defer L.Close() - logger.Trace("Lua state created successfully for match %d", i+1) + matchLogger.Trace("Lua state created successfully for match %d", i+1) // Why we're doing this whole song and dance of indices is to properly handle empty matches // Plus it's a little cleaner to surgically replace our matches @@ -99,20 +110,17 @@ func ProcessRegex(content string, command utils.ModifyCommand, filename string) // So when we're cutting open the array we say 0:7 + modified + 7:end // As if concatenating in the middle of the array // Plus it supports lookarounds - match := content[matchIndices[0]:matchIndices[1]] - matchPreview := match - if len(match) > 50 { - matchPreview = match[:47] + "..." - } - logger.Trace("Matched content: %q (length: %d)", matchPreview, len(match)) + matchContent := content[matchIndices[0]:matchIndices[1]] + matchPreview := utils.LimitString(matchContent, 50) + matchLogger.Trace("Matched content: %q (length: %d)", matchPreview, len(matchContent)) groups := matchIndices[2:] if len(groups) <= 0 { - logger.Warning("No capture groups found for match %q and regex %q", matchPreview, pattern) + matchLogger.Warning("No capture groups found for match %q and regex %q", matchPreview, pattern) continue } if len(groups)%2 == 1 { - logger.Warning("Invalid number of group indices (%d), should be even: %v", len(groups), groups) + matchLogger.Warning("Invalid number of group indices (%d), should be even: %v", len(groups), groups) continue } @@ -123,11 +131,11 @@ func ProcessRegex(content string, command utils.ModifyCommand, filename string) validGroups++ } } - logger.Debug("Found %d valid capture groups in match", validGroups) + matchLogger.Debug("Found %d valid capture groups in match", validGroups) for _, index := range groups { if index == -1 { - logger.Warning("Negative index encountered in match indices %v. This may indicate an issue with the regex pattern or an empty/optional capture group.", matchIndices) + matchLogger.Warning("Negative index encountered in match indices %v. This may indicate an issue with the regex pattern or an empty/optional capture group.", matchIndices) continue } } @@ -142,6 +150,7 @@ func ProcessRegex(content string, command utils.ModifyCommand, filename string) start := groups[i*2] end := groups[i*2+1] if start == -1 || end == -1 { + matchLogger.Debug("Skipping empty or unmatched capture group #%d (name: %q)", i+1, name) continue } @@ -154,75 +163,80 @@ func ProcessRegex(content string, command utils.ModifyCommand, filename string) // Include name info in log if available if name != "" { - logger.Trace("Capture group '%s': %q (pos %d-%d)", name, value, start, end) + matchLogger.Trace("Capture group '%s': %q (pos %d-%d)", name, value, start, end) } else { - logger.Trace("Capture group #%d: %q (pos %d-%d)", i+1, value, start, end) + matchLogger.Trace("Capture group #%d: %q (pos %d-%d)", i+1, value, start, end) } } // Use the DeduplicateGroups flag to control whether to deduplicate capture groups if !command.NoDedup { - logger.Debug("Deduplicating capture groups as specified in command settings") + matchLogger.Debug("Deduplicating capture groups as specified in command settings") captureGroups = deduplicateGroups(captureGroups) + matchLogger.Trace("Capture groups after deduplication: %v", captureGroups) + } else { + matchLogger.Debug("Skipping deduplication of capture groups (NoDedup is true)") } if err := toLua(L, captureGroups); err != nil { - logger.Error("Failed to set Lua variables: %v", err) + matchLogger.Error("Failed to set Lua variables for capture groups: %v", err) continue } - logger.Trace("Set %d capture groups as Lua variables", len(captureGroups)) + matchLogger.Debug("Set %d capture groups as Lua variables", len(captureGroups)) + matchLogger.Trace("Lua globals set for capture groups") if err := L.DoString(luaExpr); err != nil { - logger.Error("Lua script execution failed: %v\nScript: %s\nCapture Groups: %+v", - err, luaExpr, captureGroups) + matchLogger.Error("Lua script execution failed: %v\nScript: %s\nCapture Groups: %+v", + err, utils.LimitString(luaExpr, 200), captureGroups) continue } - logger.Trace("Lua script executed successfully") + matchLogger.Debug("Lua script executed successfully") // Get modifications from Lua - captureGroups, err = fromLua(L, captureGroups) + updatedCaptureGroups, err := fromLua(L, captureGroups) if err != nil { - logger.Error("Failed to retrieve modifications from Lua: %v", err) + matchLogger.Error("Failed to retrieve modifications from Lua: %v", err) continue } - logger.Trace("Retrieved updated values from Lua") + matchLogger.Debug("Retrieved updated values from Lua") + matchLogger.Trace("Updated capture groups from Lua: %v", updatedCaptureGroups) replacement := "" replacementVar := L.GetGlobal("replacement") if replacementVar.Type() != lua.LTNil { replacement = replacementVar.String() - logger.Debug("Using global replacement: %q", replacement) + matchLogger.Debug("Using global replacement variable from Lua: %q", replacement) } // Check if modification flag is set modifiedVal := L.GetGlobal("modified") if modifiedVal.Type() != lua.LTBool || !lua.LVAsBool(modifiedVal) { - logger.Debug("Skipping match - no modifications made by Lua script") + matchLogger.Debug("Skipping match - no modifications indicated by Lua script") continue } if replacement == "" { // Apply the modifications to the original match - replacement = match + replacement = matchContent // Count groups that were actually modified - modifiedGroups := 0 - for _, capture := range captureGroups { + modifiedGroupsCount := 0 + for _, capture := range updatedCaptureGroups { if capture.Value != capture.Updated { - modifiedGroups++ + modifiedGroupsCount++ } } - logger.Info("%d of %d capture groups identified for modification", modifiedGroups, len(captureGroups)) + matchLogger.Info("%d of %d capture groups identified for modification", modifiedGroupsCount, len(updatedCaptureGroups)) - for _, capture := range captureGroups { + for _, capture := range updatedCaptureGroups { if capture.Value == capture.Updated { - logger.Info("Capture group unchanged: %s", LimitString(capture.Value, 50)) + matchLogger.Debug("Capture group unchanged: %s", utils.LimitString(capture.Value, 50)) continue } // Log what changed with context - logger.Debug("Capture group %s scheduled for modification: %q → %q", - capture.Name, capture.Value, capture.Updated) + matchLogger.Debug("Capture group %q scheduled for modification: %q → %q", + capture.Name, utils.LimitString(capture.Value, 50), utils.LimitString(capture.Updated, 50)) // Indices of the group are relative to content // To relate them to match we have to subtract the match start index @@ -232,42 +246,57 @@ func ProcessRegex(content string, command utils.ModifyCommand, filename string) To: capture.Range[1], With: capture.Updated, }) + matchLogger.Trace("Added replacement command: %+v", commands[len(commands)-1]) } } else { + matchLogger.Debug("Using full replacement string from Lua: %q", utils.LimitString(replacement, 50)) commands = append(commands, utils.ReplaceCommand{ From: matchIndices[0], To: matchIndices[1], With: replacement, }) + matchLogger.Trace("Added full replacement command: %+v", commands[len(commands)-1]) } } - logger.Debug("Total regex processing time: %v", time.Since(startTime)) + processRegexLogger.Debug("Total regex processing time: %v", time.Since(startTime)) + processRegexLogger.Debug("Generated %d total modifications", len(commands)) return commands, nil } func deduplicateGroups(captureGroups []*CaptureGroup) []*CaptureGroup { - deduplicatedGroups := make([]*CaptureGroup, 0) + deduplicateGroupsLogger := regexLogger.WithPrefix("deduplicateGroups") + deduplicateGroupsLogger.Debug("Starting deduplication of capture groups") + deduplicateGroupsLogger.Trace("Input capture groups: %v", captureGroups) + + // Preserve input order and drop any group that overlaps with an already accepted group + accepted := make([]*CaptureGroup, 0, len(captureGroups)) for _, group := range captureGroups { + groupLogger := deduplicateGroupsLogger.WithField("groupName", group.Name).WithField("groupRange", group.Range) + groupLogger.Debug("Processing capture group") + overlaps := false - logger.Debug("Checking capture group: %s with range %v", group.Name, group.Range) - for _, existingGroup := range deduplicatedGroups { - logger.Debug("Comparing with existing group: %s with range %v", existingGroup.Name, existingGroup.Range) - if group.Range[0] < existingGroup.Range[1] && group.Range[1] > existingGroup.Range[0] { + for _, kept := range accepted { + // Overlap if start < keptEnd and end > keptStart (adjacent is allowed) + if group.Range[0] < kept.Range[1] && group.Range[1] > kept.Range[0] { overlaps = true - logger.Warning("Detected overlap between capture group '%s' and existing group '%s' in range %v-%v and %v-%v", group.Name, existingGroup.Name, group.Range[0], group.Range[1], existingGroup.Range[0], existingGroup.Range[1]) break } } + if overlaps { - // We CAN just continue despite this fuckup - logger.Warning("Overlapping capture group: %s", group.Name) + groupLogger.Warning("Overlapping capture group detected and skipped.") continue } - logger.Debug("No overlap detected for capture group: %s. Adding to deduplicated groups.", group.Name) - deduplicatedGroups = append(deduplicatedGroups, group) + + groupLogger.Debug("Capture group does not overlap with previously accepted groups. Adding.") + accepted = append(accepted, group) } - return deduplicatedGroups + + deduplicateGroupsLogger.Debug("Finished deduplication. Original %d groups, %d deduplicated.", len(captureGroups), len(accepted)) + deduplicateGroupsLogger.Trace("Deduplicated groups: %v", accepted) + + return accepted } // The order of these replaces is important @@ -276,105 +305,183 @@ func deduplicateGroups(captureGroups []*CaptureGroup) []*CaptureGroup { // Expand to another capture group in the capture group // We really only want one (our named) capture group func resolveRegexPlaceholders(pattern string) string { + resolveLogger := regexLogger.WithPrefix("resolveRegexPlaceholders").WithField("originalPattern", utils.LimitString(pattern, 100)) + resolveLogger.Debug("Resolving regex placeholders in pattern") + // Handle special pattern modifications if !strings.HasPrefix(pattern, "(?s)") { pattern = "(?s)" + pattern + resolveLogger.Debug("Prepended '(?s)' to pattern for single-line mode") } namedGroupNum := regexp.MustCompile(`(?:(\?<[^>]+>)(!num))`) pattern = namedGroupNum.ReplaceAllStringFunc(pattern, func(match string) string { + funcLogger := resolveLogger.WithPrefix("namedGroupNumReplace").WithField("match", utils.LimitString(match, 50)) + funcLogger.Debug("Processing named group !num placeholder") parts := namedGroupNum.FindStringSubmatch(match) if len(parts) != 3 { + funcLogger.Warning("Unexpected number of submatches for namedGroupNum: %d. Returning original match.", len(parts)) return match } replacement := `-?\d*\.?\d+` + funcLogger.Trace("Replacing !num in named group with: %q", replacement) return parts[1] + replacement }) + resolveLogger.Debug("Handled named group !num placeholders") + pattern = strings.ReplaceAll(pattern, "!num", `(-?\d*\.?\d+)`) + resolveLogger.Debug("Replaced !num with numeric capture group") + pattern = strings.ReplaceAll(pattern, "!any", `.*?`) + resolveLogger.Debug("Replaced !any with non-greedy wildcard") + repPattern := regexp.MustCompile(`!rep\(([^,]+),\s*(\d+)\)`) // !rep(pattern, count) repeats the pattern n times // Inserting !any between each repetition pattern = repPattern.ReplaceAllStringFunc(pattern, func(match string) string { + funcLogger := resolveLogger.WithPrefix("repPatternReplace").WithField("match", utils.LimitString(match, 50)) + funcLogger.Debug("Processing !rep placeholder") parts := repPattern.FindStringSubmatch(match) if len(parts) != 3 { + funcLogger.Warning("Unexpected number of submatches for repPattern: %d. Returning original match.", len(parts)) return match } repeatedPattern := parts[1] - count := parts[2] - repetitions, _ := strconv.Atoi(count) - return strings.Repeat(repeatedPattern+".*?", repetitions-1) + repeatedPattern + countStr := parts[2] + repetitions, err := strconv.Atoi(countStr) + if err != nil { + funcLogger.Error("Failed to parse repetition count %q: %v. Returning original match.", countStr, err) + return match + } + + var finalReplacement string + if repetitions > 0 { + finalReplacement = strings.Repeat(repeatedPattern+".*?", repetitions-1) + repeatedPattern + } else { + finalReplacement = "" + } + + funcLogger.Trace("Replaced !rep with %d repetitions of %q: %q", repetitions, utils.LimitString(repeatedPattern, 30), utils.LimitString(finalReplacement, 100)) + return finalReplacement }) + resolveLogger.Debug("Handled !rep placeholders") + + resolveLogger.Debug("Finished resolving regex placeholders") + resolveLogger.Trace("Final resolved pattern: %q", utils.LimitString(pattern, 100)) return pattern } // ToLua sets capture groups as Lua variables (v1, v2, etc. for numeric values and s1, s2, etc. for strings) func toLua(L *lua.LState, data interface{}) error { + toLuaLogger := regexLogger.WithPrefix("toLua") + toLuaLogger.Debug("Setting capture groups as Lua variables") + captureGroups, ok := data.([]*CaptureGroup) if !ok { + toLuaLogger.Error("Invalid data type for toLua. Expected []*CaptureGroup, got %T", data) return fmt.Errorf("expected []*CaptureGroup for captures, got %T", data) } + toLuaLogger.Trace("Input capture groups: %v", captureGroups) groupindex := 0 for _, capture := range captureGroups { + groupLogger := toLuaLogger.WithField("captureGroup", capture.Name).WithField("value", utils.LimitString(capture.Value, 50)) + groupLogger.Debug("Processing capture group for Lua") + if capture.Name == "" { // We don't want to change the name of the capture group // Even if it's empty tempName := fmt.Sprintf("%d", groupindex+1) groupindex++ + groupLogger.Debug("Unnamed capture group, assigning temporary name: %q", tempName) L.SetGlobal("s"+tempName, lua.LString(capture.Value)) + groupLogger.Trace("Set Lua global s%s = %q", tempName, capture.Value) val, err := strconv.ParseFloat(capture.Value, 64) if err == nil { L.SetGlobal("v"+tempName, lua.LNumber(val)) + groupLogger.Trace("Set Lua global v%s = %f", tempName, val) + } else { + groupLogger.Trace("Value %q is not numeric, skipping v%s assignment", capture.Value, tempName) } } else { val, err := strconv.ParseFloat(capture.Value, 64) if err == nil { L.SetGlobal(capture.Name, lua.LNumber(val)) + groupLogger.Trace("Set Lua global %s = %f (numeric)", capture.Name, val) } else { L.SetGlobal(capture.Name, lua.LString(capture.Value)) + groupLogger.Trace("Set Lua global %s = %q (string)", capture.Name, capture.Value) } } } + toLuaLogger.Debug("Finished setting capture groups as Lua variables") return nil } // FromLua implements the Processor interface for RegexProcessor func fromLua(L *lua.LState, captureGroups []*CaptureGroup) ([]*CaptureGroup, error) { + fromLuaLogger := regexLogger.WithPrefix("fromLua") + fromLuaLogger.Debug("Retrieving modifications from Lua for capture groups") + fromLuaLogger.Trace("Initial capture groups: %v", captureGroups) + captureIndex := 0 for _, capture := range captureGroups { - if capture.Name == "" { - capture.Name = fmt.Sprintf("%d", captureIndex+1) + groupLogger := fromLuaLogger.WithField("originalCaptureName", capture.Name).WithField("originalValue", utils.LimitString(capture.Value, 50)) + groupLogger.Debug("Processing capture group to retrieve updated value") - vVarName := fmt.Sprintf("v%s", capture.Name) - sVarName := fmt.Sprintf("s%s", capture.Name) + if capture.Name == "" { + // This case means it was an unnamed capture group originally. + // We need to reconstruct the original temporary name to fetch its updated value. + // The name will be set to an integer if it was empty, then incremented. + // So, we use the captureIndex to get the correct 'vX' and 'sX' variables. + tempName := fmt.Sprintf("%d", captureIndex+1) + groupLogger.Debug("Retrieving updated value for unnamed group (temp name: %q)", tempName) + + vVarName := fmt.Sprintf("v%s", tempName) + sVarName := fmt.Sprintf("s%s", tempName) captureIndex++ vLuaVal := L.GetGlobal(vVarName) sLuaVal := L.GetGlobal(sVarName) + groupLogger.Trace("Lua values for unnamed group: v=%v, s=%v", vLuaVal, sLuaVal) + if sLuaVal.Type() == lua.LTString { capture.Updated = sLuaVal.String() + groupLogger.Trace("Updated value from s%s (string): %q", tempName, capture.Updated) } // Numbers have priority if vLuaVal.Type() == lua.LTNumber { capture.Updated = vLuaVal.String() + groupLogger.Trace("Updated value from v%s (numeric): %q", tempName, capture.Updated) } } else { - // Easy shit - capture.Updated = L.GetGlobal(capture.Name).String() + // Easy shit, directly use the named capture group + updatedValue := L.GetGlobal(capture.Name) + if updatedValue.Type() != lua.LTNil { + capture.Updated = updatedValue.String() + groupLogger.Trace("Updated value for named group %q: %q", capture.Name, capture.Updated) + } else { + groupLogger.Debug("Named capture group %q not found in Lua globals or is nil. Keeping original value.", capture.Name) + capture.Updated = capture.Value // Keep original if not found or nil + } } + groupLogger.Debug("Finished processing capture group. Original: %q, Updated: %q", utils.LimitString(capture.Value, 50), utils.LimitString(capture.Updated, 50)) } + fromLuaLogger.Debug("Finished retrieving modifications from Lua") + fromLuaLogger.Trace("Final updated capture groups: %v", captureGroups) return captureGroups, nil } // estimatePatternComplexity gives a rough estimate of regex pattern complexity // This can help identify potentially problematic patterns func estimatePatternComplexity(pattern string) int { + estimateComplexityLogger := regexLogger.WithPrefix("estimatePatternComplexity").WithField("pattern", utils.LimitString(pattern, 100)) + estimateComplexityLogger.Debug("Estimating regex pattern complexity") complexity := len(pattern) // Add complexity for potentially expensive operations @@ -387,5 +494,6 @@ func estimatePatternComplexity(pattern string) int { complexity += strings.Count(pattern, "\\1") * 3 // Backreferences complexity += strings.Count(pattern, "{") * 2 // Counted repetition + estimateComplexityLogger.Debug("Estimated pattern complexity: %d", complexity) return complexity } diff --git a/utils/db.go b/utils/db.go index 1c67b1e..ee77729 100644 --- a/utils/db.go +++ b/utils/db.go @@ -1,15 +1,17 @@ package utils import ( - "fmt" "path/filepath" "time" - "git.site.quack-lab.dev/dave/cylogger" + logger "git.site.quack-lab.dev/dave/cylogger" "gorm.io/driver/sqlite" "gorm.io/gorm" ) +// dbLogger is a scoped logger for the utils/db package. +var dbLogger = logger.Default.WithPrefix("utils/db") + type DB interface { DB() *gorm.DB Raw(sql string, args ...any) *gorm.DB @@ -29,92 +31,125 @@ type DBWrapper struct { db *gorm.DB } -var db *DBWrapper +var globalDB *DBWrapper func GetDB() (DB, error) { + getDBLogger := dbLogger.WithPrefix("GetDB") + getDBLogger.Debug("Attempting to get database connection") var err error dbFile := filepath.Join("data.sqlite") + getDBLogger.Debug("Opening database file: %q", dbFile) db, err := gorm.Open(sqlite.Open(dbFile), &gorm.Config{ // SkipDefaultTransaction: true, PrepareStmt: true, // Logger: gormlogger.Default.LogMode(gormlogger.Silent), }) if err != nil { + getDBLogger.Error("Failed to open database: %v", err) return nil, err } - db.AutoMigrate(&FileSnapshot{}) + getDBLogger.Debug("Database opened successfully, running auto migration") + if err := db.AutoMigrate(&FileSnapshot{}); err != nil { + getDBLogger.Error("Auto migration failed: %v", err) + return nil, err + } + getDBLogger.Debug("Auto migration completed") - return &DBWrapper{db: db}, nil + globalDB = &DBWrapper{db: db} + getDBLogger.Debug("Database wrapper initialized") + return globalDB, nil } // Just a wrapper func (db *DBWrapper) Raw(sql string, args ...any) *gorm.DB { + rawLogger := dbLogger.WithPrefix("Raw").WithField("sql", sql) + rawLogger.Debug("Executing raw SQL query with args: %v", args) return db.db.Raw(sql, args...) } func (db *DBWrapper) DB() *gorm.DB { + dbLogger.WithPrefix("DB").Debug("Returning GORM DB instance") return db.db } func (db *DBWrapper) FileExists(filePath string) (bool, error) { + fileExistsLogger := dbLogger.WithPrefix("FileExists").WithField("filePath", filePath) + fileExistsLogger.Debug("Checking if file exists in database") var count int64 err := db.db.Model(&FileSnapshot{}).Where("file_path = ?", filePath).Count(&count).Error + if err != nil { + fileExistsLogger.Error("Error checking if file exists: %v", err) + return false, err + } + fileExistsLogger.Debug("File exists: %t", count > 0) return count > 0, err } func (db *DBWrapper) SaveFile(filePath string, fileData []byte) error { - log := cylogger.Default.WithPrefix(fmt.Sprintf("SaveFile: %q", filePath)) + saveFileLogger := dbLogger.WithPrefix("SaveFile").WithField("filePath", filePath) + saveFileLogger.Debug("Attempting to save file to database") + saveFileLogger.Trace("File data length: %d", len(fileData)) + exists, err := db.FileExists(filePath) if err != nil { - log.Error("Error checking if file exists: %v", err) + saveFileLogger.Error("Error checking if file exists: %v", err) return err } - log.Debug("File exists: %t", exists) - // Nothing to do, file already exists if exists { - log.Debug("File already exists, skipping save") + saveFileLogger.Debug("File already exists, skipping save") return nil } - log.Debug("Saving file to database") - return db.db.Create(&FileSnapshot{ + saveFileLogger.Debug("Creating new file snapshot in database") + err = db.db.Create(&FileSnapshot{ Date: time.Now(), FilePath: filePath, FileData: fileData, }).Error + if err != nil { + saveFileLogger.Error("Failed to create file snapshot: %v", err) + } else { + saveFileLogger.Debug("File saved successfully to database") + } + return err } func (db *DBWrapper) GetFile(filePath string) ([]byte, error) { - log := cylogger.Default.WithPrefix(fmt.Sprintf("GetFile: %q", filePath)) - log.Debug("Getting file from database") + getFileLogger := dbLogger.WithPrefix("GetFile").WithField("filePath", filePath) + getFileLogger.Debug("Getting file from database") var fileSnapshot FileSnapshot err := db.db.Model(&FileSnapshot{}).Where("file_path = ?", filePath).First(&fileSnapshot).Error if err != nil { + getFileLogger.Error("Failed to get file from database: %v", err) return nil, err } - log.Debug("File found in database") + getFileLogger.Debug("File found in database") + getFileLogger.Trace("Retrieved file data length: %d", len(fileSnapshot.FileData)) return fileSnapshot.FileData, nil } func (db *DBWrapper) GetAllFiles() ([]FileSnapshot, error) { - log := cylogger.Default.WithPrefix("GetAllFiles") - log.Debug("Getting all files from database") + getAllFilesLogger := dbLogger.WithPrefix("GetAllFiles") + getAllFilesLogger.Debug("Getting all files from database") var fileSnapshots []FileSnapshot err := db.db.Model(&FileSnapshot{}).Find(&fileSnapshots).Error if err != nil { + getAllFilesLogger.Error("Failed to get all files from database: %v", err) return nil, err } - log.Debug("Found %d files in database", len(fileSnapshots)) + getAllFilesLogger.Debug("Found %d files in database", len(fileSnapshots)) + getAllFilesLogger.Trace("File snapshots retrieved: %v", fileSnapshots) return fileSnapshots, nil } func (db *DBWrapper) RemoveAllFiles() error { - log := cylogger.Default.WithPrefix("RemoveAllFiles") - log.Debug("Removing all files from database") + removeAllFilesLogger := dbLogger.WithPrefix("RemoveAllFiles") + removeAllFilesLogger.Debug("Removing all files from database") err := db.db.Exec("DELETE FROM file_snapshots").Error if err != nil { - return err + removeAllFilesLogger.Error("Failed to remove all files from database: %v", err) + } else { + removeAllFilesLogger.Debug("All files removed from database") } - log.Debug("All files removed from database") - return nil + return err } diff --git a/utils/file.go b/utils/file.go index d386cc2..2da933c 100644 --- a/utils/file.go +++ b/utils/file.go @@ -1,96 +1,142 @@ package utils import ( - "fmt" "os" "path/filepath" + "strconv" "strings" - "git.site.quack-lab.dev/dave/cylogger" + logger "git.site.quack-lab.dev/dave/cylogger" ) +// fileLogger is a scoped logger for the utils/file package. +var fileLogger = logger.Default.WithPrefix("utils/file") + func CleanPath(path string) string { - log := cylogger.Default.WithPrefix(fmt.Sprintf("CleanPath: %q", path)) - log.Trace("Start") + cleanPathLogger := fileLogger.WithPrefix("CleanPath") + cleanPathLogger.Debug("Cleaning path: %q", path) + cleanPathLogger.Trace("Original path: %q", path) path = filepath.Clean(path) path = strings.ReplaceAll(path, "\\", "/") - log.Trace("Done: %q", path) + cleanPathLogger.Trace("Cleaned path result: %q", path) return path } func ToAbs(path string) string { - log := cylogger.Default.WithPrefix(fmt.Sprintf("ToAbs: %q", path)) - log.Trace("Start") + toAbsLogger := fileLogger.WithPrefix("ToAbs") + toAbsLogger.Debug("Converting path to absolute: %q", path) + toAbsLogger.Trace("Input path: %q", path) if filepath.IsAbs(path) { - log.Trace("Path is already absolute: %q", path) - return CleanPath(path) + toAbsLogger.Debug("Path is already absolute, cleaning it.") + cleanedPath := CleanPath(path) + toAbsLogger.Trace("Already absolute path after cleaning: %q", cleanedPath) + return cleanedPath } cwd, err := os.Getwd() if err != nil { - log.Error("Error getting cwd: %v", err) + toAbsLogger.Error("Error getting current working directory: %v", err) return CleanPath(path) } - log.Trace("Cwd: %q", cwd) - return CleanPath(filepath.Join(cwd, path)) + toAbsLogger.Trace("Current working directory: %q", cwd) + cleanedPath := CleanPath(filepath.Join(cwd, path)) + toAbsLogger.Trace("Converted absolute path result: %q", cleanedPath) + return cleanedPath +} + +// LimitString truncates a string to maxLen and adds "..." if truncated +func LimitString(s string, maxLen int) string { + limitStringLogger := fileLogger.WithPrefix("LimitString").WithField("originalLength", len(s)).WithField("maxLength", maxLen) + limitStringLogger.Debug("Limiting string length") + s = strings.ReplaceAll(s, "\n", "\\n") + if len(s) <= maxLen { + limitStringLogger.Trace("String length (%d) is within max length (%d), no truncation", len(s), maxLen) + return s + } + limited := s[:maxLen-3] + "..." + limitStringLogger.Trace("String truncated from %d to %d characters: %q", len(s), len(limited), limited) + return limited +} + +// StrToFloat converts a string to a float64, returning 0 on error. +func StrToFloat(s string) float64 { + strToFloatLogger := fileLogger.WithPrefix("StrToFloat").WithField("inputString", s) + strToFloatLogger.Debug("Attempting to convert string to float") + f, err := strconv.ParseFloat(s, 64) + if err != nil { + strToFloatLogger.Warning("Failed to convert string %q to float, returning 0: %v", s, err) + return 0 + } + strToFloatLogger.Trace("Successfully converted %q to float: %f", s, f) + return f } func ResetWhereNecessary(associations map[string]FileCommandAssociation, db DB) error { - log := cylogger.Default.WithPrefix("ResetWhereNecessary") - log.Debug("Start") + resetWhereNecessaryLogger := fileLogger.WithPrefix("ResetWhereNecessary") + resetWhereNecessaryLogger.Debug("Starting reset where necessary operation") + resetWhereNecessaryLogger.Trace("File-command associations input: %v", associations) dirtyFiles := make(map[string]struct{}) for _, association := range associations { + resetWhereNecessaryLogger.Debug("Processing association for file: %q", association.File) for _, command := range association.Commands { - log.Debug("Checking command %q for file %q", command.Name, association.File) + resetWhereNecessaryLogger.Debug("Checking command %q for reset requirement", command.Name) + resetWhereNecessaryLogger.Trace("Command details: %v", command) if command.Reset { - log.Debug("Command %q requires reset for file %q", command.Name, association.File) + resetWhereNecessaryLogger.Debug("Command %q requires reset for file %q, marking as dirty", command.Name, association.File) dirtyFiles[association.File] = struct{}{} } } for _, command := range association.IsolateCommands { - log.Debug("Checking isolate command %q for file %q", command.Name, association.File) + resetWhereNecessaryLogger.Debug("Checking isolate command %q for reset requirement", command.Name) + resetWhereNecessaryLogger.Trace("Isolate command details: %v", command) if command.Reset { - log.Debug("Isolate command %q requires reset for file %q", command.Name, association.File) + resetWhereNecessaryLogger.Debug("Isolate command %q requires reset for file %q, marking as dirty", command.Name, association.File) dirtyFiles[association.File] = struct{}{} } } } - log.Debug("Dirty files: %v", dirtyFiles) + resetWhereNecessaryLogger.Debug("Identified %d files that need to be reset", len(dirtyFiles)) + resetWhereNecessaryLogger.Trace("Dirty files identified: %v", dirtyFiles) + for file := range dirtyFiles { - log.Debug("Resetting file %q", file) + resetWhereNecessaryLogger.Debug("Resetting file %q", file) fileData, err := db.GetFile(file) if err != nil { - log.Warning("Failed to get file %q: %v", file, err) + resetWhereNecessaryLogger.Warning("Failed to get original content for file %q from database: %v", file, err) continue } - log.Debug("Writing file %q to disk", file) + resetWhereNecessaryLogger.Trace("Retrieved original file data length for %q: %d", file, len(fileData)) + resetWhereNecessaryLogger.Debug("Writing original content back to file %q", file) err = os.WriteFile(file, fileData, 0644) if err != nil { - log.Warning("Failed to write file %q: %v", file, err) + resetWhereNecessaryLogger.Warning("Failed to write original content back to file %q: %v", file, err) continue } - log.Debug("File %q written to disk", file) + resetWhereNecessaryLogger.Debug("Successfully reset file %q", file) } - log.Debug("Done") + resetWhereNecessaryLogger.Debug("Finished reset where necessary operation") return nil } func ResetAllFiles(db DB) error { - log := cylogger.Default.WithPrefix("ResetAllFiles") - log.Debug("Start") + resetAllFilesLogger := fileLogger.WithPrefix("ResetAllFiles") + resetAllFilesLogger.Debug("Starting reset all files operation") fileSnapshots, err := db.GetAllFiles() if err != nil { + resetAllFilesLogger.Error("Failed to get all file snapshots from database: %v", err) return err } - log.Debug("Found %d files in database", len(fileSnapshots)) + resetAllFilesLogger.Debug("Found %d files in database to reset", len(fileSnapshots)) + resetAllFilesLogger.Trace("File snapshots retrieved: %v", fileSnapshots) + for _, fileSnapshot := range fileSnapshots { - log.Debug("Resetting file %q", fileSnapshot.FilePath) + resetAllFilesLogger.Debug("Resetting file %q", fileSnapshot.FilePath) err = os.WriteFile(fileSnapshot.FilePath, fileSnapshot.FileData, 0644) if err != nil { - log.Warning("Failed to write file %q: %v", fileSnapshot.FilePath, err) + resetAllFilesLogger.Warning("Failed to write file %q to disk: %v", fileSnapshot.FilePath, err) continue } - log.Debug("File %q written to disk", fileSnapshot.FilePath) + resetAllFilesLogger.Debug("File %q written to disk successfully", fileSnapshot.FilePath) } - log.Debug("Done") + resetAllFilesLogger.Debug("Finished reset all files operation") return nil } diff --git a/utils/flags.go b/utils/flags.go index 1849a17..d76d56f 100644 --- a/utils/flags.go +++ b/utils/flags.go @@ -2,9 +2,19 @@ package utils import ( "flag" + + logger "git.site.quack-lab.dev/dave/cylogger" ) +// flagsLogger is a scoped logger for the utils/flags package. +var flagsLogger = logger.Default.WithPrefix("utils/flags") + var ( ParallelFiles = flag.Int("P", 100, "Number of files to process in parallel") Filter = flag.String("f", "", "Filter commands before running them") ) + +func init() { + flagsLogger.Debug("Initializing flags") + flagsLogger.Trace("ParallelFiles initial value: %d, Filter initial value: %q", *ParallelFiles, *Filter) +} diff --git a/utils/modifycommand.go b/utils/modifycommand.go index 4503edd..44a7ac7 100644 --- a/utils/modifycommand.go +++ b/utils/modifycommand.go @@ -11,6 +11,9 @@ import ( "gopkg.in/yaml.v3" ) +// modifyCommandLogger is a scoped logger for the utils/modifycommand package. +var modifyCommandLogger = logger.Default.WithPrefix("utils/modifycommand") + type ModifyCommand struct { Name string `yaml:"name"` Regex string `yaml:"regex"` @@ -22,21 +25,29 @@ type ModifyCommand struct { NoDedup bool `yaml:"nodedup"` Disabled bool `yaml:"disable"` } + type CookFile []ModifyCommand func (c *ModifyCommand) Validate() error { + validateLogger := modifyCommandLogger.WithPrefix("Validate").WithField("commandName", c.Name) + validateLogger.Debug("Validating command") if c.Regex == "" { + validateLogger.Error("Validation failed: Regex pattern is required") return fmt.Errorf("pattern is required") } if c.Lua == "" { + validateLogger.Error("Validation failed: Lua expression is required") return fmt.Errorf("lua expression is required") } if len(c.Files) == 0 { + validateLogger.Error("Validation failed: At least one file is required") return fmt.Errorf("at least one file is required") } if c.LogLevel == "" { + validateLogger.Debug("LogLevel not specified, defaulting to INFO") c.LogLevel = "INFO" } + validateLogger.Debug("Command validated successfully") return nil } @@ -44,34 +55,47 @@ func (c *ModifyCommand) Validate() error { var matchesMemoTable map[string]bool = make(map[string]bool) func Matches(path string, glob string) (bool, error) { + matchesLogger := modifyCommandLogger.WithPrefix("Matches").WithField("path", path).WithField("glob", glob) + matchesLogger.Debug("Checking if path matches glob") key := fmt.Sprintf("%s:%s", path, glob) if matches, ok := matchesMemoTable[key]; ok { - logger.Debug("Found match for file %q and glob %q in memo table", path, glob) + matchesLogger.Debug("Found match in memo table: %t", matches) return matches, nil } matches, err := doublestar.Match(glob, path) if err != nil { + matchesLogger.Error("Failed to match glob: %v", err) return false, fmt.Errorf("failed to match glob %s with file %s: %w", glob, path, err) } matchesMemoTable[key] = matches + matchesLogger.Debug("Match result: %t, storing in memo table", matches) return matches, nil } func SplitPattern(pattern string) (string, string) { + splitPatternLogger := modifyCommandLogger.WithPrefix("SplitPattern").WithField("pattern", pattern) + splitPatternLogger.Debug("Splitting pattern") + splitPatternLogger.Trace("Original pattern: %q", pattern) static, pattern := doublestar.SplitPattern(pattern) cwd, err := os.Getwd() if err != nil { + splitPatternLogger.Error("Error getting current working directory: %v", err) return "", "" } + splitPatternLogger.Trace("Current working directory: %q", cwd) if static == "" { + splitPatternLogger.Debug("Static part is empty, defaulting to current working directory") static = cwd } if !filepath.IsAbs(static) { + splitPatternLogger.Debug("Static part is not absolute, joining with current working directory") static = filepath.Join(cwd, static) static = filepath.Clean(static) + splitPatternLogger.Trace("Static path after joining and cleaning: %q", static) } static = strings.ReplaceAll(static, "\\", "/") + splitPatternLogger.Trace("Final static path: %q, Remaining pattern: %q", static, pattern) return static, pattern } @@ -82,180 +106,262 @@ type FileCommandAssociation struct { } func AssociateFilesWithCommands(files []string, commands []ModifyCommand) (map[string]FileCommandAssociation, error) { + associateFilesLogger := modifyCommandLogger.WithPrefix("AssociateFilesWithCommands") + associateFilesLogger.Debug("Associating files with commands") + associateFilesLogger.Trace("Input files: %v", files) + associateFilesLogger.Trace("Input commands: %v", commands) associationCount := 0 fileCommands := make(map[string]FileCommandAssociation) for _, file := range files { file = strings.ReplaceAll(file, "\\", "/") + associateFilesLogger.Debug("Processing file: %q", file) fileCommands[file] = FileCommandAssociation{ File: file, IsolateCommands: []ModifyCommand{}, Commands: []ModifyCommand{}, } for _, command := range commands { + associateFilesLogger.Debug("Checking command %q for file %q", command.Name, file) for _, glob := range command.Files { glob = strings.ReplaceAll(glob, "\\", "/") static, pattern := SplitPattern(glob) - patternFile := strings.Replace(file, static+`/`, "", 1) + associateFilesLogger.Trace("Glob parts for %q → static=%q pattern=%q", glob, static, pattern) + + // Build absolute path for the current file to compare with static + cwd, err := os.Getwd() + if err != nil { + associateFilesLogger.Warning("Failed to get CWD when matching %q for file %q: %v", glob, file, err) + continue + } + var absFile string + if filepath.IsAbs(file) { + absFile = filepath.Clean(file) + } else { + absFile = filepath.Clean(filepath.Join(cwd, file)) + } + absFile = strings.ReplaceAll(absFile, "\\", "/") + associateFilesLogger.Trace("Absolute file path resolved for matching: %q", absFile) + + // Only match if the file is under the static root + if !(strings.HasPrefix(absFile, static+"/") || absFile == static) { + associateFilesLogger.Trace("Skipping glob %q for file %q because file is outside static root %q", glob, file, static) + continue + } + + patternFile := strings.TrimPrefix(absFile, static+`/`) + associateFilesLogger.Trace("Pattern-relative path used for match: %q", patternFile) matches, err := Matches(patternFile, pattern) if err != nil { - logger.Trace("Failed to match glob %s with file %s: %v", glob, file, err) + associateFilesLogger.Warning("Failed to match glob %q with file %q: %v", glob, file, err) continue } if matches { - logger.Debug("Found match for file %q and command %q", file, command.Regex) + associateFilesLogger.Debug("File %q matches glob %q. Associating with command %q", file, glob, command.Name) association := fileCommands[file] if command.Isolate { + associateFilesLogger.Debug("Command %q is an isolate command, adding to isolate list", command.Name) association.IsolateCommands = append(association.IsolateCommands, command) } else { + associateFilesLogger.Debug("Command %q is a regular command, adding to regular list", command.Name) association.Commands = append(association.Commands, command) } fileCommands[file] = association associationCount++ + } else { + associateFilesLogger.Trace("File %q did not match glob %q (pattern=%q, rel=%q)", file, glob, pattern, patternFile) } } } - logger.Debug("Found %d commands for file %q", len(fileCommands[file].Commands), file) - if len(fileCommands[file].Commands) == 0 { - logger.Info("No commands found for file %q", file) - } - if len(fileCommands[file].IsolateCommands) > 0 { - logger.Info("Found %d isolate commands for file %q", len(fileCommands[file].IsolateCommands), file) - } + currentFileCommands := fileCommands[file] + associateFilesLogger.Debug("Finished processing file %q. Found %d regular commands and %d isolate commands", file, len(currentFileCommands.Commands), len(currentFileCommands.IsolateCommands)) + associateFilesLogger.Trace("Commands for file %q: %v", file, currentFileCommands.Commands) + associateFilesLogger.Trace("Isolate commands for file %q: %v", file, currentFileCommands.IsolateCommands) } - logger.Info("Found %d associations between %d files and %d commands", associationCount, len(files), len(commands)) + associateFilesLogger.Info("Completed association. Found %d total associations for %d files and %d commands", associationCount, len(files), len(commands)) return fileCommands, nil } func AggregateGlobs(commands []ModifyCommand) map[string]struct{} { - logger.Info("Aggregating globs for %d commands", len(commands)) + aggregateGlobsLogger := modifyCommandLogger.WithPrefix("AggregateGlobs") + aggregateGlobsLogger.Debug("Aggregating glob patterns from commands") + aggregateGlobsLogger.Trace("Input commands for aggregation: %v", commands) globs := make(map[string]struct{}) for _, command := range commands { + aggregateGlobsLogger.Debug("Processing command %q for glob patterns", command.Name) for _, glob := range command.Files { - glob = strings.Replace(glob, "~", os.Getenv("HOME"), 1) - glob = strings.ReplaceAll(glob, "\\", "/") - globs[glob] = struct{}{} + resolvedGlob := strings.Replace(glob, "~", os.Getenv("HOME"), 1) + resolvedGlob = strings.ReplaceAll(resolvedGlob, "\\", "/") + aggregateGlobsLogger.Trace("Adding glob: %q (resolved to %q)", glob, resolvedGlob) + globs[resolvedGlob] = struct{}{} } } - logger.Info("Found %d unique globs", len(globs)) + aggregateGlobsLogger.Debug("Finished aggregating globs. Found %d unique glob patterns", len(globs)) + aggregateGlobsLogger.Trace("Aggregated unique globs: %v", globs) return globs } func ExpandGLobs(patterns map[string]struct{}) ([]string, error) { + expandGlobsLogger := modifyCommandLogger.WithPrefix("ExpandGLobs") + expandGlobsLogger.Debug("Expanding glob patterns to actual files") + expandGlobsLogger.Trace("Input patterns for expansion: %v", patterns) var files []string filesMap := make(map[string]bool) cwd, err := os.Getwd() if err != nil { + expandGlobsLogger.Error("Failed to get current working directory: %v", err) return nil, fmt.Errorf("failed to get current working directory: %w", err) } + expandGlobsLogger.Debug("Current working directory: %q", cwd) - logger.Debug("Expanding patterns from directory: %s", cwd) for pattern := range patterns { - logger.Trace("Processing pattern: %s", pattern) + expandGlobsLogger.Debug("Processing glob pattern: %q", pattern) static, pattern := SplitPattern(pattern) - matches, _ := doublestar.Glob(os.DirFS(static), pattern) - logger.Debug("Found %d matches for pattern %s", len(matches), pattern) + matches, err := doublestar.Glob(os.DirFS(static), pattern) + if err != nil { + expandGlobsLogger.Warning("Error expanding glob %q in %q: %v", pattern, static, err) + continue + } + expandGlobsLogger.Debug("Found %d matches for pattern %q", len(matches), pattern) + expandGlobsLogger.Trace("Raw matches for pattern %q: %v", pattern, matches) for _, m := range matches { m = filepath.Join(static, m) info, err := os.Stat(m) if err != nil { - logger.Warning("Error getting file info for %s: %v", m, err) + expandGlobsLogger.Warning("Error getting file info for %q: %v", m, err) continue } if !info.IsDir() && !filesMap[m] { - logger.Trace("Adding file to process list: %s", m) + expandGlobsLogger.Trace("Adding unique file to list: %q", m) filesMap[m], files = true, append(files, m) } } } if len(files) > 0 { - logger.Debug("Found %d files to process: %v", len(files), files) + expandGlobsLogger.Debug("Finished expanding globs. Found %d unique files to process", len(files)) + expandGlobsLogger.Trace("Unique files to process: %v", files) + } else { + expandGlobsLogger.Warning("No files found after expanding glob patterns.") } return files, nil } func LoadCommands(args []string) ([]ModifyCommand, error) { + loadCommandsLogger := modifyCommandLogger.WithPrefix("LoadCommands") + loadCommandsLogger.Debug("Loading commands from arguments (cook files or direct patterns)") + loadCommandsLogger.Trace("Input arguments: %v", args) commands := []ModifyCommand{} - logger.Info("Loading commands from cook files: %s", args) for _, arg := range args { - newcommands, err := LoadCommandsFromCookFiles(arg) + loadCommandsLogger.Debug("Processing argument for commands: %q", arg) + newCommands, err := LoadCommandsFromCookFiles(arg) if err != nil { + loadCommandsLogger.Error("Failed to load commands from argument %q: %v", arg, err) return nil, fmt.Errorf("failed to load commands from cook files: %w", err) } - logger.Info("Successfully loaded %d commands from cook files", len(newcommands)) - for _, cmd := range newcommands { + loadCommandsLogger.Debug("Successfully loaded %d commands from %q", len(newCommands), arg) + for _, cmd := range newCommands { if cmd.Disabled { - logger.Info("Skipping disabled command: %s", cmd.Name) + loadCommandsLogger.Debug("Skipping disabled command: %q", cmd.Name) continue } commands = append(commands, cmd) + loadCommandsLogger.Trace("Added command %q. Current total commands: %d", cmd.Name, len(commands)) } - logger.Info("Now total commands: %d", len(commands)) } - logger.Info("Loaded %d commands from all cook file", len(commands)) + loadCommandsLogger.Info("Finished loading commands. Total %d commands loaded", len(commands)) return commands, nil } func LoadCommandsFromCookFiles(pattern string) ([]ModifyCommand, error) { + loadCookFilesLogger := modifyCommandLogger.WithPrefix("LoadCommandsFromCookFiles").WithField("pattern", pattern) + loadCookFilesLogger.Debug("Loading commands from cook files based on pattern") + loadCookFilesLogger.Trace("Input pattern: %q", pattern) static, pattern := SplitPattern(pattern) commands := []ModifyCommand{} cookFiles, err := doublestar.Glob(os.DirFS(static), pattern) if err != nil { + loadCookFilesLogger.Error("Failed to glob cook files for pattern %q: %v", pattern, err) return nil, fmt.Errorf("failed to glob cook files: %w", err) } + loadCookFilesLogger.Debug("Found %d cook files for pattern %q", len(cookFiles), pattern) + loadCookFilesLogger.Trace("Cook files found: %v", cookFiles) for _, cookFile := range cookFiles { cookFile = filepath.Join(static, cookFile) cookFile = filepath.Clean(cookFile) cookFile = strings.ReplaceAll(cookFile, "\\", "/") - logger.Info("Loading commands from cook file: %s", cookFile) + loadCookFilesLogger.Debug("Loading commands from individual cook file: %q", cookFile) cookFileData, err := os.ReadFile(cookFile) if err != nil { + loadCookFilesLogger.Error("Failed to read cook file %q: %v", cookFile, err) return nil, fmt.Errorf("failed to read cook file: %w", err) } - newcommands, err := LoadCommandsFromCookFile(cookFileData) + loadCookFilesLogger.Trace("Read %d bytes from cook file %q", len(cookFileData), cookFile) + newCommands, err := LoadCommandsFromCookFile(cookFileData) if err != nil { + loadCookFilesLogger.Error("Failed to load commands from cook file data for %q: %v", cookFile, err) return nil, fmt.Errorf("failed to load commands from cook file: %w", err) } - commands = append(commands, newcommands...) + commands = append(commands, newCommands...) + loadCookFilesLogger.Debug("Added %d commands from cook file %q. Total commands now: %d", len(newCommands), cookFile, len(commands)) } + loadCookFilesLogger.Debug("Finished loading commands from cook files. Total %d commands", len(commands)) return commands, nil } func LoadCommandsFromCookFile(cookFileData []byte) ([]ModifyCommand, error) { + loadCommandLogger := modifyCommandLogger.WithPrefix("LoadCommandsFromCookFile") + loadCommandLogger.Debug("Unmarshaling commands from cook file data") + loadCommandLogger.Trace("Cook file data length: %d", len(cookFileData)) commands := []ModifyCommand{} err := yaml.Unmarshal(cookFileData, &commands) if err != nil { + loadCommandLogger.Error("Failed to unmarshal cook file data: %v", err) return nil, fmt.Errorf("failed to unmarshal cook file: %w", err) } + loadCommandLogger.Debug("Successfully unmarshaled %d commands", len(commands)) + loadCommandLogger.Trace("Unmarshaled commands: %v", commands) return commands, nil } // CountGlobsBeforeDedup counts the total number of glob patterns across all commands before deduplication func CountGlobsBeforeDedup(commands []ModifyCommand) int { + countGlobsLogger := modifyCommandLogger.WithPrefix("CountGlobsBeforeDedup") + countGlobsLogger.Debug("Counting glob patterns before deduplication") count := 0 for _, cmd := range commands { + countGlobsLogger.Trace("Processing command %q, adding %d globs", cmd.Name, len(cmd.Files)) count += len(cmd.Files) } + countGlobsLogger.Debug("Total glob patterns before deduplication: %d", count) return count } func FilterCommands(commands []ModifyCommand, filter string) []ModifyCommand { + filterCommandsLogger := modifyCommandLogger.WithPrefix("FilterCommands").WithField("filter", filter) + filterCommandsLogger.Debug("Filtering commands") + filterCommandsLogger.Trace("Input commands: %v", commands) filteredCommands := []ModifyCommand{} filters := strings.Split(filter, ",") + filterCommandsLogger.Trace("Split filters: %v", filters) for _, cmd := range commands { - for _, filter := range filters { - if strings.Contains(cmd.Name, filter) { + filterCommandsLogger.Debug("Checking command %q against filters", cmd.Name) + for _, f := range filters { + if strings.Contains(cmd.Name, f) { + filterCommandsLogger.Debug("Command %q matches filter %q, adding to filtered list", cmd.Name, f) filteredCommands = append(filteredCommands, cmd) + break // Command matches, no need to check other filters } } } + filterCommandsLogger.Debug("Finished filtering commands. Found %d filtered commands", len(filteredCommands)) + filterCommandsLogger.Trace("Filtered commands: %v", filteredCommands) return filteredCommands } diff --git a/utils/replacecommand.go b/utils/replacecommand.go index cca6426..4b0a9c3 100644 --- a/utils/replacecommand.go +++ b/utils/replacecommand.go @@ -7,6 +7,9 @@ import ( logger "git.site.quack-lab.dev/dave/cylogger" ) +// replaceCommandLogger is a scoped logger for the utils/replacecommand package. +var replaceCommandLogger = logger.Default.WithPrefix("utils/replacecommand") + type ReplaceCommand struct { From int To int @@ -14,45 +17,63 @@ type ReplaceCommand struct { } func ExecuteModifications(modifications []ReplaceCommand, fileData string) (string, int) { + executeModificationsLogger := replaceCommandLogger.WithPrefix("ExecuteModifications") + executeModificationsLogger.Debug("Executing a batch of text modifications") + executeModificationsLogger.Trace("Number of modifications: %d, Original file data length: %d", len(modifications), len(fileData)) var err error sort.Slice(modifications, func(i, j int) bool { return modifications[i].From > modifications[j].From }) - logger.Trace("Preparing to apply %d replacement commands in reverse order", len(modifications)) + executeModificationsLogger.Debug("Modifications sorted in reverse order for safe replacement") + executeModificationsLogger.Trace("Sorted modifications: %v", modifications) executed := 0 - for _, modification := range modifications { + for idx, modification := range modifications { + executeModificationsLogger.Debug("Applying modification %d/%d", idx+1, len(modifications)) + executeModificationsLogger.Trace("Current modification details: From=%d, To=%d, With=%q", modification.From, modification.To, modification.With) fileData, err = modification.Execute(fileData) if err != nil { - logger.Error("Failed to execute replacement: %v", err) + executeModificationsLogger.Error("Failed to execute replacement for modification %+v: %v", modification, err) continue } executed++ + executeModificationsLogger.Trace("File data length after modification: %d", len(fileData)) } - logger.Info("Successfully applied %d text replacements", executed) + executeModificationsLogger.Info("Successfully applied %d text replacements", executed) return fileData, executed } func (m *ReplaceCommand) Execute(fileDataStr string) (string, error) { + executeLogger := replaceCommandLogger.WithPrefix("Execute").WithField("modification", fmt.Sprintf("From:%d,To:%d,With:%q", m.From, m.To, m.With)) + executeLogger.Debug("Attempting to execute single replacement") err := m.Validate(len(fileDataStr)) if err != nil { + executeLogger.Error("Failed to validate modification: %v", err) return fileDataStr, fmt.Errorf("failed to validate modification: %v", err) } - logger.Trace("Replace pos %d-%d with %q", m.From, m.To, m.With) - return fileDataStr[:m.From] + m.With + fileDataStr[m.To:], nil + executeLogger.Trace("Applying replacement: fileDataStr[:%d] + %q + fileDataStr[%d:]", m.From, m.With, m.To) + result := fileDataStr[:m.From] + m.With + fileDataStr[m.To:] + executeLogger.Trace("Replacement executed. Result length: %d", len(result)) + return result, nil } func (m *ReplaceCommand) Validate(maxsize int) error { + validateLogger := replaceCommandLogger.WithPrefix("Validate").WithField("modification", fmt.Sprintf("From:%d,To:%d,With:%q", m.From, m.To, m.With)).WithField("maxSize", maxsize) + validateLogger.Debug("Validating replacement command against max size") if m.To < m.From { + validateLogger.Error("Validation failed: 'To' (%d) is less than 'From' (%d)", m.To, m.From) return fmt.Errorf("command to is less than from: %v", m) } if m.From > maxsize || m.To > maxsize { + validateLogger.Error("Validation failed: 'From' (%d) or 'To' (%d) is greater than max size (%d)", m.From, m.To, maxsize) return fmt.Errorf("command from or to is greater than replacement length: %v", m) } if m.From < 0 || m.To < 0 { + validateLogger.Error("Validation failed: 'From' (%d) or 'To' (%d) is less than 0", m.From, m.To) return fmt.Errorf("command from or to is less than 0: %v", m) } + validateLogger.Debug("Modification command validated successfully") return nil }