Functions emulator timeout running parallel requests directly after start-up

[gewfy]

This is very similar to #4807 but occurs when the first requests to the emulator are in parallel

[REQUIRED] Environment info

firebase-tools: 11.14.1

Platform: macOS

[REQUIRED] Test case

Bare minimum http end-point

import {onRequest} from 'firebase-functions/v2/https';

export const foo = onRequest({}, (req, res) => {
  res.send('hello');
});

[REQUIRED] Steps to reproduce

1. Start firebase emulator
2. After emulator is up and running, run two curl commands in parallel - do not make any other requests before these two:

curl http://localhost:5001/some-project/us-central1/foo & curl http://localhost:5001/some-project/us-central1/foo

[REQUIRED] Expected behavior

Both curl commands should return hello

[REQUIRED] Actual behavior

Response from server is HTTP 500 with body:

{"errno":-2,"code":"ENOENT","syscall":"connect","address":"/var/folders/4s/nwqmrp5n4bv0cbt0knyzym2h0000gp/T/fire_emu_17fd97dff0e6f47b.sock"}

firebase-debug.log reads:

[debug] [2022-10-16T20:34:14.536Z] [work-queue] {"queueLength":1,"workRunningCount":0}
[debug] [2022-10-16T20:34:14.536Z] [work-queue] {"queueLength":0,"workRunningCount":1}
[debug] [2022-10-16T20:34:14.536Z] Accepted request GET /demo-29k-cupcake/us-central1/foo --> us-central1-foo
[debug] [2022-10-16T20:34:14.538Z] [functions] Runtime ready! Sending request! {"metadata":{"emulator":{"name":"functions"},"message":"[functions] Runtime ready! Sending request!"}}
[debug] [2022-10-16T20:34:14.538Z] [functions] Got req.url=/demo-29k-cupcake/us-central1/foo, mapping to path=/ {"metadata":{"emulator":{"name":"functions"},"message":"[functions] Got req.url=/demo-29k-cupcake/us-central1/foo, mapping to path=/"}}
[info] i  functions: Loaded environment variables from .env. 
[debug] [2022-10-16T20:34:14.548Z] [worker-pool] addWorker(us-central1-foo) {"metadata":{"emulator":{"name":"functions"},"message":"[worker-pool] addWorker(us-central1-foo)"}}
[debug] [2022-10-16T20:34:14.549Z] [worker-pool] Adding worker with key us-central1-foo, total=1 {"metadata":{"emulator":{"name":"functions"},"message":"[worker-pool] Adding worker with key us-central1-foo, total=1"}}
[debug] [2022-10-16T20:34:14.550Z] [work-queue] {"queueLength":1,"workRunningCount":1}
[debug] [2022-10-16T20:34:14.550Z] [work-queue] {"queueLength":0,"workRunningCount":2}
[debug] [2022-10-16T20:34:14.550Z] Accepted request GET /demo-29k-cupcake/us-central1/foo --> us-central1-foo
[debug] [2022-10-16T20:34:14.552Z] [functions] Runtime ready! Sending request! {"metadata":{"emulator":{"name":"functions"},"message":"[functions] Runtime ready! Sending request!"}}
[debug] [2022-10-16T20:34:14.552Z] [functions] Got req.url=/demo-29k-cupcake/us-central1/foo, mapping to path=/ {"metadata":{"emulator":{"name":"functions"},"message":"[functions] Got req.url=/demo-29k-cupcake/us-central1/foo, mapping to path=/"}}
[debug] [2022-10-16T20:34:14.552Z] [worker-pool] submitRequest(triggerId=us-central1-foo) {"metadata":{"emulator":{"name":"functions"},"message":"[worker-pool] submitRequest(triggerId=us-central1-foo)"}}
[debug] [2022-10-16T20:34:14.552Z] [worker-us-central1-foo-26d9982b-b0c5-48ef-baae-dfa4914c73ba]: BUSY {"metadata":{"emulator":{"name":"functions"},"message":"[worker-us-central1-foo-26d9982b-b0c5-48ef-baae-dfa4914c73ba]: BUSY"}}
[debug] [2022-10-16T20:34:14.553Z] [work-queue] {"queueLength":0,"workRunningCount":1}
[debug] [2022-10-16T20:34:14.554Z] [worker-us-central1-foo-26d9982b-b0c5-48ef-baae-dfa4914c73ba]: exited {"metadata":{"emulator":{"name":"functions"},"message":"[worker-us-central1-foo-26d9982b-b0c5-48ef-baae-dfa4914c73ba]: exited"}}
[debug] [2022-10-16T20:34:14.554Z] [worker-us-central1-foo-26d9982b-b0c5-48ef-baae-dfa4914c73ba]: FINISHED {"metadata":{"emulator":{"name":"functions"},"message":"[worker-us-central1-foo-26d9982b-b0c5-48ef-baae-dfa4914c73ba]: FINISHED"}}
[debug] FirebaseError: Failed to load function.
    at Timeout._onTimeout (/Users/jakob/Development/cupcake/functions/node_modules/firebase-tools/lib/emulator/functionsRuntimeWorker.js:152:24)
    at listOnTimeout (node:internal/timers:559:17)
    at processTimers (node:internal/timers:502:7) {"metadata":{"emulator":{"name":"functions"},"message":{"name":"FirebaseError","children":[],"exit":1,"message":"Failed to load function.","status":500}}}
[debug] [2022-10-16T20:34:44.631Z] [work-queue] {"queueLength":0,"workRunningCount":0}

Thanks for all the care you put into this developer community! :)

[marcfrankel]

I believe I'm having a similar issue where if we call a callable function (v1) from our app and we call it multiple times quickly then only the first request or two seems to work. The rest will return an "INTERNAL" error, but I can't seem to find any logs of it. It just started happening a few weeks ago and we lived with it because we figured it was an emulator issue because the function works fine when deployed.

We're on firebase-tools version 11.15.0

[marcfrankel]

Adding on that I found a stable version to go back to that removes the issue. Firebase-tools v 11.9.0. Furthermore, to find this I was walking myself back in the versions. So I can say the issue started happening for me on 11.10.0. Hope that helps!

I also found some longs and it seems to be the same "busy" error that other users are reporting.

[colerogers]

We recently changed the functions emulator internally and might have caused this behavior. We'll take a look at what we can do to fix this. Thanks!

CC @taeold

[nickpell]

Adding on that I found a stable version to go back to that removes the issue. Firebase-tools v 11.9.0. Furthermore, to find this I was walking myself back in the versions. So I can say the issue started happening for me on 11.10.0. Hope that helps!

I am seeing the identical behavior by version in my application.

[colerogers]

We just released the fix in 11.16.0. Can someone with the issue verify that parallel requests are now possible? Thanks!

[LanderBeeuwsaert]

@colerogers fixed for us

[colerogers]

Thanks, I'll mark this issue as closed

[marcfrankel]

Adding this also resolved the issue for us! Thanks team

[nickpell]

Confirming fixed, thank you!

[carchrae]

yay. 11.16.0 fixed it for me too - the 500 error occurred not only directly after startup. i was making two requests at once though. this was driving me bonkers.

both requests would fail with something like this:

[gewfy]

Thanks for fixing this @colerogers!