From 290d1a7eae969477adcde0e1ab6206bd1c52dc3f Mon Sep 17 00:00:00 2001
From: Denver Coneybeare <dconeybe@google.com>
Date: Thu, 2 Mar 2023 15:25:47 -0500
Subject: [PATCH 01/16] package.json: remove --concurrency 4 to see if we get
 better logs as to why the tests are failing

---
 package.json | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/package.json b/package.json
index 4ab7309f129..b04622d5af1 100644
--- a/package.json
+++ b/package.json
@@ -30,8 +30,8 @@
     "repl": "node tools/repl.js",
     "release": "ts-node-script scripts/release/cli.ts",
     "pretest": "node tools/pretest.js",
-    "test": "lerna run --ignore firebase-messaging-integration-test --concurrency 4 --stream test",
-    "test:ci": "lerna run --ignore firebase-messaging-integration-test --concurrency 4 test:ci",
+    "test": "lerna run --ignore firebase-messaging-integration-test --stream test",
+    "test:ci": "lerna run --ignore firebase-messaging-integration-test test:ci",
     "pretest:coverage": "mkdirp coverage",
     "ci:coverage": "lcov-result-merger 'packages/**/lcov.info' 'lcov-all.info'",
     "test:coverage": "lcov-result-merger 'packages/**/lcov.info' | coveralls",

From 18a4d426666cee0bb96bc7a1420a86a38ac18e14 Mon Sep 17 00:00:00 2001
From: Denver Coneybeare <dconeybe@google.com>
Date: Thu, 2 Mar 2023 15:28:27 -0500
Subject: [PATCH 02/16] make a trivial change to firestore so that firestore
 tests get triggered by gha

---
 packages/firestore/test/integration/util/helpers.ts | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/packages/firestore/test/integration/util/helpers.ts b/packages/firestore/test/integration/util/helpers.ts
index 79dbacaafa0..71298a9f3f2 100644
--- a/packages/firestore/test/integration/util/helpers.ts
+++ b/packages/firestore/test/integration/util/helpers.ts
@@ -81,7 +81,7 @@ function apiDescribeInternal(
   }
 
   for (const enabled of persistenceModes) {
-    describeFn(`(Persistence=${enabled}) ${message}`, () => testSuite(enabled));
+    describeFn(`(persistence=${enabled}) ${message}`, () => testSuite(enabled));
   }
 }
 

From 4964e4457ff42506d87067bc6e5c380be18ef7bc Mon Sep 17 00:00:00 2001
From: Denver Coneybeare <dconeybe@google.com>
Date: Fri, 3 Mar 2023 00:31:43 -0500
Subject: [PATCH 03/16] package.json: run-p -> run-s to remove another source
 of parallelism that could be hiding the root cause of the failure

---
 packages/firestore/package.json | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/packages/firestore/package.json b/packages/firestore/package.json
index b23650a94f0..fdb7d1978e1 100644
--- a/packages/firestore/package.json
+++ b/packages/firestore/package.json
@@ -27,8 +27,8 @@
     "test:lite:browser:debug": "karma start --browsers=Chrome --lite --auto-watch",
     "test": "run-s lint test:all",
     "test:ci": "node ../../scripts/run_tests_in_ci.js -s test:all:ci",
-    "test:all:ci": "run-p test:browser test:lite:browser test:travis",
-    "test:all": "run-p test:browser test:lite:browser test:travis test:minified",
+    "test:all:ci": "run-s test:browser test:lite:browser test:travis",
+    "test:all": "run-s test:browser test:lite:browser test:travis test:minified",
     "test:browser": "karma start --single-run",
     "test:browser:emulator:debug": "karma start --browsers=Chrome --targetBackend=emulator",
     "test:browser:emulator": "karma start --single-run --targetBackend=emulator",

From 20e2f5e26f3e327f3ad61d16c1532ff1c866bb63 Mon Sep 17 00:00:00 2001
From: Denver Coneybeare <dconeybe@google.com>
Date: Fri, 3 Mar 2023 00:51:46 -0500
Subject: [PATCH 04/16] scripts/run-tests.ts: add logging

---
 packages/firestore/scripts/run-tests.ts | 25 ++++++++++++++++++++++---
 1 file changed, 22 insertions(+), 3 deletions(-)

diff --git a/packages/firestore/scripts/run-tests.ts b/packages/firestore/scripts/run-tests.ts
index a3b94aa9eae..d780d513bfe 100644
--- a/packages/firestore/scripts/run-tests.ts
+++ b/packages/firestore/scripts/run-tests.ts
@@ -20,6 +20,12 @@ import { resolve } from 'path';
 import { spawn } from 'child-process-promise';
 import * as yargs from 'yargs';
 
+function debugLog(...args: any[]): void {
+  console.log(__filename, performance.now(),...args);
+}
+
+debugLog("command-line arguments:", process.argv);
+
 const argv = yargs.options({
   main: {
     type: 'string',
@@ -58,21 +64,34 @@ let args = [
 ];
 
 if (argv.emulator) {
+  debugLog("setting FIRESTORE_TARGET_BACKEND=emulator");
   process.env.FIRESTORE_TARGET_BACKEND = 'emulator';
 }
 
 if (argv.persistence) {
+  debugLog("setting USE_MOCK_PERSISTENCE=YES");
   process.env.USE_MOCK_PERSISTENCE = 'YES';
   args.push('--require', 'test/util/node_persistence.ts');
 }
 
 args = args.concat(argv._ as string[]);
 
+debugLog("spawning child process:", nyc, args);
+
 const childProcess = spawn(nyc, args, {
   stdio: 'inherit',
   cwd: process.cwd()
 }).childProcess;
 
-process.once('exit', () => childProcess.kill());
-process.once('SIGINT', () => childProcess.kill('SIGINT'));
-process.once('SIGTERM', () => childProcess.kill('SIGTERM'));
+process.once('exit', () => {
+  debugLog("WARNING: received 'exit' event; killing child process");
+  childProcess.kill()
+});
+process.once('SIGINT', () => {
+  debugLog("WARNING: received 'SIGINT' event; sending it to child process");
+  childProcess.kill('SIGINT')
+});
+process.once('SIGTERM', () => {
+  debugLog("WARNING: received 'SIGTERM' event; sending it to child process");
+  childProcess.kill('SIGTERM')
+});

From 6dab194663717b728878c9fd1db1ea301972bc78 Mon Sep 17 00:00:00 2001
From: Denver Coneybeare <dconeybe@google.com>
Date: Fri, 3 Mar 2023 01:04:12 -0500
Subject: [PATCH 05/16] scripts/run-tests.ts: fix linting errors

---
 packages/firestore/scripts/run-tests.ts | 7 ++++---
 1 file changed, 4 insertions(+), 3 deletions(-)

diff --git a/packages/firestore/scripts/run-tests.ts b/packages/firestore/scripts/run-tests.ts
index d780d513bfe..91add675ba1 100644
--- a/packages/firestore/scripts/run-tests.ts
+++ b/packages/firestore/scripts/run-tests.ts
@@ -21,6 +21,7 @@ import { spawn } from 'child-process-promise';
 import * as yargs from 'yargs';
 
 function debugLog(...args: any[]): void {
+  // eslint-disable-next-line no-console
   console.log(__filename, performance.now(),...args);
 }
 
@@ -85,13 +86,13 @@ const childProcess = spawn(nyc, args, {
 
 process.once('exit', () => {
   debugLog("WARNING: received 'exit' event; killing child process");
-  childProcess.kill()
+  childProcess.kill();
 });
 process.once('SIGINT', () => {
   debugLog("WARNING: received 'SIGINT' event; sending it to child process");
-  childProcess.kill('SIGINT')
+  childProcess.kill('SIGINT');
 });
 process.once('SIGTERM', () => {
   debugLog("WARNING: received 'SIGTERM' event; sending it to child process");
-  childProcess.kill('SIGTERM')
+  childProcess.kill('SIGTERM');
 });

From 8c557d60d29f80932deab5e72dca0d79344b7d9c Mon Sep 17 00:00:00 2001
From: Denver Coneybeare <dconeybe@google.com>
Date: Fri, 3 Mar 2023 01:08:53 -0500
Subject: [PATCH 06/16] scripts/run-tests.ts: make timestamp in log messages
 more human friendly

---
 packages/firestore/scripts/run-tests.ts | 46 ++++++++++++++++++++++++-
 1 file changed, 45 insertions(+), 1 deletion(-)

diff --git a/packages/firestore/scripts/run-tests.ts b/packages/firestore/scripts/run-tests.ts
index 91add675ba1..5269d193ac5 100644
--- a/packages/firestore/scripts/run-tests.ts
+++ b/packages/firestore/scripts/run-tests.ts
@@ -20,9 +20,53 @@ import { resolve } from 'path';
 import { spawn } from 'child-process-promise';
 import * as yargs from 'yargs';
 
+/**
+ * Keep track of "time zero" so that all log statements can have an offset from
+ * this "time zero". This makes it easy to see how long operations take, rather
+ * than printing the wall clock time.
+ *
+ * This value is initialized the first time that `log()` is called.
+ */
+let logStartTime: DOMHighResTimeStamp | null = null;
+
 function debugLog(...args: any[]): void {
   // eslint-disable-next-line no-console
-  console.log(__filename, performance.now(),...args);
+  console.log(__filename, elapsedTimeStr(), ...args);
+}
+
+/**
+ * Creates and returns a "timestamp" string for the elapsed time.
+ *
+ * The given timestamp is taken as an offset from the first time that this
+ * function is invoked. This allows log messages to start at "time 0" and make
+ * it easy for humans to calculate the elapsed time.
+ *
+ * @returns The timestamp string with which to prefix log lines added to the
+ * UI, created from the elapsed time since this function's first invocation.
+ */
+function elapsedTimeStr(): string {
+  const milliseconds = getElapsedMilliseconds();
+  const minutes = Math.floor(milliseconds / (1000 * 60));
+  const seconds = (milliseconds - minutes * 1000 * 60) / 1000;
+  return (
+    (minutes < 10 ? '0' : '') +
+    minutes +
+    ':' +
+    (seconds < 10 ? '0' : '') +
+    seconds.toFixed(3)
+  );
+}
+
+/**
+ * Returns the number of milliseconds that have elapsed since this function's
+ * first invocation.
+ */
+function getElapsedMilliseconds(): number {
+  if (!logStartTime) {
+    logStartTime = performance.now();
+    return 0;
+  }
+  return performance.now() - logStartTime;
 }
 
 debugLog("command-line arguments:", process.argv);

From 3569940a77ab2525b54052795201381e057c723c Mon Sep 17 00:00:00 2001
From: Denver Coneybeare <dconeybe@google.com>
Date: Fri, 3 Mar 2023 01:13:36 -0500
Subject: [PATCH 07/16] Remove check-changeset.yml because it annonyingly
 always fails when using any branch other than 'master' as the base branch of
 a PR

---
 .github/workflows/check-changeset.yml | 75 ---------------------------
 1 file changed, 75 deletions(-)
 delete mode 100644 .github/workflows/check-changeset.yml

diff --git a/.github/workflows/check-changeset.yml b/.github/workflows/check-changeset.yml
deleted file mode 100644
index d6ea0b15d63..00000000000
--- a/.github/workflows/check-changeset.yml
+++ /dev/null
@@ -1,75 +0,0 @@
-name: Check Changeset
-
-on:
-  pull_request:
-    branches-ignore:
-      - release
-
-env:
-  GITHUB_PULL_REQUEST_HEAD_SHA: ${{ github.event.pull_request.head.sha }}
-  GITHUB_PULL_REQUEST_BASE_SHA: ${{ github.event.pull_request.base.sha }}
-
-jobs:
-  check_changeset:
-    name: Check changeset vs changed files
-    runs-on: ubuntu-latest
-
-    steps:
-    - name: Checkout Repo
-      uses: actions/checkout@master
-      with:
-        # This makes Actions fetch all Git history so check_changeset script can diff properly.
-        fetch-depth: 0
-    - name: Set up Node (14)
-      uses: actions/setup-node@v2
-      with:
-        node-version: 14.x
-    - name: Yarn install
-      run: yarn
-    - name: Run changeset script
-      # pull master so changeset can diff against it
-      run: |
-        git pull -f --no-rebase origin master:master
-        yarn ts-node-script scripts/ci/check_changeset.ts
-      id: check-changeset
-    - name: Print changeset checker output
-      run: echo "${{steps.check-changeset.outputs.CHANGESET_ERROR_MESSAGE}}"
-    - name: Print blocking failure status
-      run: echo "${{steps.check-changeset.outputs.BLOCKING_FAILURE}}"
-    - name: Find Comment
-      uses: peter-evans/find-comment@v1
-      id: fc
-      with:
-        issue-number: ${{github.event.number}}
-        body-includes: Changeset File Check
-    - name: Create comment (missing packages)
-      if: ${{!steps.fc.outputs.comment-id && steps.check-changeset.outputs.CHANGESET_ERROR_MESSAGE}}
-      uses: peter-evans/create-or-update-comment@v1
-      with:
-        issue-number: ${{github.event.number}}
-        body: |
-          ### Changeset File Check :warning:
-          ${{steps.check-changeset.outputs.CHANGESET_ERROR_MESSAGE}}
-    - name: Update comment (missing packages)
-      if: ${{steps.fc.outputs.comment-id}}
-      uses: peter-evans/create-or-update-comment@v1
-      with:
-        comment-id: ${{steps.fc.outputs.comment-id}} && steps.check-changeset.outputs.CHANGESET_ERROR_MESSAGE}}
-        edit-mode: replace
-        body: |
-          ### Changeset File Check :warning:
-          ${{steps.check-changeset.outputs.CHANGESET_ERROR_MESSAGE}}
-    - name: Update comment (no missing packages)
-      if: ${{steps.fc.outputs.comment-id && !steps.check-changeset.outputs.CHANGESET_ERROR_MESSAGE}}
-      uses: peter-evans/create-or-update-comment@v1
-      with:
-        comment-id: ${{steps.fc.outputs.comment-id}}
-        edit-mode: replace
-        body: |
-          ### Changeset File Check :white_check_mark:
-          - No modified packages are missing from the changeset file.
-          - No changeset formatting errors detected.
-    # Don't want it to throw before editing the comment.
-    - name: Fail if checker script logged a blocking failure
-      if: ${{steps.check-changeset.outputs.BLOCKING_FAILURE == 'true'}}
-      run: exit 1
\ No newline at end of file

From 6f0304a2a774dc9fb9af1f89a93ed131d4fe8262 Mon Sep 17 00:00:00 2001
From: Denver Coneybeare <dconeybe@google.com>
Date: Fri, 3 Mar 2023 02:46:25 -0500
Subject: [PATCH 08/16] scripts/run_tests_in_ci.js: add more helpful debug
 logging output

---
 scripts/run_tests_in_ci.js | 68 +++++++++++++++++++++++++++++++++++---
 1 file changed, 64 insertions(+), 4 deletions(-)

diff --git a/scripts/run_tests_in_ci.js b/scripts/run_tests_in_ci.js
index fdced9cb70f..4d854e95637 100644
--- a/scripts/run_tests_in_ci.js
+++ b/scripts/run_tests_in_ci.js
@@ -20,6 +20,62 @@ const path = require('path');
 const { spawn } = require('child-process-promise');
 const { writeFileSync } = require('fs');
 
+/**
+ * Keep track of "time zero" so that all log statements can have an offset from
+ * this "time zero". This makes it easy to see how long operations take, rather
+ * than printing the wall clock time.
+ *
+ * This value is initialized the first time that `log()` is called.
+ */
+let logStartTime: DOMHighResTimeStamp | null = null;
+
+function debugLog(...args: any[]): void {
+  // eslint-disable-next-line no-console
+  console.log(__filename, elapsedTimeStr(), ...args);
+}
+
+function errorLog(...args: any[]): void {
+  // eslint-disable-next-line no-console
+  console.error(__filename, elapsedTimeStr(), ...args);
+}
+
+/**
+ * Creates and returns a "timestamp" string for the elapsed time.
+ *
+ * The given timestamp is taken as an offset from the first time that this
+ * function is invoked. This allows log messages to start at "time 0" and make
+ * it easy for humans to calculate the elapsed time.
+ *
+ * @returns The timestamp string with which to prefix log lines added to the
+ * UI, created from the elapsed time since this function's first invocation.
+ */
+function elapsedTimeStr(): string {
+  const milliseconds = getElapsedMilliseconds();
+  const minutes = Math.floor(milliseconds / (1000 * 60));
+  const seconds = (milliseconds - minutes * 1000 * 60) / 1000;
+  return (
+    (minutes < 10 ? '0' : '') +
+    minutes +
+    ':' +
+    (seconds < 10 ? '0' : '') +
+    seconds.toFixed(3)
+  );
+}
+
+/**
+ * Returns the number of milliseconds that have elapsed since this function's
+ * first invocation.
+ */
+function getElapsedMilliseconds(): number {
+  if (!logStartTime) {
+    logStartTime = performance.now();
+    return 0;
+  }
+  return performance.now() - logStartTime;
+}
+
+debugLog("command-line arguments:", process.argv);
+
 const LOGDIR = process.env.CI ? process.env.HOME : '/tmp';
 // Maps the packages where we should not run `test:all` and instead isolate the cross-browser tests.
 // TODO(dwyfrequency): Update object with `storage` and `firestore` packages.
@@ -69,7 +125,10 @@ const argv = yargs.options({
         }
       }
     }
-    const testProcess = spawn('yarn', ['--cwd', dir, scriptName]);
+
+    const yarnArgs = ['--cwd', dir, scriptName];
+    debugLog(`spawning '${name}' process`:', 'yarn', yarnArgs);
+    const testProcess = spawn('yarn', yarnArgs);
 
     testProcess.childProcess.stdout.on('data', data => {
       stdout += data.toString();
@@ -79,13 +138,14 @@ const argv = yargs.options({
     });
 
     await testProcess;
-    console.log('Success: ' + name);
+    debugLog(`${name} process completed successfully:`, 'yarn', yarnArgs);
     writeLogs('Success', name, stdout + '\n' + stderr);
   } catch (e) {
-    console.error('Failure: ' + name);
+    errorLog(`${name} process FAILED:`, 'yarn', yarnArgs);
     console.log(stdout);
     console.error(stderr);
     writeLogs('Failure', name, stdout + '\n' + stderr);
-    process.exit(1);
+    debugLog('Completing with failure exit code 76');
+    process.exit(76);
   }
 })();

From 3a5f602dacb2b6f3d68d6d522774117d0f3ffe7f Mon Sep 17 00:00:00 2001
From: Denver Coneybeare <dconeybe@google.com>
Date: Fri, 3 Mar 2023 02:50:29 -0500
Subject: [PATCH 09/16] scripts/run_tests_in_ci.js: fix typo and add dividers
 for stdout/stderr

---
 scripts/run_tests_in_ci.js | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)

diff --git a/scripts/run_tests_in_ci.js b/scripts/run_tests_in_ci.js
index 4d854e95637..98c7ecda544 100644
--- a/scripts/run_tests_in_ci.js
+++ b/scripts/run_tests_in_ci.js
@@ -127,7 +127,7 @@ const argv = yargs.options({
     }
 
     const yarnArgs = ['--cwd', dir, scriptName];
-    debugLog(`spawning '${name}' process`:', 'yarn', yarnArgs);
+    debugLog(`spawning '${name}' process:`, 'yarn', yarnArgs);
     const testProcess = spawn('yarn', yarnArgs);
 
     testProcess.childProcess.stdout.on('data', data => {
@@ -142,8 +142,12 @@ const argv = yargs.options({
     writeLogs('Success', name, stdout + '\n' + stderr);
   } catch (e) {
     errorLog(`${name} process FAILED:`, 'yarn', yarnArgs);
+    debugLog(`${name} process ==== STDOUT BEGIN ====`);
     console.log(stdout);
+    debugLog(`${name} process ==== STDOUT END ====`);
+    debugLog(`${name} process ==== STDERR BEGIN ====`);
     console.error(stderr);
+    debugLog(`${name} process ==== STDERR END ====`);
     writeLogs('Failure', name, stdout + '\n' + stderr);
     debugLog('Completing with failure exit code 76');
     process.exit(76);

From fc60e9b83edfdd0a7e776a6dcedcdc623f91682c Mon Sep 17 00:00:00 2001
From: Denver Coneybeare <dconeybe@google.com>
Date: Fri, 3 Mar 2023 02:55:00 -0500
Subject: [PATCH 10/16] more script log output additions

---
 scripts/ci-test/test_changed.ts | 62 ++++++++++++++++++++++++++++++++-
 scripts/run_tests_in_ci.js      |  2 +-
 2 files changed, 62 insertions(+), 2 deletions(-)

diff --git a/scripts/ci-test/test_changed.ts b/scripts/ci-test/test_changed.ts
index 5d2f30865ed..d0bd1b51868 100644
--- a/scripts/ci-test/test_changed.ts
+++ b/scripts/ci-test/test_changed.ts
@@ -23,6 +23,62 @@ import * as yargs from 'yargs';
 import { TestConfig, testConfig } from './testConfig';
 const root = resolve(__dirname, '../..');
 
+/**
+ * Keep track of "time zero" so that all log statements can have an offset from
+ * this "time zero". This makes it easy to see how long operations take, rather
+ * than printing the wall clock time.
+ *
+ * This value is initialized the first time that `log()` is called.
+ */
+let logStartTime: DOMHighResTimeStamp | null = null;
+
+function debugLog(...args: any[]): void {
+  // eslint-disable-next-line no-console
+  console.log(__filename, elapsedTimeStr(), ...args);
+}
+
+function errorLog(...args: any[]): void {
+  // eslint-disable-next-line no-console
+  console.error(__filename, elapsedTimeStr(), ...args);
+}
+
+/**
+ * Creates and returns a "timestamp" string for the elapsed time.
+ *
+ * The given timestamp is taken as an offset from the first time that this
+ * function is invoked. This allows log messages to start at "time 0" and make
+ * it easy for humans to calculate the elapsed time.
+ *
+ * @returns The timestamp string with which to prefix log lines added to the
+ * UI, created from the elapsed time since this function's first invocation.
+ */
+function elapsedTimeStr(): string {
+  const milliseconds = getElapsedMilliseconds();
+  const minutes = Math.floor(milliseconds / (1000 * 60));
+  const seconds = (milliseconds - minutes * 1000 * 60) / 1000;
+  return (
+    (minutes < 10 ? '0' : '') +
+    minutes +
+    ':' +
+    (seconds < 10 ? '0' : '') +
+    seconds.toFixed(3)
+  );
+}
+
+/**
+ * Returns the number of milliseconds that have elapsed since this function's
+ * first invocation.
+ */
+function getElapsedMilliseconds(): number {
+  if (!logStartTime) {
+    logStartTime = performance.now();
+    return 0;
+  }
+  return performance.now() - logStartTime;
+}
+
+debugLog("command-line arguments:", process.argv);
+
 const argv = yargs.parseSync();
 const inputTestConfigName = argv._[0].toString();
 const testCommand = 'test:ci';
@@ -76,10 +132,14 @@ async function runTests(config: TestConfig) {
     }
 
     lernaCmd.push(testCommand);
+    debugLog('spawning process: npx', lernaCmd)
     await spawn('npx', lernaCmd, { stdio: 'inherit', cwd: root });
+    debugLog('process completed successfully: npx', lernaCmd)
     process.exit(0);
   } catch (e) {
+    errorLog('process failed');
     console.error(chalk`{red ${e}}`);
-    process.exit(1);
+    errorLog('terminating with exit code 65');
+    process.exit(65);
   }
 }
diff --git a/scripts/run_tests_in_ci.js b/scripts/run_tests_in_ci.js
index 98c7ecda544..86e431eb7b6 100644
--- a/scripts/run_tests_in_ci.js
+++ b/scripts/run_tests_in_ci.js
@@ -141,7 +141,7 @@ const argv = yargs.options({
     debugLog(`${name} process completed successfully:`, 'yarn', yarnArgs);
     writeLogs('Success', name, stdout + '\n' + stderr);
   } catch (e) {
-    errorLog(`${name} process FAILED:`, 'yarn', yarnArgs);
+    errorLog(`${name} process FAILED`);
     debugLog(`${name} process ==== STDOUT BEGIN ====`);
     console.log(stdout);
     debugLog(`${name} process ==== STDOUT END ====`);

From 5992b8830b2de27012a4f7e91fd8581f90e6c3f7 Mon Sep 17 00:00:00 2001
From: Denver Coneybeare <dconeybe@google.com>
Date: Fri, 3 Mar 2023 10:43:02 -0500
Subject: [PATCH 11/16] scripts/run_tests_in_ci.js: remove TypeScript code from
 JavaScript source

---
 scripts/run_tests_in_ci.js | 10 +++++-----
 1 file changed, 5 insertions(+), 5 deletions(-)

diff --git a/scripts/run_tests_in_ci.js b/scripts/run_tests_in_ci.js
index 86e431eb7b6..61983307a4c 100644
--- a/scripts/run_tests_in_ci.js
+++ b/scripts/run_tests_in_ci.js
@@ -27,14 +27,14 @@ const { writeFileSync } = require('fs');
  *
  * This value is initialized the first time that `log()` is called.
  */
-let logStartTime: DOMHighResTimeStamp | null = null;
+let logStartTime = null;
 
-function debugLog(...args: any[]): void {
+function debugLog(...args) {
   // eslint-disable-next-line no-console
   console.log(__filename, elapsedTimeStr(), ...args);
 }
 
-function errorLog(...args: any[]): void {
+function errorLog(...args) {
   // eslint-disable-next-line no-console
   console.error(__filename, elapsedTimeStr(), ...args);
 }
@@ -49,7 +49,7 @@ function errorLog(...args: any[]): void {
  * @returns The timestamp string with which to prefix log lines added to the
  * UI, created from the elapsed time since this function's first invocation.
  */
-function elapsedTimeStr(): string {
+function elapsedTimeStr() {
   const milliseconds = getElapsedMilliseconds();
   const minutes = Math.floor(milliseconds / (1000 * 60));
   const seconds = (milliseconds - minutes * 1000 * 60) / 1000;
@@ -66,7 +66,7 @@ function elapsedTimeStr(): string {
  * Returns the number of milliseconds that have elapsed since this function's
  * first invocation.
  */
-function getElapsedMilliseconds(): number {
+function getElapsedMilliseconds() {
   if (!logStartTime) {
     logStartTime = performance.now();
     return 0;

From 26edb30dbfe3debed0622d6e538f3fd78188e971 Mon Sep 17 00:00:00 2001
From: Denver Coneybeare <dconeybe@google.com>
Date: Fri, 3 Mar 2023 10:51:09 -0500
Subject: [PATCH 12/16] scripts/ci-test/test_changed.ts: fix formatting

---
 scripts/ci-test/test_changed.ts | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/scripts/ci-test/test_changed.ts b/scripts/ci-test/test_changed.ts
index d0bd1b51868..f9f19e52f8f 100644
--- a/scripts/ci-test/test_changed.ts
+++ b/scripts/ci-test/test_changed.ts
@@ -77,7 +77,7 @@ function getElapsedMilliseconds(): number {
   return performance.now() - logStartTime;
 }
 
-debugLog("command-line arguments:", process.argv);
+debugLog('command-line arguments:', process.argv);
 
 const argv = yargs.parseSync();
 const inputTestConfigName = argv._[0].toString();
@@ -132,9 +132,9 @@ async function runTests(config: TestConfig) {
     }
 
     lernaCmd.push(testCommand);
-    debugLog('spawning process: npx', lernaCmd)
+    debugLog('spawning process: npx', lernaCmd);
     await spawn('npx', lernaCmd, { stdio: 'inherit', cwd: root });
-    debugLog('process completed successfully: npx', lernaCmd)
+    debugLog('process completed successfully: npx', lernaCmd);
     process.exit(0);
   } catch (e) {
     errorLog('process failed');

From c2e5d78f6c8c35b57a271f2c23710a026ee856f4 Mon Sep 17 00:00:00 2001
From: Denver Coneybeare <dconeybe@google.com>
Date: Fri, 3 Mar 2023 11:18:10 -0500
Subject: [PATCH 13/16] replace performance.now() with process.hrtime()

---
 packages/firestore/scripts/run-tests.ts | 55 ++++++++++++++---------
 scripts/ci-test/test_changed.ts         | 59 ++++++++++++++-----------
 scripts/run_tests_in_ci.js              | 59 ++++++++++++++-----------
 3 files changed, 100 insertions(+), 73 deletions(-)

diff --git a/packages/firestore/scripts/run-tests.ts b/packages/firestore/scripts/run-tests.ts
index 5269d193ac5..57b8f3ad3d8 100644
--- a/packages/firestore/scripts/run-tests.ts
+++ b/packages/firestore/scripts/run-tests.ts
@@ -20,19 +20,6 @@ import { resolve } from 'path';
 import { spawn } from 'child-process-promise';
 import * as yargs from 'yargs';
 
-/**
- * Keep track of "time zero" so that all log statements can have an offset from
- * this "time zero". This makes it easy to see how long operations take, rather
- * than printing the wall clock time.
- *
- * This value is initialized the first time that `log()` is called.
- */
-let logStartTime: DOMHighResTimeStamp | null = null;
-
-function debugLog(...args: any[]): void {
-  // eslint-disable-next-line no-console
-  console.log(__filename, elapsedTimeStr(), ...args);
-}
 
 /**
  * Creates and returns a "timestamp" string for the elapsed time.
@@ -41,8 +28,8 @@ function debugLog(...args: any[]): void {
  * function is invoked. This allows log messages to start at "time 0" and make
  * it easy for humans to calculate the elapsed time.
  *
- * @returns The timestamp string with which to prefix log lines added to the
- * UI, created from the elapsed time since this function's first invocation.
+ * @returns The timestamp string with which to prefix log lines, created from
+ * the elapsed time since this function's first invocation.
  */
 function elapsedTimeStr(): string {
   const milliseconds = getElapsedMilliseconds();
@@ -58,18 +45,44 @@ function elapsedTimeStr(): string {
 }
 
 /**
- * Returns the number of milliseconds that have elapsed since this function's
- * first invocation.
+ * The "start time", which is set to a non-null value upon the first invocation
+ * of `getElapsedMilliseconds()`. All subsequent invocations calculate the
+ * elapsed time using this value.
+ */
+let elapsedMillisecondsStartTime: number | null = null;
+
+/**
+ * Returns the number of nanoseconds that have elapsed since this function's
+ * first invocation. Returns 0 on its first invocation.
  */
 function getElapsedMilliseconds(): number {
-  if (!logStartTime) {
-    logStartTime = performance.now();
+  const currentTimeMilliseconds = getCurrentMonotonicTimeMilliseconds();
+  if (elapsedMillisecondsStartTime === null) {
+    elapsedMillisecondsStartTime = currentTimeMilliseconds;
     return 0;
   }
-  return performance.now() - logStartTime;
+  return currentTimeMilliseconds - elapsedMillisecondsStartTime;
+}
+
+/**
+ * Returns the current time, in milliseconds, from a monotonic clock.
+ */
+function getCurrentMonotonicTimeMilliseconds(): number {
+  const currentTime: [number, number] = process.hrtime();
+  return currentTime[0] * 1000 + currentTime[1] / 1_000_000;
+}
+
+function debugLog(...args: any[]): void {
+  // eslint-disable-next-line no-console
+  console.log(__filename, elapsedTimeStr(), ...args);
+}
+
+function errorLog(...args: any[]): void {
+  // eslint-disable-next-line no-console
+  console.error(__filename, elapsedTimeStr(), ...args);
 }
 
-debugLog("command-line arguments:", process.argv);
+debugLog('command-line arguments:', process.argv);
 
 const argv = yargs.options({
   main: {
diff --git a/scripts/ci-test/test_changed.ts b/scripts/ci-test/test_changed.ts
index f9f19e52f8f..7e96e7f4dbe 100644
--- a/scripts/ci-test/test_changed.ts
+++ b/scripts/ci-test/test_changed.ts
@@ -23,25 +23,6 @@ import * as yargs from 'yargs';
 import { TestConfig, testConfig } from './testConfig';
 const root = resolve(__dirname, '../..');
 
-/**
- * Keep track of "time zero" so that all log statements can have an offset from
- * this "time zero". This makes it easy to see how long operations take, rather
- * than printing the wall clock time.
- *
- * This value is initialized the first time that `log()` is called.
- */
-let logStartTime: DOMHighResTimeStamp | null = null;
-
-function debugLog(...args: any[]): void {
-  // eslint-disable-next-line no-console
-  console.log(__filename, elapsedTimeStr(), ...args);
-}
-
-function errorLog(...args: any[]): void {
-  // eslint-disable-next-line no-console
-  console.error(__filename, elapsedTimeStr(), ...args);
-}
-
 /**
  * Creates and returns a "timestamp" string for the elapsed time.
  *
@@ -49,8 +30,8 @@ function errorLog(...args: any[]): void {
  * function is invoked. This allows log messages to start at "time 0" and make
  * it easy for humans to calculate the elapsed time.
  *
- * @returns The timestamp string with which to prefix log lines added to the
- * UI, created from the elapsed time since this function's first invocation.
+ * @returns The timestamp string with which to prefix log lines, created from
+ * the elapsed time since this function's first invocation.
  */
 function elapsedTimeStr(): string {
   const milliseconds = getElapsedMilliseconds();
@@ -66,15 +47,41 @@ function elapsedTimeStr(): string {
 }
 
 /**
- * Returns the number of milliseconds that have elapsed since this function's
- * first invocation.
+ * The "start time", which is set to a non-null value upon the first invocation
+ * of `getElapsedMilliseconds()`. All subsequent invocations calculate the
+ * elapsed time using this value.
+ */
+let elapsedMillisecondsStartTime: number | null = null;
+
+/**
+ * Returns the number of nanoseconds that have elapsed since this function's
+ * first invocation. Returns 0 on its first invocation.
  */
 function getElapsedMilliseconds(): number {
-  if (!logStartTime) {
-    logStartTime = performance.now();
+  const currentTimeMilliseconds = getCurrentMonotonicTimeMilliseconds();
+  if (elapsedMillisecondsStartTime === null) {
+    elapsedMillisecondsStartTime = currentTimeMilliseconds;
     return 0;
   }
-  return performance.now() - logStartTime;
+  return currentTimeMilliseconds - elapsedMillisecondsStartTime;
+}
+
+/**
+ * Returns the current time, in milliseconds, from a monotonic clock.
+ */
+function getCurrentMonotonicTimeMilliseconds(): number {
+  const currentTime: [number, number] = process.hrtime();
+  return currentTime[0] * 1000 + currentTime[1] / 1_000_000;
+}
+
+function debugLog(...args: any[]): void {
+  // eslint-disable-next-line no-console
+  console.log(__filename, elapsedTimeStr(), ...args);
+}
+
+function errorLog(...args: any[]): void {
+  // eslint-disable-next-line no-console
+  console.error(__filename, elapsedTimeStr(), ...args);
 }
 
 debugLog('command-line arguments:', process.argv);
diff --git a/scripts/run_tests_in_ci.js b/scripts/run_tests_in_ci.js
index 61983307a4c..ab2dc311693 100644
--- a/scripts/run_tests_in_ci.js
+++ b/scripts/run_tests_in_ci.js
@@ -20,25 +20,6 @@ const path = require('path');
 const { spawn } = require('child-process-promise');
 const { writeFileSync } = require('fs');
 
-/**
- * Keep track of "time zero" so that all log statements can have an offset from
- * this "time zero". This makes it easy to see how long operations take, rather
- * than printing the wall clock time.
- *
- * This value is initialized the first time that `log()` is called.
- */
-let logStartTime = null;
-
-function debugLog(...args) {
-  // eslint-disable-next-line no-console
-  console.log(__filename, elapsedTimeStr(), ...args);
-}
-
-function errorLog(...args) {
-  // eslint-disable-next-line no-console
-  console.error(__filename, elapsedTimeStr(), ...args);
-}
-
 /**
  * Creates and returns a "timestamp" string for the elapsed time.
  *
@@ -46,8 +27,8 @@ function errorLog(...args) {
  * function is invoked. This allows log messages to start at "time 0" and make
  * it easy for humans to calculate the elapsed time.
  *
- * @returns The timestamp string with which to prefix log lines added to the
- * UI, created from the elapsed time since this function's first invocation.
+ * @returns The timestamp string with which to prefix log lines, created from
+ * the elapsed time since this function's first invocation.
  */
 function elapsedTimeStr() {
   const milliseconds = getElapsedMilliseconds();
@@ -63,15 +44,41 @@ function elapsedTimeStr() {
 }
 
 /**
- * Returns the number of milliseconds that have elapsed since this function's
- * first invocation.
+ * The "start time", which is set to a non-null value upon the first invocation
+ * of `getElapsedMilliseconds()`. All subsequent invocations calculate the
+ * elapsed time using this value.
+ */
+let elapsedMillisecondsStartTime = null;
+
+/**
+ * Returns the number of nanoseconds that have elapsed since this function's
+ * first invocation. Returns 0 on its first invocation.
  */
 function getElapsedMilliseconds() {
-  if (!logStartTime) {
-    logStartTime = performance.now();
+  const currentTimeMilliseconds = getCurrentMonotonicTimeMilliseconds();
+  if (elapsedMillisecondsStartTime === null) {
+    elapsedMillisecondsStartTime = currentTimeMilliseconds;
     return 0;
   }
-  return performance.now() - logStartTime;
+  return currentTimeMilliseconds - elapsedMillisecondsStartTime;
+}
+
+/**
+ * Returns the current time, in milliseconds, from a monotonic clock.
+ */
+function getCurrentMonotonicTimeMilliseconds() {
+  const currentTime = process.hrtime();
+  return currentTime[0] * 1000 + currentTime[1] / 1_000_000;
+}
+
+function debugLog(...args) {
+  // eslint-disable-next-line no-console
+  console.log(__filename, elapsedTimeStr(), ...args);
+}
+
+function errorLog(...args) {
+  // eslint-disable-next-line no-console
+  console.error(__filename, elapsedTimeStr(), ...args);
 }
 
 debugLog("command-line arguments:", process.argv);

From 28a86f21247ba4f76039001e0295a4999fced8d0 Mon Sep 17 00:00:00 2001
From: Denver Coneybeare <dconeybe@google.com>
Date: Fri, 3 Mar 2023 11:21:46 -0500
Subject: [PATCH 14/16] scripts/run_tests_in_ci.js: fix formatting

---
 scripts/run_tests_in_ci.js | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/scripts/run_tests_in_ci.js b/scripts/run_tests_in_ci.js
index ab2dc311693..30bb1b35a00 100644
--- a/scripts/run_tests_in_ci.js
+++ b/scripts/run_tests_in_ci.js
@@ -81,7 +81,7 @@ function errorLog(...args) {
   console.error(__filename, elapsedTimeStr(), ...args);
 }
 
-debugLog("command-line arguments:", process.argv);
+debugLog('command-line arguments:', process.argv);
 
 const LOGDIR = process.env.CI ? process.env.HOME : '/tmp';
 // Maps the packages where we should not run `test:all` and instead isolate the cross-browser tests.

From 97e75baf86de0a263a0b3517bb5017a6e0b8c9c5 Mon Sep 17 00:00:00 2001
From: Denver Coneybeare <dconeybe@google.com>
Date: Fri, 3 Mar 2023 11:29:11 -0500
Subject: [PATCH 15/16] firestore/scripts/run-tests.ts: use errorLog() to log
 errors, rather than debugLog().

---
 packages/firestore/scripts/run-tests.ts | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/packages/firestore/scripts/run-tests.ts b/packages/firestore/scripts/run-tests.ts
index 57b8f3ad3d8..f19ea399001 100644
--- a/packages/firestore/scripts/run-tests.ts
+++ b/packages/firestore/scripts/run-tests.ts
@@ -142,14 +142,14 @@ const childProcess = spawn(nyc, args, {
 }).childProcess;
 
 process.once('exit', () => {
-  debugLog("WARNING: received 'exit' event; killing child process");
+  errorLog("WARNING: received 'exit' event; killing child process");
   childProcess.kill();
 });
 process.once('SIGINT', () => {
-  debugLog("WARNING: received 'SIGINT' event; sending it to child process");
+  errorLog("WARNING: received 'SIGINT' event; sending it to child process");
   childProcess.kill('SIGINT');
 });
 process.once('SIGTERM', () => {
-  debugLog("WARNING: received 'SIGTERM' event; sending it to child process");
+  errorLog("WARNING: received 'SIGTERM' event; sending it to child process");
   childProcess.kill('SIGTERM');
 });

From 6cf93f80d767d653bc057f77ae5a9c5dd048816b Mon Sep 17 00:00:00 2001
From: Denver Coneybeare <dconeybe@google.com>
Date: Fri, 3 Mar 2023 15:23:10 -0500
Subject: [PATCH 16/16] make logging more palletable

---
 packages/firestore/scripts/run-tests.ts |  4 ++--
 scripts/ci-test/test_changed.ts         |  8 ++++----
 scripts/run_tests_in_ci.js              | 18 ++++++++++--------
 3 files changed, 16 insertions(+), 14 deletions(-)

diff --git a/packages/firestore/scripts/run-tests.ts b/packages/firestore/scripts/run-tests.ts
index f19ea399001..d13f91a01f0 100644
--- a/packages/firestore/scripts/run-tests.ts
+++ b/packages/firestore/scripts/run-tests.ts
@@ -82,7 +82,7 @@ function errorLog(...args: any[]): void {
   console.error(__filename, elapsedTimeStr(), ...args);
 }
 
-debugLog('command-line arguments:', process.argv);
+debugLog(`command-line arguments: ${process.argv.join(' ')}`);
 
 const argv = yargs.options({
   main: {
@@ -134,7 +134,7 @@ if (argv.persistence) {
 
 args = args.concat(argv._ as string[]);
 
-debugLog("spawning child process:", nyc, args);
+debugLog(`spawning child process: ${nyc} ${args.join(' ')}`);
 
 const childProcess = spawn(nyc, args, {
   stdio: 'inherit',
diff --git a/scripts/ci-test/test_changed.ts b/scripts/ci-test/test_changed.ts
index 7e96e7f4dbe..2546295589c 100644
--- a/scripts/ci-test/test_changed.ts
+++ b/scripts/ci-test/test_changed.ts
@@ -54,7 +54,7 @@ function elapsedTimeStr(): string {
 let elapsedMillisecondsStartTime: number | null = null;
 
 /**
- * Returns the number of nanoseconds that have elapsed since this function's
+ * Returns the number of milliseconds that have elapsed since this function's
  * first invocation. Returns 0 on its first invocation.
  */
 function getElapsedMilliseconds(): number {
@@ -84,7 +84,7 @@ function errorLog(...args: any[]): void {
   console.error(__filename, elapsedTimeStr(), ...args);
 }
 
-debugLog('command-line arguments:', process.argv);
+debugLog(`command-line arguments: ${process.argv.join(' ')}`);
 
 const argv = yargs.parseSync();
 const inputTestConfigName = argv._[0].toString();
@@ -139,9 +139,9 @@ async function runTests(config: TestConfig) {
     }
 
     lernaCmd.push(testCommand);
-    debugLog('spawning process: npx', lernaCmd);
+    debugLog(`spawning process: npx ${lernaCmd.join(' ')}`);
     await spawn('npx', lernaCmd, { stdio: 'inherit', cwd: root });
-    debugLog('process completed successfully: npx', lernaCmd);
+    debugLog(`process completed successfully: npx ${lernaCmd.join(' ')}`);
     process.exit(0);
   } catch (e) {
     errorLog('process failed');
diff --git a/scripts/run_tests_in_ci.js b/scripts/run_tests_in_ci.js
index 30bb1b35a00..609eb919180 100644
--- a/scripts/run_tests_in_ci.js
+++ b/scripts/run_tests_in_ci.js
@@ -81,7 +81,7 @@ function errorLog(...args) {
   console.error(__filename, elapsedTimeStr(), ...args);
 }
 
-debugLog('command-line arguments:', process.argv);
+debugLog(`command-line arguments: ${process.argv.join(' ')}`);
 
 const LOGDIR = process.env.CI ? process.env.HOME : '/tmp';
 // Maps the packages where we should not run `test:all` and instead isolate the cross-browser tests.
@@ -134,7 +134,7 @@ const argv = yargs.options({
     }
 
     const yarnArgs = ['--cwd', dir, scriptName];
-    debugLog(`spawning '${name}' process:`, 'yarn', yarnArgs);
+    debugLog(`spawning '${name}' process: yarn ${yarnArgs.join(' ')}`);
     const testProcess = spawn('yarn', yarnArgs);
 
     testProcess.childProcess.stdout.on('data', data => {
@@ -145,18 +145,20 @@ const argv = yargs.options({
     });
 
     await testProcess;
-    debugLog(`${name} process completed successfully:`, 'yarn', yarnArgs);
+    debugLog(
+      `'${name}' process completed successfully: yarn ${yarnArgs.join(' ')}`
+    );
     writeLogs('Success', name, stdout + '\n' + stderr);
   } catch (e) {
     errorLog(`${name} process FAILED`);
-    debugLog(`${name} process ==== STDOUT BEGIN ====`);
+    errorLog(`${name} process ==== STDOUT BEGIN ====`);
     console.log(stdout);
-    debugLog(`${name} process ==== STDOUT END ====`);
-    debugLog(`${name} process ==== STDERR BEGIN ====`);
+    errorLog(`${name} process ==== STDOUT END ====`);
+    errorLog(`${name} process ==== STDERR BEGIN ====`);
     console.error(stderr);
-    debugLog(`${name} process ==== STDERR END ====`);
+    errorLog(`${name} process ==== STDERR END ====`);
     writeLogs('Failure', name, stdout + '\n' + stderr);
-    debugLog('Completing with failure exit code 76');
+    errorLog('Completing with failure exit code 76');
     process.exit(76);
   }
 })();