From 2fb11b4cefdbfdf0172507d8e3a5f70f146691e1 Mon Sep 17 00:00:00 2001 From: Denver Coneybeare Date: Fri, 10 Mar 2023 11:11:48 -0500 Subject: [PATCH 01/10] verify the document ids in the resumed snapshot, not just the size --- .../test/integration/api/query.test.ts | 61 ++++++++++++------- .../integration/util/testing_hooks_util.ts | 11 ++-- 2 files changed, 45 insertions(+), 27 deletions(-) diff --git a/packages/firestore/test/integration/api/query.test.ts b/packages/firestore/test/integration/api/query.test.ts index cc01b5fa977..6fc24d48cba 100644 --- a/packages/firestore/test/integration/api/query.test.ts +++ b/packages/firestore/test/integration/api/query.test.ts @@ -33,6 +33,7 @@ import { DocumentChange, DocumentChangeType, documentId, + DocumentReference, enableNetwork, endAt, endBefore, @@ -2065,10 +2066,10 @@ apiDescribe('Queries', (persistence: boolean) => { }); it('resuming a query should use bloom filter to avoid full requery', async () => { - // Create 100 documents in a new collection. + // Prepare the names and contents of the 100 documents to create. const testDocs: { [key: string]: object } = {}; - for (let i = 1; i <= 100; i++) { - testDocs['doc' + i] = { key: i }; + for (let i = 0; i < 100; i++) { + testDocs['doc' + (1000 + i)] = { key: 42 }; } // The function that runs a single iteration of the test. @@ -2082,12 +2083,16 @@ apiDescribe('Queries', (persistence: boolean) => { // and a resume token. const snapshot1 = await getDocs(coll); expect(snapshot1.size, 'snapshot1.size').to.equal(100); + const createdDocuments = snapshot1.docs.map(snapshot => snapshot.ref); // Delete 50 of the 100 documents. Do this in a transaction, rather // than deleteDoc(), to avoid affecting the local cache. + const deletedDocumentIds = new Set(); await runTransaction(db, async txn => { - for (let i = 1; i <= 50; i++) { - txn.delete(doc(coll, 'doc' + i)); + for (let i = 0; i < createdDocuments.length; i += 2) { + const documentToDelete = createdDocuments[i]; + txn.delete(documentToDelete); + deletedDocumentIds.add(documentToDelete.id); } }); @@ -2096,23 +2101,35 @@ apiDescribe('Queries', (persistence: boolean) => { // events when the query is resumed. await new Promise(resolve => setTimeout(resolve, 10000)); - // Resume the query and expect to get a snapshot with the 50 - // remaining documents. Use some internal testing hooks to "capture" - // the existence filter mismatches to later verify that Watch sent a - // bloom filter, and it was used to avert a full requery. - const existenceFilterMismatches = await captureExistenceFilterMismatches( - async () => { - const snapshot2 = await getDocs(coll); - // TODO(b/270731363): Remove the "if" condition below once the - // Firestore Emulator is fixed to send an existence filter. At the - // time of writing, the Firestore emulator fails to send an - // existence filter, resulting in the client including the deleted - // documents in the snapshot of the resumed query. - if (!(USE_EMULATOR && snapshot2.size === 100)) { - expect(snapshot2.size, 'snapshot2.size').to.equal(50); - } - } - ); + // Resume the query and save the resulting snapshot for verification. + // Use some internal testing hooks to "capture" the existence filter + // mismatches to verify that Watch sent a bloom filter, and it was used to + // avert a full requery. + const [existenceFilterMismatches, snapshot2] = + await captureExistenceFilterMismatches(async () => { + return await getDocs(coll); + }); + + // Verify that the snapshot from the resumed query contains the expected + // documents; that is, that it contains the 50 documents that were _not_ + // deleted. + // TODO(b/270731363): Remove the "if" condition below once the + // Firestore Emulator is fixed to send an existence filter. At the + // time of writing, the Firestore emulator fails to send an + // existence filter, resulting in the client including the deleted + // documents in the snapshot of the resumed query. + if (!(USE_EMULATOR && snapshot2.size === 100)) { + const actualDocumentIds = snapshot2.docs + .map(documentSnapshot => documentSnapshot.ref.id) + .sort(); + const expectedDocumentIds = createdDocuments + .filter(documentRef => !deletedDocumentIds.has(documentRef.id)) + .map(documentRef => documentRef.id) + .sort(); + expect(actualDocumentIds, 'snapshot2.docs').to.deep.equal( + expectedDocumentIds + ); + } // Skip the verification of the existence filter mismatch when // persistence is disabled because without persistence there is no diff --git a/packages/firestore/test/integration/util/testing_hooks_util.ts b/packages/firestore/test/integration/util/testing_hooks_util.ts index d66a19d7ce9..d5bda1be660 100644 --- a/packages/firestore/test/integration/util/testing_hooks_util.ts +++ b/packages/firestore/test/integration/util/testing_hooks_util.ts @@ -24,9 +24,9 @@ import { _TestingHooks as TestingHooks } from './firebase_export'; * callback all existence filter mismatches will be captured. * @return the captured existence filter mismatches. */ -export async function captureExistenceFilterMismatches( - callback: () => Promise -): Promise { +export async function captureExistenceFilterMismatches( + callback: () => Promise +): Promise<[ExistenceFilterMismatchInfo[], T]> { const results: ExistenceFilterMismatchInfo[] = []; const onExistenceFilterMismatchCallback = ( info: ExistenceFilterMismatchInfo @@ -39,13 +39,14 @@ export async function captureExistenceFilterMismatches( onExistenceFilterMismatchCallback ); + let callbackResult: T; try { - await callback(); + callbackResult = await callback(); } finally { unregister(); } - return results; + return [results, callbackResult]; } /** From e532ddb77c04b30a8df08ad4ac3aa89b41bdc93b Mon Sep 17 00:00:00 2001 From: Denver Coneybeare Date: Fri, 10 Mar 2023 12:09:49 -0500 Subject: [PATCH 02/10] more cleanup --- .../test/integration/api/query.test.ts | 132 +++++++++--------- 1 file changed, 69 insertions(+), 63 deletions(-) diff --git a/packages/firestore/test/integration/api/query.test.ts b/packages/firestore/test/integration/api/query.test.ts index 6fc24d48cba..2b6521a276d 100644 --- a/packages/firestore/test/integration/api/query.test.ts +++ b/packages/firestore/test/integration/api/query.test.ts @@ -2073,20 +2073,20 @@ apiDescribe('Queries', (persistence: boolean) => { } // The function that runs a single iteration of the test. - // Below this definition, there is a "while" loop that calls this - // function potentially multiple times. + // Below this definition, there is a "while" loop that calls this function + // potentially multiple times. const runTestIteration = async ( coll: CollectionReference, db: Firestore ): Promise<'retry' | 'passed'> => { - // Run a query to populate the local cache with the 100 documents - // and a resume token. + // Run a query to populate the local cache with the 100 documents and a + // resume token. const snapshot1 = await getDocs(coll); expect(snapshot1.size, 'snapshot1.size').to.equal(100); const createdDocuments = snapshot1.docs.map(snapshot => snapshot.ref); - // Delete 50 of the 100 documents. Do this in a transaction, rather - // than deleteDoc(), to avoid affecting the local cache. + // Delete 50 of the 100 documents. Do this in a transaction, rather than + // deleteDoc(), to avoid affecting the local cache. const deletedDocumentIds = new Set(); await runTransaction(db, async txn => { for (let i = 0; i < createdDocuments.length; i += 2) { @@ -2096,9 +2096,9 @@ apiDescribe('Queries', (persistence: boolean) => { } }); - // Wait for 10 seconds, during which Watch will stop tracking the - // query and will send an existence filter rather than "delete" - // events when the query is resumed. + // Wait for 10 seconds, during which Watch will stop tracking the query + // and will send an existence filter rather than "delete" events when the + // query is resumed. await new Promise(resolve => setTimeout(resolve, 10000)); // Resume the query and save the resulting snapshot for verification. @@ -2114,10 +2114,10 @@ apiDescribe('Queries', (persistence: boolean) => { // documents; that is, that it contains the 50 documents that were _not_ // deleted. // TODO(b/270731363): Remove the "if" condition below once the - // Firestore Emulator is fixed to send an existence filter. At the - // time of writing, the Firestore emulator fails to send an - // existence filter, resulting in the client including the deleted - // documents in the snapshot of the resumed query. + // Firestore Emulator is fixed to send an existence filter. At the time of + // writing, the Firestore emulator fails to send an existence filter, + // resulting in the client including the deleted documents in the snapshot + // of the resumed query. if (!(USE_EMULATOR && snapshot2.size === 100)) { const actualDocumentIds = snapshot2.docs .map(documentSnapshot => documentSnapshot.ref.id) @@ -2131,66 +2131,72 @@ apiDescribe('Queries', (persistence: boolean) => { ); } - // Skip the verification of the existence filter mismatch when - // persistence is disabled because without persistence there is no - // resume token specified in the subsequent call to getDocs(), and, - // therefore, Watch will _not_ send an existence filter. + // Skip the verification of the existence filter mismatch when persistence + // is disabled because without persistence there is no resume token + // specified in the subsequent call to getDocs(), and, therefore, Watch + // will _not_ send an existence filter. if (!persistence) { return 'passed'; } - // Skip the verification of the existence filter mismatch when - // testing against the Firestore emulator because the Firestore - // emulator does not include the `unchanged_names` bloom filter when - // it sends ExistenceFilter messages. Some day the emulator _may_ - // implement this logic, at which time this short-circuit can be - // removed. + // Skip the verification of the existence filter mismatch when testing + // against the Firestore emulator because the Firestore emulator does not + // include the `unchanged_names` bloom filter when it sends + // ExistenceFilter messages. Some day the emulator _may_ implement this + // logic, at which time this short-circuit can be removed. if (USE_EMULATOR) { return 'passed'; } - // Verify that upon resuming the query that Watch sent an existence - // filter that included a bloom filter, and that the bloom filter - // was successfully used to avoid a full requery. - // TODO(b/271949433) Remove this check for "nightly" once the bloom - // filter logic is deployed to production, circa May 2023. - if (TARGET_BACKEND === 'nightly') { - expect( - existenceFilterMismatches, - 'existenceFilterMismatches' - ).to.have.length(1); - const { localCacheCount, existenceFilterCount, bloomFilter } = - existenceFilterMismatches[0]; - - expect(localCacheCount, 'localCacheCount').to.equal(100); - expect(existenceFilterCount, 'existenceFilterCount').to.equal(50); - if (!bloomFilter) { - expect.fail( - 'The existence filter should have specified ' + - 'a bloom filter in its `unchanged_names` field.' - ); - throw new Error('should never get here'); - } + // Verify that Watch sent an existence filter with the correct counts when + // the query was resumed. + expect( + existenceFilterMismatches, + 'existenceFilterMismatches' + ).to.have.length(1); + const { localCacheCount, existenceFilterCount, bloomFilter } = + existenceFilterMismatches[0]; + expect(localCacheCount, 'localCacheCount').to.equal(100); + expect(existenceFilterCount, 'existenceFilterCount').to.equal(50); + + // Skip the verification of the bloom filter when testing against + // production because the bloom filter is only implemented in nightly. + // TODO(b/271949433) Remove this "if" block once the bloom filter logic is + // deployed to production. + if (TARGET_BACKEND !== 'nightly') { + return 'passed'; + } - expect(bloomFilter.hashCount, 'bloomFilter.hashCount').to.be.above(0); - expect( - bloomFilter.bitmapLength, - 'bloomFilter.bitmapLength' - ).to.be.above(0); - expect(bloomFilter.padding, 'bloomFilterPadding').to.be.above(0); - expect(bloomFilter.padding, 'bloomFilterPadding').to.be.below(8); - - // Retry the entire test if a bloom filter false positive occurs. - // Although statistically rare, false positives are expected to - // happen occasionally. When a false positive _does_ happen, just - // retry the test with a different set of documents. If that retry - // _also_ experiences a false positive, then fail the test because - // that is so improbable that something must have gone wrong. - if (attemptNumber > 1 && !bloomFilter.applied) { - return 'retry'; - } - expect(bloomFilter.applied, 'bloomFilter.applied').to.be.true; + // Verify that Watch sent a valid bloom filter. + if (!bloomFilter) { + expect.fail( + 'The existence filter should have specified a bloom filter in its ' + + '`unchanged_names` field.' + ); + throw new Error('should never get here'); + } + + expect(bloomFilter.hashCount, 'bloomFilter.hashCount').to.be.above(0); + expect(bloomFilter.bitmapLength, 'bloomFilter.bitmapLength').to.be.above( + 0 + ); + expect(bloomFilter.padding, 'bloomFilterPadding').to.be.above(0); + expect(bloomFilter.padding, 'bloomFilterPadding').to.be.below(8); + + // Verify that the bloom filter was successfully used to avert a full + // request. If a false positive occurred then retry the entire test. + // Although statistically rare, false positives are expected to happen + // occasionally. When a false positive _does_ happen, just retry the test + // with a different set of documents. If that retry _also_ experiences a + // false positive, then fail the test because that is so improbable that + // something must have gone wrong. + if (attemptNumber > 1 && !bloomFilter.applied) { + return 'retry'; } + expect( + bloomFilter.applied, + `bloomFilter.applied with attemptNumber=${attemptNumber}` + ).to.be.true; return 'passed'; }; From e43ebce5e8b270c2dd592d4a1f7c6b31b811ec6d Mon Sep 17 00:00:00 2001 From: Denver Coneybeare Date: Fri, 10 Mar 2023 12:17:01 -0500 Subject: [PATCH 03/10] Add TODO(b/272754156) Re-write this test using a snapshot listener --- packages/firestore/test/integration/api/query.test.ts | 2 ++ 1 file changed, 2 insertions(+) diff --git a/packages/firestore/test/integration/api/query.test.ts b/packages/firestore/test/integration/api/query.test.ts index 2b6521a276d..ebaffa7d977 100644 --- a/packages/firestore/test/integration/api/query.test.ts +++ b/packages/firestore/test/integration/api/query.test.ts @@ -2135,6 +2135,8 @@ apiDescribe('Queries', (persistence: boolean) => { // is disabled because without persistence there is no resume token // specified in the subsequent call to getDocs(), and, therefore, Watch // will _not_ send an existence filter. + // TODO(b/272754156) Re-write this test using a snapshot listener instead + // of calls to getDocs() and remove this check for disabled persistence. if (!persistence) { return 'passed'; } From 05dd0d68cdaf3afba14eec27faf9750c0f8efa2b Mon Sep 17 00:00:00 2001 From: Denver Coneybeare Date: Fri, 10 Mar 2023 14:02:28 -0500 Subject: [PATCH 04/10] fix retry logic --- packages/firestore/test/integration/api/query.test.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/packages/firestore/test/integration/api/query.test.ts b/packages/firestore/test/integration/api/query.test.ts index ebaffa7d977..58b97049378 100644 --- a/packages/firestore/test/integration/api/query.test.ts +++ b/packages/firestore/test/integration/api/query.test.ts @@ -2186,13 +2186,13 @@ apiDescribe('Queries', (persistence: boolean) => { expect(bloomFilter.padding, 'bloomFilterPadding').to.be.below(8); // Verify that the bloom filter was successfully used to avert a full - // request. If a false positive occurred then retry the entire test. + // requery. If a false positive occurred then retry the entire test. // Although statistically rare, false positives are expected to happen // occasionally. When a false positive _does_ happen, just retry the test // with a different set of documents. If that retry _also_ experiences a // false positive, then fail the test because that is so improbable that // something must have gone wrong. - if (attemptNumber > 1 && !bloomFilter.applied) { + if (attemptNumber === 1 && !bloomFilter.applied) { return 'retry'; } expect( From 44b8cd1a1a49d677fc63b318462a2d308ebdd44f Mon Sep 17 00:00:00 2001 From: Denver Coneybeare Date: Fri, 10 Mar 2023 14:13:08 -0500 Subject: [PATCH 05/10] use WriteBatch instead of creating documents individually --- .../test/integration/util/helpers.ts | 37 ++++++++++++++++--- 1 file changed, 31 insertions(+), 6 deletions(-) diff --git a/packages/firestore/test/integration/util/helpers.ts b/packages/firestore/test/integration/util/helpers.ts index b70a116e839..9bc124dc7e7 100644 --- a/packages/firestore/test/integration/util/helpers.ts +++ b/packages/firestore/test/integration/util/helpers.ts @@ -32,7 +32,9 @@ import { PrivateSettings, SnapshotListenOptions, newTestFirestore, - newTestApp + newTestApp, + writeBatch, + WriteBatch } from './firebase_export'; import { ALT_PROJECT_ID, @@ -315,11 +317,34 @@ export function withTestCollectionSettings( const collectionId = 'test-collection-' + doc(collection(testDb, 'x')).id; const testCollection = collection(testDb, collectionId); const setupCollection = collection(setupDb, collectionId); - const sets: Array> = []; - Object.keys(docs).forEach(key => { - sets.push(setDoc(doc(setupCollection, key), docs[key])); - }); - return Promise.all(sets).then(() => fn(testCollection, testDb)); + + const writeBatchCommits: Array> = []; + let writeBatch_: WriteBatch | null = null; + let writeBatchSize = 0; + + for (const key in docs) { + if (writeBatch_ === null) { + writeBatch_ = writeBatch(setupDb); + } + + writeBatch_.set(doc(setupCollection, key), docs[key]); + writeBatchSize++; + + // Write batches are capped at 500 writes. Use 400 just to be safe. + if (writeBatchSize === 400) { + writeBatchCommits.push(writeBatch_.commit()); + writeBatch_ = null; + writeBatchSize = 0; + } + } + + if (writeBatch_ !== null) { + writeBatchCommits.push(writeBatch_.commit()); + } + + return Promise.all(writeBatchCommits).then(() => + fn(testCollection, testDb) + ); } ); } From ac5b3c593dd7283005542f81f4abf9a121ae1bc2 Mon Sep 17 00:00:00 2001 From: Denver Coneybeare Date: Fri, 10 Mar 2023 14:51:20 -0500 Subject: [PATCH 06/10] query.test.ts: remove unused import: DocumentReference --- packages/firestore/test/integration/api/query.test.ts | 1 - 1 file changed, 1 deletion(-) diff --git a/packages/firestore/test/integration/api/query.test.ts b/packages/firestore/test/integration/api/query.test.ts index 58b97049378..58b0beeda1e 100644 --- a/packages/firestore/test/integration/api/query.test.ts +++ b/packages/firestore/test/integration/api/query.test.ts @@ -33,7 +33,6 @@ import { DocumentChange, DocumentChangeType, documentId, - DocumentReference, enableNetwork, endAt, endBefore, From 51b3a44eab0d44969cdc0d80fe99377a213d93a6 Mon Sep 17 00:00:00 2001 From: Denver Coneybeare Date: Fri, 10 Mar 2023 14:52:16 -0500 Subject: [PATCH 07/10] query.test.ts: remove 'return await' idiom, as suggested by eslint: https://eslint.org/docs/latest/rules/no-return-await --- packages/firestore/test/integration/api/query.test.ts | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/packages/firestore/test/integration/api/query.test.ts b/packages/firestore/test/integration/api/query.test.ts index 58b0beeda1e..d2a1e08d4c6 100644 --- a/packages/firestore/test/integration/api/query.test.ts +++ b/packages/firestore/test/integration/api/query.test.ts @@ -2105,9 +2105,7 @@ apiDescribe('Queries', (persistence: boolean) => { // mismatches to verify that Watch sent a bloom filter, and it was used to // avert a full requery. const [existenceFilterMismatches, snapshot2] = - await captureExistenceFilterMismatches(async () => { - return await getDocs(coll); - }); + await captureExistenceFilterMismatches(() => getDocs(coll)); // Verify that the snapshot from the resumed query contains the expected // documents; that is, that it contains the 50 documents that were _not_ From 3bccef6df0a738c19158ce4079167d97e949e15c Mon Sep 17 00:00:00 2001 From: Denver Coneybeare Date: Fri, 10 Mar 2023 14:52:52 -0500 Subject: [PATCH 08/10] helpers.ts: for (const key in docs) -> for (const key of Object.keys(docs)) to fix the lint error: https://eslint.org/docs/latest/rules/guard-for-in --- 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 9bc124dc7e7..3e0f34ec302 100644 --- a/packages/firestore/test/integration/util/helpers.ts +++ b/packages/firestore/test/integration/util/helpers.ts @@ -322,7 +322,7 @@ export function withTestCollectionSettings( let writeBatch_: WriteBatch | null = null; let writeBatchSize = 0; - for (const key in docs) { + for (const key of Object.keys(docs)) { if (writeBatch_ === null) { writeBatch_ = writeBatch(setupDb); } From b224a4fd2996f8701aafa09b888c6ad5c52c9b4b Mon Sep 17 00:00:00 2001 From: Denver Coneybeare Date: Fri, 10 Mar 2023 22:24:26 -0500 Subject: [PATCH 09/10] REVERT ME: Add some extra logging to help diagnose github actions failure (patched in from https://github.com/firebase/firebase-js-sdk/pull/7088) --- package.json | 4 +- packages/firestore/package.json | 4 +- packages/firestore/scripts/run-tests.ts | 83 ++++++++++++++++++++++++- scripts/ci-test/test_changed.ts | 69 +++++++++++++++++++- scripts/run_tests_in_ci.js | 81 ++++++++++++++++++++++-- 5 files changed, 229 insertions(+), 12 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", 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/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); } })(); From 3b60c56700e3efa035542f3ff58c04f39bb330f0 Mon Sep 17 00:00:00 2001 From: Denver Coneybeare Date: Fri, 10 Mar 2023 23:38:30 -0500 Subject: [PATCH 10/10] Revert "REVERT ME: Add some extra logging to help diagnose github actions failure (patched in from https://github.com/firebase/firebase-js-sdk/pull/7088)" 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 b224a4fd2996f8701aafa09b888c6ad5c52c9b4b. --- package.json | 4 +- packages/firestore/package.json | 4 +- packages/firestore/scripts/run-tests.ts | 83 +------------------------ scripts/ci-test/test_changed.ts | 69 +------------------- scripts/run_tests_in_ci.js | 81 ++---------------------- 5 files changed, 12 insertions(+), 229 deletions(-) diff --git a/package.json b/package.json index b04622d5af1..4ab7309f129 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 --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 index dbc9ab59800..7f83d260f40 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-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 index d13f91a01f0..a3b94aa9eae 100644 --- 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 index 2546295589c..5d2f30865ed 100644 --- 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 index 609eb919180..fdced9cb70f 100644 --- 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); } })();