feat: better debugger (#13)

- create centralized structured logger with rotation
(https://github.com/versenilvis/IRIS/commit/96ad7c95ef0f7a9957b1bbf70bb6c8da3ce28b2e)
- update core lookup and utils to use new logger
(https://github.com/versenilvis/IRIS/commit/8b74b5a9cdc1828cff8c6d0bdaaccbe31da7a00a)
- add log startup metadata and propagate reload flags
(https://github.com/versenilvis/IRIS/commit/31208aa91a58e9e09abbf5497c314f5c961a58e2)
- add log key interceptions and pty events
(https://github.com/versenilvis/IRIS/commit/91ccb92835dd16ee70bf630fe0f267aad93c9db0)
- add test for logger 221a40c893b75e6215787163cd751a4c1cb6c1d8
- secure reload arguments file path to prevent symlink attacks
(https://github.com/versenilvis/IRIS/pull/13/commits/c3eabfda451230e52cb71f0c2a556687f839bd3f)
- close log file on reinitialization to prevent descriptor leak
(https://github.com/versenilvis/IRIS/pull/13/commits/a57d2c9be107a8c6200cf7046cc85b2f58667dce)

commands/core/lookup.go

@@ -5,6 +5,7 @@ import (
 	"sync"
 
 	"github.com/versenilvis/iris/integration/shell"
+	"github.com/versenilvis/iris/logger"
 )
 
 var (
@@ -103,7 +104,7 @@ func Lookup(input string) []Suggestion {
 
 	rootCmdName := tokens[0]
 	spec, exists := Registry[rootCmdName]
-	debugLog("[core] lookup tokens: %v, registry exists: %v", tokens, exists)
+	logger.Debugf("core lookup tokens: %v, registry exists: %v", tokens, exists)
 	if !exists {
 		return nil
 	}
@@ -174,8 +175,8 @@ func Lookup(input string) []Suggestion {
 	partial := tokens[len(tokens)-1]
 	allowMoreArgs := currentLimit <= 0 || argCount < currentLimit
 
-	debugLog("[core] query tokens: %v (partial: '%s')", tokens, partial)
+	logger.Debugf("core query tokens: %v (partial: '%s')", tokens, partial)
-	debugLog("[core] depth: %d, argCount: %d, limit: %d, allowMore: %v", depth, argCount, currentLimit, allowMoreArgs)
+	logger.Debugf("core depth: %d, argCount: %d, limit: %d, allowMore: %v", depth, argCount, currentLimit, allowMoreArgs)
 
 	prefixBuilder := strings.Builder{}
 	for i := 0; i < depth; i++ {

commands/core/utils.go

@@ -1,19 +1,9 @@
 package core
 
 import (
-	"fmt"
-	"io"
 	"strings"
 )
 
-var DebugWriter io.Writer
-
-func debugLog(format string, a ...any) {
-	if DebugWriter != nil {
-		_, _ = fmt.Fprintf(DebugWriter, format+"\n", a...)
-	}
-}
-
 // SplitAliasTokens parses the input string into shell-like tokens handling quotes
 // example: SplitAliasTokens("git commit -m \"hello world\"")
 func Tokenize(s string) []string {

logger/logger.go

@@ -0,0 +1,116 @@
+package logger
+
+import (
+	"fmt"
+	"os"
+	"path/filepath"
+	"runtime"
+	"strings"
+	"sync"
+	"time"
+)
+
+type Level int
+
+const (
+	LevelDebug Level = iota
+	LevelInfo
+	LevelWarn
+	LevelError
+)
+
+var (
+	mu         sync.Mutex
+	logFile    *os.File
+	currentLvl = LevelInfo
+)
+
+// Init initializes the logger writing to logFilePath
+func Init(logFilePath string, debug bool) {
+	mu.Lock()
+	defer mu.Unlock()
+
+	if logFile != nil {
+		_ = logFile.Close()
+		logFile = nil
+	}
+
+	// get log level from env
+	lvlEnv := strings.ToLower(os.Getenv("IRIS_LOG_LEVEL"))
+	switch lvlEnv {
+	case "debug":
+		currentLvl = LevelDebug
+	case "info":
+		currentLvl = LevelInfo
+	case "warn":
+		currentLvl = LevelWarn
+	case "error":
+		currentLvl = LevelError
+	default:
+		if debug {
+			currentLvl = LevelDebug
+		} else {
+			currentLvl = LevelInfo
+		}
+	}
+
+	// rotate if log file is larger than 5MB
+	if info, err := os.Stat(logFilePath); err == nil && info.Size() > 5*1024*1024 {
+		_ = os.Rename(logFilePath, logFilePath+".old")
+	}
+
+	_ = os.MkdirAll(filepath.Dir(logFilePath), 0755)
+	f, err := os.OpenFile(logFilePath, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0644)
+	if err == nil {
+		logFile = f
+	}
+}
+
+// Close closes the underlying log file
+func Close() {
+	mu.Lock()
+	defer mu.Unlock()
+	if logFile != nil {
+		_ = logFile.Close()
+		logFile = nil
+	}
+}
+
+func logmsg(lvl Level, lvlStr string, format string, a ...any) {
+	mu.Lock()
+	defer mu.Unlock()
+
+	if logFile == nil || lvl < currentLvl {
+		return
+	}
+
+	// get caller information to append file:line
+	caller := "unknown:0"
+	if _, file, line, ok := runtime.Caller(2); ok {
+		caller = fmt.Sprintf("%s:%d", filepath.Base(file), line)
+	}
+
+	tStr := time.Now().Format("2006-01-02T15:04:05.000Z07:00")
+	msg := fmt.Sprintf(format, a...)
+	_, _ = fmt.Fprintf(logFile, "%s [%s] [%s] %s\n", tStr, lvlStr, caller, msg)
+}
+
+// Debugf writes a debug log message
+func Debugf(format string, a ...any) {
+	logmsg(LevelDebug, "DEBUG", format, a...)
+}
+
+// Infof writes an info log message
+func Infof(format string, a ...any) {
+	logmsg(LevelInfo, "INFO", format, a...)
+}
+
+// Warnf writes a warning log message
+func Warnf(format string, a ...any) {
+	logmsg(LevelWarn, "WARN", format, a...)
+}
+
+// Errorf writes an error log message
+func Errorf(format string, a ...any) {
+	logmsg(LevelError, "ERROR", format, a...)
+}

root/root.go

@@ -8,13 +8,15 @@ import (
 	"os"
 	"os/exec"
 	"path/filepath"
+	"runtime"
 	"strconv"
+	"strings"
 	"syscall"
 
 	"github.com/spf13/cobra"
-	"github.com/versenilvis/iris/commands/core"
 	_ "github.com/versenilvis/iris/commands"
 	"github.com/versenilvis/iris/config"
+	"github.com/versenilvis/iris/logger"
 	"golang.org/x/term"
 )
 
@@ -36,6 +38,10 @@ It works exactly like coding editor suggestion menu drop down.`,
 			}()
 			if pidStr := os.Getenv("IRIS_PID"); pidStr != "" {
 				if pid, err := strconv.Atoi(pidStr); err == nil && pid > 0 {
+					if logDir, err := config.CachePath(); err == nil {
+						argsFile := filepath.Join(logDir, "reload-args")
+						_ = os.WriteFile(argsFile, []byte(strings.Join(os.Args[1:], "\n")), 0600)
+					}
 					_ = syscall.Kill(pid, syscall.SIGUSR1)
 					fmt.Println("\r\033[K\033[36m[IRIS] Sent reload signal to parent session.\033[0m")
 					return
@@ -46,7 +52,6 @@ It works exactly like coding editor suggestion menu drop down.`,
 	}
 	shellFlag   string
 	debugMode   bool
-	debugLogger *os.File
 )
 
 func init() {
@@ -57,26 +62,16 @@ func init() {
 		if shellFlag != "" {
 			config.Get().Core.Shell = shellFlag
 		}
-		config.Get().Core.Debug = true
+		logDir, err := config.CachePath()
-		if config.Get().Core.Debug {
+		if err == nil {
-			logDir, err := config.CachePath()
+			logger.Init(filepath.Join(logDir, "iris.log"), debugMode || config.Get().Core.Debug)
-			if err == nil {
+			logger.Infof("IRIS session started: os=%s, arch=%s, go=%s, pid=%d", runtime.GOOS, runtime.GOARCH, runtime.Version(), os.Getpid())
-				_ = os.MkdirAll(logDir, 0755)
+			cfg := config.Get()
-				f, _ := os.OpenFile(filepath.Join(logDir, "iris.log"), os.O_CREATE|os.O_TRUNC|os.O_WRONLY, 0644)
+			logger.Debugf("IRIS loaded config: shell=%q, mode=%q, ghost-text=%v, max-suggestions=%d", cfg.Core.Shell, cfg.Core.Mode, cfg.UI.GhostText, cfg.UI.MaxSuggestions)
-				debugLogger = f
-				core.DebugWriter = f
-				_, _ = fmt.Fprintf(debugLogger, "--- IRIS DEBUG LOG ---\n")
-			}
 		}
 	}
 }
 
-func debugLog(format string, a ...any) {
-	if debugLogger != nil {
-		_, _ = fmt.Fprintf(debugLogger, format+"\n", a...)
-	}
-}
-
 // runWatchdog spawns the watchdog parent process
 func runWatchdog() {
 	exe, err := os.Executable()

root/suggestions.go

@@ -7,10 +7,10 @@ import (
 	"github.com/versenilvis/iris/commands/core"
 	"github.com/versenilvis/iris/config"
 	"github.com/versenilvis/iris/integration"
+	"github.com/versenilvis/iris/logger"
 )
 
-// mergeResults collects and dedupes suggestions for a query and mode
+// MergeResults collects and dedupes suggestions for a query and mode
-// example: mergeResults("git ", "spec")
 func MergeResults(query string, mode string) []core.Suggestion {
 	maxSugg := config.Get().UI.MaxSuggestions
 	seen := make(map[string]bool)
@@ -19,7 +19,7 @@ func MergeResults(query string, mode string) []core.Suggestion {
 	// always call lookup to scan aliases and get spec suggestions
 	var cmdResults []core.Suggestion
 	if query != "" {
-		debugLog("[Merge] Calling Lookup for '%s'", query)
+		logger.Debugf("Merge Calling Lookup for '%s'", query)
 		cmdResults = core.Lookup(query)
 	}
 

root/wrapper.go

@@ -9,6 +9,7 @@ import (
 	"os"
 	"os/exec"
 	"os/signal"
+	"path/filepath"
 	"strings"
 	"sync"
 	"sync/atomic"
@@ -20,6 +21,7 @@ import (
 	"github.com/versenilvis/iris/config"
 	"github.com/versenilvis/iris/integration"
 	"github.com/versenilvis/iris/integration/shell"
+	"github.com/versenilvis/iris/logger"
 	"golang.org/x/sys/unix"
 	"golang.org/x/term"
 )
@@ -116,12 +118,16 @@ func runWrapper() {
 	_ = pty.InheritSize(os.Stdin, ptmx)
 	core.ShellPID = c.Process.Pid
 
+	logger.Infof("PTY child shell started: shell=%s, path=%s, pid=%d", shellName, adapter.GetShellPath(), c.Process.Pid)
+
 	// put terminal in raw mode to intercept every keystroke
 	var errMakeRaw error
 	oldState, errMakeRaw = term.MakeRaw(int(os.Stdin.Fd()))
 	if errMakeRaw != nil {
+		logger.Errorf("Failed to set terminal raw mode: %v", errMakeRaw)
 		panic(errMakeRaw)
 	}
+	logger.Debugf("Terminal set to raw mode successfully")
 	defer restoreTerminal()
 
 	sigCh := make(chan os.Signal, 2)
@@ -139,6 +145,7 @@ func runWrapper() {
 		for s := range sigCh {
 			switch s {
 			case syscall.SIGWINCH:
+				logger.Debugf("Received SIGWINCH terminal resize signal")
 				_ = pty.InheritSize(os.Stdin, ptmx) // handle terminal window resize
 			// this is the core feature of reloading
 			// it helps IRIS reload itself that you dont need to restart the shell manually
@@ -178,7 +185,25 @@ func runWrapper() {
 				}
 
 				restoreTerminal()
-				_ = syscall.Exec(exe, os.Args, os.Environ())
+				execArgs := []string{os.Args[0]}
+				if logDir, err := config.CachePath(); err == nil {
+					argsFile := filepath.Join(logDir, "reload-args")
+					if data, err := os.ReadFile(argsFile); err == nil {
+						lines := strings.Split(string(data), "\n")
+						for _, line := range lines {
+							trimmed := strings.TrimSpace(line)
+							if trimmed != "" {
+								execArgs = append(execArgs, trimmed)
+							}
+						}
+						_ = os.Remove(argsFile)
+					} else {
+						execArgs = os.Args
+					}
+				} else {
+					execArgs = os.Args
+				}
+				_ = syscall.Exec(exe, execArgs, os.Environ())
 			}
 		}
 	}()
@@ -305,7 +330,7 @@ func runWrapper() {
 			writeStdout([]byte(rBuf.String()))
 		}
 		if err := scanner.Err(); err != nil {
-			debugLog("[IPC] scanner error: %v", err)
+			logger.Errorf("IPC scanner error: %v", err)
 		}
 	}()
 
@@ -347,9 +372,9 @@ func runWrapper() {
 				writeStdout([]byte(overlay.ClearAndDisable()))
 				return
 			}
-			debugLog("[Render] query: '%s', mode: %s", bufCopy, modeCopy)
+			logger.Debugf("Render query: '%s', mode: %s", bufCopy, modeCopy)
 			results := MergeResults(bufCopy, modeCopy)
-			debugLog("[Render] results found: %d", len(results))
+			logger.Debugf("Render results found: %d", len(results))
 
 			if len(results) == 0 || (len(results) == 1 && strings.TrimSpace(results[0].Cmd) == strings.TrimSpace(bufCopy) && !strings.HasSuffix(bufCopy, " ")) {
 				b.WriteString(overlay.ClearAndDisable())
@@ -376,7 +401,7 @@ func runWrapper() {
 		if len(overlay.Items) > 0 && overlay.Cursor >= 0 && overlay.Cursor < len(overlay.Items) {
 			currentCmd = overlay.Items[overlay.Cursor].Cmd
 		}
-		debugLog("[RenderOverlay] nav: %v, cursor: %d, typedQuery: '%s', currentCmd: '%s'", navCopy, overlay.Cursor, overlay.TypedQuery, currentCmd)
+		logger.Debugf("RenderOverlay nav: %v, cursor: %d, typedQuery: '%s', currentCmd: '%s'", navCopy, overlay.Cursor, overlay.TypedQuery, currentCmd)
 		b.WriteString(overlay.Render())
 		writeStdout([]byte(b.String()))
 	}
@@ -448,6 +473,8 @@ func runWrapper() {
 				continue
 			}
 
+			logger.Debugf("Stdin raw input: bytes=%q, hex=%x", inputSlice[:n], inputSlice[:n])
+
 			shouldOverlayDraw := false
 			for i := 0; i < n; i++ {
 				b := inputSlice[i]
@@ -458,6 +485,7 @@ func runWrapper() {
 					if i+5 < n && inputSlice[i+1] == '[' && inputSlice[i+2] == '2' && inputSlice[i+3] == '0' {
 						if (inputSlice[i+4] == '0' || inputSlice[i+4] == '1') && inputSlice[i+5] == '~' {
 							intercepted = true
+							logger.Debugf("Intercepted bracketed paste event")
 							_, _ = ptmx.Write(inputSlice[i : i+6])
 							i += 5
 							continue
@@ -469,6 +497,7 @@ func runWrapper() {
 						if inputSlice[i+1] == '[' && inputSlice[i+2] == 'Z' {
 							intercepted = true
 							suggestionsEnabled = !suggestionsEnabled
+							logger.Debugf("Intercepted Shift+Tab, suggestionsEnabled=%v", suggestionsEnabled)
 							if !suggestionsEnabled {
 								writeStdout([]byte(overlay.ClearAndDisable()))
 							} else {
@@ -494,17 +523,20 @@ func runWrapper() {
 							}
 
 							oldCursor := overlay.Cursor
-							if inputSlice[i+2] == 'A' { // up arrow
+							arrowDir := "down"
+							if inputSlice[i+2] == 'A' {
+								arrowDir = "up"
 								overlay.Cursor--
 								if overlay.Cursor < 0 {
 									overlay.Cursor = 0
 								}
-							} else { // down arrow
+							} else {
 								overlay.Cursor++
 								if overlay.Cursor >= len(overlay.Items) {
 									overlay.Cursor = len(overlay.Items) - 1
 								}
 							}
+							logger.Debugf("Intercepted %s Arrow, cursor moved %d -> %d", arrowDir, oldCursor, overlay.Cursor)
 
 							// boundary hit - ignore redundant write to avoid PTY flooding
 							if overlay.Cursor == oldCursor {
@@ -589,6 +621,7 @@ func runWrapper() {
 
 							if hasMatch && len(ghostText) > 0 {
 								intercepted = true
+								logger.Debugf("Intercepted Right Arrow (accepted ghost text: %q)", ghostText)
 								bufferMu.Lock()
 								naiveBuffer += ghostText
 								cursorOffset = 0
@@ -681,6 +714,7 @@ func runWrapper() {
 					}
 					saveMode(activeMode)
 					activeModeMu.Unlock()
+					logger.Debugf("Intercepted Ctrl+R, toggled mode to %q", activeMode)
 					shouldOverlayDraw = true
 					// enter: enter behavior is a bit different from tab suggestions in code editor
 					// I want it to execute the command anyway and ignore the suggestions
@@ -688,6 +722,7 @@ func runWrapper() {
 					// enter is not used to select suggestions
 				} else if overlay.Visible && (b == 0x0d || b == 0x0a) {
 					intercepted = true
+					logger.Debugf("Intercepted Enter key, navigated=%v", overlay.UserNavigated)
 					if overlay.UserNavigated && len(overlay.Items) > 0 && overlay.Cursor >= 0 && overlay.Cursor < len(overlay.Items) {
 						selected := overlay.Items[overlay.Cursor].Cmd
 						activeModeMu.RLock()
@@ -711,6 +746,7 @@ func runWrapper() {
 					continue
 				} else if b == 0x09 { // tab: select suggestions
 					intercepted = true
+					logger.Debugf("Intercepted Tab key, visible=%v, cursor=%d", overlay.Visible, overlay.Cursor)
 					if !overlay.Visible {
 						shouldOverlayDraw = true
 					} else {

tests/logger_test.go

@@ -0,0 +1,91 @@
+package tests
+
+import (
+	"os"
+	"path/filepath"
+	"strings"
+	"testing"
+
+	"github.com/versenilvis/iris/logger"
+)
+
+func TestLogger(t *testing.T) {
+	tempDir, err := os.MkdirTemp("", "iris-log-test-*")
+	if err != nil {
+		t.Fatalf("failed to create temp dir: %v", err)
+	}
+	defer os.RemoveAll(tempDir)
+
+	logFilePath := filepath.Join(tempDir, "test.log")
+
+	// test 1: default init sets level to info
+	logger.Init(logFilePath, false)
+	logger.Debugf("this debug msg should not be logged")
+	logger.Infof("this info msg should be logged")
+	logger.Close()
+
+	data, err := os.ReadFile(logFilePath)
+	if err != nil {
+		t.Fatalf("failed to read log file: %v", err)
+	}
+
+	content := string(data)
+	if strings.Contains(content, "this debug msg should not be logged") {
+		t.Errorf("expected debug log to be skipped, got: %s", content)
+	}
+	if !strings.Contains(content, "this info msg should be logged") {
+		t.Errorf("expected info log to be recorded, got: %s", content)
+	}
+	if !strings.Contains(content, "[INFO]") {
+		t.Errorf("expected log to contain INFO tag, got: %s", content)
+	}
+	if !strings.Contains(content, "logger_test.go:") {
+		t.Errorf("expected log to contain caller trace info, got: %s", content)
+	}
+
+	// test 2: override init with debug = true
+	_ = os.Remove(logFilePath)
+	logger.Init(logFilePath, true)
+	logger.Debugf("this debug msg should now be logged")
+	logger.Close()
+
+	data, err = os.ReadFile(logFilePath)
+	if err != nil {
+		t.Fatalf("failed to read log file: %v", err)
+	}
+
+	content = string(data)
+	if !strings.Contains(content, "this debug msg should now be logged") {
+		t.Errorf("expected debug log to be recorded, got: %s", content)
+	}
+	if !strings.Contains(content, "[DEBUG]") {
+		t.Errorf("expected log to contain DEBUG tag, got: %s", content)
+	}
+
+	// test 3: test log rotation to .old
+	// create a large file
+	largeData := make([]byte, 6*1024*1024)
+	err = os.WriteFile(logFilePath, largeData, 0644)
+	if err != nil {
+		t.Fatalf("failed to write large file: %v", err)
+	}
+
+	logger.Init(logFilePath, false)
+	logger.Infof("new log after rotation")
+	logger.Close()
+
+	// check if old file exists and is rotated
+	oldPath := logFilePath + ".old"
+	if _, err = os.Stat(oldPath); os.IsNotExist(err) {
+		t.Errorf("expected rotated log file to exist at %s", oldPath)
+	}
+
+	data, err = os.ReadFile(logFilePath)
+	if err != nil {
+		t.Fatalf("failed to read log file: %v", err)
+	}
+	content = string(data)
+	if !strings.Contains(content, "new log after rotation") {
+		t.Errorf("expected new log to exist in the fresh log file, got: %s", content)
+	}
+}