emulators:exec command runs for long time for tests with `get` command

[Peetee06]

[REQUIRED] Environment info

firebase-tools: 13.5.2

Platform: macOS Sonoma 14.3

[REQUIRED] Test case

Minimal test example

firestore.test.js

import {
  initializeTestEnvironment,
  assertFails,
} from "@firebase/rules-unit-testing";

import { readFileSync } from "node:fs";
import { beforeEach } from "mocha";
import { assert } from "chai";

let testEnv;

async function expectFirestorePermissionDenied(promise) {
  const errorResult = await assertFails(promise);
  assert.include(["permission-denied", "PERMISSION_DENIED"], errorResult.code);
}

function parseHostAndPort(hostAndPort) {
  if (hostAndPort == undefined) {
    return undefined;
  }
  const pieces = hostAndPort.split(":");
  return {
    host: pieces[0],
    port: parseInt(pieces[1], 10),
  };
}

before(async () => {
  const { host, port } = parseHostAndPort(process.env.FIRESTORE_EMULATOR_HOST);
  testEnv = await initializeTestEnvironment({
    projectId: "my-project",
    firestore: {
      port,
      host,
      rules: readFileSync("./firestore-test.rules", "utf8"),
    },
  });
});

beforeEach(async () => {
  await testEnv.clearFirestore();
});

describe("user's document", () => {
  describe("should not be accessible by unauthenticated user", () => {
    it("for reading", async () => {
      const db = testEnv.unauthenticatedContext().firestore();
      const profile = db.collection("users").doc("test-user");

      await expectFirestorePermissionDenied(profile.get());
    });

    // it("for writing", async () => {
    //   const db = testEnv.unauthenticatedContext().firestore();
    //   const profile = db.collection("users").doc("test-user");

    //   await expectFirestorePermissionDenied(profile.set({ name: "test-user" }));
    // });

    // it("for deleting", async () => {
    //   const db = testEnv.unauthenticatedContext().firestore();
    //   const profile = db.collection("users").doc("test-user");

    //   await expectFirestorePermissionDenied(profile.delete());
    // });
  });
});

firestore-test.rules

rules_version = '2';

service cloud.firestore {
  match /databases/{database}/documents {
    match /users/{userId} {
      allow create, read, update, delete: if request.auth != null && request.auth.uid == userId;
    }
    match /{document=**} {
      allow read, write: if false;
    }
  }
}

package.json

{
  "name": "unit-test-security-rules",
  "version": "1.0.0",
  "description": "Unit tests for firebase security rules",
  "type": "module",
  "scripts": {
    "test-firestore": "mocha --reporter spec ./firestore.test.js --timeout 10000",
  },
  "devDependencies": {
    "@firebase/rules-unit-testing": "^3.0.1",
    "chai": "^5.1.0",
    "firebase-admin": "^12.0.0",
    "mocha": "^10.3.0"
  },
}

[REQUIRED] Steps to reproduce

1. Create the above files
2. Run npm install
3. Run firebase emulators:exec --only firestore 'npm run test-firestore'

[REQUIRED] Expected behavior

The command completes shortly after running the tests.

[REQUIRED] Actual behavior

After finishing test execution the command keeps running for at least another minute if there is a test case executing a get. This is not the case for test cases with set or delete where execution ends almost immediately. These cases are included in the minimal example above and can be uncommented to confirm the expected behavior.

output

[2024-03-24T13:07:33.759Z] > 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-03-24T13:07:33.759Z] > authorizing via signed-in user (p.trost93@gmail.com)
[2024-03-24T13:07:33.804Z] openjdk version "21.0.2" 2024-01-16

[2024-03-24T13:07:33.804Z] OpenJDK Runtime Environment Homebrew (build 21.0.2)
OpenJDK 64-Bit Server VM Homebrew (build 21.0.2, mixed mode, sharing)

[2024-03-24T13:07:33.808Z] Parsed Java major version: 21
i  emulators: Starting emulators: firestore {"metadata":{"emulator":{"name":"hub"},"message":"Starting emulators: firestore"}}
[2024-03-24T13:07:34.286Z] [logging] Logging Emulator only supports listening on one address (127.0.0.1). Not listening on ::1
[2024-03-24T13:07:34.286Z] [firestore] Firestore Emulator only supports listening on one address (127.0.0.1). Not listening on ::1
[2024-03-24T13:07:34.286Z] [firestore.websocket] websocket server for firestore only supports listening on one address (127.0.0.1). Not listening on ::1
[2024-03-24T13:07:34.286Z] 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}],"firestore":[{"address":"127.0.0.1","family":"IPv4","port":8080}],"firestore.websocket":[{"address":"127.0.0.1","family":"IPv4","port":9150}]},"metadata":{"message":"assigned listening specs for emulators"}}
[2024-03-24T13:07:34.290Z] [hub] writing locator at /var/folders/pc/gmwmj7cd5zd7q60p91_lxfsw0000gn/T/hub-emotely-test.json
[2024-03-24T13:07:34.297Z] Ignoring unsupported arg: auto_download {"metadata":{"emulator":{"name":"firestore"},"message":"Ignoring unsupported arg: auto_download"}}
[2024-03-24T13:07:34.297Z] Ignoring unsupported arg: single_project_mode_error {"metadata":{"emulator":{"name":"firestore"},"message":"Ignoring unsupported arg: single_project_mode_error"}}
[2024-03-24T13:07:34.297Z] Starting Firestore Emulator with command {"binary":"java","args":["-Dgoogle.cloud_firestore.debug_log_level=FINE","-Duser.language=en","-jar","/Users/petertrost/.cache/firebase/emulators/cloud-firestore-emulator-v1.19.3.jar","--host","127.0.0.1","--port",8080,"--websocket_port",9150,"--project_id","emotely-test","--rules","/Users/petertrost/dev/emotely_backend/rules/firestore.rules","--single_project_mode",true],"optionalArgs":["port","webchannel_port","host","rules","websocket_port","functions_emulator","seed_from_export","project_id","single_project_mode"],"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\",\"/Users/petertrost/.cache/firebase/emulators/cloud-firestore-emulator-v1.19.3.jar\",\"--host\",\"127.0.0.1\",\"--port\",8080,\"--websocket_port\",9150,\"--project_id\",\"emotely-test\",\"--rules\",\"/Users/petertrost/dev/emotely_backend/rules/firestore.rules\",\"--single_project_mode\",true],\"optionalArgs\":[\"port\",\"webchannel_port\",\"host\",\"rules\",\"websocket_port\",\"functions_emulator\",\"seed_from_export\",\"project_id\",\"single_project_mode\"],\"joinArgs\":false}"}}
i  firestore: Firestore Emulator logging to firestore-debug.log {"metadata":{"emulator":{"name":"firestore"},"message":"Firestore Emulator logging to \u001b[1mfirestore-debug.log\u001b[22m"}}
[2024-03-24T13:07:34.886Z] Mar 24, 2024 2:07:34 PM com.google.cloud.datastore.emulator.firestore.websocket.WebSocketServer start
INFO: Started WebSocket server on ws://127.0.0.1:9150
 {"metadata":{"emulator":{"name":"firestore"},"message":"Mar 24, 2024 2:07:34 PM com.google.cloud.datastore.emulator.firestore.websocket.WebSocketServer start\nINFO: Started WebSocket server on ws://127.0.0.1:9150\n"}}
[2024-03-24T13:07:34.897Z] API endpoint: http:// {"metadata":{"emulator":{"name":"firestore"},"message":"API endpoint: http://"}}
[2024-03-24T13:07:34.898Z] 127.0.0.1:8080
If you are using a library that supports the FIRESTORE_EMULATOR_HOST environment variable, run:

   export FIRESTORE_EMULATOR_HOST=127.0.0.1:8080

If you are running a Firestore in Datastore Mode project, run:

   export DATASTORE_EMULATOR_HOST=127.0.0.1:8080

Note: Support for Datastore Mode is in preview. If you encounter any bugs please file at https://github.com/firebase/firebase-tools/issues.
Dev App Server is now running.

 {"metadata":{"emulator":{"name":"firestore"},"message":"127.0.0.1:8080\nIf you are using a library that supports the FIRESTORE_EMULATOR_HOST environment variable, run:\n\n   export FIRESTORE_EMULATOR_HOST=127.0.0.1:8080\n\nIf you are running a Firestore in Datastore Mode project, run:\n\n   export DATASTORE_EMULATOR_HOST=127.0.0.1:8080\n\nNote: Support for Datastore Mode is in preview. If you encounter any bugs please file at https://github.com/firebase/firebase-tools/issues.\nDev App Server is now running.\n\n"}}
✔  firestore: Firestore Emulator UI websocket is running on 9150. {"metadata":{"emulator":{"name":"firestore"},"message":"Firestore Emulator UI websocket is running on 9150."}}
i  Running script: npm run test-firestore 
[2024-03-24T13:07:35.061Z] Running npm run test-firestore with environment {"COMMAND_MODE":"unix2003","HOME":"/Users/petertrost","LOGNAME":"petertrost","MallocNanoZone":"0","ORIGINAL_XDG_CURRENT_DESKTOP":"undefined","PATH":"/Users/petertrost/.rvm/gems/ruby-3.2.2/bin:/Users/petertrost/.rvm/gems/ruby-3.2.2@global/bin:/Users/petertrost/.rvm/rubies/ruby-3.2.2/bin:/Users/petertrost/.pyenv/versions/3.10.13/bin:/Users/petertrost/Downloads/google-cloud-sdk/bin:/Users/petertrost/.pyenv/shims:/Users/petertrost/.local/bin:/Users/petertrost/.nvm/versions/node/v18.19.1/bin:/usr/local/bin:/System/Cryptexes/App/usr/bin:/usr/bin:/bin:/usr/sbin:/sbin:/var/run/com.apple.security.cryptexd/codex.system/bootstrap/usr/local/bin:/var/run/com.apple.security.cryptexd/codex.system/bootstrap/usr/bin:/var/run/com.apple.security.cryptexd/codex.system/bootstrap/usr/appleinternal/bin:/Library/Apple/usr/bin:/Users/petertrost/.pyenv/versions/3.10.13/bin:/opt/homebrew/bin:/Users/petertrost/fvm/default/bin:/Users/petertrost/.pub-cache/bin:/Users/petertrost/Library/Android/sdk/cmdline-tools/latest/bin:/Users/petertrost/Library/Android/sdk/emulator:/Users/petertrost/Library/Android/sdk/tools:/Users/petertrost/Library/Android/sdk/tools/bin:/Users/petertrost/Library/Android/sdk/platform-tools:/Users/petertrost/.rvm/bin:/Applications/Visual Studio Code.app/Contents/Resources/app/bin","SHELL":"/bin/zsh","SSH_AUTH_SOCK":"/private/tmp/com.apple.launchd.7ahvUgsZ8K/Listeners","TMPDIR":"/var/folders/pc/gmwmj7cd5zd7q60p91_lxfsw0000gn/T/","USER":"petertrost","XPC_FLAGS":"0x0","XPC_SERVICE_NAME":"0","__CFBundleIdentifier":"com.microsoft.VSCode","__CF_USER_TEXT_ENCODING":"0x1F5:0x0:0x0","FIG_NEW_SESSION":"1","TERM_PROGRAM":"vscode","TERM_PROGRAM_VERSION":"1.87.2","LANG":"en_US.UTF-8","COLORTERM":"truecolor","GIT_ASKPASS":"/Applications/Visual Studio Code.app/Contents/Resources/app/extensions/git/dist/askpass.sh","VSCODE_GIT_ASKPASS_NODE":"/Applications/Visual Studio Code.app/Contents/Frameworks/Code Helper (Plugin).app/Contents/MacOS/Code Helper (Plugin)","VSCODE_GIT_ASKPASS_EXTRA_ARGS":"","VSCODE_GIT_ASKPASS_MAIN":"/Applications/Visual Studio Code.app/Contents/Resources/app/extensions/git/dist/askpass-main.js","VSCODE_GIT_IPC_HANDLE":"/var/folders/pc/gmwmj7cd5zd7q60p91_lxfsw0000gn/T/vscode-git-9b00476df3.sock","VSCODE_INJECTION":"1","VSCODE_PATH_PREFIX":"/Users/petertrost/.pyenv/versions/3.10.13/bin:","ZDOTDIR":"/Users/petertrost","USER_ZDOTDIR":"/Users/petertrost","PWD":"/Users/petertrost/dev/emotely_backend/rules","TERM":"xterm-256color","SHLVL":"1","OLDPWD":"/Users/petertrost/dev/emotely_backend","ZSH":"/Users/petertrost/.oh-my-zsh","DEFAULT_USER":"petertrost","PAGER":"less","LESS":"-R","LSCOLORS":"Gxfxcxdxbxegedabagacad","LS_COLORS":"di=1;36:ln=35:so=32:pi=33:ex=31:bd=34;46:cd=34;43:su=30;41:sg=30;46:tw=30;42:ow=30;43","NVM_DIR":"/Users/petertrost/.nvm","NVM_CD_FLAGS":"-q","NVM_BIN":"/Users/petertrost/.nvm/versions/node/v18.19.1/bin","NVM_INC":"/Users/petertrost/.nvm/versions/node/v18.19.1/include/node","PYENV_ROOT":"/Users/petertrost/.pyenv","PYENV_SHELL":"zsh","LC_ALL":"en_US.UTF-8","ANDROID_HOME":"/Users/petertrost/Library/Android/sdk","rvm_prefix":"/Users/petertrost","rvm_path":"/Users/petertrost/.rvm","rvm_bin_path":"/Users/petertrost/.rvm/bin","rvm_version":"1.29.12-next (master)","GEM_HOME":"/Users/petertrost/.rvm/gems/ruby-3.2.2","GEM_PATH":"/Users/petertrost/.rvm/gems/ruby-3.2.2:/Users/petertrost/.rvm/gems/ruby-3.2.2@global","MY_RUBY_HOME":"/Users/petertrost/.rvm/rubies/ruby-3.2.2","IRBRC":"/Users/petertrost/.rvm/rubies/ruby-3.2.2/.irbrc","RUBY_VERSION":"ruby-3.2.2","rvm_alias_expanded":"","rvm_bin_flag":"","rvm_docs_type":"","rvm_gemstone_package_file":"","rvm_gemstone_url":"","rvm_niceness":"","rvm_nightly_flag":"","rvm_only_path_flag":"","rvm_pretty_print_flag":"","rvm_proxy":"","rvm_quiet_flag":"","rvm_ruby_bits":"","rvm_ruby_file":"","rvm_ruby_make":"","rvm_ruby_make_install":"","rvm_ruby_mode":"","rvm_script_name":"","rvm_sdk":"","rvm_silent_flag":"","rvm_use_flag":"","rvm_hook":"","_":"/Users/petertrost/.nvm/versions/node/v18.19.1/bin/firebase","DEBUG":"true","IS_FIREBASE_CLI":"true","GCLOUD_PROJECT":"emotely-test","FIREBASE_CONFIG":"{\"projectId\":\"emotely-test\",\"storageBucket\":\"emotely-test.appspot.com\",\"databaseURL\":\"https://emotely-test.firebaseio.com\"}","FIREBASE_EMULATOR_HUB":"127.0.0.1:4400","FIRESTORE_EMULATOR_HOST":"127.0.0.1:8080","FIREBASE_FIRESTORE_EMULATOR_ADDRESS":"127.0.0.1:8080"}

> unit-test-security-rules@1.0.0 test-firestore
> mocha --reporter spec tests/firestore.test.js --timeout 10000



[2024-03-24T13:07:35.627Z] Mar 24, 2024 2:07:35 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
INFO: Detected non-HTTP/2 connection.
 {"metadata":{"emulator":{"name":"firestore"},"message":"Mar 24, 2024 2:07:35 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead\nINFO: Detected non-HTTP/2 connection.\n"}}
[2024-03-24T13:07:35.709Z] Mar 24, 2024 2:07:35 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
INFO: Detected HTTP/2 connection.
 {"metadata":{"emulator":{"name":"firestore"},"message":"Mar 24, 2024 2:07:35 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead\nINFO: Detected HTTP/2 connection.\n"}}
  user's document
    should be accessible by authenticated user
[2024-03-24T13:07:35.996Z] Mar 24, 2024 2:07:35 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
INFO: Detected non-HTTP/2 connection.
 {"metadata":{"emulator":{"name":"firestore"},"message":"Mar 24, 2024 2:07:35 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead\nINFO: Detected non-HTTP/2 connection.\n"}}
      ✔ for reading

[2024-03-24T13:07:36.053Z] Mar 24, 2024 2:07:36 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
INFO: Detected HTTP/2 connection.
 {"metadata":{"emulator":{"name":"firestore"},"message":"Mar 24, 2024 2:07:36 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead\nINFO: Detected HTTP/2 connection.\n"}}
[2024-03-24T13:07:36.054Z] Mar 24, 2024 2:07:36 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead
INFO: Detected non-HTTP/2 connection.
 {"metadata":{"emulator":{"name":"firestore"},"message":"Mar 24, 2024 2:07:36 PM io.gapi.emulators.netty.HttpVersionRoutingHandler channelRead\nINFO: Detected non-HTTP/2 connection.\n"}}

  1 passing (471ms)

[aalej]

Hey @Peetee06, thanks for the thorough report! This is appreciated. I was able to reproduce the issue using the code snippets you provided. From what I can tell, it looks like the issue may be with the @firebase/rules-unit-testing module. I tried running the tests on an emulator running via firebase emulators:start, and the test script does not exit.

For example:

1. Run firebase emulators:start
2. On a separate terminal, run the tests npm run test-firestore
   • The tests does not finish running

My guess is that there is still a pending promise in the test, which makes it so that the command keeps on running. I would recommend filing an issue to the firebase-js-sdk repository since they handle issues related to the @firebase/rules-unit-testing module. If you think this is a mistake, and that the issue is with firebase-tools, feel free to ask this issue to be reopened.

A possible workaround here would be to pass the --exit option to your Mocha test, which would force Mocha to quit after all the tests have finished running:

firebase emulators:exec --only firestore 'npm run test-firestore -- --exit'