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(); }