Make little better logging

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), "<?xml") {
+			return "XML"
+		}
+		if strings.HasPrefix(strings.TrimSpace(content), "{") ||
+			strings.HasPrefix(strings.TrimSpace(content), "[") {
+			return "JSON"
+		}
+		if strings.HasPrefix(strings.TrimSpace(content), "<!DOCTYPE html") ||
+			strings.HasPrefix(strings.TrimSpace(content), "<html") {
+			return "HTML"
+		}
+		return ""
+	}
+}
+
+// Helper function to get processor type name
+func getProcessorType(p Processor) string {
+	switch p.(type) {
+	case *RegexProcessor:
+		return "Regex"
+	case *XMLProcessor:
+		return "XML"
+	case *JSONProcessor:
+		return "JSON"
+	default:
+		return "Unknown"
+	}
+}
+
 // ToLua converts a struct or map to a Lua table recursively
 func ToLua(L *lua.LState, data interface{}) (lua.LValue, error) {
 	switch v := data.(type) {

processor/regex.go

@@ -109,7 +109,7 @@ func (p *RegexProcessor) ProcessContent(content string, pattern string, luaExpr
 
 	previous := luaExpr
 	luaExpr = BuildLuaScript(luaExpr)
-	logger.Debug("Changing Lua expression from: %s to: %s", previous, luaExpr)
+	logger.Debug("Transformed Lua expression: %q → %q", previous, luaExpr)
 
 	// Initialize Lua environment
 	modificationCount := 0
@@ -117,13 +117,15 @@ func (p *RegexProcessor) ProcessContent(content string, pattern string, luaExpr
 	// Process all regex matches
 	result := content
 	indices := compiledPattern.FindAllStringSubmatchIndex(content, -1)
-	logger.Debug("Found %d matches in the content", len(indices))
+	logger.Debug("Found %d matches in content of length %d", len(indices), len(content))
 
 	// We walk backwards because we're replacing something with something else that might be longer
 	// And in the case it is longer than the original all indicces past that change will be fucked up
 	// 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 := len(indices) - 1; i >= 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
 }