Skip to content

Harden Copilot api-proxy startup: verify listener accept readiness and absorb first-request ECONNREFUSED #52619

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

Closed
Copilot wants to merge 6 commits into from
Closed

Harden Copilot api-proxy startup: verify listener accept readiness and absorb first-request ECONNREFUSED #52619

Show file tree
Hide file tree
Changes from 3 commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
3faa392
Initial plan
Copilot Aug 14, 2026
763e71a
Fix Copilot proxy listener readiness and first ECONNREFUSED retry path
Copilot Aug 14, 2026
0b6bf81
Harden Copilot provider listener readiness probe behavior
Copilot Aug 14, 2026
12d8441
Address review feedback: TLS-aware readiness, noop ordering, deadline…
Copilot Aug 14, 2026
ddb0b38
Clarify connectImpl/readyEvent contract in JSDoc per code review
Copilot Aug 14, 2026
7a697e8
Merge remote-tracking branch 'origin/main' into copilot/fix-copilot-e…
Copilot Aug 15, 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
94 changes: 94 additions & 0 deletions actions/setup/js/awf_reflect.cjs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@ require("./shim.cjs");

const fs = require("fs");
const path = require("path");
const net = require("net");
const { withRetry, sleep } = require("./error_recovery.cjs");
const { getErrorMessage } = require("./error_helpers.cjs");

Expand All @@ -33,6 +34,12 @@ const AWF_REFLECT_OUTPUT_PATH = "/tmp/gh-aw/sandbox/firewall/awf-reflect.json";
const AWF_REFLECT_TIMEOUT_MS = 60000;
// Milliseconds to wait for each models_url fallback fetch (shorter than the main reflect timeout).
const AWF_MODELS_URL_TIMEOUT_MS = 3000;
// Milliseconds to wait for an api-proxy provider listener to accept a real TCP connection.
const AWF_PROVIDER_LISTENER_READY_TIMEOUT_MS = 15000;
// Delay between provider-listener readiness probes.
const AWF_PROVIDER_LISTENER_READY_RETRY_MS = 250;
// Per-attempt connect timeout while probing provider listener readiness.
const AWF_PROVIDER_LISTENER_READY_PROBE_TIMEOUT_MS = 2000;
// Maximum attempts for models_url fallback fetches when the proxy is not yet ready.
const AWF_MODELS_URL_MAX_ATTEMPTS = 5;
// Base delay between models_url fallback retries. Uses exponential backoff.
Expand Down Expand Up @@ -323,6 +330,7 @@ async function fetchAWFReflect(options) {
status: res.status,
};
}

/** @type {any} */
const reflectData = await res.json();
// Attempt to fill in null models for configured providers by fetching directly
Expand Down Expand Up @@ -364,6 +372,88 @@ async function fetchAWFReflect(options) {
}
}

/**
* Wait until a provider listener (e.g. http://api-proxy:10002) accepts a real TCP
* connection, or time out.
*
* This guards against startup races where /reflect is available but a per-provider
* listener has not yet bound/started accepting connections.
*
* @param {{
* baseUrl: string,
* timeoutMs?: number,
* retryDelayMs?: number,
* perAttemptTimeoutMs?: number,
* logger?: (msg: string) => void,
* connectImpl?: typeof net.connect,
* }} options
* @returns {Promise<{ ok: true } | { ok: false, reason: "invalid_base_url" | "timeout", error: string }>}
*/
async function waitForProviderListenerReady(options) {

@github-actions github-actions Bot Aug 14, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

L392-455: yagni: hand-rolled retry loop with manual timers/socket state machine reimplements the withRetry(operation, config) helper already imported in this file (used at line 183). withRetry + a plain net.connect promise wrapper would cut this to ~15 lines.

const logger = options?.logger ?? DEFAULT_REFLECT_LOGGER;
const timeoutMs = options?.timeoutMs ?? AWF_PROVIDER_LISTENER_READY_TIMEOUT_MS;
const retryDelayMs = options?.retryDelayMs ?? AWF_PROVIDER_LISTENER_READY_RETRY_MS;
const perAttemptTimeoutMsRaw = options?.perAttemptTimeoutMs ?? AWF_PROVIDER_LISTENER_READY_PROBE_TIMEOUT_MS;
const perAttemptTimeoutMs = Number.isFinite(perAttemptTimeoutMsRaw) && perAttemptTimeoutMsRaw > 0 ? perAttemptTimeoutMsRaw : AWF_PROVIDER_LISTENER_READY_PROBE_TIMEOUT_MS;

@github-actions github-actions Bot Aug 14, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

L396-397: yagni: defensive Number.isFinite/>0 validation on an internal-only perAttemptTimeoutMs option nobody sets from outside this repo. Drop the guard; trust the constant default.

const connectImpl = options?.connectImpl ?? net.connect;
const baseUrl = String(options?.baseUrl ?? "").trim();
if (!baseUrl) {
return { ok: false, reason: "invalid_base_url", error: "baseUrl is empty" };
}

let parsed;
try {
parsed = new URL(baseUrl);

@github-actions github-actions Bot Aug 14, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[/diagnosing-bugs] socket.end() is called on a successful connect, but the error listener is not removed before end(). If the socket emits a late error after end() (common on abrupt server closes), the error handler will fire and set lastError even though the probe already settled true.

💡 Suggested fix 
socket.once("connect", () => {
  clear();
  socket.removeAllListeners("error");
  socket.destroy(); // destroy instead of end — we only need the handshake
  settle(true);
});

Using destroy() after a successful connect avoids the half-open window where a trailing RST could trigger the error listener.

@copilot please address this.

} catch {
return { ok: false, reason: "invalid_base_url", error: `invalid baseUrl: ${baseUrl}` };
}
const host = parsed.hostname;
const port = parsed.port ? Number.parseInt(parsed.port, 10) : parsed.protocol === "https:" ? 443 : 80;
if (!host || !Number.isFinite(port) || port <= 0) {
return { ok: false, reason: "invalid_base_url", error: `baseUrl missing host/port: ${baseUrl}` };
}

logger(`awf-reflect: waiting for provider listener readiness at ${host}:${port} (timeout=${timeoutMs}ms)`);
const startedAt = Date.now();
let lastError = "connection not ready";
while (Date.now() - startedAt < timeoutMs) {
const ready = await new Promise(resolve => {
const socket = connectImpl({ host, port });
let settled = false;

@github-actions github-actions Bot Aug 14, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[/tdd] The per-attempt connect-timeout branch (where the setTimeout fires before connect/error) is not tested — only the error event path is covered.

💡 Suggested test sketch 
it("returns timeout when per-attempt timer fires (hung connect)", async () => {
  const probingConnect = vi.fn().mockImplementation(() => {
    // never fire connect or error
    return {
      once(event, cb) { return this; },
      end() {},
      destroy() {},
    };
  });
  const result = await waitForProviderListenerReady({
    baseUrl: "(apiproxy/redacted)
    timeoutMs: 50,
    retryDelayMs: 1,
    perAttemptTimeoutMs: 5,
    connectImpl: probingConnect,
    logger: () => {},
  });
  expect(result.ok).toBe(false);
  expect(result.reason).toBe("timeout");
  expect(result.error).toContain("timed out after 5ms");
});

This branch sets lastError to the per-attempt timeout message; without a test, a refactor could silently break it.

@copilot please address this.

const settle = value => {
if (settled) return;
settled = true;
resolve(value);
};
const timer = setTimeout(() => {
clear();
lastError = `connect attempt timed out after ${perAttemptTimeoutMs}ms`;
socket.destroy();
settle(false);
}, perAttemptTimeoutMs);
const clear = () => clearTimeout(timer);
socket.once("connect", () => {

@github-actions github-actions Bot Aug 14, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This readiness check is too weak for https:// providers: a raw TCP connect can succeed before the TLS listener is actually usable, so the harness can still advance into the same first-request failure path this patch is meant to prevent.

💡 Why this needs to change

waitForProviderListenerReady() derives the port from the URL, but it always probes with net.connect() and treats any accepted socket as success. For HTTPS endpoints that only proves something is listening on the port; it does not prove TLS negotiation will succeed or that the HTTP stack is ready to serve requests. In practice that leaves a race where the new gate reports ready and the first SDK call still dies during handshake/startup.

A safer approach is to probe at the protocol level: use tls.connect() for https: URLs (or perform a short /health/HEAD request through the same stack the real client uses), and only mark readiness once the secure handshake completes successfully.

const socket = parsed.protocol === "https:"
  ? tls.connect({ host, port, servername: host })
  : net.connect({ host, port });

That keeps the readiness gate aligned with the actual failure mode instead of only checking that the TCP port opened.

clear();
socket.end();
settle(true);
});
socket.once("error", err => {
clear();
lastError = getErrorMessage(err);
socket.destroy();
settle(false);
});
});
if (ready) {
logger(`awf-reflect: provider listener is accepting connections at ${host}:${port}`);
return { ok: true };
}
await sleep(retryDelayMs);
}
logger(`awf-reflect: provider listener readiness timed out for ${host}:${port} (${lastError})`);
return { ok: false, reason: "timeout", error: lastError };
}

/**
* Returns true when the model name matches well-known Anthropic naming patterns:
* "claude-*" prefix, or "-opus", "-haiku", or "-sonnet" as a segment or suffix.
Expand Down Expand Up @@ -793,11 +883,15 @@ if (typeof module !== "undefined" && module.exports) {
AWF_MODELS_URL_MAX_ATTEMPTS,
AWF_MODELS_URL_RETRY_BASE_MS,
AWF_MODELS_URL_RETRY_MAX_MS,
AWF_PROVIDER_LISTENER_READY_TIMEOUT_MS,
AWF_PROVIDER_LISTENER_READY_RETRY_MS,
AWF_PROVIDER_LISTENER_READY_PROBE_TIMEOUT_MS,
GEMINI_MODEL_NAME_PREFIX,
enrichReflectModels,
extractModelIds,
fetchAWFReflect,
fetchModelsFromUrl,
waitForProviderListenerReady,
getCatalogModelEntry,
inferProviderTypeForModel,
inferWireApiForModel,
Expand Down
69 changes: 69 additions & 0 deletions actions/setup/js/awf_reflect.test.cjs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,11 +13,15 @@ const {
AWF_MODELS_URL_MAX_ATTEMPTS,
AWF_MODELS_URL_RETRY_BASE_MS,
AWF_MODELS_URL_RETRY_MAX_MS,
AWF_PROVIDER_LISTENER_READY_TIMEOUT_MS,
AWF_PROVIDER_LISTENER_READY_RETRY_MS,
AWF_PROVIDER_LISTENER_READY_PROBE_TIMEOUT_MS,
GEMINI_MODEL_NAME_PREFIX,
enrichReflectModels,
extractModelIds,
fetchAWFReflect,
fetchModelsFromUrl,
waitForProviderListenerReady,
getCatalogModelEntry,
inferProviderTypeForModel,
inferWireApiForModel,
Expand All @@ -36,10 +40,75 @@ describe("awf_reflect.cjs", () => {
expect(AWF_MODELS_URL_MAX_ATTEMPTS).toBe(5);
expect(AWF_MODELS_URL_RETRY_BASE_MS).toBe(250);
expect(AWF_MODELS_URL_RETRY_MAX_MS).toBe(2000);
expect(AWF_PROVIDER_LISTENER_READY_TIMEOUT_MS).toBe(15000);
expect(AWF_PROVIDER_LISTENER_READY_RETRY_MS).toBe(250);
expect(AWF_PROVIDER_LISTENER_READY_PROBE_TIMEOUT_MS).toBe(2000);
expect(GEMINI_MODEL_NAME_PREFIX).toBe("models/");
});
});

describe("waitForProviderListenerReady", () => {
it("returns ok when listener accepts a connection", async () => {
const probingConnect = vi.fn().mockImplementation(() => {
const listeners = {};
queueMicrotask(() => listeners.connect && listeners.connect());
return {
once(event, cb) {
listeners[event] = cb;
return this;
},
end() {},
destroy() {},
};
});

const result = await waitForProviderListenerReady({
baseUrl: "http://api-proxy:10002",
timeoutMs: 500,
retryDelayMs: 1,
connectImpl: probingConnect,
logger: () => {},
});
expect(result).toEqual({ ok: true });
expect(probingConnect).toHaveBeenCalled();
});

it("returns timeout when listener keeps refusing connections", async () => {
const probingConnect = vi.fn().mockImplementation(() => {
const listeners = {};
queueMicrotask(() => listeners.error && listeners.error(new Error("connect ECONNREFUSED")));
return {
once(event, cb) {
listeners[event] = cb;
return this;
},
end() {},
destroy() {},
};
});

const result = await waitForProviderListenerReady({
baseUrl: "http://api-proxy:10002",
timeoutMs: 20,
retryDelayMs: 1,
connectImpl: probingConnect,
logger: () => {},
});
expect(result.ok).toBe(false);
expect(result.reason).toBe("timeout");
expect(result.error).toContain("ECONNREFUSED");
});

it("returns invalid_base_url for malformed baseUrl", async () => {
const result = await waitForProviderListenerReady({
baseUrl: "not a url",
logger: () => {},
});
expect(result.ok).toBe(false);
expect(result.reason).toBe("invalid_base_url");
});
});

describe("extractModelIds", () => {
it("returns null for null input", () => {
expect(extractModelIds(null)).toBeNull();
Expand Down
36 changes: 36 additions & 0 deletions actions/setup/js/copilot_harness.cjs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -65,6 +65,8 @@ const {
AWF_REFLECT_TIMEOUT_MS,
AWF_MODELS_URL_TIMEOUT_MS,
GEMINI_MODEL_NAME_PREFIX,
AWF_PROVIDER_LISTENER_READY_TIMEOUT_MS,
waitForProviderListenerReady,
enrichReflectModels,
extractModelIds,
fetchAWFReflect,
Expand Down Expand Up @@ -162,6 +164,8 @@ const SDK_SESSION_IDLE_TIMEOUT_PATTERN = /Timeout after \d+ms waiting for sessio
// avoid false positives from any process that logs "Gateway shutdown initiated"
// as plain text.
const MCP_GATEWAY_SHUTDOWN_PATTERN = /"message"\s*:\s*"Gateway shutdown initiated"/;
const CONNECTION_REFUSED_ERROR_PATTERN = /connection refused|ECONNREFUSED/i;
const FIRST_CONNECTION_REFUSED_RETRY_DELAY_MS = 1000;

// Pattern to detect null-type tool_call error that poisons conversation history.
// Matches the Copilot API 400 error:
Expand Down Expand Up @@ -488,6 +492,15 @@ function isMCPGatewayShutdownError(output) {
return MCP_GATEWAY_SHUTDOWN_PATTERN.test(output);
}

/**
* Determine whether output contains a connection-refused signal.
* @param {string} output
* @returns {boolean}
*/
function isConnectionRefusedError(output) {
return CONNECTION_REFUSED_ERROR_PATTERN.test(output);
}

/**
* Extract a compact tail preview from combined process output for failure logs.
* @param {string} output
Expand Down Expand Up @@ -1017,6 +1030,20 @@ async function main() {
}

log(`copilot-sdk driver mode: multi-provider config resolved (${multiProvider.providers.length} providers, ${multiProvider.models.length} models, model=${resolvedModel})`);

const uniqueProviderBaseUrls = [...new Set(multiProvider.providers.map(provider => String(provider.baseUrl || "").trim()).filter(Boolean))];
for (const providerBaseUrlToProbe of uniqueProviderBaseUrls) {
Comment on lines +1045 to +1049

@github-actions github-actions Bot Aug 14, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

L1035-1042: yagni: loops over uniqueProviderBaseUrls but in practice this is almost always a single provider; the Set/map/filter/loop machinery for the common one-provider case adds indirection for a rare multi-provider path. A simple for-of over multiProvider.providers with baseUrl dedup inline would read the same in fewer moving parts.

const readiness = await waitForProviderListenerReady({
baseUrl: providerBaseUrlToProbe,
timeoutMs: AWF_PROVIDER_LISTENER_READY_TIMEOUT_MS,
logger: log,
});
if (!readiness.ok) {
emitInfrastructureIncomplete(`api-proxy provider listener was not ready at ${providerBaseUrlToProbe} before first Copilot SDK request (${readiness.error}).`);
log(`copilot-sdk driver mode: provider listener readiness probe failed for ${providerBaseUrlToProbe}: ${readiness.error}`);

@github-actions github-actions Bot Aug 14, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[/diagnosing-bugs] If uniqueProviderBaseUrls is empty (e.g., all providers had falsy baseUrl), the loop is skipped silently. The readiness check then offers no protection for misconfigured providers.

💡 Suggested guard 
if (uniqueProviderBaseUrls.length === 0) {
  log("copilot-sdk driver mode: no provider baseUrls to probe — skipping listener readiness check");
}

A debug log here makes it visible in traces that the probe was bypassed, which helps when diagnosing future ECONNREFUSED incidents.

@copilot please address this.

process.exit(1);
}
}
}

// Merge SDK env additions into the child process env only when the SDK helper
Expand Down Expand Up @@ -1179,6 +1206,7 @@ async function main() {
const isNullTypeToolCall = isNullTypeToolCallError(result.output);
const isSDKSessionIdleTimeout = isSDKSessionIdleTimeoutError(result.output);
const isMCPGatewayShutdown = isMCPGatewayShutdownError(result.output);
const isConnectionRefused = isConnectionRefusedError(result.output);
const permissionDeniedCount = countPermissionDeniedIssues(result.output);
const hasNumerousPermissionDenied = hasNumerousPermissionDeniedIssues(result.output);
const nonRetryableGuard = detectNonRetryableHarnessGuard(result.output);
Expand Down Expand Up @@ -1215,6 +1243,7 @@ async function main() {
` isNullTypeToolCallError=${isNullTypeToolCall}` +
` isSDKSessionIdleTimeoutError=${isSDKSessionIdleTimeout}` +
` isMCPGatewayShutdownError=${isMCPGatewayShutdown}` +
` isConnectionRefusedError=${isConnectionRefused}` +
` isAuthError=${isAuthErr}` +
` isAuthenticationFailedError=${isAuthenticationFailed}` +
` permissionDeniedCount=${permissionDeniedCount}` +
Expand Down Expand Up @@ -1363,6 +1392,12 @@ async function main() {
}
}

if (attempt === 0 && isConnectionRefused && maxRetries > 0) {

@github-actions github-actions Bot Aug 14, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

[/diagnosing-bugs] The ECONNREFUSED retry only fires when attempt === 0, but the listener readiness probe already runs before the first request. If the probe passes yet the first request still gets ECONNREFUSED (e.g., provider crashes immediately after probe), the one-shot retry helps; however this intent isn't documented in a comment or test.

💡 Suggestion

Add a comment explaining the invariant:

// The readiness probe ensures the listener is up before attempt 0.
// A ECONNREFUSED here means the provider died in the narrow window
// between the probe and the first request — retry once as a fresh run.
if (attempt === 0 && isConnectionRefused && maxRetries > 0) {

Also add a test that verifies attempt > 0 ECONNREFUSED does not trigger this path, to prevent the logic from accidentally expanding.

@copilot please address this.

useContinueOnRetry = false;
log(`attempt ${attempt + 1}: connection refused on first request path — retrying as fresh run with short backoff (${FIRST_CONNECTION_REFUSED_RETRY_DELAY_MS}ms) (attempt ${attempt + 2}/${maxRetries + 1})`);
return { action: "retry", nextDelayMs: FIRST_CONNECTION_REFUSED_RETRY_DELAY_MS };
Comment on lines +1406 to +1409
}

if (isStartupRetryEligible && isStartupNoOutputRetryCandidate(result) && scheduledExit2Retries < MAX_SCHEDULED_EXIT2_RETRIES && attempt < maxRetries) {
scheduledExit2Retries += 1;
scheduledExit2RetryAttempted = true;
Expand Down Expand Up @@ -1468,6 +1503,7 @@ if (typeof module !== "undefined" && module.exports) {
AGENTIC_ENGINE_TIMEOUT_PATTERN,
buildMissingToolPermissionIssuePayload,
isAuthenticationFailedError,
isConnectionRefusedError,
isMCPGatewayShutdownError,
isSDKSessionIdleTimeoutError,
startCopilotSDKServer,
Expand Down
12 changes: 12 additions & 0 deletions actions/setup/js/copilot_harness.test.cjs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,7 @@ const {
AGENTIC_ENGINE_TIMEOUT_PATTERN,
isDetectionPhase,
isAuthenticationFailedError,
isConnectionRefusedError,
isRetryableProxyAuthenticationFailure,
isMCPGatewayShutdownError,
isModelAvailableInReflectData,
Expand Down Expand Up @@ -125,6 +126,17 @@ describe("copilot_harness.cjs", () => {
expect(CAPI_ERROR_400_PATTERN.test(errorOutput)).toBe(true);
});

describe("connection refused detection", () => {
it("detects ECONNREFUSED signals in SDK driver output", () => {
const output = "Failed native model HTTP request: error sending request for url (http://api-proxy:10002/chat/completions): " + "client error (Connect): tcp connect error: Connection refused (os error 111) [ECONNREFUSED]";
expect(isConnectionRefusedError(output)).toBe(true);
});

it("does not match unrelated output", () => {
expect(isConnectionRefusedError("CAPIError: 400 bad request")).toBe(false);
});
});

describe("CAPI quota-exceeded detection pattern", () => {
it("matches the observed CAPIError 429 quota exceeded error", () => {
expect(isCAPIQuotaExceededError("CAPIError: 429 429 quota exceeded")).toBe(true);
Expand Down
Loading