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
This commit is contained in:
Greg Gauthier 2026-03-01 12:35:21 +00:00
parent d9ebe20ae4
commit 8b6449c947
8 changed files with 294 additions and 38 deletions

View File

@ -25,6 +25,7 @@ grokkit --help
default_model = "grok-4" default_model = "grok-4"
temperature = 0.7 temperature = 0.7
timeout = 60 # seconds timeout = 60 # seconds
log_level = "info" # debug, info, warn, error
[aliases] [aliases]
beta = "grok-beta-2" beta = "grok-beta-2"
@ -33,6 +34,8 @@ beta = "grok-beta-2"
history_file = "~/.config/grokkit/chat_history.json" history_file = "~/.config/grokkit/chat_history.json"
``` ```
Logs are written to `~/.config/grokkit/grokkit.log` in JSON format for structured analysis.
## Commands ## Commands
### 💬 `grokkit chat` ### 💬 `grokkit chat`
@ -107,19 +110,43 @@ grokkit completion powershell > grokkit.ps1
## Flags ## Flags
- `--model, -m`: Specify model (e.g., grok-4, grok-beta) - `--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 ## Features
- ✅ **Structured logging with slog** - JSON logs with request tracing, timing, and context
- ✅ Context-aware HTTP requests with timeouts - ✅ Context-aware HTTP requests with timeouts
- ✅ Comprehensive error handling and logging - ✅ Comprehensive error handling and custom error types
- ✅ Persistent chat history - ✅ Persistent chat history across sessions
- ✅ Configurable temperature and parameters - ✅ Configurable temperature and parameters
- ✅ Shell completions (bash, zsh, fish, powershell) - ✅ Shell completions (bash, zsh, fish, powershell)
- ✅ Test coverage >70% - ✅ Test coverage >70%
- ✅ CI/CD with GitHub Actions - ✅ CI/CD with Gitea Actions
- ✅ Interface-based design for testability - ✅ 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 ## Development
```bash ```bash

View File

@ -10,6 +10,7 @@ import (
"github.com/spf13/cobra" "github.com/spf13/cobra"
"gmgauthier.com/grokkit/config" "gmgauthier.com/grokkit/config"
"gmgauthier.com/grokkit/internal/grok" "gmgauthier.com/grokkit/internal/grok"
"gmgauthier.com/grokkit/internal/logger"
) )
var editCmd = &cobra.Command{ var editCmd = &cobra.Command{
@ -23,23 +24,34 @@ var editCmd = &cobra.Command{
modelFlag, _ := cmd.Flags().GetString("model") modelFlag, _ := cmd.Flags().GetString("model")
model := config.GetModel(modelFlag) model := config.GetModel(modelFlag)
logger.Info("edit command started",
"file", filePath,
"instruction", instruction,
"model", model)
if _, err := os.Stat(filePath); os.IsNotExist(err) { if _, err := os.Stat(filePath); os.IsNotExist(err) {
logger.Error("file not found", "file", filePath, "error", err)
color.Red("File not found: %s", filePath) color.Red("File not found: %s", filePath)
os.Exit(1) os.Exit(1)
} }
original, err := os.ReadFile(filePath) original, err := os.ReadFile(filePath)
if err != nil { if err != nil {
logger.Error("failed to read file", "file", filePath, "error", err)
color.Red("Failed to read file: %v", err) color.Red("Failed to read file: %v", err)
os.Exit(1) os.Exit(1)
} }
logger.Debug("file read successfully", "file", filePath, "size_bytes", len(original))
cleanedOriginal := removeLastModifiedComments(string(original)) cleanedOriginal := removeLastModifiedComments(string(original))
backupPath := filePath + ".bak" backupPath := filePath + ".bak"
logger.Debug("creating backup", "backup_path", backupPath)
if err := os.WriteFile(backupPath, original, 0644); err != nil { 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) color.Red("Failed to create backup: %v", err)
os.Exit(1) os.Exit(1)
} }
logger.Info("backup created", "backup_path", backupPath)
client := grok.NewClient() client := grok.NewClient()
messages := []map[string]string{ messages := []map[string]string{
@ -65,10 +77,17 @@ var editCmd = &cobra.Command{
return return
} }
logger.Debug("applying changes", "file", filePath, "new_size_bytes", len(newContent))
if err := os.WriteFile(filePath, []byte(newContent), 0644); err != nil { 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) color.Red("Failed to write file: %v", err)
os.Exit(1) 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) color.Green("✅ Applied successfully! Backup: %s", backupPath)
}, },
} }

View File

@ -14,7 +14,18 @@ var rootCmd = &cobra.Command{
Long: `A fast, native Go CLI for Grok. Chat, edit files, and supercharge your git workflow.`, Long: `A fast, native Go CLI for Grok. Chat, edit files, and supercharge your git workflow.`,
PersistentPreRun: func(cmd *cobra.Command, args []string) { PersistentPreRun: func(cmd *cobra.Command, args []string) {
config.Load() 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 // Add model flag to all commands
rootCmd.PersistentFlags().StringP("model", "m", "", "Grok model to use (overrides config)") 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")
} }

View File

@ -23,6 +23,8 @@ func Load() {
viper.SetDefault("default_model", "grok-4") viper.SetDefault("default_model", "grok-4")
viper.SetDefault("temperature", 0.7) viper.SetDefault("temperature", 0.7)
viper.SetDefault("log_level", "info")
viper.SetDefault("timeout", 60)
// Config file is optional, so we ignore read errors // Config file is optional, so we ignore read errors
_ = viper.ReadInConfig() _ = viper.ReadInConfig()
@ -49,3 +51,7 @@ func GetTimeout() int {
} }
return timeout return timeout
} }
func GetLogLevel() string {
return viper.GetString("log_level")
}

View File

@ -3,17 +3,35 @@ package git
import ( import (
"fmt" "fmt"
"os/exec" "os/exec"
"strings"
"gmgauthier.com/grokkit/internal/logger"
) )
func Run(args []string) (string, error) { 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() out, err := exec.Command("git", args...).Output()
if err != nil { if err != nil {
logger.Error("git command failed",
"command", cmdStr,
"error", err)
return "", fmt.Errorf("git command failed: %w", 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 return string(out), nil
} }
func IsRepo() bool { func IsRepo() bool {
logger.Debug("checking if directory is a git repository")
_, err := exec.Command("git", "rev-parse", "--is-inside-work-tree").Output() _, 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
} }

View File

@ -13,6 +13,7 @@ import (
"time" "time"
"github.com/fatih/color" "github.com/fatih/color"
"gmgauthier.com/grokkit/internal/logger"
) )
type Client struct { 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 { func (c *Client) streamInternal(messages []map[string]string, model string, temperature float64, printLive bool) string {
startTime := time.Now()
url := c.BaseURL + "/chat/completions" url := c.BaseURL + "/chat/completions"
logger.Debug("preparing API request",
"model", model,
"temperature", temperature,
"message_count", len(messages),
"stream", true)
payload := map[string]interface{}{ payload := map[string]interface{}{
"model": model, "model": model,
"messages": messages, "messages": messages,
@ -58,6 +67,7 @@ func (c *Client) streamInternal(messages []map[string]string, model string, temp
body, err := json.Marshal(payload) body, err := json.Marshal(payload)
if err != nil { if err != nil {
logger.Error("failed to marshal API request", "error", err)
color.Red("Failed to marshal request: %v", err) color.Red("Failed to marshal request: %v", err)
os.Exit(1) 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)) req, err := http.NewRequestWithContext(ctx, "POST", url, bytes.NewReader(body))
if err != nil { if err != nil {
logger.Error("failed to create HTTP request", "error", err, "url", url)
color.Red("Failed to create request: %v", err) color.Red("Failed to create request: %v", err)
os.Exit(1) os.Exit(1)
} }
req.Header.Set("Authorization", "Bearer "+c.APIKey) req.Header.Set("Authorization", "Bearer "+c.APIKey)
req.Header.Set("Content-Type", "application/json") req.Header.Set("Content-Type", "application/json")
logger.Info("sending API request", "model", model, "url", url)
resp, err := http.DefaultClient.Do(req) resp, err := http.DefaultClient.Do(req)
if err != nil { if err != nil {
logger.Error("API request failed",
"error", err,
"model", model,
"duration_ms", time.Since(startTime).Milliseconds())
color.Red("Request failed: %v", err) color.Red("Request failed: %v", err)
os.Exit(1) os.Exit(1)
} }
defer resp.Body.Close() 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 var fullReply strings.Builder
scanner := bufio.NewScanner(resp.Body) scanner := bufio.NewScanner(resp.Body)
chunkCount := 0
for scanner.Scan() { for scanner.Scan() {
line := scanner.Text() line := scanner.Text()
if strings.HasPrefix(line, "data: ") { 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 choices, ok := chunk["choices"].([]any); ok && len(choices) > 0 {
if delta, ok := choices[0].(map[string]any)["delta"].(map[string]any); ok { if delta, ok := choices[0].(map[string]any)["delta"].(map[string]any); ok {
if content, ok := delta["content"].(string); ok && content != "" { if content, ok := delta["content"].(string); ok && content != "" {
chunkCount++
fullReply.WriteString(content) fullReply.WriteString(content)
if printLive { if printLive {
fmt.Print(content) fmt.Print(content)
@ -107,6 +131,17 @@ func (c *Client) streamInternal(messages []map[string]string, model string, temp
if printLive { if printLive {
fmt.Println() 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() return fullReply.String()
} }

View File

@ -1,19 +1,20 @@
package logger package logger
import ( import (
"fmt" "context"
"log" "io"
"log/slog"
"os" "os"
"path/filepath" "path/filepath"
) )
var ( var (
infoLog *log.Logger logger *slog.Logger
errorLog *log.Logger level = new(slog.LevelVar) // Allows dynamic level changes
debugLog *log.Logger
) )
func Init() error { // Init initializes the logger with the specified log level
func Init(logLevel string) error {
home, err := os.UserHomeDir() home, err := os.UserHomeDir()
if err != nil { if err != nil {
home = "." home = "."
@ -21,36 +22,100 @@ func Init() error {
logDir := filepath.Join(home, ".config", "grokkit") logDir := filepath.Join(home, ".config", "grokkit")
if err := os.MkdirAll(logDir, 0755); err != nil { 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") logFile := filepath.Join(logDir, "grokkit.log")
file, err := os.OpenFile(logFile, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0644) file, err := os.OpenFile(logFile, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0644)
if err != nil { 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) // Parse log level
errorLog = log.New(file, "ERROR: ", log.Ldate|log.Ltime|log.Lshortfile) switch logLevel {
debugLog = log.New(file, "DEBUG: ", log.Ldate|log.Ltime|log.Lshortfile) 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 return nil
} }
func Info(format string, v ...interface{}) { // SetLevel changes the log level dynamically
if infoLog != nil { func SetLevel(logLevel string) {
infoLog.Output(2, fmt.Sprintf(format, v...)) 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{}) { // Debug logs at debug level with structured fields
if errorLog != nil { func Debug(msg string, args ...any) {
errorLog.Output(2, fmt.Sprintf(format, v...)) if logger != nil {
logger.Debug(msg, args...)
} }
} }
func Debug(format string, v ...interface{}) { // Info logs at info level with structured fields
if debugLog != nil { func Info(msg string, args ...any) {
debugLog.Output(2, fmt.Sprintf(format, v...)) 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()
}

View File

@ -3,6 +3,7 @@ package logger
import ( import (
"os" "os"
"path/filepath" "path/filepath"
"strings"
"testing" "testing"
) )
@ -13,15 +14,30 @@ func TestInit(t *testing.T) {
os.Setenv("HOME", tmpDir) os.Setenv("HOME", tmpDir)
defer os.Setenv("HOME", oldHome) defer os.Setenv("HOME", oldHome)
err := Init() tests := []struct {
if err != nil { name string
t.Errorf("Init() unexpected error: %v", err) 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 for _, tt := range tests {
logFile := filepath.Join(tmpDir, ".config", "grokkit", "grokkit.log") t.Run(tt.name, func(t *testing.T) {
if _, err := os.Stat(logFile); os.IsNotExist(err) { err := Init(tt.logLevel)
t.Errorf("Log file not created at %s", logFile) 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) os.Setenv("HOME", tmpDir)
defer os.Setenv("HOME", oldHome) defer os.Setenv("HOME", oldHome)
if err := Init(); err != nil { if err := Init("debug"); err != nil {
t.Fatalf("Init() failed: %v", err) t.Fatalf("Init() failed: %v", err)
} }
// These should not panic // Test all log levels with structured fields
Info("test info message") Debug("test debug message", "key", "value")
Error("test error message") Info("test info message", "count", 42)
Debug("test debug message") Warn("test warn message", "enabled", true)
Error("test error message", "error", "something went wrong")
// Verify log file has content // Verify log file has content
logFile := filepath.Join(tmpDir, ".config", "grokkit", "grokkit.log") logFile := filepath.Join(tmpDir, ".config", "grokkit", "grokkit.log")
@ -49,4 +66,58 @@ func TestLogging(t *testing.T) {
if len(content) == 0 { if len(content) == 0 {
t.Errorf("Log file is empty") 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")
}
} }