search

firebase / firebase-tools

The Firebase Command Line Tools
MIT License
4.04k stars 955 forks source link

If the functions code takes a long time to load, an error will occur and loading will be interrupted #7165

Open takahashi-shotaro-al opened 7 months ago

takahashi-shotaro-al commented 7 months ago

[REQUIRED] Environment info

firebase-tools: 13.8.3 firebase-admin: 12.1.0 firebase-functions: 5.0.1

Platform: Windows 11 node: 20.5.1

[REQUIRED] Test case

const { onRequest } = require("firebase-functions/v2/https");

exports.helloWorld = onRequest((request, response) => {
  response.send("Hello from Firebase!");
});

function sleep(time) {
  const startTime = new Date().getTime();
  while (new Date().getTime() - startTime < time) {}
}

sleep(15 * 1000); // or require some large modules on Windows (ex. googleapis, firebase-admin, ...)

[REQUIRED] Steps to reproduce

firebase emulators:start --only functions --debug

[REQUIRED] Expected behavior

No error should have occured

[REQUIRED] Actual behavior

error functions: Failed to load function definition from source: FirebaseError: User code failed to load. Cannot determine backend specification

npm run serve (firebase emulators:start --only functions --debug)

I:\workspace\firebase-admin-timeout-test\functions> npm run serve

> serve
> firebase emulators:start --only functions --debug

[2024-05-10T17:03:48.510Z] > command requires scopes: ["email","openid","https://www.googleapis.com/auth/cloudplatformprojects.readonly","https://www.googleapis.com/auth/firebase","https://www.googleapis.com/auth/cloud-platform"]
[2024-05-10T17:03:48.511Z] > authorizing via signed-in user (takahashi@aidealab.com)
i  emulators: Starting emulators: functions {"metadata":{"emulator":{"name":"hub"},"message":"Starting emulators: functions"}}
[2024-05-10T17:03:48.527Z] [logging] Logging Emulator only supports listening on one address (127.0.0.1). Not listening on ::1
!  ui: Emulator UI unable to start on port 4000, starting on 4001 instead. {"metadata":{"emulator":{"name":"ui"},"message":"Emulator UI unable to start on port 4000, starting on 4001 instead."}}
[2024-05-10T17:03:48.529Z] assigned listening specs for emulators {"user":{"hub":[{"address":"127.0.0.1","family":"IPv4","port":4400},{"address":"::1","family":"IPv6","port":4400}],"logging":[{"address":"127.0.0.1","family":"IPv4","port":4500}],"ui":[{"address":"127.0.0.1","family":"IPv4","port":4001},{"address":"::1","family":"IPv6","port":4001}]},"metadata":{"message":"assigned listening specs for emulators"}}
[2024-05-10T17:03:48.536Z] [hub] writing locator at C:\Users\Alice\AppData\Local\Temp\hub-dummy.json
[2024-05-10T17:03:48.563Z] [functions] Functions Emulator only supports listening on one address (127.0.0.1). Not listening on ::1
[2024-05-10T17:03:48.563Z] [eventarc] Eventarc Emulator only supports listening on one address (127.0.0.1). Not listening on ::1
[2024-05-10T17:03:48.564Z] late-assigned ports for functions and eventarc emulators {"user":{"hub":[{"address":"127.0.0.1","family":"IPv4","port":4400},{"address":"::1","family":"IPv6","port":4400}],"logging":[{"address":"127.0.0.1","family":"IPv4","port":4500}],"ui":[{"address":"127.0.0.1","family":"IPv4","port":4001},{"address":"::1","family":"IPv6","port":4001}],"functions":[{"address":"127.0.0.1","family":"IPv4","port":9000}],"eventarc":[{"address":"127.0.0.1","family":"IPv4","port":9299}]},"metadata":{"message":"late-assigned ports for functions and eventarc emulators"}}
!  functions: The following emulators are not running, calls to these services from the Functions emulator will affect production: auth, firestore, database, hosting, pubsub, storage, dataconnect {"metadata":{"emulator":{"name":"functions"},"message":"The following emulators are not running, calls to these services from the Functions emulator will affect production: \u001b[1mauth, firestore, database, hosting, pubsub, storage, dataconnect\u001b[22m"}}
[2024-05-10T17:03:48.569Z] defaultcredentials: writing to file C:\Users\Alice\AppData\Roaming\firebase\takahashi_aidealab_com_application_default_credentials.json
[2024-05-10T17:03:48.573Z] Setting GAC to C:\Users\Alice\AppData\Roaming\firebase\takahashi_aidealab_com_application_default_credentials.json {"metadata":{"emulator":{"name":"functions"},"message":"Setting GAC to C:\\Users\\Alice\\AppData\\Roaming\\firebase\\takahashi_aidealab_com_application_default_credentials.json"}}
[2024-05-10T17:03:48.576Z] >>> [apiv2][query] GET https://firebase.googleapis.com/v1beta1/projects/dummy/adminSdkConfig [none]
[2024-05-10T17:03:48.965Z] <<< [apiv2][status] GET https://firebase.googleapis.com/v1beta1/projects/dummy/adminSdkConfig 403
[2024-05-10T17:03:48.966Z] <<< [apiv2][body] GET https://firebase.googleapis.com/v1beta1/projects/dummy/adminSdkConfig {"error":{"code":403,"message":"The caller does not have permission","status":"PERMISSION_DENIED"}}       
[2024-05-10T17:03:48.966Z] Failed to get Admin SDK config for dummy, falling back to cache Failed to get Admin SDK for Firebase project dummy. Please make sure the project exists and your account has permission to access it. {"name":"FirebaseError","children":[],"exit":2,"message":"Failed to get Admin SDK for Firebase project dummy. Please make sure the project exists and your account has permission to access it.","original":{"name":"FirebaseError","children":[],"context":{"body":{"error":{"code":403,"message":"The caller does not have permission","status":"PERMISSION_DENIED"}},"response":{"statusCode":403}},"exit":1,"message":"HTTP Error: 403, The caller does not have permission","status":403},"status":500}
!  functions: Unable to fetch project Admin SDK configuration, Admin SDK behavior in Cloud Functions emulator may be incorrect. {"metadata":{"emulator":{"name":"functions"},"message":"Unable to fetch project Admin SDK configuration, Admin SDK behavior in Cloud Functions emulator may be incorrect."}}
[2024-05-10T17:03:48.983Z] Ignoring unsupported arg: auto_download {"metadata":{"emulator":{"name":"ui"},"message":"Ignoring unsupported arg: auto_download"}}
[2024-05-10T17:03:48.983Z] Ignoring unsupported arg: port {"metadata":{"emulator":{"name":"ui"},"message":"Ignoring unsupported arg: port"}}
[2024-05-10T17:03:48.984Z] Starting Emulator UI with command {"binary":"node","args":["C:\\Users\\Alice\\.cache\\firebase\\emulators\\ui-v1.11.8\\server\\server.mjs"],"optionalArgs":[],"joinArgs":false,"shell":false} {"metadata":{"emulator":{"name":"ui"},"message":"Starting Emulator UI with command {\"binary\":\"node\",\"args\":[\"C:\\\\Users\\\\Alice\\\\.cache\\\\firebase\\\\emulators\\\\ui-v1.11.8\\\\server\\\\server.mjs\"],\"optionalArgs\":[],\"joinArgs\":false,\"shell\":false}"}}
i  ui: Emulator UI logging to ui-debug.log {"metadata":{"emulator":{"name":"ui"},"message":"Emulator UI logging to \u001b[1mui-debug.log\u001b[22m"}}
[2024-05-10T17:03:49.183Z] Web / API server started at 127.0.0.1:4001
 {"metadata":{"emulator":{"name":"ui"},"message":"Web / API server started at 127.0.0.1:4001\n"}}
[2024-05-10T17:03:49.184Z] Web / API server started at ::1:4001
 {"metadata":{"emulator":{"name":"ui"},"message":"Web / API server started at ::1:4001\n"}}
i  functions: Watching "I:\workspace\firebase-admin-timeout-test\functions" for Cloud Functions... {"metadata":{"emulator":{"name":"functions"},"message":"Watching \"I:\\workspace\\firebase-admin-timeout-test\\functions\" for Cloud Functions..."}}
[2024-05-10T17:03:49.218Z] Validating nodejs source
[2024-05-10T17:03:51.198Z] > [functions] package.json contents: {
  "name": "functions",
  "description": "Cloud Functions for Firebase",
  "scripts": {
    "serve": "firebase emulators:start --only functions --debug",
    "shell": "firebase functions:shell",
    "start": "npm run shell",
    "deploy": "firebase deploy --only functions",
    "logs": "firebase functions:log"
  },
  "engines": {
    "node": "20"
  },
  "main": "index.js",
  "dependencies": {
    "firebase-admin": "^12.1.0",
    "firebase-functions": "^5.0.1",
    "firebase-tools": "^13.8.3"
  },
  "devDependencies": {
    "firebase-functions-test": "^3.1.0"
  },
  "private": true
}
[2024-05-10T17:03:51.201Z] Building nodejs source
[2024-05-10T17:03:51.201Z] Failed to find version of module node: reached end of search path I:\workspace\firebase-admin-timeout-test\functions\node_modules
+  functions: Using node@20 from host.
[2024-05-10T17:03:51.204Z] Could not find functions.yaml. Must use http discovery
[2024-05-10T17:03:51.224Z] Found firebase-functions binary at 'I:\workspace\firebase-admin-timeout-test\functions\node_modules\.bin\firebase-functions'
Serving at port 8366

!!  functions: Failed to load function definition from source: FirebaseError: User code failed to load. Cannot determine backend specification {"metadata":{"emulator":{"name":"functions"},"message":"Failed to load function definition from source: FirebaseError: User code failed to load. Cannot determine backend specification"}}

┌─────────────────────────────────────────────────────────────┐
│ ✔  All emulators ready! It is now safe to connect your app. │
│ i  View Emulator UI at http://127.0.0.1:4001/               │
└─────────────────────────────────────────────────────────────┘

┌───────────┬────────────────┬─────────────────────────────────┐
│ Emulator  │ Host:Port      │ View in Emulator UI             │
├───────────┼────────────────┼─────────────────────────────────┤
│ Functions │ 127.0.0.1:9000 │ http://127.0.0.1:4001/functions │
└───────────┴────────────────┴─────────────────────────────────┘
  Emulator Hub running at 127.0.0.1:4400
  Other reserved ports: 4500

Issues? Report them at https://github.com/firebase/firebase-tools/issues and attach the *-debug.log files.

node -r .

I:\workspace\firebase-admin-timeout-test\functions> node -r .
Welcome to Node.js v20.5.1.
Type ".help" for more information.
>

Misc

similar issue: https://github.com/firebase/firebase-tools/issues/5888

On Windows, loading our production code entry point by require() takes 8~ seconds.

2024-05-10_221817 2024-05-10_223936

aalej commented 7 months ago

Hey @takahashi-shotaro, thanks for the detailed report and for sharing your observations. I was able to reproduce the issue, and it does sound reasonable to increase the timeout on use-cases where the emulators are being run on a low-spec machine or if there are a lot of dependencies which is causing the functions to load longer than expected.

I’ll raise this to our engineering team so they can take a look. Also, thanks for submitting a PR!

takahashi-shotaro-al commented 7 months ago

I forgot to mention that the same problem occurs when deploying functions.

inlined commented 7 months ago

That's a great observation and helped point us to a very surgical fix!