Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
7 changes: 0 additions & 7 deletions internal/launcher/launcher.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 }`.",
Expand Down Expand Up @@ -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
Expand All @@ -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
Expand Down
4 changes: 0 additions & 4 deletions internal/launcher/log_helpers.go
Original file line number Diff line number Diff line change
Expand Up @@ -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")
}
Expand All @@ -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 {
Expand Down Expand Up @@ -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)
Expand All @@ -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)
}
63 changes: 19 additions & 44 deletions internal/launcher/log_helpers_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@ import (
"fmt"
"log"
"os"
"path/filepath"
"strings"
"testing"
"time"
Expand All @@ -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
Expand Down Expand Up @@ -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",
Expand All @@ -84,8 +84,6 @@ func TestLauncher_LogSecurityWarning(t *testing.T) {
serverID: "docker-server",
command: "docker",
wantInLog: []string{
"docker-server",
"WARNING",
"docker",
},
},
Expand Down Expand Up @@ -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",
},
},
Expand All @@ -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",
},
},
Expand All @@ -155,7 +148,6 @@ func TestLauncher_LogLaunchStart(t *testing.T) {
args: []string{"server.js"},
isDirectCommand: true,
wantInLog: []string{
"local-server",
"node",
"isDirectCommand=true",
},
Expand All @@ -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 + "..."
},
},
Expand Down Expand Up @@ -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",
},
Expand All @@ -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",
},
},
Expand All @@ -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",
},
},
}
Expand All @@ -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")
})
}
Expand All @@ -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")
})
}
}
Expand Down Expand Up @@ -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")
}

Expand Down
2 changes: 1 addition & 1 deletion internal/proxy/proxy.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
10 changes: 8 additions & 2 deletions internal/server/guard_init.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down
43 changes: 33 additions & 10 deletions internal/server/http_helpers.go
Original file line number Diff line number Diff line change
Expand Up @@ -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
}

Expand All @@ -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.
Expand Down
29 changes: 10 additions & 19 deletions internal/server/sdk_logging.go
Original file line number Diff line number Diff line change
@@ -1,9 +1,7 @@
package server

import (
"bytes"
"encoding/json"
"io"
"net/http"
"strings"
"time"
Expand Down Expand Up @@ -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))
}
}

Expand Down
Loading