From f737961cfc6ed076333751e8d1f5669bbb2efdac Mon Sep 17 00:00:00 2001 From: Izaak Gough Date: Mon, 10 Aug 2026 10:32:12 +0100 Subject: [PATCH] fix(functions): report discovery crashes instead of blaming the timeout Function discovery polls the admin server until it answers, so a codebase that died during module load looked identical to one that was merely slow: both surfaced "User code failed to load. Cannot determine backend specification" after the full 10s budget, with the actual error nowhere in sight. Race the child's exit against the poll so a crash reports its own exit code and stderr immediately. The attendant listeners move to spawn time. Neither exit nor error replays, so a server that died before kill() ran left a listener that could never fire and a shutdown that never resolved. Also fixes the escape hatch people reach for when they hit this: - FUNCTIONS_DISCOVERY_TIMEOUT is read in seconds but the error printed milliseconds and named neither the variable nor the unit. Setting it to 30000 in the belief it meant 30s asked for 8.3 hours, disabling the timeout rather than extending it. Bare numbers still mean seconds, an explicit s or ms suffix is now accepted, and a suspiciously large bare value warns. - The timeout message now states the elapsed time in seconds and tells the user which variable to set. - The poll loop had no backoff, spinning at ~144k connection attempts per second and saturating a core taken from the process it was waiting on. It now sleeps 100ms between attempts, matching functionsRuntimeWorker. - The timeout timer is now cleared on the success path. Fixes #7775 --- CHANGELOG.md | 3 + .../runtimes/discovery/index.spec.ts | 85 +++++++++++++ .../functions/runtimes/discovery/index.ts | 120 ++++++++++++++---- src/deploy/functions/runtimes/node/index.ts | 88 +++++++++++-- 4 files changed, 257 insertions(+), 39 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index c79a6c643f6..6688fa5a716 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,6 @@ - Added `appcheck:providers:list`, `appcheck:providers:get` and `appcheck:providers:set` to configure App Check attestation providers for an app. - Added `appcheck:apps:list` to show every app with its configured App Check providers. - Added web app support for Crashlytics MCP tools and prompts.>>>>>>> main +- Fixed function discovery reporting a timeout when the discovery server had actually crashed, hiding the underlying error (#7775). +- Clarified the function discovery timeout error, which now names `FUNCTIONS_DISCOVERY_TIMEOUT` and reports the elapsed time in the same unit the variable accepts. +- Fixed `FUNCTIONS_DISCOVERY_TIMEOUT` silently accepting a millisecond value as seconds. It now also accepts an explicit `s` or `ms` suffix. diff --git a/src/deploy/functions/runtimes/discovery/index.spec.ts b/src/deploy/functions/runtimes/discovery/index.spec.ts index ab45a412130..53225452467 100644 --- a/src/deploy/functions/runtimes/discovery/index.spec.ts +++ b/src/deploy/functions/runtimes/discovery/index.spec.ts @@ -6,6 +6,7 @@ import nock from "../../../../test/helpers/nock"; import * as api from "../../../../api"; import { FirebaseError } from "../../../../error"; +import { logger } from "../../../../logger"; import * as discovery from "."; import * as build from "../../build"; @@ -120,4 +121,88 @@ describe("detectFromPort", () => { const parsed = await discovery.detectFromPort(8080, "project", "nodejs16", 0, 500); expect(parsed).to.deep.equal(BUILD); }); + + it("explains how to extend the timeout when it expires", async () => { + nock("http://127.0.0.1:8080").get("/__/functions.yaml").times(50).replyWithError({ + message: "Still booting", + code: "ECONNREFUSED", + }); + + await expect( + discovery.detectFromPort(8080, "project", "nodejs16", 0, 300), + ).to.eventually.be.rejectedWith(FirebaseError, /FUNCTIONS_DISCOVERY_TIMEOUT/); + }); + + it("reports the crash when the server exits instead of blaming the timeout", async () => { + nock("http://127.0.0.1:8080").get("/__/functions.yaml").times(50).replyWithError({ + message: "Still booting", + code: "ECONNREFUSED", + }); + + const serverExited = Promise.reject( + new FirebaseError("The functions process exited with code 1.\n\nOut of memory"), + ) as Promise; + serverExited.catch(() => { + // Raced below; this only keeps the rejection from going unhandled first. + }); + + // The timeout is far longer than the test would tolerate, so passing at all + // proves the exit is what ended discovery. + await expect( + discovery.detectFromPort(8080, "project", "nodejs16", 0, 60_000, serverExited), + ).to.eventually.be.rejectedWith(FirebaseError, /Out of memory/); + }); +}); + +describe("getFunctionDiscoveryTimeout", () => { + const ENV_VAR = "FUNCTIONS_DISCOVERY_TIMEOUT"; + let original: string | undefined; + + beforeEach(() => { + original = process.env[ENV_VAR]; + }); + + afterEach(() => { + if (original === undefined) { + delete process.env[ENV_VAR]; + } else { + process.env[ENV_VAR] = original; + } + }); + + it("returns 0 when unset", () => { + delete process.env[ENV_VAR]; + expect(discovery.getFunctionDiscoveryTimeout()).to.equal(0); + }); + + it("reads a bare number as seconds", () => { + process.env[ENV_VAR] = "60"; + expect(discovery.getFunctionDiscoveryTimeout()).to.equal(60_000); + }); + + it("accepts an explicit seconds suffix", () => { + process.env[ENV_VAR] = "60s"; + expect(discovery.getFunctionDiscoveryTimeout()).to.equal(60_000); + }); + + it("accepts an explicit milliseconds suffix", () => { + process.env[ENV_VAR] = "60000ms"; + expect(discovery.getFunctionDiscoveryTimeout()).to.equal(60_000); + }); + + it("ignores a value it cannot parse", () => { + process.env[ENV_VAR] = "one minute"; + expect(discovery.getFunctionDiscoveryTimeout()).to.equal(0); + }); + + it("warns when a bare value looks like milliseconds", () => { + const warn = sinon.stub(logger, "warn"); + try { + process.env[ENV_VAR] = "30000"; + expect(discovery.getFunctionDiscoveryTimeout()).to.equal(30_000_000); + expect(warn).to.have.been.calledWithMatch(/30000ms/); + } finally { + warn.restore(); + } + }); }); diff --git a/src/deploy/functions/runtimes/discovery/index.ts b/src/deploy/functions/runtimes/discovery/index.ts index 28f1380b83a..401f8a7ffd6 100644 --- a/src/deploy/functions/runtimes/discovery/index.ts +++ b/src/deploy/functions/runtimes/discovery/index.ts @@ -12,8 +12,66 @@ import { FirebaseError } from "../../../../error"; const TIMEOUT_OVERRIDE_ENV_VAR = "FUNCTIONS_DISCOVERY_TIMEOUT"; +// How long to wait between polls of the admin server. A tight loop competes for +// CPU with the very process we are waiting on, which on constrained machines is +// enough to cause the timeout it is meant to detect. +const RETRY_DELAY_MS = 100; + +// A bare value at or above this is almost certainly milliseconds. The variable is +// documented in seconds, so 30000 means 8.3 hours, which silently disables the +// timeout rather than extending it. +const SUSPICIOUS_SECONDS = 600; + +const sleep = (ms: number): Promise => new Promise((resolve) => setTimeout(resolve, ms)); + +/** + * The discovery timeout override, in ms, or 0 if unset. + * + * A bare number is read as seconds for backwards compatibility. An explicit "s" + * or "ms" suffix is also accepted, because the bare form is a common source of + * off-by-1000 mistakes. + */ export function getFunctionDiscoveryTimeout(): number { - return +(process.env[TIMEOUT_OVERRIDE_ENV_VAR] || 0) * 1000; /* ms */ + const raw = process.env[TIMEOUT_OVERRIDE_ENV_VAR]?.trim(); + if (!raw) { + return 0; + } + + const match = /^(\d+(?:\.\d+)?)\s*(ms|s)?$/i.exec(raw); + if (!match) { + logger.warn( + `Ignoring ${TIMEOUT_OVERRIDE_ENV_VAR}="${raw}": expected a number of seconds, e.g. 60 or 60s.`, + ); + return 0; + } + + const value = Number(match[1]); + const unit = (match[2] || "s").toLowerCase(); + if (unit === "ms") { + return value; + } + + if (value >= SUSPICIOUS_SECONDS) { + logger.warn( + `${TIMEOUT_OVERRIDE_ENV_VAR}=${raw} is being read as ${value} seconds ` + + `(${(value / 3600).toFixed(1)} hours). If you meant milliseconds, write ${raw}ms.`, + ); + } + return value * 1000; +} + +/** + * The timeout message, which has to carry its own instructions: by the time a + * user sees it they have no other signal that a timeout is what happened. + */ +function timeoutMessage(timeoutMs: number): string { + return ( + `User code failed to load. Cannot determine backend specification. ` + + `Timed out after ${timeoutMs / 1000}s. ` + + `If your code is slow to load, set ${TIMEOUT_OVERRIDE_ENV_VAR} to allow more time ` + + `(in seconds, e.g. ${TIMEOUT_OVERRIDE_ENV_VAR}=60). ` + + `See https://firebase.google.com/docs/functions/tips#avoid_deployment_timeouts_during_initialization` + ); } /** @@ -74,38 +132,48 @@ export async function detectFromPort( runtime: Runtime, initialDelay = 0, timeout = 10_000 /* 10s to boot up */, + serverExited?: Promise, ): Promise { let res: Response; const discoveryTimeout = getFunctionDiscoveryTimeout() || timeout; + let timer: NodeJS.Timeout | undefined; const timedOut = new Promise((resolve, reject) => { - setTimeout(() => { - const originalError = "User code failed to load. Cannot determine backend specification."; - const error = `${originalError} Timeout after ${discoveryTimeout}. See https://firebase.google.com/docs/functions/tips#avoid_deployment_timeouts_during_initialization'`; - reject(new FirebaseError(error)); + timer = setTimeout(() => { + reject(new FirebaseError(timeoutMessage(discoveryTimeout))); }, discoveryTimeout); }); - // Initial delay to wait for admin server to boot. - if (initialDelay > 0) { - await new Promise((resolve) => setTimeout(resolve, initialDelay)); - } + // A connection refused is ambiguous: the server may still be booting, or it may + // have died and never be coming back. Racing its exit lets us report the crash + // instead of blaming a timeout for it. + const abort: Promise[] = serverExited ? [timedOut, serverExited] : [timedOut]; - const url = `http://127.0.0.1:${port}/__/functions.yaml`; - while (true) { - try { - res = await Promise.race([fetch(url), timedOut]); - break; - } catch (err: any) { - const realErr = err?.cause || err; - if ( - err?.name === "FetchError" || - realErr?.name === "FetchError" || - ["ECONNREFUSED", "ECONNRESET", "ETIMEDOUT"].includes(realErr?.code) - ) { - continue; + try { + // Initial delay to wait for admin server to boot. + if (initialDelay > 0) { + await new Promise((resolve) => setTimeout(resolve, initialDelay)); + } + + const url = `http://127.0.0.1:${port}/__/functions.yaml`; + while (true) { + try { + res = await Promise.race([fetch(url), ...abort]); + break; + } catch (err: any) { + const realErr = err?.cause || err; + if ( + err?.name === "FetchError" || + realErr?.name === "FetchError" || + ["ECONNREFUSED", "ECONNRESET", "ETIMEDOUT"].includes(realErr?.code) + ) { + await Promise.race([sleep(RETRY_DELAY_MS), ...abort]); + continue; + } + throw err; } - throw err; } + } finally { + clearTimeout(timer); } if (res.status !== 200) { @@ -150,11 +218,7 @@ export async function detectFromOutputPath( const timer = setTimeout(() => { if (!resolved) { resolved = true; - reject( - new FirebaseError( - `User code failed to load. Cannot determine backend specification. Timeout after ${discoveryTimeout}ms`, - ), - ); + reject(new FirebaseError(timeoutMessage(discoveryTimeout))); } }, discoveryTimeout); diff --git a/src/deploy/functions/runtimes/node/index.ts b/src/deploy/functions/runtimes/node/index.ts index 4c56c4eeffc..6cbd83a4006 100644 --- a/src/deploy/functions/runtimes/node/index.ts +++ b/src/deploy/functions/runtimes/node/index.ts @@ -25,6 +25,18 @@ import * as versioning from "./versioning"; import { fileExistsSync } from "../../../../fsutils"; +/** A running function discovery server. */ +interface AdminServer { + /** Shuts the server down. Safe to call after it has already exited. */ + kill: () => Promise; + /** + * Rejects if the server exits before discovery has finished, and otherwise + * never settles. Discovery races this so that a crash during module load is + * reported as itself rather than as a timeout. + */ + serverExited: Promise; +} + /** * */ @@ -255,28 +267,75 @@ export class Delegate { config: backend.RuntimeConfigValues, envs: backend.EnvironmentVariables, port: string, - ): Promise<() => Promise> { + ): Promise { const childProcess = this.spawnFunctionsProcess(config, { ...envs, PORT: port }); - // TODO: Refactor return type to () => Promise to simplify nested promises - return Promise.resolve(async () => { - const p = new Promise((resolve, reject) => { - childProcess.once("exit", resolve); - childProcess.once("error", reject); + // Attached at spawn time rather than in kill(): neither event replays, so a + // server that died before shutdown ran would leave a listener that can never + // fire and a kill() that never resolves. + let exited = false; + const exit = new Promise((resolve, reject) => { + childProcess.once("exit", () => { + exited = true; + resolve(); }); + childProcess.once("error", reject); + }); + exit.catch(() => { + // kill() is the only intended consumer; it may never be called. + }); + let stderr = ""; + childProcess.stderr?.on("data", (chunk: Buffer) => { + stderr += chunk.toString(); + }); + + // Armed only while discovery is in flight. Once we have asked the server to + // quit, an exit is expected rather than a crash. + let armed = true; + const serverExited = new Promise((_resolve, reject) => { + childProcess.once("exit", (code, signal) => { + if (!armed) { + return; + } + const how = code === null ? `signal ${String(signal)}` : `code ${code}`; + const details = stderr.trim(); + reject( + new FirebaseError( + `User code failed to load. Cannot determine backend specification. ` + + `The functions process exited with ${how} before it could be analyzed.` + + (details ? `\n\n${details}` : ""), + ), + ); + }); + }); + serverExited.catch(() => { + // Discovery may finish before the server exits and never race this. + }); + + const kill = async (): Promise => { + armed = false; + if (exited) { + return; + } try { await fetch(`http://localhost:${port}/__/quitquitquit`); } catch (e) { logger.debug("Failed to call quitquitquit. This often means the server failed to start", e); } - setTimeout(() => { + const killTimer = setTimeout(() => { if (!childProcess.killed) { childProcess.kill("SIGKILL"); } }, 10_000); - return p; - }); + try { + await exit; + } finally { + clearTimeout(killTimer); + } + }; + + return Promise.resolve({ kill, serverExited }); } // eslint-disable-next-line require-await @@ -314,9 +373,16 @@ export class Delegate { // HTTP-based discovery (default) const basePort = 8000 + randomInt(0, 1000); // Add a jitter to reduce likelihood of race condition const port = await portfinder.getPortPromise({ port: basePort }); - const kill = await this.serveAdmin(config, env, port.toString()); + const { kill, serverExited } = await this.serveAdmin(config, env, port.toString()); try { - discovered = await discovery.detectFromPort(port, this.projectId, this.runtime); + discovered = await discovery.detectFromPort( + port, + this.projectId, + this.runtime, + undefined, + undefined, + serverExited, + ); } finally { await kill(); }