Revert "REVERT ME: Add some extra logging to help diagnose github actions failure (patched in from #7088)"

dconeybe · dconeybe · commit 3b60c56700e3 · 2023-03-10T23:38:30.000-05:00
The tests all passed with this patch. It would seem that running tests in parallel is problematic. Try to revert this commit and see if we get lucky. This reverts commit b224a4f.
diff --git 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 --stream test",
-    "test:ci": "lerna run --ignore firebase-messaging-integration-test test:ci",
+    "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",
     "pretest:coverage": "mkdirp coverage",
     "ci:coverage": "lcov-result-merger 'packages/**/lcov.info' 'lcov-all.info'",
     "test:coverage": "lcov-result-merger 'packages/**/lcov.info' | coveralls",
diff --git 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-s test:browser test:lite:browser test:travis",
-    "test:all": "run-s test:browser test:lite:browser test:travis test:minified",
+    "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:browser": "karma start --single-run",
     "test:browser:emulator:debug": "karma start --browsers=Chrome --targetBackend=emulator",
     "test:browser:emulator": "karma start --single-run --targetBackend=emulator",
diff --git a/packages/firestore/scripts/run-tests.ts b/packages/firestore/scripts/run-tests.ts
@@ -20,70 +20,6 @@ import { resolve } from 'path';
 import { spawn } from 'child-process-promise';
 import * as yargs from 'yargs';
 
-
-/**
- * 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, 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)
-  );
-}
-
-/**
- * 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 {
-  const currentTimeMilliseconds = getCurrentMonotonicTimeMilliseconds();
-  if (elapsedMillisecondsStartTime === null) {
-    elapsedMillisecondsStartTime = currentTimeMilliseconds;
-    return 0;
-  }
-  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.join(' ')}`);
-
 const argv = yargs.options({
   main: {
     type: 'string',
@@ -122,34 +58,21 @@ 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.join(' ')}`);
-
 const childProcess = spawn(nyc, args, {
   stdio: 'inherit',
   cwd: process.cwd()
 }).childProcess;
 
-process.once('exit', () => {
-  errorLog("WARNING: received 'exit' event; killing child process");
-  childProcess.kill();
-});
-process.once('SIGINT', () => {
-  errorLog("WARNING: received 'SIGINT' event; sending it to child process");
-  childProcess.kill('SIGINT');
-});
-process.once('SIGTERM', () => {
-  errorLog("WARNING: received 'SIGTERM' event; sending it to child process");
-  childProcess.kill('SIGTERM');
-});
+process.once('exit', () => childProcess.kill());
+process.once('SIGINT', () => childProcess.kill('SIGINT'));
+process.once('SIGTERM', () => childProcess.kill('SIGTERM'));
diff --git a/scripts/ci-test/test_changed.ts b/scripts/ci-test/test_changed.ts
@@ -23,69 +23,6 @@ import * as yargs from 'yargs';
 import { TestConfig, testConfig } from './testConfig';
 const root = resolve(__dirname, '../..');
 
-/**
- * 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, 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)
-  );
-}
-
-/**
- * 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 milliseconds that have elapsed since this function's
- * first invocation. Returns 0 on its first invocation.
- */
-function getElapsedMilliseconds(): number {
-  const currentTimeMilliseconds = getCurrentMonotonicTimeMilliseconds();
-  if (elapsedMillisecondsStartTime === null) {
-    elapsedMillisecondsStartTime = currentTimeMilliseconds;
-    return 0;
-  }
-  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.join(' ')}`);
-
 const argv = yargs.parseSync();
 const inputTestConfigName = argv._[0].toString();
 const testCommand = 'test:ci';
@@ -139,14 +76,10 @@ async function runTests(config: TestConfig) {
     }
 
     lernaCmd.push(testCommand);
-    debugLog(`spawning process: npx ${lernaCmd.join(' ')}`);
     await spawn('npx', lernaCmd, { stdio: 'inherit', cwd: root });
-    debugLog(`process completed successfully: npx ${lernaCmd.join(' ')}`);
     process.exit(0);
   } catch (e) {
-    errorLog('process failed');
     console.error(chalk`{red ${e}}`);
-    errorLog('terminating with exit code 65');
-    process.exit(65);
+    process.exit(1);
   }
 }
diff --git a/scripts/run_tests_in_ci.js b/scripts/run_tests_in_ci.js
@@ -20,69 +20,6 @@ const path = require('path');
 const { spawn } = require('child-process-promise');
 const { writeFileSync } = require('fs');
 
-/**
- * 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, created from
- * the elapsed time since this function's first invocation.
- */
-function elapsedTimeStr() {
-  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)
-  );
-}
-
-/**
- * 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() {
-  const currentTimeMilliseconds = getCurrentMonotonicTimeMilliseconds();
-  if (elapsedMillisecondsStartTime === null) {
-    elapsedMillisecondsStartTime = currentTimeMilliseconds;
-    return 0;
-  }
-  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.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.
 // TODO(dwyfrequency): Update object with `storage` and `firestore` packages.
@@ -132,10 +69,7 @@ const argv = yargs.options({
         }
       }
     }
-
-    const yarnArgs = ['--cwd', dir, scriptName];
-    debugLog(`spawning '${name}' process: yarn ${yarnArgs.join(' ')}`);
-    const testProcess = spawn('yarn', yarnArgs);
+    const testProcess = spawn('yarn', ['--cwd', dir, scriptName]);
 
     testProcess.childProcess.stdout.on('data', data => {
       stdout += data.toString();
@@ -145,20 +79,13 @@ const argv = yargs.options({
     });
 
     await testProcess;
-    debugLog(
-      `'${name}' process completed successfully: yarn ${yarnArgs.join(' ')}`
-    );
+    console.log('Success: ' + name);
     writeLogs('Success', name, stdout + '\n' + stderr);
   } catch (e) {
-    errorLog(`${name} process FAILED`);
-    errorLog(`${name} process ==== STDOUT BEGIN ====`);
+    console.error('Failure: ' + name);
     console.log(stdout);
-    errorLog(`${name} process ==== STDOUT END ====`);
-    errorLog(`${name} process ==== STDERR BEGIN ====`);
     console.error(stderr);
-    errorLog(`${name} process ==== STDERR END ====`);
     writeLogs('Failure', name, stdout + '\n' + stderr);
-    errorLog('Completing with failure exit code 76');
-    process.exit(76);
+    process.exit(1);
   }
 })();
