Initial commit

internal/logger/logger.go

@@ -0,0 +1,170 @@
+// @tag logging
+// @tag core
+package logger
+
+import (
+	"fmt"
+	"log"
+	"os"
+	"sync"
+	"time"
+)
+
+// Level represents the minimum severity for log messages.
+type Level int
+
+// Log severity levels from most verbose to most critical.
+const (
+	LevelDebug Level = iota // Debug logs everything including diagnostic messages
+	LevelInfo               // Info logs informational messages and above (default)
+	LevelWarn               // Warn logs warnings, errors, and critical messages
+	LevelError              // LevelError logs only errors and critical messages
+)
+
+var (
+	currentLevel = LevelInfo
+	logger       = log.New(os.Stdout, "", 0)
+	logFile      *os.File
+	logPath      string
+	pid          int
+	mu           sync.Once
+	loggerMu     sync.Mutex // Protects logger and logFile
+)
+
+// initPID gets the process ID for log messages
+func initPID() {
+	pid = os.Getpid()
+}
+
+// formatLog formats a message with timestamp, log level, and pid.
+// Format: timestamp level pekoe[pid]: message
+func formatLog(level string, message string) string {
+	mu.Do(initPID)
+
+	// Timestamp format: "YYYY Mmm dd hh:mm:ss"
+	// e.g., "2024 Apr  2 14:30:15"
+	now := time.Now()
+	timestamp := now.Format("2006 Jan _2 15:04:05")
+
+	// Format: timestamp level pekoe[pid]: message
+	// e.g., "2024 Apr  2 14:30:15 INFO pekoe[12345]: event=startup"
+	return fmt.Sprintf("%s %s pekoe[%d]: %s", timestamp, level, pid, message)
+}
+
+// SetOutput configures the logger to write to the specified file.
+// An empty path resets to stdout.
+// Returns an error if the file cannot be opened/created.
+// nolint: gosec
+func SetOutput(path string) error {
+	loggerMu.Lock()
+	defer loggerMu.Unlock()
+
+	// Close existing log file if any
+	if logFile != nil {
+		_ = logFile.Close()
+		logFile = nil
+	}
+
+	if path == "" {
+		logPath = ""
+		logger = log.New(os.Stdout, "", 0)
+		return nil
+	}
+
+	file, err := os.OpenFile(path, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
+	if err != nil {
+		return err
+	}
+
+	logPath = path
+	logFile = file
+	logger = log.New(file, "", 0)
+	return nil
+}
+
+// Reopen reopens the log file.
+// This is useful for log rotation - after the log file is moved/renamed,
+// sending SIGUSR1 will cause the server to reopen the log file.
+// Returns an error if the log file cannot be opened.
+func Reopen() error {
+	loggerMu.Lock()
+	defer loggerMu.Unlock()
+
+	// If logging to stdout, nothing to reopen
+	if logPath == "" {
+		return nil
+	}
+
+	// Close existing file
+	if logFile != nil {
+		_ = logFile.Close()
+		logFile = nil
+	}
+
+	// Open the file again (create if doesn't exist)
+	//nolint: gosec // logPath is configured by admin, not user input
+	file, err := os.OpenFile(logPath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644)
+	if err != nil {
+		// Fall back to stdout if we can't reopen
+		logger = log.New(os.Stdout, "", 0)
+		return fmt.Errorf("failed to reopen log file %s: %w", logPath, err)
+	}
+
+	logFile = file
+	logger = log.New(file, "", 0)
+	return nil
+}
+
+// SetLevel configures the minimum log level from a string name.
+// Accepted values: "debug", "info", "warn", "error".
+func SetLevel(level string) {
+	switch level {
+	case "debug":
+		currentLevel = LevelDebug
+	case "info":
+		currentLevel = LevelInfo
+	case "warn":
+		currentLevel = LevelWarn
+	case "error":
+		currentLevel = LevelError
+	}
+}
+
+// Debug logs a message at debug level. Uses fmt.Sprintf formatting.
+func Debug(format string, v ...any) {
+	if currentLevel <= LevelDebug {
+		msg := fmt.Sprintf(format, v...)
+		logger.Println(formatLog("DEBUG", msg))
+	}
+}
+
+// Info logs a message at info level. Uses fmt.Sprintf formatting.
+func Info(format string, v ...any) {
+	if currentLevel <= LevelInfo {
+		msg := fmt.Sprintf(format, v...)
+		logger.Println(formatLog("INFO", msg))
+	}
+}
+
+// Warn logs a message at warning level. Uses fmt.Sprintf formatting.
+func Warn(format string, v ...any) {
+	if currentLevel <= LevelWarn {
+		msg := fmt.Sprintf(format, v...)
+		logger.Println(formatLog("WARN", msg))
+	}
+}
+
+// Error logs a message at error level. Uses fmt.Sprintf formatting.
+func Error(format string, v ...any) {
+	if currentLevel <= LevelError {
+		msg := fmt.Sprintf(format, v...)
+		logger.Println(formatLog("ERROR", msg))
+	}
+}
+
+// Fatal logs a message at critical level and terminates the process with exit code 1.
+func Fatal(format string, v ...any) {
+	msg := fmt.Sprintf(format, v...)
+	logger.Println(formatLog("CRITICAL", msg))
+	os.Exit(1)
+}

internal/logger/logger_test.go

@@ -0,0 +1,359 @@
+package logger
+
+import (
+	"log"
+	"os"
+	"path/filepath"
+	"strings"
+	"testing"
+)
+
+// resetLogger restores package-level state between tests.
+func resetLogger() {
+	currentLevel = LevelInfo
+	loggerMu.Lock()
+	if logFile != nil {
+		_ = logFile.Close()
+	}
+	logFile = nil
+	logPath = ""
+	logger = log.New(os.Stdout, "", 0)
+	loggerMu.Unlock()
+}
+
+func TestSetLevel(t *testing.T) {
+	tests := []struct {
+		input string
+		want  Level
+	}{
+		{"debug", LevelDebug},
+		{"info", LevelInfo},
+		{"warn", LevelWarn},
+		{"error", LevelError},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.input, func(t *testing.T) {
+			resetLogger()
+			SetLevel(tt.input)
+			if currentLevel != tt.want {
+				t.Errorf("SetLevel(%q): got %d, want %d", tt.input, currentLevel, tt.want)
+			}
+		})
+	}
+}
+
+func TestSetLevelInvalid(t *testing.T) {
+	resetLogger()
+	SetLevel("info")
+	SetLevel("bogus")
+	if currentLevel != LevelInfo {
+		t.Errorf("invalid level changed current level: got %d, want %d", currentLevel, LevelInfo)
+	}
+}
+
+func TestSetLevelCaseSensitive(t *testing.T) {
+	resetLogger()
+	SetLevel("INFO") // uppercase should not match
+	if currentLevel != LevelInfo {
+		t.Errorf("uppercase level should not change level: got %d, want %d", currentLevel, LevelInfo)
+	}
+}
+
+func TestSetOutputToFile(t *testing.T) {
+	resetLogger()
+	dir := t.TempDir()
+	path := filepath.Join(dir, "test.log")
+
+	if err := SetOutput(path); err != nil {
+		t.Fatalf("SetOutput(%q): %v", path, err)
+	}
+
+	if logPath != path {
+		t.Errorf("logPath: got %q, want %q", logPath, path)
+	}
+	if logFile == nil {
+		t.Error("logFile should not be nil after SetOutput")
+	}
+
+	// Write something and verify it appears in the file
+	Info("test message")
+	if err := logFile.Sync(); err != nil {
+		t.Fatalf("sync: %v", err)
+	}
+
+	//nolint: gosec // test reads temp file in temp dir
+	data, err := os.ReadFile(path)
+	if err != nil {
+		t.Fatalf("ReadFile: %v", err)
+	}
+	if !strings.Contains(string(data), "test message") {
+		t.Errorf("log file should contain 'test message', got: %s", string(data))
+	}
+
+	// Close file before TempDir cleanup
+	resetLogger()
+}
+
+func TestSetOutputEmptyResetsToStdout(t *testing.T) {
+	resetLogger()
+	dir := t.TempDir()
+	path := filepath.Join(dir, "test.log")
+
+	if err := SetOutput(path); err != nil {
+		t.Fatalf("SetOutput: %v", err)
+	}
+
+	if err := SetOutput(""); err != nil {
+		t.Fatalf("SetOutput(\"\"): %v", err)
+	}
+
+	if logPath != "" {
+		t.Errorf("logPath should be empty, got %q", logPath)
+	}
+	if logFile != nil {
+		t.Error("logFile should be nil after reset to stdout")
+	}
+}
+
+func TestSetOutputInvalidPath(t *testing.T) {
+	resetLogger()
+	err := SetOutput("/nonexistent/dir/file.log")
+	if err == nil {
+		t.Error("SetOutput with invalid path should return error")
+	}
+}
+
+func TestReopenNoFile(t *testing.T) {
+	resetLogger()
+	// Reopen when logging to stdout should be a no-op
+	if err := Reopen(); err != nil {
+		t.Errorf("Reopen with no file should not error: %v", err)
+	}
+}
+
+func TestReopen(t *testing.T) {
+	resetLogger()
+	dir := t.TempDir()
+	path := filepath.Join(dir, "test.log")
+
+	if err := SetOutput(path); err != nil {
+		t.Fatalf("SetOutput: %v", err)
+	}
+
+	// Write initial message
+	Info("before reopen")
+	_ = logFile.Sync()
+
+	// Close and remove the file to simulate log rotation
+	_ = logFile.Close()
+	_ = os.Remove(path)
+
+	// Reopen should recreate the file
+	if err := Reopen(); err != nil {
+		t.Fatalf("Reopen: %v", err)
+	}
+
+	if logFile == nil {
+		t.Error("logFile should not be nil after reopen")
+	}
+
+	// Write after reopen
+	Info("after reopen")
+	_ = logFile.Sync()
+
+	//nolint: gosec // test reads temp file in temp dir
+	data, err := os.ReadFile(path)
+	if err != nil {
+		t.Fatalf("ReadFile: %v", err)
+	}
+	content := string(data)
+	if !strings.Contains(content, "after reopen") {
+		t.Errorf("log should contain 'after reopen', got: %s", content)
+	}
+	if strings.Contains(content, "before reopen") {
+		t.Error("log should not contain 'before reopen' after file was removed")
+	}
+
+	// Close file before TempDir cleanup
+	resetLogger()
+}
+
+func TestFormatLog(t *testing.T) {
+	// Force PID init
+	mu.Do(initPID)
+
+	msg := formatLog("INFO", "test key=value")
+
+	// Verify format: timestamp level pekoe[pid]: message
+	if !strings.Contains(msg, "INFO pekoe[") {
+		t.Errorf("expected 'INFO pekoe[', got: %s", msg)
+	}
+	if !strings.Contains(msg, "]: test key=value") {
+		t.Errorf("expected message content, got: %s", msg)
+	}
+}
+
+func TestFormatLogLevels(t *testing.T) {
+	mu.Do(initPID)
+
+	levels := []string{"DEBUG", "INFO", "WARN", "ERROR", "CRITICAL"}
+	for _, level := range levels {
+		msg := formatLog(level, "x")
+		if !strings.Contains(msg, level+" pekoe[") {
+			t.Errorf("level %s: expected '%s pekoe[', got: %s", level, level, msg)
+		}
+	}
+}
+
+func TestLevelFiltering(t *testing.T) {
+	tests := []struct {
+		level   string
+		logFunc func(string, ...interface{})
+		name    string
+		want    bool // whether message should appear
+	}{
+		// At debug level, all messages should appear
+		{"debug", Debug, "debug_at_debug", true},
+		{"debug", Info, "info_at_debug", true},
+		{"debug", Warn, "warn_at_debug", true},
+		{"debug", Error, "error_at_debug", true},
+
+		// At info level, debug should be filtered
+		{"info", Debug, "debug_at_info", false},
+		{"info", Info, "info_at_info", true},
+		{"info", Warn, "warn_at_info", true},
+		{"info", Error, "error_at_info", true},
+
+		// At warn level, debug and info should be filtered
+		{"warn", Debug, "debug_at_warn", false},
+		{"warn", Info, "info_at_warn", false},
+		{"warn", Warn, "warn_at_warn", true},
+		{"warn", Error, "error_at_warn", true},
+
+		// At error level, only error should appear
+		{"error", Debug, "debug_at_error", false},
+		{"error", Info, "info_at_error", false},
+		{"error", Warn, "warn_at_error", false},
+		{"error", Error, "error_at_error", true},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			resetLogger()
+			dir := t.TempDir()
+			path := filepath.Join(dir, "filter.log")
+
+			if err := SetOutput(path); err != nil {
+				t.Fatalf("SetOutput: %v", err)
+			}
+
+			SetLevel(tt.level)
+			tt.logFunc(tt.name)
+			_ = logFile.Sync()
+
+			//nolint: gosec // test reads temp file in temp dir
+			data, err := os.ReadFile(path)
+			if err != nil {
+				t.Fatalf("ReadFile: %v", err)
+			}
+			content := string(data)
+			contains := strings.Contains(content, tt.name)
+
+			if tt.want && !contains {
+				t.Errorf("level=%s: expected %s to appear in log, got: %s", tt.level, tt.name, content)
+			}
+			if !tt.want && contains {
+				t.Errorf("level=%s: expected %s to be filtered, but it appeared in log", tt.level, tt.name)
+			}
+
+			// Close file before TempDir cleanup
+			resetLogger()
+		})
+	}
+}
+
+func TestLogFormatIncludesKeyValues(t *testing.T) {
+	resetLogger()
+	dir := t.TempDir()
+	path := filepath.Join(dir, "format.log")
+	if err := SetOutput(path); err != nil {
+		t.Fatalf("SetOutput: %v", err)
+	}
+
+	SetLevel("debug")
+	Info("event=test key=value count=%d", 42)
+	_ = logFile.Sync()
+
+	//nolint: gosec // test reads temp file in temp dir
+	data, err := os.ReadFile(path)
+	if err != nil {
+		t.Fatalf("ReadFile: %v", err)
+	}
+	content := string(data)
+
+	// Should contain the formatted message
+	if !strings.Contains(content, "event=test") {
+		t.Errorf("expected 'event=test' in log, got: %s", content)
+	}
+	if !strings.Contains(content, "key=value") {
+		t.Errorf("expected 'key=value' in log, got: %s", content)
+	}
+	if !strings.Contains(content, "count=42") {
+		t.Errorf("expected 'count=42' in log, got: %s", content)
+	}
+
+	// Close file before TempDir cleanup
+	resetLogger()
+}
+
+func TestMultipleSetOutputSwitches(t *testing.T) {
+	resetLogger()
+	dir := t.TempDir()
+	path1 := filepath.Join(dir, "first.log")
+	path2 := filepath.Join(dir, "second.log")
+
+	// Write to first file
+	if err := SetOutput(path1); err != nil {
+		t.Fatalf("SetOutput path1: %v", err)
+	}
+	SetLevel("info")
+	Info("first file")
+	_ = logFile.Sync()
+
+	// Switch to second file (SetOutput closes the first file)
+	if err := SetOutput(path2); err != nil {
+		t.Fatalf("SetOutput path2: %v", err)
+	}
+	Info("second file")
+	_ = logFile.Sync()
+
+	// Verify first file has only its message
+	//nolint: gosec // test reads temp files in temp dir
+	data1, err := os.ReadFile(path1)
+	if err != nil {
+		t.Fatalf("ReadFile path1: %v", err)
+	}
+	if !strings.Contains(string(data1), "first file") {
+		t.Error("first log should contain 'first file'")
+	}
+	if strings.Contains(string(data1), "second file") {
+		t.Error("first log should not contain 'second file'")
+	}
+
+	// Verify second file has only its message
+	//nolint: gosec // test reads temp files in temp dir
+	data2, err := os.ReadFile(path2)
+	if err != nil {
+		t.Fatalf("ReadFile path2: %v", err)
+	}
+	if !strings.Contains(string(data2), "second file") {
+		t.Error("second log should contain 'second file'")
+	}
+	if strings.Contains(string(data2), "first file") {
+		t.Error("second log should not contain 'first file'")
+	}
+
+	// Close file before TempDir cleanup
+	resetLogger()
+}