From e847e5c3ce2b0e4c0de571ba63f4bdc6e6661d15 Mon Sep 17 00:00:00 2001 From: PhatPhuckDave Date: Thu, 27 Mar 2025 18:51:22 +0100 Subject: [PATCH] Make little better logging --- logger/logger.go | 22 ++++++++- processor/processor.go | 102 ++++++++++++++++++++++++++++++++++++++--- processor/regex.go | 97 +++++++++++++++++++++++++++++---------- 3 files changed, 187 insertions(+), 34 deletions(-) diff --git a/logger/logger.go b/logger/logger.go index 76f2157..a9197ed 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -212,7 +212,25 @@ func (l *Logger) formatMessage(level LogLevel, format string, args ...interface{ var caller string if l.flag&log.Lshortfile != 0 || l.flag&log.Llongfile != 0 { - _, file, line, ok := runtime.Caller(3 + l.callerOffset) + // Find the actual caller by scanning up the stack + // until we find a function outside the logger package + var file string + var line int + var ok bool + + // Start at a reasonable depth and scan up to 10 frames + for depth := 4; depth < 15; depth++ { + _, file, line, ok = runtime.Caller(depth) + if !ok { + break + } + + // If the caller is not in the logger package, we found our caller + if !strings.Contains(file, "logger/logger.go") { + break + } + } + if !ok { file = "???" line = 0 @@ -239,7 +257,7 @@ func (l *Logger) formatMessage(level LogLevel, format string, args ...interface{ } } - return fmt.Sprintf("%s%s%s%s[%s%s%s]%s %s\n", + return fmt.Sprintf("%s%14s%-30s%s[%s%s%s]%s %s\n", l.prefix, timeStr, caller, levelColor, levelNames[level], resetColor, fields, resetColor, msg) } diff --git a/processor/processor.go b/processor/processor.go index c87aee5..a2fdb56 100644 --- a/processor/processor.go +++ b/processor/processor.go @@ -1,10 +1,12 @@ package processor import ( + "crypto/md5" "fmt" "os" "path/filepath" "strings" + "time" "github.com/antchfx/xmlquery" lua "github.com/yuin/gopher-lua" @@ -62,6 +64,8 @@ func NewLuaState() (*lua.LState, error) { } func Process(p Processor, 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 { @@ -70,7 +74,15 @@ func Process(p Processor, filename string, pattern string, luaExpr string) (int, } fullPath := filepath.Join(cwd, filename) - logger.Trace("Reading file content from: %s", fullPath) + 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) @@ -78,32 +90,108 @@ func Process(p Processor, filename string, pattern string, luaExpr string) (int, } fileContent := string(content) - logger.Trace("File %s read successfully, size: %d bytes", fullPath, len(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("Processing content for file: %s", filename) + logger.Debug("Starting content processing with %s processor", getProcessorType(p)) modifiedContent, modCount, matchCount, err := p.ProcessContent(fileContent, pattern, luaExpr) if err != nil { - logger.Error("Error processing content for file %s: %v", filename, err) + 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 { - logger.Info("Writing %d modifications to file: %s", modCount, filename) + // 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 %s written successfully", filename) + 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 modifications to write for file: %s", filename) + logger.Debug("No matches found in file") } return modCount, matchCount, nil } +// Helper function to get a short MD5 hash of content for logging +func md5sum(data []byte) []byte { + h := md5.New() + h.Write(data) + return h.Sum(nil)[:4] // Just use first 4 bytes for brevity +} + +// Helper function to detect basic file type from extension and content +func detectFileType(filename string, content string) string { + ext := strings.ToLower(filepath.Ext(filename)) + + switch ext { + case ".xml": + return "XML" + case ".json": + return "JSON" + case ".html", ".htm": + return "HTML" + case ".txt": + return "Text" + case ".go": + return "Go" + case ".js": + return "JavaScript" + case ".py": + return "Python" + case ".java": + return "Java" + case ".c", ".cpp", ".h": + return "C/C++" + default: + // Try content-based detection for common formats + if strings.HasPrefix(strings.TrimSpace(content), "= 0; i-- { + logger.Debug("Processing match %d of %d", i+1, len(indices)) + L, err := NewLuaState() if err != nil { logger.Error("Error creating Lua state: %v", err) @@ -133,10 +135,10 @@ func (p *RegexProcessor) ProcessContent(content string, pattern string, luaExpr // 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") + logger.Trace("Lua state created successfully for match %d", i+1) matchIndices := indices[i] - logger.Trace("Processing match indices: %v", matchIndices) + logger.Trace("Match indices: %v (match position %d-%d)", matchIndices, matchIndices[0], matchIndices[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 @@ -146,21 +148,34 @@ func (p *RegexProcessor) ProcessContent(content string, pattern string, luaExpr // As if concatenating in the middle of the array // Plus it supports lookarounds match := content[matchIndices[0]:matchIndices[1]] - logger.Trace("Matched content: %s", match) + matchPreview := match + if len(match) > 50 { + matchPreview = match[:47] + "..." + } + logger.Trace("Matched content: %q (length: %d)", matchPreview, len(match)) groups := matchIndices[2:] if len(groups) <= 0 { - logger.Warning("No capture groups for lua to chew on") + logger.Warning("No capture groups found for match %q and regex %q", matchPreview, pattern) continue } if len(groups)%2 == 1 { - logger.Warning("Odd number of indices of groups, what the fuck?") + logger.Warning("Invalid number of group indices (%d), should be even: %v", len(groups), groups) continue } + + // Count how many valid groups we have + validGroups := 0 + for j := 0; j < len(groups); j += 2 { + if groups[j] != -1 && groups[j+1] != -1 { + validGroups++ + } + } + logger.Debug("Found %d valid capture groups in match", validGroups) + for _, index := range groups { if index == -1 { - // return "", 0, 0, fmt.Errorf("negative indices encountered: %v. This indicates that there was an issue with the match indices, possibly due to an empty match or an unexpected pattern. Please check the regex pattern and input content.", matchIndices) - logger.Warning("Negative indices encountered: %v. This indicates that there was an issue with the match indices, possibly due to an empty match or an unexpected pattern. This is not an error but it's possibly not what you want.", matchIndices) + 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) continue } } @@ -172,55 +187,59 @@ func (p *RegexProcessor) ProcessContent(content string, pattern string, luaExpr captureGroups := make([]*CaptureGroup, 0, len(groups)/2) groupNames := compiledPattern.SubexpNames()[1:] for i, name := range groupNames { - // if name == "" { - // continue - // } start := groups[i*2] end := groups[i*2+1] if start == -1 || end == -1 { continue } + value := content[start:end] captureGroups = append(captureGroups, &CaptureGroup{ Name: name, - Value: content[start:end], + Value: value, Range: [2]int{start, end}, }) - } - for _, capture := range captureGroups { - logger.Trace("Capture group: %+v", *capture) + // Include name info in log if available + if name != "" { + logger.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) + } } if err := p.ToLua(L, captureGroups); err != nil { - logger.Error("Error setting Lua variables: %v", err) + logger.Error("Failed to set Lua variables: %v", err) continue } - logger.Trace("Lua variables set successfully") + logger.Trace("Set %d capture groups as Lua variables", len(captureGroups)) if err := L.DoString(luaExpr); err != nil { - logger.Error("Error executing Lua code %s for groups %+v: %v", luaExpr, captureGroups, err) + logger.Error("Lua script execution failed: %v\nScript: %s\nCapture Groups: %+v", + err, luaExpr, captureGroups) continue } - logger.Trace("Lua code executed successfully") + logger.Trace("Lua script executed successfully") // Get modifications from Lua captureGroups, err = p.FromLuaCustom(L, captureGroups) if err != nil { - logger.Error("Error getting modifications: %v", err) + logger.Error("Failed to retrieve modifications from Lua: %v", err) continue } + logger.Trace("Retrieved updated values from Lua") replacement := "" replacementVar := L.GetGlobal("replacement") if replacementVar.Type() != lua.LTNil { replacement = replacementVar.String() + logger.Debug("Using global replacement: %q", replacement) } // Check if modification flag is set modifiedVal := L.GetGlobal("modified") if modifiedVal.Type() != lua.LTBool || !lua.LVAsBool(modifiedVal) { - logger.Debug("No modifications made by Lua script") + logger.Debug("Skipping match - no modifications made by Lua script") continue } @@ -228,8 +247,26 @@ func (p *RegexProcessor) ProcessContent(content string, pattern string, luaExpr commands := make([]ReplaceCommand, 0, len(captureGroups)) // Apply the modifications to the original match replacement = match + + // Count groups that were actually modified + modifiedGroups := 0 for _, capture := range captureGroups { - logger.Debug("Applying modification: %s", capture.Updated) + if capture.Value != capture.Updated { + modifiedGroups++ + } + } + logger.Debug("%d of %d capture groups were modified", modifiedGroups, len(captureGroups)) + + for _, capture := range captureGroups { + if capture.Value == capture.Updated { + logger.Trace("Capture group unchanged: %s", capture.Value) + continue + } + + // Log what changed with context + logger.Debug("Modifying group %s: %q → %q", + capture.Name, capture.Value, capture.Updated) + // Indices of the group are relative to content // To relate them to match we have to subtract the match start index // replacement = replacement[:groupStart] + newVal + replacement[groupEnd:] @@ -240,21 +277,31 @@ func (p *RegexProcessor) ProcessContent(content string, pattern string, luaExpr }) } + // Sort commands in reverse order for safe replacements sort.Slice(commands, func(i, j int) bool { return commands[i].From > commands[j].From }) + logger.Trace("Applying %d replacement commands in reverse order", len(commands)) for _, command := range commands { + logger.Trace("Replace pos %d-%d with %q", command.From, command.To, command.With) replacement = replacement[:command.From] + command.With + replacement[command.To:] } } + // Preview the replacement for logging + replacementPreview := replacement + if len(replacement) > 50 { + replacementPreview = replacement[:47] + "..." + } + logger.Debug("Replacing match %q with %q", matchPreview, replacementPreview) + modificationCount++ result = result[:matchIndices[0]] + replacement + result[matchIndices[1]:] - logger.Debug("Modification count updated: %d", modificationCount) + logger.Debug("Match #%d processed, running modification count: %d", i+1, modificationCount) } - logger.Debug("Process completed with %d modifications", modificationCount) + logger.Info("Regex processing complete: %d modifications from %d matches", modificationCount, len(indices)) return result, modificationCount, len(indices), nil }