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

Author: dconeybe

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",

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",

packages/firestore/scripts/run-tests.ts

@@ -20,6 +20,70 @@ 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',
@@ -58,21 +122,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.join(' ')}`);
+
 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', () => {
+  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');
+});

scripts/ci-test/test_changed.ts

@@ -23,6 +23,69 @@ 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';
@@ -76,10 +139,14 @@ 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}}`);
-    process.exit(1);
+    errorLog('terminating with exit code 65');
+    process.exit(65);
   }
 }

scripts/run_tests_in_ci.js

@@ -20,6 +20,69 @@ 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.
@@ -69,7 +132,10 @@ const argv = yargs.options({
         }
       }
     }
-    const testProcess = spawn('yarn', ['--cwd', dir, scriptName]);
+
+    const yarnArgs = ['--cwd', dir, scriptName];
+    debugLog(`spawning '${name}' process: yarn ${yarnArgs.join(' ')}`);
+    const testProcess = spawn('yarn', yarnArgs);
 
     testProcess.childProcess.stdout.on('data', data => {
       stdout += data.toString();
@@ -79,13 +145,20 @@ const argv = yargs.options({
     });
 
     await testProcess;
-    console.log('Success: ' + name);
+    debugLog(
+      `'${name}' process completed successfully: yarn ${yarnArgs.join(' ')}`
+    );
     writeLogs('Success', name, stdout + '\n' + stderr);
   } catch (e) {
-    console.error('Failure: ' + name);
+    errorLog(`${name} process FAILED`);
+    errorLog(`${name} process ==== STDOUT BEGIN ====`);
     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);
-    process.exit(1);
+    errorLog('Completing with failure exit code 76');
+    process.exit(76);
   }
 })();