Improve error messages when functions fails to load (#5782)

We will proactively try to identify common issues based on error messages to provide better debugging experience. 1. No `venv` directory: ``` ➜ functions firebase emulators:start i emulators: Starting emulators: functions i functions: Watching "/Users/REDACTED/google/cf3-pyinit/functions" for Cloud Functions... ⬢ functions: Failed to load function definition from source: FirebaseError: Failed to find location of Firebase Functions SDK: Missing virtual environment at venv directory. Did you forget to run 'python3.11 -m venv venv'? ``` 2. No `firebase-functions` package ``` ➜ functions firebase emulators:start i emulators: Starting emulators: functions i functions: Watching "/Users/REDACTED/google/cf3-pyinit/functions" for Cloud Functions... ⬢ functions: Failed to load function definition from source: FirebaseError: Failed to find location of Firebase Functions SDK. Did you forget to run 'source /Users/danielylee/google/cf3-pyinit/functions/venv/bin/activate && python3.11 -m pip install -r requirements.txt'? ``` 3. Runtime errors ``` ➜ functions firebase emulators:start i emulators: Starting emulators: functions i functions: Watching "/Users/REDACTED/google/cf3-pyinit/functions" for Cloud Functions... ⚠ functions: Failed to detect functions from source FirebaseError: Failed to parse build specification. stderr:WARNING: This is a development server. Do not use it in a production deployment. Use a production WSGI server instead. * Running on http://127.0.0.1:8081 Press CTRL+C to quit [2023-05-02 19:29:18,285] ERROR in app: Exception on /__/functions.yaml [GET] Traceback (most recent call last): ... File "/Users/REDACTED/google/cf3-pyinit/functions/main.py", line 8, in <module> foo += 1 ^^^ NameError: name 'foo' is not defined ```
firebase · May 2, 2023 · c48ccfe · c48ccfe
1 parent 19a8384
commit c48ccfe
Show file tree

Hide file tree

Showing 3 changed files with 68 additions and 19 deletions.
diff --git a/src/deploy/functions/runtimes/discovery/index.ts b/src/deploy/functions/runtimes/discovery/index.ts
@@ -60,7 +60,7 @@ export async function detectFromPort(
   port: number,
   project: string,
   runtime: runtimes.Runtime,
-  timeout = 30_000 /* 30s to boot up */
+  timeout = 10_000 /* 10s to boot up */
 ): Promise<build.Build> {
   // The result type of fetch isn't exported
   let res: { text(): Promise<string> };

diff --git a/src/deploy/functions/runtimes/python/index.ts b/src/deploy/functions/runtimes/python/index.ts
@@ -9,9 +9,10 @@ import * as runtimes from "..";
 import * as backend from "../../backend";
 import * as discovery from "../discovery";
 import { logger } from "../../../../logger";
-import { runWithVirtualEnv } from "../../../../functions/python";
+import { DEFAULT_VENV_DIR, runWithVirtualEnv, virtualEnvCmd } from "../../../../functions/python";
 import { FirebaseError } from "../../../../error";
 import { Build } from "../../build";
+import { logLabeledWarning } from "../../../../utils";
 
 export const LATEST_VERSION: runtimes.Runtime = "python311";
 
@@ -75,6 +76,8 @@ export class Delegate implements runtimes.RuntimeDelegate {
 
   async modulesDir(): Promise<string> {
     if (!this._modulesDir) {
+      let out = "";
+      let stderr = "";
       const child = runWithVirtualEnv(
         [
           this.bin,
@@ -84,7 +87,11 @@ export class Delegate implements runtimes.RuntimeDelegate {
         this.sourceDir,
         {}
       );
-      let out = "";
+      child.stderr?.on("data", (chunk: Buffer) => {
+        const chunkString = chunk.toString();
+        stderr = stderr + chunkString;
+        logger.debug(`stderr: ${chunkString}`);
+      });
       child.stdout?.on("data", (chunk: Buffer) => {
         const chunkString = chunk.toString();
         out = out + chunkString;
@@ -95,6 +102,21 @@ export class Delegate implements runtimes.RuntimeDelegate {
         child.on("error", reject);
       });
       this._modulesDir = out.trim();
+      if (this._modulesDir === "") {
+        if (stderr.includes("venv") && stderr.includes("activate")) {
+          throw new FirebaseError(
+            "Failed to find location of Firebase Functions SDK: Missing virtual environment at venv directory. " +
+              `Did you forget to run '${this.bin} -m venv venv'?`
+          );
+        }
+        const { command, args } = virtualEnvCmd(this.sourceDir, DEFAULT_VENV_DIR);
+        throw new FirebaseError(
+          "Failed to find location of Firebase Functions SDK. " +
+            `Did you forget to run '${command} ${args.join(" ")} && ${
+              this.bin
+            } -m pip install -r requirements.txt'?`
+        );
+      }
     }
     return this._modulesDir;
   }
@@ -116,13 +138,15 @@ export class Delegate implements runtimes.RuntimeDelegate {
     return Promise.resolve();
   }
 
-  async serveAdmin(port: number, envs: backend.EnvironmentVariables): Promise<() => Promise<void>> {
+  async serveAdmin(port: number, envs: backend.EnvironmentVariables) {
     const modulesDir = await this.modulesDir();
     const envWithAdminPort = {
       ...envs,
       ADMIN_PORT: port.toString(),
     };
     const args = [this.bin, path.join(modulesDir, "private", "serving.py")];
+    const stdout: string[] = [];
+    const stderr: string[] = [];
     logger.debug(
       `Running admin server with args: ${JSON.stringify(args)} and env: ${JSON.stringify(
         envWithAdminPort
@@ -131,20 +155,26 @@ export class Delegate implements runtimes.RuntimeDelegate {
     const childProcess = runWithVirtualEnv(args, this.sourceDir, envWithAdminPort);
     childProcess.stdout?.on("data", (chunk: Buffer) => {
       const chunkString = chunk.toString();
+      stdout.push(chunkString);
       logger.debug(`stdout: ${chunkString}`);
     });
     childProcess.stderr?.on("data", (chunk: Buffer) => {
       const chunkString = chunk.toString();
+      stderr.push(chunkString);
       logger.debug(`stderr: ${chunkString}`);
     });
-    return Promise.resolve(async () => {
-      await fetch(`http://127.0.0.1:${port}/__/quitquitquit`);
-      const quitTimeout = setTimeout(() => {
-        if (!childProcess.killed) {
-          childProcess.kill("SIGKILL");
-        }
-      }, 10_000);
-      clearTimeout(quitTimeout);
+    return Promise.resolve({
+      stderr,
+      stdout,
+      killProcess: async () => {
+        await fetch(`http://127.0.0.1:${port}/__/quitquitquit`);
+        const quitTimeout = setTimeout(() => {
+          if (!childProcess.killed) {
+            childProcess.kill("SIGKILL");
+          }
+        }, 10_000);
+        clearTimeout(quitTimeout);
+      },
     });
   }
 
@@ -157,9 +187,15 @@ export class Delegate implements runtimes.RuntimeDelegate {
       const adminPort = await portfinder.getPortPromise({
         port: 8081,
       });
-      const killProcess = await this.serveAdmin(adminPort, envs);
+      const { killProcess, stderr } = await this.serveAdmin(adminPort, envs);
       try {
         discovered = await discovery.detectFromPort(adminPort, this.projectId, this.runtime);
+      } catch (e: any) {
+        logLabeledWarning(
+          "functions",
+          `Failed to detect functions from source ${e}.\nstderr:${stderr.join("\n")}`
+        );
+        throw e;
       } finally {
         await killProcess();
       }

diff --git a/src/functions/python.ts b/src/functions/python.ts
@@ -3,7 +3,23 @@ import * as spawn from "cross-spawn";
 import * as cp from "child_process";
 import { logger } from "../logger";
 
-const DEFAULT_VENV_DIR = "venv";
+/**
+ * Default directory for python virtual environment.
+ */
+export const DEFAULT_VENV_DIR = "venv";
+
+/**
+ *  Get command for running Python virtual environment for given platform.
+ */
+export function virtualEnvCmd(cwd: string, venvDir: string): { command: string; args: string[] } {
+  const activateScriptPath =
+    process.platform === "win32" ? ["Scripts", "activate.bat"] : ["bin", "activate"];
+  const venvActivate = path.join(cwd, venvDir, ...activateScriptPath);
+  return {
+    command: process.platform === "win32" ? venvActivate : "source",
+    args: [process.platform === "win32" ? "" : venvActivate],
+  };
+}
 
 /**
  * Spawn a process inside the Python virtual environment if found.
@@ -15,11 +31,8 @@ export function runWithVirtualEnv(
   spawnOpts: cp.SpawnOptions = {},
   venvDir = DEFAULT_VENV_DIR
 ): cp.ChildProcess {
-  const activateScriptPath =
-    process.platform === "win32" ? ["Scripts", "activate.bat"] : ["bin", "activate"];
-  const venvActivate = path.join(cwd, venvDir, ...activateScriptPath);
-  const command = process.platform === "win32" ? venvActivate : "source";
-  const args = [process.platform === "win32" ? "" : venvActivate, "&&", ...commandAndArgs];
+  const { command, args } = virtualEnvCmd(cwd, venvDir);
+  args.push("&&", ...commandAndArgs);
   logger.debug(`Running command with virtualenv: command=${command}, args=${JSON.stringify(args)}`);
 
   return spawn(command, args, {