From 8b6449c947895aaceed1e729125a9549d8ae5640 Mon Sep 17 00:00:00 2001 From: Greg Gauthier Date: Sun, 1 Mar 2026 12:35:21 +0000 Subject: [PATCH] feat(logging): implement structured logging with slog - Refactor logger package to use Go's slog for JSON-structured logs - Add configurable log levels (debug, info, warn, error) via config and flags - Integrate logging across commands, git operations, and API client with metrics like timing and sizes - Update README with logging documentation and usage examples - Add global --debug and --verbose flags - Enhance tests for logger initialization, levels, and structured output --- README.md | 35 +++++++++-- cmd/edit.go | 19 ++++++ cmd/root.go | 17 +++++- config/config.go | 6 ++ internal/git/git.go | 20 ++++++- internal/grok/client.go | 35 +++++++++++ internal/logger/logger.go | 105 ++++++++++++++++++++++++++------- internal/logger/logger_test.go | 95 +++++++++++++++++++++++++---- 8 files changed, 294 insertions(+), 38 deletions(-) diff --git a/README.md b/README.md index 096d0e3..d000bb1 100644 --- a/README.md +++ b/README.md @@ -25,6 +25,7 @@ grokkit --help default_model = "grok-4" temperature = 0.7 timeout = 60 # seconds +log_level = "info" # debug, info, warn, error [aliases] beta = "grok-beta-2" @@ -33,6 +34,8 @@ beta = "grok-beta-2" history_file = "~/.config/grokkit/chat_history.json" ``` +Logs are written to `~/.config/grokkit/grokkit.log` in JSON format for structured analysis. + ## Commands ### 💬 `grokkit chat` @@ -107,19 +110,43 @@ grokkit completion powershell > grokkit.ps1 ## Flags - `--model, -m`: Specify model (e.g., grok-4, grok-beta) -- Global flag available on all commands +- `--debug`: Enable debug logging (outputs to both stderr and log file) +- `--verbose, -v`: Enable verbose logging +- All flags are global and work with any command ## Features +- ✅ **Structured logging with slog** - JSON logs with request tracing, timing, and context - ✅ Context-aware HTTP requests with timeouts -- ✅ Comprehensive error handling and logging -- ✅ Persistent chat history +- ✅ Comprehensive error handling and custom error types +- ✅ Persistent chat history across sessions - ✅ Configurable temperature and parameters - ✅ Shell completions (bash, zsh, fish, powershell) - ✅ Test coverage >70% -- ✅ CI/CD with GitHub Actions +- ✅ CI/CD with Gitea Actions - ✅ Interface-based design for testability +### Logging & Observability + +Grokkit uses Go's standard `log/slog` for structured logging: + +```bash +# Enable debug mode (logs to both stderr and file) +grokkit chat --debug + +# View logs +tail -f ~/.config/grokkit/grokkit.log + +# Parse JSON logs with jq +cat ~/.config/grokkit/grokkit.log | jq 'select(.level=="ERROR")' +``` + +**Logged metrics:** +- API request/response timing and sizes +- Git command execution and output +- File operations with size tracking +- Error context with stack traces + ## Development ```bash diff --git a/cmd/edit.go b/cmd/edit.go index 2990c4a..1ebedff 100644 --- a/cmd/edit.go +++ b/cmd/edit.go @@ -10,6 +10,7 @@ import ( "github.com/spf13/cobra" "gmgauthier.com/grokkit/config" "gmgauthier.com/grokkit/internal/grok" + "gmgauthier.com/grokkit/internal/logger" ) var editCmd = &cobra.Command{ @@ -23,23 +24,34 @@ var editCmd = &cobra.Command{ modelFlag, _ := cmd.Flags().GetString("model") model := config.GetModel(modelFlag) + logger.Info("edit command started", + "file", filePath, + "instruction", instruction, + "model", model) + if _, err := os.Stat(filePath); os.IsNotExist(err) { + logger.Error("file not found", "file", filePath, "error", err) color.Red("File not found: %s", filePath) os.Exit(1) } original, err := os.ReadFile(filePath) if err != nil { + logger.Error("failed to read file", "file", filePath, "error", err) color.Red("Failed to read file: %v", err) os.Exit(1) } + logger.Debug("file read successfully", "file", filePath, "size_bytes", len(original)) cleanedOriginal := removeLastModifiedComments(string(original)) backupPath := filePath + ".bak" + logger.Debug("creating backup", "backup_path", backupPath) if err := os.WriteFile(backupPath, original, 0644); err != nil { + logger.Error("failed to create backup", "backup_path", backupPath, "error", err) color.Red("Failed to create backup: %v", err) os.Exit(1) } + logger.Info("backup created", "backup_path", backupPath) client := grok.NewClient() messages := []map[string]string{ @@ -65,10 +77,17 @@ var editCmd = &cobra.Command{ return } + logger.Debug("applying changes", "file", filePath, "new_size_bytes", len(newContent)) if err := os.WriteFile(filePath, []byte(newContent), 0644); err != nil { + logger.Error("failed to write file", "file", filePath, "error", err) color.Red("Failed to write file: %v", err) os.Exit(1) } + logger.Info("changes applied successfully", + "file", filePath, + "backup", backupPath, + "original_size", len(original), + "new_size", len(newContent)) color.Green("✅ Applied successfully! Backup: %s", backupPath) }, } diff --git a/cmd/root.go b/cmd/root.go index d0c168b..d2bfcfb 100644 --- a/cmd/root.go +++ b/cmd/root.go @@ -14,7 +14,18 @@ var rootCmd = &cobra.Command{ Long: `A fast, native Go CLI for Grok. Chat, edit files, and supercharge your git workflow.`, PersistentPreRun: func(cmd *cobra.Command, args []string) { config.Load() - _ = logger.Init() // Logging is optional, don't fail if it errors + + // Determine log level: flag > config > default + logLevel := config.GetLogLevel() + if debug, _ := cmd.Flags().GetBool("debug"); debug { + logLevel = "debug" + } + if verbose, _ := cmd.Flags().GetBool("verbose"); verbose { + logLevel = "info" + } + + _ = logger.Init(logLevel) // Logging is optional, don't fail if it errors + logger.Info("grokkit starting", "command", cmd.Name(), "log_level", logLevel) }, } @@ -37,4 +48,8 @@ func init() { // Add model flag to all commands rootCmd.PersistentFlags().StringP("model", "m", "", "Grok model to use (overrides config)") + + // Add logging flags + rootCmd.PersistentFlags().Bool("debug", false, "Enable debug logging (logs to stderr and file)") + rootCmd.PersistentFlags().BoolP("verbose", "v", false, "Enable verbose logging") } diff --git a/config/config.go b/config/config.go index cf99f15..8b52dae 100644 --- a/config/config.go +++ b/config/config.go @@ -23,6 +23,8 @@ func Load() { viper.SetDefault("default_model", "grok-4") viper.SetDefault("temperature", 0.7) + viper.SetDefault("log_level", "info") + viper.SetDefault("timeout", 60) // Config file is optional, so we ignore read errors _ = viper.ReadInConfig() @@ -49,3 +51,7 @@ func GetTimeout() int { } return timeout } + +func GetLogLevel() string { + return viper.GetString("log_level") +} diff --git a/internal/git/git.go b/internal/git/git.go index 56ada0b..b154cf3 100644 --- a/internal/git/git.go +++ b/internal/git/git.go @@ -3,17 +3,35 @@ package git import ( "fmt" "os/exec" + "strings" + + "gmgauthier.com/grokkit/internal/logger" ) func Run(args []string) (string, error) { + cmdStr := "git " + strings.Join(args, " ") + logger.Debug("executing git command", "command", cmdStr, "args", args) + out, err := exec.Command("git", args...).Output() if err != nil { + logger.Error("git command failed", + "command", cmdStr, + "error", err) return "", fmt.Errorf("git command failed: %w", err) } + + outputLen := len(out) + logger.Debug("git command completed", + "command", cmdStr, + "output_length", outputLen) + return string(out), nil } func IsRepo() bool { + logger.Debug("checking if directory is a git repository") _, err := exec.Command("git", "rev-parse", "--is-inside-work-tree").Output() - return err == nil + isRepo := err == nil + logger.Debug("git repository check completed", "is_repo", isRepo) + return isRepo } diff --git a/internal/grok/client.go b/internal/grok/client.go index 757b523..9439ba7 100644 --- a/internal/grok/client.go +++ b/internal/grok/client.go @@ -13,6 +13,7 @@ import ( "time" "github.com/fatih/color" + "gmgauthier.com/grokkit/internal/logger" ) type Client struct { @@ -48,7 +49,15 @@ func (c *Client) StreamSilent(messages []map[string]string, model string) string } func (c *Client) streamInternal(messages []map[string]string, model string, temperature float64, printLive bool) string { + startTime := time.Now() url := c.BaseURL + "/chat/completions" + + logger.Debug("preparing API request", + "model", model, + "temperature", temperature, + "message_count", len(messages), + "stream", true) + payload := map[string]interface{}{ "model": model, "messages": messages, @@ -58,6 +67,7 @@ func (c *Client) streamInternal(messages []map[string]string, model string, temp body, err := json.Marshal(payload) if err != nil { + logger.Error("failed to marshal API request", "error", err) color.Red("Failed to marshal request: %v", err) os.Exit(1) } @@ -67,21 +77,34 @@ func (c *Client) streamInternal(messages []map[string]string, model string, temp req, err := http.NewRequestWithContext(ctx, "POST", url, bytes.NewReader(body)) if err != nil { + logger.Error("failed to create HTTP request", "error", err, "url", url) color.Red("Failed to create request: %v", err) os.Exit(1) } req.Header.Set("Authorization", "Bearer "+c.APIKey) req.Header.Set("Content-Type", "application/json") + logger.Info("sending API request", "model", model, "url", url) + resp, err := http.DefaultClient.Do(req) if err != nil { + logger.Error("API request failed", + "error", err, + "model", model, + "duration_ms", time.Since(startTime).Milliseconds()) color.Red("Request failed: %v", err) os.Exit(1) } defer resp.Body.Close() + logger.Debug("API response received", + "status", resp.Status, + "status_code", resp.StatusCode, + "duration_ms", time.Since(startTime).Milliseconds()) + var fullReply strings.Builder scanner := bufio.NewScanner(resp.Body) + chunkCount := 0 for scanner.Scan() { line := scanner.Text() if strings.HasPrefix(line, "data: ") { @@ -94,6 +117,7 @@ func (c *Client) streamInternal(messages []map[string]string, model string, temp if choices, ok := chunk["choices"].([]any); ok && len(choices) > 0 { if delta, ok := choices[0].(map[string]any)["delta"].(map[string]any); ok { if content, ok := delta["content"].(string); ok && content != "" { + chunkCount++ fullReply.WriteString(content) if printLive { fmt.Print(content) @@ -107,6 +131,17 @@ func (c *Client) streamInternal(messages []map[string]string, model string, temp if printLive { fmt.Println() } + + responseLength := fullReply.Len() + duration := time.Since(startTime) + + logger.Info("API request completed", + "model", model, + "response_length", responseLength, + "chunks_received", chunkCount, + "duration_ms", duration.Milliseconds(), + "duration", duration.String()) + return fullReply.String() } diff --git a/internal/logger/logger.go b/internal/logger/logger.go index 67204ac..91a2f9b 100644 --- a/internal/logger/logger.go +++ b/internal/logger/logger.go @@ -1,19 +1,20 @@ package logger import ( - "fmt" - "log" + "context" + "io" + "log/slog" "os" "path/filepath" ) var ( - infoLog *log.Logger - errorLog *log.Logger - debugLog *log.Logger + logger *slog.Logger + level = new(slog.LevelVar) // Allows dynamic level changes ) -func Init() error { +// Init initializes the logger with the specified log level +func Init(logLevel string) error { home, err := os.UserHomeDir() if err != nil { home = "." @@ -21,36 +22,100 @@ func Init() error { logDir := filepath.Join(home, ".config", "grokkit") if err := os.MkdirAll(logDir, 0755); err != nil { - return fmt.Errorf("failed to create log directory: %w", err) + return err } logFile := filepath.Join(logDir, "grokkit.log") file, err := os.OpenFile(logFile, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0644) if err != nil { - return fmt.Errorf("failed to open log file: %w", err) + return err } - infoLog = log.New(file, "INFO: ", log.Ldate|log.Ltime|log.Lshortfile) - errorLog = log.New(file, "ERROR: ", log.Ldate|log.Ltime|log.Lshortfile) - debugLog = log.New(file, "DEBUG: ", log.Ldate|log.Ltime|log.Lshortfile) + // Parse log level + switch logLevel { + case "debug": + level.Set(slog.LevelDebug) + case "info": + level.Set(slog.LevelInfo) + case "warn": + level.Set(slog.LevelWarn) + case "error": + level.Set(slog.LevelError) + default: + level.Set(slog.LevelInfo) + } + + // Create multi-writer for both file and stderr (if debug) + var w io.Writer = file + if logLevel == "debug" { + w = io.MultiWriter(file, os.Stderr) + } + + // Use JSON handler for structured logging + handler := slog.NewJSONHandler(w, &slog.HandlerOptions{ + Level: level, + }) + + logger = slog.New(handler) + slog.SetDefault(logger) return nil } -func Info(format string, v ...interface{}) { - if infoLog != nil { - infoLog.Output(2, fmt.Sprintf(format, v...)) +// SetLevel changes the log level dynamically +func SetLevel(logLevel string) { + switch logLevel { + case "debug": + level.Set(slog.LevelDebug) + case "info": + level.Set(slog.LevelInfo) + case "warn": + level.Set(slog.LevelWarn) + case "error": + level.Set(slog.LevelError) } } -func Error(format string, v ...interface{}) { - if errorLog != nil { - errorLog.Output(2, fmt.Sprintf(format, v...)) +// Debug logs at debug level with structured fields +func Debug(msg string, args ...any) { + if logger != nil { + logger.Debug(msg, args...) } } -func Debug(format string, v ...interface{}) { - if debugLog != nil { - debugLog.Output(2, fmt.Sprintf(format, v...)) +// Info logs at info level with structured fields +func Info(msg string, args ...any) { + if logger != nil { + logger.Info(msg, args...) } } + +// Warn logs at warn level with structured fields +func Warn(msg string, args ...any) { + if logger != nil { + logger.Warn(msg, args...) + } +} + +// Error logs at error level with structured fields +func Error(msg string, args ...any) { + if logger != nil { + logger.Error(msg, args...) + } +} + +// With returns a logger with additional context fields +func With(args ...any) *slog.Logger { + if logger != nil { + return logger.With(args...) + } + return slog.Default() +} + +// WithContext returns a logger with values from context +func WithContext(ctx context.Context) *slog.Logger { + if logger != nil { + return logger.With(slog.Any("context", ctx)) + } + return slog.Default() +} diff --git a/internal/logger/logger_test.go b/internal/logger/logger_test.go index 5c6f7a6..3d312bb 100644 --- a/internal/logger/logger_test.go +++ b/internal/logger/logger_test.go @@ -3,6 +3,7 @@ package logger import ( "os" "path/filepath" + "strings" "testing" ) @@ -13,15 +14,30 @@ func TestInit(t *testing.T) { os.Setenv("HOME", tmpDir) defer os.Setenv("HOME", oldHome) - err := Init() - if err != nil { - t.Errorf("Init() unexpected error: %v", err) + tests := []struct { + name string + logLevel string + }{ + {"default level", "info"}, + {"debug level", "debug"}, + {"warn level", "warn"}, + {"error level", "error"}, + {"invalid level defaults to info", "invalid"}, } - // Check log file was created - logFile := filepath.Join(tmpDir, ".config", "grokkit", "grokkit.log") - if _, err := os.Stat(logFile); os.IsNotExist(err) { - t.Errorf("Log file not created at %s", logFile) + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + err := Init(tt.logLevel) + if err != nil { + t.Errorf("Init(%q) unexpected error: %v", tt.logLevel, err) + } + + // Check log file was created + logFile := filepath.Join(tmpDir, ".config", "grokkit", "grokkit.log") + if _, err := os.Stat(logFile); os.IsNotExist(err) { + t.Errorf("Log file not created at %s", logFile) + } + }) } } @@ -31,14 +47,15 @@ func TestLogging(t *testing.T) { os.Setenv("HOME", tmpDir) defer os.Setenv("HOME", oldHome) - if err := Init(); err != nil { + if err := Init("debug"); err != nil { t.Fatalf("Init() failed: %v", err) } - // These should not panic - Info("test info message") - Error("test error message") - Debug("test debug message") + // Test all log levels with structured fields + Debug("test debug message", "key", "value") + Info("test info message", "count", 42) + Warn("test warn message", "enabled", true) + Error("test error message", "error", "something went wrong") // Verify log file has content logFile := filepath.Join(tmpDir, ".config", "grokkit", "grokkit.log") @@ -49,4 +66,58 @@ func TestLogging(t *testing.T) { if len(content) == 0 { t.Errorf("Log file is empty") } + + // Check for JSON structure (slog uses JSON handler) + contentStr := string(content) + if !strings.Contains(contentStr, `"level"`) { + t.Errorf("Log content doesn't contain JSON level field") + } + if !strings.Contains(contentStr, `"msg"`) { + t.Errorf("Log content doesn't contain JSON msg field") + } +} + +func TestSetLevel(t *testing.T) { + tmpDir := t.TempDir() + oldHome := os.Getenv("HOME") + os.Setenv("HOME", tmpDir) + defer os.Setenv("HOME", oldHome) + + if err := Init("info"); err != nil { + t.Fatalf("Init() failed: %v", err) + } + + // Change level to debug + SetLevel("debug") + + // Log at debug level + Debug("debug after level change", "test", true) + + // Verify log file has the debug message + logFile := filepath.Join(tmpDir, ".config", "grokkit", "grokkit.log") + content, err := os.ReadFile(logFile) + if err != nil { + t.Errorf("Failed to read log file: %v", err) + } + + if !strings.Contains(string(content), "debug after level change") { + t.Errorf("Debug message not found after level change") + } +} + +func TestWith(t *testing.T) { + tmpDir := t.TempDir() + oldHome := os.Getenv("HOME") + os.Setenv("HOME", tmpDir) + defer os.Setenv("HOME", oldHome) + + if err := Init("info"); err != nil { + t.Fatalf("Init() failed: %v", err) + } + + // Create logger with context + contextLogger := With("request_id", "123", "user", "testuser") + if contextLogger == nil { + t.Errorf("With() returned nil logger") + } }