Merge pull request 'feat: replace log.Printf with structured slog logging' (#36) from feat/23-structured-logging into main

cmd/review-bot/main.go

@@ -4,7 +4,7 @@ import (
 	"context"
 	"flag"
 	"fmt"
-	"log"
+	"log/slog"
 	"os"
 	"path/filepath"
 	"strconv"
@@ -19,8 +19,40 @@ import (
 
 var version = "dev"
 
+// setupLogger configures the global slog default logger based on format and verbosity.
+func setupLogger(format, verbosity string) {
+	var level slog.Level
+	switch strings.ToLower(verbosity) {
+	case "debug":
+		level = slog.LevelDebug
+	case "info":
+		level = slog.LevelInfo
+	case "warn":
+		level = slog.LevelWarn
+	case "error":
+		level = slog.LevelError
+	default:
+		level = slog.LevelInfo
+	}
+
+	opts := &slog.HandlerOptions{Level: level}
+
+	var handler slog.Handler
+	switch strings.ToLower(format) {
+	case "json":
+		handler = slog.NewJSONHandler(os.Stderr, opts)
+	default:
+		handler = slog.NewTextHandler(os.Stderr, opts)
+	}
+
+	slog.SetDefault(slog.New(handler))
+}
+
 func main() {
 	versionFlag := flag.Bool("version", false, "Print version and exit")
+	// Logging flags
+	logFormat := flag.String("log-format", envOrDefault("LOG_FORMAT", "text"), "Log output format: text or json")
+	verbosity := flag.String("verbosity", envOrDefault("LOG_VERBOSITY", "info"), "Log verbosity: debug, info, warn, error")
 	// CLI flags
 	giteaURL := flag.String("gitea-url", envOrDefault("GITEA_URL", ""), "Gitea instance URL")
 	repo := flag.String("repo", envOrDefault("GITEA_REPO", ""), "Repository (owner/name)")
@@ -47,7 +79,10 @@ func main() {
 		os.Exit(0)
 	}
 
-	log.Printf("review-bot %s", version)
+	// Initialize structured logger
+	setupLogger(*logFormat, *verbosity)
+
+	slog.Info("review-bot starting", "version", version)
 
 	// Validate required fields
 	if *giteaURL == "" || *repo == "" || *prNum == "" || *reviewerToken == "" ||
@@ -59,27 +94,31 @@ func main() {
 
 	// Validate reviewer-name: only safe characters allowed in sentinel
 	if err := validateReviewerName(*reviewerName); err != nil {
-		log.Fatalf("%v", err)
+		slog.Error("invalid reviewer name", "error", err)
+		os.Exit(1)
 	}
 
 	// Parse repo owner/name
 	parts := strings.SplitN(*repo, "/", 2)
 	if len(parts) != 2 {
-		log.Fatalf("Invalid repo format %q, expected owner/name", *repo)
+		slog.Error("invalid repo format", "repo", *repo, "expected", "owner/name")
+		os.Exit(1)
 	}
 	owner, repoName := parts[0], parts[1]
 
 	// Parse PR number
 	prNumber, err := strconv.Atoi(*prNum)
 	if err != nil {
-		log.Fatalf("Invalid PR number %q: %v", *prNum, err)
+		slog.Error("invalid PR number", "pr", *prNum, "error", err)
+		os.Exit(1)
 	}
 
 	// Initialize clients
 	giteaClient := gitea.NewClient(*giteaURL, *reviewerToken)
 	llmClient := llm.NewClient(*llmBaseURL, *llmAPIKey, *llmModel)
 	if *llmTemp < 0 || *llmTemp > 2 {
-		log.Fatal("--llm-temperature must be between 0 and 2")
+		slog.Error("invalid LLM temperature", "temperature", *llmTemp, "range", "0-2")
+		os.Exit(1)
 	}
 	if *llmTemp > 0 {
 		llmClient.WithTemperature(*llmTemp)
@@ -88,7 +127,8 @@ func main() {
 	case llm.ProviderOpenAI, llm.ProviderAnthropic:
 		llmClient.WithProvider(llm.Provider(*llmProvider))
 	default:
-		log.Fatalf("Invalid --llm-provider %q, must be openai or anthropic", *llmProvider)
+		slog.Error("invalid LLM provider", "provider", *llmProvider, "valid", "openai, anthropic")
+		os.Exit(1)
 	}
 	if *llmTimeout > 0 {
 		llmClient.WithTimeout(time.Duration(*llmTimeout) * time.Second)
@@ -99,30 +139,32 @@ func main() {
 	ctx, cancel := context.WithTimeout(context.Background(), overallTimeout)
 	defer cancel()
 
-	log.Printf("Reviewing PR #%d on %s/%s", prNumber, owner, repoName)
+	slog.Info("reviewing pull request", "pr", prNumber, "repo", fmt.Sprintf("%s/%s", owner, repoName))
 
 	// Step 1: Fetch PR metadata
 	pr, err := giteaClient.GetPullRequest(ctx, owner, repoName, prNumber)
 	if err != nil {
-		log.Fatalf("Failed to fetch PR: %v", err)
+		slog.Error("failed to fetch PR", "pr", prNumber, "error", err)
+		os.Exit(1)
 	}
-	log.Printf("PR: %s", pr.Title)
+	slog.Info("fetched PR metadata", "pr", prNumber, "title", pr.Title)
 
 	// Step 2: Fetch diff
 	diff, err := giteaClient.GetPullRequestDiff(ctx, owner, repoName, prNumber)
 	if err != nil {
-		log.Fatalf("Failed to fetch diff: %v", err)
+		slog.Error("failed to fetch diff", "pr", prNumber, "error", err)
+		os.Exit(1)
 	}
-	log.Printf("Diff size: %d bytes", len(diff))
+	slog.Info("fetched diff", "bytes", len(diff))
 
 	// Step 3: Fetch full file content for modified files
 	fileContext := ""
 	files, err := giteaClient.GetPullRequestFiles(ctx, owner, repoName, prNumber)
 	if err != nil {
-		log.Printf("Warning: could not fetch PR files list: %v", err)
+		slog.Warn("could not fetch PR files list", "pr", prNumber, "error", err)
 	} else {
 		fileContext = fetchFileContext(ctx, giteaClient, owner, repoName, pr.Head.Ref, files)
-		log.Printf("Fetched full context for %d files", len(files))
+		slog.Debug("fetched file context", "files", len(files))
 	}
 
 	// Step 4: Check CI status
@@ -131,10 +173,10 @@ func main() {
 	if pr.Head.Sha != "" {
 		statuses, err := giteaClient.GetCommitStatuses(ctx, owner, repoName, pr.Head.Sha)
 		if err != nil {
-			log.Printf("Warning: could not fetch CI status: %v", err)
+			slog.Warn("could not fetch CI status", "sha", pr.Head.Sha, "error", err)
 		} else {
 			ciPassed, ciDetails = evaluateCIStatus(statuses)
-			log.Printf("CI status: passed=%v", ciPassed)
+			slog.Info("CI status checked", "passed", ciPassed)
 		}
 	}
 
@@ -143,10 +185,10 @@ func main() {
 	if *conventionsFile != "" {
 		content, err := giteaClient.GetFileContent(ctx, owner, repoName, *conventionsFile)
 		if err != nil {
-			log.Printf("Warning: could not load conventions file %q: %v", *conventionsFile, err)
+			slog.Warn("could not load conventions file", "file", *conventionsFile, "error", err)
 		} else {
 			conventions = content
-			log.Printf("Loaded conventions file: %s (%d bytes)", *conventionsFile, len(conventions))
+			slog.Debug("loaded conventions file", "file", *conventionsFile, "bytes", len(conventions))
 		}
 	}
 
@@ -154,7 +196,7 @@ func main() {
 	patterns := ""
 	if *patternsRepo != "" {
 		patterns = fetchPatterns(ctx, giteaClient, *patternsRepo, *patternsFiles)
-		log.Printf("Loaded patterns from %s (%d bytes)", *patternsRepo, len(patterns))
+		slog.Debug("loaded patterns", "repo", *patternsRepo, "bytes", len(patterns))
 	}
 
 	// Step 6b: Load additional system prompt if specified
@@ -166,27 +208,32 @@ func main() {
 		}
 		absWorkspace, err := filepath.Abs(workspace)
 		if err != nil {
-			log.Fatalf("Failed to resolve workspace path: %v", err)
+			slog.Error("failed to resolve workspace path", "error", err)
+			os.Exit(1)
 		}
 		promptPath := filepath.Join(absWorkspace, *systemPromptFile)
 		promptPath = filepath.Clean(promptPath)
 		if !strings.HasPrefix(promptPath, absWorkspace+string(filepath.Separator)) && promptPath != absWorkspace {
-			log.Fatalf("system-prompt-file resolves outside workspace (got %q, workspace %q)", promptPath, absWorkspace)
+			slog.Error("system-prompt-file resolves outside workspace", "path", promptPath, "workspace", absWorkspace)
+			os.Exit(1)
 		}
 		// Resolve symlinks and re-validate to prevent symlink traversal
 		resolvedPath, err := filepath.EvalSymlinks(promptPath)
 		if err != nil {
-			log.Fatalf("Failed to resolve system prompt file %q: %v", promptPath, err)
+			slog.Error("failed to resolve system prompt file", "path", promptPath, "error", err)
+			os.Exit(1)
 		}
 		if !strings.HasPrefix(resolvedPath, absWorkspace+string(filepath.Separator)) && resolvedPath != absWorkspace {
-			log.Fatalf("system-prompt-file symlink resolves outside workspace (got %q, workspace %q)", resolvedPath, absWorkspace)
+			slog.Error("system-prompt-file symlink resolves outside workspace", "resolved", resolvedPath, "workspace", absWorkspace)
+			os.Exit(1)
 		}
 		data, err := os.ReadFile(resolvedPath)
 		if err != nil {
-			log.Fatalf("Failed to read system prompt file %q: %v", promptPath, err)
+			slog.Error("failed to read system prompt file", "path", promptPath, "error", err)
+			os.Exit(1)
 		}
 		additionalPrompt = string(data)
-		log.Printf("Loaded system prompt file: %s (%d bytes)", *systemPromptFile, len(additionalPrompt))
+		slog.Debug("loaded system prompt file", "file", *systemPromptFile, "bytes", len(additionalPrompt))
 	}
 
 	// Step 7: Budget-aware prompt assembly
@@ -203,13 +250,13 @@ func main() {
 		UserMeta:    review.BuildUserMeta(pr.Title, pr.Body, ciPassed, ciDetails),
 	}
 	budgetResult := budget.Fit(*llmModel, sections)
-	log.Printf("Token estimate: ~%dK (limit: %dK)", budgetResult.EstTokens/1000, budget.LimitForModel(*llmModel)/1000)
+	slog.Info("token budget calculated", "tokens", budgetResult.EstTokens, "limit", budget.LimitForModel(*llmModel), "model", *llmModel)
 	if len(budgetResult.Trimmed) > 0 {
-		log.Printf("Context trimmed: %v", budgetResult.Trimmed)
+		slog.Warn("context trimmed to fit budget", "trimmed", budgetResult.Trimmed)
 	}
 
 	// Step 8: Call LLM
-	log.Printf("Sending to LLM (%s)...", *llmModel)
+	slog.Info("sending request to LLM", "model", *llmModel)
 	messages := []llm.Message{
 		{Role: "system", Content: budgetResult.SystemPrompt},
 		{Role: "user", Content: budgetResult.UserPrompt},
@@ -217,16 +264,18 @@ func main() {
 
 	response, err := llmClient.Complete(ctx, messages)
 	if err != nil {
-		log.Fatalf("LLM request failed: %v", err)
+		slog.Error("LLM request failed", "model", *llmModel, "error", err)
+		os.Exit(1)
 	}
-	log.Printf("LLM response received (%d bytes)", len(response))
+	slog.Info("LLM response received", "bytes", len(response))
 
 	// Step 9: Parse response
 	result, err := review.ParseResponse(response)
 	if err != nil {
-		log.Fatalf("Failed to parse LLM response: %v", err)
+		slog.Error("failed to parse LLM response", "error", err)
+		os.Exit(1)
 	}
-	log.Printf("Verdict: %s (%d findings)", result.Verdict, len(result.Findings))
+	slog.Info("review parsed", "verdict", result.Verdict, "findings", len(result.Findings))
 
 	// Step 10: Format and post review
 	reviewBody := review.FormatMarkdown(result, *reviewerName)
@@ -254,7 +303,7 @@ func main() {
 		}
 	}
 	if len(inlineComments) > 0 {
-		log.Printf("Attaching %d inline comments", len(inlineComments))
+		slog.Debug("attaching inline comments", "count", len(inlineComments))
 	}
 
 	// --- Review update strategy ---
@@ -264,19 +313,19 @@ func main() {
 	if *updateExisting && *reviewerName != "" {
 		existingReviews, err := giteaClient.ListReviews(ctx, owner, repoName, prNumber)
 		if err != nil {
-			log.Printf("Warning: could not list existing reviews: %v", err)
+			slog.Warn("could not list existing reviews", "pr", prNumber, "error", err)
 		} else {
 			// Detect shared-token misconfiguration: if detected, skip all
 			// update logic (PATCH/supersede) to avoid clobbering a sibling's review.
 			sharedToken := hasSharedToken(existingReviews, sentinel)
 			if sharedToken {
-				log.Printf("Shared token mode: skipping update-in-place logic to avoid clobbering sibling review")
+				slog.Warn("shared token mode: skipping update-in-place logic to avoid clobbering sibling review")
 			} else {
 				existing := findOwnReview(existingReviews, sentinel)
 
 				if existing != nil {
 					if reviewUnchanged(existingReviews, reviewBody, event, sentinel) {
-						log.Printf("Review unchanged from previous run; skipping to preserve threads")
+						slog.Info("review unchanged from previous run; skipping to preserve threads", "pr", prNumber)
 						return
 					}
 
@@ -284,12 +333,12 @@ func main() {
 					if existing.State == event {
 						commentID, err := giteaClient.GetTimelineReviewCommentID(ctx, owner, repoName, prNumber, sentinel)
 						if err != nil {
-							log.Printf("Warning: could not find review comment ID, falling back to new post: %v", err)
+							slog.Warn("could not find review comment ID, falling back to new post", "error", err)
 						} else {
 							if err := giteaClient.EditComment(ctx, owner, repoName, commentID, reviewBody); err != nil {
-								log.Printf("Warning: could not edit review, falling back to new post: %v", err)
+								slog.Warn("could not edit review, falling back to new post", "comment_id", commentID, "error", err)
 							} else {
-								log.Printf("Review updated in place (comment_id=%d)", commentID)
+								slog.Info("review updated in place", "comment_id", commentID, "pr", prNumber)
 								return
 							}
 						}
@@ -297,13 +346,13 @@ func main() {
 						// State change → mark old as superseded, post new below
 						commentID, err := giteaClient.GetTimelineReviewCommentID(ctx, owner, repoName, prNumber, sentinel)
 						if err != nil {
-							log.Printf("Warning: could not find old review comment ID: %v", err)
+							slog.Warn("could not find old review comment ID", "error", err)
 						} else {
 							supersededBody := fmt.Sprintf("~~*This review has been superseded by a newer review below.*~~\n\n%s", sentinel)
 							if err := giteaClient.EditComment(ctx, owner, repoName, commentID, supersededBody); err != nil {
-								log.Printf("Warning: could not mark old review as superseded: %v", err)
+								slog.Warn("could not mark old review as superseded", "comment_id", commentID, "error", err)
 							} else {
-								log.Printf("Marked old review as superseded (state was %s, now %s)", existing.State, event)
+								slog.Info("marked old review as superseded", "old_state", existing.State, "new_state", event, "pr", prNumber)
 							}
 						}
 					}
@@ -313,12 +362,13 @@ func main() {
 	}
 
 	// POST new review (first run, or state transition fallthrough)
-	log.Printf("Posting review (event=%s)...", event)
+	slog.Info("posting review", "event", event, "pr", prNumber)
 	posted, err := giteaClient.PostReview(ctx, owner, repoName, prNumber, event, reviewBody, inlineComments)
 	if err != nil {
-		log.Fatalf("Failed to post review: %v", err)
+		slog.Error("failed to post review", "pr", prNumber, "event", event, "error", err)
+		os.Exit(1)
 	}
-	log.Printf("Review posted (id=%d, user=%s)", posted.ID, posted.User.Login)
+	slog.Info("review posted", "review_id", posted.ID, "user", posted.User.Login, "pr", prNumber)
 
 }
 
@@ -334,7 +384,7 @@ func fetchFileContext(ctx context.Context, client *gitea.Client, owner, repo, re
 		}
 		content, err := client.GetFileContentRef(ctx, owner, repo, f.Filename, ref)
 		if err != nil {
-			log.Printf("Warning: could not fetch %s: %v", f.Filename, err)
+			slog.Warn("could not fetch file content", "file", f.Filename, "error", err)
 			continue
 		}
 		sb.WriteString(fmt.Sprintf("--- %s ---\n", f.Filename))
@@ -365,7 +415,7 @@ func fetchPatterns(ctx context.Context, client *gitea.Client, patternsRepo, patt
 		}
 		parts := strings.SplitN(repoRef, "/", 2)
 		if len(parts) != 2 {
-			log.Printf("Warning: invalid patterns-repo format %q, expected owner/name", repoRef)
+			slog.Warn("invalid patterns-repo format", "repo", repoRef, "expected", "owner/name")
 			continue
 		}
 		owner, repo := parts[0], parts[1]
@@ -378,7 +428,7 @@ func fetchPatterns(ctx context.Context, client *gitea.Client, patternsRepo, patt
 
 			files, err := client.GetAllFilesInPath(ctx, owner, repo, path)
 			if err != nil {
-				log.Printf("Warning: could not fetch %s from %s: %v", path, repoRef, err)
+				slog.Warn("could not fetch patterns", "path", path, "repo", repoRef, "error", err)
 				continue
 			}
 
@@ -511,7 +561,8 @@ func hasSharedToken(reviews []gitea.Review, ownSentinel string) bool {
 	}
 	for _, r := range reviews {
 		if r.User.Login == ownLogin && strings.Contains(r.Body, "<!-- review-bot:") && !strings.Contains(r.Body, ownSentinel) {
-			log.Printf("WARNING: shared token detected — another review-bot role (%s) is using the same Gitea user %q. Each role should have its own token/user for proper multi-reviewer blocking.", extractSentinelName(r.Body), ownLogin)
+			slog.Warn("shared token detected — another review-bot role is using the same Gitea user",
+				"sibling_role", extractSentinelName(r.Body), "user", ownLogin)
 			return true
 		}
 	}

cmd/review-bot/main_test.go

@@ -1,6 +1,9 @@
 package main
 
 import (
+	"bytes"
+	"log/slog"
+	"strings"
 	"testing"
 
 	"gitea.weiker.me/rodin/review-bot/gitea"
@@ -268,3 +271,97 @@ func TestExtractSentinelName(t *testing.T) {
 		}
 	}
 }
+
+func TestSetupLogger_JSONFormat(t *testing.T) {
+	// Capture output by creating a logger manually with the same logic
+	var buf bytes.Buffer
+	opts := &slog.HandlerOptions{Level: slog.LevelInfo}
+	handler := slog.NewJSONHandler(&buf, opts)
+	logger := slog.New(handler)
+
+	logger.Info("test message", "key", "value")
+
+	output := buf.String()
+	if !strings.Contains(output, `"msg":"test message"`) {
+		t.Errorf("expected JSON msg field, got: %s", output)
+	}
+	if !strings.Contains(output, `"key":"value"`) {
+		t.Errorf("expected JSON key field, got: %s", output)
+	}
+	if !strings.Contains(output, `"level":"INFO"`) {
+		t.Errorf("expected JSON level field, got: %s", output)
+	}
+}
+
+func TestSetupLogger_TextFormat(t *testing.T) {
+	var buf bytes.Buffer
+	opts := &slog.HandlerOptions{Level: slog.LevelInfo}
+	handler := slog.NewTextHandler(&buf, opts)
+	logger := slog.New(handler)
+
+	logger.Info("test message", "key", "value")
+
+	output := buf.String()
+	if !strings.Contains(output, "msg=\"test message\"") && !strings.Contains(output, "msg=test") {
+		t.Errorf("expected text msg field, got: %s", output)
+	}
+	if !strings.Contains(output, "key=value") {
+		t.Errorf("expected text key field, got: %s", output)
+	}
+}
+
+func TestSetupLogger_LevelFiltering(t *testing.T) {
+	tests := []struct {
+		name      string
+		verbosity string
+		logLevel  slog.Level
+		expected  bool // should the message appear
+	}{
+		{"info logger shows info", "info", slog.LevelInfo, true},
+		{"info logger hides debug", "info", slog.LevelDebug, false},
+		{"debug logger shows debug", "debug", slog.LevelDebug, true},
+		{"warn logger hides info", "warn", slog.LevelInfo, false},
+		{"warn logger shows warn", "warn", slog.LevelWarn, true},
+		{"error logger hides warn", "error", slog.LevelWarn, false},
+		{"error logger shows error", "error", slog.LevelError, true},
+	}
+
+	for _, tc := range tests {
+		t.Run(tc.name, func(t *testing.T) {
+			var level slog.Level
+			switch tc.verbosity {
+			case "debug":
+				level = slog.LevelDebug
+			case "info":
+				level = slog.LevelInfo
+			case "warn":
+				level = slog.LevelWarn
+			case "error":
+				level = slog.LevelError
+			}
+
+			var buf bytes.Buffer
+			opts := &slog.HandlerOptions{Level: level}
+			handler := slog.NewTextHandler(&buf, opts)
+			logger := slog.New(handler)
+
+			logger.Log(nil, tc.logLevel, "test")
+
+			hasOutput := buf.Len() > 0
+			if hasOutput != tc.expected {
+				t.Errorf("verbosity=%s, logLevel=%s: got output=%v, want %v",
+					tc.verbosity, tc.logLevel, hasOutput, tc.expected)
+			}
+		})
+	}
+}
+
+func TestSetupLogger_Integration(t *testing.T) {
+	// Test that setupLogger doesn't panic for valid inputs
+	setupLogger("text", "info")
+	setupLogger("json", "debug")
+	setupLogger("text", "warn")
+	setupLogger("json", "error")
+	setupLogger("text", "unknown") // should default to info
+	setupLogger("invalid", "info") // should default to text
+}

gitea/client.go

@@ -10,7 +10,7 @@ import (
 	"errors"
 	"fmt"
 	"io"
-	"log"
+	"log/slog"
 	"net/http"
 	"net/url"
 	"strings"
@@ -296,14 +296,14 @@ func (c *Client) GetAllFilesInPath(ctx context.Context, owner, repo, path string
 		case "file":
 			content, err := c.GetFileContent(ctx, owner, repo, entry.Path)
 			if err != nil {
-				log.Printf("Warning: could not fetch file %s: %v", entry.Path, err)
+				slog.Warn("could not fetch file from patterns repo", "file", entry.Path, "error", err)
 				continue
 			}
 			results[entry.Path] = content
 		case "dir":
 			subResults, err := c.GetAllFilesInPath(ctx, owner, repo, entry.Path)
 			if err != nil {
-				log.Printf("Warning: could not recurse into %s: %v", entry.Path, err)
+				slog.Warn("could not recurse into directory", "dir", entry.Path, "error", err)
 				continue
 			}
 			for k, v := range subResults {