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", diff --git a/packages/firestore/package.json b/packages/firestore/package.json index 7f83d260f40..dbc9ab59800 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", diff --git a/packages/firestore/scripts/run-tests.ts b/packages/firestore/scripts/run-tests.ts index a3b94aa9eae..d13f91a01f0 100644 --- a/packages/firestore/scripts/run-tests.ts +++ b/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'); +}); diff --git a/packages/firestore/test/integration/util/helpers.ts b/packages/firestore/test/integration/util/helpers.ts index b70a116e839..ec42fb4ff08 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)); } } diff --git a/scripts/ci-test/test_changed.ts b/scripts/ci-test/test_changed.ts index 5d2f30865ed..2546295589c 100644 --- a/scripts/ci-test/test_changed.ts +++ b/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); } } diff --git a/scripts/run_tests_in_ci.js b/scripts/run_tests_in_ci.js index fdced9cb70f..609eb919180 100644 --- a/scripts/run_tests_in_ci.js +++ b/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); } })();