Skip to content

Eliminate duplicate launch logging in launcher package #563

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
lpcox merged 4 commits into from
Feb 1, 2026
+171 −112
Merged

Eliminate duplicate launch logging in launcher package #563

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
db426ad
Initial plan
Copilot Feb 1, 2026
e6a0b8b
refactor: extract duplicate launch logging into helpers (#556, #558)
Copilot Feb 1, 2026
8653735
docs: document logger naming convention (#557)
Copilot Feb 1, 2026
9ec6b32
fix: address code review feedback
Copilot Feb 1, 2026
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
24 changes: 24 additions & 0 deletions AGENTS.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -290,6 +290,30 @@ logger.LogDebug("category", "Debug details: %+v", details)
- Use colon (`:`) as separator between package and file/component name
- Be consistent with existing loggers in the codebase

**Logger Variable Naming Convention:**
- **Use descriptive names** that match the component: `var log<Component> = logger.New("pkg:component")`
- Examples: `var logLauncher = logger.New("launcher:launcher")`, `var logConfig = logger.New("config:config")`
- **Avoid generic `log` name** when it might conflict with standard library or when the file already imports `log` package
- Capitalize the component part after 'log' (e.g., `logAuth` with capital 'A', `logLauncher` with capital 'L')
- This convention makes it clear which logger is being used and reduces naming collisions
- For components with very short files or temporary code, generic `log` is acceptable but descriptive is preferred

**Examples of good logger naming:**
```go
// Descriptive - clearly indicates the component (RECOMMENDED)
var logLauncher = logger.New("launcher:launcher")
var logPool = logger.New("launcher:pool")
var logConfig = logger.New("config:config")
var logValidation = logger.New("config:validation")
var logUnified = logger.New("server:unified")
var logRouted = logger.New("server:routed")

// Generic - acceptable for simple cases but less clear
var log = logger.New("auth:header")
var log = logger.New("sys:sys")
```


**Debug Output Control:**
```bash
# Enable all debug logs
Expand Down
16 changes: 12 additions & 4 deletions CONTRIBUTING.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -254,17 +254,25 @@ Use the logger package for debug logging:
import "github.com/githubnext/gh-aw-mcpg/internal/logger"

// Create a logger with namespace following pkg:filename convention
var log = logger.New("pkg:filename")
// Use descriptive variable names (e.g., logLauncher, logConfig) for clarity
var logComponent = logger.New("pkg:filename")

// Log debug messages (only shown when DEBUG environment variable matches)
log.Printf("Processing %d items", count)
logComponent.Printf("Processing %d items", count)

// Check if logging is enabled before expensive operations
if log.Enabled() {
log.Printf("Expensive debug info: %+v", expensiveOperation())
if logComponent.Enabled() {
logComponent.Printf("Expensive debug info: %+v", expensiveOperation())
}
```

**Logger Variable Naming Convention:**
- **Prefer descriptive names**: `var log<Component> = logger.New("pkg:component")`
- Examples: `var logLauncher = logger.New("launcher:launcher")`
- Avoid generic `log` when it might conflict with standard library
- Capitalize the component part after 'log' (e.g., `logAuth` with capital 'A', `logLauncher` with capital 'L')


Control debug output:
```bash
DEBUG=* ./awmg --config config.toml # Enable all
Expand Down
120 changes: 12 additions & 108 deletions internal/launcher/launcher.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,8 +4,6 @@ import (
"context"
"fmt"
"log"
"os"
"strings"
"sync"
"time"

Expand Down Expand Up @@ -128,42 +126,14 @@ func GetOrLaunch(l *Launcher, serverID string) (*mcp.Connection, error) {
// Warn if using direct command in a container
isDirectCommand := serverCfg.Command != "docker"
if l.runningInContainer && isDirectCommand {
logger.LogWarn("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")
l.logSecurityWarning(serverID, serverCfg)
}

// Log the command being executed
logger.LogInfo("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)
log.Printf("[LAUNCHER] Command: %s", serverCfg.Command)
log.Printf("[LAUNCHER] Args: %v", sanitize.SanitizeArgs(serverCfg.Args))
logLauncher.Printf("Launching new server: serverID=%s, command=%s, inContainer=%v, isDirectCommand=%v",
serverID, serverCfg.Command, l.runningInContainer, isDirectCommand)
l.logLaunchStart(serverID, "", serverCfg, isDirectCommand)

// Check for environment variable passthrough (only check args after -e flags)
for i := 0; i < len(serverCfg.Args); i++ {
arg := serverCfg.Args[i]
// If this arg is "-e", check the next argument
if arg == "-e" && i+1 < len(serverCfg.Args) {
nextArg := serverCfg.Args[i+1]
// Check if it's a passthrough (no = sign) vs explicit value (has = sign)
if !strings.Contains(nextArg, "=") {
// This is a passthrough variable, check if it exists in our environment
if val := os.Getenv(nextArg); val != "" {
displayVal := val
if len(val) > 10 {
displayVal = val[:10] + "..."
}
log.Printf("[LAUNCHER] ✓ Env passthrough: %s=%s (from MCPG process)", nextArg, displayVal)
} else {
log.Printf("[LAUNCHER] ✗ WARNING: Env passthrough for %s requested but NOT FOUND in MCPG process", nextArg)
}
}
i++ // Skip the next arg since we just processed it
}
}
l.logEnvPassthrough(serverCfg.Args)

if len(serverCfg.Env) > 0 {
log.Printf("[LAUNCHER] Additional env vars: %v", sanitize.TruncateSecretMap(serverCfg.Env))
Expand All @@ -189,46 +159,18 @@ func GetOrLaunch(l *Launcher, serverID string) (*mcp.Connection, error) {
conn, err := result.conn, result.err
if err != nil {
// Enhanced error logging for command-based servers
logger.LogError("backend", "Failed to launch MCP backend server: %s, error=%v", serverID, err)
log.Printf("[LAUNCHER] ❌ FAILED to launch server '%s'", serverID)
log.Printf("[LAUNCHER] Error: %v", err)
log.Printf("[LAUNCHER] Debug Information:")
log.Printf("[LAUNCHER] - Command: %s", serverCfg.Command)
log.Printf("[LAUNCHER] - Args: %v", serverCfg.Args)
log.Printf("[LAUNCHER] - Env vars: %v", sanitize.TruncateSecretMap(serverCfg.Env))
log.Printf("[LAUNCHER] - Running in container: %v", l.runningInContainer)
log.Printf("[LAUNCHER] - Is direct command: %v", isDirectCommand)
log.Printf("[LAUNCHER] - Startup timeout: %v", l.startupTimeout)

if isDirectCommand && l.runningInContainer {
log.Printf("[LAUNCHER] ⚠️ Possible causes:")
log.Printf("[LAUNCHER] - Command '%s' may not be installed in the gateway container", serverCfg.Command)
log.Printf("[LAUNCHER] - Consider using 'container' config instead of 'command'")
log.Printf("[LAUNCHER] - Or add '%s' to the gateway's Dockerfile", serverCfg.Command)
} else if isDirectCommand {
log.Printf("[LAUNCHER] ⚠️ Possible causes:")
log.Printf("[LAUNCHER] - Command '%s' may not be in PATH", serverCfg.Command)
log.Printf("[LAUNCHER] - Check if '%s' is installed: which %s", serverCfg.Command, serverCfg.Command)
log.Printf("[LAUNCHER] - Verify file permissions and execute bit")
}

l.logLaunchError(serverID, "", err, serverCfg, isDirectCommand)
return nil, fmt.Errorf("failed to create connection: %w", err)
}

logger.LogInfo("backend", "Successfully launched MCP backend server: %s", serverID)
log.Printf("[LAUNCHER] Successfully launched: %s", serverID)
logLauncher.Printf("Connection established: serverID=%s", serverID)
l.logLaunchSuccess(serverID, "")

l.connections[serverID] = conn
return conn, nil

case <-time.After(l.startupTimeout):
// Timeout occurred
logger.LogError("backend", "MCP backend server startup timeout: %s, timeout=%v", serverID, 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")
log.Printf("[LAUNCHER] ⚠️ Consider increasing 'startupTimeout' in gateway config if server needs more time")
logLauncher.Printf("Startup timeout occurred: serverID=%s, timeout=%v", serverID, l.startupTimeout)
l.logTimeoutError(serverID, "")
return nil, fmt.Errorf("server startup timeout after %v", l.startupTimeout)
}
}
Expand Down Expand Up @@ -280,38 +222,14 @@ func GetOrLaunchForSession(l *Launcher, serverID, sessionID string) (*mcp.Connec
// Warn if using direct command in a container
isDirectCommand := serverCfg.Command != "docker"
if l.runningInContainer && isDirectCommand {
logger.LogWarn("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")
l.logSecurityWarning(serverID, serverCfg)
}

// Log the command being executed
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))
log.Printf("[LAUNCHER] Starting MCP server for session: %s (session: %s)", serverID, sessionID)
log.Printf("[LAUNCHER] Command: %s", serverCfg.Command)
log.Printf("[LAUNCHER] Args: %v", sanitize.SanitizeArgs(serverCfg.Args))
logLauncher.Printf("Launching new session server: serverID=%s, sessionID=%s, command=%s", serverID, sessionID, serverCfg.Command)
l.logLaunchStart(serverID, sessionID, serverCfg, isDirectCommand)

// Check for environment variable passthrough
for i := 0; i < len(serverCfg.Args); i++ {
arg := serverCfg.Args[i]
if arg == "-e" && i+1 < len(serverCfg.Args) {
nextArg := serverCfg.Args[i+1]
if !strings.Contains(nextArg, "=") {
if val := os.Getenv(nextArg); val != "" {
displayVal := val
if len(val) > 10 {
displayVal = val[:10] + "..."
}
log.Printf("[LAUNCHER] ✓ Env passthrough: %s=%s (from MCPG process)", nextArg, displayVal)
} else {
log.Printf("[LAUNCHER] ✗ WARNING: Env passthrough for %s requested but NOT FOUND in MCPG process", nextArg)
}
}
i++
}
}
l.logEnvPassthrough(serverCfg.Args)

if len(serverCfg.Env) > 0 {
log.Printf("[LAUNCHER] Additional env vars: %v", sanitize.TruncateSecretMap(serverCfg.Env))
Expand All @@ -335,37 +253,23 @@ func GetOrLaunchForSession(l *Launcher, serverID, sessionID string) (*mcp.Connec
case result := <-resultChan:
conn, err := result.conn, result.err
if err != nil {
logger.LogError("backend", "Failed to launch MCP backend server for session: server=%s, session=%s, error=%v", serverID, sessionID, err)
log.Printf("[LAUNCHER] ❌ FAILED to launch server '%s' for session '%s'", serverID, sessionID)
log.Printf("[LAUNCHER] Error: %v", err)
log.Printf("[LAUNCHER] Debug Information:")
log.Printf("[LAUNCHER] - Command: %s", serverCfg.Command)
log.Printf("[LAUNCHER] - Args: %v", serverCfg.Args)
log.Printf("[LAUNCHER] - Env vars: %v", sanitize.TruncateSecretMap(serverCfg.Env))
log.Printf("[LAUNCHER] - Running in container: %v", l.runningInContainer)
log.Printf("[LAUNCHER] - Is direct command: %v", isDirectCommand)
log.Printf("[LAUNCHER] - Startup timeout: %v", l.startupTimeout)
l.logLaunchError(serverID, sessionID, err, serverCfg, isDirectCommand)

// Record error in session pool
l.sessionPool.RecordError(serverID, sessionID)

return nil, fmt.Errorf("failed to create connection: %w", err)
}

logger.LogInfo("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)
l.logLaunchSuccess(serverID, sessionID)

// Add to session pool
l.sessionPool.Set(serverID, sessionID, conn)
return conn, nil

case <-time.After(l.startupTimeout):
// Timeout occurred
logger.LogError("backend", "MCP backend server startup timeout for session: server=%s, session=%s, timeout=%v", serverID, 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")
log.Printf("[LAUNCHER] ⚠️ Consider increasing 'startupTimeout' in gateway config if server needs more time")
l.logTimeoutError(serverID, sessionID)
// Record error in session pool before returning
l.sessionPool.RecordError(serverID, sessionID)
return nil, fmt.Errorf("server startup timeout after %v", l.startupTimeout)
Expand Down
123 changes: 123 additions & 0 deletions internal/launcher/log_helpers.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,123 @@
package launcher

import (
"fmt"
"log"
"os"
"strings"

"github.com/githubnext/gh-aw-mcpg/internal/config"
"github.com/githubnext/gh-aw-mcpg/internal/logger"
"github.com/githubnext/gh-aw-mcpg/internal/logger/sanitize"
)

// sessionSuffix returns a formatted session suffix for log messages
func sessionSuffix(sessionID string) string {
if sessionID == "" {
return ""
}
return fmt.Sprintf(" for session '%s'", sessionID)
}

// 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)
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")
}

// 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))
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))
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)
}
log.Printf("[LAUNCHER] Command: %s", serverCfg.Command)
log.Printf("[LAUNCHER] Args: %v", sanitize.SanitizeArgs(serverCfg.Args))
}

// logEnvPassthrough checks and logs environment variable passthrough status
func (l *Launcher) logEnvPassthrough(args []string) {
for i := 0; i < len(args); i++ {
arg := args[i]
// If this arg is "-e", check the next argument
if arg == "-e" && i+1 < len(args) {
nextArg := args[i+1]
// Check if it's a passthrough (no = sign) vs explicit value (has = sign)
if !strings.Contains(nextArg, "=") {
// This is a passthrough variable, check if it exists in our environment
if val := os.Getenv(nextArg); val != "" {
displayVal := val
if len(val) > 10 {
displayVal = val[:10] + "..."
}
log.Printf("[LAUNCHER] ✓ Env passthrough: %s=%s (from MCPG process)", nextArg, displayVal)
} else {
log.Printf("[LAUNCHER] ✗ WARNING: Env passthrough for %s requested but NOT FOUND in MCPG process", nextArg)
}
}
i++ // Skip the next arg since we just processed it
}
}
}

// 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",
sessionSuffix(sessionID), serverID, sessionSuffix(sessionID), err)
log.Printf("[LAUNCHER] ❌ FAILED to launch server '%s'%s", serverID, sessionSuffix(sessionID))
log.Printf("[LAUNCHER] Error: %v", err)
log.Printf("[LAUNCHER] Debug Information:")
log.Printf("[LAUNCHER] - Command: %s", serverCfg.Command)
log.Printf("[LAUNCHER] - Args: %v", serverCfg.Args)
log.Printf("[LAUNCHER] - Env vars: %v", sanitize.TruncateSecretMap(serverCfg.Env))
log.Printf("[LAUNCHER] - Running in container: %v", l.runningInContainer)
log.Printf("[LAUNCHER] - Is direct command: %v", isDirectCommand)
log.Printf("[LAUNCHER] - Startup timeout: %v", l.startupTimeout)

if isDirectCommand && l.runningInContainer {
log.Printf("[LAUNCHER] ⚠️ Possible causes:")
log.Printf("[LAUNCHER] - Command '%s' may not be installed in the gateway container", serverCfg.Command)
log.Printf("[LAUNCHER] - Consider using 'container' config instead of 'command'")
log.Printf("[LAUNCHER] - Or add '%s' to the gateway's Dockerfile", serverCfg.Command)
} else if isDirectCommand {
log.Printf("[LAUNCHER] ⚠️ Possible causes:")
log.Printf("[LAUNCHER] - Command '%s' may not be in PATH", serverCfg.Command)
log.Printf("[LAUNCHER] - Check if '%s' is installed: which %s", serverCfg.Command, serverCfg.Command)
log.Printf("[LAUNCHER] - Verify file permissions and execute bit")
}
}

// 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",
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")
log.Printf("[LAUNCHER] ⚠️ Consider increasing 'startupTimeout' in gateway config if server needs more time")
if sessionID != "" {
logLauncher.Printf("Startup timeout occurred: serverID=%s, sessionID=%s, timeout=%v", serverID, sessionID, l.startupTimeout)
} else {
logLauncher.Printf("Startup timeout occurred: serverID=%s, timeout=%v", serverID, l.startupTimeout)
}
}

// 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)
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)
log.Printf("[LAUNCHER] Successfully launched: %s", serverID)
logLauncher.Printf("Connection established: serverID=%s", serverID)
}
}
Loading