Docker re-launches may fail in a way that cripples Cloud Function emulation

akauppi commented 3 years ago

When starting Docker (npm run start), it should look like this:

If it looks like this instead:

...that means Cloud Functions are not being emulated. The rest of the systems work, so this state is confusing.

If you now run npm run test:fns:userInfo, one of the tests times out (since the Cloud Function doesn't do its work, with the database).

Analysis

We don't know what's causing this. There is nothing spectacular in:

firebase-debug.log

``` [debug] [2021-07-18T17:07:41.852Z] ---------------------------------------------------------------------- [debug] [2021-07-18T17:07:41.854Z] Command: /usr/local/bin/node /usr/local/bin/firebase emulators:start --project=demo-2 [debug] [2021-07-18T17:07:41.855Z] CLI Version: 9.16.0 [debug] [2021-07-18T17:07:41.855Z] Platform: linux [debug] [2021-07-18T17:07:41.855Z] Node Version: v16.5.0 [debug] [2021-07-18T17:07:41.855Z] Time: Sun Jul 18 2021 17:07:41 GMT+0000 (Coordinated Universal Time) [debug] [2021-07-18T17:07:41.855Z] ---------------------------------------------------------------------- [debug] [debug] [2021-07-18T17:07:41.965Z] > 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"] [debug] Failed to authenticate, have you run firebase login? [warn] ⚠ emulators: You are not currently authenticated so some features may not work correctly. Please run firebase login to authenticate the CLI. [info] i emulators: Starting emulators: auth, functions, firestore {"metadata":{"emulator":{"name":"hub"},"message":"Starting emulators: auth, functions, firestore"}} [info] i emulators: Detected demo project ID "demo-2", emulated services will use a demo configuration and attempts to access non-emulated services for this project will fail. {"metadata":{"emulator":{"name":"hub"},"message":"Detected demo project ID \"demo-2\", emulated services will use a demo configuration and attempts to access non-emulated services for this project will fail."}} [debug] [2021-07-18T17:07:42.002Z] [hub] writing locator at /tmp/hub-demo-2.json [warn] ⚠ Your requested "node" version "14 || ^16" doesn't match your global version "16" {"metadata":{"emulator":{"name":"functions"},"message":"Your requested \"node\" version \"14 || ^16\" doesn't match your global version \"16\""}} [warn] ⚠ functions: You are not signed in to the Firebase CLI. If you have authorized this machine using gcloud application-default credentials those may be discovered and used to access production services. {"metadata":{"emulator":{"name":"functions"},"message":"You are not signed in to the Firebase CLI. If you have authorized this machine using gcloud application-default credentials those may be discovered and used to access production services."}} [debug] [2021-07-18T17:07:42.038Z] Ignoring unsupported arg: projectId {"metadata":{"emulator":{"name":"firestore"},"message":"Ignoring unsupported arg: projectId"}} [debug] [2021-07-18T17:07:42.038Z] Ignoring unsupported arg: auto_download {"metadata":{"emulator":{"name":"firestore"},"message":"Ignoring unsupported arg: auto_download"}} [debug] [2021-07-18T17:07:42.038Z] Starting Firestore Emulator with command {"binary":"java","args":["-Dgoogle.cloud_firestore.debug_log_level=FINE","-Duser.language=en","-jar","/root/.cache/firebase/emulators/cloud-firestore-emulator-v1.13.1.jar","--host","0.0.0.0","--port",6767,"--rules","/work/firestore.rules","--functions_emulator","0.0.0.0:5002"],"optionalArgs":["port","webchannel_port","host","rules","functions_emulator","seed_from_export"],"joinArgs":false} {"metadata":{"emulator":{"name":"firestore"},"message":"Starting Firestore Emulator with command {\"binary\":\"java\",\"args\":[\"-Dgoogle.cloud_firestore.debug_log_level=FINE\",\"-Duser.language=en\",\"-jar\",\"/root/.cache/firebase/emulators/cloud-firestore-emulator-v1.13.1.jar\",\"--host\",\"0.0.0.0\",\"--port\",6767,\"--rules\",\"/work/firestore.rules\",\"--functions_emulator\",\"0.0.0.0:5002\"],\"optionalArgs\":[\"port\",\"webchannel_port\",\"host\",\"rules\",\"functions_emulator\",\"seed_from_export\"],\"joinArgs\":false}"}} [info] i firestore: Firestore Emulator logging to firestore-debug.log {"metadata":{"emulator":{"name":"firestore"},"message":"Firestore Emulator logging to \u001b[1mfirestore-debug.log\u001b[22m"}} [debug] [2021-07-18T17:07:43.747Z] Jul 18, 2021 5:07:43 PM com.google.cloud.datastore.emulator.firestore.websocket.WebSocketServer start INFO: Started WebSocket server on ws://0.0.0.0:38965 {"metadata":{"emulator":{"name":"firestore"},"message":"Jul 18, 2021 5:07:43 PM com.google.cloud.datastore.emulator.firestore.websocket.WebSocketServer start\nINFO: Started WebSocket server on ws://0.0.0.0:38965\n"}} [debug] [2021-07-18T17:07:43.787Z] API endpoint: http://0.0.0.0:6767 If you are using a library that supports the FIRESTORE_EMULATOR_HOST environment variable, run: export FIRESTORE_EMULATOR_HOST=0.0.0.0:6767 Dev App Server is now running. {"metadata":{"emulator":{"name":"firestore"},"message":"API endpoint: http://0.0.0.0:6767\nIf you are using a library that supports the FIRESTORE_EMULATOR_HOST environment variable, run:\n\n export FIRESTORE_EMULATOR_HOST=0.0.0.0:6767\n\nDev App Server is now running.\n\n"}} [debug] [2021-07-18T17:07:50.829Z] Jul 18, 2021 5:07:44 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead INFO: Detected non-HTTP/2 connection. Jul 18, 2021 5:07:44 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead INFO: Detected non-HTTP/2 connection. Jul 18, 2021 5:07:48 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead INFO: Detected non-HTTP/2 connection. {"metadata":{"emulator":{"name":"firestore"},"message":"Jul 18, 2021 5:07:44 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead\nINFO: Detected non-HTTP/2 connection.\nJul 18, 2021 5:07:44 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead\nINFO: Detected non-HTTP/2 connection.\nJul 18, 2021 5:07:48 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead\nINFO: Detected non-HTTP/2 connection.\n"}} [debug] [2021-07-18T17:07:50.833Z] Ignoring unsupported arg: auto_download {"metadata":{"emulator":{"name":"ui"},"message":"Ignoring unsupported arg: auto_download"}} [debug] [2021-07-18T17:07:50.834Z] Ignoring unsupported arg: port {"metadata":{"emulator":{"name":"ui"},"message":"Ignoring unsupported arg: port"}} [debug] [2021-07-18T17:07:50.834Z] Starting Emulator UI with command {"binary":"node","args":["/root/.cache/firebase/emulators/ui-v1.6.0/server.bundle.js"],"optionalArgs":[],"joinArgs":false} {"metadata":{"emulator":{"name":"ui"},"message":"Starting Emulator UI with command {\"binary\":\"node\",\"args\":[\"/root/.cache/firebase/emulators/ui-v1.6.0/server.bundle.js\"],\"optionalArgs\":[],\"joinArgs\":false}"}} [info] i ui: Emulator UI logging to ui-debug.log {"metadata":{"emulator":{"name":"ui"},"message":"Emulator UI logging to \u001b[1mui-debug.log\u001b[22m"}} [debug] [2021-07-18T17:07:51.014Z] Web / API server started at 0.0.0.0:4000 {"metadata":{"emulator":{"name":"ui"},"message":"Web / API server started at 0.0.0.0:4000\n"}} [info] i functions: Watching "/work/functions" for Cloud Functions... {"metadata":{"emulator":{"name":"functions"},"message":"Watching \"/work/functions\" for Cloud Functions..."}} [debug] [2021-07-18T17:07:51.111Z] [worker-pool] addWorker(~diagnostic~) {"metadata":{"emulator":{"name":"functions"},"message":"[worker-pool] addWorker(~diagnostic~)"}} [debug] [2021-07-18T17:07:51.112Z] [worker-pool] Adding worker with key ~diagnostic~, total=1 {"metadata":{"emulator":{"name":"functions"},"message":"[worker-pool] Adding worker with key ~diagnostic~, total=1"}} [debug] [2021-07-18T17:07:51.113Z] [worker-pool] submitWork(triggerId=) {"metadata":{"emulator":{"name":"functions"},"message":"[worker-pool] submitWork(triggerId=)"}} [debug] [2021-07-18T17:07:51.113Z] [worker-~diagnostic~-53c10ae1-222d-4817-bc51-28c943af7f53]: Assigning socketPath: /tmp/fire_emu_50.sock {"metadata":{"emulator":{"name":"functions"},"message":"[worker-~diagnostic~-53c10ae1-222d-4817-bc51-28c943af7f53]: Assigning socketPath: /tmp/fire_emu_50.sock"}} [debug] [2021-07-18T17:07:51.116Z] [worker-~diagnostic~-53c10ae1-222d-4817-bc51-28c943af7f53]: BUSY {"metadata":{"emulator":{"name":"functions"},"message":"[worker-~diagnostic~-53c10ae1-222d-4817-bc51-28c943af7f53]: BUSY"}} [debug] [2021-07-18T17:07:51.402Z] [runtime-status] [50] Functions runtime initialized. {"cwd":"/work/functions","node_version":"16.5.0"} {"metadata":{"emulator":{"name":"functions"},"message":"[runtime-status] [50] Functions runtime initialized. {\"cwd\":\"/work/functions\",\"node_version\":\"16.5.0\"}"}} [debug] [2021-07-18T17:07:51.405Z] [runtime-status] [50] Disabled runtime features: undefined {"metadata":{"emulator":{"name":"functions"},"message":"[runtime-status] [50] Disabled runtime features: undefined"}} [debug] [2021-07-18T17:07:51.420Z] [runtime-status] [50] Resolved module firebase-admin {"declared":true,"installed":true,"version":"9.11.0","resolution":"/work/functions/node_modules/firebase-admin/lib/index.js"} {"metadata":{"emulator":{"name":"functions"},"message":"[runtime-status] [50] Resolved module firebase-admin {\"declared\":true,\"installed\":true,\"version\":\"9.11.0\",\"resolution\":\"/work/functions/node_modules/firebase-admin/lib/index.js\"}"}} [debug] [2021-07-18T17:07:51.429Z] [runtime-status] [50] Resolved module firebase-functions {"declared":true,"installed":true,"version":"3.14.1","resolution":"/work/functions/node_modules/firebase-functions/lib/index.js"} {"metadata":{"emulator":{"name":"functions"},"message":"[runtime-status] [50] Resolved module firebase-functions {\"declared\":true,\"installed\":true,\"version\":\"3.14.1\",\"resolution\":\"/work/functions/node_modules/firebase-functions/lib/index.js\"}"}} [debug] [2021-07-18T17:07:51.432Z] [runtime-status] [50] Resolved module firebase-functions {"declared":true,"installed":true,"version":"3.14.1","resolution":"/work/functions/node_modules/firebase-functions/lib/index.js"} {"metadata":{"emulator":{"name":"functions"},"message":"[runtime-status] [50] Resolved module firebase-functions {\"declared\":true,\"installed\":true,\"version\":\"3.14.1\",\"resolution\":\"/work/functions/node_modules/firebase-functions/lib/index.js\"}"}} [debug] [2021-07-18T17:07:51.435Z] [runtime-status] [50] Outgoing network have been stubbed. [{"name":"http","status":"mocked"},{"name":"http","status":"mocked"},{"name":"https","status":"mocked"},{"name":"https","status":"mocked"},{"name":"net","status":"mocked"}] {"metadata":{"emulator":{"name":"functions"},"message":"[runtime-status] [50] Outgoing network have been stubbed. [{\"name\":\"http\",\"status\":\"mocked\"},{\"name\":\"http\",\"status\":\"mocked\"},{\"name\":\"https\",\"status\":\"mocked\"},{\"name\":\"https\",\"status\":\"mocked\"},{\"name\":\"net\",\"status\":\"mocked\"}]"}} [debug] [2021-07-18T17:07:51.439Z] [runtime-status] [50] Resolved module firebase-functions {"declared":true,"installed":true,"version":"3.14.1","resolution":"/work/functions/node_modules/firebase-functions/lib/index.js"} {"metadata":{"emulator":{"name":"functions"},"message":"[runtime-status] [50] Resolved module firebase-functions {\"declared\":true,\"installed\":true,\"version\":\"3.14.1\",\"resolution\":\"/work/functions/node_modules/firebase-functions/lib/index.js\"}"}} [debug] [2021-07-18T17:07:51.695Z] [runtime-status] [50] Checked functions.config() {"config":{}} {"metadata":{"emulator":{"name":"functions"},"message":"[runtime-status] [50] Checked functions.config() {\"config\":{}}"}} [debug] [2021-07-18T17:07:51.696Z] [runtime-status] [50] firebase-functions has been stubbed. {"functionsResolution":{"declared":true,"installed":true,"version":"3.14.1","resolution":"/work/functions/node_modules/firebase-functions/lib/index.js"}} {"metadata":{"emulator":{"name":"functions"},"message":"[runtime-status] [50] firebase-functions has been stubbed. {\"functionsResolution\":{\"declared\":true,\"installed\":true,\"version\":\"3.14.1\",\"resolution\":\"/work/functions/node_modules/firebase-functions/lib/index.js\"}}"}} [debug] [2021-07-18T17:07:51.699Z] [runtime-status] [50] Resolved module firebase-functions {"declared":true,"installed":true,"version":"3.14.1","resolution":"/work/functions/node_modules/firebase-functions/lib/index.js"} {"metadata":{"emulator":{"name":"functions"},"message":"[runtime-status] [50] Resolved module firebase-functions {\"declared\":true,\"installed\":true,\"version\":\"3.14.1\",\"resolution\":\"/work/functions/node_modules/firebase-functions/lib/index.js\"}"}} [debug] [2021-07-18T17:07:51.706Z] [runtime-status] [50] Resolved module firebase-admin {"declared":true,"installed":true,"version":"9.11.0","resolution":"/work/functions/node_modules/firebase-admin/lib/index.js"} {"metadata":{"emulator":{"name":"functions"},"message":"[runtime-status] [50] Resolved module firebase-admin {\"declared\":true,\"installed\":true,\"version\":\"9.11.0\",\"resolution\":\"/work/functions/node_modules/firebase-admin/lib/index.js\"}"}} [debug] [2021-07-18T17:07:51.708Z] [runtime-status] [50] Resolved module firebase-functions {"declared":true,"installed":true,"version":"3.14.1","resolution":"/work/functions/node_modules/firebase-functions/lib/index.js"} {"metadata":{"emulator":{"name":"functions"},"message":"[runtime-status] [50] Resolved module firebase-functions {\"declared\":true,\"installed\":true,\"version\":\"3.14.1\",\"resolution\":\"/work/functions/node_modules/firebase-functions/lib/index.js\"}"}} [debug] [2021-07-18T17:07:51.709Z] [runtime-status] [50] firebase-admin has been stubbed. {"adminResolution":{"declared":true,"installed":true,"version":"9.11.0","resolution":"/work/functions/node_modules/firebase-admin/lib/index.js"}} {"metadata":{"emulator":{"name":"functions"},"message":"[runtime-status] [50] firebase-admin has been stubbed. {\"adminResolution\":{\"declared\":true,\"installed\":true,\"version\":\"9.11.0\",\"resolution\":\"/work/functions/node_modules/firebase-admin/lib/index.js\"}}"}} [debug] [2021-07-18T17:08:48.906Z] Jul 18, 2021 5:08:48 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead INFO: Detected non-HTTP/2 connection. {"metadata":{"emulator":{"name":"firestore"},"message":"Jul 18, 2021 5:08:48 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead\nINFO: Detected non-HTTP/2 connection.\n"}} [debug] [2021-07-18T17:10:04.485Z] Jul 18, 2021 5:10:04 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead INFO: Detected non-HTTP/2 connection. {"metadata":{"emulator":{"name":"firestore"},"message":"Jul 18, 2021 5:10:04 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead\nINFO: Detected non-HTTP/2 connection.\n"}} ```

firestore-debug.log

``` Jul 18, 2021 5:07:43 PM com.google.cloud.datastore.emulator.firestore.websocket.WebSocketServer start INFO: Started WebSocket server on ws://0.0.0.0:38965 API endpoint: http://0.0.0.0:6767 If you are using a library that supports the FIRESTORE_EMULATOR_HOST environment variable, run: export FIRESTORE_EMULATOR_HOST=0.0.0.0:6767 Dev App Server is now running. Jul 18, 2021 5:07:44 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead INFO: Detected non-HTTP/2 connection. Jul 18, 2021 5:07:44 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead INFO: Detected non-HTTP/2 connection. Jul 18, 2021 5:07:48 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead INFO: Detected non-HTTP/2 connection. ```

Work-around

If noticing that npm run start doesn't properly list the ports, don't hesitate. It doesn't get better by waiting.

Restart Docker
Launch npm run start again.

This works always.

This can be anything.

It's hard for me to fathom, how killing a Docker process (by Ctrl-C) wouldn't kill all of it. The purpose of using Docker is to have reproducible, stable development platform but unfortunately, in this case it lets us down. Luckily, the aid is easy to give.

Note: I'm not actively working on this. Can live with it, and maybe some update (Docker or Firebase) eventually resolves it.

You can help by:

[ ] report this to Firebase CLI Issues

akauppi commented 3 years ago

Unfortunately, this manifests also with npm test, as failing tests.

The same cure works, restarting Docker.

All this leads to the following development recommendation (which is anyways how I've envisioned the development flow to be):

you do npm run start and keep it running
run tests with npm run test:<fns|rules>:<testname> or npm test

Notice that npm test picks up the emulators, if they are already running.

As long as the Docker process is not terminated, things are stable.

akauppi commented 3 years ago

This may no longer be an issue with #68 🤞

akauppi commented 3 years ago

Still an issue with app, for some reason.

Others can use "-it friendly" flags (see tools/docker-run-cmd.js) but for app: npm run dev[:local] I wasn't able to make Docker start with them. Even with Concurrently input flags.

With "it friendly" turned on, in tools/docker-run-cmd.js (so Ctrl-C would be picked up):

$ npm run dev:local

> predev:local
> port-is-free 3000,5002 && npm run -s _genEnvLocal

> dev:local
> concurrently --kill-others-on-fail --handle-input --default-input-target -n emul,init "npm run _dev_local_emul" "npm run _dev_local_init && npm run _dev_local_vite"

[emul] 
[emul] > _dev_local_emul
[emul] > npm run -s _checkPort4000 && $(docker-run-cmd) firebase emulators:start --project=demo-abc | grep -v -E "Detected demo project ID|You are not currently authenticated|You are not signed in"
[emul] 
[init] 
[init] > _dev_local_init
[init] > wait-for 4000 && firebase-prime --project=demo-abc local/docs.js local/users.js | grep -v -E "Do not use with production credentials"
[init] 
[emul] Launching Docker... 🐳
[emul] the input device is not a TTY
[emul] npm run _dev_local_emul exited with code 1

concurrently ... --handle-input --default-input-target is supposed to tie the stdin to the particular child process, but doesn't quite look like it.

akauppi commented 3 years ago

Also app-deploy-ops: npm run watch suffers

akauppi commented 3 years ago

Also backend when the server is not yet running: npm test suffers 😢

akauppi commented 3 years ago

Solved by moving to Docker Compose at #73

akauppi / GroundLevel-firebase-es

Docker re-launches may fail in a way that cripples Cloud Function emulation #67