fix(functions): report discovery crashes instead of blaming the timeout

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.

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

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<void> => 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<never>,
 ): Promise<build.Build> {
   let res: Response;
   const discoveryTimeout = getFunctionDiscoveryTimeout() || timeout;
+  let timer: NodeJS.Timeout | undefined;
   const timedOut = new Promise<never>((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<never>[] = 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);
 

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<void>;
+  /**
+   * 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<never>;
+}
+
 /**
  *
  */
@@ -255,28 +267,75 @@ export class Delegate {
     config: backend.RuntimeConfigValues,
     envs: backend.EnvironmentVariables,
     port: string,
-  ): Promise<() => Promise<void>> {
+  ): Promise<AdminServer> {
     const childProcess = this.spawnFunctionsProcess(config, { ...envs, PORT: port });
 
-    // TODO: Refactor return type to () => Promise<void> to simplify nested promises
-    return Promise.resolve(async () => {
-      const p = new Promise<void>((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<void>((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<never>((_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<void> => {
+      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();
         }