Merge pull request #146 from githubnext/copilot/update-gateway-log-accessibility

Author: pelikhan

internal/logger/file_logger.go

@@ -7,7 +7,6 @@ import (
 	"os"
 	"path/filepath"
 	"sync"
-	"syscall"
 	"time"
 )
 
@@ -19,7 +18,6 @@ type FileLogger struct {
 	logDir      string
 	fileName    string
 	useFallback bool
-	locked      bool // tracks if file is locked
 }
 
 var (
@@ -70,36 +68,21 @@ func InitFileLogger(logDir, fileName string) error {
 	fl.logFile = file
 	fl.logger = log.New(file, "", 0)
 
-	// Apply a shared lock (LOCK_SH) to allow other processes to read the file
-	// This is non-blocking (LOCK_NB) so we don't hang if another process has an exclusive lock
-	if err := syscall.Flock(int(file.Fd()), syscall.LOCK_SH|syscall.LOCK_NB); err != nil {
-		// If we can't get a shared lock, log a warning but continue
-		// The file is still usable, just not with advisory locking guarantees
-		log.Printf("WARNING: Failed to acquire shared lock on log file %s: %v", logPath, err)
-		log.Printf("WARNING: Continuing without file lock - other processes may have limited access")
-	} else {
-		fl.locked = true
-	}
-
 	log.Printf("Logging to file: %s", logPath)
 
 	globalFileLogger = fl
 	return nil
 }
 
-// Close closes the log file and releases any locks
+// Close closes the log file
 func (fl *FileLogger) Close() error {
 	fl.mu.Lock()
 	defer fl.mu.Unlock()
 
 	if fl.logFile != nil {
-		// Release the file lock before closing
-		if fl.locked {
-			if err := syscall.Flock(int(fl.logFile.Fd()), syscall.LOCK_UN); err != nil {
-				log.Printf("WARNING: Failed to release lock on log file: %v", err)
-				// Continue to close the file even if unlock fails
-			}
-			fl.locked = false
+		// Sync any remaining buffered data before closing
+		if err := fl.logFile.Sync(); err != nil {
+			log.Printf("WARNING: Failed to sync log file before close: %v", err)
 		}
 		return fl.logFile.Close()
 	}
@@ -126,6 +109,14 @@ func (fl *FileLogger) Log(level LogLevel, category, format string, args ...inter
 
 	logLine := fmt.Sprintf("[%s] [%s] [%s] %s", timestamp, level, category, message)
 	fl.logger.Println(logLine)
+
+	// Flush the log to disk immediately to ensure it's readable by other processes
+	if fl.logFile != nil {
+		if err := fl.logFile.Sync(); err != nil {
+			// Log sync errors to stderr to avoid infinite recursion
+			log.Printf("WARNING: Failed to sync log file: %v", err)
+		}
+	}
 }
 
 // GetWriter returns the underlying io.Writer for the file logger

internal/logger/file_logger_test.go

@@ -4,7 +4,6 @@ import (
 	"os"
 	"path/filepath"
 	"strings"
-	"syscall"
 	"testing"
 )
 
@@ -210,100 +209,77 @@ func TestFileLoggerConcurrency(t *testing.T) {
 	}
 }
 
-func TestFileLoggerLocking(t *testing.T) {
+func TestFileLoggerReadableByOtherProcesses(t *testing.T) {
 	tmpDir := t.TempDir()
 	logDir := filepath.Join(tmpDir, "logs")
-	fileName := "lock-test.log"
+	fileName := "readable-test.log"
 	logPath := filepath.Join(logDir, fileName)
 
-	// Initialize the logger - this will acquire a shared lock
+	// Initialize the logger
 	err := InitFileLogger(logDir, fileName)
 	if err != nil {
 		t.Fatalf("InitFileLogger failed: %v", err)
 	}
 
 	// Write some data
-	LogInfo("test", "Testing file locking")
+	LogInfo("test", "Testing file readability")
 
-	// Verify another process can open and read the file with a shared lock
+	// Verify another process can open and read the file without any locks
 	// This simulates another process trying to read the log file
 	readFile, err := os.Open(logPath)
 	if err != nil {
 		t.Fatalf("Failed to open log file for reading: %v", err)
 	}
 	defer readFile.Close()
 
-	// Try to acquire a shared lock (should succeed with shared lock)
-	err = syscall.Flock(int(readFile.Fd()), syscall.LOCK_SH|syscall.LOCK_NB)
-	if err != nil {
-		t.Errorf("Failed to acquire shared lock for reading: %v", err)
-	} else {
-		// Release the shared lock
-		syscall.Flock(int(readFile.Fd()), syscall.LOCK_UN)
-	}
-
 	// Read the content to verify it's readable
 	content, err := os.ReadFile(logPath)
 	if err != nil {
 		t.Fatalf("Failed to read log file content: %v", err)
 	}
 
-	if !strings.Contains(string(content), "Testing file locking") {
+	if !strings.Contains(string(content), "Testing file readability") {
 		t.Errorf("Log file does not contain expected content")
 	}
 
-	// Close the logger - this should release the lock
+	// Close the logger
 	CloseGlobalLogger()
 
-	// Try to acquire an exclusive lock (should succeed now that we've released)
-	exclusiveFile, err := os.OpenFile(logPath, os.O_RDWR, 0644)
+	// Verify file is still readable after close
+	content, err = os.ReadFile(logPath)
 	if err != nil {
-		t.Fatalf("Failed to open log file for exclusive lock: %v", err)
+		t.Fatalf("Failed to read log file after close: %v", err)
 	}
-	defer exclusiveFile.Close()
 
-	err = syscall.Flock(int(exclusiveFile.Fd()), syscall.LOCK_EX|syscall.LOCK_NB)
-	if err != nil {
-		t.Errorf("Failed to acquire exclusive lock after close: %v", err)
-	} else {
-		// Successfully got exclusive lock - release it
-		syscall.Flock(int(exclusiveFile.Fd()), syscall.LOCK_UN)
+	if !strings.Contains(string(content), "Testing file readability") {
+		t.Errorf("Log file does not contain expected content after close")
 	}
 }
 
-func TestFileLoggerLockReleasedOnClose(t *testing.T) {
+func TestFileLoggerFlushes(t *testing.T) {
 	tmpDir := t.TempDir()
 	logDir := filepath.Join(tmpDir, "logs")
-	fileName := "lock-release-test.log"
+	fileName := "flush-test.log"
 	logPath := filepath.Join(logDir, fileName)
 
-	// Initialize and immediately close
+	// Initialize the logger
 	err := InitFileLogger(logDir, fileName)
 	if err != nil {
 		t.Fatalf("InitFileLogger failed: %v", err)
 	}
+	defer CloseGlobalLogger()
 
-	LogInfo("test", "Test message")
-
-	// Close the logger
-	err = CloseGlobalLogger()
-	if err != nil {
-		t.Fatalf("CloseGlobalLogger failed: %v", err)
-	}
+	// Write a message
+	LogInfo("test", "Immediate flush test")
 
-	// Verify we can acquire an exclusive lock after closing
-	file, err := os.OpenFile(logPath, os.O_RDWR, 0644)
+	// Immediately read the file without closing the logger
+	// This tests that Sync() is being called after each write
+	content, err := os.ReadFile(logPath)
 	if err != nil {
-		t.Fatalf("Failed to open log file: %v", err)
+		t.Fatalf("Failed to read log file: %v", err)
 	}
-	defer file.Close()
 
-	// Should be able to get exclusive lock since logger is closed
-	err = syscall.Flock(int(file.Fd()), syscall.LOCK_EX|syscall.LOCK_NB)
-	if err != nil {
-		t.Fatalf("Failed to acquire exclusive lock after logger close: %v", err)
+	if !strings.Contains(string(content), "Immediate flush test") {
+		t.Errorf("Log file does not contain message immediately after write - data not flushed")
 	}
-
-	// Clean up
-	syscall.Flock(int(file.Fd()), syscall.LOCK_UN)
 }

test/integration/binary_test.go

@@ -678,3 +678,163 @@ func parseSSEResponse(t *testing.T, body string) map[string]interface{} {
 
 	return result
 }
+
+// TestBinaryInvocation_LogFileCreation tests that the mcp-gateway.log file is created when the binary runs
+func TestBinaryInvocation_LogFileCreation(t *testing.T) {
+	if testing.Short() {
+		t.Skip("Skipping binary integration test in short mode")
+	}
+
+	binaryPath := findBinary(t)
+	t.Logf("Using binary: %s", binaryPath)
+
+	// Create a temporary directory for logs
+	tmpLogDir, err := os.MkdirTemp("", "awmg-log-test-*")
+	if err != nil {
+		t.Fatalf("Failed to create temp log directory: %v", err)
+	}
+	defer os.RemoveAll(tmpLogDir)
+
+	// Create a temporary config file
+	configFile := createTempConfig(t, map[string]interface{}{
+		"testserver": map[string]interface{}{
+			"command": "echo",
+			"args":    []string{},
+		},
+	})
+	defer os.Remove(configFile)
+
+	// Start the server process with custom log directory
+	ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
+	defer cancel()
+
+	port := "13006"
+	cmd := exec.CommandContext(ctx, binaryPath,
+		"--config", configFile,
+		"--listen", "127.0.0.1:"+port,
+		"--log-dir", tmpLogDir,
+		"--routed",
+	)
+
+	var stdout, stderr bytes.Buffer
+	cmd.Stdout = &stdout
+	cmd.Stderr = &stderr
+
+	if err := cmd.Start(); err != nil {
+		t.Fatalf("Failed to start server: %v", err)
+	}
+
+	defer func() {
+		if cmd.Process != nil {
+			cmd.Process.Kill()
+		}
+	}()
+
+	// Wait for server to start
+	serverURL := "http://127.0.0.1:" + port
+	if !waitForServer(t, serverURL+"/health", 5*time.Second) {
+		t.Logf("STDOUT: %s", stdout.String())
+		t.Logf("STDERR: %s", stderr.String())
+		t.Fatal("Server did not start in time")
+	}
+
+	t.Log("✓ Server started successfully")
+
+	// Check that the log file was created
+	logFilePath := filepath.Join(tmpLogDir, "mcp-gateway.log")
+	if _, err := os.Stat(logFilePath); os.IsNotExist(err) {
+		t.Fatalf("Log file was not created at %s", logFilePath)
+	}
+
+	t.Logf("✓ Log file created at: %s", logFilePath)
+
+	// Read the log file to verify it contains log entries
+	logContent, err := os.ReadFile(logFilePath)
+	if err != nil {
+		t.Fatalf("Failed to read log file: %v", err)
+	}
+
+	if len(logContent) == 0 {
+		t.Error("Log file is empty")
+	} else {
+		t.Logf("✓ Log file contains %d bytes", len(logContent))
+	}
+
+	// Verify log file contains expected startup messages
+	logStr := string(logContent)
+	expectedMessages := []string{
+		"startup",
+		"Starting MCPG",
+	}
+
+	for _, msg := range expectedMessages {
+		if !bytes.Contains(logContent, []byte(msg)) {
+			t.Errorf("Log file does not contain expected message: %q", msg)
+			t.Logf("Log content:\n%s", logStr)
+		}
+	}
+
+	t.Log("✓ Log file contains expected startup messages")
+
+	// Verify log file permissions (should be 0644)
+	fileInfo, err := os.Stat(logFilePath)
+	if err != nil {
+		t.Fatalf("Failed to stat log file: %v", err)
+	}
+
+	perms := fileInfo.Mode().Perm()
+	expectedPerms := os.FileMode(0644)
+	if perms != expectedPerms {
+		t.Errorf("Log file has incorrect permissions: got %o, expected %o", perms, expectedPerms)
+	} else {
+		t.Logf("✓ Log file has correct permissions: %o", perms)
+	}
+
+	// Test that the log file is readable by other processes
+	// Try to open and read the file while the server is still running
+	readFile, err := os.Open(logFilePath)
+	if err != nil {
+		t.Fatalf("Failed to open log file for reading (concurrent access): %v", err)
+	}
+	defer readFile.Close()
+
+	// Read content
+	concurrentRead, err := io.ReadAll(readFile)
+	if err != nil {
+		t.Fatalf("Failed to read log file concurrently: %v", err)
+	}
+
+	if len(concurrentRead) == 0 {
+		t.Error("Concurrent read returned empty content")
+	} else {
+		t.Logf("✓ Log file is readable by other processes (%d bytes read concurrently)", len(concurrentRead))
+	}
+
+	// Make an API call to generate more log entries
+	resp, err := http.Get(serverURL + "/health")
+	if err == nil {
+		resp.Body.Close()
+	}
+
+	// Wait a moment for logs to be written
+	time.Sleep(200 * time.Millisecond)
+
+	// Read the log file again to verify new entries were added (or at least it's still readable)
+	newLogContent, err := os.ReadFile(logFilePath)
+	if err != nil {
+		t.Fatalf("Failed to read log file after API call: %v", err)
+	}
+
+	// Log file should either grow or stay the same (health endpoint may not always log)
+	if len(newLogContent) >= len(logContent) {
+		if len(newLogContent) > len(logContent) {
+			t.Logf("✓ Log file grew from %d to %d bytes after API call (immediate flush working)", len(logContent), len(newLogContent))
+		} else {
+			t.Logf("✓ Log file size unchanged (%d bytes) but still readable after API call", len(logContent))
+		}
+	} else {
+		t.Errorf("Log file shrank from %d to %d bytes - unexpected behavior", len(logContent), len(newLogContent))
+	}
+
+	t.Log("✓ All log file checks passed")
+}