diff --git a/src/deploy/functions/runtimes/discovery/index.spec.ts b/src/deploy/functions/runtimes/discovery/index.spec.ts index ab45a412130..59889e15188 100644 --- a/src/deploy/functions/runtimes/discovery/index.spec.ts +++ b/src/deploy/functions/runtimes/discovery/index.spec.ts @@ -1,5 +1,7 @@ import { expect } from "chai"; import * as fs from "fs/promises"; +import { EventEmitter } from "events"; +import { ChildProcess } from "child_process"; import * as yaml from "yaml"; import * as sinon from "sinon"; import nock from "../../../../test/helpers/nock"; @@ -120,4 +122,85 @@ describe("detectFromPort", () => { const parsed = await discovery.detectFromPort(8080, "project", "nodejs16", 0, 500); expect(parsed).to.deep.equal(BUILD); }); + + it("surfaces the admin process's exit code and stderr instead of waiting out the timeout", async () => { + // In case the first fetch attempt happens to land before the process-exit branch + // wins the race, resolve it successfully so it doesn't produce an unhandled rejection. + nock("http://127.0.0.1:8082").get("/__/functions.yaml").reply(200, YAML_TEXT); + + const fakeStderr = new EventEmitter(); + const fakeChildProcess = new EventEmitter() as unknown as ChildProcess; + (fakeChildProcess as unknown as { stderr: EventEmitter }).stderr = fakeStderr; + + // Set a long overall timeout; the exit event should short-circuit well before it fires. + const detectPromise = discovery.detectFromPort( + 8082, + "project", + "nodejs16", + 0, + 60_000, + fakeChildProcess, + ); + + // Emitted synchronously, before the event loop gets a chance to settle the in-flight + // fetch, so this deterministically wins the Promise.race in detectFromPort. + fakeStderr.emit("data", Buffer.from("ReferenceError: SOME_VAR is not defined")); + fakeChildProcess.emit("exit", 1); + + await expect(detectPromise).to.eventually.be.rejectedWith( + FirebaseError, + /Process exited with code 1[\s\S]*ReferenceError: SOME_VAR is not defined/, + ); + }); + + it("fails fast when the admin process exits cleanly before discovery completes", async () => { + // In case the first fetch attempt happens to land before the process-exit branch + // wins the race, resolve it successfully so it doesn't produce an unhandled rejection. + nock("http://127.0.0.1:8083").get("/__/functions.yaml").reply(200, YAML_TEXT); + + const fakeChildProcess = new EventEmitter() as unknown as ChildProcess; + (fakeChildProcess as unknown as { stderr: EventEmitter }).stderr = new EventEmitter(); + + // Set a long overall timeout; the exit event should short-circuit well before it fires. + const detectPromise = discovery.detectFromPort( + 8083, + "project", + "nodejs16", + 0, + 60_000, + fakeChildProcess, + ); + + // A code-0 (or signal, i.e. null) exit is just as unexpected as a non-zero one: the + // admin server should never go away on its own while discovery is still in flight. + fakeChildProcess.emit("exit", 0); + + await expect(detectPromise).to.eventually.be.rejectedWith( + FirebaseError, + /Process exited with code 0/, + ); + }); + + it("fails fast when the admin process is killed by a signal before discovery completes", async () => { + nock("http://127.0.0.1:8084").get("/__/functions.yaml").reply(200, YAML_TEXT); + + const fakeChildProcess = new EventEmitter() as unknown as ChildProcess; + (fakeChildProcess as unknown as { stderr: EventEmitter }).stderr = new EventEmitter(); + + const detectPromise = discovery.detectFromPort( + 8084, + "project", + "nodejs16", + 0, + 60_000, + fakeChildProcess, + ); + + fakeChildProcess.emit("exit", null); + + await expect(detectPromise).to.eventually.be.rejectedWith( + FirebaseError, + /Process exited via a signal/, + ); + }); }); diff --git a/src/deploy/functions/runtimes/discovery/index.ts b/src/deploy/functions/runtimes/discovery/index.ts index 28f1380b83a..367f6d8f4b0 100644 --- a/src/deploy/functions/runtimes/discovery/index.ts +++ b/src/deploy/functions/runtimes/discovery/index.ts @@ -74,6 +74,7 @@ export async function detectFromPort( runtime: Runtime, initialDelay = 0, timeout = 10_000 /* 10s to boot up */, + childProcess?: ChildProcess, ): Promise { let res: Response; const discoveryTimeout = getFunctionDiscoveryTimeout() || timeout; @@ -85,6 +86,28 @@ export async function detectFromPort( }, discoveryTimeout); }); + // If the admin server's process exits before we've finished discovery, surface + // its exit code (or the fact that it was killed by a signal) and any stderr it + // produced instead of retrying blindly until the generic timeout above fires. + // Any exit here is unexpected: the admin server is a long-lived HTTP server + // that should never go away on its own while we're still waiting on it. + let stderrBuffer = ""; + childProcess?.stderr?.on("data", (chunk: Buffer) => { + stderrBuffer += chunk.toString(); + }); + const exitedWithError = new Promise((resolve, reject) => { + childProcess?.once("exit", (code: number | null) => { + const message = stderrBuffer.trim(); + const exitStatus = code === null ? "via a signal" : `with code ${code}`; + reject( + new FirebaseError( + `User code failed to load. Cannot determine backend specification.\n` + + `Process exited ${exitStatus}.${message ? `\n${message}` : ""}`, + ), + ); + }); + }); + // Initial delay to wait for admin server to boot. if (initialDelay > 0) { await new Promise((resolve) => setTimeout(resolve, initialDelay)); @@ -93,18 +116,22 @@ export async function detectFromPort( const url = `http://127.0.0.1:${port}/__/functions.yaml`; while (true) { try { - res = await Promise.race([fetch(url), timedOut]); + res = await Promise.race([fetch(url), timedOut, exitedWithError]); break; } catch (err: any) { - const realErr = err?.cause || err; - if ( - err?.name === "FetchError" || - realErr?.name === "FetchError" || - ["ECONNREFUSED", "ECONNRESET", "ETIMEDOUT"].includes(realErr?.code) - ) { - continue; + // `timedOut` and `exitedWithError` are the only two conditions that should end the + // retry loop early; both reject with a FirebaseError. Everything else is assumed to + // be a transient network-layer failure while the admin server is still booting (or + // tearing down) and gets retried. This is intentionally not narrowed to specific + // error names/codes (e.g. ECONNREFUSED): the exact shape of a "the process we were + // talking to just died" error varies (e.g. undici's SocketError/UND_ERR_SOCKET when + // the admin server accepts a connection and is then killed mid-request), and + // guessing at that shape previously caused this loop to give up with a cryptic raw + // fetch error instead of looping back to let exitedWithError report the real cause. + if (err instanceof FirebaseError) { + throw err; } - throw err; + continue; } } diff --git a/src/deploy/functions/runtimes/node/index.ts b/src/deploy/functions/runtimes/node/index.ts index 4c56c4eeffc..113cb15cd2a 100644 --- a/src/deploy/functions/runtimes/node/index.ts +++ b/src/deploy/functions/runtimes/node/index.ts @@ -255,15 +255,21 @@ export class Delegate { config: backend.RuntimeConfigValues, envs: backend.EnvironmentVariables, port: string, - ): Promise<() => Promise> { + ): Promise<{ process: ChildProcess; kill: () => 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); - }); + const kill = async (): Promise => { + // The process may have already exited (e.g. it crashed while discovery was + // still running) before kill() is called. In that case the 'exit' event has + // already fired and a listener registered now would never see it, hanging + // this function forever. + const alreadyExited = childProcess.exitCode !== null || childProcess.signalCode !== null; + const p = alreadyExited + ? Promise.resolve() + : new Promise((resolve, reject) => { + childProcess.once("exit", resolve); + childProcess.once("error", reject); + }); try { await fetch(`http://localhost:${port}/__/quitquitquit`); @@ -276,7 +282,8 @@ export class Delegate { } }, 10_000); return p; - }); + }; + return Promise.resolve({ process: childProcess, kill }); } // eslint-disable-next-line require-await @@ -314,9 +321,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 { process: adminProcess, kill } = 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, + /* initialDelay= */ 0, + /* timeout= */ 10_000, + adminProcess, + ); } finally { await kill(); } diff --git a/src/deploy/functions/runtimes/python/index.ts b/src/deploy/functions/runtimes/python/index.ts index 0bd3d343a8e..c5d0adabdaf 100644 --- a/src/deploy/functions/runtimes/python/index.ts +++ b/src/deploy/functions/runtimes/python/index.ts @@ -1,6 +1,7 @@ import * as fs from "fs"; import * as path from "path"; import { promisify } from "util"; +import { ChildProcess } from "child_process"; import * as portfinder from "portfinder"; @@ -149,7 +150,10 @@ export class Delegate implements runtimes.RuntimeDelegate { return Promise.resolve(); } - async serveAdmin(port: number, envs: backend.EnvironmentVariables) { + async serveAdmin( + port: number, + envs: backend.EnvironmentVariables, + ): Promise<{ process: ChildProcess; kill: () => Promise }> { const modulesDir = await this.modulesDir(); const envWithAdminPort = { ...envs, @@ -168,23 +172,36 @@ export class Delegate implements runtimes.RuntimeDelegate { childProcess.stderr?.on("data", (chunk: Buffer) => { logger.error(chunk.toString("utf8")); }); - return Promise.resolve(async () => { + const kill = async (): Promise => { try { await fetch(`http://127.0.0.1:${port}/__/quitquitquit`); } catch (e) { logger.debug("Failed to call quitquitquit. This often means the server failed to start", e); } + // The process may have already exited (e.g. it crashed while discovery was + // still running) before kill() is called. In that case the 'exit' event has + // already fired and a listener registered now would never see it, hanging + // this function forever. + if (childProcess.exitCode !== null || childProcess.signalCode !== null) { + return; + } const quitTimeout = setTimeout(() => { if (!childProcess.killed) { childProcess.kill("SIGKILL"); } }, 10_000); - clearTimeout(quitTimeout); return new Promise((resolve, reject) => { - childProcess.once("exit", resolve); - childProcess.once("error", reject); + childProcess.once("exit", () => { + clearTimeout(quitTimeout); + resolve(); + }); + childProcess.once("error", (err) => { + clearTimeout(quitTimeout); + reject(err); + }); }); - }); + }; + return Promise.resolve({ process: childProcess, kill }); } async discoverBuild( @@ -196,16 +213,18 @@ export class Delegate implements runtimes.RuntimeDelegate { const adminPort = await portfinder.getPortPromise({ port: 8081, }); - const killProcess = await this.serveAdmin(adminPort, envs); + const { process: adminProcess, kill } = await this.serveAdmin(adminPort, envs); try { discovered = await discovery.detectFromPort( adminPort, this.projectId, this.runtime, 500 /* initialDelay, python startup is slow */, + 10_000 /* timeout */, + adminProcess, ); } finally { - await killProcess(); + await kill(); } } return discovered;