Merge pull request #160 from githubnext/copilot/merge-debug-into-file-logger

Author: pelikhan

.github/workflows/go-logger.md

@@ -91,6 +91,12 @@ Replace `pkg:filename` with the actual package and filename:
 - For `internal/cmd/root.go` → `"cmd:root"`
 - For `internal/launcher/docker.go` → `"launcher:docker"`
 
+**Note:** Debug loggers created with `logger.New()` write to both:
+- **stderr** - Colorized output with time diffs (when `DEBUG` env var matches namespace)
+- **file logger** - Text-only output (always logged when the logger is enabled)
+
+This dual output approach ensures all debug logs are captured to file for troubleshooting while providing real-time colored output during development.
+
 ### Logger Usage Patterns
 
 **Good logging examples:**

AGENTS.md

@@ -148,7 +148,9 @@ import "github.com/githubnext/gh-aw-mcpg/internal/logger"
 // Create a logger with namespace following pkg:filename convention
 var log = logger.New("pkg:filename")
 
-// Log debug messages (only shown when DEBUG environment variable matches)
+// Log debug messages
+// - Writes to stderr with colors and time diffs (when DEBUG matches namespace)
+// - Also writes to file logger as text-only (always, when logger is enabled)
 log.Printf("Processing %d items", count)
 log.Print("Simple debug message")
 
@@ -158,7 +160,7 @@ if log.Enabled() {
 }
 ```
 
-**For operational/file logging, use the file logger:**
+**For operational/file logging, use the file logger directly:**
 
 ```go
 import "github.com/githubnext/gh-aw-mcpg/internal/logger"
@@ -170,6 +172,8 @@ logger.LogError("category", "Operation failed: %v", err)
 logger.LogDebug("category", "Debug details: %+v", details)
 ```
 
+**Note:** Debug loggers created with `logger.New()` now write to both stderr (with colors/time diffs) and the file logger (text-only). This provides real-time colored output during development while ensuring all debug logs are captured to file for production troubleshooting.
+
 **Logging Categories:**
 - `startup` - Gateway initialization and configuration
 - `shutdown` - Graceful shutdown events

internal/logger/README.md

@@ -125,7 +125,14 @@ Each logger tracks the time of its last log call to display elapsed time, simila
 
 ### Output Destination
 
-All log output goes to **stderr** to avoid interfering with stdout data (JSON, command output, etc.).
+Log output goes to **two destinations**:
+- **stderr** - Colorized output with time diffs (controlled by `DEBUG` environment variable)
+- **file logger** - Text-only output without colors or time diffs (always logged when enabled)
+
+This dual output approach allows:
+- Real-time debugging with colored, timestamped output during development
+- Persistent, parseable log files for production troubleshooting
+- All debug logs are captured to file, making it easier to diagnose issues after the fact
 
 ### Printf Interface
 

internal/logger/logger.go

@@ -99,6 +99,7 @@ func (l *Logger) Enabled() bool {
 // Printf prints a formatted message if the logger is enabled.
 // A newline is always added at the end.
 // Time diff since last log is displayed like the debug npm package.
+// Also writes to the file logger in text-only format.
 func (l *Logger) Printf(format string, args ...any) {
 	if !l.enabled {
 		return
@@ -110,16 +111,22 @@ func (l *Logger) Printf(format string, args ...any) {
 	l.mu.Unlock()
 
 	message := fmt.Sprintf(format, args...)
+
+	// Write to stderr with colors and time diff
 	if l.color != "" {
 		fmt.Fprintf(os.Stderr, "%s%s%s %s +%s\n", l.color, l.namespace, colorReset, message, timeutil.FormatDuration(diff))
 	} else {
 		fmt.Fprintf(os.Stderr, "%s %s +%s\n", l.namespace, message, timeutil.FormatDuration(diff))
 	}
+
+	// Also write to file logger in text-only format (no colors, no time diff)
+	LogDebug(l.namespace, "%s", message)
 }
 
 // Print prints a message if the logger is enabled.
 // A newline is always added at the end.
 // Time diff since last log is displayed like the debug npm package.
+// Also writes to the file logger in text-only format.
 func (l *Logger) Print(args ...any) {
 	if !l.enabled {
 		return
@@ -131,11 +138,16 @@ func (l *Logger) Print(args ...any) {
 	l.mu.Unlock()
 
 	message := fmt.Sprint(args...)
+
+	// Write to stderr with colors and time diff
 	if l.color != "" {
 		fmt.Fprintf(os.Stderr, "%s%s%s %s +%s\n", l.color, l.namespace, colorReset, message, timeutil.FormatDuration(diff))
 	} else {
 		fmt.Fprintf(os.Stderr, "%s %s +%s\n", l.namespace, message, timeutil.FormatDuration(diff))
 	}
+
+	// Also write to file logger in text-only format (no colors, no time diff)
+	LogDebug(l.namespace, "%s", message)
 }
 
 // computeEnabled computes whether a namespace matches the DEBUG patterns

internal/logger/logger_test.go

@@ -3,6 +3,7 @@ package logger
 import (
 	"bytes"
 	"os"
+	"path/filepath"
 	"strings"
 	"testing"
 	"time"
@@ -391,3 +392,117 @@ func TestComputeEnabled(t *testing.T) {
 		})
 	}
 }
+
+func TestDebugLoggerWritesToFile(t *testing.T) {
+	// Create a temporary directory for the file logger
+	tmpDir := t.TempDir()
+	logDir := filepath.Join(tmpDir, "logs")
+	fileName := "debug-test.log"
+
+	// Initialize the file logger
+	err := InitFileLogger(logDir, fileName)
+	if err != nil {
+		t.Fatalf("InitFileLogger failed: %v", err)
+	}
+	defer CloseGlobalLogger()
+
+	// Enable all debug loggers
+	debugEnv = "*"
+
+	// Create a debug logger
+	log := New("test:debug")
+
+	// Capture stderr to verify stderr output
+	stderrOutput := captureStderr(func() {
+		log.Printf("Test message %d", 42)
+		log.Print("Another test message")
+	})
+
+	// Verify stderr output contains the messages
+	if !strings.Contains(stderrOutput, "Test message 42") {
+		t.Errorf("Stderr should contain debug message, got: %s", stderrOutput)
+	}
+	if !strings.Contains(stderrOutput, "Another test message") {
+		t.Errorf("Stderr should contain debug message, got: %s", stderrOutput)
+	}
+
+	// Close the file logger to flush all data
+	CloseGlobalLogger()
+
+	// Read the log file
+	logPath := filepath.Join(logDir, fileName)
+	content, err := os.ReadFile(logPath)
+	if err != nil {
+		t.Fatalf("Failed to read log file: %v", err)
+	}
+
+	logContent := string(content)
+
+	// Verify the file logger contains the same messages (text-only, no colors)
+	if !strings.Contains(logContent, "Test message 42") {
+		t.Errorf("Log file should contain debug message, got: %s", logContent)
+	}
+	if !strings.Contains(logContent, "Another test message") {
+		t.Errorf("Log file should contain debug message, got: %s", logContent)
+	}
+
+	// Verify the file logger has DEBUG level
+	if !strings.Contains(logContent, "[DEBUG]") {
+		t.Errorf("Log file should contain [DEBUG] level, got: %s", logContent)
+	}
+
+	// Verify the file logger has the namespace as category
+	if !strings.Contains(logContent, "[test:debug]") {
+		t.Errorf("Log file should contain [test:debug] category, got: %s", logContent)
+	}
+
+	// Verify no color codes in file output
+	if strings.Contains(logContent, "\033[") {
+		t.Errorf("Log file should not contain ANSI color codes, got: %s", logContent)
+	}
+}
+
+func TestDebugLoggerDisabledNoFileWrite(t *testing.T) {
+	// Create a temporary directory for the file logger
+	tmpDir := t.TempDir()
+	logDir := filepath.Join(tmpDir, "logs")
+	fileName := "debug-disabled-test.log"
+
+	// Initialize the file logger
+	err := InitFileLogger(logDir, fileName)
+	if err != nil {
+		t.Fatalf("InitFileLogger failed: %v", err)
+	}
+	defer CloseGlobalLogger()
+
+	// Disable all debug loggers
+	debugEnv = ""
+
+	// Create a debug logger (should be disabled)
+	log := New("test:disabled")
+
+	// Verify logger is disabled
+	if log.Enabled() {
+		t.Fatal("Logger should be disabled when DEBUG is empty")
+	}
+
+	// Try to log (should not write anywhere)
+	log.Printf("This should not appear")
+
+	// Close the file logger to flush all data
+	CloseGlobalLogger()
+
+	// Read the log file
+	logPath := filepath.Join(logDir, fileName)
+	content, err := os.ReadFile(logPath)
+	if err != nil {
+		t.Fatalf("Failed to read log file: %v", err)
+	}
+
+	logContent := string(content)
+
+	// Verify the message is NOT in the file (logger was disabled)
+	if strings.Contains(logContent, "This should not appear") {
+		t.Errorf("Disabled logger should not write to file, got: %s", logContent)
+	}
+}