diff --git a/.changeset/patch-extend-safe-outputs-timeout.md b/.changeset/patch-extend-safe-outputs-timeout.md new file mode 100644 index 0000000000..56b16e3cb6 --- /dev/null +++ b/.changeset/patch-extend-safe-outputs-timeout.md @@ -0,0 +1,5 @@ +--- +"gh-aw": patch +--- + +Add more diagnostic logging around safe-outputs MCP server initialization and extend the startup timeout from 10s to 60s to reduce CI flakes. diff --git a/.changeset/patch-safe-outputs-startup-logging.md b/.changeset/patch-safe-outputs-startup-logging.md new file mode 100644 index 0000000000..adfb8d2cf0 --- /dev/null +++ b/.changeset/patch-safe-outputs-startup-logging.md @@ -0,0 +1,5 @@ +--- +"gh-aw": patch +--- + +Add diagnostic logging and widen the safe-outputs MCP server startup timeout to 60 seconds to tame CI flakiness. diff --git a/actions/setup/js/mcp_http_transport.cjs b/actions/setup/js/mcp_http_transport.cjs index 9ba0a5336a..044a756b49 100644 --- a/actions/setup/js/mcp_http_transport.cjs +++ b/actions/setup/js/mcp_http_transport.cjs @@ -1,6 +1,12 @@ // @ts-check /// +const { createLogger } = require("./mcp_logger.cjs"); +const moduleLogger = createLogger("mcp_http_transport"); + +// Log immediately at module load time +moduleLogger.debug("Module is being loaded"); + /** * MCP HTTP Transport Implementation * @@ -74,9 +80,14 @@ class MCPServer { * @param {any} transport - Transport instance (must have setServer and start methods) */ async connect(transport) { + const logger = createLogger("MCPServer"); + logger.debug("Starting connect..."); this.transport = transport; + logger.debug("Set transport"); transport.setServer(this); + logger.debug("Called setServer"); await transport.start(); + logger.debug("Transport.start() completed"); } /** @@ -126,10 +137,13 @@ class MCPHTTPTransport { * Start the transport */ async start() { + const logger = createLogger("MCPHTTPTransport"); + logger.debug(`Called, started=${this.started}`); if (this.started) { throw new Error("Transport already started"); } this.started = true; + logger.debug("Set started=true"); } /** diff --git a/actions/setup/js/mcp_server_core.cjs b/actions/setup/js/mcp_server_core.cjs index 697ab1d554..e41b6c2067 100644 --- a/actions/setup/js/mcp_server_core.cjs +++ b/actions/setup/js/mcp_server_core.cjs @@ -1,6 +1,12 @@ // @ts-check /// +const { createLogger } = require("./mcp_logger.cjs"); +const moduleLogger = createLogger("mcp_server_core"); + +// Log immediately at module load time +moduleLogger.debug("Module is being loaded"); + /** * MCP Server Core Module * diff --git a/actions/setup/js/safe-outputs-mcp-server.cjs b/actions/setup/js/safe-outputs-mcp-server.cjs index 601fbe8f79..decf5dbb13 100644 --- a/actions/setup/js/safe-outputs-mcp-server.cjs +++ b/actions/setup/js/safe-outputs-mcp-server.cjs @@ -5,8 +5,16 @@ // This is the main entry point script for the safe-outputs MCP server // It starts the HTTP server on the configured port +const { createLogger } = require("./mcp_logger.cjs"); +const logger = createLogger("safe-outputs-entry"); + +// Log immediately to verify Node.js execution starts +logger.debug("Entry point script executing"); + const { startHttpServer } = require("./safe_outputs_mcp_server_http.cjs"); +logger.debug("Successfully required safe_outputs_mcp_server_http.cjs"); + // Start the HTTP server // The server reads configuration from /opt/gh-aw/safeoutputs/config.json // Port and API key are configured via environment variables: @@ -18,13 +26,18 @@ const { startHttpServer } = require("./safe_outputs_mcp_server_http.cjs"); // the MCP gateway doesn't perform the MCP protocol initialization handshake. // It directly calls methods like tools/list without the Mcp-Session-Id header. if (require.main === module) { + logger.debug("In require.main === module block"); const port = parseInt(process.env.GH_AW_SAFE_OUTPUTS_PORT || "3001", 10); const logDir = process.env.GH_AW_MCP_LOG_DIR; + logger.debug(`Port: ${port}, LogDir: ${logDir}`); + logger.debug("Calling startHttpServer..."); startHttpServer({ port, logDir, stateless: true }).catch(error => { - console.error(`Failed to start safe-outputs HTTP server: ${error.message}`); + logger.debugError("Failed to start safe-outputs HTTP server: ", error); process.exit(1); }); + + logger.debug("startHttpServer call initiated (async)"); } module.exports = { startHttpServer }; diff --git a/actions/setup/js/safe_outputs_mcp_server_http.cjs b/actions/setup/js/safe_outputs_mcp_server_http.cjs index 873d56ff8c..e4916ac4dd 100644 --- a/actions/setup/js/safe_outputs_mcp_server_http.cjs +++ b/actions/setup/js/safe_outputs_mcp_server_http.cjs @@ -1,6 +1,12 @@ // @ts-check /// +const { createLogger } = require("./mcp_logger.cjs"); +const moduleLogger = createLogger("safe_outputs_mcp_server_http"); + +// Log immediately at module load time (before any requires) +moduleLogger.debug("Module is being loaded"); + /** * Safe Outputs MCP Server with HTTP Transport * @@ -19,14 +25,23 @@ */ const http = require("http"); +moduleLogger.debug("Loaded http"); const { randomUUID } = require("crypto"); +moduleLogger.debug("Loaded crypto"); const { MCPServer, MCPHTTPTransport } = require("./mcp_http_transport.cjs"); -const { createLogger } = require("./mcp_logger.cjs"); +moduleLogger.debug("Loaded mcp_http_transport.cjs"); +const { createLogger: createMCPLogger } = require("./mcp_logger.cjs"); +moduleLogger.debug("Loaded mcp_logger.cjs"); const { bootstrapSafeOutputsServer, cleanupConfigFile } = require("./safe_outputs_bootstrap.cjs"); +moduleLogger.debug("Loaded safe_outputs_bootstrap.cjs"); const { createAppendFunction } = require("./safe_outputs_append.cjs"); +moduleLogger.debug("Loaded safe_outputs_append.cjs"); const { createHandlers } = require("./safe_outputs_handlers.cjs"); +moduleLogger.debug("Loaded safe_outputs_handlers.cjs"); const { attachHandlers, registerPredefinedTools, registerDynamicTools } = require("./safe_outputs_tools_loader.cjs"); +moduleLogger.debug("Loaded safe_outputs_tools_loader.cjs"); const { getErrorMessage } = require("./error_helpers.cjs"); +moduleLogger.debug("All modules loaded successfully"); /** * Create and configure the MCP server with tools @@ -36,7 +51,7 @@ const { getErrorMessage } = require("./error_helpers.cjs"); */ function createMCPServer(options = {}) { // Create logger early - const logger = createLogger("safeoutputs"); + const logger = createMCPLogger("safeoutputs"); logger.debug(`=== Creating MCP Server ===`); @@ -176,8 +191,9 @@ async function startHttpServer(options = {}) { const port = options.port || 3000; const stateless = options.stateless || false; - const logger = createLogger("safe-outputs-startup"); + const logger = createMCPLogger("safe-outputs-startup"); + logger.debug(`startHttpServer called with port=${port}, stateless=${stateless}`); logger.debug(`=== Starting Safe Outputs MCP HTTP Server ===`); logger.debug(`Port: ${port}`); logger.debug(`Mode: ${stateless ? "stateless" : "stateful"}`); @@ -185,6 +201,7 @@ async function startHttpServer(options = {}) { // Create the MCP server try { + logger.debug(`About to call createMCPServer...`); const { server, config, logger: mcpLogger } = createMCPServer({ logDir: options.logDir }); // Use the MCP logger for subsequent messages @@ -206,7 +223,9 @@ async function startHttpServer(options = {}) { // Connect server to transport logger.debug(`Connecting server to transport...`); + logger.debug(`About to call server.connect(transport)...`); await server.connect(transport); + logger.debug(`server.connect(transport) completed successfully`); logger.debug(`Server connected to transport successfully`); // Create HTTP server diff --git a/actions/setup/sh/start_safe_outputs_server.sh b/actions/setup/sh/start_safe_outputs_server.sh index e95cd11cf5..c8fdb5d58c 100755 --- a/actions/setup/sh/start_safe_outputs_server.sh +++ b/actions/setup/sh/start_safe_outputs_server.sh @@ -87,9 +87,9 @@ node mcp-server.cjs >> /tmp/gh-aw/mcp-logs/safeoutputs/server.log 2>&1 & SERVER_PID=$! echo "Started safe-outputs MCP server with PID $SERVER_PID" -# Wait for server to be ready (max 10 seconds) +# Wait for server to be ready (max 60 seconds) echo "Waiting for server to become ready..." -for i in {1..10}; do +for i in {1..60}; do # Check if process is still running if ! kill -0 $SERVER_PID 2>/dev/null; then echo "ERROR: Server process $SERVER_PID has died" @@ -100,12 +100,12 @@ for i in {1..10}; do # Check if server is responding if curl -s -f "http://localhost:$GH_AW_SAFE_OUTPUTS_PORT/health" > /dev/null 2>&1; then - echo "Safe Outputs MCP server is ready (attempt $i/10)" + echo "Safe Outputs MCP server is ready (attempt $i/60)" break fi - if [ "$i" -eq 10 ]; then - echo "ERROR: Safe Outputs MCP server failed to start after 10 seconds" + if [ "$i" -eq 60 ]; then + echo "ERROR: Safe Outputs MCP server failed to start after 60 seconds" echo "Process status: $(pgrep -f 'mcp-server.cjs' || echo 'not running')" echo "Server log contents:" cat /tmp/gh-aw/mcp-logs/safeoutputs/server.log @@ -114,7 +114,7 @@ for i in {1..10}; do exit 1 fi - echo "Waiting for server... (attempt $i/10)" + echo "Waiting for server... (attempt $i/60)" sleep 1 done