diff --git a/AGENTS.md b/AGENTS.md index e2cac4c..ecbc19e 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -366,11 +366,23 @@ DEBUG_COLORS=0 DEBUG=* ./awmg --config config.toml - `MCP_GATEWAY_PAYLOAD_DIR` - Large payload storage directory (sets default for `--payload-dir` flag, default: `/tmp/jq-payloads`) **File Logging:** -- Operational logs are always written to `mcp-gateway.log` in the configured log directory +- Operational logs are always written to log files in the configured log directory - Default log directory: `/tmp/gh-aw/mcp-logs` (configurable via `--log-dir` flag or `MCP_GATEWAY_LOG_DIR` env var) - Falls back to stdout if log directory cannot be created +- **Log Files Created:** + - `mcp-gateway.log` - Unified log with all messages + - `{serverID}.log` - Per-server logs (e.g., `github.log`, `slack.log`) for easier troubleshooting + - `gateway.md` - Markdown-formatted logs for GitHub workflow previews + - `rpc-messages.jsonl` - Machine-readable JSONL format for RPC message analysis - Logs include: startup, client interactions, backend operations, auth events, errors +**Per-ServerID Logging:** +- Each backend MCP server gets its own log file for easier troubleshooting +- Use `LogInfoWithServer`, `LogWarnWithServer`, `LogErrorWithServer`, `LogDebugWithServer` functions +- Example: `logger.LogInfoWithServer("github", "backend", "Server started successfully")` +- Logs are written to both the server-specific file and the unified `mcp-gateway.log` +- Thread-safe concurrent logging with automatic fallback + **Large Payload Handling:** - Large tool response payloads are stored in the configured payload directory - Default payload directory: `/tmp/jq-payloads` (configurable via `--payload-dir` flag, `MCP_GATEWAY_PAYLOAD_DIR` env var, or `payload_dir` in config) diff --git a/README.md b/README.md index 514606f..e063d53 100644 --- a/README.md +++ b/README.md @@ -23,6 +23,7 @@ This gateway is used with [GitHub Agentic Workflows](https://github.com/github/g - **Stdio Transport**: JSON-RPC 2.0 over stdin/stdout for MCP communication - **Container Detection**: Automatic detection of containerized environments with security warnings - **Enhanced Debugging**: Detailed error context and troubleshooting suggestions for command failures +- **Per-ServerID Logs**: Separate log files for each backend MCP server (`{serverID}.log`) for easier troubleshooting ## Getting Started @@ -67,6 +68,10 @@ For detailed setup instructions, building from source, and local development, se - `-e MCP_GATEWAY_*`: Required environment variables - `-v /var/run/docker.sock`: Required for spawning backend MCP servers - `-v /path/to/logs:/tmp/gh-aw/mcp-logs`: Mount for persistent gateway logs (or use `-e MCP_GATEWAY_LOG_DIR=/custom/path` with matching volume mount) + - `mcp-gateway.log`: Unified log with all messages + - `{serverID}.log`: Per-server logs for easier troubleshooting + - `gateway.md`: Markdown-formatted logs for GitHub workflow previews + - `rpc-messages.jsonl`: Machine-readable RPC message logs - `-p 8000:8000`: Port mapping must match `MCP_GATEWAY_PORT` MCPG will start in routed mode on `http://0.0.0.0:8000` (using `MCP_GATEWAY_PORT`), proxying MCP requests to your configured backend servers. @@ -329,15 +334,44 @@ MCP_GATEWAY_PORT=3000 ./run.sh MCPG provides comprehensive logging of all gateway operations to help diagnose issues and monitor activity. +### Log Files + +The gateway creates multiple log files for different purposes: + +1. **`mcp-gateway.log`** - Unified log with all gateway messages +2. **`{serverID}.log`** - Per-server logs (e.g., `github.log`, `slack.log`) for easier troubleshooting of specific backend servers +3. **`gateway.md`** - Markdown-formatted logs for GitHub workflow previews +4. **`rpc-messages.jsonl`** - Machine-readable JSONL format for RPC message analysis + ### Log File Location -By default, logs are written to `/tmp/gh-aw/mcp-logs/mcp-gateway.log`. This location can be configured using either: +By default, logs are written to `/tmp/gh-aw/mcp-logs/`. This location can be configured using either: 1. **`MCP_GATEWAY_LOG_DIR` environment variable** - Sets the default log directory 2. **`--log-dir` flag** - Overrides the environment variable and default The precedence order is: `--log-dir` flag → `MCP_GATEWAY_LOG_DIR` env var → default (`/tmp/gh-aw/mcp-logs`) +### Per-ServerID Logs + +Each backend MCP server gets its own log file (e.g., `github.log`, `slack.log`) in addition to the unified `mcp-gateway.log`. This makes it much easier to: + +- Debug issues with a specific backend server +- View all activity for one server without filtering +- Identify which server is causing problems +- Troubleshoot server-specific configuration issues + +Example log directory structure: +``` +/tmp/gh-aw/mcp-logs/ +├── mcp-gateway.log # All messages +├── github.log # Only GitHub server logs +├── slack.log # Only Slack server logs +├── notion.log # Only Notion server logs +├── gateway.md # Markdown format +└── rpc-messages.jsonl # RPC messages +``` + **Using the environment variable:** ```bash export MCP_GATEWAY_LOG_DIR=/var/log/mcp-gateway diff --git a/internal/cmd/root.go b/internal/cmd/root.go index ae4870c..14730b4 100644 --- a/internal/cmd/root.go +++ b/internal/cmd/root.go @@ -138,6 +138,12 @@ func run(cmd *cobra.Command, args []string) error { } defer logger.CloseGlobalLogger() + // Initialize per-serverID logger + if err := logger.InitServerFileLogger(logDir); err != nil { + log.Printf("Warning: Failed to initialize server file logger: %v", err) + } + defer logger.CloseServerFileLogger() + // Initialize markdown logger for GitHub workflow preview if err := logger.InitMarkdownLogger(logDir, "gateway.md"); err != nil { log.Printf("Warning: Failed to initialize markdown logger: %v", err) diff --git a/internal/launcher/launcher.go b/internal/launcher/launcher.go index bd87cc6..a94b5b2 100644 --- a/internal/launcher/launcher.go +++ b/internal/launcher/launcher.go @@ -63,14 +63,14 @@ func New(ctx context.Context, cfg *config.Config) *Launcher { // GetOrLaunch returns an existing connection or launches a new one func GetOrLaunch(l *Launcher, serverID string) (*mcp.Connection, error) { - logger.LogDebug("backend", "GetOrLaunch called for server: %s", serverID) + logger.LogDebugWithServer(serverID, "backend", "GetOrLaunch called for server: %s", serverID) logLauncher.Printf("GetOrLaunch called: serverID=%s", serverID) // Check if already exists l.mu.RLock() if conn, ok := l.connections[serverID]; ok { l.mu.RUnlock() - logger.LogDebug("backend", "Reusing existing backend connection: %s", serverID) + logger.LogDebugWithServer(serverID, "backend", "Reusing existing backend connection: %s", serverID) logLauncher.Printf("Reusing existing connection: serverID=%s", serverID) return conn, nil } @@ -84,7 +84,7 @@ func GetOrLaunch(l *Launcher, serverID string) (*mcp.Connection, error) { // Double-check after acquiring write lock if conn, ok := l.connections[serverID]; ok { - logger.LogDebug("backend", "Backend connection created by another goroutine: %s", serverID) + logger.LogDebugWithServer(serverID, "backend", "Backend connection created by another goroutine: %s", serverID) logLauncher.Printf("Connection created by another goroutine: serverID=%s", serverID) return conn, nil } @@ -92,7 +92,7 @@ func GetOrLaunch(l *Launcher, serverID string) (*mcp.Connection, error) { // Get server config serverCfg, ok := l.config.Servers[serverID] if !ok { - logger.LogError("backend", "Backend server not found in config: %s", serverID) + logger.LogErrorWithServer(serverID, "backend", "Backend server not found in config: %s", serverID) logLauncher.Printf("Server not found in config: serverID=%s", serverID) return nil, fmt.Errorf("server '%s' not found in config", serverID) } @@ -100,7 +100,7 @@ func GetOrLaunch(l *Launcher, serverID string) (*mcp.Connection, error) { // Handle HTTP backends differently if serverCfg.Type == "http" { - logger.LogInfo("backend", "Configuring HTTP MCP backend: %s, url=%s", serverID, serverCfg.URL) + logger.LogInfoWithServer(serverID, "backend", "Configuring HTTP MCP backend: %s, url=%s", serverID, serverCfg.URL) log.Printf("[LAUNCHER] Configuring HTTP MCP backend: %s", serverID) log.Printf("[LAUNCHER] URL: %s", serverCfg.URL) logLauncher.Printf("HTTP backend: serverID=%s, url=%s", serverID, serverCfg.URL) @@ -108,13 +108,13 @@ func GetOrLaunch(l *Launcher, serverID string) (*mcp.Connection, error) { // Create an HTTP connection conn, err := mcp.NewHTTPConnection(l.ctx, serverID, serverCfg.URL, serverCfg.Headers) if err != nil { - logger.LogError("backend", "Failed to create HTTP connection: %s, error=%v", serverID, err) + logger.LogErrorWithServer(serverID, "backend", "Failed to create HTTP connection: %s, error=%v", serverID, err) log.Printf("[LAUNCHER] ❌ FAILED to create HTTP connection for '%s'", serverID) log.Printf("[LAUNCHER] Error: %v", err) return nil, fmt.Errorf("failed to create HTTP connection: %w", err) } - logger.LogInfo("backend", "Successfully configured HTTP MCP backend: %s", serverID) + logger.LogInfoWithServer(serverID, "backend", "Successfully configured HTTP MCP backend: %s", serverID) log.Printf("[LAUNCHER] Successfully configured HTTP backend: %s", serverID) logLauncher.Printf("HTTP connection configured: serverID=%s", serverID) @@ -178,7 +178,7 @@ func GetOrLaunch(l *Launcher, serverID string) (*mcp.Connection, error) { // GetOrLaunchForSession returns a session-aware connection or launches a new one // This is used for stateful stdio backends that require persistent connections func GetOrLaunchForSession(l *Launcher, serverID, sessionID string) (*mcp.Connection, error) { - logger.LogDebug("backend", "GetOrLaunchForSession called: server=%s, session=%s", serverID, sessionID) + logger.LogDebugWithServer(serverID, "backend", "GetOrLaunchForSession called: server=%s, session=%s", serverID, sessionID) logLauncher.Printf("GetOrLaunchForSession called: serverID=%s, sessionID=%s", serverID, sessionID) // Get server config first to determine backend type @@ -187,7 +187,7 @@ func GetOrLaunchForSession(l *Launcher, serverID, sessionID string) (*mcp.Connec l.mu.RUnlock() if !ok { - logger.LogError("backend", "Backend server not found in config: %s", serverID) + logger.LogErrorWithServer(serverID, "backend", "Backend server not found in config: %s", serverID) return nil, fmt.Errorf("server '%s' not found in config", serverID) } @@ -200,7 +200,7 @@ func GetOrLaunchForSession(l *Launcher, serverID, sessionID string) (*mcp.Connec logLauncher.Printf("Checking session pool: serverID=%s, sessionID=%s", serverID, sessionID) // For stdio backends, check the session pool first if conn, exists := l.sessionPool.Get(serverID, sessionID); exists { - logger.LogDebug("backend", "Reusing session connection: server=%s, session=%s", serverID, sessionID) + logger.LogDebugWithServer(serverID, "backend", "Reusing session connection: server=%s, session=%s", serverID, sessionID) logLauncher.Printf("Reusing session connection: serverID=%s, sessionID=%s", serverID, sessionID) return conn, nil } @@ -214,7 +214,7 @@ func GetOrLaunchForSession(l *Launcher, serverID, sessionID string) (*mcp.Connec // Double-check after acquiring lock if conn, exists := l.sessionPool.Get(serverID, sessionID); exists { - logger.LogDebug("backend", "Session connection created by another goroutine: server=%s, session=%s", serverID, sessionID) + logger.LogDebugWithServer(serverID, "backend", "Session connection created by another goroutine: server=%s, session=%s", serverID, sessionID) logLauncher.Printf("Session connection created by another goroutine: serverID=%s, sessionID=%s", serverID, sessionID) return conn, nil } diff --git a/internal/launcher/log_helpers.go b/internal/launcher/log_helpers.go index bc375da..3d42bab 100644 --- a/internal/launcher/log_helpers.go +++ b/internal/launcher/log_helpers.go @@ -21,7 +21,7 @@ func sessionSuffix(sessionID string) string { // logSecurityWarning logs container security warnings func (l *Launcher) logSecurityWarning(serverID string, serverCfg *config.ServerConfig) { - logger.LogWarn("backend", "Server '%s' uses direct command execution inside a container (command: %s)", serverID, serverCfg.Command) + logger.LogWarnWithServer(serverID, "backend", "Server '%s' uses direct command execution inside a container (command: %s)", serverID, serverCfg.Command) log.Printf("[LAUNCHER] ⚠️ WARNING: Server '%s' uses direct command execution inside a container", serverID) log.Printf("[LAUNCHER] ⚠️ Security Notice: Command '%s' will execute with the same privileges as the gateway", serverCfg.Command) log.Printf("[LAUNCHER] ⚠️ Consider using 'container' field instead for better isolation") @@ -30,11 +30,11 @@ func (l *Launcher) logSecurityWarning(serverID string, serverCfg *config.ServerC // logLaunchStart logs server launch initiation func (l *Launcher) logLaunchStart(serverID, sessionID string, serverCfg *config.ServerConfig, isDirectCommand bool) { if sessionID != "" { - logger.LogInfo("backend", "Launching MCP backend server for session: server=%s, session=%s, command=%s, args=%v", serverID, sessionID, serverCfg.Command, sanitize.SanitizeArgs(serverCfg.Args)) + logger.LogInfoWithServer(serverID, "backend", "Launching MCP backend server for session: server=%s, session=%s, command=%s, args=%v", serverID, sessionID, serverCfg.Command, sanitize.SanitizeArgs(serverCfg.Args)) log.Printf("[LAUNCHER] Starting MCP server for session: %s (session: %s)", serverID, sessionID) logLauncher.Printf("Launching new session server: serverID=%s, sessionID=%s, command=%s", serverID, sessionID, serverCfg.Command) } else { - logger.LogInfo("backend", "Launching MCP backend server: %s, command=%s, args=%v", serverID, serverCfg.Command, sanitize.SanitizeArgs(serverCfg.Args)) + logger.LogInfoWithServer(serverID, "backend", "Launching MCP backend server: %s, command=%s, args=%v", serverID, serverCfg.Command, sanitize.SanitizeArgs(serverCfg.Args)) log.Printf("[LAUNCHER] Starting MCP server: %s", serverID) logLauncher.Printf("Launching new server: serverID=%s, command=%s, inContainer=%v, isDirectCommand=%v", serverID, serverCfg.Command, l.runningInContainer, isDirectCommand) @@ -70,7 +70,7 @@ func (l *Launcher) logEnvPassthrough(args []string) { // logLaunchError logs detailed launch failure diagnostics func (l *Launcher) logLaunchError(serverID, sessionID string, err error, serverCfg *config.ServerConfig, isDirectCommand bool) { - logger.LogError("backend", "Failed to launch MCP backend server%s: server=%s%s, error=%v", + logger.LogErrorWithServer(serverID, "backend", "Failed to launch MCP backend server%s: server=%s%s, error=%v", sessionSuffix(sessionID), serverID, sessionSuffix(sessionID), err) log.Printf("[LAUNCHER] ❌ FAILED to launch server '%s'%s", serverID, sessionSuffix(sessionID)) log.Printf("[LAUNCHER] Error: %v", err) @@ -97,7 +97,7 @@ func (l *Launcher) logLaunchError(serverID, sessionID string, err error, serverC // logTimeoutError logs startup timeout diagnostics func (l *Launcher) logTimeoutError(serverID, sessionID string) { - logger.LogError("backend", "MCP backend server startup timeout%s: server=%s%s, timeout=%v", + logger.LogErrorWithServer(serverID, "backend", "MCP backend server startup timeout%s: server=%s%s, timeout=%v", sessionSuffix(sessionID), serverID, sessionSuffix(sessionID), l.startupTimeout) log.Printf("[LAUNCHER] ❌ Server startup timed out after %v", l.startupTimeout) log.Printf("[LAUNCHER] ⚠️ The server may be hanging or taking too long to initialize") @@ -112,11 +112,11 @@ func (l *Launcher) logTimeoutError(serverID, sessionID string) { // logLaunchSuccess logs successful server launch func (l *Launcher) logLaunchSuccess(serverID, sessionID string) { if sessionID != "" { - logger.LogInfo("backend", "Successfully launched MCP backend server for session: server=%s, session=%s", serverID, sessionID) + logger.LogInfoWithServer(serverID, "backend", "Successfully launched MCP backend server for session: server=%s, session=%s", serverID, sessionID) log.Printf("[LAUNCHER] Successfully launched: %s (session: %s)", serverID, sessionID) logLauncher.Printf("Session connection established: serverID=%s, sessionID=%s", serverID, sessionID) } else { - logger.LogInfo("backend", "Successfully launched MCP backend server: %s", serverID) + logger.LogInfoWithServer(serverID, "backend", "Successfully launched MCP backend server: %s", serverID) log.Printf("[LAUNCHER] Successfully launched: %s", serverID) logLauncher.Printf("Connection established: serverID=%s", serverID) } diff --git a/internal/logger/README.md b/internal/logger/README.md index 229dbc7..6023cfd 100644 --- a/internal/logger/README.md +++ b/internal/logger/README.md @@ -11,6 +11,61 @@ A simple, debug-style logging framework for Go that follows the pattern matching - **Automatic color coding**: Each namespace gets a unique color when stderr is a TTY - **Zero overhead**: Logger enabled state is computed once at construction time - **Thread-safe**: Safe for concurrent use +- **Per-ServerID Logs**: Separate log files for each backend MCP server for easier troubleshooting + +## Per-ServerID Logging + +The logger package supports creating separate log files for each backend MCP server (identified by serverID). This makes it much easier to troubleshoot specific servers without sifting through unified logs. + +### How It Works + +- Each serverID gets its own log file: `{serverID}.log` in the log directory +- Logs are also written to the main `mcp-gateway.log` for a unified view +- Concurrent writes to different serverID logs are handled safely +- Fallback to unified logging if per-serverID logging cannot be initialized + +### Usage + +```go +import "github.com/github/gh-aw-mcpg/internal/logger" + +// Log to both the unified log and the server-specific log +logger.LogInfoWithServer("github", "backend", "Server started successfully") +logger.LogWarnWithServer("slack", "backend", "Connection timeout") +logger.LogErrorWithServer("github", "backend", "Failed to authenticate: %v", err) +logger.LogDebugWithServer("notion", "backend", "Processing request: %v", req) +``` + +### Log File Structure + +When per-serverID logging is enabled, the log directory contains: +``` +/tmp/gh-aw/mcp-logs/ +├── mcp-gateway.log # Unified log with all messages +├── github.log # Only logs for the "github" server +├── slack.log # Only logs for the "slack" server +└── notion.log # Only logs for the "notion" server +``` + +Each server-specific log file contains only the messages related to that serverID, making it easier to debug issues with individual backend servers. + +### Initialization + +Per-serverID logging is automatically initialized when the gateway starts: + +```go +// In internal/cmd/root.go +logger.InitServerFileLogger(logDir) +defer logger.CloseServerFileLogger() +``` + +### Benefits + +- **Easier Debugging**: View all logs for a specific server in isolation +- **Reduced Noise**: No need to filter through logs from other servers +- **Better Troubleshooting**: Quickly identify which server is having issues +- **Concurrent Access**: Safe to log to multiple servers simultaneously +- **Backward Compatible**: Falls back gracefully if initialization fails ## Usage diff --git a/internal/logger/server_file_logger.go b/internal/logger/server_file_logger.go new file mode 100644 index 0000000..eff1626 --- /dev/null +++ b/internal/logger/server_file_logger.go @@ -0,0 +1,235 @@ +package logger + +import ( + "fmt" + "log" + "os" + "path/filepath" + "sync" + "time" +) + +// ServerFileLogger manages per-serverID log files +type ServerFileLogger struct { + logDir string + loggers map[string]*log.Logger + files map[string]*os.File + mu sync.RWMutex + useFallback bool +} + +var ( + globalServerFileLogger *ServerFileLogger + globalServerLoggerMu sync.RWMutex +) + +// InitServerFileLogger initializes the global server file logger +func InitServerFileLogger(logDir string) error { + // Create log directory if it doesn't exist + if err := os.MkdirAll(logDir, 0755); err != nil { + log.Printf("WARNING: Failed to create log directory for server logs: %v", err) + log.Printf("WARNING: Falling back to unified logging only") + // Create a fallback logger that won't create files + sfl := &ServerFileLogger{ + logDir: logDir, + loggers: make(map[string]*log.Logger), + files: make(map[string]*os.File), + useFallback: true, + } + initGlobalServerFileLogger(sfl) + return nil + } + + sfl := &ServerFileLogger{ + logDir: logDir, + loggers: make(map[string]*log.Logger), + files: make(map[string]*os.File), + useFallback: false, + } + + log.Printf("Initialized per-serverID logging in directory: %s", logDir) + initGlobalServerFileLogger(sfl) + return nil +} + +// getOrCreateLogger returns a logger for the given serverID, creating it if necessary +func (sfl *ServerFileLogger) getOrCreateLogger(serverID string) (*log.Logger, error) { + // Fast path: check if logger already exists (read lock) + sfl.mu.RLock() + if logger, exists := sfl.loggers[serverID]; exists { + sfl.mu.RUnlock() + return logger, nil + } + sfl.mu.RUnlock() + + // Slow path: create new logger (write lock) + sfl.mu.Lock() + defer sfl.mu.Unlock() + + // Double-check in case another goroutine created it while we waited for the lock + if logger, exists := sfl.loggers[serverID]; exists { + return logger, nil + } + + // If in fallback mode, return nil to indicate no per-server logging + if sfl.useFallback { + return nil, fmt.Errorf("server file logger in fallback mode") + } + + // Create log file for this serverID + fileName := fmt.Sprintf("%s.log", serverID) + logPath := filepath.Join(sfl.logDir, fileName) + file, err := os.OpenFile(logPath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644) + if err != nil { + return nil, fmt.Errorf("failed to open log file for server %s: %w", serverID, err) + } + + // Create logger + logger := log.New(file, "", 0) + + // Store in maps + sfl.loggers[serverID] = logger + sfl.files[serverID] = file + + return logger, nil +} + +// Log writes a log message to the server-specific log file +func (sfl *ServerFileLogger) Log(serverID string, level LogLevel, category, format string, args ...interface{}) { + if sfl == nil { + return + } + + logger, err := sfl.getOrCreateLogger(serverID) + if err != nil { + // If we can't create a logger, fall back to the global logger + // but include the serverID in the message + LogDebug(category, "[%s] "+format, append([]interface{}{serverID}, args...)...) + return + } + + timestamp := time.Now().UTC().Format(time.RFC3339) + message := fmt.Sprintf(format, args...) + logLine := fmt.Sprintf("[%s] [%s] [%s] %s", timestamp, level, category, message) + + logger.Println(logLine) + + // Flush to disk immediately + sfl.mu.RLock() + if file, exists := sfl.files[serverID]; exists { + if err := file.Sync(); err != nil { + log.Printf("WARNING: Failed to sync log file for server %s: %v", serverID, err) + } + } + sfl.mu.RUnlock() +} + +// Close closes all server log files +func (sfl *ServerFileLogger) Close() error { + if sfl == nil { + return nil + } + + sfl.mu.Lock() + defer sfl.mu.Unlock() + + var firstErr error + for serverID, file := range sfl.files { + if err := file.Sync(); err != nil { + log.Printf("WARNING: Failed to sync log file for server %s: %v", serverID, err) + if firstErr == nil { + firstErr = err + } + } + if err := file.Close(); err != nil { + log.Printf("WARNING: Failed to close log file for server %s: %v", serverID, err) + if firstErr == nil { + firstErr = err + } + } + } + + // Clear maps + sfl.loggers = make(map[string]*log.Logger) + sfl.files = make(map[string]*os.File) + + return firstErr +} + +// Global logging functions that use the global server file logger + +// LogInfoWithServer logs an informational message to the server-specific log file +func LogInfoWithServer(serverID, category, format string, args ...interface{}) { + globalServerLoggerMu.RLock() + defer globalServerLoggerMu.RUnlock() + + if globalServerFileLogger != nil { + globalServerFileLogger.Log(serverID, LogLevelInfo, category, format, args...) + } + + // Also log to the main log file for unified view + LogInfo(category, "[%s] %s", serverID, fmt.Sprintf(format, args...)) +} + +// LogWarnWithServer logs a warning message to the server-specific log file +func LogWarnWithServer(serverID, category, format string, args ...interface{}) { + globalServerLoggerMu.RLock() + defer globalServerLoggerMu.RUnlock() + + if globalServerFileLogger != nil { + globalServerFileLogger.Log(serverID, LogLevelWarn, category, format, args...) + } + + // Also log to the main log file for unified view + LogWarn(category, "[%s] %s", serverID, fmt.Sprintf(format, args...)) +} + +// LogErrorWithServer logs an error message to the server-specific log file +func LogErrorWithServer(serverID, category, format string, args ...interface{}) { + globalServerLoggerMu.RLock() + defer globalServerLoggerMu.RUnlock() + + if globalServerFileLogger != nil { + globalServerFileLogger.Log(serverID, LogLevelError, category, format, args...) + } + + // Also log to the main log file for unified view + LogError(category, "[%s] %s", serverID, fmt.Sprintf(format, args...)) +} + +// LogDebugWithServer logs a debug message to the server-specific log file +func LogDebugWithServer(serverID, category, format string, args ...interface{}) { + globalServerLoggerMu.RLock() + defer globalServerLoggerMu.RUnlock() + + if globalServerFileLogger != nil { + globalServerFileLogger.Log(serverID, LogLevelDebug, category, format, args...) + } + + // Also log to the main log file for unified view + LogDebug(category, "[%s] %s", serverID, fmt.Sprintf(format, args...)) +} + +// CloseServerFileLogger closes the global server file logger +func CloseServerFileLogger() error { + globalServerLoggerMu.Lock() + defer globalServerLoggerMu.Unlock() + + if globalServerFileLogger != nil { + err := globalServerFileLogger.Close() + globalServerFileLogger = nil + return err + } + return nil +} + +// Helper function for initializing the global server file logger +func initGlobalServerFileLogger(logger *ServerFileLogger) { + globalServerLoggerMu.Lock() + defer globalServerLoggerMu.Unlock() + + if globalServerFileLogger != nil { + globalServerFileLogger.Close() + } + globalServerFileLogger = logger +} diff --git a/internal/logger/server_file_logger_test.go b/internal/logger/server_file_logger_test.go new file mode 100644 index 0000000..f40890f --- /dev/null +++ b/internal/logger/server_file_logger_test.go @@ -0,0 +1,265 @@ +package logger + +import ( + "os" + "path/filepath" + "strings" + "sync" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestInitServerFileLogger(t *testing.T) { + // Create a temporary directory for testing + tmpDir := t.TempDir() + logDir := filepath.Join(tmpDir, "server-logs") + + // Initialize the server logger + err := InitServerFileLogger(logDir) + require.NoError(t, err, "InitServerFileLogger failed") + defer CloseServerFileLogger() + + // Check that the log directory was created + _, err = os.Stat(logDir) + assert.NoError(t, err, "Log directory was not created: %s", logDir) +} + +func TestServerFileLoggerCreatesLogFiles(t *testing.T) { + // Create a temporary directory for testing + tmpDir := t.TempDir() + logDir := filepath.Join(tmpDir, "server-logs") + + // Initialize the server logger + err := InitServerFileLogger(logDir) + require.NoError(t, err) + defer CloseServerFileLogger() + + // Log messages for different servers + LogInfoWithServer("github", "test", "Test message 1") + LogInfoWithServer("slack", "test", "Test message 2") + LogWarnWithServer("github", "test", "Warning message") + + // Close to flush all files + err = CloseServerFileLogger() + require.NoError(t, err) + + // Check that log files were created for each server + githubLog := filepath.Join(logDir, "github.log") + slackLog := filepath.Join(logDir, "slack.log") + + _, err = os.Stat(githubLog) + assert.NoError(t, err, "github.log was not created") + + _, err = os.Stat(slackLog) + assert.NoError(t, err, "slack.log was not created") + + // Read and verify log contents + githubContent, err := os.ReadFile(githubLog) + require.NoError(t, err) + assert.Contains(t, string(githubContent), "Test message 1") + assert.Contains(t, string(githubContent), "Warning message") + assert.Contains(t, string(githubContent), "[INFO]") + assert.Contains(t, string(githubContent), "[WARN]") + + slackContent, err := os.ReadFile(slackLog) + require.NoError(t, err) + assert.Contains(t, string(slackContent), "Test message 2") + assert.NotContains(t, string(slackContent), "Test message 1") +} + +func TestServerFileLoggerConcurrentAccess(t *testing.T) { + // Create a temporary directory for testing + tmpDir := t.TempDir() + logDir := filepath.Join(tmpDir, "server-logs") + + // Initialize the server logger + err := InitServerFileLogger(logDir) + require.NoError(t, err) + defer CloseServerFileLogger() + + // Concurrently log messages from multiple goroutines + var wg sync.WaitGroup + serverIDs := []string{"server1", "server2", "server3"} + messagesPerServer := 50 + + for _, serverID := range serverIDs { + for i := 0; i < messagesPerServer; i++ { + wg.Add(1) + go func(sid string, index int) { + defer wg.Done() + LogInfoWithServer(sid, "test", "Message %d", index) + }(serverID, i) + } + } + + wg.Wait() + + // Close to flush all files + err = CloseServerFileLogger() + require.NoError(t, err) + + // Verify that each server has the expected number of log entries + for _, serverID := range serverIDs { + logFile := filepath.Join(logDir, serverID+".log") + content, err := os.ReadFile(logFile) + require.NoError(t, err, "Failed to read log file for %s", serverID) + + // Count the number of lines + lines := strings.Split(strings.TrimSpace(string(content)), "\n") + assert.Equal(t, messagesPerServer, len(lines), + "Server %s should have %d log entries, got %d", serverID, messagesPerServer, len(lines)) + } +} + +func TestServerFileLoggerFallback(t *testing.T) { + // Use a non-writable directory to trigger fallback + logDir := "/root/nonexistent/directory" + + // Initialize the logger - should not fail, but use fallback + err := InitServerFileLogger(logDir) + require.NoError(t, err, "InitServerFileLogger should not fail on fallback") + defer CloseServerFileLogger() + + globalServerLoggerMu.RLock() + useFallback := globalServerFileLogger.useFallback + globalServerLoggerMu.RUnlock() + + assert.True(t, useFallback, "Logger should be in fallback mode") + + // Log should not panic in fallback mode + assert.NotPanics(t, func() { + LogInfoWithServer("github", "test", "Test message in fallback mode") + }) +} + +func TestServerFileLoggerAllLevels(t *testing.T) { + // Create a temporary directory for testing + tmpDir := t.TempDir() + logDir := filepath.Join(tmpDir, "server-logs") + + // Initialize the server logger + err := InitServerFileLogger(logDir) + require.NoError(t, err) + defer CloseServerFileLogger() + + serverID := "test-server" + + // Log messages at all levels + LogInfoWithServer(serverID, "test", "Info message") + LogWarnWithServer(serverID, "test", "Warning message") + LogErrorWithServer(serverID, "test", "Error message") + LogDebugWithServer(serverID, "test", "Debug message") + + // Close to flush + err = CloseServerFileLogger() + require.NoError(t, err) + + // Read log file + logFile := filepath.Join(logDir, serverID+".log") + content, err := os.ReadFile(logFile) + require.NoError(t, err) + + contentStr := string(content) + + // Verify all log levels are present + assert.Contains(t, contentStr, "[INFO]") + assert.Contains(t, contentStr, "[WARN]") + assert.Contains(t, contentStr, "[ERROR]") + assert.Contains(t, contentStr, "[DEBUG]") + + // Verify messages are present + assert.Contains(t, contentStr, "Info message") + assert.Contains(t, contentStr, "Warning message") + assert.Contains(t, contentStr, "Error message") + assert.Contains(t, contentStr, "Debug message") +} + +func TestServerFileLoggerMultipleInit(t *testing.T) { + // Create a temporary directory for testing + tmpDir := t.TempDir() + logDir := filepath.Join(tmpDir, "server-logs") + + // Initialize the server logger + err := InitServerFileLogger(logDir) + require.NoError(t, err) + + // Log a message + LogInfoWithServer("server1", "test", "Message 1") + + // Re-initialize (should close old logger and create new one) + err = InitServerFileLogger(logDir) + require.NoError(t, err) + + // Log another message + LogInfoWithServer("server1", "test", "Message 2") + + // Close + err = CloseServerFileLogger() + require.NoError(t, err) + + // Verify both messages are in the file + logFile := filepath.Join(logDir, "server1.log") + content, err := os.ReadFile(logFile) + require.NoError(t, err) + + assert.Contains(t, string(content), "Message 1") + assert.Contains(t, string(content), "Message 2") +} + +func TestServerFileLoggerPreservesUnifiedView(t *testing.T) { + // Create temporary directories for testing + tmpDir := t.TempDir() + logDir := filepath.Join(tmpDir, "logs") + + // Initialize both the unified file logger and the server file logger + err := InitFileLogger(logDir, "mcp-gateway.log") + require.NoError(t, err, "InitFileLogger failed") + defer CloseGlobalLogger() + + err = InitServerFileLogger(logDir) + require.NoError(t, err, "InitServerFileLogger failed") + defer CloseServerFileLogger() + + // Log messages using per-serverID logging + LogInfoWithServer("github", "backend", "GitHub server started") + LogWarnWithServer("slack", "backend", "Slack connection timeout") + LogErrorWithServer("github", "backend", "GitHub authentication failed") + + // Close loggers to flush + err = CloseServerFileLogger() + require.NoError(t, err) + err = CloseGlobalLogger() + require.NoError(t, err) + + // Verify per-serverID log files exist and contain correct messages + githubLog := filepath.Join(logDir, "github.log") + githubContent, err := os.ReadFile(githubLog) + require.NoError(t, err, "github.log should exist") + assert.Contains(t, string(githubContent), "GitHub server started") + assert.Contains(t, string(githubContent), "GitHub authentication failed") + assert.NotContains(t, string(githubContent), "Slack connection timeout", "github.log should not contain Slack messages") + + slackLog := filepath.Join(logDir, "slack.log") + slackContent, err := os.ReadFile(slackLog) + require.NoError(t, err, "slack.log should exist") + assert.Contains(t, string(slackContent), "Slack connection timeout") + assert.NotContains(t, string(slackContent), "GitHub", "slack.log should not contain GitHub messages") + + // CRITICAL: Verify unified log file contains ALL messages from all servers + unifiedLog := filepath.Join(logDir, "mcp-gateway.log") + unifiedContent, err := os.ReadFile(unifiedLog) + require.NoError(t, err, "mcp-gateway.log should exist") + + // All messages should be in the unified log with serverID prefix + assert.Contains(t, string(unifiedContent), "[github]", "unified log should have github prefix") + assert.Contains(t, string(unifiedContent), "GitHub server started", "unified log should contain GitHub message") + assert.Contains(t, string(unifiedContent), "[slack]", "unified log should have slack prefix") + assert.Contains(t, string(unifiedContent), "Slack connection timeout", "unified log should contain Slack message") + assert.Contains(t, string(unifiedContent), "GitHub authentication failed", "unified log should contain GitHub error") + + // Verify unified log has all three messages + lines := strings.Split(strings.TrimSpace(string(unifiedContent)), "\n") + assert.GreaterOrEqual(t, len(lines), 3, "unified log should have at least 3 messages") +} diff --git a/internal/mcp/connection.go b/internal/mcp/connection.go index 712783f..6ab009b 100644 --- a/internal/mcp/connection.go +++ b/internal/mcp/connection.go @@ -198,7 +198,7 @@ func NewConnection(ctx context.Context, serverID, command string, args []string, scanner := bufio.NewScanner(stderrPipeReader) for scanner.Scan() { line := scanner.Text() - logger.LogInfo("backend", "[%s stderr] %s", serverID, line) + logger.LogInfoWithServer(serverID, "backend", "[stderr] %s", line) logConn.Printf("[%s stderr] %s", serverID, line) } }() diff --git a/internal/server/unified.go b/internal/server/unified.go index f304b03..a84c368 100644 --- a/internal/server/unified.go +++ b/internal/server/unified.go @@ -228,11 +228,11 @@ func (us *UnifiedServer) registerAllToolsParallel(serverIDs []string) error { for result := range results { if result.err != nil { log.Printf("Warning: failed to register tools from %s (took %v): %v", result.serverID, result.duration, result.err) - logger.LogWarn("backend", "Failed to register tools from %s (took %v): %v", result.serverID, result.duration, result.err) + logger.LogWarnWithServer(result.serverID, "backend", "Failed to register tools from %s (took %v): %v", result.serverID, result.duration, result.err) failureCount++ } else { logUnified.Printf("Successfully registered tools from %s (took %v)", result.serverID, result.duration) - logger.LogInfo("backend", "Successfully registered tools from %s (took %v)", result.serverID, result.duration) + logger.LogInfoWithServer(result.serverID, "backend", "Successfully registered tools from %s (took %v)", result.serverID, result.duration) successCount++ } }