diff --git a/packages/firestore/src/api.ts b/packages/firestore/src/api.ts index d05f032a910..8af8fbd0a56 100644 --- a/packages/firestore/src/api.ts +++ b/packages/firestore/src/api.ts @@ -238,7 +238,11 @@ export { debugAssert as _debugAssert } from './util/assert'; export { FieldPath as _FieldPath } from './model/path'; export type { ResourcePath as _ResourcePath } from './model/path'; export { ByteString as _ByteString } from './util/byte_string'; -export { logWarn as _logWarn } from './util/log'; +export { + logWarn as _logWarn, + enableLogBuffer as _enableLogBuffer, + dumpLogBuffer as _dumpLogBuffer +} from './util/log'; export { AutoId as _AutoId } from './util/misc'; export type { AuthTokenFactory, diff --git a/packages/firestore/src/api/database.ts b/packages/firestore/src/api/database.ts index a2feb19507f..e8be9d57fc0 100644 --- a/packages/firestore/src/api/database.ts +++ b/packages/firestore/src/api/database.ts @@ -61,9 +61,10 @@ import { LRU_MINIMUM_CACHE_SIZE_BYTES } from '../local/lru_garbage_collector_imp import { debugAssert } from '../util/assert'; import { AsyncQueue } from '../util/async_queue'; import { AsyncQueueImpl } from '../util/async_queue_impl'; +import { generateUniqueDebugId } from '../util/debug_uid'; import { Code, FirestoreError } from '../util/error'; import { cast } from '../util/input_validation'; -import { logWarn } from '../util/log'; +import { logDebug, logWarn } from '../util/log'; import { Deferred } from '../util/promise'; import { LoadBundleTask } from './bundle'; @@ -94,6 +95,7 @@ export const CACHE_SIZE_UNLIMITED = LRU_COLLECTION_DISABLED; * Do not call this constructor directly. Instead, use {@link (getFirestore:1)}. */ export class Firestore extends LiteFirestore { + readonly _debugId = `Firestore@${generateUniqueDebugId()}`; /** * Whether it's a {@link Firestore} or Firestore Lite instance. */ @@ -204,10 +206,20 @@ export function initializeFirestore( void pingServer(settings.host); } - return provider.initialize({ + const db = provider.initialize({ options: settings, instanceIdentifier: databaseId }); + + logDebug( + `initializeFirestore(` + + `app.name=${app.name ?? 'undefined'}, databaseId=${ + databaseId ?? 'undefined' + }` + + `) returns ${db._debugId}` + ); + + return db; } /** @@ -269,6 +281,15 @@ export function getFirestore( connectFirestoreEmulator(db, ...emulator); } } + + logDebug( + `getFirestore(` + + `app.name=${app.name ?? 'undefined'}, databaseId=${ + databaseId ?? 'undefined' + }` + + `) returns ${db._debugId}` + ); + return db; } @@ -323,6 +344,7 @@ export function configureFirestore(firestore: Firestore): void { firestore._componentsProvider && buildComponentProvider(firestore._componentsProvider) ); + logDebug(`${firestore._firestoreClient} created by ${firestore._debugId}`); } function buildComponentProvider(componentsProvider: { @@ -500,6 +522,8 @@ export function clearIndexedDbPersistence(firestore: Firestore): Promise { ); } + logDebug(firestore._debugId, 'clearIndexedDbPersistence()'); + const deferred = new Deferred(); firestore._queue.enqueueAndForgetEvenWhileRestricted(async () => { try { @@ -531,6 +555,7 @@ export function clearIndexedDbPersistence(firestore: Firestore): Promise { * acknowledged by the backend. */ export function waitForPendingWrites(firestore: Firestore): Promise { + logDebug(firestore._debugId, 'waitForPendingWrites()'); firestore = cast(firestore, Firestore); const client = ensureFirestoreConfigured(firestore); return firestoreClientWaitForPendingWrites(client); @@ -543,6 +568,7 @@ export function waitForPendingWrites(firestore: Firestore): Promise { * @returns A `Promise` that is resolved once the network has been enabled. */ export function enableNetwork(firestore: Firestore): Promise { + logDebug(firestore._debugId, 'enableNetwork()'); firestore = cast(firestore, Firestore); const client = ensureFirestoreConfigured(firestore); return firestoreClientEnableNetwork(client); @@ -557,6 +583,7 @@ export function enableNetwork(firestore: Firestore): Promise { * @returns A `Promise` that is resolved once the network has been disabled. */ export function disableNetwork(firestore: Firestore): Promise { + logDebug(firestore._debugId, 'disableNetwork()'); firestore = cast(firestore, Firestore); const client = ensureFirestoreConfigured(firestore); return firestoreClientDisableNetwork(client); @@ -585,6 +612,7 @@ export function disableNetwork(firestore: Firestore): Promise { * terminated. */ export function terminate(firestore: Firestore): Promise { + logDebug(firestore._debugId, 'terminate()'); _removeServiceInstance( firestore.app, 'firestore', @@ -608,6 +636,7 @@ export function loadBundle( firestore: Firestore, bundleData: ReadableStream | ArrayBuffer | string ): LoadBundleTask { + logDebug(firestore._debugId, 'loadBundle()'); firestore = cast(firestore, Firestore); const client = ensureFirestoreConfigured(firestore); const resultTask = new LoadBundleTask(); @@ -636,6 +665,7 @@ export function namedQuery( firestore: Firestore, name: string ): Promise { + logDebug(firestore._debugId, 'namedQuery() name:', name); firestore = cast(firestore, Firestore); const client = ensureFirestoreConfigured(firestore); return firestoreClientGetNamedQuery(client, name).then(namedQuery => { diff --git a/packages/firestore/src/core/component_provider.ts b/packages/firestore/src/core/component_provider.ts index 183a1046cc9..79e125a2a38 100644 --- a/packages/firestore/src/core/component_provider.ts +++ b/packages/firestore/src/core/component_provider.ts @@ -56,7 +56,9 @@ import { import { JsonProtoSerializer } from '../remote/serializer'; import { hardAssert } from '../util/assert'; import { AsyncQueue } from '../util/async_queue'; +import { generateUniqueDebugId } from '../util/debug_uid'; import { Code, FirestoreError } from '../util/error'; +import { logDebug } from '../util/log'; import { DatabaseInfo } from './database_info'; import { EventManager, newEventManager } from './event_manager'; @@ -78,6 +80,8 @@ import { OnlineStateSource } from './types'; type Kind = 'memory' | 'persistent'; export interface ComponentConfiguration { + readonly debugId: string; + asyncQueue: AsyncQueue; databaseInfo: DatabaseInfo; authCredentials: CredentialsProvider; @@ -96,6 +100,7 @@ export interface OfflineComponentProviderFactory { * cache. Implementations override `initialize()` to provide all components. */ export interface OfflineComponentProvider { + readonly debugId: string; readonly kind: Kind; persistence: Persistence; sharedClientState: SharedClientState; @@ -116,8 +121,13 @@ export interface OfflineComponentProvider { export class MemoryOfflineComponentProvider implements OfflineComponentProvider { + readonly debugId: string; kind: Kind = 'memory'; + constructor() { + this.debugId = `MemoryOfflineComponentProvider@${generateUniqueDebugId()}`; + } + static readonly provider: OfflineComponentProviderFactory = { build: () => new MemoryOfflineComponentProvider() }; @@ -171,7 +181,12 @@ export class MemoryOfflineComponentProvider } createPersistence(cfg: ComponentConfiguration): Persistence { - return new MemoryPersistence(MemoryEagerDelegate.factory, this.serializer); + const persistence = new MemoryPersistence( + MemoryEagerDelegate.factory, + this.serializer + ); + logDebug(`${persistence.debugId} created from ${this.debugId}`); + return persistence; } createSharedClientState(cfg: ComponentConfiguration): SharedClientState { @@ -222,6 +237,7 @@ export class LruGcMemoryOfflineComponentProvider extends MemoryOfflineComponentP * Provides all components needed for Firestore with IndexedDB persistence. */ export class IndexedDbOfflineComponentProvider extends MemoryOfflineComponentProvider { + readonly debugId: string; kind: Kind = 'persistent'; persistence!: IndexedDbPersistence; sharedClientState!: SharedClientState; @@ -236,6 +252,7 @@ export class IndexedDbOfflineComponentProvider extends MemoryOfflineComponentPro protected readonly forceOwnership: boolean | undefined ) { super(); + this.debugId = `IndexedDbOfflineComponentProvider@${generateUniqueDebugId()}`; } async initialize(cfg: ComponentConfiguration): Promise { @@ -301,7 +318,7 @@ export class IndexedDbOfflineComponentProvider extends MemoryOfflineComponentPro ? LruParams.withCacheSize(this.cacheSizeBytes) : LruParams.DEFAULT; - return new IndexedDbPersistence( + const persistence = new IndexedDbPersistence( this.synchronizeTabs, persistenceKey, cfg.clientId, @@ -313,6 +330,10 @@ export class IndexedDbOfflineComponentProvider extends MemoryOfflineComponentPro this.sharedClientState, !!this.forceOwnership ); + + logDebug(`${persistence.debugId} created from ${this.debugId}`); + + return persistence; } createSharedClientState(cfg: ComponentConfiguration): SharedClientState { @@ -467,6 +488,7 @@ export class OnlineComponentProvider { createDatastore(cfg: ComponentConfiguration): Datastore { const serializer = newSerializer(cfg.databaseInfo.databaseId); const connection = newConnection(cfg.databaseInfo); + logDebug(`${connection.debugId} created for ${cfg.debugId}`); return newDatastore( cfg.authCredentials, cfg.appCheckCredentials, diff --git a/packages/firestore/src/core/firestore_client.ts b/packages/firestore/src/core/firestore_client.ts index d04f37a3d7b..8b44889a9fc 100644 --- a/packages/firestore/src/core/firestore_client.ts +++ b/packages/firestore/src/core/firestore_client.ts @@ -56,6 +56,7 @@ import { AsyncQueue, wrapInUserErrorIfRecoverable } from '../util/async_queue'; import { BundleReader, BundleReaderSync } from '../util/bundle_reader'; import { newBundleReader } from '../util/bundle_reader_impl'; import { newBundleReaderSync } from '../util/bundle_reader_sync_impl'; +import { generateUniqueDebugId } from '../util/debug_uid'; import { Code, FirestoreError } from '../util/error'; import { logDebug, logWarn } from '../util/log'; import { AutoId } from '../util/misc'; @@ -98,7 +99,6 @@ import { TransactionRunner } from './transaction_runner'; import { View } from './view'; import { ViewSnapshot } from './view_snapshot'; -const LOG_TAG = 'FirestoreClient'; export const MAX_CONCURRENT_LIMBO_RESOLUTIONS = 100; /** DOMException error code constants. */ @@ -112,6 +112,8 @@ const DOM_EXCEPTION_QUOTA_EXCEEDED = 22; * async queue that is shared by all of the other components in the system. // */ export class FirestoreClient { + readonly debugId = `FirestoreClient@${generateUniqueDebugId()}`; + private user = User.UNAUTHENTICATED; private readonly clientId = AutoId.newId(); private authCredentialListener: CredentialChangeListener = () => @@ -148,18 +150,19 @@ export class FirestoreClient { ) { this._uninitializedComponentsProvider = componentProvider; this.authCredentials.start(asyncQueue, async user => { - logDebug(LOG_TAG, 'Received user=', user.uid); + logDebug(this.debugId, 'Received user=', user.uid); await this.authCredentialListener(user); this.user = user; }); this.appCheckCredentials.start(asyncQueue, newAppCheckToken => { - logDebug(LOG_TAG, 'Received new app check token=', newAppCheckToken); + logDebug(this.debugId, 'Received new app check token=', newAppCheckToken); return this.appCheckCredentialListener(newAppCheckToken, this.user); }); } get configuration(): ComponentConfiguration { return { + debugId: this.debugId, asyncQueue: this.asyncQueue, databaseInfo: this.databaseInfo, clientId: this.clientId, @@ -216,7 +219,7 @@ export async function setOfflineComponentProvider( ): Promise { client.asyncQueue.verifyOperationInProgress(); - logDebug(LOG_TAG, 'Initializing OfflineComponentProvider'); + logDebug(client.debugId, 'Initializing OfflineComponentProvider'); const configuration = client.configuration; await offlineComponentProvider.initialize(configuration); @@ -260,7 +263,7 @@ export async function setOnlineComponentProvider( const offlineComponents = await ensureOfflineComponents(client); - logDebug(LOG_TAG, 'Initializing OnlineComponentProvider'); + logDebug(client.debugId, 'Initializing OnlineComponentProvider'); await onlineComponentProvider.initialize( offlineComponents, client.configuration @@ -319,7 +322,7 @@ async function ensureOfflineComponents( ): Promise { if (!client._offlineComponents) { if (client._uninitializedComponentsProvider) { - logDebug(LOG_TAG, 'Using user provided OfflineComponentProvider'); + logDebug(client.debugId, 'Using user provided OfflineComponentProvider'); try { await setOfflineComponentProvider( client, @@ -341,12 +344,17 @@ async function ensureOfflineComponents( ); } } else { - logDebug(LOG_TAG, 'Using default OfflineComponentProvider'); + logDebug(client.debugId, 'Using default OfflineComponentProvider'); await setOfflineComponentProvider( client, new LruGcMemoryOfflineComponentProvider(undefined) ); } + logDebug( + `${client.debugId} using OfflineComponentProvider: ${ + client._offlineComponents!.debugId + }` + ); } return client._offlineComponents!; @@ -357,13 +365,13 @@ export async function ensureOnlineComponents( ): Promise { if (!client._onlineComponents) { if (client._uninitializedComponentsProvider) { - logDebug(LOG_TAG, 'Using user provided OnlineComponentProvider'); + logDebug(client.debugId, 'Using user provided OnlineComponentProvider'); await setOnlineComponentProvider( client, client._uninitializedComponentsProvider._online ); } else { - logDebug(LOG_TAG, 'Using default OnlineComponentProvider'); + logDebug(client.debugId, 'Using default OnlineComponentProvider'); await setOnlineComponentProvider(client, new OnlineComponentProvider()); } } diff --git a/packages/firestore/src/local/indexeddb_persistence.ts b/packages/firestore/src/local/indexeddb_persistence.ts index 0ec2baabfe4..35051e4b833 100644 --- a/packages/firestore/src/local/indexeddb_persistence.ts +++ b/packages/firestore/src/local/indexeddb_persistence.ts @@ -23,6 +23,7 @@ import { ListenSequence, SequenceNumberSyncer } from '../core/listen_sequence'; import { JsonProtoSerializer } from '../remote/serializer'; import { debugAssert } from '../util/assert'; import { AsyncQueue, DelayedOperation, TimerId } from '../util/async_queue'; +import { generateUniqueDebugId } from '../util/debug_uid'; import { Code, FirestoreError } from '../util/error'; import { logDebug, logError } from '../util/log'; import { DocumentLike, WindowLike } from '../util/types'; @@ -76,8 +77,6 @@ import { SimpleDbStore } from './simple_db'; -const LOG_TAG = 'IndexedDbPersistence'; - /** * Oldest acceptable age in milliseconds for client metadata before the client * is considered inactive and its associated data is garbage collected. @@ -167,6 +166,8 @@ export const MAIN_DATABASE = 'main'; * longer optional. */ export class IndexedDbPersistence implements Persistence { + readonly debugId = `IndexedDbPersistence@${generateUniqueDebugId()}`; + private simpleDb: SimpleDb; private listenSequence: ListenSequence | null = null; @@ -239,6 +240,7 @@ export class IndexedDbPersistence implements Persistence { this.schemaVersion, new SchemaConverter(this.serializer) ); + logDebug(`${this.simpleDb.debugId} created from ${this.debugId}`); this.globalsCache = new IndexedDbGlobalsCache(); this.targetCache = new IndexedDbTargetCache( this.referenceDelegate, @@ -252,7 +254,7 @@ export class IndexedDbPersistence implements Persistence { this.webStorage = null; if (forceOwningTab === false) { logError( - LOG_TAG, + this.debugId, 'LocalStorage is unavailable. As a result, persistence may not work ' + 'reliably. In particular enablePersistence() could fail immediately ' + 'after refreshing the page.' @@ -267,6 +269,7 @@ export class IndexedDbPersistence implements Persistence { * @returns Whether persistence was enabled. */ start(): Promise { + logDebug(this.debugId, 'start()'); debugAssert(!this.started, 'IndexedDbPersistence double-started!'); debugAssert(this.window !== null, "Expected 'window' to be defined"); @@ -356,6 +359,7 @@ export class IndexedDbPersistence implements Persistence { * PORTING NOTE: This is only used for Web multi-tab. */ setNetworkEnabled(networkEnabled: boolean): void { + logDebug(this.debugId, `setNetworkEnabled(${networkEnabled})`); if (this.networkEnabled !== networkEnabled) { this.networkEnabled = networkEnabled; // Schedule a primary lease refresh for immediate execution. The eventual @@ -413,7 +417,7 @@ export class IndexedDbPersistence implements Persistence { ) .catch(e => { if (isIndexedDbTransactionError(e)) { - logDebug(LOG_TAG, 'Failed to extend owner lease: ', e); + logDebug(this.debugId, 'Failed to extend owner lease: ', e); // Proceed with the existing state. Any subsequent access to // IndexedDB will verify the lease. return this.isPrimary; @@ -424,7 +428,7 @@ export class IndexedDbPersistence implements Persistence { } logDebug( - LOG_TAG, + this.debugId, 'Releasing owner lease after error during lease refresh', e ); @@ -637,7 +641,7 @@ export class IndexedDbPersistence implements Persistence { .next(canActAsPrimary => { if (this.isPrimary !== canActAsPrimary) { logDebug( - LOG_TAG, + this.debugId, `Client ${ canActAsPrimary ? 'is' : 'is not' } eligible for a primary lease.` @@ -648,6 +652,7 @@ export class IndexedDbPersistence implements Persistence { } async shutdown(): Promise { + logDebug(this.debugId, 'shutdown()'); // The shutdown() operations are idempotent and can be called even when // start() aborted (e.g. because it couldn't acquire the persistence lease). this._started = false; @@ -795,7 +800,7 @@ export class IndexedDbPersistence implements Persistence { transaction: PersistenceTransaction ) => PersistencePromise ): Promise { - logDebug(LOG_TAG, 'Starting transaction:', action); + logDebug(this.debugId, 'Starting transaction:', action); const simpleDbMode = mode === 'readonly' ? 'readonly' : 'readwrite'; const objectStores = getObjectStores(this.schemaVersion); @@ -919,7 +924,7 @@ export class IndexedDbPersistence implements Persistence { const store = primaryClientStore(txn); return store.get(DbPrimaryClientKey).next(primaryClient => { if (this.isLocalClient(primaryClient)) { - logDebug(LOG_TAG, 'Releasing primary lease.'); + logDebug(this.debugId, 'Releasing primary lease.'); return store.delete(DbPrimaryClientKey); } else { return PersistencePromise.resolve(); @@ -1044,7 +1049,7 @@ export class IndexedDbPersistence implements Persistence { this.zombiedClientLocalStorageKey(clientId) ) !== null; logDebug( - LOG_TAG, + this.debugId, `Client '${clientId}' ${ isZombied ? 'is' : 'is not' } zombied in LocalStorage` @@ -1052,7 +1057,7 @@ export class IndexedDbPersistence implements Persistence { return isZombied; } catch (e) { // Gracefully handle if LocalStorage isn't working. - logError(LOG_TAG, 'Failed to get zombied client id.', e); + logError(this.debugId, 'Failed to get zombied client id.', e); return false; } } diff --git a/packages/firestore/src/local/indexeddb_schema_converter.ts b/packages/firestore/src/local/indexeddb_schema_converter.ts index 1b84fa4f2c1..7817bb28ce6 100644 --- a/packages/firestore/src/local/indexeddb_schema_converter.ts +++ b/packages/firestore/src/local/indexeddb_schema_converter.ts @@ -128,7 +128,11 @@ import { import { MemoryCollectionParentIndex } from './memory_index_manager'; import { MemoryEagerDelegate, MemoryPersistence } from './memory_persistence'; import { PersistencePromise } from './persistence_promise'; -import { SimpleDbSchemaConverter, SimpleDbTransaction } from './simple_db'; +import { + IdbDatabaseDebugIdPair, + SimpleDbSchemaConverter, + SimpleDbTransaction +} from './simple_db'; /** Performs database creation and schema upgrades. */ export class SchemaConverter implements SimpleDbSchemaConverter { @@ -142,7 +146,7 @@ export class SchemaConverter implements SimpleDbSchemaConverter { * and local feature development. */ createOrUpgrade( - db: IDBDatabase, + idbDatabaseDebugIdPair: IdbDatabaseDebugIdPair, txn: IDBTransaction, fromVersion: number, toVersion: number @@ -154,7 +158,13 @@ export class SchemaConverter implements SimpleDbSchemaConverter { `Unexpected schema upgrade from v${fromVersion} to v${toVersion}.` ); - const simpleDbTransaction = new SimpleDbTransaction('createOrUpgrade', txn); + const { idbDatabase: db, debugId: dbDebugId } = idbDatabaseDebugIdPair; + + const simpleDbTransaction = new SimpleDbTransaction( + 'createOrUpgrade', + txn, + dbDebugId + ); if (fromVersion < 1 && toVersion >= 1) { createPrimaryClientStore(db); diff --git a/packages/firestore/src/local/memory_persistence.ts b/packages/firestore/src/local/memory_persistence.ts index fcb6db42059..22516329f0b 100644 --- a/packages/firestore/src/local/memory_persistence.ts +++ b/packages/firestore/src/local/memory_persistence.ts @@ -24,6 +24,7 @@ import { DocumentKey } from '../model/document_key'; import { estimateByteSize } from '../model/values'; import { JsonProtoSerializer } from '../remote/serializer'; import { fail } from '../util/assert'; +import { generateUniqueDebugId } from '../util/debug_uid'; import { logDebug } from '../util/log'; import { ObjectMap } from '../util/obj_map'; @@ -59,12 +60,12 @@ import { import { ReferenceSet } from './reference_set'; import { TargetData } from './target_data'; -const LOG_TAG = 'MemoryPersistence'; /** * A memory-backed instance of Persistence. Data is stored only in RAM and * not persisted across sessions. */ export class MemoryPersistence implements Persistence { + readonly debugId = `MemoryPersistence@${generateUniqueDebugId()}`; /** * Note that these are retained here to make it easier to write tests * affecting both the in-memory and IndexedDB-backed persistence layers. Tests @@ -177,7 +178,7 @@ export class MemoryPersistence implements Persistence { transaction: PersistenceTransaction ) => PersistencePromise ): Promise { - logDebug(LOG_TAG, 'Starting transaction:', action); + logDebug(this.debugId, 'Starting transaction:', action); const txn = new MemoryTransaction(this.listenSequence.next()); this.referenceDelegate.onTransactionStarted(); return transactionOperation(txn) diff --git a/packages/firestore/src/local/simple_db.ts b/packages/firestore/src/local/simple_db.ts index e284c3c46ee..35b511d242f 100644 --- a/packages/firestore/src/local/simple_db.ts +++ b/packages/firestore/src/local/simple_db.ts @@ -17,9 +17,10 @@ import { getGlobal, getUA, isIndexedDBAvailable } from '@firebase/util'; -import { debugAssert } from '../util/assert'; +import { debugAssert, hardAssert } from '../util/assert'; +import { generateUniqueDebugId } from '../util/debug_uid'; import { Code, FirestoreError } from '../util/error'; -import { logDebug, logError, logWarn } from '../util/log'; +import { logDebug, logError, logWarn, dumpLogBuffer } from '../util/log'; import { Deferred } from '../util/promise'; import { DatabaseDeletedListener } from './persistence'; @@ -28,8 +29,6 @@ import { PersistencePromise } from './persistence_promise'; // References to `indexedDB` are guarded by SimpleDb.isAvailable() and getGlobal() /* eslint-disable no-restricted-globals */ -const LOG_TAG = 'SimpleDb'; - /** * The maximum number of retry attempts for an IndexedDb transaction that fails * with a DOMException. @@ -41,7 +40,7 @@ type SimpleDbTransactionMode = 'readonly' | 'readwrite'; export interface SimpleDbSchemaConverter { createOrUpgrade( - db: IDBDatabase, + db: IdbDatabaseDebugIdPair, txn: IDBTransaction, fromVersion: number, toVersion: number @@ -53,6 +52,7 @@ export interface SimpleDbSchemaConverter { * specific object store. */ export class SimpleDbTransaction { + readonly debugId: string; private aborted = false; /** @@ -61,7 +61,7 @@ export class SimpleDbTransaction { private readonly completionDeferred = new Deferred(); static open( - db: IDBDatabase, + db: IdbDatabaseDebugIdPair, action: string, mode: IDBTransactionMode, objectStoreNames: string[] @@ -69,7 +69,8 @@ export class SimpleDbTransaction { try { return new SimpleDbTransaction( action, - db.transaction(objectStoreNames, mode) + db.idbDatabase.transaction(objectStoreNames, mode), + db.debugId ); } catch (e) { throw new IndexedDbTransactionError(action, e as Error); @@ -78,8 +79,12 @@ export class SimpleDbTransaction { constructor( private readonly action: string, - private readonly transaction: IDBTransaction + private readonly transaction: IDBTransaction, + readonly dbDebugId: string ) { + this.debugId = + `SimpleDbTransaction@${generateUniqueDebugId()}, ` + + `action="${action}", dbDebugId=${dbDebugId}`; this.transaction.oncomplete = () => { this.completionDeferred.resolve(); }; @@ -113,7 +118,7 @@ export class SimpleDbTransaction { if (!this.aborted) { logDebug( - LOG_TAG, + this.debugId, 'Aborting transaction:', error ? error.message : 'Client-initiated abort' ); @@ -146,10 +151,69 @@ export class SimpleDbTransaction { ): SimpleDbStore { const store = this.transaction.objectStore(storeName); debugAssert(!!store, 'Object store not part of transaction: ' + storeName); - return new SimpleDbStore(store); + return new SimpleDbStore(store, this.debugId); } } +export interface IdbDatabaseDebugIdPair { + idbDatabase: IDBDatabase; + debugId: string; +} + +class SimpleDbStateNew { + readonly name = 'new' as const; + + constructor( + readonly databaseDeletedListener: DatabaseDeletedListener | null + ) {} + + withDatabaseDeletedListener( + databaseDeletedListener: DatabaseDeletedListener + ): SimpleDbStateNew { + return new SimpleDbStateNew(databaseDeletedListener); + } +} + +class SimpleDbStateOpening { + readonly name = 'opening' as const; + + constructor( + readonly promise: Promise, + readonly databaseDeletedListener: DatabaseDeletedListener | null + ) {} + + withDatabaseDeletedListener( + databaseDeletedListener: DatabaseDeletedListener + ): SimpleDbStateOpening { + return new SimpleDbStateOpening(this.promise, databaseDeletedListener); + } +} + +class SimpleDbStateOpened { + readonly name = 'opened' as const; + + constructor( + readonly db: IdbDatabaseDebugIdPair, + readonly databaseDeletedListener: DatabaseDeletedListener | null + ) {} + + withDatabaseDeletedListener( + databaseDeletedListener: DatabaseDeletedListener + ): SimpleDbStateOpened { + return new SimpleDbStateOpened(this.db, databaseDeletedListener); + } +} + +class SimpleDbStateClosed { + readonly name = 'closed' as const; +} + +type SimpleDbState = + | SimpleDbStateNew + | SimpleDbStateOpened + | SimpleDbStateOpening + | SimpleDbStateClosed; + /** * Provides a wrapper around IndexedDb with a simplified interface that uses * Promise-like return values to chain operations. Real promises cannot be used @@ -158,16 +222,25 @@ export class SimpleDbTransaction { * See PersistencePromise for more details. */ export class SimpleDb { - private db?: IDBDatabase; - private databaseDeletedListener?: DatabaseDeletedListener; + readonly debugId = `SimpleDb@${generateUniqueDebugId()}`; + private state: SimpleDbState = new SimpleDbStateNew(null); /** Deletes the specified database. */ static delete(name: string): Promise { - logDebug(LOG_TAG, 'Removing database:', name); + const logTag = `SimpleDb[op=${generateUniqueDebugId()}]`; + logDebug(logTag, `Deleting IndexedDB database "${name}"`); const globals = getGlobal(); - return wrapRequest( - globals.indexedDB.deleteDatabase(name) - ).toPromise(); + + return wrapRequest(globals.indexedDB.deleteDatabase(name)) + .toPromise() + .then( + () => { + logDebug(logTag, `Deleting IndexedDB database "${name}" completed`); + }, + e => { + logWarn(logTag, `Deleting IndexedDB database "${name}" failed`, e); + } + ); } /** Returns true if IndexedDB is available in the current environment. */ @@ -287,113 +360,185 @@ export class SimpleDb { /** * Opens the specified database, creating or upgrading it if necessary. */ - async ensureDb(action: string): Promise { - if (!this.db) { - logDebug(LOG_TAG, 'Opening database:', this.name); - this.db = await new Promise((resolve, reject) => { - // TODO(mikelehen): Investigate browser compatibility. - // https://developer.mozilla.org/en-US/docs/Web/API/IndexedDB_API/Using_IndexedDB - // suggests IE9 and older WebKit browsers handle upgrade - // differently. They expect setVersion, as described here: - // https://developer.mozilla.org/en-US/docs/Web/API/IDBVersionChangeRequest/setVersion - const request = indexedDB.open(this.name, this.version); + async ensureDb(action: string): Promise { + while (true) { + const currentState = this.state; + if (currentState.name === 'closed') { + console.trace( + `zzyzx ${this.debugId} ` + + `ensureDb(${JSON.stringify(action)}) called after close()` + ); + dumpLogBuffer('SimpleDb.ensureDb after close'); + throw new Error(`${this.debugId} has been closed`); + } else if (currentState.name === 'opening') { + await currentState.promise.catch(_ => {}); + } else if (currentState.name === 'opened') { + return currentState.db; + } else { + hardAssert(currentState.name === 'new', 0x56e8, { state: this.state }); + const promise = this.openDb(action); + const openingState = new SimpleDbStateOpening( + promise, + currentState.databaseDeletedListener + ); + this.state = openingState; + try { + const db = await promise; + if (this.state === openingState) { + this.state = new SimpleDbStateOpened( + db, + openingState.databaseDeletedListener + ); + return db; + } else { + db.idbDatabase.close(); + } + } catch (e) { + if (this.state === openingState) { + this.state = new SimpleDbStateNew( + this.state.databaseDeletedListener + ); + throw e; + } + } + } + } + } - request.onsuccess = (event: Event) => { - const db = (event.target as IDBOpenDBRequest).result; - resolve(db); - }; + private async openDb(action: string): Promise { + const dbDebugId = `${this.debugId} IDBDatabase@${generateUniqueDebugId()}`; + logDebug( + dbDebugId, + `Opening database:`, + `name="${this.name}" version=${this.version} action="${action}"` + ); + + const db = await new Promise((resolve, reject) => { + const request = indexedDB.open(this.name, this.version); + + request.onsuccess = (event: Event) => { + logDebug(dbDebugId, 'IDBOpenDBRequest.onsuccess'); + const db = (event.target as IDBOpenDBRequest).result; + resolve(db); + }; + + request.onblocked = () => { + logWarn(dbDebugId, 'IDBOpenDBRequest.onblocked'); + reject( + new IndexedDbTransactionError( + action, + 'Cannot upgrade IndexedDB schema while another tab is open. ' + + 'Close all tabs that access Firestore and reload this page to proceed.' + ) + ); + }; - request.onblocked = () => { + request.onerror = (event: Event) => { + const error: DOMException = (event.target as IDBOpenDBRequest).error!; + logWarn(dbDebugId, 'IDBOpenDBRequest.onerror', error); + if (error.name === 'VersionError') { reject( - new IndexedDbTransactionError( - action, - 'Cannot upgrade IndexedDB schema while another tab is open. ' + - 'Close all tabs that access Firestore and reload this page to proceed.' + new FirestoreError( + Code.FAILED_PRECONDITION, + 'A newer version of the Firestore SDK was previously used and so the persisted ' + + 'data is not compatible with the version of the SDK you are now using. The SDK ' + + 'will operate with persistence disabled. If you need persistence, please ' + + 're-upgrade to a newer version of the SDK or else clear the persisted IndexedDB ' + + 'data for your app to start fresh.' ) ); - }; + } else if (error.name === 'InvalidStateError') { + reject( + new FirestoreError( + Code.FAILED_PRECONDITION, + 'Unable to open an IndexedDB connection. This could be due to running in a ' + + 'private browsing session on a browser whose private browsing sessions do not ' + + 'support IndexedDB: ' + + error + ) + ); + } else { + reject(new IndexedDbTransactionError(action, error)); + } + }; - request.onerror = (event: Event) => { - const error: DOMException = (event.target as IDBOpenDBRequest).error!; - if (error.name === 'VersionError') { - reject( - new FirestoreError( - Code.FAILED_PRECONDITION, - 'A newer version of the Firestore SDK was previously used and so the persisted ' + - 'data is not compatible with the version of the SDK you are now using. The SDK ' + - 'will operate with persistence disabled. If you need persistence, please ' + - 're-upgrade to a newer version of the SDK or else clear the persisted IndexedDB ' + - 'data for your app to start fresh.' - ) - ); - } else if (error.name === 'InvalidStateError') { - reject( - new FirestoreError( - Code.FAILED_PRECONDITION, - 'Unable to open an IndexedDB connection. This could be due to running in a ' + - 'private browsing session on a browser whose private browsing sessions do not ' + - 'support IndexedDB: ' + - error - ) + request.onupgradeneeded = (event: IDBVersionChangeEvent) => { + logDebug( + dbDebugId, + `IDBOpenDBRequest.onupgradeneeded oldVersion=${event.oldVersion} newVersion=${event.newVersion}` + ); + const db = (event.target as IDBOpenDBRequest).result; + this.schemaConverter + .createOrUpgrade( + { idbDatabase: db, debugId: dbDebugId }, + request.transaction!, + event.oldVersion, + this.version + ) + .next(() => { + logDebug( + this.debugId, + 'Database upgrade to version ' + this.version + ' complete' ); - } else { - reject(new IndexedDbTransactionError(action, error)); - } - }; - - request.onupgradeneeded = (event: IDBVersionChangeEvent) => { - logDebug( - LOG_TAG, - 'Database "' + this.name + '" requires upgrade from version:', - event.oldVersion - ); - const db = (event.target as IDBOpenDBRequest).result; - this.schemaConverter - .createOrUpgrade( - db, - request.transaction!, - event.oldVersion, - this.version - ) - .next(() => { - logDebug( - LOG_TAG, - 'Database upgrade to version ' + this.version + ' complete' - ); - }); - }; - }); - } + }); + }; + }); - this.db.addEventListener( + db.addEventListener( 'versionchange', event => { + logDebug( + dbDebugId, + `IDBDatabase "versionchange" event: ` + + `oldVersion=${event.oldVersion} newVersion=${event.newVersion}` + ); + // Notify the listener if another tab attempted to delete the IndexedDb // database, such as by calling clearIndexedDbPersistence(). if (event.newVersion === null) { logWarn( + dbDebugId, `Received "versionchange" event with newVersion===null; ` + 'notifying the registered DatabaseDeletedListener, if any' ); - this.databaseDeletedListener?.(); + if ('databaseDeletedListener' in this.state) { + this.state.databaseDeletedListener?.(); + } } }, { passive: true } ); - return this.db; + db.addEventListener( + 'close', + () => { + logWarn( + dbDebugId, + `IDBDatabase "close" event received, ` + + `indicating that the IDBDatabase was abnormally closed. ` + + `One possible cause is clicking the "Clear Site Data" button ` + + `in a web browser.` + ); + dumpLogBuffer('SimpleDbCloseEvent'); + }, + { passive: true } + ); + + return { idbDatabase: db, debugId: dbDebugId }; } setDatabaseDeletedListener( databaseDeletedListener: DatabaseDeletedListener ): void { - if (this.databaseDeletedListener) { - throw new Error( - 'setDatabaseDeletedListener() may only be called once, ' + - 'and it has already been called' - ); + if (!('databaseDeletedListener' in this.state)) { + return; } - this.databaseDeletedListener = databaseDeletedListener; + if (this.state.databaseDeletedListener) { + throw new Error('setDatabaseDeletedListener() has already been called'); + } + this.state = this.state.withDatabaseDeletedListener( + databaseDeletedListener + ); } async runTransaction( @@ -402,17 +547,29 @@ export class SimpleDb { objectStores: string[], transactionFn: (transaction: SimpleDbTransaction) => PersistencePromise ): Promise { + const transactionId = generateUniqueDebugId(); + logDebug( + this.debugId, + `runTransaction transactionId=${transactionId} starting; ` + + `action="${action}", mode="${mode}", objectStores=${objectStores.join()}` + ); const readonly = mode === 'readonly'; let attemptNumber = 0; while (true) { ++attemptNumber; + logDebug( + this.debugId, + `runTransaction transactionId=${transactionId} attemptNumber=${attemptNumber}` + ); + + const dbBefore = 'db' in this.state ? this.state.db : null; try { - this.db = await this.ensureDb(action); + const db = await this.ensureDb(action); const transaction = SimpleDbTransaction.open( - this.db, + db, action, readonly ? 'readonly' : 'readwrite', objectStores @@ -454,14 +611,23 @@ export class SimpleDb { error.name !== 'FirebaseError' && attemptNumber < TRANSACTION_RETRY_COUNT; logDebug( - LOG_TAG, - 'Transaction failed with error:', + this.debugId, + `Transaction transactionId=${transactionId} failed with error:`, error.message, 'Retrying:', retryable ); - this.close(); + if ('db' in this.state && dbBefore === this.state.db) { + this.state = new SimpleDbStateNew(this.state.databaseDeletedListener); + logWarn( + this.debugId, + `Transaction transactionId=${transactionId} closing IDBDatabase ` + + `due to error:`, + error.message + ); + dbBefore.idbDatabase.close(); + } if (!retryable) { return Promise.reject(error); @@ -471,10 +637,15 @@ export class SimpleDb { } close(): void { - if (this.db) { - this.db.close(); + if (this.state.name === 'closed') { + dumpLogBuffer('SimpleDb.close'); + return; } - this.db = undefined; + logDebug(this.debugId, 'close()'); + if ('db' in this.state) { + this.state.db.idbDatabase.close(); + } + this.state = new SimpleDbStateClosed(); } } @@ -592,7 +763,11 @@ export class SimpleDbStore< KeyType extends IDBValidKey, ValueType extends unknown > { - constructor(private store: IDBObjectStore) {} + readonly debugId: string; + + constructor(private store: IDBObjectStore, transactionId: string) { + this.debugId = transactionId; + } /** * Writes a value into the Object Store. @@ -609,10 +784,10 @@ export class SimpleDbStore< ): PersistencePromise { let request; if (value !== undefined) { - logDebug(LOG_TAG, 'PUT', this.store.name, keyOrValue, value); + logDebug(this.debugId, 'PUT', this.store.name, keyOrValue, value); request = this.store.put(value, keyOrValue as KeyType); } else { - logDebug(LOG_TAG, 'PUT', this.store.name, '', keyOrValue); + logDebug(this.debugId, 'PUT', this.store.name, '', keyOrValue); request = this.store.put(keyOrValue as ValueType); } return wrapRequest(request); @@ -626,7 +801,7 @@ export class SimpleDbStore< * @returns The key of the value to add. */ add(value: ValueType): PersistencePromise { - logDebug(LOG_TAG, 'ADD', this.store.name, value, value); + logDebug(this.debugId, 'ADD', this.store.name, value, value); const request = this.store.add(value as ValueType); return wrapRequest(request); } @@ -647,13 +822,13 @@ export class SimpleDbStore< if (result === undefined) { result = null; } - logDebug(LOG_TAG, 'GET', this.store.name, key, result); + logDebug(this.debugId, 'GET', this.store.name, key, result); return result; }); } delete(key: KeyType | IDBKeyRange): PersistencePromise { - logDebug(LOG_TAG, 'DELETE', this.store.name, key); + logDebug(this.debugId, 'DELETE', this.store.name, key); const request = this.store.delete(key); return wrapRequest(request); } @@ -665,7 +840,7 @@ export class SimpleDbStore< * Returns the number of rows in the store. */ count(): PersistencePromise { - logDebug(LOG_TAG, 'COUNT', this.store.name); + logDebug(this.debugId, 'COUNT', this.store.name); const request = this.store.count(); return wrapRequest(request); } @@ -741,7 +916,7 @@ export class SimpleDbStore< indexOrRange?: string | IDBKeyRange, range?: IDBKeyRange ): PersistencePromise { - logDebug(LOG_TAG, 'DELETE ALL', this.store.name); + logDebug(this.debugId, 'DELETE ALL', this.store.name); const options = this.options(indexOrRange, range); options.keysOnly = false; const cursor = this.cursor(options); diff --git a/packages/firestore/src/platform/browser/webchannel_connection.ts b/packages/firestore/src/platform/browser/webchannel_connection.ts index 56f57aa9595..c56d53a989d 100644 --- a/packages/firestore/src/platform/browser/webchannel_connection.ts +++ b/packages/firestore/src/platform/browser/webchannel_connection.ts @@ -47,13 +47,13 @@ import { logDebug, logWarn } from '../../util/log'; import { Rejecter, Resolver } from '../../util/promise'; import { StringMap } from '../../util/types'; -const LOG_TAG = 'WebChannelConnection'; - const RPC_STREAM_SERVICE = 'google.firestore.v1.Firestore'; const XHR_TIMEOUT_SECS = 15; export class WebChannelConnection extends RestConnection { + readonly debugId = `WebChannelConnection@${generateUniqueDebugId()}`; + private readonly forceLongPolling: boolean; private readonly autoDetectLongPolling: boolean; private readonly useFetchStreams: boolean; @@ -77,7 +77,7 @@ export class WebChannelConnection extends RestConnection { body: Req, _forwardCredentials: boolean ): Promise { - const streamId = generateUniqueDebugId(); + const streamId = `stream@${generateUniqueDebugId()}`; return new Promise((resolve: Resolver, reject: Rejecter) => { const xhr = new XhrIo(); xhr.setWithCredentials(true); @@ -87,14 +87,14 @@ export class WebChannelConnection extends RestConnection { case ErrorCode.NO_ERROR: const json = xhr.getResponseJson() as Resp; logDebug( - LOG_TAG, + this.debugId, `XHR for RPC '${rpcName}' ${streamId} received:`, JSON.stringify(json) ); resolve(json); break; case ErrorCode.TIMEOUT: - logDebug(LOG_TAG, `RPC '${rpcName}' ${streamId} timed out`); + logDebug(this.debugId, `RPC '${rpcName}' ${streamId} timed out`); reject( new FirestoreError(Code.DEADLINE_EXCEEDED, 'Request time out') ); @@ -102,7 +102,7 @@ export class WebChannelConnection extends RestConnection { case ErrorCode.HTTP_ERROR: const status = xhr.getStatus(); logDebug( - LOG_TAG, + this.debugId, `RPC '${rpcName}' ${streamId} failed with status:`, status, 'response text:', @@ -157,12 +157,16 @@ export class WebChannelConnection extends RestConnection { ); } } finally { - logDebug(LOG_TAG, `RPC '${rpcName}' ${streamId} completed.`); + logDebug(this.debugId, `RPC '${rpcName}' ${streamId} completed.`); } }); const requestString = JSON.stringify(body); - logDebug(LOG_TAG, `RPC '${rpcName}' ${streamId} sending request:`, body); + logDebug( + this.debugId, + `RPC '${rpcName}' ${streamId} sending request:`, + body + ); xhr.send(url, 'POST', requestString, headers, XHR_TIMEOUT_SECS); }); } @@ -237,7 +241,7 @@ export class WebChannelConnection extends RestConnection { const url = urlParts.join(''); logDebug( - LOG_TAG, + this.debugId, `Creating RPC '${rpcName}' stream ${streamId}: ${url}`, request ); @@ -261,21 +265,21 @@ export class WebChannelConnection extends RestConnection { if (!closed) { if (!opened) { logDebug( - LOG_TAG, + this.debugId, `Opening RPC '${rpcName}' stream ${streamId} transport.` ); channel.open(); opened = true; } logDebug( - LOG_TAG, + this.debugId, `RPC '${rpcName}' stream ${streamId} sending:`, msg ); channel.send(msg); } else { logDebug( - LOG_TAG, + this.debugId, `Not sending because RPC '${rpcName}' stream ${streamId} ` + 'is closed:', msg @@ -310,7 +314,7 @@ export class WebChannelConnection extends RestConnection { unguardedEventListen(channel, WebChannel.EventType.OPEN, () => { if (!closed) { logDebug( - LOG_TAG, + this.debugId, `RPC '${rpcName}' stream ${streamId} transport opened.` ); streamBridge.callOnConnected(); @@ -321,7 +325,7 @@ export class WebChannelConnection extends RestConnection { if (!closed) { closed = true; logDebug( - LOG_TAG, + this.debugId, `RPC '${rpcName}' stream ${streamId} transport closed` ); streamBridge.callOnClose(); @@ -333,7 +337,7 @@ export class WebChannelConnection extends RestConnection { if (!closed) { closed = true; logWarn( - LOG_TAG, + this.debugId, `RPC '${rpcName}' stream ${streamId} transport errored. Name:`, err.name, 'Message:', @@ -377,7 +381,7 @@ export class WebChannelConnection extends RestConnection { (msgDataOrError as WebChannelError[])[0]?.error; if (error) { logDebug( - LOG_TAG, + this.debugId, `RPC '${rpcName}' stream ${streamId} received error:`, error ); @@ -399,7 +403,7 @@ export class WebChannelConnection extends RestConnection { channel.close(); } else { logDebug( - LOG_TAG, + this.debugId, `RPC '${rpcName}' stream ${streamId} received:`, msgData ); @@ -412,12 +416,12 @@ export class WebChannelConnection extends RestConnection { unguardedEventListen(requestStats, Event.STAT_EVENT, event => { if (event.stat === Stat.PROXY) { logDebug( - LOG_TAG, + this.debugId, `RPC '${rpcName}' stream ${streamId} detected buffering proxy` ); } else if (event.stat === Stat.NOPROXY) { logDebug( - LOG_TAG, + this.debugId, `RPC '${rpcName}' stream ${streamId} detected no buffering proxy` ); } diff --git a/packages/firestore/src/platform/browser_lite/fetch_connection.ts b/packages/firestore/src/platform/browser_lite/fetch_connection.ts index 227322153e9..8ec4e1d4a72 100644 --- a/packages/firestore/src/platform/browser_lite/fetch_connection.ts +++ b/packages/firestore/src/platform/browser_lite/fetch_connection.ts @@ -19,6 +19,7 @@ import { Token } from '../../api/credentials'; import { Stream } from '../../remote/connection'; import { RestConnection } from '../../remote/rest_connection'; import { mapCodeFromHttpStatus } from '../../remote/rpc_error'; +import { generateUniqueDebugId } from '../../util/debug_uid'; import { FirestoreError } from '../../util/error'; import { StringMap } from '../../util/types'; @@ -27,6 +28,8 @@ import { StringMap } from '../../util/types'; * (e.g. `fetch` or a polyfill). */ export class FetchConnection extends RestConnection { + readonly debugId = `FetchConnection@${generateUniqueDebugId()}`; + openStream( rpcName: string, token: Token | null diff --git a/packages/firestore/src/platform/node/grpc_connection.ts b/packages/firestore/src/platform/node/grpc_connection.ts index d50a3149416..fab3735268c 100644 --- a/packages/firestore/src/platform/node/grpc_connection.ts +++ b/packages/firestore/src/platform/node/grpc_connection.ts @@ -37,7 +37,6 @@ import { Deferred } from '../../util/promise'; // when there's a cleaner way to dynamic require JSON in both Node ESM and CJS const grpcVersion = '__GRPC_VERSION__'; -const LOG_TAG = 'GrpcConnection'; const X_GOOG_API_CLIENT_VALUE = `gl-node/${process.versions.node} fire/${SDK_VERSION} grpc/${grpcVersion}`; function createMetadata( @@ -81,6 +80,8 @@ type GeneratedGrpcStub = any; * A Connection implemented by GRPC-Node. */ export class GrpcConnection implements Connection { + readonly debugId = `GrpcConnection@${generateUniqueDebugId()}`; + private readonly databasePath: string; // eslint-disable-next-line @typescript-eslint/no-explicit-any private readonly firestore: any; @@ -102,7 +103,7 @@ export class GrpcConnection implements Connection { private ensureActiveStub(): GeneratedGrpcStub { if (!this.cachedStub) { - logDebug(LOG_TAG, 'Creating Firestore stub.'); + logDebug(this.debugId, 'Creating Firestore stub.'); const credentials = this.databaseInfo.ssl ? grpc.credentials.createSsl() : grpc.credentials.createInsecure(); @@ -133,7 +134,7 @@ export class GrpcConnection implements Connection { return nodePromise((callback: NodeCallback) => { logDebug( - LOG_TAG, + this.debugId, `RPC '${rpcName}' ${streamId} invoked with request:`, request ); @@ -143,7 +144,7 @@ export class GrpcConnection implements Connection { (grpcError?: grpc.ServiceError, value?: Resp) => { if (grpcError) { logDebug( - LOG_TAG, + this.debugId, `RPC '${rpcName}' ${streamId} failed with error:`, grpcError ); @@ -155,7 +156,7 @@ export class GrpcConnection implements Connection { ); } else { logDebug( - LOG_TAG, + this.debugId, `RPC '${rpcName}' ${streamId} completed with response:`, value ); @@ -178,7 +179,7 @@ export class GrpcConnection implements Connection { const results: Resp[] = []; const responseDeferred = new Deferred(); logDebug( - LOG_TAG, + this.debugId, `RPC '${rpcName}' ${streamId} invoked (streaming) with request:`, request ); @@ -194,7 +195,7 @@ export class GrpcConnection implements Connection { let callbackFired = false; stream.on('data', (response: Resp) => { logDebug( - LOG_TAG, + this.debugId, `RPC ${rpcName} ${streamId} received result:`, response ); @@ -208,7 +209,7 @@ export class GrpcConnection implements Connection { } }); stream.on('end', () => { - logDebug(LOG_TAG, `RPC '${rpcName}' ${streamId} completed.`); + logDebug(this.debugId, `RPC '${rpcName}' ${streamId} completed.`); if (!callbackFired) { callbackFired = true; responseDeferred.resolve(results); @@ -216,7 +217,7 @@ export class GrpcConnection implements Connection { }); stream.on('error', (grpcError: grpc.ServiceError) => { logDebug( - LOG_TAG, + this.debugId, `RPC '${rpcName}' ${streamId} failed with error:`, grpcError ); @@ -256,7 +257,7 @@ export class GrpcConnection implements Connection { sendFn: (msg: Req) => { if (!closed) { logDebug( - LOG_TAG, + this.debugId, `RPC '${rpcName}' stream ${streamId} sending:`, msg ); @@ -271,7 +272,7 @@ export class GrpcConnection implements Connection { } } else { logDebug( - LOG_TAG, + this.debugId, `RPC '${rpcName}' stream ${streamId} ` + 'not sending because gRPC stream is closed:', msg @@ -280,7 +281,7 @@ export class GrpcConnection implements Connection { }, closeFn: () => { logDebug( - LOG_TAG, + this.debugId, `RPC '${rpcName}' stream ${streamId} closed locally via close().` ); close(); @@ -290,7 +291,11 @@ export class GrpcConnection implements Connection { let onConnectedSent = false; grpcStream.on('data', (msg: Resp) => { if (!closed) { - logDebug(LOG_TAG, `RPC '${rpcName}' stream ${streamId} received:`, msg); + logDebug( + this.debugId, + `RPC '${rpcName}' stream ${streamId} received:`, + msg + ); // Emulate the "onConnected" event that WebChannelConnection sends. if (!onConnectedSent) { stream.callOnConnected(); @@ -301,14 +306,14 @@ export class GrpcConnection implements Connection { }); grpcStream.on('end', () => { - logDebug(LOG_TAG, `RPC '${rpcName}' stream ${streamId} ended.`); + logDebug(this.debugId, `RPC '${rpcName}' stream ${streamId} ended.`); close(); }); grpcStream.on('error', (grpcError: grpc.ServiceError) => { if (!closed) { logWarn( - LOG_TAG, + this.debugId, `RPC '${rpcName}' stream ${streamId} error. Code:`, grpcError.code, 'Message:', @@ -320,7 +325,7 @@ export class GrpcConnection implements Connection { }); logDebug( - LOG_TAG, + this.debugId, `Opening RPC '${rpcName}' stream ${streamId} ` + `to ${this.databaseInfo.host}` ); diff --git a/packages/firestore/src/remote/connection.ts b/packages/firestore/src/remote/connection.ts index 2bf982eb4d1..5ede8d50b7b 100644 --- a/packages/firestore/src/remote/connection.ts +++ b/packages/firestore/src/remote/connection.ts @@ -34,6 +34,8 @@ import { FirestoreError } from '../util/error'; * creating the equivalent protocol buffers for GRPC. */ export interface Connection { + readonly debugId: string; + /** * Invokes an RPC by name, given a request message as a JavaScript object * representing the JSON to send. diff --git a/packages/firestore/src/remote/rest_connection.ts b/packages/firestore/src/remote/rest_connection.ts index 2d6889dac3b..8555da6aace 100644 --- a/packages/firestore/src/remote/rest_connection.ts +++ b/packages/firestore/src/remote/rest_connection.ts @@ -33,8 +33,6 @@ import { StringMap } from '../util/types'; import { Connection, Stream } from './connection'; -const LOG_TAG = 'RestConnection'; - /** * Maps RPC names to the corresponding REST endpoint name. * @@ -59,6 +57,8 @@ function getGoogApiClientValue(): string { * HTTP). */ export abstract class RestConnection implements Connection { + readonly debugId = `RestConnection@${generateUniqueDebugId()}`; + protected readonly databaseId: DatabaseId; protected readonly baseUrl: string; private readonly databasePath: string; @@ -92,7 +92,7 @@ export abstract class RestConnection implements Connection { ): Promise { const streamId = generateUniqueDebugId(); const url = this.makeUrl(rpcName, path.toUriEncodedString()); - logDebug(LOG_TAG, `Sending RPC '${rpcName}' ${streamId}:`, url, req); + logDebug(this.debugId, `Sending RPC '${rpcName}' ${streamId}:`, url, req); const headers: StringMap = { 'google-cloud-resource-prefix': this.databasePath, @@ -110,12 +110,16 @@ export abstract class RestConnection implements Connection { forwardCredentials ).then( response => { - logDebug(LOG_TAG, `Received RPC '${rpcName}' ${streamId}: `, response); + logDebug( + this.debugId, + `Received RPC '${rpcName}' ${streamId}: `, + response + ); return response; }, (err: FirestoreError) => { logWarn( - LOG_TAG, + this.debugId, `RPC '${rpcName}' ${streamId} failed with error: `, err, 'url: ', diff --git a/packages/firestore/src/util/log.ts b/packages/firestore/src/util/log.ts index cbdbad38ecf..74936b24a5a 100644 --- a/packages/firestore/src/util/log.ts +++ b/packages/firestore/src/util/log.ts @@ -47,6 +47,7 @@ export function setLogLevel(logLevel: LogLevelString): void { } export function logDebug(msg: string, ...obj: unknown[]): void { + logBuffer?.add(LogLevel.DEBUG, msg, obj); if (logClient.logLevel <= LogLevel.DEBUG) { const args = obj.map(argToString); logClient.debug(`Firestore (${SDK_VERSION}): ${msg}`, ...args); @@ -54,6 +55,7 @@ export function logDebug(msg: string, ...obj: unknown[]): void { } export function logError(msg: string, ...obj: unknown[]): void { + logBuffer?.add(LogLevel.ERROR, msg, obj); if (logClient.logLevel <= LogLevel.ERROR) { const args = obj.map(argToString); logClient.error(`Firestore (${SDK_VERSION}): ${msg}`, ...args); @@ -64,6 +66,7 @@ export function logError(msg: string, ...obj: unknown[]): void { * @internal */ export function logWarn(msg: string, ...obj: unknown[]): void { + logBuffer?.add(LogLevel.WARN, msg, obj); if (logClient.logLevel <= LogLevel.WARN) { const args = obj.map(argToString); logClient.warn(`Firestore (${SDK_VERSION}): ${msg}`, ...args); @@ -85,3 +88,100 @@ function argToString(obj: unknown): string | unknown { } } } + +interface LogBufferMessage { + level: LogLevel; + msg: string; + objs: unknown[]; + timestamp: number; +} + +class LogBuffer { + private readonly messages: LogBufferMessage[] = []; + private readonly enabledDumpIds: string[]; + + constructor(private readonly maxLength: number, enabledDumpIds: string[]) { + this.enabledDumpIds = Array.from(enabledDumpIds); + } + + add(level: LogLevel, msg: string, objs: unknown[]): void { + const message: LogBufferMessage = { + level, + msg, + objs: objs.map(value => structuredClone(value)), + timestamp: performance.now() + }; + if (this.messages.length === this.maxLength) { + this.messages.shift(); + } + this.messages.push(message); + } + + private isDumpIdEnabled(dumpId: string | undefined): boolean { + return ( + dumpId === undefined || + this.enabledDumpIds.length === 0 || + this.enabledDumpIds.includes(dumpId) + ); + } + + dump(dumpId?: string | undefined): void { + if (!this.isDumpIdEnabled(dumpId)) { + return; + } + const oldLogLevel = logClient.logLevel; + logClient.setLogLevel(LogLevel.DEBUG); + try { + this.doDump(); + } finally { + logClient.setLogLevel(oldLogLevel); + } + } + + private doDump(dumpId?: string | undefined): void { + const now = performance.now(); + const numBufferedMessages = this.messages.length; + logClient.info( + `Firestore (${SDK_VERSION}): ` + + `Dumping ${numBufferedMessages} buffered log messages ` + + `with dumpId=${dumpId}` + ); + + const i = 1; + + while (true) { + const message = this.messages.shift(); + if (!message) { + break; + } + const { level, msg, objs, timestamp } = message; + const args = objs.map(argToString); + const messageString = + `Firestore (${SDK_VERSION}): BUFFERED ${i}/${numBufferedMessages} ` + + `(${now - timestamp}ms ago): ${msg}`; + if (level === LogLevel.WARN) { + logClient.warn(messageString, ...args); + } else if (level === LogLevel.ERROR) { + logClient.error(messageString, ...args); + } else { + logClient.debug(messageString, ...args); + } + } + } +} + +let logBuffer: LogBuffer | null = null; + +export function enableLogBuffer( + maxLength: number, + enabledDumpIds?: string[] +): void { + if (logBuffer) { + throw new Error('log buffer has already been enabled'); + } + logBuffer = new LogBuffer(maxLength, enabledDumpIds ?? []); +} + +export function dumpLogBuffer(dumpId?: string | undefined): void { + logBuffer?.dump(dumpId); +} diff --git a/packages/firestore/test/integration/util/firebase_export.ts b/packages/firestore/test/integration/util/firebase_export.ts index f58b3ce045b..3444378bfa7 100644 --- a/packages/firestore/test/integration/util/firebase_export.ts +++ b/packages/firestore/test/integration/util/firebase_export.ts @@ -22,13 +22,15 @@ import { FirebaseApp, initializeApp } from '@firebase/app'; -import { Firestore, initializeFirestore } from '../../../src'; +import { Firestore, initializeFirestore, _enableLogBuffer } from '../../../src'; import { PrivateSettings } from '../../../src/lite-api/settings'; // TODO(dimond): Right now we create a new app and Firestore instance for // every test and never clean them up. We may need to revisit. let appCount = 0; +_enableLogBuffer(1000); + export function newTestApp(projectId: string, appName?: string): FirebaseApp { if (appName === undefined) { appName = 'test-app-' + appCount++; diff --git a/packages/firestore/test/unit/local/encoded_resource_path.test.ts b/packages/firestore/test/unit/local/encoded_resource_path.test.ts index f9e48415e1a..d5ca1e6baab 100644 --- a/packages/firestore/test/unit/local/encoded_resource_path.test.ts +++ b/packages/firestore/test/unit/local/encoded_resource_path.test.ts @@ -23,6 +23,7 @@ import { } from '../../../src/local/encoded_resource_path'; import { PersistencePromise } from '../../../src/local/persistence_promise'; import { + IdbDatabaseDebugIdPair, SimpleDb, SimpleDbSchemaConverter, SimpleDbStore, @@ -36,12 +37,12 @@ const sep = '\u0001\u0001'; class EncodedResourcePathSchemaConverter implements SimpleDbSchemaConverter { createOrUpgrade( - db: IDBDatabase, + idbDatabaseDebugIdPair: IdbDatabaseDebugIdPair, txn: IDBTransaction, fromVersion: number, toVersion: number ): PersistencePromise { - db.createObjectStore('test'); + idbDatabaseDebugIdPair.idbDatabase.createObjectStore('test'); return PersistencePromise.resolve(); } } diff --git a/packages/firestore/test/unit/local/indexeddb_persistence.test.ts b/packages/firestore/test/unit/local/indexeddb_persistence.test.ts index 9fa872101b1..4ec0569cbf0 100644 --- a/packages/firestore/test/unit/local/indexeddb_persistence.test.ts +++ b/packages/firestore/test/unit/local/indexeddb_persistence.test.ts @@ -138,7 +138,8 @@ async function withDb( schemaVersion, schemaConverter ); - const database = await simpleDb.ensureDb('IndexedDbPersistenceTests'); + const dbWithDebugId = await simpleDb.ensureDb('IndexedDbPersistenceTests'); + const database = dbWithDebugId.idbDatabase; return fn( simpleDb, database.version, diff --git a/packages/firestore/test/unit/local/simple_db.test.ts b/packages/firestore/test/unit/local/simple_db.test.ts index 207e454fb5b..ef71ab9686f 100644 --- a/packages/firestore/test/unit/local/simple_db.test.ts +++ b/packages/firestore/test/unit/local/simple_db.test.ts @@ -23,6 +23,7 @@ import { dbKeyComparator } from '../../../src/local/indexeddb_remote_document_ca import { PersistencePromise } from '../../../src/local/persistence_promise'; import { getAndroidVersion, + IdbDatabaseDebugIdPair, SimpleDb, SimpleDbSchemaConverter, SimpleDbStore, @@ -64,11 +65,13 @@ function isIndexedDbMock(): boolean { class TestSchemaConverter implements SimpleDbSchemaConverter { createOrUpgrade( - db: IDBDatabase, + idbDatabaseDebugIdPair: IdbDatabaseDebugIdPair, txn: IDBTransaction, fromVersion: number, toVersion: number ): PersistencePromise { + const db = idbDatabaseDebugIdPair.idbDatabase; + const userStore = db.createObjectStore('users', { keyPath: 'id' }); userStore.createIndex('age-name', ['age', 'name'], { unique: false diff --git a/packages/firestore/test/unit/remote/datastore.test.ts b/packages/firestore/test/unit/remote/datastore.test.ts index 3f2a2da146a..1c2588a411a 100644 --- a/packages/firestore/test/unit/remote/datastore.test.ts +++ b/packages/firestore/test/unit/remote/datastore.test.ts @@ -33,6 +33,7 @@ import { invokeBatchGetDocumentsRpc } from '../../../src/remote/datastore'; import { JsonProtoSerializer } from '../../../src/remote/serializer'; +import { generateUniqueDebugId } from '../../../src/util/debug_uid'; import { Code, FirestoreError } from '../../../src/util/error'; use(chaiAsPromised); @@ -42,6 +43,8 @@ use(chaiAsPromised); // `invokeRPC()` and `invokeStreamingRPC()`. describe('Datastore', () => { class MockConnection implements Connection { + readonly debugId = `DatastoreMockConnection@${generateUniqueDebugId}`; + terminateInvoked = false; terminate(): void { diff --git a/packages/firestore/test/unit/specs/spec_test_components.ts b/packages/firestore/test/unit/specs/spec_test_components.ts index 017afe1d924..2aee9633ce0 100644 --- a/packages/firestore/test/unit/specs/spec_test_components.ts +++ b/packages/firestore/test/unit/specs/spec_test_components.ts @@ -61,6 +61,7 @@ import { JsonProtoSerializer } from '../../../src/remote/serializer'; import { StreamBridge } from '../../../src/remote/stream_bridge'; import { debugAssert, fail } from '../../../src/util/assert'; import { AsyncQueue } from '../../../src/util/async_queue'; +import { generateUniqueDebugId } from '../../../src/util/debug_uid'; import { FirestoreError } from '../../../src/util/error'; import { Deferred } from '../../../src/util/promise'; import { WindowLike } from '../../../src/util/types'; @@ -229,6 +230,8 @@ export class MockMemoryOfflineComponentProvider extends MemoryOfflineComponentPr } export class MockConnection implements Connection { + readonly debugId = `SpecTestMockConnection@${generateUniqueDebugId}`; + watchStream: StreamBridge | null = null; writeStream: StreamBridge | null = null; diff --git a/packages/firestore/test/unit/specs/spec_test_runner.ts b/packages/firestore/test/unit/specs/spec_test_runner.ts index daa513edb68..15000c53d6d 100644 --- a/packages/firestore/test/unit/specs/spec_test_runner.ts +++ b/packages/firestore/test/unit/specs/spec_test_runner.ts @@ -132,6 +132,7 @@ import { } from '../../../src/util/async_queue_impl'; import { newBundleReader } from '../../../src/util/bundle_reader_impl'; import { ByteString } from '../../../src/util/byte_string'; +import { generateUniqueDebugId } from '../../../src/util/debug_uid'; import { FirestoreError } from '../../../src/util/error'; import { logWarn } from '../../../src/util/log'; import { primitiveComparator } from '../../../src/util/misc'; @@ -223,6 +224,8 @@ export function parseQuery(querySpec: string | SpecQuery): Query { } abstract class TestRunner { + readonly debugId = `TestRunner@${generateUniqueDebugId()}`; + protected queue: AsyncQueueImpl; // Initialized asynchronously via start(). @@ -310,6 +313,7 @@ abstract class TestRunner { async start(): Promise { const configuration = { + debugId: this.debugId, asyncQueue: this.queue, databaseInfo: this.databaseInfo, authCredentials: new EmptyAuthCredentialsProvider(),