From f37f0681ce2e22054fc636f37acc79d8347c6a1f Mon Sep 17 00:00:00 2001 From: VERSE Date: Wed, 1 Jul 2026 20:09:38 +0700 Subject: [PATCH] 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 | 7 +-- commands/core/utils.go | 10 ---- logger/logger.go | 116 ++++++++++++++++++++++++++++++++++++++++ root/root.go | 31 +++++------ root/suggestions.go | 6 +-- root/wrapper.go | 50 ++++++++++++++--- tests/logger_test.go | 91 +++++++++++++++++++++++++++++++ 7 files changed, 270 insertions(+), 41 deletions(-) create mode 100644 logger/logger.go create mode 100644 tests/logger_test.go diff --git a/commands/core/lookup.go b/commands/core/lookup.go index 2e9e9de..26abb8a 100644 --- a/commands/core/lookup.go +++ b/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) - debugLog("[core] depth: %d, argCount: %d, limit: %d, allowMore: %v", depth, argCount, currentLimit, allowMoreArgs) + logger.Debugf("core query tokens: %v (partial: '%s')", tokens, partial) + logger.Debugf("core depth: %d, argCount: %d, limit: %d, allowMore: %v", depth, argCount, currentLimit, allowMoreArgs) prefixBuilder := strings.Builder{} for i := 0; i < depth; i++ { diff --git a/commands/core/utils.go b/commands/core/utils.go index 6a1810d..30556b9 100644 --- a/commands/core/utils.go +++ b/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 { diff --git a/logger/logger.go b/logger/logger.go new file mode 100644 index 0000000..233698c --- /dev/null +++ b/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...) +} diff --git a/root/root.go b/root/root.go index 97038fe..3dcc72e 100644 --- a/root/root.go +++ b/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 - if config.Get().Core.Debug { - logDir, err := config.CachePath() - if err == nil { - _ = os.MkdirAll(logDir, 0755) - f, _ := os.OpenFile(filepath.Join(logDir, "iris.log"), os.O_CREATE|os.O_TRUNC|os.O_WRONLY, 0644) - debugLogger = f - core.DebugWriter = f - _, _ = fmt.Fprintf(debugLogger, "--- IRIS DEBUG LOG ---\n") - } + logDir, err := config.CachePath() + if err == nil { + logger.Init(filepath.Join(logDir, "iris.log"), debugMode || config.Get().Core.Debug) + logger.Infof("IRIS session started: os=%s, arch=%s, go=%s, pid=%d", runtime.GOOS, runtime.GOARCH, runtime.Version(), os.Getpid()) + cfg := config.Get() + 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) } } } -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() diff --git a/root/suggestions.go b/root/suggestions.go index 923ae45..88c342d 100644 --- a/root/suggestions.go +++ b/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 -// example: mergeResults("git ", "spec") +// MergeResults collects and dedupes suggestions for a query and mode 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) } diff --git a/root/wrapper.go b/root/wrapper.go index 58c344b..890b04f 100644 --- a/root/wrapper.go +++ b/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 { diff --git a/tests/logger_test.go b/tests/logger_test.go new file mode 100644 index 0000000..31cfd0a --- /dev/null +++ b/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) + } +}