diff --git a/internal/launcher/launcher.go b/internal/launcher/launcher.go index 28185205..4f90bab6 100644 --- a/internal/launcher/launcher.go +++ b/internal/launcher/launcher.go @@ -75,8 +75,6 @@ func New(ctx context.Context, cfg *config.Config) *Launcher { // Validate that all servers requiring OIDC have the provider available for serverID, serverCfg := range cfg.Servers { if serverCfg.Auth != nil && serverCfg.Auth.Type == "github-oidc" && oidcProvider == nil { - log.Printf("[LAUNCHER] ERROR: Server %q requires OIDC authentication but ACTIONS_ID_TOKEN_REQUEST_URL is not set.", serverID) - log.Printf("[LAUNCHER] OIDC auth is only available when running in GitHub Actions with `permissions: { id-token: write }`.") logger.LogError("startup", "Server %q requires OIDC authentication but ACTIONS_ID_TOKEN_REQUEST_URL is not set. "+ "OIDC auth is only available when running in GitHub Actions with `permissions: { id-token: write }`.", @@ -115,8 +113,6 @@ func GetOrLaunch(l *Launcher, serverID string) (*mcp.Connection, error) { // Handle HTTP backends differently if serverCfg.Type == "http" { 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) // Determine OIDC provider and audience for this server var oidcProvider *oidc.Provider @@ -142,14 +138,11 @@ func GetOrLaunch(l *Launcher, serverID string) (*mcp.Connection, error) { conn, err := mcp.NewHTTPConnection(l.ctx, serverID, serverCfg.URL, serverCfg.Headers, oidcProvider, oidcAudience, l.config.Gateway.HTTPKeepaliveInterval()) if err != nil { 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) l.recordError(serverID, err.Error()) return nil, fmt.Errorf("failed to create HTTP connection: %w", err) } logger.LogInfoWithServer(serverID, "backend", "Successfully configured HTTP MCP backend: %s", serverID) - log.Printf("[LAUNCHER] Successfully configured HTTP backend: %s", serverID) l.recordStart(serverID) return conn, nil diff --git a/internal/launcher/log_helpers.go b/internal/launcher/log_helpers.go index e343e8bb..08a6fd98 100644 --- a/internal/launcher/log_helpers.go +++ b/internal/launcher/log_helpers.go @@ -23,7 +23,6 @@ func sessionSuffix(sessionID string) string { // logSecurityWarning logs container security warnings func (l *Launcher) logSecurityWarning(serverID string, serverCfg *config.ServerConfig) { 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") } @@ -33,7 +32,6 @@ func (l *Launcher) logLaunchStart(serverID, sessionID string, serverCfg *config. suffix := sessionSuffix(sessionID) logger.LogInfoWithServer(serverID, "backend", "Launching MCP backend server%s: server=%s%s, command=%s, args=%v", suffix, serverID, suffix, serverCfg.Command, sanitize.SanitizeArgs(serverCfg.Args)) - log.Printf("[LAUNCHER] Starting MCP server: %s%s", serverID, suffix) if sessionID != "" { logLauncher.Printf("Launching new session server: serverID=%s, sessionID=%s, command=%s", serverID, sessionID, serverCfg.Command) } else { @@ -87,7 +85,6 @@ func (l *Launcher) logTimeoutError(serverID, sessionID string) { suffix := sessionSuffix(sessionID) logger.LogErrorWithServer(serverID, "backend", "MCP backend server startup timeout%s: server=%s%s, timeout=%v", suffix, serverID, suffix, l.startupTimeout) - log.Printf("[LAUNCHER] ❌ Server '%s'%s startup timed out after %v", serverID, suffix, l.startupTimeout) log.Printf("[LAUNCHER] ⚠️ The server may be hanging or taking too long to initialize") log.Printf("[LAUNCHER] ⚠️ Consider increasing 'startupTimeout' in gateway config if server needs more time") logLauncher.Printf("Startup timeout occurred: serverID=%s%s, timeout=%v", serverID, suffix, l.startupTimeout) @@ -97,6 +94,5 @@ func (l *Launcher) logTimeoutError(serverID, sessionID string) { func (l *Launcher) logLaunchSuccess(serverID, sessionID string) { suffix := sessionSuffix(sessionID) logger.LogInfoWithServer(serverID, "backend", "Successfully launched MCP backend server%s: server=%s%s", suffix, serverID, suffix) - log.Printf("[LAUNCHER] Successfully launched: %s%s", serverID, suffix) logLauncher.Printf("Connection established: serverID=%s%s", serverID, suffix) } diff --git a/internal/launcher/log_helpers_test.go b/internal/launcher/log_helpers_test.go index 30f04a59..041cb656 100644 --- a/internal/launcher/log_helpers_test.go +++ b/internal/launcher/log_helpers_test.go @@ -6,6 +6,7 @@ import ( "fmt" "log" "os" + "path/filepath" "strings" "testing" "time" @@ -14,6 +15,7 @@ import ( "github.com/stretchr/testify/require" "github.com/github/gh-aw-mcpg/internal/config" + "github.com/github/gh-aw-mcpg/internal/logger" ) // captureLogOutput captures log output to a buffer for testing @@ -72,8 +74,6 @@ func TestLauncher_LogSecurityWarning(t *testing.T) { serverID: "test-server", command: "/usr/bin/node", wantInLog: []string{ - "test-server", - "direct command execution", "/usr/bin/node", "same privileges", "container", @@ -84,8 +84,6 @@ func TestLauncher_LogSecurityWarning(t *testing.T) { serverID: "docker-server", command: "docker", wantInLog: []string{ - "docker-server", - "WARNING", "docker", }, }, @@ -128,9 +126,6 @@ func TestLauncher_LogLaunchStart(t *testing.T) { args: []string{"run", "ghcr.io/github/github-mcp-server"}, isDirectCommand: false, wantInLog: []string{ - "github", - "session-123", - "Starting MCP server", "docker", }, }, @@ -142,8 +137,6 @@ func TestLauncher_LogLaunchStart(t *testing.T) { args: []string{"run", "slack-mcp-server"}, isDirectCommand: false, wantInLog: []string{ - "slack", - "Starting MCP server", "docker", }, }, @@ -155,7 +148,6 @@ func TestLauncher_LogLaunchStart(t *testing.T) { args: []string{"server.js"}, isDirectCommand: true, wantInLog: []string{ - "local-server", "node", "isDirectCommand=true", }, @@ -168,8 +160,6 @@ func TestLauncher_LogLaunchStart(t *testing.T) { args: []string{"run", "-e", "API_KEY=secret-value-12345"}, isDirectCommand: false, wantInLog: []string{ - "env-server", - "env-session", "secr...", // TruncateSecret shows first 4 chars + "..." }, }, @@ -399,10 +389,6 @@ func TestLauncher_LogTimeoutError(t *testing.T) { sessionID: "session-456", startupTimeout: 30 * time.Second, wantInLog: []string{ - "slow-server", - "session-456", - "timed out", - "30s", "hanging", "startupTimeout", }, @@ -413,9 +399,6 @@ func TestLauncher_LogTimeoutError(t *testing.T) { sessionID: "", startupTimeout: 60 * time.Second, wantInLog: []string{ - "slow-server", - "timed out", - "1m0s", // Go formats 60s as 1m0s "hanging", }, }, @@ -425,9 +408,7 @@ func TestLauncher_LogTimeoutError(t *testing.T) { sessionID: "test-session", startupTimeout: 2 * time.Minute, wantInLog: []string{ - "test-server", - "test-session", - "2m0s", + "startupTimeout", }, }, } @@ -445,7 +426,6 @@ func TestLauncher_LogTimeoutError(t *testing.T) { for _, want := range tt.wantInLog { assert.Contains(t, output, want, "Expected log output to contain: %s", want) } - assert.Contains(t, output, "❌", "Expected error emoji in output") assert.Contains(t, output, "⚠️", "Expected warning emoji in output") }) } @@ -456,41 +436,39 @@ func TestLauncher_LogLaunchSuccess(t *testing.T) { name string serverID string sessionID string - wantInLog []string + wantLog string }{ { name: "success with session", serverID: "github", sessionID: "session-789", - wantInLog: []string{ - "Successfully launched", - "github", - "session-789", - }, + wantLog: "Successfully launched MCP backend server", }, { name: "success without session", serverID: "slack", sessionID: "", - wantInLog: []string{ - "Successfully launched", - "slack", - }, + wantLog: "Successfully launched MCP backend server", }, } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - launcher := &Launcher{} - - output := captureLogOutput(t, func() { - launcher.logLaunchSuccess(tt.serverID, tt.sessionID) - }) + logDir := t.TempDir() + require.NoError(t, logger.InitServerFileLogger(logDir)) + t.Cleanup(func() { logger.CloseServerFileLogger() }) - for _, want := range tt.wantInLog { - assert.Contains(t, output, want, "Expected log output to contain: %s", want) + launcher := &Launcher{} + launcher.logLaunchSuccess(tt.serverID, tt.sessionID) + + logFile := filepath.Join(logDir, tt.serverID+".log") + content, err := os.ReadFile(logFile) + require.NoError(t, err, "Server log file should exist") + assert.Contains(t, string(content), tt.wantLog) + assert.Contains(t, string(content), tt.serverID) + if tt.sessionID != "" { + assert.Contains(t, string(content), tt.sessionID) } - assert.Contains(t, output, "[LAUNCHER]", "Expected [LAUNCHER] prefix") }) } } @@ -521,9 +499,6 @@ func TestLogHelpersIntegration(t *testing.T) { allOutput.WriteString(output) // Verify the complete flow - assert.Contains(t, allOutput.String(), "Starting MCP server") - assert.Contains(t, allOutput.String(), "test-server") - assert.Contains(t, allOutput.String(), "test-session") assert.Contains(t, allOutput.String(), "TEST_VAR") } diff --git a/internal/proxy/proxy.go b/internal/proxy/proxy.go index 581e1619..eea9a2fe 100644 --- a/internal/proxy/proxy.go +++ b/internal/proxy/proxy.go @@ -324,7 +324,7 @@ func (r *restBackendCaller) CallTool(ctx context.Context, toolName string, args if pp, ok := argsMap["perPage"].(float64); ok { perPage = fmt.Sprintf("%d", int(pp)) } - apiPath = fmt.Sprintf("/search/repositories?q=%s&per_page=%s", query, perPage) + apiPath = fmt.Sprintf("/search/repositories?q=%s&per_page=%s", url.QueryEscape(query), perPage) case "get_collaborator_permission": owner, _ := argsMap["owner"].(string) diff --git a/internal/server/guard_init.go b/internal/server/guard_init.go index a3b45ad0..59721f48 100644 --- a/internal/server/guard_init.go +++ b/internal/server/guard_init.go @@ -154,8 +154,14 @@ func (us *UnifiedServer) logServerGuardPolicies(serverID string) { log.Printf("[DIFC] guard policy for MCP server '%s': %s", serverID, string(policyJSON)) } +// getWASMGuardsRootDir returns the trimmed value of the WASM guards root +// directory environment variable, or an empty string if it is not set. +func getWASMGuardsRootDir() string { + return strings.TrimSpace(os.Getenv(wasmGuardsDirEnvVar)) +} + func findServerWASMGuardFile(serverID string) (string, bool, error) { - guardsRootDir := strings.TrimSpace(os.Getenv(wasmGuardsDirEnvVar)) + guardsRootDir := getWASMGuardsRootDir() if guardsRootDir == "" { logGuardInit.Printf("Skipping WASM guard discovery: %s is not set", wasmGuardsDirEnvVar) return "", false, nil @@ -189,7 +195,7 @@ func findServerWASMGuardFile(serverID string) (string, bool, error) { } func (us *UnifiedServer) logWASMGuardsDirConfiguration() { - guardsRootDir := strings.TrimSpace(os.Getenv(wasmGuardsDirEnvVar)) + guardsRootDir := getWASMGuardsRootDir() if guardsRootDir == "" { log.Printf("[DIFC] %s is not set", wasmGuardsDirEnvVar) return diff --git a/internal/server/http_helpers.go b/internal/server/http_helpers.go index 540b97f4..9f2e1d0b 100644 --- a/internal/server/http_helpers.go +++ b/internal/server/http_helpers.go @@ -100,20 +100,46 @@ func extractAndValidateSession(r *http.Request) string { return sessionID } +// peekRequestBody reads all bytes from a POST request body and restores it +// so downstream handlers can read it again. +// Returns nil, nil for non-POST requests or requests with no body. +func peekRequestBody(r *http.Request) ([]byte, error) { + if r.Method != http.MethodPost || r.Body == nil || r.Body == http.NoBody { + return nil, nil + } + + origBody := r.Body + b, err := io.ReadAll(origBody) + closeErr := origBody.Close() + if err != nil { + return nil, err + } + if closeErr != nil { + return nil, closeErr + } + + if len(b) == 0 { + r.Body = http.NoBody + return b, nil + } + + r.Body = io.NopCloser(bytes.NewReader(b)) + return b, nil +} + // logHTTPRequestBody logs the request body for debugging purposes. // It reads the body, logs it, and restores it so it can be read again. // The backendID parameter is optional and can be empty for unified mode. func logHTTPRequestBody(r *http.Request, sessionID, backendID string) { logHelpers.Printf("Checking request body: method=%s, hasBody=%v, sessionID=%s", r.Method, r.Body != nil, sessionID) - if r.Method != "POST" || r.Body == nil { - logHelpers.Printf("Skipping body logging: not a POST request or no body present") + bodyBytes, err := peekRequestBody(r) + if err != nil { + logHelpers.Printf("Body read failed: err=%v", err) return } - - bodyBytes, err := io.ReadAll(r.Body) - if err != nil || len(bodyBytes) == 0 { - logHelpers.Printf("Body read failed or empty: err=%v, size=%d", err, len(bodyBytes)) + if len(bodyBytes) == 0 { + logHelpers.Printf("Skipping body logging: not a POST request, no body present, or empty body") return } @@ -129,10 +155,7 @@ func logHTTPRequestBody(r *http.Request, sessionID, backendID string) { logger.LogDebug("client", "MCP request body, session=%s, body=%s", sessionID, sanitizedBody) } log.Printf("Request body: %s", sanitizedBody) - - // Restore body for subsequent reads - r.Body = io.NopCloser(bytes.NewBuffer(bodyBytes)) - logHelpers.Print("Request body restored for subsequent reads") + logHelpers.Print("Request body logged for debugging") } // injectSessionContext stores the session ID and optional backend ID into the request context. diff --git a/internal/server/sdk_logging.go b/internal/server/sdk_logging.go index 8c09641e..14d320ff 100644 --- a/internal/server/sdk_logging.go +++ b/internal/server/sdk_logging.go @@ -1,9 +1,7 @@ package server import ( - "bytes" "encoding/json" - "io" "net/http" "strings" "time" @@ -54,24 +52,17 @@ func WithSDKLogging(handler http.Handler, mode string) http.Handler { mode, auth.TruncateSessionID(sessionID), auth.TruncateSessionID(mcpSessionID), r.Method, r.URL.Path) // Capture and log request body for POST requests - var requestBody []byte + requestBody, err := peekRequestBody(r) var jsonrpcReq JSONRPCRequest - if r.Method == "POST" && r.Body != nil { - var err error - requestBody, err = io.ReadAll(r.Body) - if err == nil && len(requestBody) > 0 { - // Restore body for the actual handler - r.Body = io.NopCloser(bytes.NewBuffer(requestBody)) - - // Parse JSON-RPC request - if err := json.Unmarshal(requestBody, &jsonrpcReq); err == nil { - logSDK.Printf(" JSON-RPC Request: method=%s id=%v", jsonrpcReq.Method, jsonrpcReq.ID) - logger.LogDebug("sdk-frontend", "JSON-RPC request parsed: mode=%s, method=%s, id=%v, session=%s", - mode, jsonrpcReq.Method, jsonrpcReq.ID, auth.TruncateSessionID(sessionID)) - } else { - logSDK.Printf(" Failed to parse JSON-RPC request: %v", err) - logSDK.Printf(" Raw body: %s", string(requestBody)) - } + if err == nil && len(requestBody) > 0 { + // Parse JSON-RPC request + if err := json.Unmarshal(requestBody, &jsonrpcReq); err == nil { + logSDK.Printf(" JSON-RPC Request: method=%s id=%v", jsonrpcReq.Method, jsonrpcReq.ID) + logger.LogDebug("sdk-frontend", "JSON-RPC request parsed: mode=%s, method=%s, id=%v, session=%s", + mode, jsonrpcReq.Method, jsonrpcReq.ID, auth.TruncateSessionID(sessionID)) + } else { + logSDK.Printf(" Failed to parse JSON-RPC request: %v", err) + logSDK.Printf(" Raw body: %s", string(requestBody)) } }